Logging

Logging

Package utilizes extensive logging of its internal work to be able to pinpoint problems during application debugging.

Logging statements are emitted when Logging level is set to either Debug or Trace.

Imagine business operation doing two queries onto database.

When Debug level is used, business operation emits these log statements:

Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: Connection to Chinook opened in 3,334 ms (Hash: 12547953).
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: SQL statement executed in 3,13 ms.
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: SQL statement executed in 1,839 ms.
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: Connection closed (ReleaseConnection). (Hash: 12547953)

When logging level is set to Trace (extensive logging), these statements are getting into log:

Salix.Dapper.Cqrs.MsSql.SqlDatabaseSession: Trace: QueryFirstOrDefaultAsync<T>(SELECT ArtistId, Name FROM Artist WHERE ArtistId = @id) called with expected return of type Artist.
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Created new MS SQL connection with Hash: 12547953 to DBSERVER:Chinook
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Opening SQL connection (Hash: 12547953).
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Event: MS SQL Connection StateChange (Closed => Open)
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: Connection to Chinook opened in 3,334 ms (Hash: 12547953).
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Created new SQL transaction with Hash: 11429296 with Isolation level ReadCommitted onto connection 12547953.
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Attempting to execute SQL statement (ExecuteSql).
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: SQL statement executed in 3,13 ms.
Salix.Dapper.Cqrs.MsSql.SqlDatabaseSession: Trace: QueryAsync<T>(SELECT AlbumId, Arti… FROM Album WHERE ArtistId = @id) called with expected return of type IEnumerable<Album>.
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Attempting to execute SQL statement (ExecuteSql).
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: SQL statement executed in 1,839 ms.
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: SQL Transaction (Hash: 11429296) Commit in ReleaseConnection (business operation complete).
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Event: MS SQL Connection StateChange (Open => Closed)
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Debug: Connection closed (ReleaseConnection). (Hash: 12547953)
Salix.Dapper.Cqrs.MsSql.DatabaseContext: Trace: Event: MS SQL Connection got disposed

When lowest level - Trace is set, you can see whether database connection and transaction is the same for all database queries - see Hash value - it should stay the same for same object types.

Logging levels

A bit of off-topic for package... Just to remind what are these logging levels.

Logging systems can be configured to emit 6 levels of log statements.

1. Trace/Verbose
2. Debug
3. Information
4. Warning
5. Error
6. Critical/Fatal

.. or None.

When system is set to one of levels for logging, it emits log statements for this level and all levels below it, for example, if logging is set to "Information" (usually in production), then it emits logs for "Information", "Warning", "Error" and "Critical" levels. If set to "Trace" - all levels are getting logged.

Read more information in Microsoft Docs.

How to set logging level

For Microsoft.Extensions.Logging, it can be set in configuration file:

{
  "Logging": {
    "LogLevel": {
      "Default": "Information", //<-- This sets application level
      "Microsoft": "Warning",
      "Microsoft.Hosting.Lifetime": "Information"
    }
  }
}

or in code

ILoggerFactory loggerFactory = LoggerFactory.Create(builder => builder
        .AddFilter("Microsoft", LogLevel.Warning)
        .AddFilter("System", LogLevel.Warning)
        .AddFilter("MyApp", LogLevel.Trace)
        .AddDebug()
        .AddConsole());
ILogger<Program> _logger = loggerFactory.CreateLogger<Program>();

Besides Microsoft provided logger, there are many other logging system providers.

How emit log statements

These are code statements you use in code by referencing logger instance:

_logger.LogDebug("GET Pages.PrivacyModel called."); // Writes to log "Debug" message.

Statement above will appear in logs only if "Debug" or "Trace" levels are set in application to be used. Otherwise it will not appear in logs.