Skip to content

[Logs] Fix buffered log scopes being reused #3731

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

Merged
merged 4 commits into from
Oct 5, 2022
Merged

[Logs] Fix buffered log scopes being reused #3731

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
70c4205
Fix buffered log scopes being reused.
CodeBlanch Oct 5, 2022
cf2d966
CHANGELOG update.
CodeBlanch Oct 5, 2022
88cd258
Test fixes.
CodeBlanch Oct 5, 2022
0ab4d51
Merge branch 'main' into logs-scope-buffering-fix
cijothomas Oct 5, 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
5 changes: 5 additions & 0 deletions src/OpenTelemetry/CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,11 @@

## Unreleased

* Fixed an issue where `LogRecord.ForEachScope` may return scopes from a
previous log if accessed in a custom processor before
`BatchLogRecordExportProcessor.OnEnd` is fired.
([#3731](https://github.com/open-telemetry/opentelemetry-dotnet/pull/3731))

## 1.4.0-beta.1

Released 2022-Sep-29
Expand Down
7 changes: 5 additions & 2 deletions src/OpenTelemetry/Logs/LogRecord.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,6 +33,7 @@ public sealed class LogRecord
{
internal LogRecordData Data;
internal List<KeyValuePair<string, object?>>? AttributeStorage;
internal List<object?>? ScopeStorage;
internal List<object?>? BufferedScopes;
internal int PoolReferenceCount = int.MaxValue;

Expand Down Expand Up @@ -309,11 +310,13 @@ private void BufferLogScopes()
return;
}

List<object?> scopes = this.BufferedScopes ??= new List<object?>(LogRecordPoolHelper.DefaultMaxNumberOfScopes);
var scopeStorage = this.ScopeStorage ??= new List<object?>(LogRecordPoolHelper.DefaultMaxNumberOfScopes);

this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopes);
this.ScopeProvider.ForEachScope(AddScopeToBufferedList, scopeStorage);

this.ScopeProvider = null;

this.BufferedScopes = scopeStorage;
}

private readonly struct ScopeForEachState<TState>
Expand Down
1 change: 1 addition & 0 deletions src/OpenTelemetry/Logs/OpenTelemetryLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -60,6 +60,7 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
record.ScopeProvider = provider.IncludeScopes ? this.ScopeProvider : null;
record.State = provider.ParseStateValues ? null : state;
record.StateValues = provider.ParseStateValues ? ParseState(record, state) : null;
record.BufferedScopes = null;

ref LogRecordData data = ref record.Data;

Expand Down
10 changes: 5 additions & 5 deletions src/OpenTelemetry/Logs/Pool/LogRecordPoolHelper.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -41,19 +41,19 @@ underlying array (capacity). */
}
}

var bufferedScopes = logRecord.BufferedScopes;
if (bufferedScopes != null)
var scopeStorage = logRecord.ScopeStorage;
if (scopeStorage != null)
{
if (bufferedScopes.Count > DefaultMaxNumberOfScopes)
if (scopeStorage.Count > DefaultMaxNumberOfScopes)
{
// Don't allow the pool to grow unconstained.
logRecord.BufferedScopes = null;
logRecord.ScopeStorage = null;
}
else
{
/* List<T>.Clear sets the count/size to 0 but it maintains the
underlying array (capacity). */
bufferedScopes.Clear();
scopeStorage.Clear();
}
}
}
Expand Down
12 changes: 6 additions & 6 deletions test/OpenTelemetry.Tests/Logs/LogRecordSharedPoolTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -136,19 +136,19 @@ public void ClearTests()
new KeyValuePair<string, object?>("key1", "value1"),
new KeyValuePair<string, object?>("key2", "value2"),
};
logRecord1.BufferedScopes = new List<object?>(8) { null, null };
logRecord1.ScopeStorage = new List<object?>(8) { null, null };

pool.Return(logRecord1);

Assert.Empty(logRecord1.AttributeStorage);
Assert.Equal(16, logRecord1.AttributeStorage.Capacity);
Assert.Empty(logRecord1.BufferedScopes);
Assert.Equal(8, logRecord1.BufferedScopes.Capacity);
Assert.Empty(logRecord1.ScopeStorage);
Assert.Equal(8, logRecord1.ScopeStorage.Capacity);

logRecord1 = pool.Rent();

