Operation has been cancelled for taking too long during task 'Confirm transaction'

[Leonardiae]

One error I see frequently on the APM is: 2020-08-19 07:41:33 pop-tasks- WARN MiningOperation - [vbtc0089040d] Failed: Operation has been cancelled for taking too long during task 'Confirm transaction'.

I believe in this case it's caused by a transaction being added to the network right before a new Veriblock block is found:

getoperationlogs vbtc0089040d debug
2020-08-19T06:41:33.905 DEBUG - New state: Initial
2020-08-19T06:41:33.905 INFO - Getting the mining instruction...
2020-08-19T06:41:33.920 DEBUG - New state: Mining Instruction retrieved
2020-08-19T06:41:33.920 INFO - Successfully retrieved the mining instruction!
2020-08-19T06:41:33.920 INFO - Submitting endorsement VBK transaction...
2020-08-19T06:41:33.936 DEBUG - New state: Endorsement Transaction submitted
2020-08-19T06:41:33.936 INFO - Successfully added the VBK transaction: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0!
2020-08-19T06:41:33.936 INFO - Waiting for the transaction to be included in VeriBlock block...
2020-08-19T07:41:33.950 WARN - Failed: Operation has been cancelled for taking too long during task 'Confirm transaction'.
2020-08-19T07:41:33.950 DEBUG - New state: Failed

Nodecore log shows:

2020-08-19 06:41:33.999+0200 INFO [nc-bus-thread-37] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.063+0200 INFO [nc-bus-thread-33] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.063+0200 INFO [nc-bus-thread-15] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.063+0200 INFO [nc-bus-thread-4] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.063+0200 INFO [nc-bus-thread-13] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.126+0200 INFO [nc-bus-thread-2] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.126+0200 INFO [nc-bus-thread-32] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:34.126+0200 INFO [nc-bus-thread-11] n.p2p.c [PeerEventListener.java:761] Found a transaction for the given transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0
2020-08-19 06:41:35.384+0200 INFO [nc-peer-table-1] n.p.PeerTable [PeerTable.java:344] Minimum peer threshold met!
2020-08-19 06:41:35.710+0200 INFO [nc-block-thread] n.e.a.q [Blockchain.java:539] New block: 000000007099B633A387C70798B0794BADFD9D225672F062 @ 785143

Here the complete operation log:

