Skip to content

Commit ba3fd40

Browse files
Fix logs still appearing even when LogLevel is set to none bug (#3318)
## Why make this change? - Closes issue #3262 The logger for the Startup class is not initialized properly, since this logger is special due to the nature of the Startup class it needs to be continuously updated as DAB initializes. This causes two problems: - Some logs appear even when LogLevel is set to some value that would impede those logs to appear. - Some logs don't appear at all, even when LogLevel is set to a value that should allow them to be logged. - Closes issue #3256 & #3255 The CLI logger still outputs some logs even when the LogLevel is set to `none`. It is expected that if the LogLevel set is `none` or some other level that shouldn't output the `information` level, the logs will not appear. ## What is this change? Important Note: These changes currently only allow us to change the LogLevel from the CLI with the `default` namespace in the config file. An task was created to solve this issue: #3451 In order to solve issue #3262: - We removed the LogBuffer from the services inside of `Startup.cs`, this is necessary since we wanted each class to have its own LogBuffer so that we are able to tell from which logger the logs are being outputted. - Then, we also correctly initialized the `Startup` logger by changing the method that it was using to initialize the logger, it now uses `CreateLoggerFactoryForHostedAndNonHostedScenario` which checks if there are any LogLevel namespaces from the config file that can be applicable for the specific logger. It is important to note that there are multiple places where the logs are flushed in order to cover for the cases in which an exception is found and causes DAB to end abruptly, and when we there is an IsLateConfigured scenario. - We also changed the logger for the LogBuffer in all the missing places where it creates logs before the logger is able to properly initialize to add those logs to the LogBuffer and only flush them after the loggers are initialized. In order to solve issue #3256 & #3255: - We changed the CLI so that we add all the logs go to a single global LogBuffer that is created inside the `StartOptions.cs` until it is able to deserialize the RuntimeConfig and find which level to set the `LogLevel` in order to flush all the logs. - This is something that we only want to happen when we use the `dab start` command, which is why we only make this change in the `StartOptions.cs` file, on the function `TryStartEngineWithOptions` inside of `ConfigGenerator.cs`, and a few functions from `Utils.cs` and `ConfigMerger.cs` that are used inside the `TryStartEngine` function. ## How was this tested? - [ ] Integration Tests - [x] Unit Tests ## Sample Request(s) - dab start --LogLevel none - dab start --LogLevel error --------- Co-authored-by: Aniruddh Munde <anmunde@microsoft.com>
1 parent b51fad0 commit ba3fd40

21 files changed

Lines changed: 505 additions & 171 deletions

src/Cli.Tests/CustomLoggerTests.cs

Lines changed: 34 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -18,8 +18,6 @@ public class CustomLoggerTests
1818
[DataTestMethod]
1919
[DataRow(LogLevel.Information, "info:")]
2020
[DataRow(LogLevel.Warning, "warn:")]
21-
[DataRow(LogLevel.Error, "fail:")]
22-
[DataRow(LogLevel.Critical, "crit:")]
2321
public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix)
2422
{
2523
CustomLoggerProvider provider = new();
@@ -46,4 +44,38 @@ public void LogOutput_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string ex
4644
Console.SetOut(originalOut);
4745
}
4846
}
47+
48+
/// <summary>
49+
/// Validates that each log level error and above produces the correct abbreviated
50+
/// label matching ASP.NET Core's default console formatter convention.
51+
/// Error and Critical logs should go to the stderr stream.
52+
/// </summary>
53+
[DataTestMethod]
54+
[DataRow(LogLevel.Error, "fail:")]
55+
[DataRow(LogLevel.Critical, "crit:")]
56+
public void LogError_UsesAbbreviatedLogLevelLabels(LogLevel logLevel, string expectedPrefix)
57+
{
58+
CustomLoggerProvider provider = new();
59+
ILogger logger = provider.CreateLogger("TestCategory");
60+
61+
TextWriter originalError = Console.Error;
62+
try
63+
{
64+
StringWriter writer = new();
65+
Console.SetError(writer);
66+
logger.Log(logLevel, "test message");
67+
68+
string output = writer.ToString();
69+
Assert.IsTrue(
70+
output.StartsWith(expectedPrefix),
71+
$"Expected output to start with '{expectedPrefix}' but got: '{output}'");
72+
Assert.IsTrue(
73+
output.Contains("test message"),
74+
$"Expected output to contain 'test message' but got: '{output}'");
75+
}
76+
finally
77+
{
78+
Console.SetError(originalError);
79+
}
80+
}
4981
}

