Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

GenevaExporter - LogSerialization Fixes #295

Merged
merged 5 commits into from
Apr 14, 2022
Merged

GenevaExporter - LogSerialization Fixes #295

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
a248946
Geneva Log serialization fixes
cijothomas Apr 14, 2022
a39c584
min tweaks
cijothomas Apr 14, 2022
ac4ffec
pr
cijothomas Apr 14, 2022
2ac1f5e
format
cijothomas Apr 14, 2022
30d97bb
Merge branch 'main' into cijothomas/geneva_logfix
utpilla Apr 14, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
118 changes: 53 additions & 65 deletions src/OpenTelemetry.Exporter.Geneva/GenevaLogExporter.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -181,22 +181,19 @@ internal bool IsUsingUnixDomainSocket

internal int SerializeLogRecord(LogRecord logRecord)
{
bool isUnstructuredLog = true;
IReadOnlyList<KeyValuePair<string, object>> listKvp;
if (logRecord.State == null)
{
// When State is null, OTel SDK guarantees StateValues is populated
cijothomas marked this conversation as resolved.
Show resolved Hide resolved
// TODO: Debug.Assert?
listKvp = logRecord.StateValues;
}
else
{
// Attempt to see if State could be ROL_KVP.
listKvp = logRecord.State as IReadOnlyList<KeyValuePair<string, object>>;
}

if (listKvp != null)
{
isUnstructuredLog = listKvp.Count == 1;
}

var name = logRecord.CategoryName;

// If user configured explicit TableName, use it.
Expand Down Expand Up @@ -325,81 +322,72 @@ internal int SerializeLogRecord(LogRecord logRecord)
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, name);
cntFields += 1;

if (isUnstructuredLog)
bool hasEnvProperties = false;
bool bodyPopulated = false;
for (int i = 0; i < listKvp?.Count; i++)
{
var entry = listKvp[i];

// Iteration #1 - Get those fields which become dedicated columns
// i.e all Part B fields and opt-in Part C fields.
if (entry.Key == "{OriginalFormat}")
{
cursor = MessagePackSerializer.SerializeAsciiString(buffer, cursor, "body");
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, logRecord.FormattedMessage ?? Convert.ToString(entry.Value, CultureInfo.InvariantCulture));
cntFields += 1;
bodyPopulated = true;
continue;
}
else if (this.m_customFields == null || this.m_customFields.ContainsKey(entry.Key))
{
// TODO: the above null check can be optimized and avoided inside foreach.
if (entry.Value != null)
{
// null is not supported.
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, entry.Key);
cursor = MessagePackSerializer.Serialize(buffer, cursor, entry.Value);
cntFields += 1;
}
}
else
{
hasEnvProperties = true;
continue;
}
}

if (!bodyPopulated && logRecord.FormattedMessage != null)
{
cursor = MessagePackSerializer.SerializeAsciiString(buffer, cursor, "body");
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, logRecord.FormattedMessage ?? (listKvp != null ? Convert.ToString(listKvp[0].Value, CultureInfo.InvariantCulture) : Convert.ToString(logRecord.State, CultureInfo.InvariantCulture)));
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, logRecord.FormattedMessage);
cntFields += 1;
}
else

