Add logging for transaction start, commit, roll back

[yang-xiaodong]

Request to classify logs. Each category can be distinguished by Logger Name.

For example, the transaction log cannot currently be directly viewed such as transaction commit, transaction rollback, etc.

Refer:

https://github.com/npgsql/npgsql/blob/main/src/Npgsql/NpgsqlLoggingConfiguration.cs#L21

[bgrainger]

There are different logger names:

MySqlConnector/src/MySqlConnector/Logging/MySqlConnectorLoggingConfiguration.cs

Lines 8 to 12 in ab05700

	public ILogger DataSourceLogger { get; } = loggerFactory.CreateLogger("MySqlConnector.MySqlDataSource");
	public ILogger ConnectionLogger { get; } = loggerFactory.CreateLogger("MySqlConnector.MySqlConnection");
	public ILogger CommandLogger { get; } = loggerFactory.CreateLogger("MySqlConnector.MySqlCommand");
	public ILogger PoolLogger { get; } = loggerFactory.CreateLogger("MySqlConnector.ConnectionPool");
	public ILogger BulkCopyLogger { get; } = loggerFactory.CreateLogger("MySqlConnector.MySqlBulkCopy");

Are you asking for specific logger messages to change categories? Which messages?

[yang-xiaodong]

Hi @bgrainger

Thanks for your quick reply, please allow me to share my detailed views.

• Create a new logger named "TransactionLogger" to differentiate it from the Command's Logger.
• The log level for TransactionLogger should be Debug instead of Trace to align with Npgsql.
• Change the current logging descriptions for transactions from:

Session 1.1 preparing command payload for: start transaction;
Session 1.1 preparing command payload for: commit
Session 1.1 preparing command payload for: rollback
To:
Session 1.1 Starting transaction
Session 1.1 Committed transaction
Session 1.1 Rolling back transaction
Session 1.1 Rolled back transaction

[bgrainger]

Those existing logs won't change because that's in common code. Reclassifying this as a feature request for new Info-level logging.

[bgrainger]

Just to make sure I'm understanding the purpose correctly, what's the use case for this new logging?

[yang-xiaodong]

I'm not sure if you still remember the support for DiagnosticSource I proposed a few years ago (Issue #471), but after final discussions, it ended up supporting OpenTelemetry, actually using the Activity implementation internally. However, one drawback of Activity compared to DiagnosticSource is that it can't be monitored through DiagnosticObserver.

I am the author of the CAP project. In CAP, there is a use case for the outbox pattern, which needs to be integrated with transactions. As a library integrated with other third-party ORMs, I can't know when transactions are committed. Thus, I need the ORM to hand over the transaction object to CAP for committing. The current code is as follows:

using (var connection = new MySqlConnection(ConnectionString))
{
    using (var capTrans = connection.BeginTransaction(_capBus, autoCommit: false))
    {
        //business logic code

        _capBus.Publish("xxx.services.show.time", DateTime.Now);

        capTrans.Commit();                
    }
}

After committing the transaction, CAP flushes the messages to the Broker, this API looks not very good, right?

I hope to simplify this process's API, meaning I want to find a way to know when the transaction is committed without actively creating a CAP transaction to wrap the database transaction.

In SQL Server, I can do this through DiagnosticObserver because it supports DiagnosticSource.

In Npgsql and MySqlConnector, I thought of a new method, which is to inject a custom logger to capture the transaction commit logs and then flush the messages to the Broker.

The final API might look something like this:

using (var connection = new MySqlConnection(ConnectionString))
{
    using (var dbTransaction = connection.BeginTransaction())
    {
        //your business logic code

        _capBus.Publish(transaction,"xxx.services.show.time", DateTime.Now);  // I just need transaction 

       dbTransaction.Commit();
    }
}

That's my case, what do you think?

[bgrainger]

This seems very brittle to me. I would never consider emitted log messages to be part of the "public API", meaning that they could be removed, reworded, change severity, etc. in a patch release. Depending on the exact category and message of a log message (to implement critical behaviour) feels very risky.

After committing the transaction, CAP flushes the messages to the Broker, this API looks not very good, right?

It looks fine to me (and virtually the same as "The final API might look something like this"), so I'm not sure what I'm missing. (Admittedly, I'm not familiar with the CAP library so I might be overlooking some obvious detail.)

[yang-xiaodong]

I know that using logs is not a good way and as you said it might change at any time, but in reality, the likelihood of this change happening for transactions logs maybe very small.

If I add the code for sending transactions, you should be able to see the difference. The former is an extension method that creates a CAPTransaction object, while the latter uses the IDbTransaction object.

using (var connection = new MySqlConnection(ConnectionString))
{
    using (var capTrans = connection.BeginTransaction(_capBus, autoCommit: false))
    {
        connection.Execute("insert into test(name) values('test')", transaction: (IDbTransaction)capTrans.DbTransaction);

        _capBus.Publish("xxx.services.show.time", DateTime.Now);

        capTrans.Commit();                
    }
}

VS

using (var connection = new MySqlConnection(ConnectionString))
{
    using (var transaction = connection.BeginTransaction())
    {
        connection.Execute("insert into test(name) values('test')", transaction: transaction);

        _capBus.Publish(transaction, "xxx.services.show.time", DateTime.Now);

        transaction.Commit();                
    }
}

Overall, thank you for your reply, it made me think again.

[bgrainger]

Planning to add Debug messages for "Starting", "Committed", "Rolled Back" (to match npgsql), as well as Trace messages for "Started", "Committing", "Rolling Back".

[bgrainger]

Fixed in 2.3.6.