HttpClientFactory prevent throwing if ILogger couldn't be created#90503
Conversation
ghost
assigned
|
Tagging subscribers to this area: @dotnet/ncl Issue DetailsFixes #90386
|
| { | ||
| logger = loggerLazy.Value; | ||
| } | ||
| catch { } // not throwing in logs |
There was a problem hiding this comment.
This eats all exceptions? What was being done before?
There was a problem hiding this comment.
Before, the ILogger was created during DefaultHttpClientFactory constructor, so if any exception happens, DefaultHttpClientFactory instance was not created at all. Now, the instance is already up and running.
My understanding is that logging should never throw (especially given that the logging could be turned off for this logger category in the settings... but it will be applied only within the logging infra). The only time it could throw is somewhere around the startup when everything gets created (how it was before). Unfortunately, due to circular dependency (in e.g. OTel) we cannot do this in constructor anymore (see #89032).
My initial attempt to fix this was to go away from ILogger and substitute it with EventSource, but this would be a breaking change (even though these logs seem to be internal diagnostic debug logs).
There was a problem hiding this comment.
(now I believe it is also needed in case the factory was never disposed...)
There was a problem hiding this comment.
Maybe we should only eat the documented exceptions for Lazy<T>.Value which are:
I'm not sure any of those would actually throw, so perhaps the only likely exception would be null access?
There was a problem hiding this comment.
The actual reported one is ObjectDisposedException; though, it could be any exception thrown by e.g. a 3rd party ILoggerProvider/ILoggerFactory/failing to create ILogger instance because of some other problem.
There was a problem hiding this comment.
It seems to me then that we should only eat ObjectDisposedException, as that's the one we know is safe to be eaten.
There was a problem hiding this comment.
Theoretically I can only swallow ObjectDisposedException, that would fix the reported issue. But if we ever stumble upon some other ILogger creation exception, this will become a regression, since it would crash the process where it was not crashing before.
There was a problem hiding this comment.
(I meant not that the current PR would introduce a regression, but #89531 already did)
|
PTAL @stephentoub |
| _expiredHandlers.Enqueue(expired); | ||
|
|
||
| Log.HandlerExpired(_logger.Value, active.Name, active.Lifetime); | ||
| Log.HandlerExpired(_logger, active.Name, active.Lifetime); |
There was a problem hiding this comment.
I'm not clear on why making the handler implement IDisposable impacts where we initialize the logger. Can you elaborate on that?
There was a problem hiding this comment.
Not handler, but the factory... So the story is:
When the application is shutting down, ServiceProvider gets disposed. (It will also dispose all IDisposable singletons alongside).
Now, the Logger has lazy initialization (since #89032), that would happen on the first access to it. The first access happens when (upd.: this is when I realize I've been stopping the wrong timer - it should have been expiryTimer, not cleanupTimer 🤦♀️) ExpiryTimer_Tick is being called the first time, meaning the first of created handlers has just expired (ExpiryTimer_Tick is called from a timer attached to the cached HttpMessageHandler instance).
So if the application is shutting down around the handler expiry, what happened was that:
- The ServiceProvider gets disposed by the app
- The expiry callback still fires, because no one has stopped it, and tries to log
- It accesses Lazy, which accesses ServiceProvider to get ILoggerFactory from it
- ServiceProvider throws ObjectDisposedException
Now re me realizing it was the wrong timer. Making the factory disposable theoretically would still make the behavior a little bit better, because if _dispoised is set already, ExpiryTimer_Tick will just return. But the proper fix would be to go over all cached handlers and stop their respective timers.
Given the time left before ZBB, I am considering to actually remove all of the changes and leave only swallowing exceptions on ILogger creation. All the timers would still fire, but they were firing before.
Now, I can just only ever swallow ObjectDisposedException, that would fix the reported issue. But if we ever stumble upon some other ILogger creation exception, this will become a regression, since it would crash the process where it was not crashing before.
Thoughts @stephentoub ?
CarnaViire
changed the title
| { | ||
| logger = loggerLazy.Value; | ||
| } | ||
| catch { } // not throwing in logs |
There was a problem hiding this comment.
I assume at this point there's nowhere we can reasonably log the exception, since it was the retrieval of the logger in the first place that failed?
6 participants
Fixes #90386