jellyfish: Trillian signer reporting "TX rollback error" at startup
When the trillian signer on poc.so started after being updated to 1.6.0 it reported "TX rollback error" and restarted.
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: W1001 17:22:12.901733 2567176 log_storage.go:343] Failed to prepare dequeue select: context deadline exceeded
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: W1001 17:22:13.068565 2567176 tree_storage.go:379] TX rollback error: sql: transaction has already been committed or rolled back, stack:
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: goroutine 129619303 [running]:
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: runtime/debug.Stack()
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /usr/lib/go-1.22/src/runtime/debug/stack.go:24 +0x5e
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/storage/mysql.(*treeTX).rollbackInternal(0x20?)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/storage/mysql/tree_storage.go:379 +0x3e
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/storage/mysql.(*treeTX).Close(0x0?)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/storage/mysql/tree_storage.go:391 +0xae
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/storage/mysql.(*mySQLLogStorage).ReadWriteTransaction.func1()
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/storage/mysql/log_storage.go:233 +0x1d
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/storage/mysql.(*mySQLLogStorage).ReadWriteTransaction(0x0?, {0x1aad8a8, 0xc0005b8870}, 0x413d45?, 0xc0001bc380)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/storage/mysql/log_storage.go:238 +0x117
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/log.IntegrateBatch({0x1aad8a8, 0xc0005b8870}, 0xc0005dea20, 0x64, 0x0, 0x34630b8a000, {0x1aa41d8, 0x27baea0}, {0x1ab24c0, 0xc0004d2ff0}, ...)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/log/sequencer.go:283 +0x1c3
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/log.(*SequencerManager).ExecutePass(0xc0002682a0, {0x1aad950, 0xc00053c700}, 0x6cd8c7d67198db08, 0xc000124c60)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/log/sequencer_manager.go:62 +0x245
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/log.executePass({0x1aad950, 0xc00053c700}, 0xc000124c60, {0x1a8c8e0, 0xc0002682a0}, 0x6cd8c7d67198db08)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/log/operation_manager.go:443 +0xcb
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: github.com/google/trillian/log.executePassForAll.func1(0x6cd8c7d67198db08)
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/log/operation_manager.go:427 +0xb8
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: created by github.com/google/trillian/log.executePassForAll in goroutine 60
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: /var/sigsum/sigsum/go/pkg/mod/github.com/google/trillian@v1.5.2/log/operation_manager.go:424 +0x1f9
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: W1001 17:22:13.081252 2567176 tree_storage.go:393] Rollback error on Close(): sql: transaction has already been committed or rolled back
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:13.081266 2567176 log_storage.go:234] tx.Close(): sql: transaction has already been committed or rolled back
Oct 01 17:22:13 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:13.152099 2567176 operation_manager.go:428] ExecutePass(7843238474908490504) failed: failed to integrate batch for 7843238474908490504: 7843238474908490504: Sequence>
Oct 01 17:22:25 poc.sigsum.org systemd[1]: Stopping trillian-signer.service - "Trillian signer"...
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: W1001 17:22:25.681727 2567176 process.go:39] Signal received: terminated
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.684217 2567176 runner.go:144] 2911227427682708616: no longer the master!
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.684263 2567176 runner.go:119] 2911227427682708616: context canceled
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.684284 2567176 runner.go:144] 7843238474908490504: no longer the master!
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.684317 2567176 runner.go:119] 7843238474908490504: context canceled
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.684383 2567176 runner.go:144] 2155966655961518675: no longer the master!
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.684390 2567176 runner.go:144] 7125341355459897519: no longer the master!
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.695775 2567176 runner.go:119] 7125341355459897519: context canceled
Oct 01 17:22:25 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:25.696061 2567176 runner.go:119] 2155966655961518675: context canceled
Oct 01 17:22:30 poc.sigsum.org trillian_log_signer[2567176]: E1001 17:22:30.701396 2567176 main.go:128] DBClose(): bad connection
Oct 01 17:22:35 poc.sigsum.org systemd[1]: trillian-signer.service: Deactivated successfully.
Oct 01 17:22:35 poc.sigsum.org systemd[1]: Stopped trillian-signer.service - "Trillian signer".
Oct 01 17:22:35 poc.sigsum.org systemd[1]: trillian-signer.service: Consumed 18h 9min 11.059s CPU time.
Oct 01 17:22:35 poc.sigsum.org systemd[1]: Started trillian-signer.service - "Trillian signer".
Oct 01 17:22:35 poc.sigsum.org trillian_log_signer[3958093]: W1001 17:22:35.793917 3958093 main.go:147] **** Acting as master for all logs ****The corresponding log entries for the server:
Oct 01 17:22:20 poc.sigsum.org systemd[1]: Stopping trillian-server.service - "Trillian server"...
Oct 01 17:22:20 poc.sigsum.org trillian_log_server[2567234]: W1001 17:22:20.628391 2567234 process.go:39] Signal received: terminated
Oct 01 17:22:25 poc.sigsum.org trillian_log_server[2567234]: E1001 17:22:25.636761 2567234 main.go:128] DBClose(): bad connection
Oct 01 17:22:25 poc.sigsum.org systemd[1]: trillian-server.service: Deactivated successfully.
Oct 01 17:22:25 poc.sigsum.org systemd[1]: Stopped trillian-server.service - "Trillian server".
Oct 01 17:22:25 poc.sigsum.org systemd[1]: trillian-server.service: Consumed 4min 52.054s CPU time.
Oct 01 17:22:35 poc.sigsum.org systemd[1]: Started trillian-server.service - "Trillian server".
Oct 01 17:22:36 poc.sigsum.org trillian_log_server[3958095]: W1001 17:22:36.016736 3958095 process.go:39] Signal received: terminated
Oct 01 17:22:36 poc.sigsum.org systemd[1]: Stopping trillian-server.service - "Trillian server"...
Oct 01 17:22:41 poc.sigsum.org systemd[1]: trillian-server.service: Deactivated successfully.
Oct 01 17:22:41 poc.sigsum.org systemd[1]: Stopped trillian-server.service - "Trillian server".
Oct 01 17:22:41 poc.sigsum.org systemd[1]: Started trillian-server.service - "Trillian server".Edited by Linus Nordberg