Dapper support for v2.xx - SQL Parameters not in LogSensitiveData output anymore.

[JMan7777]

Hi,

I really like this project but since I upgraded to the newer dapper versions it does not show the SQL parameters anymore (LogSensitiveData is set to true).

Instead it shows e.g.:

Parameters:System.Collections.Generic.Dictionary2[System.String,System.Object], elapsed: 4 ms`

The SQL statement itself is shown correctly.

Could you please kindly update this package.

Thx a lot.

Regards,

Markus

[hryz]

Hey,

I'm going to resurrect the repo and package this weekend. Stay tuned 😉

[JMan7777]

Thx a million.

If you have some spare time, would it be possible to make a small extension as well.

I know I can configure the following messages in general during startup: OpenConnectionMessage CloseConnectionMessage ExecuteQueryMessage but I would like to modify them during runtime.,

Background on this is, that I have my own DBConnector wrapper with ID's for every connection. And I would like to have this ID in the messages.

It be very nice to have some kind of external callbacks called with the full string of: OpenConnectionMessage CloseConnectionMessage ExecuteQueryMessage during execution.

So basically the DBConnection provided by your factory has the possibility to add event handler/callbacks to it.

Thx again.

Cheers Markus

[hryz]

Hey @JMan7777,

Please check out the last commit. I've updated the package dependencies to the latest versions. Also, there was a major redesign of the implementation. Now it consists of 2 levels of API:

• generic low-level API that provides only hooks with no effect, and
• logging effect that uses hooks Both levels are publicly available for clients. Also, there is a middle ground: a logging effect with an option to pass the extra context. This version combines simplicity and agility.

PS: It took me a while to figure out why some messages were missing in Kibana. It turns out that it's a pretty bad idea to use {0}, {1} in the template instead of named arguments. When Serilog inserts the very first message into index elastic determines the field type. If the first parameter in the first log was a number it will try to parse all first parameters of all queries as numbers. If it fails the log messages will be lost. Thankfully, elastic spams about it in docker console about it.
Another thing to keep in mind while specifying a custom template is the special syntax of the complex type parameters {@paramName} without the @ sign it will call .ToString()

[JMan7777]

Hi @hryz,

Thx a million.

I just upgraded your package without any other changes but the query parameter output is still not correct:

2020-04-20 01:44:43.7297|Thread: 9||INFO|System.Data.Common.DbConnection|Dapper query:
2020-04-20T01:44:43.734557147Z "SELECT [test].[VIEW_User_Jobs_Updatable].[id] AS [ID], [test].[VIEW_User_Jobs_Updatable].[server] AS [ServerName], [test].[VIEW_User_Jobs_Updatable].[status] AS [Status], [test].[VIEW_User_Jobs_Updatable].[status_details] AS [StatusDetails], [test].[VIEW_User_Jobs_Updatable].[description] AS [Description], [test].[VIEW_User_Jobs_Updatable].[request_object] AS [RequestObject], [test].[VIEW_User_Jobs_Updatable].[request_object_type] AS [RequestObjectType], [test].[VIEW_User_Jobs_Updatable].[partition_country] AS [PartitionCountry], [test].[VIEW_User_Jobs_Updatable].[changed_at] AS [ChangedAt], [test].[VIEW_User_Jobs_Updatable].[changed_by] AS [ChangedBy], [test].[VIEW_User_Jobs_Updatable].[created_at] AS [CreatedAt], [test].[VIEW_User_Jobs_Updatable].[created_by] AS [CreatedBy], [test].[VIEW_User_Jobs_Updatable].[version] AS [Version] FROM [test].[VIEW_User_Jobs_Updatable] WHERE (([test].[VIEW_User_Jobs_Updatable].[status] = @Status_0))"
2020-04-20T01:44:43.734565146Z Parameters: "Status_0"="?", elapsed: 104 ms, context: "Dapper.Logging.ContextlessLoggingFactory+Empty" |url: |action: 

It shows "Status_0"="?" but actually instead of "?" I would expect the real value (smallint 1 to 9 in my case) .

In my startup.cs I just do:

 services.AddDbConnectionFactory(
                prv => new SqlConnection(dBConnectionString),
                options => new DbLoggingConfigurationBuilder()
                {
                    LogLevel = LogLevel.Debug,
                    LogSensitiveData = true //Show values of the query parameters
                }
                , ServiceLifetime.Singleton);

Thx for havinga look.

[hryz]

Hey @JMan7777,

I think I figured out what's the problem. Sorry for a confusing API, but the extension method that registers the Connection Factory uses an Action<T> not the Function<T, T>. That's why if you don't use the fluent syntax for setting the configuration properties but returning a new instance of builder instead it's lost and the default configuration is applied. https://github.com/hryz/Dapper.Logging/blob/master/src/Dapper.Logging/Extensions.cs#L26 Unfortunately, fixing this will break other people's code. On the bright side, the fix is a one-liner in your code.

[hryz]

Hey @JMan7777,

I fixed the confusing behavior of the configuration builders. Please update the Nuget package to v0.4. Also, I noticed that the behavior of Serilog differs from other loggers. Serilog support structured logging and it can extract properties from POCO objects if the parameter name starts with @. The default logger for some reason prints the props of anonymous objects, but not types ones.

[JMan7777]

Hi @hryz,

Thx again. Working now like a charm ;).

I would have one small special wish (if this is possible):

In my code I use the injected IDBConnectionFactory to create the DBConnection with enabled logging.

sQLConnection = DBConnectionFactory.CreateConnection();

Then in my special case I wrap around my own DBConnection implementation:

customSQLConnection = new CustomSQLConnection(sQLConnection);

This CustomSQLConnection has some more attributes I need for my project. One example is a unique GUID to identify all DB transactions in my log file.

Would it be possible to enhance the DBConnection object returned back from .CreateConnection() to have .e.g. an event handler which is called inside your code instead of direct logging your logging messages out. Basically if the event handler is set, don't log out direct by your framework but just pass the log message to the event handler instead.

Something like this:

sQLConnection = DBConnectionFactory.CreateConnection();
customSQLConnection = new CustomSQLConnection(sQLConnection, Logger);
sQLConnection.LoggingOverrideEvent += customSQLConnection.loggingDapperMessages;

In my CustomSQLConnection I would then put my own logging implementation by getting your log message from the EventArgs:

public void loggingOverrideEvent (object sender, EventArgs e)
{
     .....
}

Thx. As mentioned this would just be a wish but would also allow people to implement their own logging mechanism writing if they not use e.g.ILogger or if they have additional logging requirements.

Cheers

[hryz]

Hello @JMan7777,

You can do this now. If you just want to pass an extra piece of information to the log messages you can use the Connection factory parametrized by a context:

services.AddDbConnectionFactoryWithCtx<LoggingContext>(
                prv => new NpgsqlConnection(conStr), 
                options => options
                    .WithLogLevel(LogLevel.Information)
                    .WithSensitiveDataLogging() //show values of the query parameters                    
                ,ServiceLifetime.Scoped);

Then, while creating the connection it will capture the cotext:

var ctx = new LoggingContext
            {
                ConnectionId = Guid.NewGuid().ToString("N").Substring(0,8),
                UserId = "j.doe@gmail.com"
            };

            using (var db = _connectionFactory.CreateConnection(ctx))
            {
                 ...
            }

and it will include the conext in the log messages:

public void CommandExecuted(DbCommand command, T context, long elapsedMs) =>
            _logger.Log(
                _config.LogLevel, 
                _config.ExecuteQueryMessage, 
                command.CommandText,
                command.GetParameters(hideValues: !_config.LogSensitiveData),
                elapsedMs,
                context, //<-----
                _connectionProjector(command.Connection));

Alternatively, If you need just hooks without any predefined effect (let say, you're integrating Dapper with AppMetrics) you can use the low-level abstraction:

services.AddDbConnectionFactoryWithHooks<Context>(
                prv => new NpgsqlConnection(conStr)
                ,ServiceLifetime.Scoped);

Then, while creating a connection it will accept an instance of ISqlHooks<T> and it will call the appropriate method when something happened:

protected override DbDataReader ExecuteDbDataReader(CommandBehavior behavior)
        {
            var sw = Stopwatch.StartNew();
            var reader = _command.ExecuteReader(behavior);
            _hooks.CommandExecuted(this, _context, sw.ElapsedMilliseconds);
            return reader;
        }

[JMan7777]

Hi @hryz , Thx for the explanation.

I will give it a try tomorrow and then close the issue.

Cheers

[JMan7777]

Hi @hryz , I ended up using the AddDbConnectionFactoryWithHooks which worked best for my purposes.

It took me a while to figure out how to use it correctly. Maybe you can update the examples a little bit more to also include an example instance of ISqlHooks<T> ;)

Thx again.