Skip to content

Conversation

@mikeminutillo
Copy link
Member

@mikeminutillo mikeminutillo commented Jul 29, 2021

Closes #238

Uses the same technique as NServiceBus.Extensions.Hosting to capture all log messages in deferred loggers until an ILogger instance is available.

NOTE: This will only provide startup logs when the first trigger is called.

@mikeminutillo mikeminutillo self-assigned this Jul 29, 2021
@mikeminutillo
Copy link
Member Author

Collapsed back into a single logger that can defer until it is handed a logger via a call to Process(). Note that if you don't provide a logger then we put a NullLogger in place. This prevents deferred logs from building up indefinitely.

There is still a case where logs could grow indefinitely. That's where you're using FunctionEndpoint but never calling Process().

@mikeminutillo
Copy link
Member Author

mikeminutillo commented Aug 6, 2021

Smoke testing

image

This also highlights the fact that all of the sending/publishing APIs can also be passed a logger and this works as expected.

Copy link
Contributor

@timbussmann timbussmann left a comment

Choose a reason for hiding this comment

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

one thought but otherwise LGTM

var concreteLogger = logger.Value;
if (concreteLogger == null)
{
deferredMessageLogs.Enqueue((level, message));
Copy link
Contributor

Choose a reason for hiding this comment

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

is there a potential race condition in a case where a caller entered the if condition and then concurrently the logger is set and the queues are emptied before the caller enters the enqueue method, essentially causing a "log loss"?

Copy link
Member Author

Choose a reason for hiding this comment

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

The concrete logger comes from an async local. If another thread sets it then it will be in that threads async local context so it should not affect this one.

Copy link
Contributor

Choose a reason for hiding this comment

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

hm not sure that's what I mean, here's what I was thinking about:

Thread1(T1): checks concreteLogger, value is null, enters if condition.
Thread2(T2): calls SetCurrentLogger
T2: Sets logger value to logger instance
T2: Subsequentlly calls Flush
T2: Flush empties all defferedMessageLogs entries
T2: completes
T1: adds log entry to defferedMessageLogs as part of the previously entered if-block. defferedMessageLogs isn't read anymore.

Copy link
Member Author

Choose a reason for hiding this comment

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

We used to flush on every log call which would resolve this problem. I can put that back. Given that the deferred logger will usually be empty, this shoud be quick. We'd create three enumerators, for every log call which we can probably avoid if we check the queue length before enumerating them.

Copy link
Member Author

Choose a reason for hiding this comment

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

Actually, because it's a queue we only ever TryDequeue. There's no enumerator created. This should be quick.

Copy link
Contributor

Choose a reason for hiding this comment

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

not really sure that's worthwhile though. Arguably, there shouldn't really be log statements being created while the logger is being replaced as we haven't started processing messages yet and the endpoint started up already, so maybe this is something that doesn't necessarily need to be fixed. The only potential log statements would come from sort of background job which shouldn't really happen without an active message pump.

@timbussmann
Copy link
Contributor

merging this for now to start testing. @mikeminutillo if you want to follow-up on our discussion regarding the race condition, we can also do that via a separate PR I think

@timbussmann timbussmann merged commit b6c0385 into master Aug 9, 2021
@timbussmann timbussmann deleted the deferred-logging branch August 9, 2021 11:16
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Log messages about license files and probed locations are missing

5 participants