src/Cli.Tests/EndToEndTests.cs

Lines changed: 67 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -48,6 +48,9 @@ public void TestCleanup()
4848
_fileSystem = null;
4949
_runtimeConfigLoader = null;
5050
_cliLogger = null;
51+
52+
// Reset the LoggerFactoryForCli to avoid impacting other tests.
53+
Utils.LoggerFactoryForCli = Utils.GetLoggerFactoryForCli();
5154
}
5255

5356
/// <summary>
@@ -822,24 +825,12 @@ public Task TestUpdatingStoredProcedureWithRestMethods()
822825
[DataRow("--LogLevel 0", DisplayName = "LogLevel 0 from command line.")]
823826
[DataRow("--LogLevel 1", DisplayName = "LogLevel 1 from command line.")]
824827
[DataRow("--LogLevel 2", DisplayName = "LogLevel 2 from command line.")]
825-
[DataRow("--LogLevel 3", DisplayName = "LogLevel 3 from command line.")]
826-
[DataRow("--LogLevel 4", DisplayName = "LogLevel 4 from command line.")]
827-
[DataRow("--LogLevel 5", DisplayName = "LogLevel 5 from command line.")]
828-
[DataRow("--LogLevel 6", DisplayName = "LogLevel 6 from command line.")]
829828
[DataRow("--LogLevel Trace", DisplayName = "LogLevel Trace from command line.")]
830829
[DataRow("--LogLevel Debug", DisplayName = "LogLevel Debug from command line.")]
831830
[DataRow("--LogLevel Information", DisplayName = "LogLevel Information from command line.")]
832-
[DataRow("--LogLevel Warning", DisplayName = "LogLevel Warning from command line.")]
833-
[DataRow("--LogLevel Error", DisplayName = "LogLevel Error from command line.")]
834-
[DataRow("--LogLevel Critical", DisplayName = "LogLevel Critical from command line.")]
835-
[DataRow("--LogLevel None", DisplayName = "LogLevel None from command line.")]
836831
[DataRow("--LogLevel tRace", DisplayName = "Case sensitivity: LogLevel Trace from command line.")]
837832
[DataRow("--LogLevel DebUG", DisplayName = "Case sensitivity: LogLevel Debug from command line.")]
838833
[DataRow("--LogLevel information", DisplayName = "Case sensitivity: LogLevel Information from command line.")]
839-
[DataRow("--LogLevel waRNing", DisplayName = "Case sensitivity: LogLevel Warning from command line.")]
840-
[DataRow("--LogLevel eRROR", DisplayName = "Case sensitivity: LogLevel Error from command line.")]
841-
[DataRow("--LogLevel CrItIcal", DisplayName = "Case sensitivity: LogLevel Critical from command line.")]
842-
[DataRow("--LogLevel NONE", DisplayName = "Case sensitivity: LogLevel None from command line.")]
843834
public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption)
844835
{
845836
_fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG);
@@ -859,6 +850,70 @@ public void TestEngineStartUpWithVerboseAndLogLevelOptions(string logLevelOption
859850
}
860851

