diff --git a/src/Directory.Packages.props b/src/Directory.Packages.props index dfd35a5f78..16035eade5 100644 --- a/src/Directory.Packages.props +++ b/src/Directory.Packages.props @@ -24,6 +24,8 @@ + + diff --git a/src/ServiceControl.AcceptanceTesting/DiscardMessagesBehavior.cs b/src/ServiceControl.AcceptanceTesting/DiscardMessagesBehavior.cs index ed2fd50768..134db9bdec 100644 --- a/src/ServiceControl.AcceptanceTesting/DiscardMessagesBehavior.cs +++ b/src/ServiceControl.AcceptanceTesting/DiscardMessagesBehavior.cs @@ -3,10 +3,11 @@ namespace ServiceControl.AcceptanceTesting using System; using System.Linq; using System.Threading.Tasks; + using Microsoft.Extensions.Logging; using NServiceBus; using NServiceBus.AcceptanceTesting; - using NServiceBus.Logging; using NServiceBus.Pipeline; + using ServiceControl.Infrastructure; public class DiscardMessagesBehavior : IBehavior { @@ -44,7 +45,13 @@ public Task Invoke(ITransportReceiveContext context, Func(); + logger.LogDebug("Discarding message '{MessageId}'({OriginalMessageId}) because it's session id is '{MessageSessionId}' instead of '{CurrentSessionId}' Message Types: {EnclosedMessageTypes}.", + context.Message.MessageId, + originalMessageId ?? string.Empty, + session, + currentSession, + enclosedMessageTypes); return Task.CompletedTask; } @@ -52,7 +59,6 @@ public Task Invoke(ITransportReceiveContext context, Func(); static string[] pluginMessages = { diff --git a/src/ServiceControl.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs b/src/ServiceControl.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs index f1b3e58a01..8ac0a4454a 100644 --- a/src/ServiceControl.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs +++ b/src/ServiceControl.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs @@ -50,6 +50,7 @@ async Task InitializeServiceControl(ScenarioContext context) var logPath = Path.Combine(Path.GetTempPath(), Path.GetRandomFileName()); Directory.CreateDirectory(logPath); var loggingSettings = new LoggingSettings(Settings.SettingsRootNamespace, defaultLevel: LogLevel.Debug, logPath: logPath); + LoggerUtil.ActiveLoggers = Loggers.Test; var settings = new Settings(transportToUse.TypeName, persistenceToUse.PersistenceType, loggingSettings, forwardErrorMessages: false, errorRetentionPeriod: TimeSpan.FromDays(10)) { @@ -65,9 +66,9 @@ async Task InitializeServiceControl(ScenarioContext context) { var headers = messageContext.Headers; var id = messageContext.NativeMessageId; - var log = NServiceBus.Logging.LogManager.GetLogger(); + var logger = LoggerUtil.CreateStaticLogger(loggingSettings.LogLevel); headers.TryGetValue(Headers.MessageId, out var originalMessageId); - log.Debug($"OnMessage for message '{id}'({originalMessageId ?? string.Empty})."); + logger.LogDebug("OnMessage for message '{MessageId}'({OriginalMessageId})", id, originalMessageId ?? string.Empty); //Do not filter out CC, SA and HB messages as they can't be stamped if (headers.TryGetValue(Headers.EnclosedMessageTypes, out var messageTypes) @@ -86,7 +87,7 @@ async Task InitializeServiceControl(ScenarioContext context) var currentSession = context.TestRunId.ToString(); if (!headers.TryGetValue("SC.SessionID", out var session) || session != currentSession) { - log.Debug($"Discarding message '{id}'({originalMessageId ?? string.Empty}) because it's session id is '{session}' instead of '{currentSession}'."); + logger.LogDebug("Discarding message '{MessageId}'({OriginalMessageId}) because it's session id is '{SessionId}' instead of '{CurrentSessionId}'", id, originalMessageId ?? string.Empty, session, currentSession); return true; } diff --git a/src/ServiceControl.Audit.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs b/src/ServiceControl.Audit.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs index 65e1b4752f..27ed1bfade 100644 --- a/src/ServiceControl.Audit.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs +++ b/src/ServiceControl.Audit.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs @@ -45,6 +45,7 @@ async Task InitializeServiceControl(ScenarioContext context) Directory.CreateDirectory(logPath); var loggingSettings = new LoggingSettings(Settings.SettingsRootNamespace, defaultLevel: LogLevel.Debug, logPath: logPath); + LoggerUtil.ActiveLoggers = Loggers.Test; settings = new Settings(transportToUse.TypeName, persistenceToUse.PersistenceType, loggingSettings) { @@ -56,9 +57,9 @@ async Task InitializeServiceControl(ScenarioContext context) { var id = messageContext.NativeMessageId; var headers = messageContext.Headers; - var log = LoggerUtil.CreateStaticLogger(); + var logger = LoggerUtil.CreateStaticLogger(loggingSettings.LogLevel); headers.TryGetValue(Headers.MessageId, out var originalMessageId); - log.LogDebug("OnMessage for message '{MessageId}'({OriginalMessageId}).", id, originalMessageId ?? string.Empty); + logger.LogDebug("OnMessage for message '{MessageId}'({OriginalMessageId}).", id, originalMessageId ?? string.Empty); //Do not filter out CC, SA and HB messages as they can't be stamped if (headers.TryGetValue(Headers.EnclosedMessageTypes, out var messageTypes) @@ -77,7 +78,7 @@ async Task InitializeServiceControl(ScenarioContext context) var currentSession = context.TestRunId.ToString(); if (!headers.TryGetValue("SC.SessionID", out var session) || session != currentSession) { - log.LogDebug("Discarding message '{MessageId}'({OriginalMessageId}) because it's session id is '{SessionId}' instead of '{CurrentSessionId}'.", id, originalMessageId ?? string.Empty, session, currentSession); + logger.LogDebug("Discarding message '{MessageId}'({OriginalMessageId}) because it's session id is '{SessionId}' instead of '{CurrentSessionId}'.", id, originalMessageId ?? string.Empty, session, currentSession); return true; } diff --git a/src/ServiceControl.Audit.Persistence.RavenDB/RavenPersistenceConfiguration.cs b/src/ServiceControl.Audit.Persistence.RavenDB/RavenPersistenceConfiguration.cs index 3611a3f646..eced9e35b2 100644 --- a/src/ServiceControl.Audit.Persistence.RavenDB/RavenPersistenceConfiguration.cs +++ b/src/ServiceControl.Audit.Persistence.RavenDB/RavenPersistenceConfiguration.cs @@ -108,7 +108,7 @@ internal static DatabaseConfiguration GetDatabaseConfiguration(PersistenceSettin if (settings.PersisterSpecificSettings.TryGetValue(RavenDbLogLevelKey, out var ravenDbLogLevel)) { - logsMode = RavenDbLogLevelToLogsModeMapper.Map(ravenDbLogLevel); + logsMode = RavenDbLogLevelToLogsModeMapper.Map(ravenDbLogLevel, Logger); } serverConfiguration = new ServerConfiguration(dbPath, serverUrl, logPath, logsMode); diff --git a/src/ServiceControl.DomainEvents/DomainEvents.cs b/src/ServiceControl.DomainEvents/DomainEvents.cs index 5443c784d7..0367f199fb 100644 --- a/src/ServiceControl.DomainEvents/DomainEvents.cs +++ b/src/ServiceControl.DomainEvents/DomainEvents.cs @@ -4,15 +4,10 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; - public class DomainEvents : IDomainEvents + public class DomainEvents(IServiceProvider serviceProvider, ILogger logger) : IDomainEvents { - static readonly ILog Log = LogManager.GetLogger(); - - readonly IServiceProvider serviceProvider; - public DomainEvents(IServiceProvider serviceProvider) => this.serviceProvider = serviceProvider; - public async Task Raise(T domainEvent, CancellationToken cancellationToken) where T : IDomainEvent { var handlers = serviceProvider.GetServices>(); @@ -25,7 +20,7 @@ await handler.Handle(domainEvent, cancellationToken) } catch (Exception e) { - Log.Error($"Unexpected error publishing domain event {typeof(T)}", e); + logger.LogError(e, "Unexpected error publishing domain event {EventType}", typeof(T)); throw; } } @@ -40,7 +35,7 @@ await handler.Handle(domainEvent, cancellationToken) } catch (Exception e) { - Log.Error($"Unexpected error publishing domain event {typeof(T)}", e); + logger.LogError(e, "Unexpected error publishing domain event {EventType}", typeof(T)); throw; } } diff --git a/src/ServiceControl.DomainEvents/ServiceControl.DomainEvents.csproj b/src/ServiceControl.DomainEvents/ServiceControl.DomainEvents.csproj index 8b8037bc48..bb654606ec 100644 --- a/src/ServiceControl.DomainEvents/ServiceControl.DomainEvents.csproj +++ b/src/ServiceControl.DomainEvents/ServiceControl.DomainEvents.csproj @@ -6,6 +6,7 @@ + diff --git a/src/ServiceControl.Infrastructure/LoggerUtil.cs b/src/ServiceControl.Infrastructure/LoggerUtil.cs index 34fc16beb1..c18a54afc1 100644 --- a/src/ServiceControl.Infrastructure/LoggerUtil.cs +++ b/src/ServiceControl.Infrastructure/LoggerUtil.cs @@ -19,17 +19,22 @@ public static class LoggerUtil { public static Loggers ActiveLoggers { private get; set; } = Loggers.None; + public static bool IsLoggingTo(Loggers logger) + { + return (logger & ActiveLoggers) == logger; + } + public static void BuildLogger(this ILoggingBuilder loggingBuilder, LogLevel level) { - if ((Loggers.Test & ActiveLoggers) == Loggers.Test) + if (IsLoggingTo(Loggers.Test)) { - loggingBuilder.Services.AddSingleton(new TestContextProvider()); + loggingBuilder.Services.AddSingleton(new TestContextProvider(level)); } - if ((Loggers.NLog & ActiveLoggers) == Loggers.NLog) + if (IsLoggingTo(Loggers.NLog)) { loggingBuilder.AddNLog(); } - if ((Loggers.Seq & ActiveLoggers) == Loggers.Seq) + if (IsLoggingTo(Loggers.Seq)) { loggingBuilder.AddSeq(); } diff --git a/src/ServiceControl.Infrastructure/LoggingConfigurator.cs b/src/ServiceControl.Infrastructure/LoggingConfigurator.cs index 4845965394..848c6a3cf3 100644 --- a/src/ServiceControl.Infrastructure/LoggingConfigurator.cs +++ b/src/ServiceControl.Infrastructure/LoggingConfigurator.cs @@ -12,16 +12,19 @@ namespace ServiceControl.Infrastructure using LogManager = NServiceBus.Logging.LogManager; using LogLevel = NLog.LogLevel; - // TODO: Migrate from NLog to .NET logging public static class LoggingConfigurator { public static void ConfigureLogging(LoggingSettings loggingSettings) { - if (NLog.LogManager.Configuration != null) + //used for loggers outside of ServiceControl (i.e. transports and core) to use the logger factory defined here + LogManager.UseFactory(new ExtensionsLoggerFactory(LoggerFactory.Create(configure => configure.BuildLogger(loggingSettings.LogLevel)))); + + if (!LoggerUtil.IsLoggingTo(Loggers.NLog) || NLog.LogManager.Configuration != null) { return; } + //configure NLog var nlogConfig = new LoggingConfiguration(); var simpleLayout = new SimpleLayout("${longdate}|${processtime}|${threadid}|${level}|${logger}|${message}${onexception:|${exception:format=tostring}}"); @@ -76,8 +79,7 @@ public static void ConfigureLogging(LoggingSettings loggingSettings) NLog.LogManager.Configuration = nlogConfig; - LogManager.UseFactory(new ExtensionsLoggerFactory(LoggerFactory.Create(configure => configure.BuildLogger(loggingSettings.LogLevel)))); - + //using LogManager here rather than LoggerUtil.CreateStaticLogger since this is exclusive to NLog var logger = LogManager.GetLogger("LoggingConfiguration"); var logEventInfo = new LogEventInfo { TimeStamp = DateTime.UtcNow }; var loggingTo = AppEnvironment.RunningInContainer ? "console" : fileTarget.FileName.Render(logEventInfo); diff --git a/src/ServiceControl.Infrastructure/LoggingSettings.cs b/src/ServiceControl.Infrastructure/LoggingSettings.cs index c48b27d889..ea8967bb00 100644 --- a/src/ServiceControl.Infrastructure/LoggingSettings.cs +++ b/src/ServiceControl.Infrastructure/LoggingSettings.cs @@ -11,9 +11,6 @@ public class LoggingSettings { public LoggingSettings(SettingsRootNamespace rootNamespace, LogLevel defaultLevel = LogLevel.Information, string logPath = null) { - LogLevel = InitializeLogLevel(rootNamespace, defaultLevel); - LogPath = SettingsReader.Read(rootNamespace, logPathKey, Environment.ExpandEnvironmentVariables(logPath ?? DefaultLogLocation())); - var loggingProviders = (SettingsReader.Read(rootNamespace, loggingProvidersKey) ?? "").Split(","); var activeLoggers = Loggers.None; if (loggingProviders.Contains("NLog")) @@ -26,6 +23,9 @@ public LoggingSettings(SettingsRootNamespace rootNamespace, LogLevel defaultLeve } //this defaults to NLog because historically that was the default, and we don't want to break existing installs that don't have the config key to define loggingProviders LoggerUtil.ActiveLoggers = activeLoggers == Loggers.None ? Loggers.NLog : activeLoggers; + + LogLevel = InitializeLogLevel(rootNamespace, defaultLevel); + LogPath = SettingsReader.Read(rootNamespace, logPathKey, Environment.ExpandEnvironmentVariables(logPath ?? DefaultLogLocation())); } public LogLevel LogLevel { get; } diff --git a/src/ServiceControl.Infrastructure/RavenDbLogLevelToLogsModeMapper.cs b/src/ServiceControl.Infrastructure/RavenDbLogLevelToLogsModeMapper.cs index 8711bc9854..d3316ba830 100644 --- a/src/ServiceControl.Infrastructure/RavenDbLogLevelToLogsModeMapper.cs +++ b/src/ServiceControl.Infrastructure/RavenDbLogLevelToLogsModeMapper.cs @@ -1,12 +1,10 @@ namespace ServiceControl { - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; public class RavenDbLogLevelToLogsModeMapper { - static readonly ILog Logger = LogManager.GetLogger(typeof(RavenDbLogLevelToLogsModeMapper)); - - public static string Map(string ravenDbLogLevel) + public static string Map(string ravenDbLogLevel, ILogger logger) { switch (ravenDbLogLevel.ToLower()) { @@ -24,7 +22,7 @@ public static string Map(string ravenDbLogLevel) case "operations": return "Operations"; default: - Logger.WarnFormat("Unknown log level '{0}', mapped to 'Operations'", ravenDbLogLevel); + logger.LogWarning("Unknown log level '{RavenDbLogLevel}', mapped to 'Operations'", ravenDbLogLevel); return "Operations"; } } diff --git a/src/ServiceControl.Infrastructure/RepeatedFailuresOverTimeCircuitBreaker.cs b/src/ServiceControl.Infrastructure/RepeatedFailuresOverTimeCircuitBreaker.cs index abd6c9a354..3ae3d1c879 100644 --- a/src/ServiceControl.Infrastructure/RepeatedFailuresOverTimeCircuitBreaker.cs +++ b/src/ServiceControl.Infrastructure/RepeatedFailuresOverTimeCircuitBreaker.cs @@ -5,7 +5,7 @@ namespace NServiceBus; using System; using System.Threading; using System.Threading.Tasks; -using Logging; +using Microsoft.Extensions.Logging; /// /// A circuit breaker that is armed on a failure and disarmed on success. After in the @@ -44,6 +44,7 @@ public RepeatedFailuresOverTimeCircuitBreaker( string name, TimeSpan timeToWaitBeforeTriggering, Action triggerAction, + ILogger logger, Action? armedAction = null, Action? disarmedAction = null, TimeSpan? timeToWaitWhenTriggered = default, @@ -51,6 +52,7 @@ public RepeatedFailuresOverTimeCircuitBreaker( { this.name = name; this.triggerAction = triggerAction; + this.logger = logger; this.armedAction = armedAction ?? (static () => { }); this.disarmedAction = disarmedAction ?? (static () => { }); this.timeToWaitBeforeTriggering = timeToWaitBeforeTriggering; @@ -82,14 +84,14 @@ public void Success() circuitBreakerState = Disarmed; _ = timer.Change(Timeout.Infinite, Timeout.Infinite); - Logger.InfoFormat("The circuit breaker for '{0}' is now disarmed.", name); + logger.LogInformation("The circuit breaker for '{BreakerName}' is now disarmed.", name); try { disarmedAction(); } catch (Exception ex) { - Logger.Error($"The circuit breaker for '{name}' was unable to execute the disarm action.", ex); + logger.LogError(ex, "The circuit breaker for '{BreakerName}' was unable to execute the disarm action.", name); throw; } } @@ -130,12 +132,12 @@ public Task Failure(Exception exception, CancellationToken cancellationToken = d } catch (Exception ex) { - Logger.Error($"The circuit breaker for '{name}' was unable to execute the arm action.", new AggregateException(ex, exception)); + logger.LogError(new AggregateException(ex, exception), "The circuit breaker for '{BreakerName}' was unable to execute the arm action.", name); throw; } _ = timer.Change(timeToWaitBeforeTriggering, NoPeriodicTriggering); - Logger.WarnFormat("The circuit breaker for '{0}' is now in the armed state due to '{1}' and might trigger in '{2}' when not disarmed.", name, exception, timeToWaitBeforeTriggering); + logger.LogWarning("The circuit breaker for '{BreakerName}' is now in the armed state due to '{BreakerCause}' and might trigger in '{BreakerTriggerTime}' when not disarmed.", name, exception, timeToWaitBeforeTriggering); } return Delay(); @@ -143,10 +145,7 @@ public Task Failure(Exception exception, CancellationToken cancellationToken = d Task Delay() { var timeToWait = previousState == Triggered ? timeToWaitWhenTriggered : timeToWaitWhenArmed; - if (Logger.IsDebugEnabled) - { - Logger.DebugFormat("The circuit breaker for '{0}' is delaying the operation by '{1}'.", name, timeToWait); - } + logger.LogDebug("The circuit breaker for '{BreakerName}' is delaying the operation by '{BreakerTriggerTime}'.", name, timeToWait); return Task.Delay(timeToWait, cancellationToken); } } @@ -173,7 +172,7 @@ void CircuitBreakerTriggered(object? state) } circuitBreakerState = Triggered; - Logger.WarnFormat("The circuit breaker for '{0}' will now be triggered with exception '{1}'.", name, lastException); + logger.LogWarning("The circuit breaker for '{BreakerName}' will now be triggered with exception '{BreakerCause}'.", name, lastException); try { @@ -181,7 +180,7 @@ void CircuitBreakerTriggered(object? state) } catch (Exception ex) { - Logger.Fatal($"The circuit breaker for '{name}' was unable to execute the trigger action.", new AggregateException(ex, lastException!)); + logger.LogCritical(new AggregateException(ex, lastException!), "The circuit breaker for '{BreakerName}' was unable to execute the trigger action.", name); } } } @@ -204,5 +203,5 @@ void CircuitBreakerTriggered(object? state) const int Triggered = 2; static readonly TimeSpan NoPeriodicTriggering = TimeSpan.FromMilliseconds(-1); - static readonly ILog Logger = LogManager.GetLogger(); + readonly ILogger logger; } \ No newline at end of file diff --git a/src/ServiceControl.Infrastructure/TestLogger/TestContextAppender.cs b/src/ServiceControl.Infrastructure/TestLogger/TestContextAppender.cs index c353a3b60a..ed37368e16 100644 --- a/src/ServiceControl.Infrastructure/TestLogger/TestContextAppender.cs +++ b/src/ServiceControl.Infrastructure/TestLogger/TestContextAppender.cs @@ -4,7 +4,7 @@ using Microsoft.Extensions.Logging; using NUnit.Framework; - class TestContextAppender(string categoryName) : ILogger + class TestContextAppender(string categoryName, LogLevel level) : ILogger { public void Log(LogLevel logLevel, EventId eventId, TState state, Exception exception, Func formatter) { @@ -13,7 +13,7 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except TestContext.Out.WriteLine($"{categoryName}: {formatter(state, exception)}"); } } - public bool IsEnabled(LogLevel logLevel) => logLevel >= LogLevel.Warning; + public bool IsEnabled(LogLevel logLevel) => logLevel >= level; public IDisposable BeginScope(TState state) where TState : notnull => Disposable.Instance; diff --git a/src/ServiceControl.Infrastructure/TestLogger/TestContextAppenderFactory.cs b/src/ServiceControl.Infrastructure/TestLogger/TestContextAppenderFactory.cs index 98e1d683fb..3cac38fce7 100644 --- a/src/ServiceControl.Infrastructure/TestLogger/TestContextAppenderFactory.cs +++ b/src/ServiceControl.Infrastructure/TestLogger/TestContextAppenderFactory.cs @@ -2,13 +2,13 @@ { using Microsoft.Extensions.Logging; - public class TestContextAppenderFactory : ILoggerFactory + public class TestContextAppenderFactory(LogLevel logLevel) : ILoggerFactory { public void AddProvider(ILoggerProvider provider) { } - public ILogger CreateLogger(string categoryName) => new TestContextAppender(categoryName); + public ILogger CreateLogger(string categoryName) => new TestContextAppender(categoryName, logLevel); public void Dispose() { diff --git a/src/ServiceControl.Infrastructure/TestLogger/TestContextProvider.cs b/src/ServiceControl.Infrastructure/TestLogger/TestContextProvider.cs index e879c814a3..90e2dae5d8 100644 --- a/src/ServiceControl.Infrastructure/TestLogger/TestContextProvider.cs +++ b/src/ServiceControl.Infrastructure/TestLogger/TestContextProvider.cs @@ -4,7 +4,14 @@ public class TestContextProvider : ILoggerProvider { - public ILogger CreateLogger(string categoryName) => new TestContextAppender(categoryName); + readonly LogLevel level; + + public TestContextProvider(LogLevel level) + { + this.level = level; + } + + public ILogger CreateLogger(string categoryName) => new TestContextAppender(categoryName, level); public void Dispose() { diff --git a/src/ServiceControl.Monitoring.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs b/src/ServiceControl.Monitoring.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs index debc3ed629..63635fa2cf 100644 --- a/src/ServiceControl.Monitoring.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs +++ b/src/ServiceControl.Monitoring.AcceptanceTests/TestSupport/ServiceControlComponentRunner.cs @@ -13,11 +13,12 @@ namespace ServiceControl.Monitoring.AcceptanceTests.TestSupport using Microsoft.AspNetCore.TestHost; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; + using Microsoft.Extensions.Logging; using Monitoring; using NServiceBus; using NServiceBus.AcceptanceTesting; using NServiceBus.AcceptanceTesting.Support; - using NServiceBus.Logging; + using ServiceControl.Infrastructure; class ServiceControlComponentRunner( ITransportIntegration transportToUse, @@ -33,15 +34,16 @@ class ServiceControlComponentRunner( async Task InitializeServiceControl(ScenarioContext context) { + LoggerUtil.ActiveLoggers = Loggers.Test; settings = new Settings(transportType: transportToUse.TypeName) { ConnectionString = transportToUse.ConnectionString, HttpHostName = "localhost", OnMessage = (id, headers, body, @continue) => { - var log = LogManager.GetLogger(); + var logger = LoggerUtil.CreateStaticLogger(); headers.TryGetValue(Headers.MessageId, out var originalMessageId); - log.Debug($"OnMessage for message '{id}'({originalMessageId ?? string.Empty})."); + logger.LogDebug("OnMessage for message '{MessageId}'({OriginalMessageId})", id, originalMessageId ?? string.Empty); //Do not filter out CC, SA and HB messages as they can't be stamped if (headers.TryGetValue(Headers.EnclosedMessageTypes, out var messageTypes) @@ -60,7 +62,7 @@ async Task InitializeServiceControl(ScenarioContext context) var currentSession = context.TestRunId.ToString(); if (!headers.TryGetValue("SC.SessionID", out var session) || session != currentSession) { - log.Debug($"Discarding message '{id}'({originalMessageId ?? string.Empty}) because it's session id is '{session}' instead of '{currentSession}'."); + logger.LogDebug("Discarding message '{MessageId}'({OriginalMessageId}) because it's session id is '{SessionId}' instead of '{CurrentSessionId}'", id, originalMessageId ?? string.Empty, session, currentSession); return Task.CompletedTask; } @@ -91,12 +93,15 @@ async Task InitializeServiceControl(ScenarioContext context) // Force the DI container to run the dependency resolution check to verify all dependencies can be resolved EnvironmentName = Environments.Development }); + hostBuilder.Logging.ClearProviders(); + hostBuilder.Logging.BuildLogger(LogLevel.Information); + hostBuilder.AddServiceControlMonitoring((criticalErrorContext, cancellationToken) => { var logitem = new ScenarioContext.LogItem { Endpoint = settings.InstanceName, - Level = LogLevel.Fatal, + Level = NServiceBus.Logging.LogLevel.Fatal, LoggerName = $"{settings.InstanceName}.CriticalError", Message = $"{criticalErrorContext.Error}{Environment.NewLine}{criticalErrorContext.Exception}" }; diff --git a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckDirtyMemory.cs b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckDirtyMemory.cs index 8eee53911a..c90bbc4a8e 100644 --- a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckDirtyMemory.cs +++ b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckDirtyMemory.cs @@ -3,26 +3,23 @@ namespace ServiceControl.Persistence.RavenDB.CustomChecks; using System; using System.Threading; using System.Threading.Tasks; +using Microsoft.Extensions.Logging; using NServiceBus.CustomChecks; -using NServiceBus.Logging; -class CheckDirtyMemory(MemoryInformationRetriever memoryInformationRetriever) : CustomCheck("RavenDB dirty memory", "ServiceControl Health", TimeSpan.FromMinutes(5)) +class CheckDirtyMemory(MemoryInformationRetriever memoryInformationRetriever, ILogger logger) : CustomCheck("RavenDB dirty memory", "ServiceControl Health", TimeSpan.FromMinutes(5)) { public override async Task PerformCheck(CancellationToken cancellationToken = default) { var (isHighDirty, dirtyMemory) = await memoryInformationRetriever.GetMemoryInformation(cancellationToken); - Log.Debug($"RavenDB dirty memory value: {dirtyMemory}."); + logger.LogDebug("RavenDB dirty memory value: {DirtyMemory}.", dirtyMemory); if (isHighDirty) { - var message = $"There is a high level of RavenDB dirty memory ({dirtyMemory}). See https://docs.particular.net/servicecontrol/troubleshooting#ravendb-dirty-memory for guidance on how to mitigate the issue."; - Log.Warn(message); - return CheckResult.Failed(message); + logger.LogWarning("There is a high level of RavenDB dirty memory ({DirtyMemory}). See https://docs.particular.net/servicecontrol/troubleshooting#ravendb-dirty-memory for guidance on how to mitigate the issue.", dirtyMemory); + return CheckResult.Failed($"There is a high level of RavenDB dirty memory ({dirtyMemory}). See https://docs.particular.net/servicecontrol/troubleshooting#ravendb-dirty-memory for guidance on how to mitigate the issue."); } return CheckResult.Pass; } - - static readonly ILog Log = LogManager.GetLogger(); } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckFreeDiskSpace.cs b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckFreeDiskSpace.cs index c90bce9807..22029f309c 100644 --- a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckFreeDiskSpace.cs +++ b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckFreeDiskSpace.cs @@ -4,18 +4,16 @@ using System.IO; using System.Threading; using System.Threading.Tasks; + using Microsoft.Extensions.Logging; using NServiceBus.CustomChecks; - using NServiceBus.Logging; + using ServiceControl.Infrastructure; using ServiceControl.Persistence.RavenDB; - class CheckFreeDiskSpace(RavenPersisterSettings settings) : CustomCheck("ServiceControl database", "Storage space", TimeSpan.FromMinutes(5)) + class CheckFreeDiskSpace(RavenPersisterSettings settings, ILogger logger) : CustomCheck("ServiceControl database", "Storage space", TimeSpan.FromMinutes(5)) { public override Task PerformCheck(CancellationToken cancellationToken = default) { - if (Logger.IsDebugEnabled) - { - Logger.Debug($"Check ServiceControl data drive space remaining custom check starting. Threshold {percentageThreshold:P0}"); - } + logger.LogDebug("Check ServiceControl data drive space remaining custom check starting. Threshold {PercentageThreshold:P0}", percentageThreshold); if (!settings.UseEmbeddedServer) { @@ -33,10 +31,7 @@ public override Task PerformCheck(CancellationToken cancellationTok var percentRemaining = (decimal)dataDriveInfo.AvailableFreeSpace / dataDriveInfo.TotalSize; - if (Logger.IsDebugEnabled) - { - Logger.Debug($"Free space: {availableFreeSpace:N0}B | Total: {totalSpace:N0}B | Percent remaining {percentRemaining:P1}"); - } + logger.LogDebug("Free space: {AvailableFreeSpace:N0}B | Total: {TotalSpace:N0}B | Percent remaining {PercentRemaining:P1}", availableFreeSpace, totalSpace, percentRemaining); return percentRemaining > percentageThreshold ? CheckResult.Pass @@ -45,22 +40,19 @@ public override Task PerformCheck(CancellationToken cancellationTok public static void Validate(RavenPersisterSettings settings) { + var logger = LoggerUtil.CreateStaticLogger(); var threshold = settings.DataSpaceRemainingThreshold; - string message; - if (threshold < 0) { - message = $"{RavenPersistenceConfiguration.DataSpaceRemainingThresholdKey} is invalid, minimum value is 0."; - Logger.Fatal(message); - throw new Exception(message); + logger.LogCritical("{RavenPersistenceConfigurationDataSpaceRemainingThresholdKey} is invalid, minimum value is 0.", RavenPersistenceConfiguration.DataSpaceRemainingThresholdKey); + throw new Exception($"{RavenPersistenceConfiguration.DataSpaceRemainingThresholdKey} is invalid, minimum value is 0."); } if (threshold > 100) { - message = $"{RavenPersistenceConfiguration.DataSpaceRemainingThresholdKey} is invalid, maximum value is 100."; - Logger.Fatal(message); - throw new Exception(message); + logger.LogCritical("{RavenPersistenceConfigurationDataSpaceRemainingThresholdKey} is invalid, maximum value is 100.", RavenPersistenceConfiguration.DataSpaceRemainingThresholdKey); + throw new Exception($"{RavenPersistenceConfiguration.DataSpaceRemainingThresholdKey} is invalid, maximum value is 100."); } } @@ -68,6 +60,5 @@ public static void Validate(RavenPersisterSettings settings) readonly decimal percentageThreshold = settings.DataSpaceRemainingThreshold / 100m; public const int DataSpaceRemainingThresholdDefault = 20; - static readonly ILog Logger = LogManager.GetLogger(typeof(CheckFreeDiskSpace)); } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckMinimumStorageRequiredForIngestion.cs b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckMinimumStorageRequiredForIngestion.cs index 053a41cff7..0c04857571 100644 --- a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckMinimumStorageRequiredForIngestion.cs +++ b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckMinimumStorageRequiredForIngestion.cs @@ -4,21 +4,19 @@ using System.IO; using System.Threading; using System.Threading.Tasks; + using Microsoft.Extensions.Logging; using NServiceBus.CustomChecks; - using NServiceBus.Logging; + using ServiceControl.Infrastructure; using ServiceControl.Persistence; using ServiceControl.Persistence.RavenDB; - class CheckMinimumStorageRequiredForIngestion(MinimumRequiredStorageState stateHolder, RavenPersisterSettings settings) : CustomCheck("Message Ingestion Process", "ServiceControl Health", TimeSpan.FromSeconds(5)) + class CheckMinimumStorageRequiredForIngestion(MinimumRequiredStorageState stateHolder, RavenPersisterSettings settings, ILogger logger) : CustomCheck("Message Ingestion Process", "ServiceControl Health", TimeSpan.FromSeconds(5)) { public override Task PerformCheck(CancellationToken cancellationToken = default) { var percentageThreshold = settings.MinimumStorageLeftRequiredForIngestion / 100m; - if (Logger.IsDebugEnabled) - { - Logger.Debug($"Check ServiceControl data drive space starting. Threshold {percentageThreshold:P0}"); - } + logger.LogDebug("Check ServiceControl data drive space starting. Threshold {PercentageThreshold:P0}", percentageThreshold); // Should be checking UseEmbeddedServer but need to check DatabasePath instead for the ATT hack to work if (string.IsNullOrEmpty(settings.DatabasePath)) @@ -35,10 +33,7 @@ public override Task PerformCheck(CancellationToken cancellationTok var percentRemaining = (decimal)dataDriveInfo.AvailableFreeSpace / dataDriveInfo.TotalSize; - if (Logger.IsDebugEnabled) - { - Logger.Debug($"Free space: {availableFreeSpace:N0}B | Total: {totalSpace:N0}B | Percent remaining {percentRemaining:P1}"); - } + logger.LogDebug("Free space: {AvailableFreeSpace:N0}B | Total: {TotalSpace:N0}B | Percent remaining {PercentRemaining:P1}", availableFreeSpace, totalSpace, percentRemaining); if (percentRemaining > percentageThreshold) { @@ -46,33 +41,36 @@ public override Task PerformCheck(CancellationToken cancellationTok return SuccessResult; } - var message = $"Error message ingestion stopped! {percentRemaining:P0} disk space remaining on data drive '{dataDriveInfo.VolumeLabel} ({dataDriveInfo.RootDirectory})' on '{Environment.MachineName}'. This is less than {percentageThreshold}% - the minimal required space configured. The threshold can be set using the {RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey} configuration setting."; - Logger.Warn(message); + logger.LogWarning("Error message ingestion stopped! {PercentRemaining:P0} disk space remaining on data drive '{DataDriveInfoVolumeLabel} ({DataDriveInfoRootDirectory})' on '{MachineName}'. This is less than {PercentageThreshold}% - the minimal required space configured. The threshold can be set using the {RavenBootstrapperMinimumStorageLeftRequiredForIngestionKey} configuration setting.", + percentRemaining, + dataDriveInfo.VolumeLabel, + dataDriveInfo.RootDirectory, + Environment.MachineName, + percentageThreshold, + RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey); stateHolder.CanIngestMore = false; - return CheckResult.Failed(message); + return CheckResult.Failed($"Error message ingestion stopped! {percentRemaining:P0} disk space remaining on data drive '{dataDriveInfo.VolumeLabel} ({dataDriveInfo.RootDirectory})' on '{Environment.MachineName}'. This is less than {percentageThreshold}% - the minimal required space configured. The threshold can be set using the {RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey} configuration setting."); } public static void Validate(RavenPersisterSettings settings) { + var logger = LoggerUtil.CreateStaticLogger(); var threshold = settings.MinimumStorageLeftRequiredForIngestion; if (threshold < 0) { - var message = $"{RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey} is invalid, minimum value is 0."; - Logger.Fatal(message); - throw new Exception(message); + logger.LogCritical("{RavenBootstrapperMinimumStorageLeftRequiredForIngestionKey} is invalid, minimum value is 0.", RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey); + throw new Exception($"{RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey} is invalid, minimum value is 0."); } if (threshold > 100) { - var message = $"{RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey} is invalid, maximum value is 100."; - Logger.Fatal(message); - throw new Exception(message); + logger.LogCritical("{RavenBootstrapperMinimumStorageLeftRequiredForIngestionKey} is invalid, maximum value is 100.", RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey); + throw new Exception($"{RavenBootstrapper.MinimumStorageLeftRequiredForIngestionKey} is invalid, maximum value is 100."); } } public const int MinimumStorageLeftRequiredForIngestionDefault = 5; static readonly Task SuccessResult = Task.FromResult(CheckResult.Pass); - static readonly ILog Logger = LogManager.GetLogger(typeof(CheckMinimumStorageRequiredForIngestion)); } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexErrors.cs b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexErrors.cs index 5567aa7507..89ea567a80 100644 --- a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexErrors.cs +++ b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexErrors.cs @@ -5,12 +5,12 @@ using System.Text; using System.Threading; using System.Threading.Tasks; + using Microsoft.Extensions.Logging; using NServiceBus.CustomChecks; - using NServiceBus.Logging; using Raven.Client.Documents.Operations.Indexes; using ServiceControl.Persistence.RavenDB; - class CheckRavenDBIndexErrors(IRavenDocumentStoreProvider documentStoreProvider) : CustomCheck("Error Database Index Errors", "ServiceControl Health", TimeSpan.FromMinutes(5)) + class CheckRavenDBIndexErrors(IRavenDocumentStoreProvider documentStoreProvider, ILogger logger) : CustomCheck("Error Database Index Errors", "ServiceControl Health", TimeSpan.FromMinutes(5)) { public override async Task PerformCheck(CancellationToken cancellationToken = default) { @@ -41,10 +41,8 @@ public override async Task PerformCheck(CancellationToken cancellat text.AppendLine().AppendLine("See: https://docs.particular.net/search?q=servicecontrol+troubleshooting"); var message = text.ToString(); - Logger.Error(message); + logger.LogError(message); return CheckResult.Failed(message); } - - static readonly ILog Logger = LogManager.GetLogger(); } } diff --git a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexLag.cs b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexLag.cs index 7084d78e34..d0fd05de1c 100644 --- a/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexLag.cs +++ b/src/ServiceControl.Persistence.RavenDB/CustomChecks/CheckRavenDBIndexLag.cs @@ -5,13 +5,13 @@ using System.Text; using System.Threading; using System.Threading.Tasks; + using Microsoft.Extensions.Logging; using NServiceBus.CustomChecks; - using NServiceBus.Logging; using Raven.Client.Documents.Operations; using ServiceControl.Persistence.RavenDB; using CustomCheck = NServiceBus.CustomChecks.CustomCheck; - class CheckRavenDBIndexLag(IRavenDocumentStoreProvider documentStoreProvider) : CustomCheck("Error Database Index Lag", "ServiceControl Health", TimeSpan.FromMinutes(5)) + class CheckRavenDBIndexLag(IRavenDocumentStoreProvider documentStoreProvider, ILogger logger) : CustomCheck("Error Database Index Lag", "ServiceControl Health", TimeSpan.FromMinutes(5)) { public override async Task PerformCheck(CancellationToken cancellationToken = default) { @@ -31,7 +31,7 @@ public override async Task PerformCheck(CancellationToken cancellat return CheckResult.Pass; } - static int CheckAndReportIndexesWithTooMuchIndexLag(IndexInformation[] indexes) + int CheckAndReportIndexesWithTooMuchIndexLag(IndexInformation[] indexes) { int indexCountWithTooMuchLag = 0; @@ -44,12 +44,12 @@ static int CheckAndReportIndexesWithTooMuchIndexLag(IndexInformation[] indexes) if (indexLag > IndexLagThresholdError) { indexCountWithTooMuchLag++; - Log.Error($"Index [{indexStats.Name}] IndexingLag {indexLag} is above error threshold ({IndexLagThresholdError}). Launch in maintenance mode to let indexes catch up."); + logger.LogError("Index [{IndexName}] IndexingLag {IndexLag} is above error threshold ({IndexLagThresholdError}). Launch in maintenance mode to let indexes catch up.", indexStats.Name, indexLag, IndexLagThresholdError); } else if (indexLag > IndexLagThresholdWarning) { indexCountWithTooMuchLag++; - Log.Warn($"Index [{indexStats.Name}] IndexingLag {indexLag} is above warning threshold ({IndexLagThresholdWarning}). Launch in maintenance mode to let indexes catch up."); + logger.LogWarning("Index [{IndexName}] IndexingLag {IndexLag} is above warning threshold ({IndexLagThresholdWarning}). Launch in maintenance mode to let indexes catch up.", indexStats.Name, indexLag, IndexLagThresholdWarning); } } } @@ -57,9 +57,9 @@ static int CheckAndReportIndexesWithTooMuchIndexLag(IndexInformation[] indexes) return indexCountWithTooMuchLag; } - static void CreateDiagnosticsLogEntry(DatabaseStatistics statistics, IndexInformation[] indexes) + void CreateDiagnosticsLogEntry(DatabaseStatistics statistics, IndexInformation[] indexes) { - if (!Log.IsDebugEnabled) + if (!logger.IsEnabled(LogLevel.Debug)) { return; } @@ -73,11 +73,10 @@ static void CreateDiagnosticsLogEntry(DatabaseStatistics statistics, IndexInform { report.AppendLine($"- Index [{indexStats.Name,-44}] State: {indexStats.State}, Stale: {indexStats.IsStale,-5}, Priority: {indexStats.Priority,-6}, LastIndexingTime: {indexStats.LastIndexingTime:u}"); } - Log.Debug(report.ToString()); + logger.LogDebug(report.ToString()); } static readonly TimeSpan IndexLagThresholdWarning = TimeSpan.FromMinutes(1); static readonly TimeSpan IndexLagThresholdError = TimeSpan.FromMinutes(10); - static readonly ILog Log = LogManager.GetLogger(); } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/ErrorMessagesDataStore.cs b/src/ServiceControl.Persistence.RavenDB/ErrorMessagesDataStore.cs index 4c3f77bf6d..4940807646 100644 --- a/src/ServiceControl.Persistence.RavenDB/ErrorMessagesDataStore.cs +++ b/src/ServiceControl.Persistence.RavenDB/ErrorMessagesDataStore.cs @@ -6,7 +6,7 @@ using System.Linq; using System.Threading.Tasks; using Editing; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Raven.Client; using Raven.Client.Documents; using Raven.Client.Documents.Commands; @@ -28,7 +28,8 @@ class ErrorMessagesDataStore( IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider, IBodyStorage bodyStorage, - ExpirationManager expirationManager) + ExpirationManager expirationManager, + ILogger logger) : IErrorMessageDataStore { public async Task>> GetAllMessages( @@ -338,7 +339,7 @@ public async Task ErrorLastBy(string failedMessageId) return result; } - static FailedMessageView Map(FailedMessage message, IAsyncDocumentSession session) + FailedMessageView Map(FailedMessage message, IAsyncDocumentSession session) { var processingAttempt = message.ProcessingAttempts.Last(); @@ -369,7 +370,7 @@ static FailedMessageView Map(FailedMessage message, IAsyncDocumentSession sessio } catch (Exception ex) { - Logger.Warn($"Unable to parse SendingEndpoint from metadata for messageId {message.UniqueMessageId}", ex); + logger.LogWarning(ex, "Unable to parse SendingEndpoint from metadata for messageId {UniqueMessageId}", message.UniqueMessageId); failedMsgView.SendingEndpoint = EndpointDetailsParser.SendingEndpoint(processingAttempt.Headers); } @@ -379,7 +380,7 @@ static FailedMessageView Map(FailedMessage message, IAsyncDocumentSession sessio } catch (Exception ex) { - Logger.Warn($"Unable to parse ReceivingEndpoint from metadata for messageId {message.UniqueMessageId}", ex); + logger.LogWarning(ex, "Unable to parse ReceivingEndpoint from metadata for messageId {UniqueMessageId}", message.UniqueMessageId); failedMsgView.ReceivingEndpoint = EndpointDetailsParser.ReceivingEndpoint(processingAttempt.Headers); } @@ -676,7 +677,5 @@ public async Task StoreFailedMessagesForTestsOnly(params FailedMessage[] failedM await session.SaveChangesAsync(); } - - static readonly ILog Logger = LogManager.GetLogger(); } } diff --git a/src/ServiceControl.Persistence.RavenDB/ExternalIntegrationRequestsDataStore.cs b/src/ServiceControl.Persistence.RavenDB/ExternalIntegrationRequestsDataStore.cs index 27762fc546..6f68141edc 100644 --- a/src/ServiceControl.Persistence.RavenDB/ExternalIntegrationRequestsDataStore.cs +++ b/src/ServiceControl.Persistence.RavenDB/ExternalIntegrationRequestsDataStore.cs @@ -8,8 +8,8 @@ using System.Threading.Tasks; using ExternalIntegrations; using Microsoft.Extensions.Hosting; + using Microsoft.Extensions.Logging; using NServiceBus; - using NServiceBus.Logging; using Raven.Client.Documents; using Raven.Client.Documents.Changes; using ServiceControl.Infrastructure; @@ -20,12 +20,17 @@ class ExternalIntegrationRequestsDataStore , IAsyncDisposable { - public ExternalIntegrationRequestsDataStore(RavenPersisterSettings settings, IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider, CriticalError criticalError) + public ExternalIntegrationRequestsDataStore( + RavenPersisterSettings settings, + IRavenSessionProvider sessionProvider, + IRavenDocumentStoreProvider documentStoreProvider, + CriticalError criticalError, + ILogger logger) { this.settings = settings; this.sessionProvider = sessionProvider; this.documentStoreProvider = documentStoreProvider; - + this.logger = logger; var timeToWait = TimeSpan.FromMinutes(5); var delayAfterFailure = TimeSpan.FromSeconds(20); @@ -33,6 +38,7 @@ public ExternalIntegrationRequestsDataStore(RavenPersisterSettings settings, IRa "EventDispatcher", timeToWait, ex => criticalError.Raise("Repeated failures when dispatching external integration events.", ex), + logger, timeToWaitWhenArmed: delayAfterFailure ); } @@ -97,7 +103,7 @@ async Task StartDispatcherTask(CancellationToken cancellationToken) } catch (Exception ex) { - Logger.Error("An exception occurred when dispatching external integration events", ex); + logger.LogError(ex, "An exception occurred when dispatching external integration events"); await circuitBreaker.Failure(ex, cancellationToken); if (!tokenSource.IsCancellationRequested) @@ -143,10 +149,7 @@ async Task TryDispatchEventBatch() } var allContexts = awaitingDispatching.Select(r => r.DispatchContext).ToArray(); - if (Logger.IsDebugEnabled) - { - Logger.Debug($"Dispatching {allContexts.Length} events."); - } + logger.LogDebug("Dispatching {EventCount} events.", allContexts.Length); await callback(allContexts); @@ -206,6 +209,6 @@ public async ValueTask DisposeAsync() Func callback; bool isDisposed; - static ILog Logger = LogManager.GetLogger(typeof(ExternalIntegrationRequestsDataStore)); + readonly ILogger logger; } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/FailedErrorImportDataStore.cs b/src/ServiceControl.Persistence.RavenDB/FailedErrorImportDataStore.cs index 440468a790..730413af0b 100644 --- a/src/ServiceControl.Persistence.RavenDB/FailedErrorImportDataStore.cs +++ b/src/ServiceControl.Persistence.RavenDB/FailedErrorImportDataStore.cs @@ -3,14 +3,12 @@ using System; using System.Threading; using System.Threading.Tasks; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Raven.Client.Documents.Commands; using ServiceControl.Operations; - class FailedErrorImportDataStore(IRavenSessionProvider sessionProvider) : IFailedErrorImportDataStore + class FailedErrorImportDataStore(IRavenSessionProvider sessionProvider, ILogger logger) : IFailedErrorImportDataStore { - static readonly ILog Logger = LogManager.GetLogger(typeof(FailedErrorImportDataStore)); - public async Task ProcessFailedErrorImports(Func processMessage, CancellationToken cancellationToken) { var succeeded = 0; @@ -30,28 +28,25 @@ public async Task ProcessFailedErrorImports(Func p succeeded++; - if (Logger.IsDebugEnabled) - { - Logger.Debug($"Successfully re-imported failed error message {transportMessage.Id}."); - } + logger.LogDebug("Successfully re-imported failed error message {MessageId}", transportMessage.Id); } catch (OperationCanceledException e) when (cancellationToken.IsCancellationRequested) { - Logger.Info("Cancelled", e); + logger.LogInformation(e, "Cancelled"); } catch (Exception e) { - Logger.Error($"Error while attempting to re-import failed error message {transportMessage.Id}.", e); + logger.LogError(e, "Error while attempting to re-import failed error message {MessageId}.", transportMessage.Id); failed++; } } } - Logger.Info($"Done re-importing failed errors. Successfully re-imported {succeeded} messages. Failed re-importing {failed} messages."); + logger.LogInformation("Done re-importing failed errors. Successfully re-imported {SucceededCount} messages. Failed re-importing {FailedCount} messages.", succeeded, failed); if (failed > 0) { - Logger.Warn($"{failed} messages could not be re-imported. This could indicate a problem with the data. Contact Particular support if you need help with recovering the messages."); + logger.LogWarning("{FailedCount} messages could not be re-imported. This could indicate a problem with the data. Contact Particular support if you need help with recovering the messages.", failed); } } diff --git a/src/ServiceControl.Persistence.RavenDB/FailedMessageViewIndexNotifications.cs b/src/ServiceControl.Persistence.RavenDB/FailedMessageViewIndexNotifications.cs index 690bc056bb..83b2370b36 100644 --- a/src/ServiceControl.Persistence.RavenDB/FailedMessageViewIndexNotifications.cs +++ b/src/ServiceControl.Persistence.RavenDB/FailedMessageViewIndexNotifications.cs @@ -5,12 +5,12 @@ using System.Threading.Tasks; using Api; using Microsoft.Extensions.Hosting; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Persistence; using Persistence.RavenDB; using Raven.Client.Documents; - class FailedMessageViewIndexNotifications(IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider) : IFailedMessageViewIndexNotifications + class FailedMessageViewIndexNotifications(IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider, ILogger logger) : IFailedMessageViewIndexNotifications , IDisposable , IHostedService { @@ -22,7 +22,7 @@ void OnNext() } catch (Exception ex) { - Logger.WarnFormat("Failed to emit MessageFailuresUpdated - {0}", ex); + logger.LogWarning(ex, "Failed to emit MessageFailuresUpdated"); } } @@ -87,8 +87,6 @@ public Task StopAsync(CancellationToken cancellationToken) return Task.CompletedTask; } - static readonly ILog Logger = LogManager.GetLogger(typeof(FailedMessageViewIndexNotifications)); - Func subscriber; IDisposable subscription; int lastUnresolvedCount; diff --git a/src/ServiceControl.Persistence.RavenDB/Infrastructure/Subscriptions/RavenSubscriptionStorage.cs b/src/ServiceControl.Persistence.RavenDB/Infrastructure/Subscriptions/RavenSubscriptionStorage.cs index fdf1520dd6..6b8218b753 100644 --- a/src/ServiceControl.Persistence.RavenDB/Infrastructure/Subscriptions/RavenSubscriptionStorage.cs +++ b/src/ServiceControl.Persistence.RavenDB/Infrastructure/Subscriptions/RavenSubscriptionStorage.cs @@ -7,9 +7,9 @@ using System.Text; using System.Threading; using System.Threading.Tasks; + using Microsoft.Extensions.Logging; using NServiceBus; using NServiceBus.Extensibility; - using NServiceBus.Logging; using NServiceBus.Settings; using NServiceBus.Unicast.Subscriptions; using NServiceBus.Unicast.Subscriptions.MessageDrivenSubscriptions; @@ -21,12 +21,12 @@ class RavenSubscriptionStorage : IServiceControlSubscriptionStorage { - public RavenSubscriptionStorage(IRavenSessionProvider sessionProvider, IReadOnlySettings settings, ReceiveAddresses receiveAddresses) : - this(sessionProvider, settings.EndpointName(), receiveAddresses.MainReceiveAddress, settings.GetAvailableTypes().Implementing().Select(e => new MessageType(e)).ToArray()) + public RavenSubscriptionStorage(IRavenSessionProvider sessionProvider, IReadOnlySettings settings, ReceiveAddresses receiveAddresses, ILogger logger) : + this(sessionProvider, settings.EndpointName(), receiveAddresses.MainReceiveAddress, settings.GetAvailableTypes().Implementing().Select(e => new MessageType(e)).ToArray(), logger) { } - public RavenSubscriptionStorage(IRavenSessionProvider sessionProvider, string endpointName, string localAddress, MessageType[] locallyHandledEventTypes) + public RavenSubscriptionStorage(IRavenSessionProvider sessionProvider, string endpointName, string localAddress, MessageType[] locallyHandledEventTypes, ILogger logger) { this.sessionProvider = sessionProvider; localClient = new SubscriptionClient @@ -36,7 +36,7 @@ public RavenSubscriptionStorage(IRavenSessionProvider sessionProvider, string en }; this.locallyHandledEventTypes = locallyHandledEventTypes; - + this.logger = logger; subscriptions = new Subscriptions(); UpdateLookup(); } @@ -198,9 +198,9 @@ async Task SetSubscriptions(Subscriptions newSubscriptions) static Task LoadSubscriptions(IAsyncDocumentSession session) => session.LoadAsync(Subscriptions.SingleDocumentId); - static async Task MigrateSubscriptions(IAsyncDocumentSession session, SubscriptionClient localClient) + async Task MigrateSubscriptions(IAsyncDocumentSession session, SubscriptionClient localClient) { - Logger.Info("Migrating subscriptions to new format"); + logger.LogInformation("Migrating subscriptions to new format"); var subscriptions = new Subscriptions(); @@ -224,10 +224,8 @@ static async Task MigrateSubscriptions(IAsyncDocumentSession sess Subscriptions subscriptions; ILookup subscriptionsLookup; MessageType[] locallyHandledEventTypes; - + readonly ILogger logger; SemaphoreSlim subscriptionsLock = new SemaphoreSlim(1); - - static readonly ILog Logger = LogManager.GetLogger(); } class Subscriptions diff --git a/src/ServiceControl.Persistence.RavenDB/RavenEmbeddedPersistenceLifecycle.cs b/src/ServiceControl.Persistence.RavenDB/RavenEmbeddedPersistenceLifecycle.cs index f1971af65c..f0172acff7 100644 --- a/src/ServiceControl.Persistence.RavenDB/RavenEmbeddedPersistenceLifecycle.cs +++ b/src/ServiceControl.Persistence.RavenDB/RavenEmbeddedPersistenceLifecycle.cs @@ -6,12 +6,12 @@ namespace ServiceControl.Persistence.RavenDB using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Hosting; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Raven.Client.Documents; using Raven.Client.Exceptions.Database; using ServiceControl.RavenDB; - sealed class RavenEmbeddedPersistenceLifecycle(RavenPersisterSettings databaseConfiguration, IHostApplicationLifetime lifetime) + sealed class RavenEmbeddedPersistenceLifecycle(RavenPersisterSettings databaseConfiguration, IHostApplicationLifetime lifetime, ILogger logger) : IRavenPersistenceLifecycle, IRavenDocumentStoreProvider, IDisposable { public async ValueTask GetDocumentStore(CancellationToken cancellationToken = default) @@ -58,7 +58,7 @@ public async Task Initialize(CancellationToken cancellationToken) } catch (DatabaseLoadTimeoutException e) { - Log.Warn("Could not connect to database. Retrying in 500ms...", e); + logger.LogWarning(e, "Could not connect to database. Retrying in 500ms..."); await Task.Delay(500, cancellationToken); } } @@ -86,7 +86,5 @@ public void Dispose() IDocumentStore? documentStore; EmbeddedDatabase? database; readonly SemaphoreSlim initializeSemaphore = new(1, 1); - - static readonly ILog Log = LogManager.GetLogger(typeof(RavenEmbeddedPersistenceLifecycle)); } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/RavenPersistenceConfiguration.cs b/src/ServiceControl.Persistence.RavenDB/RavenPersistenceConfiguration.cs index f9f66aa6ca..c9d03685e7 100644 --- a/src/ServiceControl.Persistence.RavenDB/RavenPersistenceConfiguration.cs +++ b/src/ServiceControl.Persistence.RavenDB/RavenPersistenceConfiguration.cs @@ -6,6 +6,7 @@ using Configuration; using CustomChecks; using Particular.LicensingComponent.Contracts; + using ServiceControl.Infrastructure; class RavenPersistenceConfiguration : IPersistenceConfiguration { @@ -29,7 +30,7 @@ static T GetRequiredSetting(SettingsRootNamespace settingsRootNamespace, stri } var ravenDbLogLevel = SettingsReader.Read(settingsRootNamespace, RavenBootstrapper.RavenDbLogLevelKey, "Warn"); - var logsMode = RavenDbLogLevelToLogsModeMapper.Map(ravenDbLogLevel); + var logsMode = RavenDbLogLevelToLogsModeMapper.Map(ravenDbLogLevel, LoggerUtil.CreateStaticLogger()); var settings = new RavenPersisterSettings { diff --git a/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/ArchiveDocumentManager.cs b/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/ArchiveDocumentManager.cs index 46589133a4..c83e693141 100644 --- a/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/ArchiveDocumentManager.cs +++ b/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/ArchiveDocumentManager.cs @@ -5,14 +5,14 @@ using System.Linq; using System.Threading.Tasks; using MessageFailures; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Persistence.RavenDB; using Raven.Client.Documents; using Raven.Client.Documents.Commands.Batches; using Raven.Client.Documents.Operations; using Raven.Client.Documents.Session; - class ArchiveDocumentManager(ExpirationManager expirationManager) + class ArchiveDocumentManager(ExpirationManager expirationManager, ILogger logger) { public Task LoadArchiveOperation(IAsyncDocumentSession session, string groupId, ArchiveType archiveType) => session.LoadAsync(ArchiveOperation.MakeId(groupId, archiveType)); @@ -138,7 +138,7 @@ public async Task RemoveArchiveOperation(IRavenSessionProvider sessionProvider, session.Advanced.Defer(new DeleteCommandData(archiveOperation.Id, null)); await session.SaveChangesAsync(); - Logger.Info($"Removing ArchiveOperation {archiveOperation.Id} completed"); + logger.LogInformation("Removing ArchiveOperation {ArchiveOperationId} completed", archiveOperation.Id); } public class GroupDetails @@ -147,6 +147,5 @@ public class GroupDetails public int NumberOfMessagesInGroup { get; set; } } - static readonly ILog Logger = LogManager.GetLogger(); } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/MessageArchiver.cs b/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/MessageArchiver.cs index caf8715282..64f722bbe2 100644 --- a/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/MessageArchiver.cs +++ b/src/ServiceControl.Persistence.RavenDB/Recoverability/Archiving/MessageArchiver.cs @@ -4,8 +4,7 @@ using System.Collections.Generic; using System.Linq; using System.Threading.Tasks; - using NServiceBus.Logging; - using Raven.Client.Documents; + using Microsoft.Extensions.Logging; using RavenDB; using ServiceControl.Infrastructure.DomainEvents; using ServiceControl.Persistence.Recoverability; @@ -17,15 +16,17 @@ public MessageArchiver( IRavenSessionProvider sessionProvider, OperationsManager operationsManager, IDomainEvents domainEvents, - ExpirationManager expirationManager + ExpirationManager expirationManager, + ILogger logger ) { this.sessionProvider = sessionProvider; this.domainEvents = domainEvents; this.expirationManager = expirationManager; + this.logger = logger; this.operationsManager = operationsManager; - archiveDocumentManager = new ArchiveDocumentManager(expirationManager); + archiveDocumentManager = new ArchiveDocumentManager(expirationManager, logger); archivingManager = new ArchivingManager(domainEvents, operationsManager); unarchiveDocumentManager = new UnarchiveDocumentManager(); @@ -34,7 +35,7 @@ ExpirationManager expirationManager public async Task ArchiveAllInGroup(string groupId) { - logger.Info($"Archiving of {groupId} started"); + logger.LogInformation("Archiving of {GroupId} started", groupId); ArchiveOperation archiveOperation; using (var session = await sessionProvider.OpenSession()) @@ -48,15 +49,15 @@ public async Task ArchiveAllInGroup(string groupId) var groupDetails = await archiveDocumentManager.GetGroupDetails(session, groupId); if (groupDetails.NumberOfMessagesInGroup == 0) { - logger.Warn($"No messages to archive in group {groupId}"); + logger.LogWarning("No messages to archive in group {GroupId}", groupId); return; } - logger.Info($"Splitting group {groupId} into batches"); + logger.LogInformation("Splitting group {GroupId} into batches", groupId); archiveOperation = await archiveDocumentManager.CreateArchiveOperation(session, groupId, ArchiveType.FailureGroup, groupDetails.NumberOfMessagesInGroup, groupDetails.GroupName, batchSize); await session.SaveChangesAsync(); - logger.Info($"Group {groupId} has been split into {archiveOperation.NumberOfBatches} batches"); + logger.LogInformation("Group {GroupId} has been split into {NumberOfBatches} batches", groupId, archiveOperation.NumberOfBatches); } } @@ -70,11 +71,11 @@ public async Task ArchiveAllInGroup(string groupId) if (nextBatch == null) { // We're only here in the case where Raven indexes are stale - logger.Warn($"Attempting to archive a batch ({archiveOperation.Id}/{archiveOperation.CurrentBatch}) which appears to already have been archived."); + logger.LogWarning("Attempting to archive a batch ({ArchiveOperationId}/{ArchiveOperationCurrentBatch}) which appears to already have been archived.", archiveOperation.Id, archiveOperation.CurrentBatch); } else { - logger.Info($"Archiving {nextBatch.DocumentIds.Count} messages from group {groupId} starting"); + logger.LogInformation("Archiving {MessageCount} messages from group {GroupId} starting", nextBatch.DocumentIds.Count, groupId); } archiveDocumentManager.ArchiveMessageGroupBatch(batchSession, nextBatch); @@ -98,17 +99,17 @@ await domainEvents.Raise(new FailedMessageGroupBatchArchived if (nextBatch != null) { - logger.Info($"Archiving of {nextBatch.DocumentIds.Count} messages from group {groupId} completed"); + logger.LogInformation("Archiving of {MessageCount} messages from group {GroupId} completed", nextBatch.DocumentIds.Count, groupId); } } } - logger.Info($"Archiving of group {groupId} is complete. Waiting for index updates."); + logger.LogInformation("Archiving of group {GroupId} is complete. Waiting for index updates.", groupId); await archivingManager.ArchiveOperationFinalizing(archiveOperation.RequestId, archiveOperation.ArchiveType); if (!await archiveDocumentManager.WaitForIndexUpdateOfArchiveOperation(sessionProvider, archiveOperation.RequestId, TimeSpan.FromMinutes(5)) ) { - logger.Warn($"Archiving group {groupId} completed but index not updated."); + logger.LogWarning("Archiving group {GroupId} completed but index not updated.", groupId); } await archivingManager.ArchiveOperationCompleted(archiveOperation.RequestId, archiveOperation.ArchiveType); @@ -121,12 +122,12 @@ await domainEvents.Raise(new FailedMessageGroupArchived MessagesCount = archiveOperation.TotalNumberOfMessages, }); - logger.Info($"Archiving of group {groupId} completed"); + logger.LogInformation("Archiving of group {GroupId} completed", groupId); } public async Task UnarchiveAllInGroup(string groupId) { - logger.Info($"Unarchiving of {groupId} started"); + logger.LogInformation("Unarchiving of {GroupId} started", groupId); UnarchiveOperation unarchiveOperation; using (var session = await sessionProvider.OpenSession()) @@ -140,16 +141,16 @@ public async Task UnarchiveAllInGroup(string groupId) var groupDetails = await unarchiveDocumentManager.GetGroupDetails(session, groupId); if (groupDetails.NumberOfMessagesInGroup == 0) { - logger.Warn($"No messages to unarchive in group {groupId}"); + logger.LogWarning("No messages to unarchive in group {GroupId}", groupId); return; } - logger.Info($"Splitting group {groupId} into batches"); + logger.LogInformation("Splitting group {GroupId} into batches", groupId); unarchiveOperation = await unarchiveDocumentManager.CreateUnarchiveOperation(session, groupId, ArchiveType.FailureGroup, groupDetails.NumberOfMessagesInGroup, groupDetails.GroupName, batchSize); await session.SaveChangesAsync(); - logger.Info($"Group {groupId} has been split into {unarchiveOperation.NumberOfBatches} batches"); + logger.LogInformation("Group {GroupId} has been split into {NumberOfBatches} batches", groupId, unarchiveOperation.NumberOfBatches); } } @@ -162,11 +163,11 @@ public async Task UnarchiveAllInGroup(string groupId) if (nextBatch == null) { // We're only here in the case where Raven indexes are stale - logger.Warn($"Attempting to unarchive a batch ({unarchiveOperation.Id}/{unarchiveOperation.CurrentBatch}) which appears to already have been archived."); + logger.LogWarning("Attempting to unarchive a batch ({UnarchiveOperationId}/{UnarchiveOperationCurrentBatch}) which appears to already have been archived.", unarchiveOperation.Id, unarchiveOperation.CurrentBatch); } else { - logger.Info($"Unarchiving {nextBatch.DocumentIds.Count} messages from group {groupId} starting"); + logger.LogInformation("Unarchiving {MessageCount} messages from group {GroupId} starting", nextBatch.DocumentIds.Count, groupId); } unarchiveDocumentManager.UnarchiveMessageGroupBatch(batchSession, nextBatch, expirationManager); @@ -190,19 +191,19 @@ await domainEvents.Raise(new FailedMessageGroupBatchUnarchived if (nextBatch != null) { - logger.Info($"Unarchiving of {nextBatch.DocumentIds.Count} messages from group {groupId} completed"); + logger.LogInformation("Unarchiving of {MessageCount} messages from group {GroupId} completed", nextBatch.DocumentIds.Count, groupId); } } - logger.Info($"Unarchiving of group {groupId} is complete. Waiting for index updates."); + logger.LogInformation("Unarchiving of group {GroupId} is complete. Waiting for index updates.", groupId); await unarchivingManager.UnarchiveOperationFinalizing(unarchiveOperation.RequestId, unarchiveOperation.ArchiveType); if (!await unarchiveDocumentManager.WaitForIndexUpdateOfUnarchiveOperation(sessionProvider, unarchiveOperation.RequestId, TimeSpan.FromMinutes(5)) ) { - logger.Warn($"Unarchiving group {groupId} completed but index not updated."); + logger.LogWarning("Unarchiving group {GroupId} completed but index not updated.", groupId); } - logger.Info($"Unarchiving of group {groupId} completed"); + logger.LogInformation("Unarchiving of group {GroupId} completed", groupId); await unarchivingManager.UnarchiveOperationCompleted(unarchiveOperation.RequestId, unarchiveOperation.ArchiveType); await unarchiveDocumentManager.RemoveUnarchiveOperation(sessionProvider, unarchiveOperation); @@ -239,7 +240,7 @@ public IEnumerable GetArchivalOperations() readonly ArchivingManager archivingManager; readonly UnarchiveDocumentManager unarchiveDocumentManager; readonly UnarchivingManager unarchivingManager; - static readonly ILog logger = LogManager.GetLogger(); + readonly ILogger logger; const int batchSize = 1000; } } diff --git a/src/ServiceControl.Persistence.RavenDB/RetryBatchesDataStore.cs b/src/ServiceControl.Persistence.RavenDB/RetryBatchesDataStore.cs index 3138d9b893..4d951b9354 100644 --- a/src/ServiceControl.Persistence.RavenDB/RetryBatchesDataStore.cs +++ b/src/ServiceControl.Persistence.RavenDB/RetryBatchesDataStore.cs @@ -4,18 +4,16 @@ using System.Collections.Generic; using System.Threading.Tasks; using MessageFailures; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Raven.Client.Documents.Commands; using Raven.Client.Documents.Commands.Batches; using Raven.Client.Documents.Operations; using Raven.Client.Exceptions; using ServiceControl.Recoverability; - class RetryBatchesDataStore(IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider, ExpirationManager expirationManager) + class RetryBatchesDataStore(IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider, ExpirationManager expirationManager, ILogger logger) : IRetryBatchesDataStore { - static readonly ILog Log = LogManager.GetLogger(typeof(RetryBatchesDataStore)); - public async Task CreateRetryBatchesManager() { var session = await sessionProvider.OpenSession(); @@ -32,7 +30,7 @@ public async Task RecordFailedStagingAttempt(IReadOnlyCollection { var failedMessageRetry = failedMessageRetriesById[failedMessage.Id]; - Log.Warn($"Attempt {1} of {maxStagingAttempts} to stage a retry message {failedMessage.UniqueMessageId} failed", e); + logger.LogWarning(e, "Attempt 1 of {MaxStagingAttempts} to stage a retry message {UniqueMessageId} failed", maxStagingAttempts, failedMessage.UniqueMessageId); commands[commandIndex] = new PatchCommandData(failedMessageRetry.Id, null, new PatchRequest { @@ -57,8 +55,8 @@ public async Task RecordFailedStagingAttempt(IReadOnlyCollection } catch (ConcurrencyException) { - Log.DebugFormat( - "Ignoring concurrency exception while incrementing staging attempt count for {0}", + logger.LogDebug( + "Ignoring concurrency exception while incrementing staging attempt count for {StagingId}", stagingId); } } @@ -75,7 +73,7 @@ public async Task IncrementAttemptCounter(FailedMessageRetry message) } catch (ConcurrencyException) { - Log.DebugFormat("Ignoring concurrency exception while incrementing staging attempt count for {0}", message.FailedMessageId); + logger.LogDebug("Ignoring concurrency exception while incrementing staging attempt count for {MessageId}", message.FailedMessageId); } } diff --git a/src/ServiceControl.Persistence.RavenDB/RetryDocumentDataStore.cs b/src/ServiceControl.Persistence.RavenDB/RetryDocumentDataStore.cs index 5d5270cc14..686b77df9f 100644 --- a/src/ServiceControl.Persistence.RavenDB/RetryDocumentDataStore.cs +++ b/src/ServiceControl.Persistence.RavenDB/RetryDocumentDataStore.cs @@ -5,7 +5,7 @@ using System.Linq; using System.Threading.Tasks; using MessageFailures; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Persistence.Infrastructure; using Raven.Client.Documents; using Raven.Client.Documents.Commands.Batches; @@ -15,7 +15,7 @@ using ServiceControl.MessageFailures.Api; using ServiceControl.Recoverability; - class RetryDocumentDataStore(IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider) : IRetryDocumentDataStore + class RetryDocumentDataStore(IRavenSessionProvider sessionProvider, IRavenDocumentStoreProvider documentStoreProvider, ILogger logger) : IRetryDocumentDataStore { public async Task StageRetryByUniqueMessageIds(string batchDocumentId, string[] messageIds) { @@ -48,7 +48,7 @@ public async Task MoveBatchToStaging(string batchDocumentId) } catch (ConcurrencyException) { - Logger.DebugFormat("Ignoring concurrency exception while moving batch to staging {0}", batchDocumentId); + logger.LogDebug("Ignoring concurrency exception while moving batch to staging {BatchDocumentId}", batchDocumentId); } } @@ -202,7 +202,5 @@ public async Task QueryFailureGroupViewOnGroupId(string groupI .FirstOrDefaultAsync(x => x.Id == groupId); return group; } - - static readonly ILog Logger = LogManager.GetLogger(typeof(RetryDocumentDataStore)); } } \ No newline at end of file diff --git a/src/ServiceControl.Persistence.Tests.InMemory/ServiceControl.Persistence.Tests.InMemory.csproj b/src/ServiceControl.Persistence.Tests.InMemory/ServiceControl.Persistence.Tests.InMemory.csproj index 4e0fac1da4..14f8701c33 100644 --- a/src/ServiceControl.Persistence.Tests.InMemory/ServiceControl.Persistence.Tests.InMemory.csproj +++ b/src/ServiceControl.Persistence.Tests.InMemory/ServiceControl.Persistence.Tests.InMemory.csproj @@ -6,6 +6,7 @@ + diff --git a/src/ServiceControl.Persistence.Tests.RavenDB/ServiceControl.Persistence.Tests.RavenDB.csproj b/src/ServiceControl.Persistence.Tests.RavenDB/ServiceControl.Persistence.Tests.RavenDB.csproj index bb4f028ee1..f3ed716dde 100644 --- a/src/ServiceControl.Persistence.Tests.RavenDB/ServiceControl.Persistence.Tests.RavenDB.csproj +++ b/src/ServiceControl.Persistence.Tests.RavenDB/ServiceControl.Persistence.Tests.RavenDB.csproj @@ -5,6 +5,7 @@ + diff --git a/src/ServiceControl.Persistence.Tests.RavenDB/SubscriptionPersisterTests.cs b/src/ServiceControl.Persistence.Tests.RavenDB/SubscriptionPersisterTests.cs index bf60c59a17..1a5b35664c 100644 --- a/src/ServiceControl.Persistence.Tests.RavenDB/SubscriptionPersisterTests.cs +++ b/src/ServiceControl.Persistence.Tests.RavenDB/SubscriptionPersisterTests.cs @@ -8,6 +8,7 @@ using NServiceBus.Unicast.Subscriptions; using NServiceBus.Unicast.Subscriptions.MessageDrivenSubscriptions; using NUnit.Framework; + using ServiceControl.Infrastructure; using ServiceControl.Infrastructure.RavenDB.Subscriptions; [TestFixture] @@ -16,7 +17,7 @@ class SubscriptionPersisterTests : RavenPersistenceTestBase [Test] public async Task ShouldReturnSubscriptionsForOlderVersionsOfSameMessageType() { - var subscriptionPersister = new RavenSubscriptionStorage(SessionProvider, "NServiceBus.Routing.EndpointName", "TestEndpoint", []); + var subscriptionPersister = new RavenSubscriptionStorage(SessionProvider, "NServiceBus.Routing.EndpointName", "TestEndpoint", [], LoggerUtil.CreateStaticLogger()); var v1MessageType = new MessageType(typeof(SampleMessageType).FullName, new Version(1, 0, 0)); var v2MessageType = new MessageType(typeof(SampleMessageType).FullName, new Version(2, 0, 0)); @@ -37,7 +38,7 @@ public async Task ShouldReturnSubscriptionsForOlderVersionsOfSameMessageType() [Test] public async Task ShouldReturnSubscriptionsForNewerVersionsOfSameMessageType() { - var subscriptionPersister = new RavenSubscriptionStorage(SessionProvider, "NServiceBus.Routing.EndpointName", "TestEndpoint", []); + var subscriptionPersister = new RavenSubscriptionStorage(SessionProvider, "NServiceBus.Routing.EndpointName", "TestEndpoint", [], LoggerUtil.CreateStaticLogger()); var v1MessageType = new MessageType(typeof(SampleMessageType).FullName, new Version(1, 0, 0)); var v2MessageType = new MessageType(typeof(SampleMessageType).FullName, new Version(2, 0, 0)); diff --git a/src/ServiceControl.Persistence.Tests/PersistenceTestBase.cs b/src/ServiceControl.Persistence.Tests/PersistenceTestBase.cs index c6d0de3aa2..7cc5f39cca 100644 --- a/src/ServiceControl.Persistence.Tests/PersistenceTestBase.cs +++ b/src/ServiceControl.Persistence.Tests/PersistenceTestBase.cs @@ -4,10 +4,12 @@ using System.Threading.Tasks; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; +using Microsoft.Extensions.Logging; using NServiceBus; using NServiceBus.Settings; using NUnit.Framework; using Particular.LicensingComponent.Persistence; +using ServiceControl.Infrastructure; using ServiceControl.Infrastructure.DomainEvents; using ServiceControl.Operations.BodyStorage; using ServiceControl.Persistence; @@ -30,6 +32,10 @@ public async Task SetUp() } var hostBuilder = Host.CreateApplicationBuilder(); + + LoggerUtil.ActiveLoggers = Loggers.Test; + hostBuilder.Logging.BuildLogger(LogLevel.Information); + await PersistenceTestsContext.Setup(hostBuilder); // This is not cool. We have things that are registered as part of "the persistence" that then require parts diff --git a/src/ServiceControl.Persistence/PersistenceManifest.cs b/src/ServiceControl.Persistence/PersistenceManifest.cs index 0be97cafb6..9279f6cdc6 100644 --- a/src/ServiceControl.Persistence/PersistenceManifest.cs +++ b/src/ServiceControl.Persistence/PersistenceManifest.cs @@ -5,7 +5,8 @@ using System.IO; using System.Linq; using System.Text.Json; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; + using ServiceControl.Infrastructure; public class PersistenceManifest { @@ -68,7 +69,7 @@ static PersistenceManifestLibrary() } catch (Exception ex) { - logger.Warn($"Failed to load persistence manifests from {assemblyDirectory}", ex); + logger.LogWarning(ex, "Failed to load persistence manifests from {AssemblyDirectory}", assemblyDirectory); } try @@ -83,10 +84,10 @@ static PersistenceManifestLibrary() } catch (Exception ex) { - logger.Warn($"Failed to load persistence manifests from development locations", ex); + logger.LogWarning(ex, "Failed to load persistence manifests from development locations"); } - PersistenceManifests.ForEach(m => logger.Info($"Found persistence manifest for {m.DisplayName}")); + PersistenceManifests.ForEach(m => logger.LogInformation("Found persistence manifest for {ManifestDisplayName}", m.DisplayName)); } static string GetAssemblyDirectory() @@ -107,7 +108,7 @@ public static PersistenceManifest Find(string persistenceType) return persistenceManifest; } - static readonly ILog logger = LogManager.GetLogger(typeof(PersistenceManifestLibrary)); + static readonly ILogger logger = LoggerUtil.CreateStaticLogger(typeof(PersistenceManifestLibrary)); } } diff --git a/src/ServiceControl.Persistence/ServiceControl.Persistence.csproj b/src/ServiceControl.Persistence/ServiceControl.Persistence.csproj index 050bcbec4b..1806eaf133 100644 --- a/src/ServiceControl.Persistence/ServiceControl.Persistence.csproj +++ b/src/ServiceControl.Persistence/ServiceControl.Persistence.csproj @@ -7,6 +7,7 @@ + diff --git a/src/ServiceControl.RavenDB/EmbeddedDatabase.cs b/src/ServiceControl.RavenDB/EmbeddedDatabase.cs index 590792fe20..e9fa10ea44 100644 --- a/src/ServiceControl.RavenDB/EmbeddedDatabase.cs +++ b/src/ServiceControl.RavenDB/EmbeddedDatabase.cs @@ -10,11 +10,12 @@ namespace ServiceControl.RavenDB using System.Threading.Tasks; using ByteSizeLib; using Microsoft.Extensions.Hosting; - using NServiceBus.Logging; + using Microsoft.Extensions.Logging; using Raven.Client.Documents; using Raven.Client.Documents.Conventions; using Raven.Client.ServerWide.Operations; using Raven.Embedded; + using ServiceControl.Infrastructure; using Sparrow.Logging; public sealed class EmbeddedDatabase : IDisposable @@ -67,7 +68,7 @@ public static EmbeddedDatabase Start(EmbeddedDatabaseConfiguration databaseConfi ); } - Logger.InfoFormat("Loading RavenDB license from {0}", licenseFileNameAndServerDirectory.LicenseFileName); + logger.LogInformation("Loading RavenDB license from {LicenseFileName}", licenseFileNameAndServerDirectory.LicenseFileName); var serverOptions = new ServerOptions { CommandLineArgs = @@ -119,12 +120,12 @@ void Start(ServerOptions serverOptions) shutdownCancellationToken.ThrowIfCancellationRequested(); - Logger.Info("Restarting RavenDB server process"); + logger.LogInformation("Restarting RavenDB server process"); await EmbeddedServer.Instance.RestartServerAsync(); restartRequired = false; - Logger.Info("RavenDB server process restarted successfully."); + logger.LogInformation("RavenDB server process restarted successfully."); } catch (OperationCanceledException) when (shutdownCancellationToken.IsCancellationRequested) { @@ -132,7 +133,7 @@ void Start(ServerOptions serverOptions) } catch (Exception e) { - Logger.Fatal($"RavenDB server restart failed. Restart will be retried in {delayBetweenRestarts}.", e); + logger.LogCritical(e, "RavenDB server restart failed. Restart will be retried in {RavenDelayBetweenRestarts}.", delayBetweenRestarts); } } }, CancellationToken.None); @@ -148,11 +149,11 @@ void OnServerProcessExited(object? sender, ServerProcessExitedEventArgs _) restartRequired = true; if (sender is Process process) { - Logger.Warn($"RavenDB server process exited unexpectedly with exitCode: {process.ExitCode}. Process will be restarted."); + logger.LogWarning("RavenDB server process exited unexpectedly with exitCode: {RavenExitCode}. Process will be restarted.", process.ExitCode); } else { - Logger.Warn($"RavenDB server process exited unexpectedly. Process will be restarted."); + logger.LogWarning("RavenDB server process exited unexpectedly. Process will be restarted."); } } @@ -187,7 +188,7 @@ public async Task DeleteDatabase(string dbName) public async Task Stop(CancellationToken cancellationToken) { - Logger.Debug("Stopping RavenDB server"); + logger.LogDebug("Stopping RavenDB server"); EmbeddedServer.Instance.ServerProcessExited -= OnServerProcessExited; await shutdownTokenSource.CancelAsync(); @@ -224,23 +225,23 @@ public async Task Stop(CancellationToken cancellationToken) { // We always want to try and kill the process, even when already cancelled processId = await EmbeddedServer.Instance.GetServerProcessIdAsync(CancellationToken.None); - Logger.WarnFormat("Killing RavenDB server PID {0} because host cancelled", processId); + logger.LogWarning("Killing RavenDB server PID {PID} because host cancelled", processId); using var ravenChildProcess = Process.GetProcessById(processId); ravenChildProcess.Kill(entireProcessTree: true); // Kill only signals - Logger.WarnFormat("Waiting for RavenDB server PID {0} to exit... ", processId); + logger.LogWarning("Waiting for RavenDB server PID {PID} to exit... ", processId); // When WaitForExitAsync returns, the process could still exist but in a frozen state to flush // memory mapped pages to storage. await ravenChildProcess.WaitForExitAsync(CancellationToken.None); } catch (Exception e) { - Logger.ErrorFormat("Failed to kill RavenDB server PID {0} shutdown\n{1}", processId, e); + logger.LogError(e, "Failed to kill RavenDB server PID {PID} shutdown", processId); } } serverOptions = null!; - Logger.Debug("Stopped RavenDB server"); + logger.LogDebug("Stopped RavenDB server"); } public void Dispose() @@ -262,9 +263,9 @@ public void Dispose() // Set GracefulShutdownTimeout to Zero and exit ASAP, under normal operation instance would already // have been allowed to gracefully stop during "Stop" method. serverOptions!.GracefulShutdownTimeout = TimeSpan.Zero; - Logger.Debug("Disposing RavenDB server"); + logger.LogDebug("Disposing RavenDB server"); EmbeddedServer.Instance.Dispose(); - Logger.Debug("Disposed RavenDB server"); + logger.LogDebug("Disposed RavenDB server"); } shutdownTokenSource.Dispose(); @@ -287,7 +288,7 @@ static void RecordStartup(EmbeddedDatabaseConfiguration configuration) RavenDB Logging Level: {configuration.LogsMode} -------------------------------------------------------------"; - Logger.Info(startupMessage); + logger.LogInformation(startupMessage); } static long DataSize(EmbeddedDatabaseConfiguration configuration) @@ -354,6 +355,6 @@ static long DirSize(DirectoryInfo d) ServerOptions? serverOptions; static TimeSpan delayBetweenRestarts = TimeSpan.FromSeconds(60); - static readonly ILog Logger = LogManager.GetLogger(); + static readonly ILogger logger = LoggerUtil.CreateStaticLogger(); } } diff --git a/src/ServiceControl.RavenDB/ServiceControl.RavenDB.csproj b/src/ServiceControl.RavenDB/ServiceControl.RavenDB.csproj index 46705a80e7..0479c4ff74 100644 --- a/src/ServiceControl.RavenDB/ServiceControl.RavenDB.csproj +++ b/src/ServiceControl.RavenDB/ServiceControl.RavenDB.csproj @@ -12,6 +12,10 @@ + + + + diff --git a/src/ServiceControl.Transports.Tests/TransportTestFixture.cs b/src/ServiceControl.Transports.Tests/TransportTestFixture.cs index ac1501232b..7dd9d6ef5d 100644 --- a/src/ServiceControl.Transports.Tests/TransportTestFixture.cs +++ b/src/ServiceControl.Transports.Tests/TransportTestFixture.cs @@ -23,8 +23,8 @@ class TransportTestFixture [SetUp] public virtual async Task Setup() { - //TODO remove LogManager usage - LogManager.UseFactory(new ExtensionsLoggerFactory(new TestContextAppenderFactory())); + //used for loggers outside of ServiceControl (i.e. transports and core) to use the logger factory defined here + LogManager.UseFactory(new ExtensionsLoggerFactory(new TestContextAppenderFactory(Microsoft.Extensions.Logging.LogLevel.Warning))); LoggerUtil.ActiveLoggers = Loggers.Test; configuration = new TransportTestsConfiguration(); testCancellationTokenSource = Debugger.IsAttached ? new CancellationTokenSource() : new CancellationTokenSource(TestTimeout); diff --git a/src/ServiceControl.UnitTests/RepeatedFailuresOverTimeCircuitBreakerTests.cs b/src/ServiceControl.UnitTests/RepeatedFailuresOverTimeCircuitBreakerTests.cs index 67e71198cc..e955646a88 100644 --- a/src/ServiceControl.UnitTests/RepeatedFailuresOverTimeCircuitBreakerTests.cs +++ b/src/ServiceControl.UnitTests/RepeatedFailuresOverTimeCircuitBreakerTests.cs @@ -6,12 +6,16 @@ using System.Threading; using System.Threading.Tasks; using NUnit.Framework; + using ServiceControl.Infrastructure; // Ideally the circuit breaker would use a time provider to allow for easier testing but that would require a significant refactor // and we want keep the changes to a minimum for now to allow backporting to older versions. [TestFixture] public class RepeatedFailuresOverTimeCircuitBreakerTests { + [SetUp] + public void Setup() => LoggerUtil.ActiveLoggers = Loggers.Test; + [Test] public async Task Should_disarm_on_success() { @@ -22,6 +26,7 @@ public async Task Should_disarm_on_success() "TestCircuitBreaker", TimeSpan.FromMilliseconds(100), ex => { }, + LoggerUtil.CreateStaticLogger(), () => armedActionCalled = true, () => disarmedActionCalled = true, TimeSpan.Zero, @@ -42,6 +47,7 @@ public async Task Should_rethrow_exception_on_success() "TestCircuitBreaker", TimeSpan.FromMilliseconds(100), ex => { }, + LoggerUtil.CreateStaticLogger(), () => { }, () => throw new Exception("Exception from disarmed action"), timeToWaitWhenTriggered: TimeSpan.Zero, @@ -64,6 +70,7 @@ public async Task Should_trigger_after_failure_timeout() "TestCircuitBreaker", TimeSpan.Zero, ex => { triggerActionCalled = true; lastTriggerException = ex; }, + LoggerUtil.CreateStaticLogger(), timeToWaitWhenTriggered: TimeSpan.Zero, timeToWaitWhenArmed: TimeSpan.FromMilliseconds(100) ); @@ -81,6 +88,7 @@ public void Should_rethrow_exception_on_failure() "TestCircuitBreaker", TimeSpan.FromMilliseconds(100), ex => { }, + LoggerUtil.CreateStaticLogger(), () => throw new Exception("Exception from armed action"), () => { }, timeToWaitWhenTriggered: TimeSpan.Zero, @@ -101,6 +109,7 @@ public async Task Should_delay_after_trigger_failure() "TestCircuitBreaker", TimeSpan.Zero, _ => { }, + LoggerUtil.CreateStaticLogger(), timeToWaitWhenTriggered: timeToWaitWhenTriggered, timeToWaitWhenArmed: timeToWaitWhenArmed ); @@ -124,6 +133,7 @@ public async Task Should_not_trigger_if_disarmed_before_timeout() "TestCircuitBreaker", TimeSpan.FromMilliseconds(100), ex => triggerActionCalled = true, + LoggerUtil.CreateStaticLogger(), timeToWaitWhenTriggered: TimeSpan.Zero, timeToWaitWhenArmed: TimeSpan.Zero ); @@ -145,6 +155,7 @@ public async Task Should_handle_concurrent_failure_and_success() "TestCircuitBreaker", TimeSpan.FromMilliseconds(100), ex => triggerActionCalled = true, + LoggerUtil.CreateStaticLogger(), () => armedActionCalled = true, () => disarmedActionCalled = true, TimeSpan.Zero, @@ -176,6 +187,7 @@ public async Task Should_handle_high_concurrent_failure_and_success() "TestCircuitBreaker", TimeSpan.FromSeconds(5), ex => Interlocked.Increment(ref triggerActionCalled), + LoggerUtil.CreateStaticLogger(), () => Interlocked.Increment(ref armedActionCalled), () => Interlocked.Increment(ref disarmedActionCalled), TimeSpan.Zero, @@ -209,6 +221,7 @@ public async Task Should_trigger_after_multiple_failures_and_timeout() "TestCircuitBreaker", TimeSpan.FromMilliseconds(50), ex => triggerActionCalled = true, + LoggerUtil.CreateStaticLogger(), timeToWaitWhenTriggered: TimeSpan.FromMilliseconds(50), timeToWaitWhenArmed: TimeSpan.FromMilliseconds(50) ); diff --git a/src/ServiceControl/HostApplicationBuilderExtensions.cs b/src/ServiceControl/HostApplicationBuilderExtensions.cs index 25685e7623..14ee26a003 100644 --- a/src/ServiceControl/HostApplicationBuilderExtensions.cs +++ b/src/ServiceControl/HostApplicationBuilderExtensions.cs @@ -21,7 +21,6 @@ namespace Particular.ServiceControl using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Hosting.WindowsServices; using Microsoft.Extensions.Logging; - using NLog.Extensions.Logging; using NServiceBus; using NServiceBus.Configuration.AdvancedExtensibility; using NServiceBus.Transport; @@ -42,11 +41,8 @@ public static void AddServiceControl(this IHostApplicationBuilder hostBuilder, S EventSourceCreator.Create(); } - var logging = hostBuilder.Logging; - logging.ClearProviders(); - //HINT: configuration used by NLog comes from LoggingConfigurator.cs - logging.AddNLog(); - logging.SetMinimumLevel(settings.LoggingSettings.LogLevel); + hostBuilder.Logging.ClearProviders(); + hostBuilder.Logging.BuildLogger(settings.LoggingSettings.LogLevel); var services = hostBuilder.Services; var transportSettings = settings.ToTransportSettings();