Panic Caused Following SQL Transaction Rollback

[onelapahead]

I was creating two token pools programmatically and seemed to have caused a SQL transaction rollback that caused a panic / crash. I was only able to get the following logs:

{"@timestamp":"2022-11-04T18:19:16.993Z","breq":"_LpGVpJt","level":"debug","message":"\u003c== POST http://firefly-erc1155:3000/api/v1/activatepool [204] (127.76ms)","pid":"1","proto":"fftokens"}
{"@timestamp":"2022-11-04T18:19:16.993Z","level":"debug","message":"fftokens updating operation default:d3a4c134-2614-4ace-9aab-4e758dd21bfa status=Succeeded","ns":"default","pid":"1"}
{"@timestamp":"2022-11-04T18:19:16.993Z","level":"debug","message":"Submitting operation update id=d3a4c134-2614-4ace-9aab-4e758dd21bfa status=Succeeded blockchainTX= worker=opu_003","ns":"default","pid":"1"}
{"@timestamp":"2022-11-04T18:19:16.993Z","dbtx":"sZW9aNhb","level":"debug","message":"SQL-\u003e begin","ns":"default","pid":"1","role":"aggregator"}
{"@timestamp":"2022-11-04T18:19:16.994Z","dbtx":"sZW9aNhb","level":"debug","message":"SQL\u003c- begin","ns":"default","pid":"1","role":"aggregator"}
{"@timestamp":"2022-11-04T18:19:16.994Z","dbtx":"sZW9aNhb","level":"debug","message":"SQL-\u003e commit","ns":"default","pid":"1","role":"aggregator"}
{"@timestamp":"2022-11-04T18:19:16.994Z","dbtx":"sZW9aNhb","level":"debug","message":"SQL\u003c- commit","ns":"default","pid":"1","role":"aggregator"}
{"@timestamp":"2022-11-04T18:19:16.999Z","breq":"XpTkerjB","level":"debug","message":"\u003c== POST http://firefly-erc1155:3000/api/v1/createpool [202] (33.84ms)","pid":"1","proto":"fftokens"}
{"@timestamp":"2022-11-04T18:19:17.035Z","level":"info","message":"Received operation update: status=Pending request=default:e67f31db-bc13-4630-9160-901d10604d37 tx=0xf276c932635b2957fcf6b9c066da6e29a0940213d77f57afc06b206b61110a8c message=","pid":"1","proto":"ethereum","role":"event-loop"}
{"@timestamp":"2022-11-04T18:19:17.035Z","level":"debug","message":"ethereum updating operation default:e67f31db-bc13-4630-9160-901d10604d37 status=Pending","ns":"default","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.035Z","level":"debug","message":"Submitting operation update id=e67f31db-bc13-4630-9160-901d10604d37 status=Pending blockchainTX=0xf276c932635b2957fcf6b9c066da6e29a0940213d77f57afc06b206b61110a8c worker=opu_003","ns":"default","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.036Z","level":"debug","message":"Received receipt event ","pid":"1","proto":"fftokens","role":"event-loop"}
{"@timestamp":"2022-11-04T18:19:17.036Z","level":"info","message":"Received operation update: status=Pending request=default:e67f31db-bc13-4630-9160-901d10604d37 message=","pid":"1","proto":"fftokens","role":"event-loop"}
{"@timestamp":"2022-11-04T18:19:17.036Z","level":"debug","message":"fftokens updating operation default:e67f31db-bc13-4630-9160-901d10604d37 status=Pending","ns":"default","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.036Z","level":"debug","message":"Submitting operation update id=e67f31db-bc13-4630-9160-901d10604d37 status=Pending blockchainTX=0xf276c932635b2957fcf6b9c066da6e29a0940213d77f57afc06b206b61110a8c worker=opu_003","ns":"default","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.043Z","dbtx":"Et74dU4o","level":"debug","message":"SQL-\u003e begin","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.044Z","dbtx":"Et74dU4o","level":"debug","message":"SQL\u003c- begin","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.044Z","dbtx":"Et74dU4o","level":"debug","message":"SQL-\u003e query transactions","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.046Z","dbtx":"Et74dU4o","level":"debug","message":"SQL\u003c- query transactions","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.046Z","dbtx":"Et74dU4o","level":"debug","message":"Transaction '9475c06d-4c69-4097-b1d7-5550e98df40d' not found","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.046Z","dbtx":"Et74dU4o","level":"debug","message":"SQL-\u003e update operations","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.048Z","dbtx":"Et74dU4o","level":"debug","message":"SQL\u003c- update operations affected=1","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.048Z","dbtx":"Et74dU4o","level":"debug","message":"Operation update 'default:e67f31db-bc13-4630-9160-901d10604d37' from 'ethereum' ignored, as it does not match operation source 'fftokens'","ns":"default","opupdater":"opu_003","pid":"1"}
{"@timestamp":"2022-11-04T18:19:17.048Z","dbtx":"Et74dU4o","level":"warning","message":"SQL! transaction rollback","ns":"default","opupdater":"opu_003","pid":"1"}
panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0xa2fa5b]