getoperation vbtc0089040d
Operation data:
{
  "operationId": "vbtc0089040d",
  "chain": "vBitcoin",
  "state": "Endorsement Transaction submitted",
  "blockHeight": 9065,
  "task": "Confirm Endorsement Transaction",
  "stateDetail": {
    "expectedRewardBlock": "9115",
    "chainIdentifier": "3860170",
    "publicationDataHeader": "00000820F2D4913FB947C9C175DC0A1F9B9578C30AAB51A2127BC2060723A4CD0000000018AD0159422A1846D316E236299373537F6AD8576424F1F515AD9BE698CE646ECFA93C5F954D031DBAFAD750",
    "publicationDataContextInfo": "000023699DC849CBF1A8B0A9910098CCE2F9A5EBDC3DDFD9C3E372298944483502000000D4EFD3AFB1685305E98AC32CC2AA3C6A003AC134B5D520EF100CB28000000000F10BA7722A9CCBEF4E3858F78193A4F81D0EE7315B9EC4B7ECD0FC0933CE409B",
    "publicationDataPayoutInfo": "0014D4B89850E2175B40F28A3977F89F4F77C9A72AE5",
    "vbkContextBlockHashes": "0000000051125F215A4C09D0708F2904F63E3ACF9A1F8EBA, 00000000739AFA0A1DA666C1503368DA6E5D44724C299CAF, 00000000522C7A8C10B46205F1350818CEAE065CE6EE7B4F, 0000000049478C9B0A17D8D14878C3E08B4556E04DC90827, 000000001B8C4BEF87B4B62CA89B88AFDBF89C6ED6974561, 000000000C926EAC2C778A801BB59790D9B8F84DFE75AF5C, 0000000000AF1658245DCF3A5F2876B04A4EFF4711C2BEF8, 00000000607705D7DF6E8D4588D64909CDAE1FEF073B76CF, 0000000070694AB56A9047ECF27F3FF14EFB29AB5E2B3BE8, 00000000281BD2D36997CFCA265B8A38FE292FE5D63795C1, 000000006C5947D550A27959F9B55F807B79B130DC1F3FCE, 000000000B4E1D4D47EB90A81F48B30BECCF9674ABEFFBF7, 0000000032AC7D02CF9C21F3016837AF9AB3FC31115B3D96, 00000000214D69882B58E81F9A686D427DC01F14F05C15A8, 000000001B34EA0926719E863F3EBCD6B5624DF183CA7260, 0000000042EF3C0F866879FE102E629017A5C568461A6BE6",
    "btcContextBlockHashes": "00000000BF0EC16A551727230A56BA5C37AAE9158114E6F906C1DF9655BF97ED, 0000000025BB0555DB0C29D9537ABED75F941C33EBF9D16D3DCD08251A960220, 00000000000000A3C060B7B50025D40F6685D4AA178A48815343082D93BC685A, 00000000000001057A14501681A06B5D4A9F164B5255A945F501588F8238836E, 000000000000004BA307FE391ABE937214DDBE1931287A81C853931EB2D3572F, 00000000000000A2D2A979BD84283660396D9522CD609B28006D64874F971185, 00000000CFDB55856E2FF8A90A32D4808A55C31FF0EAB713897D7AB1B80C1DCB, 0000000000000017692BE8874C24477EFDA23ED7C99D567A61DBC4446B33B9B2, 000000000000001D685F2B7E67620C93489091C488C7A3D41F91B0DE93F4D36B, 00000000000000A23592A37814568F3DD27E08CDB5F535B168979E6F5E031F13, 000000007A626C67E0420A2BF4F28088398FAA510EDDA4EC51B4845816E15C82, 000000000000005C08124A79013B1F43283A216A89E993D9FB69C5FB12CEFA77, 0000000000000049193060F91B7C7CB1F8D3B3745B6B9B58B614A6CEB1997FF6, 000000001192E019BC635E5E8B53B563105D91399F823F272DAC74FCC55A207A, 00000000000000F53A14A4C8A850441B1F47FB1E617A2A69E6B9E203C7F444CD, 000000006B45E8DCA4F9D91B01C2204A137820AAF02D19E2F3EB3A8309B8B5E7",
    "vbkEndorsementTxId": "CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0",
    "vbkEndorsementTxFee": "0.00564944",
    "failureReason": "Operation has been cancelled for taking too long during task \u0027Confirm transaction\u0027."
  }
}
Operation workflow:
DONE      1. START                           Created APM operation id: vbtc0089040d
DONE      2. RETRIEVE_MINING_INSTRUCTION     Endorsed vBitcoin block height: 9065
DONE      3. SUBMIT_ENDORSEMENT_TRANSACTION  tVBK endorsement transaction id: CF9072CA2902BDD8F91B7FBCE90AE68BFE226861E269E8147D5EC26608B6B0F0 (fee: 0.00564944)
FAILED    4. CONFIRM_ENDORSEMENT_TRANSACTION Operation has been cancelled for taking too long during task 'Confirm transaction'.
          5. DETERMINE_BLOCK_OF_PROOF
          6. PROVE_ENDORSEMENT_TRANSACTION
          7. WAIT_FOR_KEYSTONE_OF_PROOF
          8. GET_VBK_PUBLICATIONS
          9. SUBMIT_POP_TRANSACTION
         10. CONFIRM_ATV
         11. WAIT_FOR_PAYOUT_BLOCK
         11. COMPLETED

