Logs fail to report after django startup

[quinnmil]

Observed that while logs appear to send as expected in a django application, only the initial batch of startup logs do so, while all others (any logs stemming from request handlers) seem to be silently dropped and fail to report to our otel reporting endpoint.

I have been through the ringer trying to identity the source of this issue, but don't have anything concrete. I know that v1.0.0 (previous release) does not have this problem, but something about the latest batch of changed included in the latest release is causing this strange behavior.

I am quite confident that the culprit was introduced in #24.
This PR introduced an initialization lock, and removed a try/except/finally block. It wasn't a great PR (authored by yours truly) and at the time I choose to delay actually tagging a release until I gave the problem another look. Well.. we got busy and that never happened, so it was released as part of the v1.0.2 tag last week.

I have created so many local branches to try and nail down what exactly the issue is here, but am yet unable. I have added a ton of debug logging to the handler itself (using print statements to avoid any more recursion) and can confirm the otel_handler.emit is called just where we'd expect.

If anything, I may propose we just release a new tag which essentially rolls back all of #24 but keeps that scout_transaction_id rename. Problem here is that would be effectively a breaking change, as django users will need use use env variables for configuration.

However, as it stands now, the currently released version seems effectively broken, at least for django. So we should do something soon.

[quinnmil]

Figured it out! This was indeed quite tricky.
While the changes introduced in #24 did lead to this problem, the logic that change introduced was correct, it just exposed the real issue.

First of all, Django likes to reconfigure logging. In my local testing app, I watch the logging handler be instantiated a consistent 7 times on startup. This is fine, I assume Django does this for initial setup, and then for on each App initialization, middleware, etc.

Part of the change in that PR was to avoid multiple instantiations of the OpenTelemetry LoggingHandler while Django does its thing. We wanted to share state between multiple instances of the ScoutHandler, which this change accomplished.
however - this shared state revealed an issue that the multiple instances of the class hid.

Specifically: Django calls "close" on handlers. We implemented "close" to call LoggerProvider.shutdown. When we were just creating new LoggerProviders on every instance of the handler, those first logger providers would get shutdown, but the later ones would stay connected. Now that the LoggerProvider is a singleton, shared between instances of the class, get shutdown once, and it's down for all instances.

When the LoggerProvider is shut down, calling it's emit method does nothing, silently. This explains what I was observing: logs suddenly stopping to report after django startup, but internal debug logging validating that yes, otel_logger.emit was indeed being called when we expected.

The simple fix would be either remove or make the ScoutOtelHandler.close method a NoOp. Not sure if there's any issue with leaving the provider open - so this warrants some testing.

I will hopefully have a PR up for this tonight, as I'd like to get a fix released ASAP.

[quinnmil]

A look at the otel sdk source shows that the LoggerProvider automatically registers an atexit handler to call shutdown on process completion. So nothing to worry about there.

https://github.com/open-telemetry/opentelemetry-python/blob/102fec2be1fe9d0a8e299598a21ad6ec3b96dcca/opentelemetry-sdk/src/opentelemetry/sdk/_logs/_internal/__init__.py#L688