Skip to content

Commit

Permalink
[Logs-branch] Port scope buffering fix to logs branch (#3736)
Browse files Browse the repository at this point in the history 
* [Logs] Fix buffered log scopes being reused (#3731)

* Fix buffered log scopes being reused.

* CHANGELOG update.

* Test fixes.

Co-authored-by: Cijo Thomas <[email protected]>

* Update log scope buffering fix for new api.

Co-authored-by: Cijo Thomas <[email protected]>
  • Loading branch information
@CodeBlanch @cijothomas
CodeBlanch and cijothomas authored Oct 6, 2022
1 parent 9c3f53f commit 9aebae2
Show file tree
Hide file tree
Showing 8 changed files with 127 additions and 37 deletions.
5 changes: 5 additions & 0 deletions src/OpenTelemetry/CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,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
5 changes: 3 additions & 2 deletions src/OpenTelemetry/Logs/ILogger/OpenTelemetryLogger.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -75,6 +75,8 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
iloggerData.CategoryName = this.categoryName;
iloggerData.EventId = eventId;
iloggerData.Exception = exception;
iloggerData.ScopeProvider = iloggerProvider.IncludeScopes ? this.ScopeProvider : null;
iloggerData.BufferedScopes = null;

ref LogRecordData data = ref record.Data;

Expand Down Expand Up @@ -114,9 +116,8 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
iloggerData.FormattedMessage = iloggerProvider.IncludeFormattedMessage ? formatter?.Invoke(state, exception) : null;
}

record.ScopeProvider = iloggerProvider.IncludeScopes ? this.ScopeProvider : null;
processor.OnEnd(record);
record.ScopeProvider = null;
iloggerData.ScopeProvider = null;

// Attempt to return the LogRecord to the pool. This will no-op
// if a batch exporter has added a reference.
Expand Down
54 changes: 39 additions & 15 deletions src/OpenTelemetry/Logs/LogRecord.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -34,7 +34,7 @@ public sealed class LogRecord
internal LogRecordData Data;
internal LogRecordILoggerData ILoggerData;
internal List<KeyValuePair<string, object?>>? AttributeStorage;
internal List<object?>? BufferedScopes;
internal List<object?>? ScopeStorage;
internal int PoolReferenceCount = int.MaxValue;

private static readonly Action<object?, List<object?>> AddScopeToBufferedList = (object? scope, List<object?> state) =>
Expand Down Expand Up @@ -75,6 +75,7 @@ internal LogRecord(
EventId = eventId,
Exception = exception,
State = state,
ScopeProvider = scopeProvider,
};

if (stateValues != null && stateValues.Count > 0)
Expand All @@ -90,8 +91,6 @@ internal LogRecord(
this.InstrumentationScope = null;

this.Attributes = stateValues;

this.ScopeProvider = scopeProvider;
}

/// <summary>
Expand Down Expand Up @@ -262,8 +261,6 @@ public LogRecordSeverity? Severity
/// </summary>
public InstrumentationScope? InstrumentationScope { get; internal set; }

internal IExternalScopeProvider? ScopeProvider { get; set; }

/// <summary>
/// Executes callback for each currently active scope objects in order
/// of creation. All callbacks are guaranteed to be called inline from
Expand All @@ -281,16 +278,16 @@ public void ForEachScope<TState>(Action<LogRecordScope, TState> callback, TState

var forEachScopeState = new ScopeForEachState<TState>(callback, state);

if (this.BufferedScopes != null)
if (this.ILoggerData.BufferedScopes != null)
{
foreach (object? scope in this.BufferedScopes)
foreach (object? scope in this.ILoggerData.BufferedScopes)
{
ScopeForEachState<TState>.ForEachScope(scope, forEachScopeState);
}
}
else
{
this.ScopeProvider?.ForEachScope(ScopeForEachState<TState>.ForEachScope, forEachScopeState);
this.ILoggerData.ScopeProvider?.ForEachScope(ScopeForEachState<TState>.ForEachScope, forEachScopeState);
}
}

Expand Down Expand Up @@ -330,13 +327,14 @@ internal LogRecord Copy()
// directly below.
this.BufferLogScopes();

return new()
var copy = new LogRecord()
{
Data = this.Data,
ILoggerData = this.ILoggerData,
ILoggerData = this.ILoggerData.Copy(),
Attributes = this.Attributes == null ? null : new List<KeyValuePair<string, object?>>(this.Attributes),
BufferedScopes = this.BufferedScopes == null ? null : new List<object?>(this.BufferedScopes),
};

return copy;
}

/// <summary>
Expand Down Expand Up @@ -370,16 +368,19 @@ private void BufferLogAttributes()
/// </summary>
private void BufferLogScopes()
{
if (this.ScopeProvider == null)
var scopeProvider = this.ILoggerData.ScopeProvider;
if (scopeProvider == null)
{
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);
scopeProvider.ForEachScope(AddScopeToBufferedList, scopeStorage);

this.ScopeProvider = null;
this.ILoggerData.ScopeProvider = null;

this.ILoggerData.BufferedScopes = scopeStorage;
}

internal struct LogRecordILoggerData
Expand All @@ -390,6 +391,29 @@ internal struct LogRecordILoggerData
public string? FormattedMessage;
public Exception? Exception;
public object? State;
public IExternalScopeProvider? ScopeProvider;
public List<object?>? BufferedScopes;

public LogRecordILoggerData Copy()
{
var copy = new LogRecordILoggerData
{
TraceState = this.TraceState,
CategoryName = this.CategoryName,
EventId = this.EventId,
FormattedMessage = this.FormattedMessage,
Exception = this.Exception,
State = this.State,
};

var bufferedScopes = this.BufferedScopes;
if (bufferedScopes != null)
{
copy.BufferedScopes = new List<object?>(bufferedScopes);
}

return copy;
}
}

private readonly struct ScopeForEachState<TState>
Expand Down
10 changes: 5 additions & 5 deletions src/OpenTelemetry/Logs/Pool/LogRecordPoolHelper.cs
View file
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
6 changes: 3 additions & 3 deletions test/OpenTelemetry.Tests/Logs/BatchLogRecordExportProcessorTests.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -41,7 +41,7 @@ public void StateValuesAndScopeBufferingTest()

var state = new LogRecordTest.DisposingState("Hello world");

logRecord.ScopeProvider = scopeProvider;
logRecord.ILoggerData.ScopeProvider = scopeProvider;
logRecord.StateValues = state;

processor.OnEnd(logRecord);
Expand All @@ -50,10 +50,10 @@ public void StateValuesAndScopeBufferingTest()

Assert.Empty(exportedItems);

Assert.Null(logRecord.ScopeProvider);
Assert.Null(logRecord.ILoggerData.ScopeProvider);
Assert.False(ReferenceEquals(state, logRecord.StateValues));
Assert.NotNull(logRecord.AttributeStorage);
Assert.NotNull(logRecord.BufferedScopes);
Assert.NotNull(logRecord.ILoggerData.BufferedScopes);

KeyValuePair<string, object> actualState = logRecord.StateValues[0];

Expand Down
12 changes: 6 additions & 6 deletions test/OpenTelemetry.Tests/Logs/LogRecordSharedPoolTests.cs
View file
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
Original file line number Diff line number Diff line change
Expand Up @@ -934,6 +934,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 @@ -1084,5 +1117,32 @@ private class CustomState

public string Property3 { 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();
}
}
}
}
}
12 changes: 6 additions & 6 deletions test/OpenTelemetry.Tests/Logs/LogRecordThreadStaticPoolTests.cs
View file
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);
}
}
}

0 comments on commit 9aebae2

Please sign in to comment.