Skip to content

Commit abcfb58

Browse files
CopilotRubenCerna2079Aniruddh25anushakolan
authored
Fix LogLevel: CLI phase suppression and case-insensitive "Default" config key (#3203)
## Why make this change? - #3201 Two `LogLevel` bugs: Using the `None` LogLevel still emits some `Information` messages (version, config path, etc.), and using `"Default"` (capital D) as a key in `telemetry.log-level` config crashes startup with `NotSupportedException`. ## What is this change? **All logs follow the LogLevel configuration** - Added more specific configuration for logs in the host level, `Program.cs` which where outputing some logs that where not following the LogLevel configuration from CLI and from configuration file. - Add `DynamicLogLevelProvider` class which allows the loggers in the host level to be updated after the RuntimeConfig is parsed and we know the LogLevel. - Add `StartupLogBuffer` class which saves the logs that are created before we know the LogLevel, and sends them to their respective logger after the RuntimeConfig is parsed. **Case-insensitive `"Default"` key in config** - `IsLoggerFilterValid` used `string.Equals` (ordinal), so `"Default"` failed against the registered `"default"` filter. - `GetConfiguredLogLevel` used `TryGetValue("default")` (case-sensitive), silently ignoring `"Default"` keys. - Both fixed with `StringComparison.OrdinalIgnoreCase` / LINQ `FirstOrDefault`. ```json // Now works — previously threw NotSupportedException "telemetry": { "log-level": { "Default": "warning" } } ``` ``` # Now silent — previously emitted "Information: Microsoft.DataApiBuilder ..." dab start --LogLevel None ``` ## How was this tested? - [ ] Integration Tests - [x] Unit Tests - `ValidStringLogLevelFilters`: added `"Default"` (capital D) data row to cover the case-insensitive validation fix. ## Sample Request(s) ```bash # Suppress all output dab start --LogLevel None # Config key now case-insensitive # dab-config.json: # "telemetry": { "log-level": { "Default": "none" } } dab start ``` --------- Co-authored-by: copilot-swe-agent[bot] <[email protected]> Co-authored-by: RubenCerna2079 <[email protected]> Co-authored-by: Ruben Cerna <[email protected]> Co-authored-by: Aniruddh Munde <[email protected]> Co-authored-by: Anusha Kolan <[email protected]>
1 parent 041a722 commit abcfb58

9 files changed

Lines changed: 165 additions & 36 deletions

File tree

‎src/Cli.Tests/EndToEndTests.cs‎

Lines changed: 0 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1088,10 +1088,6 @@ public async Task TestExitOfRuntimeEngineWithInvalidConfig(
10881088
output = await process.StandardOutput.ReadLineAsync();
10891089
Assert.IsNotNull(output);
10901090
StringAssert.Contains(output, $"Setting default minimum LogLevel:", StringComparison.Ordinal);
1091-
1092-
output = await process.StandardOutput.ReadLineAsync();
1093-
Assert.IsNotNull(output);
1094-
StringAssert.Contains(output, "Starting the runtime engine...", StringComparison.Ordinal);
10951091
}
10961092
else
10971093
{

‎src/Config/FileSystemRuntimeConfigLoader.cs‎

Lines changed: 50 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -59,6 +59,13 @@ public class FileSystemRuntimeConfigLoader : RuntimeConfigLoader
5959
/// </summary>
6060
private readonly IFileSystem _fileSystem;
6161

62+
/// <summary>
63+
/// Logger used to log all the events that occur inside of FileSystemRuntimeConfigLoader
64+
/// </summary>
65+
private ILogger<FileSystemRuntimeConfigLoader>? _logger;
66+
67+
private StartupLogBuffer? _logBuffer;
68+
6269
public const string CONFIGFILE_NAME = "dab-config";
6370
public const string CONFIG_EXTENSION = ".json";
6471
public const string ENVIRONMENT_PREFIX = "DAB_";
@@ -82,13 +89,17 @@ public FileSystemRuntimeConfigLoader(
8289
HotReloadEventHandler<HotReloadEventArgs>? handler = null,
8390
string baseConfigFilePath = DEFAULT_CONFIG_FILE_NAME,
8491
string? connectionString = null,
85-
bool isCliLoader = false)
92+
bool isCliLoader = false,
93+
ILogger<FileSystemRuntimeConfigLoader>? logger = null,
94+
StartupLogBuffer? logBuffer = null)
8695
: base(handler, connectionString)
8796
{
8897
_fileSystem = fileSystem;
8998
_baseConfigFilePath = baseConfigFilePath;
9099
ConfigFilePath = GetFinalConfigFilePath();
91100
_isCliLoader = isCliLoader;
101+
_logger = logger;
102+
_logBuffer = logBuffer;
92103
}
93104

94105
/// <summary>
@@ -196,7 +207,7 @@ public bool TryLoadConfig(
196207
{
197208
if (_fileSystem.File.Exists(path))
198209
{
199-
Console.WriteLine($"Loading config file from {_fileSystem.Path.GetFullPath(path)}.");
210+
SendLogToBufferOrLogger(LogLevel.Information, $"Loading config file from {_fileSystem.Path.GetFullPath(path)}.");
200211

201212
// Use File.ReadAllText because DAB doesn't need write access to the file
202213
// and ensures the file handle is released immediately after reading.
@@ -215,7 +226,8 @@ public bool TryLoadConfig(
215226
}
216227
catch (IOException ex)
217228
{
218-
Console.WriteLine($"IO Exception, retrying due to {ex.Message}");
229+
SendLogToBufferOrLogger(LogLevel.Warning, $"IO Exception, retrying due to {ex.Message}");
230+
219231
if (runCount == FileUtilities.RunLimit)
220232
{
221233
throw;
@@ -238,8 +250,7 @@ public bool TryLoadConfig(
238250
{
239251
if (TrySetupConfigFileWatcher())
240252
{
241-
Console.WriteLine("Monitoring config: {0} for hot-reloading.", ConfigFilePath);
242-
logger?.LogInformation("Monitoring config: {ConfigFilePath} for hot-reloading.", ConfigFilePath);
253+
SendLogToBufferOrLogger(LogLevel.Information, $"Monitoring config: {ConfigFilePath} for hot-reloading.");
243254
}
244255

245256
// 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(
249260
// Log error when the mode is changed during hot-reload.
250261
if (isDevMode != this.RuntimeConfig.IsDevelopmentMode())
251262
{
252-
if (logger is null)
253-
{
254-
Console.WriteLine("Hot-reload doesn't support switching mode. Please restart the service to switch the mode.");
255-
}
256-
else
257-
{
258-
logger.LogError("Hot-reload doesn't support switching mode. Please restart the service to switch the mode.");
259-
}
263+
SendLogToBufferOrLogger(LogLevel.Error, "Hot-reload doesn't support switching mode. Please restart the service to switch the mode.");
260264
}
261265

262266
RuntimeConfig.Runtime.Host.Mode = (bool)isDevMode ? HostMode.Development : HostMode.Production;
@@ -281,16 +285,8 @@ public bool TryLoadConfig(
281285
return false;
282286
}
283287

284-
if (logger is null)
285-
{
286-
string errorMessage = $"Unable to find config file: {path} does not exist.";
287-
Console.Error.WriteLine(errorMessage);
288-
}
289-
else
290-
{
291-
string errorMessage = "Unable to find config file: {path} does not exist.";
292-
logger.LogError(message: errorMessage, path);
293-
}
288+
string errorMessage = $"Unable to find config file: {path} does not exist.";
289+
SendLogToBufferOrLogger(LogLevel.Error, errorMessage);
294290

295291
config = null;
296292
return false;
@@ -516,4 +512,35 @@ public void UpdateConfigFilePath(string filePath)
516512
_baseConfigFilePath = filePath;
517513
ConfigFilePath = filePath;
518514
}
515+
516+
public void SetLogger(ILogger<FileSystemRuntimeConfigLoader> logger)
517+
{
518+
_logger = logger;
519+
}
520+
521+
/// <summary>
522+
/// Flush all logs from the buffer after the log level is set from the RuntimeConfig.
523+
/// </summary>
524+
public void FlushLogBuffer()
525+
{
526+
_logBuffer?.FlushToLogger(_logger);
527+
}
528+
529+
/// <summary>
530+
/// Helper method that sends the log to the buffer if the logger has not being set up.
531+
/// Else, it will send the log to the logger.
532+
/// </summary>
533+
/// <param name="logLevel">LogLevel of the log.</param>
534+
/// <param name="message">Message that will be printed in the log.</param>
535+
private void SendLogToBufferOrLogger(LogLevel logLevel, string message)
536+
{
537+
if (_logger is null)
538+
{
539+
_logBuffer?.BufferLog(logLevel, message);
540+
}
541+
else
542+
{
543+
_logger?.Log(logLevel, message);
544+
}
545+
}
519546
}

‎src/Config/ObjectModel/RuntimeConfig.cs‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -774,7 +774,6 @@ Runtime.Telemetry.LoggerLevel is null ||
774774
/// </summary>
775775
public LogLevel GetConfiguredLogLevel(string loggerFilter = "")
776776
{
777-
778777
if (!IsLogLevelNull())
779778
{
780779
int max = 0;
@@ -795,7 +794,8 @@ public LogLevel GetConfiguredLogLevel(string loggerFilter = "")
795794
return (LogLevel)value;
796795
}
797796

798-
Runtime!.Telemetry!.LoggerLevel!.TryGetValue("default", out value);
797+
value = Runtime!.Telemetry!.LoggerLevel!
798+
.SingleOrDefault(kvp => kvp.Key.Equals("default", StringComparison.OrdinalIgnoreCase)).Value;
799799
if (value is not null)
800800
{
801801
return (LogLevel)value;

‎src/Config/StartupLogBuffer.cs‎

Lines changed: 45 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,45 @@
1+
// Copyright (c) Microsoft Corporation.
2+
// Licensed under the MIT License.
3+
4+
using System.Collections.Concurrent;
5+
using Microsoft.Extensions.Logging;
6+
7+
namespace Azure.DataApiBuilder.Config
8+
{
9+
/// <summary>
10+
/// A general-purpose log buffer that stores log entries before the final log level is determined.
11+
/// Can be used across different components during startup to capture important early logs.
12+
/// </summary>
13+
public class StartupLogBuffer
14+
{
15+
private readonly ConcurrentQueue<(LogLevel LogLevel, string Message)> _logBuffer;
16+
private readonly object _flushLock = new();
17+
18+
public StartupLogBuffer()
19+
{
20+
_logBuffer = new();
21+
}
22+
23+
/// <summary>
24+
/// Buffers a log entry with a specific category name.
25+
/// </summary>
26+
public void BufferLog(LogLevel logLevel, string message)
27+
{
28+
_logBuffer.Enqueue((logLevel, message));
29+
}
30+
31+
/// <summary>
32+
/// Flushes all buffered logs to a single target logger.
33+
/// </summary>
34+
public void FlushToLogger(ILogger? targetLogger)
35+
{
36+
lock (_flushLock)
37+
{
38+
while (_logBuffer.TryDequeue(out (LogLevel LogLevel, string Message) entry))
39+
{
40+
targetLogger?.Log(entry.LogLevel, message: entry.Message);
41+
}
42+
}
43+
}
44+
}
45+
}

‎src/Core/Configurations/RuntimeConfigValidator.cs‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -1585,7 +1585,7 @@ private static bool IsLoggerFilterValid(string loggerFilter)
15851585
{
15861586
for (int j = 0; j < loggerSub.Length; j++)
15871587
{
1588-
if (!loggerSub[j].Equals(validFiltersSub[j]))
1588+
if (!loggerSub[j].Equals(validFiltersSub[j], StringComparison.OrdinalIgnoreCase))
15891589
{
15901590
isValid = false;
15911591
break;

‎src/Service.Tests/Configuration/ConfigurationTests.cs‎

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4268,6 +4268,7 @@ public void ValidLogLevelFilters(LogLevel logLevel, Type loggingType)
42684268
[DataTestMethod]
42694269
[TestCategory(TestCategory.MSSQL)]
42704270
[DataRow(LogLevel.Trace, "default")]
4271+
[DataRow(LogLevel.Warning, "Default")]
42714272
[DataRow(LogLevel.Debug, "Azure")]
42724273
[DataRow(LogLevel.Information, "Azure.DataApiBuilder")]
42734274
[DataRow(LogLevel.Warning, "Azure.DataApiBuilder.Core")]

‎src/Service/Program.cs‎

Lines changed: 14 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -33,6 +33,7 @@ namespace Azure.DataApiBuilder.Service
3333
public class Program
3434
{
3535
public static bool IsHttpsRedirectionDisabled { get; private set; }
36+
public static DynamicLogLevelProvider LogLevelProvider = new();
3637

3738
public static void Main(string[] args)
3839
{
@@ -59,7 +60,6 @@ public static void Main(string[] args)
5960

6061
public static bool StartEngine(string[] args, bool runMcpStdio, string? mcpRole)
6162
{
62-
Console.WriteLine("Starting the runtime engine...");
6363
try
6464
{
6565
IHost host = CreateHostBuilder(args, runMcpStdio, mcpRole).Build();
@@ -107,9 +107,19 @@ public static IHostBuilder CreateHostBuilder(string[] args, bool runMcpStdio, st
107107
McpStdioHelper.ConfigureMcpStdio(builder, mcpRole);
108108
}
109109
})
110+
.ConfigureServices((context, services) =>
111+
{
112+
services.AddSingleton(LogLevelProvider);
113+
})
114+
.ConfigureLogging(logging =>
115+
{
116+
logging.AddFilter("Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel));
117+
logging.AddFilter("Microsoft.Hosting.Lifetime", logLevel => LogLevelProvider.ShouldLog(logLevel));
118+
})
110119
.ConfigureWebHostDefaults(webBuilder =>
111120
{
112121
Startup.MinimumLogLevel = GetLogLevelFromCommandLineArgs(args, out Startup.IsLogLevelOverriddenByCli);
122+
LogLevelProvider.SetInitialLogLevel(Startup.MinimumLogLevel, Startup.IsLogLevelOverriddenByCli);
113123
ILoggerFactory loggerFactory = GetLoggerFactoryForLogLevel(Startup.MinimumLogLevel, stdio: runMcpStdio);
114124
ILogger<Startup> startupLogger = loggerFactory.CreateLogger<Startup>();
115125
DisableHttpsRedirectionIfNeeded(args);
@@ -185,9 +195,9 @@ public static ILoggerFactory GetLoggerFactoryForLogLevel(
185195
// "Azure.DataApiBuilder.Service"
186196
if (logLevelInitializer is null)
187197
{
188-
builder.AddFilter(category: "Microsoft", logLevel);
189-
builder.AddFilter(category: "Azure", logLevel);
190-
builder.AddFilter(category: "Default", logLevel);
198+
builder.AddFilter(category: "Microsoft", logLevel => LogLevelProvider.ShouldLog(logLevel));
199+
builder.AddFilter(category: "Azure", logLevel => LogLevelProvider.ShouldLog(logLevel));
200+
builder.AddFilter(category: "Default", logLevel => LogLevelProvider.ShouldLog(logLevel));
191201
}
192202
else
193203
{

‎src/Service/Startup.cs‎

Lines changed: 21 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -86,6 +86,7 @@ public class Startup(IConfiguration configuration, ILogger<Startup> logger)
8686
public static AzureLogAnalyticsOptions AzureLogAnalyticsOptions = new();
8787
public static FileSinkOptions FileSinkOptions = new();
8888
public const string NO_HTTPS_REDIRECT_FLAG = "--no-https-redirect";
89+
private StartupLogBuffer _logBuffer = new();
8990
private readonly HotReloadEventHandler<HotReloadEventArgs> _hotReloadEventHandler = new();
9091
private RuntimeConfigProvider? _configProvider;
9192
private ILogger<Startup> _logger = logger;
@@ -105,13 +106,15 @@ public class Startup(IConfiguration configuration, ILogger<Startup> logger)
105106
public void ConfigureServices(IServiceCollection services)
106107
{
107108
Startup.AddValidFilters();
109+
services.AddSingleton(_logBuffer);
110+
services.AddSingleton(Program.LogLevelProvider);
108111
services.AddSingleton(_hotReloadEventHandler);
109112
string configFileName = Configuration.GetValue<string>("ConfigFileName") ?? FileSystemRuntimeConfigLoader.DEFAULT_CONFIG_FILE_NAME;
110113
string? connectionString = Configuration.GetValue<string?>(
111114
FileSystemRuntimeConfigLoader.RUNTIME_ENV_CONNECTION_STRING.Replace(FileSystemRuntimeConfigLoader.ENVIRONMENT_PREFIX, ""),
112115
null);
113116
IFileSystem fileSystem = new FileSystem();
114-
FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString);
117+
FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString, logBuffer: _logBuffer);
115118
RuntimeConfigProvider configProvider = new(configLoader);
116119
_configProvider = configProvider;
117120

@@ -231,6 +234,13 @@ public void ConfigureServices(IServiceCollection services)
231234
services.AddHealthChecks()
232235
.AddCheck<BasicHealthCheck>(nameof(BasicHealthCheck));
233236

237+
services.AddSingleton<ILogger<FileSystemRuntimeConfigLoader>>(implementationFactory: (serviceProvider) =>
238+
{
239+
LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(FileSystemRuntimeConfigLoader).FullName, _configProvider, _hotReloadEventHandler);
240+
ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(serviceProvider, logLevelInit);
241+
return loggerFactory.CreateLogger<FileSystemRuntimeConfigLoader>();
242+
});
243+
234244
services.AddSingleton<ILogger<SqlQueryEngine>>(implementationFactory: (serviceProvider) =>
235245
{
236246
LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(SqlQueryEngine).FullName, _configProvider, _hotReloadEventHandler);
@@ -695,7 +705,16 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC
695705

696706
if (runtimeConfigProvider.TryGetConfig(out RuntimeConfig? runtimeConfig))
697707
{
698-
// Configure Application Insights Telemetry
708+
// Set LogLevel based on RuntimeConfig
709+
DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService<DynamicLogLevelProvider>();
710+
logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig);
711+
FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService<FileSystemRuntimeConfigLoader>();
712+
713+
//Flush all logs that were buffered before setting the LogLevel
714+
configLoader.SetLogger(app.ApplicationServices.GetRequiredService<ILogger<FileSystemRuntimeConfigLoader>>());
715+
configLoader.FlushLogBuffer();
716+
717+
// Configure Telemetry
699718
ConfigureApplicationInsightsTelemetry(app, runtimeConfig);
700719
ConfigureOpenTelemetry(runtimeConfig);
701720
ConfigureAzureLogAnalytics(runtimeConfig);

‎src/Service/Telemetry/DynamicLogLevelProvider.cs‎

Lines changed: 31 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,31 @@
1+
using Azure.DataApiBuilder.Config.ObjectModel;
2+
using Microsoft.Extensions.Logging;
3+
4+
namespace Azure.DataApiBuilder.Service.Telemetry
5+
{
6+
public class DynamicLogLevelProvider
7+
{
8+
public LogLevel CurrentLogLevel { get; private set; }
9+
public bool IsCliOverridden { get; private set; }
10+
11+
public void SetInitialLogLevel(LogLevel logLevel = LogLevel.Error, bool isCliOverridden = false)
12+
{
13+
CurrentLogLevel = logLevel;
14+
IsCliOverridden = isCliOverridden;
15+
}
16+
17+
public void UpdateFromRuntimeConfig(RuntimeConfig runtimeConfig)
18+
{
19+
// Only update if CLI didn't override
20+
if (!IsCliOverridden)
21+
{
22+
CurrentLogLevel = runtimeConfig.GetConfiguredLogLevel();
23+
}
24+
}
25+
26+
public bool ShouldLog(LogLevel logLevel)
27+
{
28+
return logLevel >= CurrentLogLevel;
29+
}
30+
}
31+
}

0 commit comments

Comments
 (0)