Veriblock PoP Miner is allowed to start two operations at about the same time

[Leonardiae]

When a PoP operation is started it checks if another operation is already running by trying to aquire a lock. It turns out that this is not always the best solution. Maybe it's possible to add a check like this (https://github.com/VeriBlock/nodecore/commit/5ddc43126f9e3765c8502355db61caefc4057f1e) when starting a new operation.

Below you find a part of nodecore-pop logging (with some extra logging I added). Operation 84d402a2 is started at 16:53:18.790. Operation 0a7947d5 is started at 16:53:19.798. It tries to acquire a lock which is succesfull because the previous transaction is released soon after this operation is started. I think it's better to wait until the broadcasting of the previous operation has been finished (successfully of failed) before a new operation is allowed to start. I believe this is function CreateBitcoinTransactionTask.

2020-03-08 16:53:18.790+0100 INFO [pop-tasks-41] n.m.p.c.PoPMiningOperationState [PoPMiningOperationState.java:320] Start new mining operation ID: 84d402a2
2020-03-08 16:53:18.794+0100 INFO [pop-tasks-41] n.m.p.s.PoPStateService [PoPStateService.java:80] onPoPMiningOperationStateChanged called in PoPStateService
2020-03-08 16:53:18.796+0100 INFO [pop-tasks-41] n.m.p.s.PoPStateService [PoPStateService.java:106] serialize called in PoPStateService
2020-03-08 16:53:18.822+0100 INFO [pop-tasks-41] n.m.p.s.PoPStateService [PoPStateService.java:80] onPoPMiningOperationStateChanged called in PoPStateService
2020-03-08 16:53:18.824+0100 INFO [pop-tasks-41] n.m.p.s.PoPStateService [PoPStateService.java:106] serialize called in PoPStateService
2020-03-08 16:53:18.829+0100 INFO [pop-tasks-41] n.m.p.s.BitcoinService [BitcoinService.java:591] Waiting to acquire lock to create transaction
2020-03-08 16:53:18.830+0100 INFO [pop-tasks-41] n.m.p.s.BitcoinService [BitcoinService.java:601] Acquired lock to create transaction
2020-03-08 16:53:18.840+0100 INFO [pop-tasks-41] n.m.p.s.BitcoinService [BitcoinService.java:555] Created transaction spending 1 inputs:
2020-03-08 16:53:18.841+0100 INFO [pop-tasks-41] n.m.p.s.BitcoinService [BitcoinService.java:557]   x:0
2020-03-08 16:53:18.844+0100 INFO [pop-tasks-41] n.m.p.s.BitcoinService [BitcoinService.java:568] Broadcasting tx TransactionIDChanged to peer group
2020-03-08 16:53:18.849+0100 INFO [pop-tasks-41] n.m.p.s.BitcoinService [BitcoinService.java:585] Awaiting confirmation of broadcast of Tx TransactionIDChanged
2020-03-08 16:53:19.794+0100 INFO [nc-poll] n.m.p.s.BitcoinService [BitcoinService.java:250] Wallet.BalanceType.AVAILABLE_SPENDABLE: 173595
2020-03-08 16:53:19.795+0100 INFO [nc-poll] n.m.p.s.BitcoinService [BitcoinService.java:251] Wallet.BalanceType.AVAILABLE: 173595
2020-03-08 16:53:19.795+0100 INFO [nc-poll] n.m.p.s.BitcoinService [BitcoinService.java:252] Wallet.BalanceType.ESTIMATED: 173595
2020-03-08 16:53:19.797+0100 INFO [nc-poll] n.m.p.s.BitcoinService [BitcoinService.java:253] Wallet.BalanceType.ESTIMATED_SPENDABLE: 173595
2020-03-08 16:53:19.798+0100 INFO [pop-tasks-42] n.m.p.c.PoPMiningOperationState [PoPMiningOperationState.java:320] Start new mining operation ID: 0a7947d5
2020-03-08 16:53:19.799+0100 INFO [pop-tasks-42] n.m.p.s.PoPStateService [PoPStateService.java:80] onPoPMiningOperationStateChanged called in PoPStateService
2020-03-08 16:53:19.800+0100 INFO [pop-tasks-42] n.m.p.s.PoPStateService [PoPStateService.java:106] serialize called in PoPStateService
2020-03-08 16:53:19.806+0100 INFO [pop-tasks-42] n.m.p.s.PoPStateService [PoPStateService.java:80] onPoPMiningOperationStateChanged called in PoPStateService
2020-03-08 16:53:19.807+0100 INFO [pop-tasks-42] n.m.p.s.PoPStateService [PoPStateService.java:106] serialize called in PoPStateService
2020-03-08 16:53:19.811+0100 INFO [pop-tasks-42] n.m.p.s.BitcoinService [BitcoinService.java:591] Waiting to acquire lock to create transaction
2020-03-08 16:53:20.905+0100 INFO [ForkJoinPool.commonPool-worker-25] n.m.p.s.PopShell [PopShell.kt:96] Received pending tx 'TransactionIDChanged', pending balance: '0.00173391 BTC'
2020-03-08 16:53:21.636+0100 INFO [pop-tasks-44] n.m.p.c.BaseTask [CreateBitcoinTransactionTask.java:59] Successfully broadcast transaction TransactionIDChanged
2020-03-08 16:53:21.636+0100 INFO [pop-tasks-43] n.m.p.s.BitcoinService [BitcoinService.java:605] Releasing create transaction lock
2020-03-08 16:53:21.638+0100 INFO [pop-tasks-44] n.m.p.c.PoPMiningOperationState [PoPMiningOperationState.java:91] TxID: TransactionIDChanged
2020-03-08 16:53:21.638+0100 INFO [pop-tasks-42] n.m.p.s.BitcoinService [BitcoinService.java:601] Acquired lock to create transaction
2020-03-08 16:53:21.639+0100 INFO [pop-tasks-44] n.m.p.c.PoPMiningOperationState [PoPMiningOperationState.java:92] Operation ID: 84d402a2
2020-03-08 16:53:21.640+0100 INFO [pop-tasks-44] n.m.p.s.PoPStateService [PoPStateService.java:80] onPoPMiningOperationStateChanged called in PoPStateService
2020-03-08 16:53:21.640+0100 INFO [pop-tasks-44] n.m.p.s.PoPStateService [PoPStateService.java:106] serialize called in PoPStateService
2020-03-08 16:53:21.735+0100 INFO [pop-tasks-42] n.m.p.s.BitcoinService [BitcoinService.java:605] Releasing create transaction lock
2020-03-08 16:53:21.737+0100 INFO [pop-tasks-42] n.m.p.c.BaseTask [CreateBitcoinTransactionTask.java:87] Insufficient money,  missing 0.00000073 BTC
2020-03-08 16:53:21.738+0100 WARN [pop-tasks-42] n.m.p.c.BaseTask [BaseTask.java:41] Operation 0a7947d5 failed for reason: PoP wallet does not contain sufficient funds to create PoP transaction

[Leonardiae]

This is an edge case which should not happen that often but lately it does because of fast block times. I see it ~10 times a day.

[Leonardiae]

It looks like this is not nessecary anymore after the redesign done by @PCasafont. I'm closing this issue.