sequencer: TX rollback error: sql: transaction has already been committed or rolled back

[rgdd]

Longer description here:
https://git.glasklar.is/sigsum/core/log-go/-/issues/98

Any hunches for why we're seeing TX rollback error and whether it should be ignored or not?

[rgdd]

From slack/matrix:

@mhutchinson: I think this is because Trillian always ensures that we close transactions in the most defensive way possible, and schedules a Rollback via defers every time one is opened. If the tx is committed then the rollback does nothing, except logs this warning.

---

We're currently on v1.6.1 (and still seeing this).

@mhutchinson: FWIW I think it is likely to still be happening based on my understanding, but would be best to confirm that before I look at making any changes

Next step: We'll let you know once we (probably) see it on v1.7.1

[mhutchinson]

The report on link in OP suggests that the same behaviour is happening on the latest tagged release. The report shows that this is happening in the admin code too, which I'm zooming into solving first as it has fewer logic branches than the tree storage.

feb 17 14:03:09 poc.sigsum.org trillian_log_server[38529]: E0217 14:00:55.856003   38529 admin_helpers.go:137] tx.Close(): sql: transaction has already been committed or rolled back

Relevant code:

• admin_helpers RunInAdminSnapshot
• mysql implementation

Looking at the code, I can see defence against attempting to close an already closed transaction in the form of the tx.closed boolean, which is set to true appropriately when Commit or Close are called on the transaction. When closing the transaction, it returns early if closed is true. The mutex locking this stuff seems appropriate.

I'll take another look at this code in the morning to see if I'm missing anything silly, but my money is on the tx being cancelled/closed outside of the Commit/Close operations we wrap it in. Most likely option is the context passed into the transaction construction is being cancelled before we attempt to Close normally. The docs for https://pkg.go.dev/database/sql#DB.BeginTx say that the tx will be rolled back in this case.

Thinking out loud, this looks like a credible explanation if the same context is being used for all of the calls in the error log below:

feb 17 14:03:09 poc.sigsum.org trillian_log_server[38529]: E0217 14:00:55.856003   38529 admin_helpers.go:137] tx.Close(): sql: transaction has already been committed or rolled back
feb 17 14:03:09 poc.sigsum.org trillian_log_signer[38473]: W0217 14:03:09.659492   38473 tree_storage.go:159] Could not start tree TX: context deadline exceeded
feb 17 14:03:09 poc.sigsum.org trillian_log_signer[38473]: E0217 14:03:09.659551   38473 operation_manager.go:428] ExecutePass(2911227427682708616) failed: failed to integrate batch for 2911227427682708616: context deadline exceeded

If the context timed out during the first call, then it would cancel the tx, causing that first error when the deferred Close tried to run. The second and third errors would then occur because the same (timed out) context was being passed into future work. I'm not sure what the higher level code is that is making these calls though. @rgdd thoughts?

Anyway, in all cases that I can see, the problem is only that we attempt to rollback a tx that is already rolled back. It's safe to ignore, though I'd still like to remove the spam if possible.

[rgdd]

Sorry for the slow response. You're analysis and PR looks good to me -- thanks for taking a stab at this! I'll ask that elias start running with version 0ebd9da on our poc log to start with.