[Bug]: LogLevel incorrect behavior and failing

[JerryNixon]

What?

LogLevel isn't working as expected.

Example

This is the normal DAB start output

C:\Temp\dab-todo-test>dab start
Information: Microsoft.DataApiBuilder 1.7.90
Information: Config not provided. Trying to get default config based on DAB_ENVIRONMENT...
Information: Environment variable DAB_ENVIRONMENT is (null)
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Information: Loaded config file: dab-config.json
Information: Setting default minimum LogLevel: Debug for Development mode.
Starting the runtime engine...
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Monitoring config: dab-config.json for hot-reloading.
info: Microsoft.AspNetCore.DataProtection.KeyManagement.XmlKeyManager[63]
      User profile is available. Using 'C:\Users\jnixon\AppData\Local\ASP.NET\DataProtection-Keys' as key repository and Windows DPAPI to encrypt keys at rest.
info: Azure.DataApiBuilder.Core.Services.ISqlMetadataProvider[0]
      [Todos] REST path: /api/Todos
dbug: Azure.DataApiBuilder.Core.Resolvers.IQueryExecutor[0]
       Executing query: SELECT STE.type_desc FROM sys.triggers ST inner join sys.trigger_events STE On ST.object_id = STE.object_id AND ST.parent_id = object_id(@param0 + '.' + @param1) WHERE ST.is_disabled = 0;
dbug: Azure.DataApiBuilder.Core.Resolvers.IQueryExecutor[0]
       Executing query: SELECT ifsc.COLUMN_NAME from sys.columns as sc INNER JOIN INFORMATION_SCHEMA.COLUMNS as ifsc ON (sc.is_computed = 1 or ifsc.DATA_TYPE = 'timestamp') AND sc.object_id = object_id(@param0+'.'+@param1) AND ifsc.TABLE_SCHEMA = @param0 AND ifsc.TABLE_NAME = @param1 AND ifsc.COLUMN_NAME = sc.name;
dbug: Azure.DataApiBuilder.Core.Services.ISqlMetadataProvider[0]
      Logging primary key information for entity: Todos.
dbug: Azure.DataApiBuilder.Core.Services.ISqlMetadataProvider[0]
      Primary key column name: Id
      Primary key mapped name: Id
      Type: Int32
      IsNullable: False
      IsAutoGenerated: True
info: Azure.DataApiBuilder.Service.Startup[0]
      Successfully completed runtime initialization.
info: Microsoft.Hosting.Lifetime[14]
      Now listening on: http://localhost:5000
info: Microsoft.Hosting.Lifetime[0]
      Application started. Press Ctrl+C to shut down.
info: Microsoft.Hosting.Lifetime[0]
      Hosting environment: Production
info: Microsoft.Hosting.Lifetime[0]
      Content root path: C:\Temp\dab-todo-test

Suppress ASPNET logging

set Logging__LogLevel__Default=None

This works.

C:\Temp\dab-todo-test>set Logging__LogLevel__Default=None

C:\Temp\dab-todo-test>dab start
Information: Microsoft.DataApiBuilder 1.7.90
Information: Config not provided. Trying to get default config based on DAB_ENVIRONMENT...
Information: Environment variable DAB_ENVIRONMENT is (null)
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Information: Loaded config file: dab-config.json
Information: Setting default minimum LogLevel: Debug for Development mode.
Starting the runtime engine...
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Monitoring config: dab-config.json for hot-reloading.
info: Azure.DataApiBuilder.Core.Services.ISqlMetadataProvider[0]
      [Todos] REST path: /api/Todos
dbug: Azure.DataApiBuilder.Core.Resolvers.IQueryExecutor[0]
       Executing query: SELECT STE.type_desc FROM sys.triggers ST inner join sys.trigger_events STE On ST.object_id = STE.object_id AND ST.parent_id = object_id(@param0 + '.' + @param1) WHERE ST.is_disabled = 0;
dbug: Azure.DataApiBuilder.Core.Resolvers.IQueryExecutor[0]
       Executing query: SELECT ifsc.COLUMN_NAME from sys.columns as sc INNER JOIN INFORMATION_SCHEMA.COLUMNS as ifsc ON (sc.is_computed = 1 or ifsc.DATA_TYPE = 'timestamp') AND sc.object_id = object_id(@param0+'.'+@param1) AND ifsc.TABLE_SCHEMA = @param0 AND ifsc.TABLE_NAME = @param1 AND ifsc.COLUMN_NAME = sc.name;
