Integration test failed - replacement transaction underpriced

[awrichar]

Failed in integration run 315 (TestEthereumMultipartyE2ESuite, besu, sqlite3)

https://github.com/hyperledger/firefly/runs/7986304780?check_suite_focus=true

    restclient.go:109: 2022-08-24T02:10:24.238500576Z: ==> POST /namespaces/default/datatypes map[confirm:[true]]: {"validator":"","name":"widget","version":"0.0.75364048","value":{"$id":"https://example.com/widget.schema.json","$schema":"https://json-schema.org/draft/2020-12/schema","title":"Widget","type":"object","properties":{"id":{"type":"string","description":"The unique identifier for the widget."},"name":{"type":"string","description":"The person's last name."}},"additionalProperties":false}}
    restclient.go:116: 2022-08-24T02:12:24.24110887Z: <== 408
    restclient.go:118: <!! {"error":"FF10260: The request with id '55bde12d-2884-49e9-85fe-c5f5df225472' timed out after 120,000.61ms"}
    restclient.go:119: Headers: map[Content-Length:[109] Content-Type:[application/json] Date:[Wed, 24 Aug 2022 02:12:24 GMT] Vary:[Origin]]
    restclient.go:546: 
        	Error Trace:	/home/runner/work/firefly/firefly/test/e2e/runners/restclient.go:546
        	            				/home/runner/work/firefly/firefly/test/e2e/runners/onchain_offchain.go:178
        	Error:      	Not equal: 
        	            	expected: 200
        	            	actual  : 408
        	Test:       	TestEthereumMultipartyE2ESuite/TestStrongDatatypesPrivate
        	Messages:   	POST /namespaces/default/datatypes [408]: {"error":"FF10260: The request with id '55bde12d-2884-49e9-85fe-c5f5df225472' timed out after 120,000.61ms"}

Message ID: 55bde12d-2884-49e9-85fe-c5f5df225472
Batch ID: 3a07b88d-b459-4bcb-b9ed-2a1851e4ec58
Batch Pin Operation ID: 9d1fb088-7fa7-4afd-b5f9-84296016fa1f

�[33;1mfirefly_core_0_1  |�[0m [2022-08-24T02:10:25.274Z]  INFO Executing blockchain_pin_batch operation 9d1fb088-7fa7-4afd-b5f9-84296016fa1f via handler MultipartyManager d=pinned_broadcast ns=default opcache=6w4jw1re p=did:firefly:org/org_0| pid=1 role=batchmgr
�[33;1mfirefly_core_0_1  |�[0m [2022-08-24T02:10:25.299Z]  INFO Received operation update: status=Failed request=default:9d1fb088-7fa7-4afd-b5f9-84296016fa1f tx= message=Replacement transaction underpriced pid=1 proto=ethereum role=event-loop
�[33;1mfirefly_core_0_1  |�[0m [2022-08-24T02:10:25.299Z] DEBUG ethereum updating operation default:9d1fb088-7fa7-4afd-b5f9-84296016fa1f status=Failed error=Replacement transaction underpriced ns=default pid=1

[awrichar]

container-logs-TestEthereumMultipartyE2ESuite-besu-sqlite3.zip

[awrichar]

Notably there was this batch-pin (08d10d4d-77a3-4537-9385-236477b61e4e) from an earlier test step which ended up being submitted almost concurrently and then succeeded a few seconds later:

�[33;1mfirefly_core_0_1  |�[0m [2022-08-24T02:10:25.264Z]  INFO Executing blockchain_pin_batch operation 08d10d4d-77a3-4537-9385-236477b61e4e via handler MultipartyManager d=pinned_private ns=default opcache=Sfy5Hh5a p=did:firefly:org/org_0|ba89a603401f814615991d6092fe458f189140b... pid=1 role=batchmgr
�[33;1mfirefly_core_0_1  |�[0m [2022-08-24T02:10:28.270Z]  INFO Received operation update: status=Succeeded request=default:08d10d4d-77a3-4537-9385-236477b61e4e tx=0xc07033ea94dc8a2fd8c9aad9043cecfa8fb62a4d21b1b066a4fd83e74f5a98f1 message= pid=1 proto=ethereum role=event-loop

[awrichar]

From ethconnect on 9d1fb088-7fa7-4afd-b5f9-84296016fa1f:

�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.277Z]  INFO Webhook accepted message. MsgID: default:9d1fb088-7fa7-4afd-b5f9-84296016fa1f Type: SendTransaction
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.277Z] DEBUG --> OnMessage default:9d1fb088-7fa7-4afd-b5f9-84296016fa1f
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.277Z]  INFO In-flight 1000011 added. nonce=0 addr=0x77bb76c561f0a43c1de24a8ce0e65790dc28bb2e before=1 (node=false)
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.298Z]  INFO In-flight 1000011 complete. nonce=0 addr=0x77bb76c561f0a43c1de24a8ce0e65790dc28bb2e nan=true sub=false before=2 after=1 highest=0
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.298Z]  WARN Failed to process message MsgContext[SendTransaction/default:9d1fb088-7fa7-4afd-b5f9-84296016fa1f]: Replacement transaction underpriced
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.298Z]  INFO Received reply message. requestId='default:9d1fb088-7fa7-4afd-b5f9-84296016fa1f' reqOffset='' type='Error': Replacement transaction underpriced

On 08d10d4d-77a3-4537-9385-236477b61e4e:

�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.267Z]  INFO Webhook accepted message. MsgID: default:08d10d4d-77a3-4537-9385-236477b61e4e Type: SendTransaction
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.267Z] DEBUG --> OnMessage default:08d10d4d-77a3-4537-9385-236477b61e4e
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:25.267Z]  INFO In-flight 1000010 added. nonce=0 addr=0x77bb76c561f0a43c1de24a8ce0e65790dc28bb2e before=0 (node=false)
�[35methconnect_0_1    |�[0m [2022-08-24T02:10:28.270Z]  INFO Received reply message. requestId='default:08d10d4d-77a3-4537-9385-236477b61e4e' reqOffset='' type='TransactionSuccess': 0xc07033ea94dc8a2fd8c9aad9043cecfa8fb62a4d21b1b066a4fd83e74f5a98f1

[awrichar]

As a side note, this highlights the fact that a failed batch pin operation does not bubble up an error to any messages being tracked by the sync-async handler (ie it will just time out). This is somewhat expected since the operation -> batch -> message mapping is a few levels of indirection, but it's one of those things that could stand to be enhanced if possible.