861852
/// <summary>
853+
/// Test to validate that the engine starts successfully when --LogLevel is set to Warning
854+
/// or above. At these levels, CLI phase messages (logged at Information) are suppressed,
855+
/// so no stdout output with message 'info' is expected during the CLI phase.
856+
/// </summary>
857+
/// <param name="logLevelOption">Log level options</param>
858+
[DataTestMethod]
859+
[DataRow("3", DisplayName = "LogLevel 3 from command line.")]
860+
[DataRow("4", DisplayName = "LogLevel 4 from command line.")]
861+
[DataRow("5", DisplayName = "LogLevel 5 from command line.")]
862+
[DataRow("Warning", DisplayName = "LogLevel Warning from command line.")]
863+
[DataRow("Error", DisplayName = "LogLevel Error from command line.")]
864+
[DataRow("Critical", DisplayName = "LogLevel Critical from command line.")]
865+
[DataRow("waRNing", DisplayName = "Case sensitivity: LogLevel Warning from command line.")]
866+
[DataRow("eRROR", DisplayName = "Case sensitivity: LogLevel Error from command line.")]
867+
[DataRow("CrItIcal", DisplayName = "Case sensitivity: LogLevel Critical from command line.")]
868+
public async Task TestEngineStartUpWithHighLogLevelOptions(string logLevelOption)
869+
{
870+
StringLogger logger = new();
871+
StringWriter consoleOutput = new();
872+
Console.SetOut(consoleOutput);
873+
874+
string[] args = { "start", "--config", TEST_RUNTIME_CONFIG_FILE, "--LogLevel", logLevelOption };
875+
_fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG);
876+
877+
// Run Program.Execute on a background task because StartEngine blocks until the host shuts down.
878+
Task engineTask = Task.Run(() => Program.Execute(args, logger, _fileSystem!, _runtimeConfigLoader!));
879+
880+
// Wait for the CLI to set up the proper LogLevel.
881+
await Task.Delay(TimeSpan.FromSeconds(5));
882+
883+
string engineStdOut = consoleOutput.ToString();
884+
Assert.IsNotNull(engineStdOut);
885+
Assert.IsFalse(engineStdOut.Contains("info"), $"Expected no 'info' outputs at LogLevel {logLevelOption}, but got: {engineStdOut}");
886+
}
887+
888+
/// <summary>
889+
/// Test to validate that the engine starts successfully when --LogLevel is set to None.
890+
/// At these levels, CLI phase messages (logged at Information) are suppressed,
891+
/// so no stdout output is expected during the CLI phase.
892+
/// </summary>
893+
/// <param name="logLevelOption">Log level options</param>
894+
[DataTestMethod]
895+
[DataRow("6", DisplayName = "LogLevel 6 from command line.")]
896+
[DataRow("None", DisplayName = "LogLevel None from command line.")]
897+
[DataRow("NONE", DisplayName = "Case sensitivity: LogLevel None from command line.")]
898+
public async Task TestEngineStartUpWithLogLevelNone(string logLevelOption)
899+
{
900+
StringLogger logger = new();
901+
StringWriter consoleOutput = new();
902+
Console.SetOut(consoleOutput);
903+
904+
string[] args = { "start", "--config", TEST_RUNTIME_CONFIG_FILE, "--LogLevel", logLevelOption };
905+
_fileSystem!.File.WriteAllText(TEST_RUNTIME_CONFIG_FILE, INITIAL_CONFIG);
906+
907+
// Run Program.Execute on a background task because StartEngine blocks until the host shuts down.
908+
Task engineTask = Task.Run(() => Program.Execute(args, logger, _fileSystem!, _runtimeConfigLoader!));
909+
910+
// Wait for the CLI to set up the proper LogLevel.
911+
await Task.Delay(TimeSpan.FromSeconds(5));
912+
913+
string engineStdOut = consoleOutput.ToString();
914+
Assert.IsTrue(string.IsNullOrEmpty(engineStdOut), $"Expected no output at LogLevel {logLevelOption}, but got: {engineStdOut}");
915+
}
916+
862917
/// Validates that `dab start` correctly sets <see cref="Startup.IsLogLevelOverriddenByCli"/>
863918
/// based on whether the --LogLevel CLI flag is provided.
864919
///