I have seen this behaviour many times in the past: Transactions which are added to the Veriblock network in the last few seconds before a block is found are removed from the mempool despit not making it into a block yet. In older versions of Nodecore there was a logline in the Nodecore log which mentioned that the mempool was cleared, my guess is that is whats causing this issue.

My expectation is that transactions that do no make it into a block stay in the mempool, so they can be added to the next block.

[Leonardiae]

One can see this phenomenon clearly when stress testing Nodecore and adding a transaction every (say) 250 milliseconds. You count how many transactions are created and how many make it into the next block. There is often a difference and this amounts to the transactions added in the last seconds before the new block is found.

In this case 120 transactions are created in 30 seconds. Say ~100 will make it into the next block.

[Warchant]

@Leonardiae Could you retest? Things should be much better with this in NodeCore.

[Leonardiae]

Still seeing these errors in my logs (also without stresstesting). Few times a day:

2021-12-31 12:34:04.805+0100 WARN [pop-tasks-9] org.veriblock.miners.pop.core.MiningOperation [OperationLogging.kt:61] [pexaca979cb2] Failed: Operation has been cancelled for taking too long during task 'Confirm transaction'
2021-12-31 12:34:04.825+0100 DEBUG [si-poll] org.veriblock.miners.pop.securityinheriting.SecurityInheritingMonitor [SecurityInheritingMonitor.kt:348] Found new PHL block: 000000101a86923990a619e1189c949d9a8eb1ba65a0ac0a7af9d994a9d9b979 @ 6043 with no VBK publications
2021-12-31 12:34:04.810+0100 WARN [pop-tasks-10] org.veriblock.miners.pop.core.MiningOperation [OperationLogging.kt:61] [phl4cddbb94] Failed: Error while trying to get PoP Mining Instruction from PHL
2021-12-31 12:34:04.825+0100 DEBUG [pop-tasks-9] org.veriblock.miners.pop.core.MiningOperation [OperationLogging.kt:59] [pexaca979cb2] Stack Trace:
kotlinx.coroutines.TimeoutCancellationException: Timed out waiting for 3600000 ms
    at kotlinx.coroutines.TimeoutKt.TimeoutCancellationException(Timeout.kt:186) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.TimeoutCoroutine.run(Timeout.kt:156) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.EventLoopImplBase$DelayedRunnableTask.run(EventLoop.common.kt:497) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.EventLoopImplBase.processNextEvent(EventLoop.common.kt:274) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.DefaultExecutor.run(DefaultExecutor.kt:69) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at java.lang.Thread.run(Unknown Source) [?:1.8.0_221]
