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

log4net layout: log latest scope value #367

Merged
merged 4 commits into from
Apr 4, 2024
Merged

log4net layout: log latest scope value #367

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
bd173be
Fix test by using case insensitive version of StartsWith().
andreycha Apr 2, 2024
a7cc6a7
Adjust test names.
andreycha Apr 2, 2024
0db9cdc
Put latest property value to metadata (requires latest log4net version).
andreycha Apr 2, 2024
2451b02
Update readme to reflect the latest state of generated events.
andreycha Apr 2, 2024
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
2 changes: 1 addition & 1 deletion src/Elastic.CommonSchema.Log4net/Elastic.CommonSchema.Log4net.csproj
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,6 @@
<ProjectReference Include="..\Elastic.CommonSchema\Elastic.CommonSchema.csproj" />
</ItemGroup>
<ItemGroup>
<PackageReference Include="log4net" Version="2.0.15" />
<PackageReference Include="log4net" Version="2.0.17" />
</ItemGroup>
</Project>
15 changes: 9 additions & 6 deletions src/Elastic.CommonSchema.Log4net/LoggingEventConverter.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,14 +78,17 @@ private static MetadataDictionary GetMetadata(LoggingEvent loggingEvent)

var value = properties[property];

// use string representation of stacks because:
// - if stack is empty then null is returned
// - if stack contains one item log4net anyway supports only string values
// - if stack contains several items then we need all of them
// use latest string representation of the value in the stack
if (value is ThreadContextStack tcs)
value = tcs.ToString();
{
var stackValue = tcs.Peek();
value = !string.IsNullOrEmpty(stackValue) ? stackValue : null;
}
else if (value is LogicalThreadContextStack ltcs)
value = ltcs.ToString();
{
var stackValue = ltcs.Peek();
value = !string.IsNullOrEmpty(stackValue) ? stackValue : null;
}

if (value != null)
metadata[property] = value;
Expand Down
55 changes: 37 additions & 18 deletions src/Elastic.CommonSchema.Log4net/README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -45,6 +45,7 @@ is supported and will directly set the appropriate ECS field.

