search

hyperledger / firefly

Hyperledger FireFly is the first open source Supernode: a complete stack for enterprises to build and scale secure Web3 applications. The FireFly API for digital assets, data flows, and blockchain transactions makes it radically faster to build production-ready apps on popular chains and protocols.
https://hyperledger.github.io/firefly
Apache License 2.0
498 stars 204 forks source link

Panic Caused Following SQL Transaction Rollback #1093

Open onelapahead opened 1 year ago

onelapahead commented 1 year ago

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/firefly-common@v1.1.1/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 commented 1 year ago

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...?