Skip to content

Commit 2c7859b

Browse files
CopilotRubenCerna2079Aniruddh25anushakolan
committed
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] <198982749+Copilot@users.noreply.github.com> Co-authored-by: RubenCerna2079 <32799214+RubenCerna2079@users.noreply.github.com> Co-authored-by: Ruben Cerna <rcernaserna@microsoft.com> Co-authored-by: Aniruddh Munde <anmunde@microsoft.com> Co-authored-by: Anusha Kolan <anushakolan10@gmail.com>
1 parent 76b4d4f commit 2c7859b

File tree

9 files changed

+165
-36
lines changed

9 files changed

+165
-36
lines changed

src/Cli.Tests/EndToEndTests.cs

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

src/Config/FileSystemRuntimeConfigLoader.cs

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

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

93104
/// <summary>
@@ -195,7 +206,7 @@ public bool TryLoadConfig(
195206
{
196207
if (_fileSystem.File.Exists(path))
197208
{
198-
Console.WriteLine($"Loading config file from {_fileSystem.Path.GetFullPath(path)}.");
209+
SendLogToBufferOrLogger(LogLevel.Information, $"Loading config file from {_fileSystem.Path.GetFullPath(path)}.");
199210

200211
// Use File.ReadAllText because DAB doesn't need write access to the file
201212
// and ensures the file handle is released immediately after reading.
@@ -214,7 +225,8 @@ public bool TryLoadConfig(
214225
}
215226
catch (IOException ex)
216227
{
217-
Console.WriteLine($"IO Exception, retrying due to {ex.Message}");
228+
SendLogToBufferOrLogger(LogLevel.Warning, $"IO Exception, retrying due to {ex.Message}");
229+
218230
if (runCount == FileUtilities.RunLimit)
219231
{
220232
throw;
@@ -237,8 +249,7 @@ public bool TryLoadConfig(
237249
{
238250
if (TrySetupConfigFileWatcher())
239251
{
240-
Console.WriteLine("Monitoring config: {0} for hot-reloading.", ConfigFilePath);
241-
logger?.LogInformation("Monitoring config: {ConfigFilePath} for hot-reloading.", ConfigFilePath);
252+
SendLogToBufferOrLogger(LogLevel.Information, $"Monitoring config: {ConfigFilePath} for hot-reloading.");
242253
}
243254

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

261265
RuntimeConfig.Runtime.Host.Mode = (bool)isDevMode ? HostMode.Development : HostMode.Production;
@@ -280,16 +284,8 @@ public bool TryLoadConfig(
280284
return false;
281285
}
282286

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

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

src/Config/ObjectModel/RuntimeConfig.cs

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -714,7 +714,6 @@ Runtime.Telemetry.LoggerLevel is null ||
714714
/// </summary>
715715
public LogLevel GetConfiguredLogLevel(string loggerFilter = "")
716716
{
717-
718717
if (!IsLogLevelNull())
719718
{
720719
int max = 0;
@@ -735,7 +734,8 @@ public LogLevel GetConfiguredLogLevel(string loggerFilter = "")
735734
return (LogLevel)value;
736735
}
737736

738-
Runtime!.Telemetry!.LoggerLevel!.TryGetValue("default", out value);
737+
value = Runtime!.Telemetry!.LoggerLevel!
738+
.SingleOrDefault(kvp => kvp.Key.Equals("default", StringComparison.OrdinalIgnoreCase)).Value;
739739
if (value is not null)
740740
{
741741
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
@@ -1502,7 +1502,7 @@ private static bool IsLoggerFilterValid(string loggerFilter)
15021502
{
15031503
for (int j = 0; j < loggerSub.Length; j++)
15041504
{
1505-
if (!loggerSub[j].Equals(validFiltersSub[j]))
1505+
if (!loggerSub[j].Equals(validFiltersSub[j], StringComparison.OrdinalIgnoreCase))
15061506
{
15071507
isValid = false;
15081508
break;

src/Service.Tests/Configuration/ConfigurationTests.cs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -4057,6 +4057,7 @@ public void ValidLogLevelFilters(LogLevel logLevel, Type loggingType)
40574057
[DataTestMethod]
40584058
[TestCategory(TestCategory.MSSQL)]
40594059
[DataRow(LogLevel.Trace, "default")]
4060+
[DataRow(LogLevel.Warning, "Default")]
40604061
[DataRow(LogLevel.Debug, "Azure")]
40614062
[DataRow(LogLevel.Information, "Azure.DataApiBuilder")]
40624063
[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
@@ -81,6 +81,7 @@ public class Startup(IConfiguration configuration, ILogger<Startup> logger)
8181
public static AzureLogAnalyticsOptions AzureLogAnalyticsOptions = new();
8282
public static FileSinkOptions FileSinkOptions = new();
8383
public const string NO_HTTPS_REDIRECT_FLAG = "--no-https-redirect";
84+
private StartupLogBuffer _logBuffer = new();
8485
private readonly HotReloadEventHandler<HotReloadEventArgs> _hotReloadEventHandler = new();
8586
private RuntimeConfigProvider? _configProvider;
8687
private ILogger<Startup> _logger = logger;
@@ -100,13 +101,15 @@ public class Startup(IConfiguration configuration, ILogger<Startup> logger)
100101
public void ConfigureServices(IServiceCollection services)
101102
{
102103
Startup.AddValidFilters();
104+
services.AddSingleton(_logBuffer);
105+
services.AddSingleton(Program.LogLevelProvider);
103106
services.AddSingleton(_hotReloadEventHandler);
104107
string configFileName = Configuration.GetValue<string>("ConfigFileName") ?? FileSystemRuntimeConfigLoader.DEFAULT_CONFIG_FILE_NAME;
105108
string? connectionString = Configuration.GetValue<string?>(
106109
FileSystemRuntimeConfigLoader.RUNTIME_ENV_CONNECTION_STRING.Replace(FileSystemRuntimeConfigLoader.ENVIRONMENT_PREFIX, ""),
107110
null);
108111
IFileSystem fileSystem = new FileSystem();
109-
FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString);
112+
FileSystemRuntimeConfigLoader configLoader = new(fileSystem, _hotReloadEventHandler, configFileName, connectionString, logBuffer: _logBuffer);
110113
RuntimeConfigProvider configProvider = new(configLoader);
111114
_configProvider = configProvider;
112115

@@ -225,6 +228,13 @@ public void ConfigureServices(IServiceCollection services)
225228
services.AddHealthChecks()
226229
.AddCheck<BasicHealthCheck>(nameof(BasicHealthCheck));
227230

231+
services.AddSingleton<ILogger<FileSystemRuntimeConfigLoader>>(implementationFactory: (serviceProvider) =>
232+
{
233+
LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(FileSystemRuntimeConfigLoader).FullName, _configProvider, _hotReloadEventHandler);
234+
ILoggerFactory? loggerFactory = CreateLoggerFactoryForHostedAndNonHostedScenario(serviceProvider, logLevelInit);
235+
return loggerFactory.CreateLogger<FileSystemRuntimeConfigLoader>();
236+
});
237+
228238
services.AddSingleton<ILogger<SqlQueryEngine>>(implementationFactory: (serviceProvider) =>
229239
{
230240
LogLevelInitializer logLevelInit = new(MinimumLogLevel, typeof(SqlQueryEngine).FullName, _configProvider, _hotReloadEventHandler);
@@ -569,7 +579,16 @@ public void Configure(IApplicationBuilder app, IWebHostEnvironment env, RuntimeC
569579

570580
if (runtimeConfigProvider.TryGetConfig(out RuntimeConfig? runtimeConfig))
571581
{
572-
// Configure Application Insights Telemetry
582+
// Set LogLevel based on RuntimeConfig
583+
DynamicLogLevelProvider logLevelProvider = app.ApplicationServices.GetRequiredService<DynamicLogLevelProvider>();
584+
logLevelProvider.UpdateFromRuntimeConfig(runtimeConfig);
585+
FileSystemRuntimeConfigLoader configLoader = app.ApplicationServices.GetRequiredService<FileSystemRuntimeConfigLoader>();
586+
587+
//Flush all logs that were buffered before setting the LogLevel
588+
configLoader.SetLogger(app.ApplicationServices.GetRequiredService<ILogger<FileSystemRuntimeConfigLoader>>());
589+
configLoader.FlushLogBuffer();
590+
591+
// Configure Telemetry
573592
ConfigureApplicationInsightsTelemetry(app, runtimeConfig);
574593
ConfigureOpenTelemetry(runtimeConfig);
575594
ConfigureAzureLogAnalytics(runtimeConfig);
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)