Apart from [mandatory fields](https://www.elastic.co/guide/en/ecs/current/ecs-guidelines.html#_general_guidelines), the output contains additional data:

- `labels` is taken from `metadata` (string and boolean properties)
- `log.origin.file.name` is taken from `LocationInformation`
- `log.origin.file.line` is taken from `LocationInformation`
- `log.origin.function` is taken from `LocationInformation`
Expand All @@ -67,21 +68,7 @@ Sample log event output (formatted for readability):
"@timestamp": "2022-08-28T14:06:28.5121651+02:00",
"log.level": "INFO",
"message": "Hi! Welcome to example!",
"metadata": {
"global_property": "Example",
"message_template": "{0}! Welcome to example!"
"0": "Hi"
},
"ecs": {
"version": "8.3.1"
},
"event": {
"timezone": "Central European Time",
"created": "2022-08-28T14:06:28.5121651+02:00"
},
"host": {
"hostname": "HGU780D3"
},
"ecs.version": "8.6.0",
"log": {
"logger": "Elastic.CommonSchema.Log4net.Example.Program",
"original": null,
Expand All @@ -93,14 +80,46 @@ Sample log event output (formatted for readability):
"function": "Main"
}
},
"labels": {
"MessageTemplate": "{0}! Welcome to example!"
"0": "Hi"
},
"agent": {
"type": "Elastic.CommonSchema.Log4net.Example",
"version": "1.0.0.0"
},
"event": {
"created": "2024-04-02T17:43:55.3829964+02:00",
"timezone": "W. Europe Standard Time"
},
"host": {
"os": {
"full": "Microsoft Windows 10.0.22631",
"platform": "Win32NT",
"version": "10.0.22631.0"
},
"architecture": "X64",
"hostname": "HGU780D3",
"name": "HGU780D3"
},
"process": {
"thread": {
"id": 1
}
"name": "Elastic.CommonSchema.Log4net.Example",
"pid": 39652,
"thread.id": 17,
"thread.name": ".NET Long Running Task",
"title": ""
},
"service": {
"name": "Elastic.CommonSchema.Log4net.Example",
"type": "dotnet",
"version": "1.0.0.0"
},
"user": {
"domain": "company",
"name": "user"
},
"metadata": {
"GlobalAmountProperty": 3.14
}
}
```
Expand Down
149 changes: 73 additions & 76 deletions tests/Elastic.CommonSchema.Log4net.Tests/EcsFieldsAsPropertiesTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,95 +10,54 @@
using log4net.Core;
using Xunit;

namespace Elastic.CommonSchema.Log4net.Tests
{
[CollectionDefinition("EcsProperties", DisableParallelization = true)]
public class EcsFieldsAsPropertiesTests : LogTestsBase
{
private const string FixedTraceId = "my-trace-id";

[Fact]
public void EcsFieldInLogProperties()
{
void LogAndAssert(ILog log, Func<List<string>> getLogEvents)
{
log.Info("DummyText");

var logEvents = getLogEvents();
logEvents.Should().HaveCount(1);

var (_, info) = ToEcsEvents(logEvents).First();
info.TraceId.Should().Be(FixedTraceId);
}

// Testing these in one unit test because ThreadContext overwrites LogicalThreadContext which overwrites GlobalContext.
// Testing these in isolation introduces race issues when we remove the property

LogicalThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
try
{
TestLogger(LogAndAssert);
}
finally
{
LogicalThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
}

ThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
try
{
TestLogger(LogAndAssert);
}
finally
{
ThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
}
TestLogger((log, getLogEvents) =>
{
var loggingEvent = new LoggingEvent(GetType(), log.Logger.Repository, log.Logger.Name, Level.Info, "DummyText", null);
loggingEvent.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
log.Logger.Log(loggingEvent);

var logEvents = getLogEvents();
logEvents.Should().HaveCount(1);

var (_, info) = ToEcsEvents(logEvents).First();
info.TraceId.Should().Be(FixedTraceId);
});

GlobalContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
try
{
TestLogger(LogAndAssert);
}
finally
{
GlobalContext.Properties.Remove(LogTemplateProperties.TraceId);
}

}
namespace Elastic.CommonSchema.Log4net.Tests;

[CollectionDefinition("EcsProperties", DisableParallelization = true)]
public class EcsFieldsAsPropertiesTests : LogTestsBase
{
private const string FixedTraceId = "my-trace-id";

[Fact]
public void EcsFieldsInThreadContextStack() => TestLogger((log, getLogEvents) =>
[Fact]
public void EcsFieldInLogProperties()
{
void LogAndAssert(ILog log, Func<List<string>> getLogEvents)
{
using var _ = ThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);

log.Info("DummyText");

var logEvents = getLogEvents();
logEvents.Should().HaveCount(1);

var (_, info) = ToEcsEvents(logEvents).First();
info.TraceId.Should().Be(FixedTraceId);
});
}

// Testing these in one unit test because ThreadContext overwrites LogicalThreadContext which overwrites GlobalContext.
// Testing these in isolation introduces race issues when we remove the property

[Fact]
public void EcsFieldsInLogicalTheadContextStack() => TestLogger((log, getLogEvents) =>
LogicalThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
try
{
TestLogger(LogAndAssert);
}
finally
{
using var _ = LogicalThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);
LogicalThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
}

log.Info("DummyText");
ThreadContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
try
{
TestLogger(LogAndAssert);
}
finally
{
ThreadContext.Properties.Remove(LogTemplateProperties.TraceId);
}
TestLogger((log, getLogEvents) =>
{
var loggingEvent = new LoggingEvent(GetType(), log.Logger.Repository, log.Logger.Name, Level.Info, "DummyText", null);
loggingEvent.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
log.Logger.Log(loggingEvent);

var logEvents = getLogEvents();
logEvents.Should().HaveCount(1);
Expand All @@ -107,5 +66,43 @@ public void EcsFieldsInLogicalTheadContextStack() => TestLogger((log, getLogEven
info.TraceId.Should().Be(FixedTraceId);
});

GlobalContext.Properties[LogTemplateProperties.TraceId] = FixedTraceId;
try
{
TestLogger(LogAndAssert);
}
finally
{
GlobalContext.Properties.Remove(LogTemplateProperties.TraceId);
}

}

[Fact]
public void EcsFieldsInThreadContextStack() => TestLogger((log, getLogEvents) =>
{
using var _ = ThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);

log.Info("DummyText");

var logEvents = getLogEvents();
logEvents.Should().HaveCount(1);

var (_, info) = ToEcsEvents(logEvents).First();
info.TraceId.Should().Be(FixedTraceId);
});

[Fact]
public void EcsFieldsInLogicalTheadContextStack() => TestLogger((log, getLogEvents) =>
{
using var _ = LogicalThreadContext.Stacks[LogTemplateProperties.TraceId].Push(FixedTraceId);

log.Info("DummyText");

var logEvents = getLogEvents();
logEvents.Should().HaveCount(1);

var (_, info) = ToEcsEvents(logEvents).First();
info.TraceId.Should().Be(FixedTraceId);
});
}
52 changes: 25 additions & 27 deletions tests/Elastic.CommonSchema.Log4net.Tests/LogTestsBase.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,41 +10,39 @@
using log4net.Core;
using log4net.Repository.Hierarchy;

namespace Elastic.CommonSchema.Log4net.Tests;

namespace Elastic.CommonSchema.Log4net.Tests
public abstract class LogTestsBase
{
public abstract class LogTestsBase
{
private static readonly object _lock = new();
protected List<(string Json, EcsDocument Base)> ToEcsEvents(List<string> logEvents) =>
logEvents.Select(s => (s, EcsDocument.Deserialize(s)))
.ToList();
private static readonly object _lock = new();
protected List<(string Json, EcsDocument Base)> ToEcsEvents(List<string> logEvents) =>
logEvents.Select(s => (s, EcsDocument.Deserialize(s)))
.ToList();

protected void TestLogger(Action<ILog, Func<List<string>>> act)
protected void TestLogger(Action<ILog, Func<List<string>>> act)
{
lock (_lock)
{
lock (_lock)
var repositoryId = Guid.NewGuid().ToString();
var hierarchy = (Hierarchy)LogManager.CreateRepository(repositoryId);
var appender = new TestAppender
{
var repositoryId = Guid.NewGuid().ToString();
var hierarchy = (Hierarchy)LogManager.CreateRepository(repositoryId);
var appender = new TestAppender
{
Layout = new EcsLayout()
};
hierarchy.Root.AddAppender(appender);
hierarchy.Root.Level = Level.All;
hierarchy.Configured = true;

List<string> GetAndValidateLogEvents()
{
foreach (var log in appender.Events)
Spec.Validate(log);
Layout = new EcsLayout()
};
hierarchy.Root.AddAppender(appender);
hierarchy.Root.Level = Level.All;
hierarchy.Configured = true;

return appender.Events;
}
List<string> GetAndValidateLogEvents()
{
foreach (var log in appender.Events)
Spec.Validate(log);

var log = LogManager.GetLogger(repositoryId, GetType().Name);
act(log, GetAndValidateLogEvents);
return appender.Events;
}

var log = LogManager.GetLogger(repositoryId, GetType().Name);
act(log, GetAndValidateLogEvents);
}
}
}
Loading
Loading