Fix: Logs could be exported via ConsoleExporter after LoggerFactory is disposed #1848

[jackyshang12321]

Fixes #1848

Changes

The ConsoleExporter will stop exporting data after it's disposed
If it's the first consumption after disposal, an error message will be output to user, along with the stack trace where the disposal happened, and subsequent calls will not output any data.

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: jackyshang12321 / name: Jacky Shang (51bc047, 5b6cc57)

[codecov]

Codecov Report

Merging #3578 (915bce2) into main (0447871) will increase coverage by 0.23%.
The diff coverage is n/a.

Additional details and impacted files

@@            Coverage Diff             @@
##             main    #3578      +/-   ##
==========================================
+ Coverage   87.09%   87.33%   +0.23%     
==========================================
  Files         280      280              
  Lines       10081    10081              
==========================================
+ Hits         8780     8804      +24     
+ Misses       1301     1277      -24     

Impacted Files	Coverage Δ
...Telemetry/Internal/SelfDiagnosticsEventListener.cs	96.87% <0.00%> (-0.79%)	⬇️
...metryProtocol/Implementation/ActivityExtensions.cs	95.05% <0.00%> (+3.29%)	⬆️
...emetry.Api/Internal/OpenTelemetryApiEventSource.cs	82.35% <0.00%> (+5.88%)	⬆️
...tation/OpenTelemetryProtocolExporterEventSource.cs	85.00% <0.00%> (+10.00%)	⬆️
...xporter.OpenTelemetryProtocol/OtlpTraceExporter.cs	77.27% <0.00%> (+40.90%)	⬆️
...entation/ExportClient/OtlpGrpcTraceExportClient.cs	78.57% <0.00%> (+42.85%)	⬆️

[reyang]

I think the 1st step is to define the expected behavior and agree on it. @jackyshang12321 would you update the PR description and explain what exact behavior should we expect?

After we agree on the design, we can move to the coding part (which should be fairly straightforward).

[jackyshang12321]

I think the 1st step is to define the expected behavior and agree on it. @jackyshang12321 would you update the PR description and explain what exact behavior should we expect?

After we agree on the design, we can move to the coding part (which should be fairly straightforward).

Hi @reyang , thanks so much for the feedback, PR comment updated, please have a looks, thanks

[reyang]

I think the 1st step is to define the expected behavior and agree on it. @jackyshang12321 would you update the PR description and explain what exact behavior should we expect?
After we agree on the design, we can move to the coding part (which should be fairly straightforward).

Hi @reyang , thanks so much for the feedback, PR comment updated, please have a looks, thanks

What are the other options you've considered? What's the pros/cons? What's the design principle here? (e.g. usability, maintain 100% same with existing .NET Console Log Provider, or something else).

[jackyshang12321]

I think the 1st step is to define the expected behavior and agree on it. @jackyshang12321 would you update the PR description and explain what exact behavior should we expect?
After we agree on the design, we can move to the coding part (which should be fairly straightforward).

Hi @reyang , thanks so much for the feedback, PR comment updated, please have a looks, thanks

What are the other options you've considered? What's the pros/cons? What's the design principle here? (e.g. usability, maintain 100% same with existing .NET Console Log Provider, or something else).

Hi @reyang , thank you so much for such a quick reply and leading thought.

I've repeatedly thought about the two solutions you mentioned. One is that when the logger factory is destroyed, the console will no longer output any log.
My concern about this is that those applications that have already used the open-telemetry console exporter and are running, they may lose some important information.
In particular, the logger factory is not something the programmer wants to actively disable.

In this case, if we can give a special message to inform the user that the logger factory has been destroyed, the log information may not be output in subsequent open-telemetry updates, that may be more friendly to running applications and users.

One concern is that just modifying the console exporter will lead to inconsistent behavior with other exporters, but we can start from console exporter and roll out to others later.

Another thought on this question is, when an object of the upper/parent layer is destroyed, the object derived or generated by it should also be destroyed (otherwise it will cause some problems, such as resource or memory leaks), which is a reasonable and expected behavior.
So to that point, I think it's the correct behavior to disable the console exporter when the logger factory is disabled.

