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.

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

[logs] Mitigate unwanted object creation during configuration reload #5514

Merged
merged 19 commits into from
Apr 12, 2024
Merged
Show file tree
Hide file tree
Changes from 13 commits
Commits
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
1 change: 1 addition & 0 deletions OpenTelemetry.sln
Original file line number Diff line number Diff line change
Expand Up @@ -300,6 +300,7 @@ Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Options", "Options", "{4949
ProjectSection(SolutionItems) = preProject
src\Shared\Options\DelegatingOptionsFactory.cs = src\Shared\Options\DelegatingOptionsFactory.cs
src\Shared\Options\DelegatingOptionsFactoryServiceCollectionExtensions.cs = src\Shared\Options\DelegatingOptionsFactoryServiceCollectionExtensions.cs
src\Shared\Options\SingletonOptionsMonitor.cs = src\Shared\Options\SingletonOptionsMonitor.cs
EndProjectSection
EndProject
Project("{2150E333-8FDC-42A3-9474-1A3956D46DE8}") = "Shims", "Shims", "{A0CB9A10-F22D-4E66-A449-74B3D0361A9C}"
Expand Down
5 changes: 5 additions & 0 deletions src/OpenTelemetry/CHANGELOG.md
Original file line number Diff line number Diff line change
Expand Up @@ -2,6 +2,11 @@

## Unreleased

* Fixed an issue in Logging where unwanted objects (processors, exporters, etc.)
could be created inside delegates automatically executed by the Options API
during configuration reload.
([#5514](https://github.com/open-telemetry/opentelemetry-dotnet/pull/5514))

## 1.8.0

Released 2024-Apr-02
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -117,6 +117,7 @@ public OpenTelemetryLoggerOptions SetResourceBuilder(ResourceBuilder resourceBui
Guard.ThrowIfNull(resourceBuilder);

this.ResourceBuilder = resourceBuilder;

return this;
}

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -173,6 +173,12 @@ private static ILoggingBuilder AddOpenTelemetryInternal(
// Note: This will bind logger options element (e.g., "Logging:OpenTelemetry") to OpenTelemetryLoggerOptions
RegisterLoggerProviderOptions(services);

// Note: We disable built-in IOptionsMonitor features for
// OpenTelemetryLoggerOptions as a workaround to prevent unwanted
// objects (processors, exporters, etc.) being created by
// configuration delegates during reload of IConfiguration.
services.DisableOptionsMonitor<OpenTelemetryLoggerOptions>();
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you need all this infrastructure? Instead, can't you just use IOptions instead of IOptionsMonitor everywhere?

cc @davidfowl @halter73 @tarekgh

Copy link
Member Author

@CodeBlanch CodeBlanch Apr 10, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This PR is changing OTel to use IOptions (instead of IOptionsMonitor) for OpenTelemetryLoggerOptions. But my thinking is, we can't prevent users from accessing IOptionsMonitor and we can't prevent some future dev from re-introducing it. The infrastructure here is so we can make it deterministic and have unit tests validating it will work correctly should IOptionsMonitor<OpenTelemetryLoggerOptions> sneak into the process anywhere.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

  1. Do we really expect someone outside of OpenTelemetry to try to get an IOptionsMonitor<OpenTelemetryLoggerOptions>? What would they do with it?
  2. If someone does explicitly use IOptionsMonitor, don't they want updates as the config changes? That's why they choose IOptionsMonitor.

Would it be better to just fail in this case if we explicitly want to block it?

Copy link

@halter73 halter73 Apr 10, 2024

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While it's unclear why anyone else would need to monitor OpenTelemetryLoggerOptions for changes when the core library won't react to changes itself, it feels like code smell to go out of our way prevent it by replacing core options services and changing how they work. What if someone wants to just new up an OpenTelemetryLoggerOptions and calls options.AddProcessor(new BatchLogRecordExportProcessor(new OtlpLogExporter(new())) in a test or something? Should they know that this will spawn a thread that will never get stopped?

I think the core issue is how BatchExportProcessor<T> spawns a thread in its constructor.

this.exporterThread = new Thread(this.ExporterProc)
{
IsBackground = true,
Name = $"OpenTelemetry-{nameof(BatchExportProcessor<T>)}-{exporter.GetType().Name}",
};
this.exporterThread.Start();

I know that this API has already shipped, so adding a StartAsync method or something like that may not be feasible, but could you unseal OnStart in the base class and start the thread there? Or lazily start the thread some other way? If not, should we deprecate the BaseProcessor<LogRecord> overload of AddProcessor() and tell people to use the Func<IServiceProvider, BaseProcessor<LogRecord> overload instead?

If we have to override the IOptionsMonitor<OpenTelemetryLoggerOptions>, I agree with @eerhardt that it should throw from everything with a NotSupportedException indicating that reloading OpenTelemetryLoggerOptions is completely unsupported.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I just pushed updates so that accessing OpenTelemetryLoggerOptions via IOptionsMonitor or IOptionsSnapshot will result in a NotSupportedException. Technically breaking, but I think the impact will be very low.

If not, should we deprecate the BaseProcessor overload of AddProcessor() and tell people to use the Func<IServiceProvider, BaseProcessor overload instead?

This is the plan yes (more or less)! We have another API for building logging pipelines which does not suffer from these issues. The plan is to make that a stable API (#5442) and then we can Obsolete these AddProcessor methods on OpenTelemetryLoggerOptions.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good discussion and thanks for the suggestions/ideas!

While I agree with most parts here, I suggest that we focus on "mitigate the issue quickly with minimum change/risk" instead of trying to get a complete solution in this PR. I'm specifically concerned about throwing exception in this PR. I suggest that we take the feedback and think about exception or other approaches in a follow up PR once the mitigation/hotfix is released.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I suggest that we focus on "mitigate the issue quickly with minimum change/risk" instead of trying to get a complete solution in this PR

So that means just changing our references of IOptionsMonitor<OpenTelemetryLoggerOptions> => IOptions<OpenTelemetryLoggerOptions>? Don't do anything to prevent users from accessing IOptionsMonitor. Am I understanding that correctly?

If so, I agree that since this is a hotfix, keep it scoped to resolving the issue at hand.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't have strong opinion regarding the actual solution (e.g. IOptions/IOptionsMonitor, singleton, etc.), as long as it meets the two conditions #5514 (review) I'm good 👍.


/* Note: This ensures IConfiguration is available when using
* IServiceCollections NOT attached to a host. For example when
* performing:
Expand All @@ -192,7 +198,7 @@ private static ILoggingBuilder AddOpenTelemetryInternal(
var loggingBuilder = new LoggerProviderBuilderBase(services).ConfigureBuilder(
(sp, logging) =>
{
var options = sp.GetRequiredService<IOptionsMonitor<OpenTelemetryLoggerOptions>>().CurrentValue;
var options = sp.GetRequiredService<IOptions<OpenTelemetryLoggerOptions>>().Value;

if (options.ResourceBuilder != null)
{
Expand Down Expand Up @@ -249,7 +255,7 @@ private static ILoggingBuilder AddOpenTelemetryInternal(

return new OpenTelemetryLoggerProvider(
provider,
sp.GetRequiredService<IOptionsMonitor<OpenTelemetryLoggerOptions>>().CurrentValue,
sp.GetRequiredService<IOptions<OpenTelemetryLoggerOptions>>().Value,
disposeProvider: false);
}));

Expand Down
1 change: 1 addition & 0 deletions src/Shared/Options/DelegatingOptionsFactory.cs
Original file line number Diff line number Diff line change
Expand Up @@ -81,6 +81,7 @@ public DelegatingOptionsFactory(
public TOptions Create(string name)
{
TOptions options = this.optionsFactoryFunc(this.configuration, name);

foreach (IConfigureOptions<TOptions> setup in _setups)
{
if (setup is IConfigureNamedOptions<TOptions> namedSetup)
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -62,6 +62,21 @@ public static IServiceCollection RegisterOptionsFactory<T>(
sp.GetServices<IValidateOptions<T>>());
});

return services!;
}

#if NET6_0_OR_GREATER
public static IServiceCollection DisableOptionsMonitor<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicConstructors)] T>(
#else
public static IServiceCollection DisableOptionsMonitor<T>(
#endif
this IServiceCollection services)
where T : class
{
Debug.Assert(services != null, "services was null");

services!.TryAddSingleton<IOptionsMonitor<T>, SingletonOptionsMonitor<T>>();

return services!;
}
}
31 changes: 31 additions & 0 deletions src/Shared/Options/SingletonOptionsMonitor.cs
Original file line number Diff line number Diff line change
@@ -0,0 +1,31 @@
// Copyright The OpenTelemetry Authors
// SPDX-License-Identifier: Apache-2.0

#nullable enable

#if NET6_0_OR_GREATER
using System.Diagnostics.CodeAnalysis;
#endif

namespace Microsoft.Extensions.Options;

#if NET6_0_OR_GREATER
internal sealed class SingletonOptionsMonitor<[DynamicallyAccessedMembers(DynamicallyAccessedMemberTypes.PublicParameterlessConstructor)] TOptions> : IOptionsMonitor<TOptions>
#else
internal sealed class SingletonOptionsMonitor<TOptions> : IOptionsMonitor<TOptions>
#endif
where TOptions : class
{
private readonly TOptions instance;

public SingletonOptionsMonitor(IOptions<TOptions> options)
{
this.instance = options.Value;
}

public TOptions CurrentValue => this.instance;

public TOptions Get(string? name) => this.instance;

public IDisposable? OnChange(Action<TOptions, string?> listener) => null;
}
108 changes: 106 additions & 2 deletions test/OpenTelemetry.Tests/Logs/OpenTelemetryLoggingExtensionsTests.cs
Original file line number Diff line number Diff line change
Expand Up @@ -7,6 +7,7 @@
using Microsoft.Extensions.Configuration;
using Microsoft.Extensions.DependencyInjection;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Options;
using Xunit;

namespace OpenTelemetry.Logs.Tests;
Expand Down Expand Up @@ -297,11 +298,114 @@ public void CircularReferenceTest(bool requestLoggerProviderDirectly)
Assert.True(loggerProvider.Processor is TestLogProcessorWithILoggerFactoryDependency);
}

private class TestLogProcessor : BaseProcessor<LogRecord>
[Theory]
[InlineData(true)]
[InlineData(false)]
public void OptionReloadingTest(bool useOptionsMonitor)
{
var defaultInstance = new OpenTelemetryLoggerOptions();

OpenTelemetryLoggerOptions? lastOptions = null;
var processors = new List<TestLogProcessor>();
var delegateInvocationCount = 0;

var root = new ConfigurationBuilder().Build();

var services = new ServiceCollection();

services.AddSingleton<IConfiguration>(root);

services.AddLogging(logging => logging
.AddConfiguration(root.GetSection("logging"))
.AddOpenTelemetry(options =>
{
Assert.Equal(defaultInstance.IncludeFormattedMessage, options.IncludeFormattedMessage);
Assert.Equal(defaultInstance.IncludeScopes, options.IncludeScopes);
Assert.Equal(defaultInstance.ParseStateValues, options.ParseStateValues);
Assert.Equal(defaultInstance.IncludeAttributes, options.IncludeAttributes);
Assert.Equal(defaultInstance.IncludeTraceState, options.IncludeTraceState);

if (lastOptions != null)
{
Assert.True(ReferenceEquals(options, lastOptions));
}

lastOptions = options;

delegateInvocationCount++;
var processor = new TestLogProcessor();
processors.Add(processor);
options.AddProcessor(processor);

options.IncludeFormattedMessage = !defaultInstance.IncludeFormattedMessage;
options.IncludeScopes = !defaultInstance.IncludeScopes;
options.ParseStateValues = !defaultInstance.ParseStateValues;
options.IncludeAttributes = !defaultInstance.IncludeAttributes;
options.IncludeTraceState = !defaultInstance.IncludeTraceState;
}));

using var sp = services.BuildServiceProvider();

if (useOptionsMonitor)
{
var optionsMonitor = sp.GetRequiredService<IOptionsMonitor<OpenTelemetryLoggerOptions>>();

// Note: Change notification is disabled for OpenTelemetryLoggerOptions.
Assert.Null(optionsMonitor.OnChange((o, n) => Assert.Fail()));
}

var loggerFactory = sp.GetRequiredService<ILoggerFactory>();

Assert.Equal(1, delegateInvocationCount);
Assert.Single(processors);
Assert.DoesNotContain(processors, p => p.Disposed);

root.Reload();

Assert.Equal(1, delegateInvocationCount);
Assert.Single(processors);
Assert.DoesNotContain(processors, p => p.Disposed);
}

[Fact]
public void MixedOptionsUsageTest()
{
var root = new ConfigurationBuilder().Build();

var services = new ServiceCollection();

services.AddSingleton<IConfiguration>(root);

services.AddLogging(logging => logging
.AddConfiguration(root.GetSection("logging"))
.AddOpenTelemetry(options =>
{
options.AddProcessor(new TestLogProcessor());
}));

using var sp = services.BuildServiceProvider();

var loggerFactory = sp.GetRequiredService<ILoggerFactory>();

var optionsMonitor = sp.GetRequiredService<IOptionsMonitor<OpenTelemetryLoggerOptions>>().CurrentValue;
var options = sp.GetRequiredService<IOptions<OpenTelemetryLoggerOptions>>().Value;

Assert.True(ReferenceEquals(options, optionsMonitor));
}

private sealed class TestLogProcessor : BaseProcessor<LogRecord>
{
public bool Disposed;

protected override void Dispose(bool disposing)
{
this.Disposed = true;

base.Dispose(disposing);
}
}

private class TestLogProcessorWithILoggerFactoryDependency : BaseProcessor<LogRecord>
private sealed class TestLogProcessorWithILoggerFactoryDependency : BaseProcessor<LogRecord>
{
private readonly ILogger logger;

Expand Down