diff --git a/src/Cli.Tests/EndToEndTests.cs b/src/Cli.Tests/EndToEndTests.cs index 581ecd5a23..4ae27f790f 100644 --- a/src/Cli.Tests/EndToEndTests.cs +++ b/src/Cli.Tests/EndToEndTests.cs @@ -1088,10 +1088,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/Config/FileSystemRuntimeConfigLoader.cs b/src/Config/FileSystemRuntimeConfigLoader.cs index 70b36d8294..ecefd6a9c2 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,7 @@ public bool TryLoadConfig( { if (_fileSystem.File.Exists(path)) { - Console.WriteLine($"Loading config file from {_fileSystem.Path.GetFullPath(path)}."); + SendLogToBufferOrLogger(LogLevel.Information, $"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 +226,8 @@ public bool TryLoadConfig( } catch (IOException ex) { - Console.WriteLine($"IO Exception, retrying due to {ex.Message}"); + SendLogToBufferOrLogger(LogLevel.Warning, $"IO Exception, retrying due to {ex.Message}"); + if (runCount == FileUtilities.RunLimit) { throw; @@ -238,8 +250,7 @@ public bool TryLoadConfig( { if (TrySetupConfigFileWatcher()) { - Console.WriteLine("Monitoring config: {0} for hot-reloading.", ConfigFilePath); - logger?.LogInformation("Monitoring config: {ConfigFilePath} for hot-reloading.", ConfigFilePath); + SendLogToBufferOrLogger(LogLevel.Information, $"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 +260,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."); - } + SendLogToBufferOrLogger(LogLevel.Error, "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 +285,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 errorMessage = $"Unable to find config file: {path} does not exist."; + SendLogToBufferOrLogger(LogLevel.Error, errorMessage); config = null; return false; @@ -516,4 +512,35 @@ 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); + } + + /// + /// Helper method that sends the log to the buffer if the logger has not being set up. + /// Else, it will send the log to the logger. + /// + /// LogLevel of the log. + /// Message that will be printed in the log. + private void SendLogToBufferOrLogger(LogLevel logLevel, string message) + { + if (_logger is null) + { + _logBuffer?.BufferLog(logLevel, message); + } + else + { + _logger?.Log(logLevel, message); + } + } } diff --git a/src/Config/ObjectModel/RuntimeConfig.cs b/src/Config/ObjectModel/RuntimeConfig.cs index eea7d79c57..89cc7413d1 100644 --- a/src/Config/ObjectModel/RuntimeConfig.cs +++ b/src/Config/ObjectModel/RuntimeConfig.cs @@ -774,7 +774,6 @@ Runtime.Telemetry.LoggerLevel is null || /// public LogLevel GetConfiguredLogLevel(string loggerFilter = "") { - if (!IsLogLevelNull()) { int max = 0; @@ -795,7 +794,8 @@ public LogLevel GetConfiguredLogLevel(string loggerFilter = "") return (LogLevel)value; } - Runtime!.Telemetry!.LoggerLevel!.TryGetValue("default", out value); + value = Runtime!.Telemetry!.LoggerLevel! + .SingleOrDefault(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 536d7d87f0..323649baf8 100644 --- a/src/Service.Tests/Configuration/ConfigurationTests.cs +++ b/src/Service.Tests/Configuration/ConfigurationTests.cs @@ -4268,6 +4268,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 411c4bb38d..12cbd18ab0 100644 --- a/src/Service/Startup.cs +++ b/src/Service/Startup.cs @@ -86,6 +86,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; @@ -105,13 +106,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; @@ -231,6 +234,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); @@ -695,7 +705,16 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC if (runtimeConfigProvider.TryGetConfig(out RuntimeConfig? runtimeConfig)) { - // Configure Application Insights Telemetry + // Set LogLevel based on RuntimeConfig + DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService(); + logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig); + FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService(); + + //Flush all logs that were buffered before setting the LogLevel + 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..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; + } + } +}