I'm not sure if there are other more reasonable solutions and ways to deal with this problem
One question I'm still thinking about is how to notify users in a more open-telemetry way

[reyang]

Here is my thinking:

1. As stated in the official doc, Console Exporter is intended for learning and dev inner-loop. It is not designed/intended for production. So any change on the output behavior is very unlikely to cause any production regressions.
2. I think the main usage of Console Exporter is to help the developers to learn and discover potential issues at early states - with that said, exporting after disposal is indeed a serious issue for many exporters, especially those who have underlying TCP / UDP / Unix Domain Socket connections. I have a strong feeling that Console Exporter SHOULD let the user notice these potential bugs in their code before moving to a production exporters.
3. If we agree on 1 and 2, I think we can conclude that:
   3.1. Console Exporter SHOULD prioritize on how to help the developer to discover potential issues in the early stage, rather than hide them.
   3.2. Console Exporter SHOULD report these potential issues in an actionable way, so folks know what should be done.

[CodeBlanch]

We could modify this code...

opentelemetry-dotnet/src/OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs

Line 291 in 42374d9

protected override void Dispose(bool disposing)

...to do this:

        protected override void Dispose(bool disposing)
        {
            if (!this.disposed)
            {
                if (disposing)
                {
                    // Wait for up to 5 seconds grace period
                    var processor = this.Processor;
                    if (processor != null)
                    {
                       processor.Shutdown(5000);
                       processor.Dispose();
                       this.Processor = null;
                    }

                    this.ownedServiceProvider?.Dispose();
                }

                this.disposed = true;
                OpenTelemetrySdkEventSource.Log.ProviderDisposed(nameof(OpenTelemetryLoggerProvider));
            }

            base.Dispose(disposing);
        }

There is already an SDK log message there when it is disposed if anyone is interested.

The log logic has a null check on the processor so this would effectively stop logging:

opentelemetry-dotnet/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs

Line 54 in 42374d9

if (processor != null)

And this would work across the board.

I still question the usefulness of this, but might be a better approach to "fixing" it.

[jackyshang12321]

Here is my thinking:

1. As stated in the official doc, Console Exporter is intended for learning and dev inner-loop. It is not designed/intended for production. So any change on the output behavior is very unlikely to cause any production regressions.
2. I think the main usage of Console Exporter is to help the developers to learn and discover potential issues at early states - with that said, exporting after disposal is indeed a serious issue for many exporters, especially those who have underlying TCP / UDP / Unix Domain Socket connections. I have a strong feeling that Console Exporter SHOULD let the user notice these potential bugs in their code before moving to a production exporters.
3. If we agree on 1 and 2, I think we can conclude that:
   3.1. Console Exporter SHOULD prioritize on how to help the developer to discover potential issues in the early stage, rather than hide them.
   3.2. Console Exporter SHOULD report these potential issues in an actionable way, so folks know what should be done.

Then it makes perfect sense to stop exporting console log if it's already been disposed.
@reyang , what is the most appropriate way for folks to know what needs to be done? Documentation on the official website? output specific logs? or some other way?

[jackyshang12321]

We could modify this code...

opentelemetry-dotnet/src/OpenTelemetry/Logs/OpenTelemetryLoggerProvider.cs

Line 291 in 42374d9

protected override void Dispose(bool disposing)

...to do this:

        protected override void Dispose(bool disposing)
        {
            if (!this.disposed)
            {
                if (disposing)
                {
                    // Wait for up to 5 seconds grace period
                    var processor = this.Processor;
                    if (processor != null)
                    {
                       processor.Shutdown(5000);
                       processor.Dispose();
                       this.Processor = null;
                    }

                    this.ownedServiceProvider?.Dispose();
                }

                this.disposed = true;
                OpenTelemetrySdkEventSource.Log.ProviderDisposed(nameof(OpenTelemetryLoggerProvider));
            }

            base.Dispose(disposing);
        }

There is already an SDK log message there when it is disposed if anyone is interested.

The log logic has a null check on the processor so this would effectively stop logging:

