diff --git a/src/Cli.Tests/EndToEndTests.cs b/src/Cli.Tests/EndToEndTests.cs index 862d097a6d..1f23c6857f 100644 --- a/src/Cli.Tests/EndToEndTests.cs +++ b/src/Cli.Tests/EndToEndTests.cs @@ -810,35 +810,24 @@ public Task TestUpdatingStoredProcedureWithRestMethods() } /// - /// Test to validate that the engine starts successfully when --verbose and --LogLevel - /// options are used with the start command - /// This test does not validate whether the engine logs messages at the specified log level + /// Validates that the engine starts successfully when --verbose or --LogLevel is set to a level + /// at or below Information (0-2 / Trace, Debug, Information). + /// CLI phase messages (product name, config path) are emitted at Information level and must + /// therefore appear in stdout. /// - /// Log level options + /// Log level option passed to the start command. [DataTestMethod] [DataRow("", DisplayName = "No logging from command line.")] [DataRow("--verbose", DisplayName = "Verbose logging from command line.")] [DataRow("--LogLevel 0", DisplayName = "LogLevel 0 from command line.")] [DataRow("--LogLevel 1", DisplayName = "LogLevel 1 from command line.")] [DataRow("--LogLevel 2", DisplayName = "LogLevel 2 from command line.")] - [DataRow("--LogLevel 3", DisplayName = "LogLevel 3 from command line.")] - [DataRow("--LogLevel 4", DisplayName = "LogLevel 4 from command line.")] - [DataRow("--LogLevel 5", DisplayName = "LogLevel 5 from command line.")] - [DataRow("--LogLevel 6", DisplayName = "LogLevel 6 from command line.")] [DataRow("--LogLevel Trace", DisplayName = "LogLevel Trace from command line.")] [DataRow("--LogLevel Debug", DisplayName = "LogLevel Debug from command line.")] [DataRow("--LogLevel Information", DisplayName = "LogLevel Information from command line.")] - [DataRow("--LogLevel Warning", DisplayName = "LogLevel Warning from command line.")] - [DataRow("--LogLevel Error", DisplayName = "LogLevel Error from command line.")] - [DataRow("--LogLevel Critical", DisplayName = "LogLevel Critical from command line.")] - [DataRow("--LogLevel None", DisplayName = "LogLevel None from command line.")] [DataRow("--LogLevel tRace", DisplayName = "Case sensitivity: LogLevel Trace from command line.")] [DataRow("--LogLevel DebUG", DisplayName = "Case sensitivity: LogLevel Debug from command line.")] [DataRow("--LogLevel information", DisplayName = "Case sensitivity: LogLevel Information from command line.")] - [DataRow("--LogLevel waRNing", DisplayName = "Case sensitivity: LogLevel Warning from command line.")] - [DataRow("--LogLevel eRROR", DisplayName = "Case sensitivity: LogLevel Error from command line.")] - [DataRow("--LogLevel CrItIcal", DisplayName = "Case sensitivity: LogLevel Critical from command line.")] - [DataRow("--LogLevel NONE", DisplayName = "Case sensitivity: LogLevel None from command line.")] public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption) { _fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG); @@ -857,6 +846,42 @@ public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption StringAssert.Contains(output, $"User provided config file: {TEST_RUNTIME_CONFIG_FILE}", StringComparison.Ordinal); } + /// + /// Validates that the engine starts successfully when --LogLevel is set to Warning or above + /// (3-6 / Warning, Error, Critical, None). + /// CLI phase messages are logged at Information level and are suppressed at Warning+, so no + /// stdout output is expected during the CLI phase. + /// + /// Log level option passed to the start command. + [DataTestMethod] + [DataRow("--LogLevel 3", DisplayName = "LogLevel 3 from command line.")] + [DataRow("--LogLevel 4", DisplayName = "LogLevel 4 from command line.")] + [DataRow("--LogLevel 5", DisplayName = "LogLevel 5 from command line.")] + [DataRow("--LogLevel 6", DisplayName = "LogLevel 6 from command line.")] + [DataRow("--LogLevel Warning", DisplayName = "LogLevel Warning from command line.")] + [DataRow("--LogLevel Error", DisplayName = "LogLevel Error from command line.")] + [DataRow("--LogLevel Critical", DisplayName = "LogLevel Critical from command line.")] + [DataRow("--LogLevel None", DisplayName = "LogLevel None from command line.")] + [DataRow("--LogLevel waRNing", DisplayName = "Case sensitivity: LogLevel Warning from command line.")] + [DataRow("--LogLevel eRROR", DisplayName = "Case sensitivity: LogLevel Error from command line.")] + [DataRow("--LogLevel CrItIcal", DisplayName = "Case sensitivity: LogLevel Critical from command line.")] + [DataRow("--LogLevel NONE", DisplayName = "Case sensitivity: LogLevel None from command line.")] + public void TestEngineStartUpWithHighLogLevelOptions(string logLevelOption) + { + _fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG); + + using Process process = ExecuteDabCommand( + command: $"start --config {TEST_RUNTIME_CONFIG_FILE}", + logLevelOption + ); + + // CLI phase messages are at Information level and are suppressed by Warning+. + // Assert the engine did not exit within a short timeout, then clean up. + bool exitedWithinTimeout = process.WaitForExit(1000); + Assert.IsFalse(exitedWithinTimeout, "Engine process should still be running after 1 second."); + process.Kill(); + } + /// /// Validates that valid usage of verbs and associated options produce exit code 0 (CliReturnCode.SUCCESS). /// Verifies that explicitly implemented verbs (add, update, init, start) and appropriately @@ -1088,10 +1113,6 @@ public async Task TestExitOfRuntimeEngineWithInvalidConfig( output = await process.StandardOutput.ReadLineAsync(); Assert.IsNotNull(output); StringAssert.Contains(output, $"Setting default minimum LogLevel:", StringComparison.Ordinal); - - output = await process.StandardOutput.ReadLineAsync(); - Assert.IsNotNull(output); - StringAssert.Contains(output, "Starting the runtime engine...", StringComparison.Ordinal); } else { diff --git a/src/Cli.Tests/UtilsTests.cs b/src/Cli.Tests/UtilsTests.cs index b02649339d..4133be7caa 100644 --- a/src/Cli.Tests/UtilsTests.cs +++ b/src/Cli.Tests/UtilsTests.cs @@ -313,3 +313,54 @@ public void TestMergeConfigAvailability( } } +/// +/// Unit tests for . +/// +[TestClass] +public class ProgramPreParseLogLevelTests +{ + /// + /// Verifies that numeric and named log level values, including mixed-case variants, + /// are parsed correctly from the raw argument array. + /// + [DataTestMethod] + [DataRow(new string[] { "--LogLevel", "0" }, LogLevel.Trace, DisplayName = "Numeric 0 -> Trace")] + [DataRow(new string[] { "--LogLevel", "1" }, LogLevel.Debug, DisplayName = "Numeric 1 -> Debug")] + [DataRow(new string[] { "--LogLevel", "2" }, LogLevel.Information, DisplayName = "Numeric 2 -> Information")] + [DataRow(new string[] { "--LogLevel", "3" }, LogLevel.Warning, DisplayName = "Numeric 3 -> Warning")] + [DataRow(new string[] { "--LogLevel", "4" }, LogLevel.Error, DisplayName = "Numeric 4 -> Error")] + [DataRow(new string[] { "--LogLevel", "5" }, LogLevel.Critical, DisplayName = "Numeric 5 -> Critical")] + [DataRow(new string[] { "--LogLevel", "6" }, LogLevel.None, DisplayName = "Numeric 6 -> None")] + [DataRow(new string[] { "--LogLevel", "Trace" }, LogLevel.Trace, DisplayName = "Named Trace")] + [DataRow(new string[] { "--LogLevel", "Debug" }, LogLevel.Debug, DisplayName = "Named Debug")] + [DataRow(new string[] { "--LogLevel", "Information" }, LogLevel.Information, DisplayName = "Named Information")] + [DataRow(new string[] { "--LogLevel", "Warning" }, LogLevel.Warning, DisplayName = "Named Warning")] + [DataRow(new string[] { "--LogLevel", "Error" }, LogLevel.Error, DisplayName = "Named Error")] + [DataRow(new string[] { "--LogLevel", "Critical" }, LogLevel.Critical, DisplayName = "Named Critical")] + [DataRow(new string[] { "--LogLevel", "None" }, LogLevel.None, DisplayName = "Named None")] + [DataRow(new string[] { "--LogLevel", "tRace" }, LogLevel.Trace, DisplayName = "Case-insensitive: tRace -> Trace")] + [DataRow(new string[] { "--LogLevel", "NONE" }, LogLevel.None, DisplayName = "Case-insensitive: NONE -> None")] + [DataRow(new string[] { "--LogLevel", "waRNing" }, LogLevel.Warning, DisplayName = "Case-insensitive: waRNing -> Warning")] + public void PreParseLogLevel_ValidValues_ReturnsExpectedLogLevel(string[] args, LogLevel expected) + { + LogLevel actual = Cli.Program.PreParseLogLevel(args); + Assert.AreEqual(expected, actual); + } + + /// + /// Verifies that the default log level () is returned + /// when --LogLevel is absent or its value is invalid. + /// + [DataTestMethod] + [DataRow(new string[] { }, DisplayName = "Empty args -> Information")] + [DataRow(new string[] { "start", "--config", "dab-config.json" }, DisplayName = "No --LogLevel flag -> Information")] + [DataRow(new string[] { "--LogLevel", "bogus" }, DisplayName = "Invalid value -> Information")] + [DataRow(new string[] { "--LogLevel", "7" }, DisplayName = "Out-of-range numeric 7 -> Information")] + [DataRow(new string[] { "--LogLevel" }, DisplayName = "Flag with no value -> Information")] + public void PreParseLogLevel_InvalidOrAbsent_ReturnsInformation(string[] args) + { + LogLevel actual = Cli.Program.PreParseLogLevel(args); + Assert.AreEqual(LogLevel.Information, actual); + } +} + diff --git a/src/Cli/CustomLoggerProvider.cs b/src/Cli/CustomLoggerProvider.cs index c06918b93f..e1b820953a 100644 --- a/src/Cli/CustomLoggerProvider.cs +++ b/src/Cli/CustomLoggerProvider.cs @@ -8,18 +8,25 @@ /// public class CustomLoggerProvider : ILoggerProvider { + private readonly LogLevel _minimumLogLevel; + + public CustomLoggerProvider(LogLevel minimumLogLevel = LogLevel.Information) + { + _minimumLogLevel = minimumLogLevel; + } + public void Dispose() { } /// public ILogger CreateLogger(string categoryName) { - return new CustomConsoleLogger(); + return new CustomConsoleLogger(_minimumLogLevel); } public class CustomConsoleLogger : ILogger { // Minimum LogLevel. LogLevel below this would be disabled. - private readonly LogLevel _minimumLogLevel = LogLevel.Information; + private readonly LogLevel _minimumLogLevel; // Color values based on LogLevel // LogLevel Foreground Background @@ -56,12 +63,17 @@ public class CustomConsoleLogger : ILogger {LogLevel.Critical, ConsoleColor.DarkRed} }; + public CustomConsoleLogger(LogLevel minimumLogLevel = LogLevel.Information) + { + _minimumLogLevel = minimumLogLevel; + } + /// /// Creates Log message by setting console message color based on LogLevel. /// public void Log(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func formatter) { - if (!IsEnabled(logLevel) || logLevel < _minimumLogLevel) + if (!IsEnabled(logLevel)) { return; } @@ -79,8 +91,9 @@ public void Log(LogLevel logLevel, EventId eventId, TState state, Except /// public bool IsEnabled(LogLevel logLevel) { - return true; + return logLevel != LogLevel.None && logLevel >= _minimumLogLevel; } + public IDisposable? BeginScope(TState state) where TState : notnull { throw new NotImplementedException(); diff --git a/src/Cli/Program.cs b/src/Cli/Program.cs index de16ed27f5..ea5d37411a 100644 --- a/src/Cli/Program.cs +++ b/src/Cli/Program.cs @@ -26,8 +26,12 @@ public static int Main(string[] args) // Load environment variables from .env file if present. DotNetEnv.Env.Load(); + // Pre-parse --LogLevel from raw args before CommandLine.Parser runs so that + // CLI-phase messages (version info, config path) respect the user-specified level. + LogLevel cliLogLevel = PreParseLogLevel(args); + // Logger setup and configuration - ILoggerFactory loggerFactory = Utils.LoggerFactoryForCli; + ILoggerFactory loggerFactory = Utils.GetLoggerFactoryForCli(cliLogLevel); ILogger cliLogger = loggerFactory.CreateLogger(); ILogger configGeneratorLogger = loggerFactory.CreateLogger(); ILogger cliUtilsLogger = loggerFactory.CreateLogger(); @@ -37,10 +41,42 @@ public static int Main(string[] args) // Sets up the filesystem used for reading and writing runtime configuration files. IFileSystem fileSystem = new FileSystem(); FileSystemRuntimeConfigLoader loader = new(fileSystem, handler: null, isCliLoader: true); - return Execute(args, cliLogger, fileSystem, loader); } + /// + /// Scans for a --LogLevel flag and returns the parsed + /// . Falls back to when the + /// flag is absent or its value cannot be parsed. + /// + /// Raw command-line arguments. + /// The log level to use for the CLI logging phase. + public static LogLevel PreParseLogLevel(string[] args) + { + for (int i = 0; i < args.Length - 1; i++) + { + if (string.Equals(args[i], "--LogLevel", StringComparison.OrdinalIgnoreCase)) + { + string raw = args[i + 1]; + // Accept both integer form (0-6) and named form (Trace, Debug, …). + if (int.TryParse(raw, out int numericLevel) + && numericLevel >= (int)LogLevel.Trace + && numericLevel <= (int)LogLevel.None) + { + return (LogLevel)numericLevel; + } + + if (Enum.TryParse(raw, ignoreCase: true, out LogLevel namedLevel) + && namedLevel >= LogLevel.Trace && namedLevel <= LogLevel.None) + { + return namedLevel; + } + } + } + + return LogLevel.Information; + } + /// /// Execute the CLI command /// diff --git a/src/Cli/Utils.cs b/src/Cli/Utils.cs index 48edd4411c..b2ee161ca7 100644 --- a/src/Cli/Utils.cs +++ b/src/Cli/Utils.cs @@ -960,10 +960,11 @@ public static bool IsEntityProvided(string? entity, ILogger cliLogger, string co /// /// Returns ILoggerFactory with CLI custom logger provider. /// - public static ILoggerFactory GetLoggerFactoryForCli() + /// Minimum log level for the CLI logger. Defaults to . + public static ILoggerFactory GetLoggerFactoryForCli(LogLevel minimumLogLevel = LogLevel.Information) { ILoggerFactory loggerFactory = new LoggerFactory(); - loggerFactory.AddProvider(new CustomLoggerProvider()); + loggerFactory.AddProvider(new CustomLoggerProvider(minimumLogLevel)); return loggerFactory; } } diff --git a/src/Config/FileSystemRuntimeConfigLoader.cs b/src/Config/FileSystemRuntimeConfigLoader.cs index 70b36d8294..d383237735 100644 --- a/src/Config/FileSystemRuntimeConfigLoader.cs +++ b/src/Config/FileSystemRuntimeConfigLoader.cs @@ -59,6 +59,19 @@ public class FileSystemRuntimeConfigLoader : RuntimeConfigLoader /// private readonly IFileSystem _fileSystem; + /// + /// Logger used to log events inside . + /// Null until the DI container has been built (i.e. before is called). + /// When null, messages are routed through if available, or written + /// directly to for errors. + /// + private ILogger? _logger; + + /// + /// Early-startup log buffer used before a proper is available. + /// + private StartupLogBuffer? _logBuffer; + public const string CONFIGFILE_NAME = "dab-config"; public const string CONFIG_EXTENSION = ".json"; public const string ENVIRONMENT_PREFIX = "DAB_"; @@ -82,13 +95,17 @@ public FileSystemRuntimeConfigLoader( HotReloadEventHandler? handler = null, string baseConfigFilePath = DEFAULT_CONFIG_FILE_NAME, string? connectionString = null, - bool isCliLoader = false) + bool isCliLoader = false, + ILogger? logger = null, + StartupLogBuffer? logBuffer = null) : base(handler, connectionString) { _fileSystem = fileSystem; _baseConfigFilePath = baseConfigFilePath; ConfigFilePath = GetFinalConfigFilePath(); _isCliLoader = isCliLoader; + _logger = logger; + _logBuffer = logBuffer; } /// @@ -196,7 +213,7 @@ public bool TryLoadConfig( { if (_fileSystem.File.Exists(path)) { - Console.WriteLine($"Loading config file from {_fileSystem.Path.GetFullPath(path)}."); + LogInformation($"Loading config file from {_fileSystem.Path.GetFullPath(path)}."); // Use File.ReadAllText because DAB doesn't need write access to the file // and ensures the file handle is released immediately after reading. @@ -215,7 +232,7 @@ public bool TryLoadConfig( } catch (IOException ex) { - Console.WriteLine($"IO Exception, retrying due to {ex.Message}"); + LogWarning($"IO Exception, retrying due to {ex.Message}"); if (runCount == FileUtilities.RunLimit) { throw; @@ -238,8 +255,9 @@ public bool TryLoadConfig( { if (TrySetupConfigFileWatcher()) { - Console.WriteLine("Monitoring config: {0} for hot-reloading.", ConfigFilePath); - logger?.LogInformation("Monitoring config: {ConfigFilePath} for hot-reloading.", ConfigFilePath); + // Use LogInformation (routes through _logger, buffer, or Console) to avoid + // duplicate entries when both _logger and the caller's logger are set. + LogInformation($"Monitoring config: {ConfigFilePath} for hot-reloading."); } // When isDevMode is not null it means we are in a hot-reload scenario, and need to save the previous @@ -249,14 +267,7 @@ public bool TryLoadConfig( // Log error when the mode is changed during hot-reload. if (isDevMode != this.RuntimeConfig.IsDevelopmentMode()) { - if (logger is null) - { - Console.WriteLine("Hot-reload doesn't support switching mode. Please restart the service to switch the mode."); - } - else - { - logger.LogError("Hot-reload doesn't support switching mode. Please restart the service to switch the mode."); - } + LogError("Hot-reload doesn't support switching mode. Please restart the service to switch the mode."); } RuntimeConfig.Runtime.Host.Mode = (bool)isDevMode ? HostMode.Development : HostMode.Production; @@ -281,16 +292,8 @@ public bool TryLoadConfig( return false; } - if (logger is null) - { - string errorMessage = $"Unable to find config file: {path} does not exist."; - Console.Error.WriteLine(errorMessage); - } - else - { - string errorMessage = "Unable to find config file: {path} does not exist."; - logger.LogError(message: errorMessage, path); - } + string configMissingError = $"Unable to find config file: {path} does not exist."; + LogError(configMissingError); config = null; return false; @@ -516,4 +519,85 @@ public void UpdateConfigFilePath(string filePath) _baseConfigFilePath = filePath; ConfigFilePath = filePath; } + + /// + /// Wires the DI-provided logger into this loader. + /// Called from Startup.Configure once the DI container has been fully built. + /// After this call, subsequent log writes use directly. + /// + /// The resolved logger for this class. + public void SetLogger(ILogger logger) + { + _logger = logger; + } + + /// + /// Flushes all log entries that were buffered before the logger was available. + /// Should be called immediately after in + /// Startup.Configure so that early-startup messages are not lost. + /// + public void FlushLogBuffer() + { + _logBuffer?.FlushToLogger(_logger); + } + + /// + /// Routes an Information-level message to the logger, the buffer, or (as a last resort) + /// to so that it is never silently dropped. + /// + private void LogInformation(string message) + { + if (_logger is not null) + { + _logger.LogInformation(message); + } + else if (_logBuffer is not null) + { + _logBuffer.BufferLog(LogLevel.Information, message); + } + else + { + Console.WriteLine(message); + } + } + + /// + /// Routes a Warning-level message to the logger, the buffer, or (as a last resort) + /// to so that it is never silently dropped. + /// + private void LogWarning(string message) + { + if (_logger is not null) + { + _logger.LogWarning(message); + } + else if (_logBuffer is not null) + { + _logBuffer.BufferLog(LogLevel.Warning, message); + } + else + { + Console.WriteLine(message); + } + } + + /// + /// Routes an Error-level message to the logger, the buffer, or (as a last resort) + /// to so that it is never silently dropped. + /// + private void LogError(string message) + { + if (_logger is not null) + { + _logger.LogError(message); + } + else if (_logBuffer is not null) + { + _logBuffer.BufferLog(LogLevel.Error, message); + } + else + { + Console.Error.WriteLine(message); + } + } } diff --git a/src/Config/ObjectModel/RuntimeConfig.cs b/src/Config/ObjectModel/RuntimeConfig.cs index 46ff5a8dda..1b0d7e9fd6 100644 --- a/src/Config/ObjectModel/RuntimeConfig.cs +++ b/src/Config/ObjectModel/RuntimeConfig.cs @@ -767,15 +767,15 @@ Runtime.Telemetry.LoggerLevel is null || /// public LogLevel GetConfiguredLogLevel(string loggerFilter = "") { - if (!IsLogLevelNull()) { int max = 0; string currentFilter = string.Empty; foreach (KeyValuePair logger in Runtime!.Telemetry!.LoggerLevel!) { - // Checks if the new key that is valid has more priority than the current key - if (logger.Key.Length > max && loggerFilter.StartsWith(logger.Key)) + // Checks if the new key that is valid has more priority than the current key. + // Case-insensitive comparison so that e.g. "azure" matches "Azure.DataApiBuilder". + if (logger.Key.Length > max && loggerFilter.StartsWith(logger.Key, StringComparison.OrdinalIgnoreCase)) { max = logger.Key.Length; currentFilter = logger.Key; @@ -788,10 +788,14 @@ public LogLevel GetConfiguredLogLevel(string loggerFilter = "") return (LogLevel)value; } - Runtime!.Telemetry!.LoggerLevel!.TryGetValue("default", out value); - if (value is not null) + // "default" key is case-insensitive. Use FirstOrDefault so that a mis-configured + // file with both "default" and "Default" is handled gracefully (first match wins) + // rather than throwing a cryptic InvalidOperationException. + LogLevel? defaultValue = Runtime!.Telemetry!.LoggerLevel! + .FirstOrDefault(kvp => kvp.Key.Equals("default", StringComparison.OrdinalIgnoreCase)).Value; + if (defaultValue is not null) { - return (LogLevel)value; + return (LogLevel)defaultValue; } } diff --git a/src/Config/StartupLogBuffer.cs b/src/Config/StartupLogBuffer.cs new file mode 100644 index 0000000000..91a36e73b3 --- /dev/null +++ b/src/Config/StartupLogBuffer.cs @@ -0,0 +1,48 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Config +{ + /// + /// Buffers log entries that are emitted before the final log level is determined (e.g. before + /// the has been loaded). Once the proper + /// is available, call to replay the buffered + /// entries at their original log levels. + /// + public class StartupLogBuffer + { + private readonly ConcurrentQueue<(LogLevel LogLevel, string Message)> _logBuffer = new(); + private readonly object _flushLock = new(); + + /// + /// Enqueues a log entry to be emitted later. + /// + /// Severity of the log entry. + /// Log message. + public void BufferLog(LogLevel logLevel, string message) + { + _logBuffer.Enqueue((logLevel, message)); + } + + /// + /// Drains the buffer and forwards every entry to . + /// Entries are discarded (not re-buffered) when is null. + /// This method is thread-safe and idempotent: a second call after the buffer is empty + /// is a no-op. + /// + /// The logger to write buffered entries to, or null to discard them. + public void FlushToLogger(ILogger? targetLogger) + { + lock (_flushLock) + { + while (_logBuffer.TryDequeue(out (LogLevel LogLevel, string Message) entry)) + { + targetLogger?.Log(entry.LogLevel, message: entry.Message); + } + } + } + } +} diff --git a/src/Core/Configurations/RuntimeConfigValidator.cs b/src/Core/Configurations/RuntimeConfigValidator.cs index de35bf8ed5..c8d86e8e11 100644 --- a/src/Core/Configurations/RuntimeConfigValidator.cs +++ b/src/Core/Configurations/RuntimeConfigValidator.cs @@ -1585,7 +1585,7 @@ private static bool IsLoggerFilterValid(string loggerFilter) { for (int j = 0; j < loggerSub.Length; j++) { - if (!loggerSub[j].Equals(validFiltersSub[j])) + if (!loggerSub[j].Equals(validFiltersSub[j], StringComparison.OrdinalIgnoreCase)) { isValid = false; break; diff --git a/src/Service.Tests/Configuration/ConfigurationTests.cs b/src/Service.Tests/Configuration/ConfigurationTests.cs index 0ef9b67a4b..e428f9d65d 100644 --- a/src/Service.Tests/Configuration/ConfigurationTests.cs +++ b/src/Service.Tests/Configuration/ConfigurationTests.cs @@ -4138,6 +4138,7 @@ public void ValidLogLevelFilters(LogLevel logLevel, Type loggingType) [DataTestMethod] [TestCategory(TestCategory.MSSQL)] [DataRow(LogLevel.Trace, "default")] + [DataRow(LogLevel.Warning, "Default")] [DataRow(LogLevel.Debug, "Azure")] [DataRow(LogLevel.Information, "Azure.DataApiBuilder")] [DataRow(LogLevel.Warning, "Azure.DataApiBuilder.Core")] diff --git a/src/Service.Tests/UnitTests/LoggingUnitTests.cs b/src/Service.Tests/UnitTests/LoggingUnitTests.cs new file mode 100644 index 0000000000..96518182c1 --- /dev/null +++ b/src/Service.Tests/UnitTests/LoggingUnitTests.cs @@ -0,0 +1,305 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +#nullable enable + +using System; +using System.Collections.Generic; +using Azure.DataApiBuilder.Config; +using Azure.DataApiBuilder.Config.ObjectModel; +using Azure.DataApiBuilder.Service.Telemetry; +using Microsoft.Extensions.Logging; +using Microsoft.VisualStudio.TestTools.UnitTesting; +using Moq; + +namespace Azure.DataApiBuilder.Service.Tests.UnitTests +{ + /// + /// Unit tests for . + /// + [TestClass] + public class StartupLogBufferTests + { + /// + /// Verifies that replays buffered entries + /// to the target logger in the order they were enqueued. + /// + [TestMethod] + public void FlushToLogger_ReplayBufferedEntriesInOrder() + { + // Arrange + StartupLogBuffer buffer = new(); + buffer.BufferLog(LogLevel.Information, "first"); + buffer.BufferLog(LogLevel.Warning, "second"); + buffer.BufferLog(LogLevel.Error, "third"); + + List<(LogLevel level, string msg)> received = new(); + Mock mockLogger = new(); + mockLogger + .Setup(l => l.Log( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny>())) + .Callback((level, _, state, _, formatter) => + { + received.Add((level, formatter.DynamicInvoke(state, null) as string ?? string.Empty)); + }); + mockLogger.Setup(l => l.IsEnabled(It.IsAny())).Returns(true); + + // Act + buffer.FlushToLogger(mockLogger.Object); + + // Assert + Assert.AreEqual(3, received.Count); + Assert.AreEqual(LogLevel.Information, received[0].level); + Assert.AreEqual(LogLevel.Warning, received[1].level); + Assert.AreEqual(LogLevel.Error, received[2].level); + StringAssert.Contains(received[0].msg, "first"); + StringAssert.Contains(received[1].msg, "second"); + StringAssert.Contains(received[2].msg, "third"); + } + + /// + /// Verifies that with a null logger + /// simply discards all buffered entries without throwing. + /// + [TestMethod] + public void FlushToLogger_NullLogger_DiscardsEntriesWithoutThrowing() + { + StartupLogBuffer buffer = new(); + buffer.BufferLog(LogLevel.Information, "message"); + + // Should not throw + buffer.FlushToLogger(null); + } + + /// + /// Verifies that calling a second time + /// after the buffer has been drained is a no-op (no duplicate logging). + /// + [TestMethod] + public void FlushToLogger_SecondCallOnDrainedBuffer_IsNoOp() + { + StartupLogBuffer buffer = new(); + buffer.BufferLog(LogLevel.Information, "only once"); + + int callCount = 0; + Mock mockLogger = new(); + mockLogger + .Setup(l => l.Log( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny>())) + .Callback(() => callCount++); + mockLogger.Setup(l => l.IsEnabled(It.IsAny())).Returns(true); + + buffer.FlushToLogger(mockLogger.Object); + buffer.FlushToLogger(mockLogger.Object); // second flush on empty buffer + + Assert.AreEqual(1, callCount, "The message should have been logged exactly once."); + } + + /// + /// Verifies that an empty buffer produces no log calls. + /// + [TestMethod] + public void FlushToLogger_EmptyBuffer_NoLogCalls() + { + StartupLogBuffer buffer = new(); + Mock mockLogger = new(); + + buffer.FlushToLogger(mockLogger.Object); + + mockLogger.Verify( + l => l.Log( + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny(), + It.IsAny>()), + Times.Never); + } + } + + /// + /// Unit tests for . + /// + [TestClass] + public class DynamicLogLevelProviderTests + { + /// + /// Verifies that sets the + /// current log level and the CLI-override flag correctly. + /// + [DataTestMethod] + [DataRow(LogLevel.Trace, true, DisplayName = "Trace with CLI override")] + [DataRow(LogLevel.Warning, false, DisplayName = "Warning without CLI override")] + [DataRow(LogLevel.None, true, DisplayName = "None with CLI override")] + [DataRow(LogLevel.Error, false, DisplayName = "Error without CLI override")] + public void SetInitialLogLevel_SetsLevelAndFlag(LogLevel logLevel, bool isCliOverridden) + { + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(logLevel, isCliOverridden); + + Assert.AreEqual(logLevel, provider.CurrentLogLevel); + Assert.AreEqual(isCliOverridden, provider.IsCliOverridden); + } + + /// + /// Verifies that updates + /// the log level when the CLI has not overridden it. + /// + [TestMethod] + public void UpdateFromRuntimeConfig_WithoutCliOverride_UpdatesLevel() + { + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.Error, isCliOverridden: false); + + // Build a RuntimeConfig with a "default" log level of Warning. + Dictionary logLevels = new() { { "default", LogLevel.Warning } }; + RuntimeConfig config = BuildConfigWithLogLevel(logLevels); + + provider.UpdateFromRuntimeConfig(config); + + Assert.AreEqual(LogLevel.Warning, provider.CurrentLogLevel); + } + + /// + /// Verifies that does NOT + /// change the log level when the CLI has already overridden it. + /// + [TestMethod] + public void UpdateFromRuntimeConfig_WithCliOverride_KeepsCliLevel() + { + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(LogLevel.None, isCliOverridden: true); + + // Config would set Warning, but CLI None must win. + Dictionary logLevels = new() { { "default", LogLevel.Warning } }; + RuntimeConfig config = BuildConfigWithLogLevel(logLevels); + + provider.UpdateFromRuntimeConfig(config); + + Assert.AreEqual(LogLevel.None, provider.CurrentLogLevel); + } + + /// + /// Verifies that returns true only + /// for messages at or above . + /// + [DataTestMethod] + [DataRow(LogLevel.Warning, LogLevel.Trace, false, DisplayName = "Trace suppressed at Warning threshold")] + [DataRow(LogLevel.Warning, LogLevel.Debug, false, DisplayName = "Debug suppressed at Warning threshold")] + [DataRow(LogLevel.Warning, LogLevel.Information, false, DisplayName = "Info suppressed at Warning threshold")] + [DataRow(LogLevel.Warning, LogLevel.Warning, true, DisplayName = "Warning passes Warning threshold")] + [DataRow(LogLevel.Warning, LogLevel.Error, true, DisplayName = "Error passes Warning threshold")] + [DataRow(LogLevel.Warning, LogLevel.Critical, true, DisplayName = "Critical passes Warning threshold")] + [DataRow(LogLevel.None, LogLevel.Critical, false, DisplayName = "Critical suppressed at None threshold")] + [DataRow(LogLevel.Trace, LogLevel.Trace, true, DisplayName = "Trace passes Trace threshold")] + public void ShouldLog_ReturnsCorrectResult(LogLevel threshold, LogLevel messageLevel, bool expected) + { + DynamicLogLevelProvider provider = new(); + provider.SetInitialLogLevel(threshold); + + Assert.AreEqual(expected, provider.ShouldLog(messageLevel)); + } + + // ------------------------------------------------------------------ helpers + + private static RuntimeConfig BuildConfigWithLogLevel(Dictionary logLevels) + { + TelemetryOptions telemetry = new( + ApplicationInsights: null, + OpenTelemetry: null, + LoggerLevel: logLevels); + RuntimeOptions runtimeOptions = new( + Rest: null, + GraphQL: null, + Host: new HostOptions( + Cors: null, + Authentication: new AuthenticationOptions(Provider: "Unauthenticated"), + Mode: HostMode.Production), + BaseRoute: null, + Telemetry: telemetry, + Cache: null, + Pagination: null, + Mcp: null); + return new RuntimeConfig( + Schema: "https://github.com/Azure/data-api-builder/releases/download/vmajor.minor.patch/dab.draft.schema.json", + DataSource: new DataSource(DatabaseType.MSSQL, string.Empty, Options: null), + Runtime: runtimeOptions, + Entities: new(new Dictionary())); + } + } + + /// + /// Unit tests for that cover the + /// case-insensitive "default" key fix. + /// + [TestClass] + public class GetConfiguredLogLevelTests + { + /// + /// Verifies that both lowercase "default" and title-case "Default" are resolved + /// correctly as the fallback log level. + /// + [DataTestMethod] + [DataRow("default", LogLevel.Warning, DisplayName = "Lowercase 'default' key is resolved")] + [DataRow("Default", LogLevel.Warning, DisplayName = "Title-case 'Default' key is resolved (case-insensitive fix)")] + [DataRow("DEFAULT", LogLevel.Warning, DisplayName = "All-caps 'DEFAULT' key is resolved (case-insensitive fix)")] + public void GetConfiguredLogLevel_DefaultKeyVariants_ReturnExpectedLevel(string defaultKey, LogLevel expectedLevel) + { + Dictionary logLevels = new() { { defaultKey, expectedLevel } }; + RuntimeConfig config = BuildConfigWithLogLevel(logLevels); + + LogLevel actual = config.GetConfiguredLogLevel(); + Assert.AreEqual(expectedLevel, actual); + } + + /// + /// Verifies that a more-specific filter takes precedence over the "default" fallback. + /// + [TestMethod] + public void GetConfiguredLogLevel_SpecificFilterTakesPrecedenceOverDefault() + { + Dictionary logLevels = new() + { + { "Default", LogLevel.Error }, + { "Azure.DataApiBuilder", LogLevel.Debug } + }; + RuntimeConfig config = BuildConfigWithLogLevel(logLevels); + + LogLevel actual = config.GetConfiguredLogLevel("Azure.DataApiBuilder.Core"); + Assert.AreEqual(LogLevel.Debug, actual, "More specific 'Azure.DataApiBuilder' filter should win over 'Default'."); + } + + private static RuntimeConfig BuildConfigWithLogLevel(Dictionary logLevels) + { + TelemetryOptions telemetry = new( + ApplicationInsights: null, + OpenTelemetry: null, + LoggerLevel: logLevels); + RuntimeOptions runtimeOptions = new( + Rest: null, + GraphQL: null, + Host: new HostOptions( + Cors: null, + Authentication: new AuthenticationOptions(Provider: "Unauthenticated"), + Mode: HostMode.Production), + BaseRoute: null, + Telemetry: telemetry, + Cache: null, + Pagination: null, + Mcp: null); + return new RuntimeConfig( + Schema: "https://github.com/Azure/data-api-builder/releases/download/vmajor.minor.patch/dab.draft.schema.json", + DataSource: new DataSource(DatabaseType.MSSQL, string.Empty, Options: null), + Runtime: runtimeOptions, + Entities: new(new Dictionary())); + } + } +} diff --git a/src/Service/Program.cs b/src/Service/Program.cs index c7e6cb10e5..f5d9057f7e 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -34,6 +34,13 @@ public class Program { public static bool IsHttpsRedirectionDisabled { get; private set; } + /// + /// Shared that is wired into the logging pipeline. + /// Initialised with the CLI-provided log level before the host builds, then optionally + /// updated from the loaded RuntimeConfig in Startup.Configure. + /// + public static DynamicLogLevelProvider LogLevelProvider { get; } = new(); + public static void Main(string[] args) { bool runMcpStdio = McpStdioHelper.ShouldRunMcpStdio(args, out string? mcpRole); @@ -59,7 +66,6 @@ public static void Main(string[] args) public static bool StartEngine(string[] args, bool runMcpStdio, string? mcpRole) { - Console.WriteLine("Starting the runtime engine..."); try { IHost host = CreateHostBuilder(args, runMcpStdio, mcpRole).Build(); @@ -107,9 +113,23 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st McpStdioHelper.ConfigureMcpStdio(builder, mcpRole); } }) + .ConfigureServices((_, services) => + { + // Register the shared provider so it can be injected into Startup. + services.AddSingleton(LogLevelProvider); + }) + .ConfigureLogging(logging => + { + // Apply the dynamic log level to the host's logging pipeline so that + // all Microsoft.* framework messages are also filtered. + logging.AddFilter("Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel)); + }) .ConfigureWebHostDefaults(webBuilder => { Startup.MinimumLogLevel = GetLogLevelFromCommandLineArgs(args, out Startup.IsLogLevelOverriddenByCli); + // Initialise provider immediately so that the host-level filters above are + // already using the CLI-provided level. + LogLevelProvider.SetInitialLogLevel(Startup.MinimumLogLevel, Startup.IsLogLevelOverriddenByCli); ILoggerFactory loggerFactory = GetLoggerFactoryForLogLevel(Startup.MinimumLogLevel, stdio: runMcpStdio); ILogger startupLogger = loggerFactory.CreateLogger(); DisableHttpsRedirectionIfNeeded(args); @@ -185,9 +205,9 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel( // "Azure.DataApiBuilder.Service" if (logLevelInitializer is null) { - builder.AddFilter(category: "Microsoft", logLevel); - builder.AddFilter(category: "Azure", logLevel); - builder.AddFilter(category: "Default", logLevel); + builder.AddFilter(category: "Microsoft", level => LogLevelProvider.ShouldLog(level)); + builder.AddFilter(category: "Azure", level => LogLevelProvider.ShouldLog(level)); + builder.AddFilter(category: "Default", level => LogLevelProvider.ShouldLog(level)); } else { diff --git a/src/Service/Startup.cs b/src/Service/Startup.cs index d36155e3ec..b9b59fb229 100644 --- a/src/Service/Startup.cs +++ b/src/Service/Startup.cs @@ -85,6 +85,7 @@ public class Startup(IConfiguration configuration, ILogger logger) public static AzureLogAnalyticsOptions AzureLogAnalyticsOptions = new(); public static FileSinkOptions FileSinkOptions = new(); public const string NO_HTTPS_REDIRECT_FLAG = "--no-https-redirect"; + private readonly StartupLogBuffer _logBuffer = new(); private readonly HotReloadEventHandler _hotReloadEventHandler = new(); private RuntimeConfigProvider? _configProvider; private ILogger _logger = logger; @@ -104,13 +105,15 @@ public class Startup(IConfiguration configuration, ILogger logger) public void ConfigureServices(IServiceCollection services) { Startup.AddValidFilters(); + services.AddSingleton(_logBuffer); + services.AddSingleton(Program.LogLevelProvider); services.AddSingleton(_hotReloadEventHandler); string configFileName = Configuration.GetValue("ConfigFileName") ?? FileSystemRuntimeConfigLoader.DEFAULT_CONFIG_FILE_NAME; string? connectionString = Configuration.GetValue( FileSystemRuntimeConfigLoader.RUNTIME_ENV_CONNECTION_STRING.Replace(FileSystemRuntimeConfigLoader.ENVIRONMENT_PREFIX, ""), null); IFileSystem fileSystem = new FileSystem(); - FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString); + FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString, logBuffer: _logBuffer); RuntimeConfigProvider configProvider = new(configLoader); _configProvider = configProvider; @@ -230,6 +233,13 @@ public void ConfigureServices(IServiceCollection services) services.AddHealthChecks() .AddCheck(nameof(BasicHealthCheck)); + services.AddSingleton>(implementationFactory: (serviceProvider) => + { + LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(FileSystemRuntimeConfigLoader).FullName, _configProvider, _hotReloadEventHandler); + ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(serviceProvider, logLevelInit); + return loggerFactory.CreateLogger(); + }); + services.AddSingleton>(implementationFactory: (serviceProvider) => { LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(SqlQueryEngine).FullName, _configProvider, _hotReloadEventHandler); @@ -694,7 +704,15 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC if (runtimeConfigProvider.TryGetConfig(out RuntimeConfig? runtimeConfig)) { - // Configure Application Insights Telemetry + // Update the dynamic log level from the config (no-op when CLI already overrode it), + // then wire up the proper logger on the config loader and flush buffered startup messages. + DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService(); + logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig); + FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService(); + configLoader.SetLogger(app.ApplicationServices.GetRequiredService>()); + configLoader.FlushLogBuffer(); + + // Configure Telemetry ConfigureApplicationInsightsTelemetry(app, runtimeConfig); ConfigureOpenTelemetry(runtimeConfig); ConfigureAzureLogAnalytics(runtimeConfig); diff --git a/src/Service/Telemetry/DynamicLogLevelProvider.cs b/src/Service/Telemetry/DynamicLogLevelProvider.cs new file mode 100644 index 0000000000..1f03e63320 --- /dev/null +++ b/src/Service/Telemetry/DynamicLogLevelProvider.cs @@ -0,0 +1,64 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using Azure.DataApiBuilder.Config.ObjectModel; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Service.Telemetry +{ + /// + /// Provides a runtime-updatable log level that can be shared across logging pipelines. + /// Initialized from CLI args before host builds, then optionally updated from the loaded + /// RuntimeConfig (unless the CLI has already overridden the level). + /// + public class DynamicLogLevelProvider + { + /// + /// The current minimum log level. Messages below this level are suppressed. + /// + public LogLevel CurrentLogLevel { get; private set; } = LogLevel.Error; + + /// + /// Whether the log level was explicitly set via CLI args and should not be + /// overridden by the config file. + /// + public bool IsCliOverridden { get; private set; } + + /// + /// Sets the initial log level, typically from parsed CLI args. + /// Must be called before the host is built so that the log filters are wired correctly. + /// + /// Minimum log level to apply. + /// + /// True when the caller explicitly provided via a CLI flag; + /// false when falling back to a default. + /// + public void SetInitialLogLevel(LogLevel logLevel = LogLevel.Error, bool isCliOverridden = false) + { + CurrentLogLevel = logLevel; + IsCliOverridden = isCliOverridden; + } + + /// + /// Updates the current log level from the loaded . + /// Has no effect when the log level was already set via the CLI. + /// + /// The runtime configuration to read the configured log level from. + public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig) + { + if (!IsCliOverridden) + { + CurrentLogLevel = runtimeConfig.GetConfiguredLogLevel(); + } + } + + /// + /// Returns true when the given meets or exceeds + /// . + /// + public bool ShouldLog(LogLevel logLevel) + { + return logLevel >= CurrentLogLevel; + } + } +}