dbug: Azure.DataApiBuilder.Core.Services.ISqlMetadataProvider[0]
      Logging primary key information for entity: Todos.
dbug: Azure.DataApiBuilder.Core.Services.ISqlMetadataProvider[0]
      Primary key column name: Id
      Primary key mapped name: Id
      Type: Int32
      IsNullable: False
      IsAutoGenerated: True
info: Azure.DataApiBuilder.Service.Startup[0]
      Successfully completed runtime initialization.

Suppress DAB Logging at Command Line

dab start --LogLevel None

⭐⭐ This does not work as expected. None should result in ZERO logging. Not a char, except errors.

C:\Temp\dab-todo-test>dab start --LogLevel None
Information: Microsoft.DataApiBuilder 1.7.90
Information: Config not provided. Trying to get default config based on DAB_ENVIRONMENT...
Information: Environment variable DAB_ENVIRONMENT is (null)
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Information: Loaded config file: dab-config.json
Information: Setting minimum LogLevel: None.
Starting the runtime engine...
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Monitoring config: dab-config.json for hot-reloading.

Suppress DAB Logging in Configuration

    "telemetry": {
      "log-level": {
        "Default": "none"
      }
    },

This does not work at all. It prevents DAB from starting.

C:\Temp\dab-todo-test>dab start
Information: Microsoft.DataApiBuilder 1.7.90
Information: Config not provided. Trying to get default config based on DAB_ENVIRONMENT...
Information: Environment variable DAB_ENVIRONMENT is (null)
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Information: Loaded config file: dab-config.json
Information: Setting default minimum LogLevel: Debug for Development mode.
Starting the runtime engine...
Loading config file from C:\Temp\dab-todo-test\dab-config.json.
Monitoring config: dab-config.json for hot-reloading.
fail: Azure.DataApiBuilder.Service.Startup[0]
      Unable to complete runtime initialization. Refer to exception for error details.
      System.NotSupportedException: Log level filter Default needs to be of a valid log class.
         at Azure.DataApiBuilder.Core.Configurations.RuntimeConfigValidator.ValidateLoggerFilters(RuntimeConfig runtimeConfig) in /_/src/Core/Configurations/RuntimeConfigValidator.cs:line 155
         at Azure.DataApiBuilder.Core.Configurations.RuntimeConfigValidator.ValidateConfigProperties() in /_/src/Core/Configurations/RuntimeConfigValidator.cs:line 83
         at Azure.DataApiBuilder.Service.Startup.PerformOnConfigChangeAsync(IApplicationBuilder app) in /_/src/Service/Startup.cs:line 1046
fail: Azure.DataApiBuilder.Service.Startup[0]
      Could not initialize the engine with the runtime config file: dab-config.json
Unable to launch the Data API builder engine.
Error: Failed to start the engine.

[JerryNixon]

Workaround for configuration

Default -> default

I can resolve this in the docs, but in the case of default, it should be case-insensitive.

This fails

    "telemetry": {
      "log-level": {
        "Default": "none"
      }
    },

This works

    "telemetry": {
      "log-level": {
        "default": "none"
      }
    },

[JerryNixon]

The CLI logger's minimum level is not updated when --LogLevel is parsed. The CLI phase and the engine phase have independent loggers.

Research

When dab start --LogLevel None is used, CLI startup messages are still emitted. This is because the CLI logger (CustomConsoleLogger) has a hardcoded minimum log level of Information and writes messages before the engine's log level takes effect. And in ConfigGenerator.TryStartEngineWithOptions, multiple _logger.LogInformation(...) calls happen before the engine starts.

Suggestion

The --LogLevel option should be propagated to the CLI's CustomConsoleLogger as well. When LogLevel.None is specified, the CLI-phase messages (version info, config loading, etc.) should also be suppressed. This could be done by making the _minimumLogLevel in CustomConsoleLogger configurable, or by checking the StartOptions.LogLevel before emitting CLI messages.