opentelemetry-dotnet/src/OpenTelemetry/Logs/OpenTelemetryLogger.cs

Line 54 in 42374d9

if (processor != null)

And this would work across the board.

I still question the usefulness of this, but might be a better approach to "fixing" it.

Thanks @CodeBlanch , if we get an agreement, then that will be the change

Hey @CodeBlanch , I'm new to this, please correct me if I'm wrong, if we set this.Processor to null, will that impact exporters other than ConsoleExporter? like otlp exporter. I think our goal is to disable log export from console

[linux-foundation-easycla]

The committers listed above are authorized under a signed CLA.

• ✅ login: jackyshang12321 / name: Jacky Shang (51bc047, 5b6cc57, d44c7a8, 2157ebb, 699472c, 72a9f5c)
• ✅ login: brianwarner / name: Brian Warner (14e2ff8)

[jackyshang12321]

Hi @reyang , sorry to bother you again, so what's the next step for this?

[reyang]

Hi @reyang , sorry to bother you again, so what's the next step for this?

I've briefly discussed this with @CodeBlanch and here is my suggestion:

For ConsoleExporter (this PR):

1. Record the callstack when the ConsoleExporter is disposed.
2. If ConsoleExporter.Export is ever called after it is disposed, depending on whether it is the 1st time:
   2.1 if it is the first time - outputs an error message - including "what happened" and "what's the consequence" and "what should be done in order to fix the issue", plus two callstacks 1) the callstack where the export is being called 2) the callstack where dispose happened.
   2.2 if it is not the first time, simply drop the data and don't output anything.
3. Everything here has to be done in a thread-safe manner.

For InMemoryExporter (out of the scope of this PR):

1. Simply throw ObjectDisposedException so the user would get early error during development stage.
2. I've sent a PR here [InMemoryExporter] Throw ObjectDisposedException if Export happened after disposal #3607.

[jackyshang12321]

Hey @reyang , thank you so much for such a detailed design, the code has been modified according to the decision, and the output is similar to the following

Please suggest is that Ok? Or do you think it would be more appropriate to remove the call stack inside opentelemetry?

[reyang]

LGTM with a changelog entry.

[reyang]

Please find my comments.

[reyang]

LGTM.

[jackyshang12321]

Hi @reyang , I am confused by the error, I checked the error messages in the build and code coverage steps, but I don't understand what is causing the failure, could you help check it when you get a chance, thank you

[reyang]

Hi @reyang , I am confused by the error, I checked the error messages in the build and code coverage steps, but I don't understand what is causing the failure, could you help check it when you get a chance, thank you

Would you rebase to the latest main branch?

[jackyshang12321]

Hi @reyang , I am confused by the error, I checked the error messages in the build and code coverage steps, but I don't understand what is causing the failure, could you help check it when you get a chance, thank you

Would you rebase to the latest main branch?

Done, thank you

[cijothomas]

@jackyshang12321 Would you update the PR description to reflect the final design? Also rebase from main, and we are good to merge! Thank you.

[utpilla]

This could be the result of invalid lifecycle management of the OpenTelemetry .NET SDK.

This could be misinterpreted for OTel SDK being at fault. As in the OTel .NET SDK does not do lifecycle management of something correctly. I think we should clearly call out who is at fault.

Suggested change

	this.WriteLine("The console exporter is still being invoked after it has been disposed. This could be the result of invalid lifecycle management of the OpenTelemetry .NET SDK.");
	this.WriteLine("The console exporter is still being invoked after it has been disposed. This could be the due to the application's incorrect lifecycle management of the LoggerFactory/OpenTelemetry .NET SDK.");

[jackyshang12321]

Hi @utpilla , updated, thanks

[jackyshang12321]

@jackyshang12321 Would you update the PR description to reflect the final design? Also rebase from main, and we are good to merge! Thank you.

Done, please check, thank you

[jackyshang12321]

Hi @reyang , I want to say thank you, this is my first github PR, you know the first time you always feel like you can't figure it out, but thank you so much for being so patient with me, and for helping me figure everything out.