Assert.NotNull(logRecord1.AttributeStorage);
Assert.NotNull(logRecord1.BufferedScopes);
Assert.NotNull(logRecord1.ScopeStorage);

for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfAttributes; i++)
{
Expand All @@ -157,13 +157,13 @@ public void ClearTests()

for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfScopes; i++)
{
logRecord1.BufferedScopes!.Add(null);
logRecord1.ScopeStorage!.Add(null);
}

pool.Return(logRecord1);

Assert.Null(logRecord1.AttributeStorage);
Assert.Null(logRecord1.BufferedScopes);
Assert.Null(logRecord1.ScopeStorage);
}

[Theory]
Expand Down
60 changes: 60 additions & 0 deletions test/OpenTelemetry.Tests/Logs/LogRecordTest.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -771,6 +771,39 @@ public void DisposingStateTest()
Assert.Same("Hello world", actualState.Value);
}

[Theory]
[InlineData(true)]
[InlineData(false)]
public void ReusedLogRecordScopeTest(bool buffer)
{
var processor = new ScopeProcessor(buffer);

using var loggerFactory = LoggerFactory.Create(builder =>
{
builder.AddOpenTelemetry(options =>
{
options.IncludeScopes = true;
options.AddProcessor(processor);
});
});

var logger = loggerFactory.CreateLogger("TestLogger");

using (var scope1 = logger.BeginScope("scope1"))
{
logger.LogInformation("message1");
}

using (var scope2 = logger.BeginScope("scope2"))
{
logger.LogInformation("message2");
}

Assert.Equal(2, processor.Scopes.Count);
Assert.Equal("scope1", processor.Scopes[0]);
Assert.Equal("scope2", processor.Scopes[1]);
}

private static ILoggerFactory InitializeLoggerFactory(out List<LogRecord> exportedItems, Action<OpenTelemetryLoggerOptions> configure = null)
{
var items = exportedItems = new List<LogRecord>();
Expand Down Expand Up @@ -915,6 +948,33 @@ private class CustomState
{
public string Property { get; set; }
}

private class ScopeProcessor : BaseProcessor<LogRecord>
{
private readonly bool buffer;

public ScopeProcessor(bool buffer)
{
this.buffer = buffer;
}

public List<object> Scopes { get; } = new();

public override void OnEnd(LogRecord data)
{
data.ForEachScope<object>(
(scope, state) =>
{
this.Scopes.Add(scope.Scope);
},
null);

if (this.buffer)
{
data.Buffer();
}
}
}
}
}
#endif
12 changes: 6 additions & 6 deletions test/OpenTelemetry.Tests/Logs/LogRecordThreadStaticPoolTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -57,19 +57,19 @@ public void ClearTests()
new KeyValuePair<string, object?>("key1", "value1"),
new KeyValuePair<string, object?>("key2", "value2"),
};
logRecord1.BufferedScopes = new List<object?>(8) { null, null };
logRecord1.ScopeStorage = new List<object?>(8) { null, null };

LogRecordThreadStaticPool.Instance.Return(logRecord1);

Assert.Empty(logRecord1.AttributeStorage);
Assert.Equal(16, logRecord1.AttributeStorage.Capacity);
Assert.Empty(logRecord1.BufferedScopes);
Assert.Equal(8, logRecord1.BufferedScopes.Capacity);
Assert.Empty(logRecord1.ScopeStorage);
Assert.Equal(8, logRecord1.ScopeStorage.Capacity);

logRecord1 = LogRecordThreadStaticPool.Instance.Rent();

Assert.NotNull(logRecord1.AttributeStorage);
Assert.NotNull(logRecord1.BufferedScopes);
Assert.NotNull(logRecord1.ScopeStorage);

for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfAttributes; i++)
{
Expand All @@ -78,13 +78,13 @@ public void ClearTests()

for (int i = 0; i <= LogRecordPoolHelper.DefaultMaxNumberOfScopes; i++)
{
logRecord1.BufferedScopes!.Add(null);
logRecord1.ScopeStorage!.Add(null);
}

LogRecordThreadStaticPool.Instance.Return(logRecord1);

Assert.Null(logRecord1.AttributeStorage);
Assert.Null(logRecord1.BufferedScopes);
Assert.Null(logRecord1.ScopeStorage);
}
}
}