if (hasEnvProperties)
{
bool hasEnvProperties = false;
bool bodyPopulated = false;
// Iteration #2 - Get all "other" fields and collapse them into single field
// named "env_properties".
ushort envPropertiesCount = 0;
cursor = MessagePackSerializer.SerializeAsciiString(buffer, cursor, "env_properties");
cursor = MessagePackSerializer.WriteMapHeader(buffer, cursor, ushort.MaxValue);
int idxMapSizeEnvPropertiesPatch = cursor - 2;
for (int i = 0; i < listKvp.Count; i++)
{
var entry = listKvp[i];

// Iteration #1 - Get those fields which become dedicated column
// i.e all PartB fields and opt-in part c fields.
if (entry.Key == "{OriginalFormat}")
if (entry.Key == "{OriginalFormat}" || this.m_customFields.ContainsKey(entry.Key))
{
cursor = MessagePackSerializer.SerializeAsciiString(buffer, cursor, "body");
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, logRecord.FormattedMessage ?? Convert.ToString(entry.Value, CultureInfo.InvariantCulture));
cntFields += 1;
bodyPopulated = true;
continue;
}
else if (this.m_customFields == null || this.m_customFields.ContainsKey(entry.Key))
{
// TODO: the above null check can be optimized and avoided inside foreach.
if (entry.Value != null)
{
// Geneva doesn't support null.
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, entry.Key);
cursor = MessagePackSerializer.Serialize(buffer, cursor, entry.Value);
cntFields += 1;
}
}
else
{
hasEnvProperties = true;
continue;
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, entry.Key);
cursor = MessagePackSerializer.Serialize(buffer, cursor, entry.Value);
envPropertiesCount += 1;
}
}

if (!bodyPopulated && logRecord.FormattedMessage != null)
{
cursor = MessagePackSerializer.SerializeAsciiString(buffer, cursor, "body");
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, logRecord.FormattedMessage);
cntFields += 1;
}

if (hasEnvProperties)
{
// Iteration #2 - Get all "other" fields and collapse them into single field
// named "env_properties".
ushort envPropertiesCount = 0;
cursor = MessagePackSerializer.SerializeAsciiString(buffer, cursor, "env_properties");
cursor = MessagePackSerializer.WriteMapHeader(buffer, cursor, ushort.MaxValue);
int idxMapSizeEnvPropertiesPatch = cursor - 2;
for (int i = 0; i < listKvp.Count; i++)
{
var entry = listKvp[i];
if (entry.Key == "{OriginalFormat}" || this.m_customFields.ContainsKey(entry.Key))
{
continue;
}
else
{
cursor = MessagePackSerializer.SerializeUnicodeString(buffer, cursor, entry.Key);
cursor = MessagePackSerializer.Serialize(buffer, cursor, entry.Value);
envPropertiesCount += 1;
}
}

cntFields += 1;
MessagePackSerializer.WriteUInt16(buffer, idxMapSizeEnvPropertiesPatch, envPropertiesCount);
}
cntFields += 1;
MessagePackSerializer.WriteUInt16(buffer, idxMapSizeEnvPropertiesPatch, envPropertiesCount);
}

var eventId = logRecord.EventId;
Expand Down
82 changes: 56 additions & 26 deletions test/OpenTelemetry.Exporter.Geneva.Tests/GenevaLogExporterTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -261,8 +261,15 @@ public void SerializationTestWithILoggerLogMethod(bool includeFormattedMessage)
_ = exporter.SerializeLogRecord(logRecordList[0]);
object fluentdData = MessagePack.MessagePackSerializer.Deserialize<object>(m_buffer.Value, MessagePack.Resolvers.ContractlessStandardResolver.Instance);
var body = GetField(fluentdData, "body");
string expectedBody = includeFormattedMessage ? "Formatted Message" : null;
Assert.Equal(expectedBody, body);
if (includeFormattedMessage)
{
Assert.Equal("Formatted Message", body);
}
else
{
Assert.Null(body);
}

Assert.Equal("Value1", GetField(fluentdData, "Key1"));
Assert.Equal("Value2", GetField(fluentdData, "Key2"));

Expand All @@ -284,8 +291,14 @@ public void SerializationTestWithILoggerLogMethod(bool includeFormattedMessage)
_ = exporter.SerializeLogRecord(logRecordList[0]);
fluentdData = MessagePack.MessagePackSerializer.Deserialize<object>(m_buffer.Value, MessagePack.Resolvers.ContractlessStandardResolver.Instance);
body = GetField(fluentdData, "body");
expectedBody = includeFormattedMessage ? "Formatted Message" : "somestringasdata";
Assert.Equal(expectedBody, body);
if (includeFormattedMessage)
{
Assert.Equal("Formatted Message", body);
}
else
{
Assert.Null(body);
}

