Skip to content

Capture NServiceBus endpoint startup logs before logger is available #239

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.

Sign up for GitHub

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

Merged
timbussmann merged 6 commits into from
Aug 9, 2021
Merged

Capture NServiceBus endpoint startup logs before logger is available #239

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
4d089a8
Set up deferred logging
mikeminutillo Jul 29, 2021
644a3c8
Switch to functions logger before flushing
mikeminutillo Aug 5, 2021
ebbd115
Flush deferred logger at startup
mikeminutillo Aug 6, 2021
197fd5d
Combine loggers
mikeminutillo Aug 6, 2021
3247258
Tests
mikeminutillo Aug 6, 2021
9588185
Address review comments
mikeminutillo Aug 6, 2021
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
8 changes: 6 additions & 2 deletions src/NServiceBus.AzureFunctions.InProcess.ServiceBus/Logging/FunctionsLoggerFactory.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -4,13 +4,14 @@
using System.Threading;
using Logging;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using ILoggerFactory = Logging.ILoggerFactory;

class FunctionsLoggerFactory : ILoggerFactory
{
public static FunctionsLoggerFactory Instance { get; } = new FunctionsLoggerFactory();

ILog log;
Logger log;

AsyncLocal<ILogger> logger = new AsyncLocal<ILogger>();

Expand All @@ -21,7 +22,10 @@ class FunctionsLoggerFactory : ILoggerFactory

public void SetCurrentLogger(ILogger currentLogger)
{
logger.Value = currentLogger;
var newLogger = currentLogger ?? NullLogger.Instance;

logger.Value = newLogger;
log.Flush(newLogger);
}

public ILog GetLogger(Type type)
Expand Down
127 changes: 67 additions & 60 deletions src/NServiceBus.AzureFunctions.InProcess.ServiceBus/Logging/Logger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -1,10 +1,10 @@
namespace NServiceBus.AzureFunctions.InProcess.ServiceBus
{
using System;
using System.Collections.Concurrent;
using System.Threading;
using Logging;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;
using LogLevel = Microsoft.Extensions.Logging.LogLevel;

class Logger : ILog
Expand All @@ -14,89 +14,96 @@ public Logger(AsyncLocal<ILogger> logger)
this.logger = logger;
}

ILogger CurrentLogger => logger.Value ?? NullLogger.Instance;
public bool IsDebugEnabled => logger.Value?.IsEnabled(LogLevel.Debug) ?? true;
public bool IsInfoEnabled => logger.Value?.IsEnabled(LogLevel.Information) ?? true;
public bool IsWarnEnabled => logger.Value?.IsEnabled(LogLevel.Warning) ?? true;
public bool IsErrorEnabled => logger.Value?.IsEnabled(LogLevel.Error) ?? true;
public bool IsFatalEnabled => logger.Value?.IsEnabled(LogLevel.Critical) ?? true;

public bool IsDebugEnabled => CurrentLogger.IsEnabled(LogLevel.Debug);
public bool IsInfoEnabled => CurrentLogger.IsEnabled(LogLevel.Information);
public bool IsWarnEnabled => CurrentLogger.IsEnabled(LogLevel.Warning);
public bool IsErrorEnabled => CurrentLogger.IsEnabled(LogLevel.Error);
public bool IsFatalEnabled => CurrentLogger.IsEnabled(LogLevel.Critical);

public void Debug(string message)
void Log(LogLevel level, string message)
{
CurrentLogger.Log(LogLevel.Debug, message);
var concreteLogger = logger.Value;
if (concreteLogger == null)
{
deferredMessageLogs.Enqueue((level, message));
Copy link
Contributor

@timbussmann timbussmann Aug 6, 2021

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

@mikeminutillo mikeminutillo Aug 6, 2021

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

@timbussmann timbussmann Aug 6, 2021

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

@mikeminutillo mikeminutillo Aug 9, 2021

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

@mikeminutillo mikeminutillo Aug 9, 2021

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

@timbussmann timbussmann Aug 9, 2021

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.

return;
}
concreteLogger.Log(level, message);
}

public void Debug(string message, Exception exception)
void Log(LogLevel level, string message, Exception exception)
{
CurrentLogger.Log(LogLevel.Debug, exception, message);
var concreteLogger = logger.Value;
if (concreteLogger == null)
{
deferredExceptionLogs.Enqueue((level, message, exception));
return;
}
concreteLogger.Log(level, exception, message);
}

public void DebugFormat(string format, params object[] args)
void Log(LogLevel level, string format, object[] args)
{
CurrentLogger.Log(LogLevel.Debug, format, args);
var concreteLogger = logger.Value;
if (concreteLogger == null)
{
deferredFormatLogs.Enqueue((level, format, args));
return;
}
concreteLogger.Log(level, format, args);
}

public void Info(string message)
{
CurrentLogger.Log(LogLevel.Information, message);
}
public void Debug(string message) => Log(LogLevel.Debug, message);

public void Info(string message, Exception exception)
{
CurrentLogger.Log(LogLevel.Information, exception, message);
}
public void Debug(string message, Exception exception) => Log(LogLevel.Debug, message, exception);

public void InfoFormat(string format, params object[] args)
{
CurrentLogger.Log(LogLevel.Information, format, args);
}
public void DebugFormat(string format, params object[] args) => Log(LogLevel.Debug, format, args);

public void Warn(string message)
{
CurrentLogger.Log(LogLevel.Warning, message);
}
public void Info(string message) => Log(LogLevel.Information, message);

public void Warn(string message, Exception exception)
{
CurrentLogger.Log(LogLevel.Warning, exception, message);
}
public void Info(string message, Exception exception) => Log(LogLevel.Information, message, exception);

public void WarnFormat(string format, params object[] args)
{
CurrentLogger.Log(LogLevel.Warning, format, args);
}
public void InfoFormat(string format, params object[] args) => Log(LogLevel.Information, format, args);

public void Error(string message)
{
CurrentLogger.Log(LogLevel.Error, message);
}
public void Warn(string message) => Log(LogLevel.Warning, message);

public void Error(string message, Exception exception)
{
CurrentLogger.Log(LogLevel.Error, exception, message);
}
public void Warn(string message, Exception exception) => Log(LogLevel.Warning, message, exception);

public void ErrorFormat(string format, params object[] args)
{
CurrentLogger.Log(LogLevel.Error, format, args);
}
public void WarnFormat(string format, params object[] args) => Log(LogLevel.Warning, format, args);

public void Fatal(string message)
{
CurrentLogger.Log(LogLevel.Critical, message);
}
public void Error(string message) => Log(LogLevel.Error, message);

public void Fatal(string message, Exception exception)
{
CurrentLogger.Log(LogLevel.Critical, exception, message);
}
public void Error(string message, Exception exception) => Log(LogLevel.Error, message, exception);

public void ErrorFormat(string format, params object[] args) => Log(LogLevel.Error, format, args);

public void Fatal(string message) => Log(LogLevel.Critical, message);

public void Fatal(string message, Exception exception) => Log(LogLevel.Critical, message, exception);

public void FatalFormat(string format, params object[] args)
public void FatalFormat(string format, params object[] args) => Log(LogLevel.Critical, format, args);

internal void Flush(ILogger concreteLogger)
{
CurrentLogger.Log(LogLevel.Critical, format, args);
while (deferredMessageLogs.TryDequeue(out var entry))
{
concreteLogger.Log(entry.level, entry.message);
}

while (deferredExceptionLogs.TryDequeue(out var entry))
{
concreteLogger.Log(entry.level, entry.exception, entry.message);
}

while (deferredFormatLogs.TryDequeue(out var entry))
{
concreteLogger.Log(entry.level, entry.format, entry.args);
}
}

AsyncLocal<ILogger> logger;
readonly ConcurrentQueue<(LogLevel level, string message)> deferredMessageLogs = new ConcurrentQueue<(LogLevel level, string message)>();
readonly ConcurrentQueue<(LogLevel level, string message, Exception exception)> deferredExceptionLogs = new ConcurrentQueue<(LogLevel level, string message, Exception exception)>();
readonly ConcurrentQueue<(LogLevel level, string format, object[] args)> deferredFormatLogs = new ConcurrentQueue<(LogLevel level, string format, object[] args)>();
}
}
119 changes: 119 additions & 0 deletions src/ServiceBus.Tests/LoggingTests.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,119 @@
namespace ServiceBus.Tests
{
using System;
using System.Collections.Concurrent;
using System.Threading.Tasks;
using Microsoft.Extensions.Logging;
using NServiceBus.AzureFunctions.InProcess.ServiceBus;
using NServiceBus.Logging;
using NUnit.Framework;
using LogLevel = Microsoft.Extensions.Logging.LogLevel;

[TestFixture]
class LoggingTests
{
[Test]
public void Always_returns_same_logger()
{
var loggerA = FunctionsLoggerFactory.Instance.GetLogger("A");
var loggerB = FunctionsLoggerFactory.Instance.GetLogger("B");

Assert.AreSame(loggerA, loggerB);
}

[Test]
public void Captures_logs_before_handed_logger()
{
var logger = FunctionsLoggerFactory.Instance.GetLogger("logger");
logger.Info("Deferred message");

var fakeLogger = new FakeLogger();

FunctionsLoggerFactory.Instance.SetCurrentLogger(fakeLogger);

Assert.AreEqual(1, fakeLogger.CapturedLogs.Count);
fakeLogger.CapturedLogs.TryDequeue(out var capturedLog);
Assert.AreEqual("Deferred message", capturedLog.message);
}

[Test]
public void Forwards_logs_after_handed_logger()
{
var logger = FunctionsLoggerFactory.Instance.GetLogger("logger");

var fakeLogger = new FakeLogger();

FunctionsLoggerFactory.Instance.SetCurrentLogger(fakeLogger);

logger.Info("Forwarded message");

Assert.AreEqual(1, fakeLogger.CapturedLogs.Count);
fakeLogger.CapturedLogs.TryDequeue(out var capturedLog);
Assert.AreEqual("Forwarded message", capturedLog.message);
}

[Test]
public void Only_first_logger_gets_deferred_messages()
{
var logger = FunctionsLoggerFactory.Instance.GetLogger("logger");
logger.Info("Deferred message");

var firstLogger = new FakeLogger();
var secondLogger = new FakeLogger();

FunctionsLoggerFactory.Instance.SetCurrentLogger(firstLogger);
FunctionsLoggerFactory.Instance.SetCurrentLogger(secondLogger);

Assert.AreEqual(1, firstLogger.CapturedLogs.Count);
Assert.AreEqual(0, secondLogger.CapturedLogs.Count);
}

[Test]
public async Task Concurrent_loggers_are_isolated()
{
var logger = FunctionsLoggerFactory.Instance.GetLogger("logger");
var firstLoggerTask = Execute(logger, 1);
var secondLoggerTask = Execute(logger, 2);

await Task.WhenAll(firstLoggerTask, secondLoggerTask);

var firstLogger = firstLoggerTask.Result;
var secondLogger = secondLoggerTask.Result;

Assert.AreEqual(1, firstLogger.CapturedLogs.Count);
Assert.AreEqual(1, secondLogger.CapturedLogs.Count);

firstLogger.CapturedLogs.TryDequeue(out var firstLog);
Assert.AreEqual("Running task 1", firstLog.message);

secondLogger.CapturedLogs.TryDequeue(out var secondLog);
Assert.AreEqual("Running task 2", secondLog.message);

async Task<FakeLogger> Execute(ILog log, int n)
{
await Task.Yield();
var fakeLogger = new FakeLogger();
FunctionsLoggerFactory.Instance.SetCurrentLogger(fakeLogger);
log.Info($"Running task {n}");
return fakeLogger;
}
}

class FakeLogger : ILogger
{
public ConcurrentQueue<(LogLevel level, EventId eventId, Exception exception, string message)> CapturedLogs
{
get;
} = new ConcurrentQueue<(LogLevel level, EventId eventId, Exception exception, string message)>();


public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
Func<TState, Exception, string> formatter)
=> CapturedLogs.Enqueue((logLevel, eventId, exception, formatter(state, exception)));

public bool IsEnabled(LogLevel logLevel) => true;

public IDisposable BeginScope<TState>(TState state) => throw new NotImplementedException();
}
}
}