src/Cli.Tests/EnvironmentTests.cs

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -162,7 +162,7 @@ public async Task FailureToStartEngineWhenEnvVarNamedWrong()
162162
$"-c {TEST_RUNTIME_CONFIG_FILE}"
163163
);
164164

165-
string? output = await process.StandardError.ReadLineAsync();
165+
string? output = await process.StandardError.ReadToEndAsync();
166166
Assert.IsNotNull(output);
167167
// Clean error message on stderr with no stack trace.
168168
StringAssert.Contains(output, "A valid Connection String should be provided.", StringComparison.Ordinal);

src/Cli.Tests/UtilsTests.cs

Lines changed: 5 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -253,9 +253,11 @@ public void TestMergeConfig()
253253

254254
FileSystemRuntimeConfigLoader loader = new(fileSystem);
255255

256+
LogBuffer logBuffer = new();
257+
256258
Environment.SetEnvironmentVariable(RUNTIME_ENVIRONMENT_VAR_NAME, "Test");
257259

258-
Assert.IsTrue(ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), out string? mergedConfig), "Failed to merge config files");
260+
Assert.IsTrue(ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), logBuffer, out string? mergedConfig), "Failed to merge config files");
259261
Assert.AreEqual(mergedConfig, "dab-config.Test.merged.json");
260262
Assert.IsTrue(fileSystem.File.Exists(mergedConfig));
261263
Assert.IsTrue(JToken.DeepEquals(JObject.Parse(MERGED_CONFIG), JObject.Parse(fileSystem.File.ReadAllText(mergedConfig))));
@@ -306,10 +308,11 @@ public void TestMergeConfigAvailability(
306308
}
307309

308310
FileSystemRuntimeConfigLoader loader = new(fileSystem);
311+
LogBuffer logBuffer = new();
309312

310313
Assert.AreEqual(
311314
expectedIsMergedConfigAvailable,
312-
ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), out string? mergedConfigFile),
315+
ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, new StringLogger(), logBuffer, out string? mergedConfigFile),
313316
"Availability of merge config should match");
314317
Assert.AreEqual(expectedMergedConfigFileName, mergedConfigFile, "Merge config file name should match expected");
315318

src/Cli.Tests/ValidateConfigTests.cs

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -70,8 +70,9 @@ public void TestErrorHandlingForRelationshipValidationWithNonWorkingConnectionSt
7070
((MockFileSystem)_fileSystem!).AddFile(TEST_RUNTIME_CONFIG_FILE, COMPLETE_CONFIG_WITH_RELATIONSHIPS_NON_WORKING_CONN_STRING);
7171
ValidateOptions validateOptions = new(TEST_RUNTIME_CONFIG_FILE);
7272
StringWriter writer = new();
73+
7374
// Capture console output to get error messaging.
74-
Console.SetOut(writer);
75+
Console.SetError(writer);
7576

7677
// Act
7778
ConfigGenerator.IsConfigValid(validateOptions, _runtimeConfigLoader!, _fileSystem!);
@@ -292,6 +293,7 @@ public void ValidateConfigSchemaWhereConfigReferencesEnvironmentVariables()
292293
ValidateOptions validateOptions = new(TEST_RUNTIME_CONFIG_FILE);
293294

294295
// Act
296+
Utils.LoggerFactoryForCli = Utils.GetLoggerFactoryForCli();
295297
ConfigGenerator.IsConfigValid(validateOptions, _runtimeConfigLoader!, _fileSystem!);
296298

297299
// Assert

src/Cli/Commands/StartOptions.cs