// ARRANGE
logRecordList.Clear();
Expand All @@ -306,9 +319,42 @@ public void SerializationTestWithILoggerLogMethod(bool includeFormattedMessage)
fluentdData = MessagePack.MessagePackSerializer.Deserialize<object>(m_buffer.Value, MessagePack.Resolvers.ContractlessStandardResolver.Instance);
body = GetField(fluentdData, "body");

// Formatter is null, hence body is always the ToString() of the data
expectedBody = "somestringasdata";
Assert.Equal(expectedBody, body);
// Formatter is null, hence body is always null
Assert.Null(body);

// ARRANGE
logRecordList.Clear();

// ACT
// This is treated as Structured logging as the state can be converted to IReadOnlyList<KeyValuePair<string, object>>
logger.Log(
logLevel: LogLevel.Information,
eventId: default,
new List<KeyValuePair<string, object>>()
{
new KeyValuePair<string, object>("Key1", "Value1"),
},
exception: null,
formatter: (state, ex) => "Example formatted message.");

// VALIDATE
Assert.Single(logRecordList);
m_buffer = typeof(GenevaLogExporter).GetField("m_buffer", BindingFlags.NonPublic | BindingFlags.Static).GetValue(exporter) as ThreadLocal<byte[]>;
_ = exporter.SerializeLogRecord(logRecordList[0]);
fluentdData = MessagePack.MessagePackSerializer.Deserialize<object>(m_buffer.Value, MessagePack.Resolvers.ContractlessStandardResolver.Instance);
Assert.Equal("Value1", GetField(fluentdData, "Key1"));

body = GetField(fluentdData, "body");

// Only populate body if FormattedMessage is enabled
if (includeFormattedMessage)
{
Assert.Equal("Example formatted message.", body);
}
else
{
Assert.Null(body);
}
}
finally
{
Expand All @@ -333,7 +379,7 @@ public void SerializationTestWithILoggerLogMethod(bool includeFormattedMessage)
[InlineData(true, false, true)]
[InlineData(true, true, true)]
[Trait("Platform", "Any")]
public void SuccessfulSerialization(bool hasTableNameMapping, bool hasCustomFields, bool parseStateValues)
public void SerializationTestWithILoggerLogWithTemplates(bool hasTableNameMapping, bool hasCustomFields, bool parseStateValues)
{
string path = string.Empty;
Socket server = null;
Expand Down Expand Up @@ -427,29 +473,13 @@ public void SuccessfulSerialization(bool hasTableNameMapping, bool hasCustomFiel
logger.Log(LogLevel.Error, 101, "Log a {customField} and {property}", "CustomFieldValue", "PropertyValue");
logger.Log(LogLevel.Critical, 101, "Log a {customField} and {property}", "CustomFieldValue", "PropertyValue");
logger.LogInformation("Hello World!"); // unstructured logging

logger.Log(LogLevel.Information, default, "Hello World!", null, null); // unstructured logging using a non-extension method call

// logging custom state
// This is treated as structured logging as the state can be converted to IReadOnlyList<KeyValuePair<string, object>>
logger.Log(
LogLevel.Information,
default,
new List<KeyValuePair<string, object>>()
{
new KeyValuePair<string, object>("Key1", "Value1"),
new KeyValuePair<string, object>("Key2", "Value2"),
},
null,
(state, ex) => "Formatted Exception!");

logger.LogError(new InvalidOperationException("Oops! Food is spoiled!"), "Hello from {food} {price}.", "artichoke", 3.99);

var loggerWithDefaultCategory = loggerFactory.CreateLogger("DefaultCategory");
loggerWithDefaultCategory.LogInformation("Basic test");

// logRecordList should have two logRecord entries after the logger.LogInformation calls
Assert.Equal(14, logRecordList.Count);
// logRecordList should have 12 logRecord entries as there were 12 Log calls
Assert.Equal(12, logRecordList.Count);

var m_buffer = typeof(GenevaLogExporter).GetField("m_buffer", BindingFlags.NonPublic | BindingFlags.Static).GetValue(exporter) as ThreadLocal<byte[]>;

Expand Down