diff --git a/src/Cli.Tests/EndToEndTests.cs b/src/Cli.Tests/EndToEndTests.cs index e3e32d5076..4d0fe186e7 100644 --- a/src/Cli.Tests/EndToEndTests.cs +++ b/src/Cli.Tests/EndToEndTests.cs @@ -811,8 +811,9 @@ 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 + /// options are used with the start command, for log levels at or below Information. + /// CLI phase messages (version info, config path) are expected in the output because + /// they are logged at Information level. /// /// Log level options [DataTestMethod] @@ -821,24 +822,12 @@ public Task TestUpdatingStoredProcedureWithRestMethods() [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,40 @@ public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption StringAssert.Contains(output, $"User provided config file: {TEST_RUNTIME_CONFIG_FILE}", StringComparison.Ordinal); } + /// + /// Test to validate that the engine starts successfully when --LogLevel is set to Warning + /// or above. At these levels, CLI phase messages (logged at Information) are suppressed, + /// so no stdout output is expected during the CLI phase. + /// + /// Log level options + [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 will be suppressed by Warning+. + // Verify the engine started (process not immediately exited) then clean up. + Assert.IsFalse(process.HasExited); + 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 +1111,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/Program.cs b/src/Cli/Program.cs index de16ed27f5..6a079a469c 100644 --- a/src/Cli/Program.cs +++ b/src/Cli/Program.cs @@ -37,7 +37,6 @@ 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); } diff --git a/src/Config/FileSystemRuntimeConfigLoader.cs b/src/Config/FileSystemRuntimeConfigLoader.cs index 70b36d8294..4eab5f1f57 100644 --- a/src/Config/FileSystemRuntimeConfigLoader.cs +++ b/src/Config/FileSystemRuntimeConfigLoader.cs @@ -59,6 +59,13 @@ public class FileSystemRuntimeConfigLoader : RuntimeConfigLoader /// private readonly IFileSystem _fileSystem; + /// + /// Logger used to log all the events that occur inside of FileSystemRuntimeConfigLoader + /// + private ILogger? _logger; + + private StartupLogBuffer? _logBuffer; + public const string CONFIGFILE_NAME = "dab-config"; public const string CONFIG_EXTENSION = ".json"; public const string ENVIRONMENT_PREFIX = "DAB_"; @@ -82,13 +89,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 +207,14 @@ public bool TryLoadConfig( { if (_fileSystem.File.Exists(path)) { - Console.WriteLine($"Loading config file from {_fileSystem.Path.GetFullPath(path)}."); + if (_logger is null) + { + _logBuffer?.BufferLog(LogLevel.Information, $"Loading config file from {_fileSystem.Path.GetFullPath(path)}."); + } + else + { + _logger?.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 +233,15 @@ public bool TryLoadConfig( } catch (IOException ex) { - Console.WriteLine($"IO Exception, retrying due to {ex.Message}"); + if (_logger is null) + { + _logBuffer?.BufferLog(LogLevel.Warning, $"IO Exception, retrying due to {ex.Message}"); + } + else + { + _logger?.LogWarning($"IO Exception, retrying due to {ex.Message}"); + } + if (runCount == FileUtilities.RunLimit) { throw; @@ -238,8 +264,14 @@ public bool TryLoadConfig( { if (TrySetupConfigFileWatcher()) { - Console.WriteLine("Monitoring config: {0} for hot-reloading.", ConfigFilePath); - logger?.LogInformation("Monitoring config: {ConfigFilePath} for hot-reloading.", ConfigFilePath); + if (_logger is null) + { + _logBuffer?.BufferLog(LogLevel.Information, $"Monitoring config: {ConfigFilePath} for hot-reloading."); + } + else + { + _logger?.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,13 +281,13 @@ public bool TryLoadConfig( // Log error when the mode is changed during hot-reload. if (isDevMode != this.RuntimeConfig.IsDevelopmentMode()) { - if (logger is null) + if (_logger is null) { - Console.WriteLine("Hot-reload doesn't support switching mode. Please restart the service to switch the mode."); + _logBuffer?.BufferLog(LogLevel.Error, "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."); + _logger?.LogError("Hot-reload doesn't support switching mode. Please restart the service to switch the mode."); } } @@ -281,15 +313,14 @@ public bool TryLoadConfig( return false; } - if (logger is null) + string errorMessage = $"Unable to find config file: {path} does not exist."; + if (_logger is null) { - string errorMessage = $"Unable to find config file: {path} does not exist."; - Console.Error.WriteLine(errorMessage); + _logBuffer?.BufferLog(LogLevel.Error, errorMessage); } else { - string errorMessage = "Unable to find config file: {path} does not exist."; - logger.LogError(message: errorMessage, path); + _logger?.LogError(message: errorMessage); } config = null; @@ -516,4 +547,17 @@ public void UpdateConfigFilePath(string filePath) _baseConfigFilePath = filePath; ConfigFilePath = filePath; } + + public void SetLogger(ILogger logger) + { + _logger = logger; + } + + /// + /// Flush all logs from the buffer after the log level is set from the RuntimeConfig. + /// + public void FlushLogBuffer() + { + _logBuffer?.FlushToLogger(_logger); + } } diff --git a/src/Config/ObjectModel/RuntimeConfig.cs b/src/Config/ObjectModel/RuntimeConfig.cs index 46ff5a8dda..204ba05874 100644 --- a/src/Config/ObjectModel/RuntimeConfig.cs +++ b/src/Config/ObjectModel/RuntimeConfig.cs @@ -767,7 +767,6 @@ Runtime.Telemetry.LoggerLevel is null || /// public LogLevel GetConfiguredLogLevel(string loggerFilter = "") { - if (!IsLogLevelNull()) { int max = 0; @@ -788,7 +787,8 @@ public LogLevel GetConfiguredLogLevel(string loggerFilter = "") return (LogLevel)value; } - Runtime!.Telemetry!.LoggerLevel!.TryGetValue("default", out value); + value = Runtime!.Telemetry!.LoggerLevel! + .FirstOrDefault(kvp => kvp.Key.Equals("default", StringComparison.OrdinalIgnoreCase)).Value; if (value is not null) { return (LogLevel)value; diff --git a/src/Config/StartupLogBuffer.cs b/src/Config/StartupLogBuffer.cs new file mode 100644 index 0000000000..4a01ee7617 --- /dev/null +++ b/src/Config/StartupLogBuffer.cs @@ -0,0 +1,45 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +using System.Collections.Concurrent; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Config +{ + /// + /// A general-purpose log buffer that stores log entries before the final log level is determined. + /// Can be used across different components during startup to capture important early logs. + /// + public class StartupLogBuffer + { + private readonly ConcurrentQueue<(LogLevel LogLevel, string Message)> _logBuffer; + private readonly object _flushLock = new(); + + public StartupLogBuffer() + { + _logBuffer = new(); + } + + /// + /// Buffers a log entry with a specific category name. + /// + public void BufferLog(LogLevel logLevel, string message) + { + _logBuffer.Enqueue((logLevel, message)); + } + + /// + /// Flushes all buffered logs to a single target logger. + /// + 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/Program.cs b/src/Service/Program.cs index c7e6cb10e5..d601f4f6b4 100644 --- a/src/Service/Program.cs +++ b/src/Service/Program.cs @@ -33,6 +33,7 @@ namespace Azure.DataApiBuilder.Service public class Program { public static bool IsHttpsRedirectionDisabled { get; private set; } + public static DynamicLogLevelProvider LogLevelProvider = new(); public static void Main(string[] args) { @@ -59,7 +60,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 +107,19 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st McpStdioHelper.ConfigureMcpStdio(builder, mcpRole); } }) + .ConfigureServices((context, services) => + { + services.AddSingleton(LogLevelProvider); + }) + .ConfigureLogging(logging => + { + logging.AddFilter("Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel)); + logging.AddFilter("Microsoft.Hosting.Lifetime", logLevel => LogLevelProvider.ShouldLog(logLevel)); + }) .ConfigureWebHostDefaults(webBuilder => { Startup.MinimumLogLevel = GetLogLevelFromCommandLineArgs(args, out Startup.IsLogLevelOverriddenByCli); + LogLevelProvider.SetInitialLogLevel(Startup.MinimumLogLevel, Startup.IsLogLevelOverriddenByCli); ILoggerFactory loggerFactory = GetLoggerFactoryForLogLevel(Startup.MinimumLogLevel, stdio: runMcpStdio); ILogger startupLogger = loggerFactory.CreateLogger(); DisableHttpsRedirectionIfNeeded(args); @@ -185,9 +195,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", logLevel => LogLevelProvider.ShouldLog(logLevel)); + builder.AddFilter(category: "Azure", logLevel => LogLevelProvider.ShouldLog(logLevel)); + builder.AddFilter(category: "Default", logLevel => LogLevelProvider.ShouldLog(logLevel)); } else { diff --git a/src/Service/Startup.cs b/src/Service/Startup.cs index f4caee4ed5..dea13dad6b 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 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,13 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC if (runtimeConfigProvider.TryGetConfig(out RuntimeConfig? runtimeConfig)) { - // Configure Application Insights Telemetry + // Configure Telemetry + DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService(); + logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig); + FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService(); + configLoader.SetLogger(app.ApplicationServices.GetRequiredService>()); + configLoader.FlushLogBuffer(); + 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..3c35e295e6 --- /dev/null +++ b/src/Service/Telemetry/DynamicLogLevelProvider.cs @@ -0,0 +1,31 @@ +using Azure.DataApiBuilder.Config.ObjectModel; +using Microsoft.Extensions.Logging; + +namespace Azure.DataApiBuilder.Service.Telemetry +{ + public class DynamicLogLevelProvider + { + public LogLevel CurrentLogLevel { get; private set; } + public bool IsCliOverridden { get; private set; } + + public void SetInitialLogLevel(LogLevel logLevel = LogLevel.Error, bool isCliOverridden = false) + { + CurrentLogLevel = logLevel; + IsCliOverridden = isCliOverridden; + } + + public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig) + { + // Only update if CLI didn't override + if (!IsCliOverridden) + { + CurrentLogLevel = runtimeConfig.GetConfiguredLogLevel(); + } + } + + public bool ShouldLog(LogLevel logLevel) + { + return logLevel >= CurrentLogLevel; + } + } +}