diff --git a/src/Cli.Tests/EndToEndTests.cs b/src/Cli.Tests/EndToEndTests.cs index 99a9b77b6e..28704adc79 100644 --- a/src/Cli.Tests/EndToEndTests.cs +++ b/src/Cli.Tests/EndToEndTests.cs @@ -1087,10 +1087,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 614cfbd11c..336eadf44d 100644 --- a/src/Config/FileSystemRuntimeConfigLoader.cs +++ b/src/Config/FileSystemRuntimeConfigLoader.cs @@ -58,6 +58,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_"; @@ -81,13 +88,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; } /// @@ -195,7 +206,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. @@ -214,7 +225,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; @@ -237,8 +249,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 @@ -248,14 +259,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; @@ -280,16 +284,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; @@ -515,4 +511,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 f1ab0d1f10..ab6764f77a 100644 --- a/src/Config/ObjectModel/RuntimeConfig.cs +++ b/src/Config/ObjectModel/RuntimeConfig.cs @@ -714,7 +714,6 @@ Runtime.Telemetry.LoggerLevel is null || /// public LogLevel GetConfiguredLogLevel(string loggerFilter = "") { - if (!IsLogLevelNull()) { int max = 0; @@ -735,7 +734,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 ec97a48e4c..80572a2298 100644 --- a/src/Core/Configurations/RuntimeConfigValidator.cs +++ b/src/Core/Configurations/RuntimeConfigValidator.cs @@ -1502,7 +1502,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 d42af33259..391b6ed1c6 100644 --- a/src/Service.Tests/Configuration/ConfigurationTests.cs +++ b/src/Service.Tests/Configuration/ConfigurationTests.cs @@ -4057,6 +4057,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/Configuration/HealthEndpointTests.cs b/src/Service.Tests/Configuration/HealthEndpointTests.cs index 7f84d4fa15..a1a8bf4223 100644 --- a/src/Service.Tests/Configuration/HealthEndpointTests.cs +++ b/src/Service.Tests/Configuration/HealthEndpointTests.cs @@ -564,6 +564,94 @@ private static RuntimeConfig CreateRuntimeConfig(Dictionary enti return runtimeConfig; } + /// + /// Verifies that stored procedures are excluded from health check results. + /// Creates a config with both a table entity and a stored procedure entity, + /// then validates that only the table entity appears in the health endpoint response. + /// + [TestMethod] + [TestCategory(TestCategory.MSSQL)] + public async Task HealthEndpoint_ExcludesStoredProcedures() + { + // Create a table entity + Entity tableEntity = new( + Health: new(enabled: true), + Source: new("books", EntitySourceType.Table, null, null), + Fields: null, + Rest: new(Enabled: true), + GraphQL: new("book", "bookLists", true), + Permissions: new[] { ConfigurationTests.GetMinimalPermissionConfig(AuthorizationResolver.ROLE_ANONYMOUS) }, + Relationships: null, + Mappings: null); + + // Create a stored procedure entity - using an actual stored procedure from test schema + Entity storedProcEntity = new( + Health: new(enabled: true), + Source: new("get_books", EntitySourceType.StoredProcedure, null, null), + Fields: null, + Rest: new(Enabled: true), + GraphQL: new("executeGetBooks", "executeGetBooksList", true), + Permissions: new[] { ConfigurationTests.GetMinimalPermissionConfig(AuthorizationResolver.ROLE_ANONYMOUS) }, + Relationships: null, + Mappings: null); + + Dictionary entityMap = new() + { + { "Book", tableEntity }, + { "GetBooks", storedProcEntity } + }; + + RuntimeConfig runtimeConfig = CreateRuntimeConfig( + entityMap, + enableGlobalRest: true, + enableGlobalGraphql: true, + enabledGlobalMcp: true, + enableGlobalHealth: true, + enableDatasourceHealth: true, + hostMode: HostMode.Development); + + WriteToCustomConfigFile(runtimeConfig); + + string[] args = new[] + { + $"--ConfigFileName={CUSTOM_CONFIG_FILENAME}" + }; + + using (TestServer server = new(Program.CreateWebHostBuilder(args))) + using (HttpClient client = server.CreateClient()) + { + HttpRequestMessage healthRequest = new(HttpMethod.Get, $"{BASE_DAB_URL}/health"); + HttpResponseMessage response = await client.SendAsync(healthRequest); + + Assert.AreEqual(HttpStatusCode.OK, response.StatusCode, "Health endpoint should return OK"); + + string responseBody = await response.Content.ReadAsStringAsync(); + Dictionary responseProperties = JsonSerializer.Deserialize>(responseBody); + + // Get the checks array + Assert.IsTrue(responseProperties.TryGetValue("checks", out JsonElement checksElement), "Response should contain 'checks' property"); + Assert.AreEqual(JsonValueKind.Array, checksElement.ValueKind, "Checks should be an array"); + + // Get all entity names from the health check results + List entityNamesInHealthCheck = new(); + foreach (JsonElement check in checksElement.EnumerateArray()) + { + if (check.TryGetProperty("name", out JsonElement nameElement)) + { + entityNamesInHealthCheck.Add(nameElement.GetString()); + } + } + + // Verify that the table entity (Book) appears in health checks + Assert.IsTrue(entityNamesInHealthCheck.Contains("Book"), + "Table entity 'Book' should be included in health check results"); + + // Verify that the stored procedure entity (GetBooks) does NOT appear in health checks + Assert.IsFalse(entityNamesInHealthCheck.Contains("GetBooks"), + "Stored procedure entity 'GetBooks' should be excluded from health check results"); + } + } + private static void WriteToCustomConfigFile(RuntimeConfig runtimeConfig) { File.WriteAllText( diff --git a/src/Service/HealthCheck/HealthCheckHelper.cs b/src/Service/HealthCheck/HealthCheckHelper.cs index 83b8b7a301..72d93521ea 100644 --- a/src/Service/HealthCheck/HealthCheckHelper.cs +++ b/src/Service/HealthCheck/HealthCheckHelper.cs @@ -198,10 +198,11 @@ private async Task UpdateDataSourceHealthCheckResultsAsync(ComprehensiveHealthCh // Updates the Entity Health Check Results in the response. // Goes through the entities one by one and executes the rest and graphql checks (if enabled). + // Stored procedures are excluded from health checks because they require parameters and are not guaranteed to be deterministic. private async Task UpdateEntityHealthCheckResultsAsync(ComprehensiveHealthCheckReport report, RuntimeConfig runtimeConfig) { List> enabledEntities = runtimeConfig.Entities.Entities - .Where(e => e.Value.IsEntityHealthEnabled) + .Where(e => e.Value.IsEntityHealthEnabled && e.Value.Source.Type != EntitySourceType.StoredProcedure) .ToList(); if (enabledEntities.Count == 0) diff --git a/src/Service/Program.cs b/src/Service/Program.cs index e23fb98cd9..368eaffc46 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 ca69e59a16..9cd553446f 100644 --- a/src/Service/Startup.cs +++ b/src/Service/Startup.cs @@ -81,6 +81,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; @@ -100,13 +101,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; @@ -225,6 +228,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); @@ -569,7 +579,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; + } + } +}