2021-12-31 12:34:04.834+0100 DEBUG [pop-tasks-9] org.veriblock.miners.pop.core.MiningOperation [OperationLogging.kt:59] [pexaca979cb2] New state: Failed
2021-12-31 12:34:04.829+0100 DEBUG [pop-tasks-10] org.veriblock.miners.pop.core.MiningOperation [OperationLogging.kt:59] [phl4cddbb94] Stack Trace:
java.util.concurrent.CancellationException: Timed out waiting for 90000 ms
    at io.ktor.client.engine.UtilsKt$attachToUserJob$cleanupHandler$1.invoke(Utils.kt:78) ~[ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.engine.UtilsKt$attachToUserJob$cleanupHandler$1.invoke(Utils.kt) ~[ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at kotlinx.coroutines.JobSupport.invokeOnCompletion(JobSupport.kt:1559) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.Job$DefaultImpls.invokeOnCompletion$default(Job.kt:353) ~[kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at io.ktor.client.engine.HttpClientEngineJvmKt.createCallContext(HttpClientEngineJvm.kt:26) ~[ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.engine.HttpClientEngine$DefaultImpls.executeWithinCallContext(HttpClientEngine.kt:77) ~[ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.engine.HttpClientEngine$install$1.invokeSuspend(HttpClientEngine.kt:66) ~[ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.engine.HttpClientEngine$install$1.invoke(HttpClientEngine.kt) ~[ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.loop(PipelineContext.kt:323) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.proceed(PipelineContext.kt:168) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.execute(PipelineContext.kt:188) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.Pipeline.execute(Pipeline.kt:31) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpSend$DefaultSender.execute(HttpSend.kt:124) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpSend$Feature$install$1.invokeSuspend(HttpSend.kt:88) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpSend$Feature$install$1.invoke(HttpSend.kt) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.loop(PipelineContext.kt:323) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.proceed(PipelineContext.kt:168) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.proceedWith(PipelineContext.kt:178) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpPlainText$Feature$install$1.invokeSuspend(HttpPlainText.kt:138) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpPlainText$Feature$install$1.invoke(HttpPlainText.kt) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.loop(PipelineContext.kt:323) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.proceed(PipelineContext.kt:168) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpRequestLifecycle$Feature$install$1.invokeSuspend(HttpRequestLifecycle.kt:37) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.features.HttpRequestLifecycle$Feature$install$1.invoke(HttpRequestLifecycle.kt) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.loop(PipelineContext.kt:323) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.proceed(PipelineContext.kt:168) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.SuspendFunctionGun.execute(PipelineContext.kt:188) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.util.pipeline.Pipeline.execute(Pipeline.kt:31) [ktor-utils-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.HttpClient.execute(HttpClient.kt:185) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at io.ktor.client.statement.HttpStatement.executeUnsafe(HttpStatement.kt:104) [ktor-client-core-jvm-1.4.0.jar:1.4.0]
    at org.veriblock.alt.plugins.bitcoin.BitcoinFamilyChain.getMiningInstruction(BitcoinFamilyChain.kt:951) [altchain-plugins-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.ApmTaskService$runTasksInternal$2.invokeSuspend(ApmTaskService.kt:58) [altchain-pop-miner-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.ApmTaskService$runTasksInternal$2.invoke(ApmTaskService.kt) [altchain-pop-miner-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.TaskService$runTask$2.invokeSuspend(TaskService.kt:64) [pop-miners-common-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.TaskService$runTask$2.invoke(TaskService.kt) [pop-miners-common-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at kotlinx.coroutines.intrinsics.UndispatchedKt.startUndispatchedOrReturnIgnoreTimeout(Undispatched.kt:102) [kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.TimeoutKt.setupTimeout(Timeout.kt:148) [kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.TimeoutKt.withTimeout(Timeout.kt:44) [kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at kotlinx.coroutines.time.TimeKt.withTimeout(Time.kt:45) [kotlinx-coroutines-jdk8-1.4.1.jar:?]
    at org.veriblock.miners.pop.service.TaskService.runTask(TaskService.kt:63) [pop-miners-common-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.ApmTaskService.runTasksInternal(ApmTaskService.kt:49) [altchain-pop-miner-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.ApmTaskService.runTasksInternal(ApmTaskService.kt:41) [altchain-pop-miner-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.TaskService.runTasks(TaskService.kt:30) [pop-miners-common-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at org.veriblock.miners.pop.service.AltchainPopMinerService$submit$1.invokeSuspend(AltchainPopMinerService.kt:328) [altchain-pop-miner-0.4.12-dev.10.uncommitted.jar:0.4.12-dev.10.uncommitted]
    at kotlin.coroutines.jvm.internal.BaseContinuationImpl.resumeWith(ContinuationImpl.kt:33) [kotlin-stdlib-1.4.10.jar:1.4.10-release-411 (1.4.10)]
    at kotlinx.coroutines.DispatchedTask.run(DispatchedTask.kt:106) [kotlinx-coroutines-core-jvm-1.4.1.jar:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:1.8.0_221]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:1.8.0_221]
    at java.lang.Thread.run(Unknown Source) [?:1.8.0_221]
2021-12-31 12:34:04.834+0100 DEBUG [pop-tasks-10] org.veriblock.miners.pop.core.MiningOperation [OperationLogging.kt:59] [phl4cddbb94] New state: Failed

[Mr-Leshiy]

Nodecore related, closed