goroutine 127 [running]:
github.com/hyperledger/firefly/internal/operations.(*operationUpdater).doUpdate(0xc000126280, {0x1044018, 0xc00095b710}, 0xc000561830, {0xc000773500, 0x3, 0x0}, {0xc000ae0220, 0x3, 0x4})
	/firefly/internal/operations/operation_updater.go:265 +0x55b
github.com/hyperledger/firefly/internal/operations.(*operationUpdater).doBatchUpdate(0xc000126280, {0x1044018, 0xc00095b710}, {0xc000ae01c0, 0x3, 0x0})
	/firefly/internal/operations/operation_updater.go:228 +0x476
github.com/hyperledger/firefly/internal/operations.(*operationUpdater).doBatchUpdateWithRetry.func1.1({0x1044018, 0xc00095b710})
	/firefly/internal/operations/operation_updater.go:180 +0x3c
github.com/hyperledger/firefly/internal/database/sqlcommon.(*SQLCommon).RunAsGroup(0xc000148460, {0x1044018, 0xc00055a030}, 0xc00095b5f0)
	/firefly/internal/database/sqlcommon/sqlcommon.go:159 +0x109
github.com/hyperledger/firefly/internal/operations.(*operationUpdater).doBatchUpdateWithRetry.func1(0x45244f)
	/firefly/internal/operations/operation_updater.go:179 +0xdc
github.com/hyperledger/firefly-common/pkg/retry.(*Retry).Do(0xc000194d80, {0x1044018, 0xc00055a030}, {0xee919c, 0x10}, 0xc00099be68)
	/go/pkg/mod/github.com/hyperledger/[email protected]/pkg/retry/retry.go:56 +0xe4
github.com/hyperledger/firefly/internal/operations.(*operationUpdater).doBatchUpdateWithRetry(0xc00099bf88, {0x1044018, 0xc00055a030}, {0xc000ae01c0, 0xc00033b0c9, 0x1})
	/firefly/internal/operations/operation_updater.go:178 +0x9b
github.com/hyperledger/firefly/internal/operations.(*operationUpdater).updaterLoop(0xc000126280, 0x1c)
	/firefly/internal/operations/operation_updater.go:167 +0x37c
created by github.com/hyperledger/firefly/internal/operations.(*operationUpdater).start
	/firefly/internal/operations/operation_updater.go:134 +0x186

This was using a fork of the ERC1155 connector (based on v1.1.x), and a Postgres database backend. Good news is, once the FireFly node recovered it had still replayed the receipts and events from creating the pool such that it seems to have been made it successfully. So while this wasn't a show stopper, would be good to determine how the invalid memory reference occurred and prevent the panic in the first place.

[awrichar]

It's technically possible for transaction to be nil here:

https://github.com/hyperledger/firefly/blob/9ffba93f85153128288274b91a58abd44f8e9a86/internal/operations/operation_updater.go#L218-L221

and therefore for candidate to be nil here:

https://github.com/hyperledger/firefly/blob/9ffba93f85153128288274b91a58abd44f8e9a86/internal/operations/operation_updater.go#L265

I really don't think it should be possible to have an operation exist and a transaction not exist, but...?