Lines changed: 11 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -19,6 +19,8 @@ public class StartOptions : Options
1919
{
2020
private const string LOGLEVEL_HELPTEXT = "Specifies logging level as provided value. For possible values, see: https://go.microsoft.com/fwlink/?linkid=2263106";
2121

22+
public LogBuffer CliBuffer { get; }
23+
2224
public StartOptions(bool verbose, LogLevel? logLevel, bool isHttpsRedirectionDisabled, bool mcpStdio, string? mcpRole, string config)
2325
: base(config)
2426
{
@@ -27,6 +29,7 @@ public StartOptions(bool verbose, LogLevel? logLevel, bool isHttpsRedirectionDis
2729
IsHttpsRedirectionDisabled = isHttpsRedirectionDisabled;
2830
McpStdio = mcpStdio;
2931
McpRole = mcpRole;
32+
CliBuffer = new LogBuffer();
3033
}
3134

3235
// SetName defines mutually exclusive sets, ie: can not have
@@ -48,11 +51,18 @@ public StartOptions(bool verbose, LogLevel? logLevel, bool isHttpsRedirectionDis
4851

4952
public int Handler(ILogger logger, FileSystemRuntimeConfigLoader loader, IFileSystem fileSystem)
5053
{
51-
logger.LogInformation("{productName} {version}", PRODUCT_NAME, ProductInfo.GetProductVersion());
54+
CliBuffer.BufferLog(Microsoft.Extensions.Logging.LogLevel.Information, $"{PRODUCT_NAME} {ProductInfo.GetProductVersion()}");
5255
bool isSuccess = ConfigGenerator.TryStartEngineWithOptions(this, loader, fileSystem);
5356

5457
if (!isSuccess)
5558
{
59+
// Update loggers and flush buffers to ensure that all the logs are printed if the TryStartEngineWithOptions fails.
60+
logger = Utils.LoggerFactoryForCli.CreateLogger<Program>();
61+
loader.SetLogger(Utils.LoggerFactoryForCli.CreateLogger<FileSystemRuntimeConfigLoader>());
62+
63+
CliBuffer.FlushToLogger(logger);
64+
loader.FlushLogBuffer();
65+
5666
logger.LogError("Failed to start the engine{mode}.",
5767
McpStdio ? " in MCP stdio mode" : string.Empty);
5868
}

src/Cli/ConfigGenerator.cs

Lines changed: 48 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -2684,7 +2684,7 @@ public static bool VerifyCanUpdateRelationship(RuntimeConfig runtimeConfig, stri
26842684
/// </summary>
26852685
public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRuntimeConfigLoader loader, IFileSystem fileSystem)
26862686
{
2687-
if (!TryGetConfigForRuntimeEngine(options.Config, loader, fileSystem, out string runtimeConfigFile))
2687+
if (!TryGetConfigForRuntimeEngine(options.Config, loader, fileSystem, out string runtimeConfigFile, options.CliBuffer))
26882688
{
26892689
return false;
26902690
}
@@ -2698,19 +2698,19 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun
26982698
// duplicate output (stderr + stdout).
26992699
if (!loader.IsParseErrorEmitted)
27002700
{
2701-
_logger.LogError("Failed to parse the config file: {runtimeConfigFile}.", runtimeConfigFile);
2701+
options.CliBuffer.BufferLog(LogLevel.Error, $"Failed to parse the config file: {runtimeConfigFile}.");
27022702
}
27032703

27042704
return false;
27052705
}
27062706
else
27072707
{
2708-
_logger.LogInformation("Loaded config file: {runtimeConfigFile}", runtimeConfigFile);
2708+
options.CliBuffer.BufferLog(LogLevel.Information, $"Loaded config file: {runtimeConfigFile}");
27092709
}
27102710

27112711
if (string.IsNullOrWhiteSpace(deserializedRuntimeConfig.DataSource.ConnectionString))
27122712
{
2713-
_logger.LogError("Invalid connection-string provided in the config.");
2713+
options.CliBuffer.BufferLog(LogLevel.Error, "Invalid connection-string provided in the config.");
27142714
return false;
27152715
}
27162716

@@ -2729,9 +2729,8 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun
27292729
{
27302730
if (options.LogLevel is < LogLevel.Trace or > LogLevel.None)
27312731
{
2732-
_logger.LogError(
2733-
"LogLevel's valid range is 0 to 6, your value: {logLevel}, see: https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.loglevel",
2734-
options.LogLevel);
2732+
options.CliBuffer.BufferLog(LogLevel.Error,
2733+
$"LogLevel's valid range is 0 to 6, your value: {options.LogLevel}, see: https://learn.microsoft.com/dotnet/api/microsoft.extensions.logging.loglevel");
27352734
return false;
27362735
}
27372736

@@ -2740,8 +2739,28 @@ public static bool TryStartEngineWithOptions(StartOptions options, FileSystemRun
27402739
// This allows MCP logging/setLevel to work when no CLI override is present.
27412740
args.Add("--LogLevel");
27422741
args.Add(minimumLogLevel.ToString());
2743-
_logger.LogInformation("Setting minimum LogLevel: {minimumLogLevel}.", minimumLogLevel);
27442742
}
2743+
else
2744+
{
2745+
minimumLogLevel = deserializedRuntimeConfig.GetConfiguredLogLevel();
2746+
}
2747+
2748+
options.CliBuffer.BufferLog(LogLevel.Information, $"Setting minimum LogLevel: {minimumLogLevel}.");
2749+
2750+
Utils.LoggerFactoryForCli = Utils.GetLoggerFactoryForCli(minimumLogLevel);
2751+
2752+
// Update logger for StartOptions and
2753+
// flush all current logs saved in LogBuffer
2754+
ILogger<Program> programLogger = Utils.LoggerFactoryForCli.CreateLogger<Program>();
2755+
options.CliBuffer.FlushToLogger(programLogger);
2756+
2757+
// Update logger for Utils
2758+
ILogger<Utils> utilsLogger = Utils.LoggerFactoryForCli.CreateLogger<Utils>();
2759+
Utils.SetCliUtilsLogger(utilsLogger);
2760+
2761+
// Update logger for ConfigGenerator
2762+
ILogger<ConfigGenerator> configGeneratorLogger = Utils.LoggerFactoryForCli.CreateLogger<ConfigGenerator>();
2763+
SetLoggerForCliConfigGenerator(configGeneratorLogger);
27452764

27462765
// This will add args to disable automatic redirects to https if specified by user
27472766
if (options.IsHttpsRedirectionDisabled)
@@ -2843,16 +2862,32 @@ public static bool TryGetConfigForRuntimeEngine(
28432862
string? configToBeUsed,
28442863
FileSystemRuntimeConfigLoader loader,
28452864
IFileSystem fileSystem,
2846-
out string runtimeConfigFile)
2865+
out string runtimeConfigFile,
2866+
LogBuffer? logBuffer = null)
28472867
{
2848-
if (string.IsNullOrEmpty(configToBeUsed) && ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, _logger, out configToBeUsed))
2868+
if (string.IsNullOrEmpty(configToBeUsed) && ConfigMerger.TryMergeConfigsIfAvailable(fileSystem, loader, _logger, logBuffer, out configToBeUsed))
28492869
{
2850-
_logger.LogInformation("Using merged config file based on environment: {configToBeUsed}.", configToBeUsed);
2870+
if (logBuffer is null)
2871+
{
2872+
_logger.LogInformation("Using merged config file based on environment: {configToBeUsed}.", configToBeUsed);
2873+
}
2874+
else
2875+
{
2876+
logBuffer.BufferLog(LogLevel.Information, $"Using merged config file based on environment: {configToBeUsed}.");
2877+
}
28512878
}
28522879

2853-
if (!TryGetConfigFileBasedOnCliPrecedence(loader, configToBeUsed, out runtimeConfigFile))
2880+
if (!TryGetConfigFileBasedOnCliPrecedence(loader, configToBeUsed, out runtimeConfigFile, logBuffer))
28542881
{
2855-
_logger.LogError("Config not provided and default config file doesn't exist.");
2882+
if (logBuffer is null)
2883+
{
2884+
_logger.LogError("Config not provided and default config file doesn't exist.");
2885+
}
2886+
else
2887+
{
2888+
logBuffer.BufferLog(LogLevel.Error, "Config not provided and default config file doesn't exist.");
2889+
}
2890+
28562891
return false;
28572892
}
28582893

0 commit comments

Comments
 (0)