client/core: fix btc wallet cfg in simnet tests, other improvements#589
Merged
Conversation
itswisdomagain
commented
Aug 7, 2020
chappjc
reviewed
Aug 7, 2020
| dcrw.config["account"] = "default" | ||
| btcw.config["account"] = btcw.name | ||
| dcrw.config["account"] = dcrw.account | ||
| btcw.config["walletname"] = btcw.walletName |
Member
There was a problem hiding this comment.
I need to run this more often, sorry. BTW I'm hoping at least one of the following possible errors you listed is resolved now:
dcrdex/client/core/trade_simnet_test.go
Lines 15 to 18 in 6b4bea6
Coin locking has improved a ton ofc, dcrwallet listunspent is fixed, and we're pulling only utxos from the funding account. There's probably still bugs with all that, but it should be more robust than even a week ago.
Really confused about the signrawtransaction errors that show up randomly now though...
Member
Author
There was a problem hiding this comment.
Yeah, coin locking/unlocking has improved significantly. Just noticed an instance where dcrdex did not unlock a coin from a failed trade though and subsequent trading attempts with the coin return a rpc error 36: coin <> is locked.
A close examination of the logs below suggests that a couple failed trades were not revoked. The first match in the log is for 9ae7937ae39747044667978628da99231bebd3b9f5185ac1f52377cf5650e9c6 which ended at NewlyMatched (timestamp 00:51:12).
Another match followed (6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625) which completed successfully (timestamp 00:54:18-00:54:46).
Then 2 more matches (3227781362fe63e9efde569a2fd590c76814f614d3284920ae94c5ea6c6da411 and a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9) ended at NewlyMatched and MakerSwap (timestamps 00:54:48-00:54:54 and 00:54:57-00:55:05) respectively.
Then between 00:55:29 and 01:05:29, the first match (9ae7937a) got revoked, although the revoke_match request could not be sent to the clients because they'd long disconnected. But that's all in my log regarding a revocation, which would explain the coin is locked server errors I started getting at some point.
dcrdex logs
2020-08-08 00:51:06.038 [TRC] MKT: Received order 8fa87deae70f261f31578f7b8763fb5a04cc13997255fc8fbd61d41185403e5f at 2020-08-08 00:51:06.038 +0000 UTC
2020-08-08 00:51:06.122 [TRC] MKT: Received order da482da19194eb15bd9e2865baa09e2dfbbbdfde2ad4b2fa32c185a6d4f2fc38 at 2020-08-08 00:51:06.122 +0000 UTC
2020-08-08 00:51:12.000 [TRC] MKT: Preimage request sent for order da482da19194eb15bd9e2865baa09e2dfbbbdfde2ad4b2fa32c185a6d4f2fc38
2020-08-08 00:51:12.000 [TRC] MKT: Preimage request sent for order 8fa87deae70f261f31578f7b8763fb5a04cc13997255fc8fbd61d41185403e5f
2020-08-08 00:51:12.000 [TRC] MKT: Good preimage received for order da482da19194eb15bd9e2865baa09e2dfbbbdfde2ad4b2fa32c185a6d4f2fc38: 4a443d973a0dd5939fc0cc7818e330a0be44e50580a1f1d921f3282e675d1f9a
2020-08-08 00:51:12.001 [TRC] MKT: Good preimage received for order 8fa87deae70f261f31578f7b8763fb5a04cc13997255fc8fbd61d41185403e5f: 31659b5c4177c1b82c4a22ae800274cafb4f5f81ef3de57f3557a5115693b120
2020-08-08 00:51:12.003 [INF] MKT: Collected 2 valid order preimages, missed 0. Commit checksum: ae2b645c01dcd59ea8faa66006bb20d053deecfd926eef82e21bf86cc8183caf
2020-08-08 00:51:12.003 [INF] MKT: Matching complete for market dcr_btc epoch 266141311: 1 matches (0 partial fills), 1 completed OK (not booked), 1 booked, 1 unbooked, 0 failed
2020-08-08 00:51:12.007 [DBG] MKT: Negotiating 1 matches for epoch 266141311:6000
2020-08-08 00:51:12.008 [WRN] SWAP: Unable to determining optimal fee rate for "dcr", using fallback of 10. Err: -32603: no bucket with the minimum required success percentage found
2020-08-08 00:51:12.010 [DBG] SWAP: Optimal fee rate for "btc": 6
2020-08-08 00:51:12.011 [DBG] SWAP: Negotiate: sending 'match' ack request to user 954b5da2a022fde4945080f88b61c1a906a23fbcfe548be8b795932aeaa24c24 for 1 matches
2020-08-08 00:51:12.011 [DBG] SWAP: Negotiate: sending 'match' ack request to user a4e38f1a4c4b3bd8222e90bfe1a26cf9a30a8e74219479c637f26329d4096a9b for 1 matches
2020-08-08 00:51:12.012 [DBG] SWAP: processMatchAcks: 'match' ack received from 954b5da2a022fde4945080f88b61c1a906a23fbcfe548be8b795932aeaa24c24 for 1 matches
2020-08-08 00:51:12.014 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from 954b5da2a022fde4945080f88b61c1a906a23fbcfe548be8b795932aeaa24c24 (maker=true) for match 9ae7937ae39747044667978628da99231bebd3b9f5185ac1f52377cf5650e9c6 (status NewlyMatched)
2020-08-08 00:51:12.014 [DBG] SWAP: processMatchAcks: 'match' ack received from a4e38f1a4c4b3bd8222e90bfe1a26cf9a30a8e74219479c637f26329d4096a9b for 1 matches
2020-08-08 00:51:12.015 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from a4e38f1a4c4b3bd8222e90bfe1a26cf9a30a8e74219479c637f26329d4096a9b (maker=false) for match 9ae7937ae39747044667978628da99231bebd3b9f5185ac1f52377cf5650e9c6 (status NewlyMatched)
2020-08-08 00:54:18.232 [TRC] MKT: Received order c71b1526beabb8222e4106700f5e44fa3981ecd3f09b0aa406291c7e3a44f59d at 2020-08-08 00:54:18.232 +0000 UTC
2020-08-08 00:54:18.331 [TRC] MKT: Received order a41110e76884fe103e27d5d2a050f5728cb968cfddd752c1a51b6954915cbc99 at 2020-08-08 00:54:18.331 +0000 UTC
2020-08-08 00:54:24.000 [TRC] MKT: Preimage request sent for order c71b1526beabb8222e4106700f5e44fa3981ecd3f09b0aa406291c7e3a44f59d
2020-08-08 00:54:24.000 [TRC] MKT: Preimage request sent for order a41110e76884fe103e27d5d2a050f5728cb968cfddd752c1a51b6954915cbc99
2020-08-08 00:54:24.001 [TRC] MKT: Good preimage received for order a41110e76884fe103e27d5d2a050f5728cb968cfddd752c1a51b6954915cbc99: 652dd91cc57c82ba925b6d6d587a95ea1e4ef20581465c503bf9d5c5c75baa1a
2020-08-08 00:54:24.001 [TRC] MKT: Good preimage received for order c71b1526beabb8222e4106700f5e44fa3981ecd3f09b0aa406291c7e3a44f59d: 825d289786bbf28440ae2747a3a4d79ad996fad0a19fe92b1b28092a6eac605b
2020-08-08 00:54:24.002 [INF] MKT: Collected 2 valid order preimages, missed 0. Commit checksum: 8e5b3f59f83f5a975ae816351041575ba4f80298cb2c01bce7fd20a0dc95d059
2020-08-08 00:54:24.003 [INF] MKT: Matching complete for market dcr_btc epoch 266141343: 1 matches (0 partial fills), 1 completed OK (not booked), 1 booked, 1 unbooked, 0 failed
2020-08-08 00:54:24.007 [DBG] MKT: Negotiating 1 matches for epoch 266141343:6000
2020-08-08 00:54:24.007 [WRN] SWAP: Unable to determining optimal fee rate for "dcr", using fallback of 10. Err: -32603: no bucket with the minimum required success percentage found
2020-08-08 00:54:24.010 [DBG] SWAP: Optimal fee rate for "btc": 6
2020-08-08 00:54:24.011 [DBG] SWAP: Negotiate: sending 'match' ack request to user fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for 1 matches
2020-08-08 00:54:24.011 [DBG] SWAP: Negotiate: sending 'match' ack request to user 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for 1 matches
2020-08-08 00:54:24.012 [DBG] SWAP: processMatchAcks: 'match' ack received from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for 1 matches
2020-08-08 00:54:24.014 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d (maker=true) for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625 (status NewlyMatched)
2020-08-08 00:54:24.014 [DBG] SWAP: processMatchAcks: 'match' ack received from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for 1 matches
2020-08-08 00:54:24.015 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 (maker=false) for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625 (status NewlyMatched)
2020-08-08 00:54:24.290 [DBG] SWAP: handleInit: 'init' received from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, order a41110e76884fe103e27d5d2a050f5728cb968cfddd752c1a51b6954915cbc99
2020-08-08 00:54:24.291 [DBG] SWAP: step(user=fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d, match=6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625): ready for user 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 action, status NewlyMatched, next MakerSwapCast
2020-08-08 00:54:24.294 [DBG] SWAP: processInit: valid contract received at 2020-08-08 00:54:24.294 +0000 UTC from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, swapStatus NewlyMatched => MakerSwapCast
2020-08-08 00:54:24.295 [DBG] SWAP: processInit: sending contract 'audit' ack request to counterparty 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625
2020-08-08 00:54:29.620 [DBG] ASSET[btc]: Run: Processing new block 45ace13a6455ecea56671bb68ace942c227e3a55b034104a045b9c9ca17e0762
2020-08-08 00:54:29.620 [DBG] ASSET[btc]: Notifying 1 btc asset consumers of new block at height 261
2020-08-08 00:54:30.120 [DBG] SWAP: handleInit: 'init' received from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, order c71b1526beabb8222e4106700f5e44fa3981ecd3f09b0aa406291c7e3a44f59d
2020-08-08 00:54:30.120 [DBG] SWAP: step(user=4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662, match=6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625): ready for user fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d action, status MakerSwapCast, next TakerSwapCast
2020-08-08 00:54:30.122 [DBG] SWAP: processInit: valid contract received at 2020-08-08 00:54:30.121 +0000 UTC from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, swapStatus MakerSwapCast => TakerSwapCast
2020-08-08 00:54:30.122 [DBG] SWAP: processInit: sending contract 'audit' ack request to counterparty fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625
2020-08-08 00:54:35.669 [DBG] ASSET[dcr]: Run: Processing new block 042c0c74febe9316c4408edd79faf5db3094199dd3420aa08470423749b26f8b
2020-08-08 00:54:35.669 [DBG] ASSET[dcr]: Notifying 1 dcr asset consumers of new block at height 264
2020-08-08 00:54:36.126 [DBG] SWAP: handleRedeem: 'redeem' received from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, order a41110e76884fe103e27d5d2a050f5728cb968cfddd752c1a51b6954915cbc99
2020-08-08 00:54:36.126 [DBG] SWAP: step(user=fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d, match=6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625): ready for user 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 action, status TakerSwapCast, next MakerRedeemed
2020-08-08 00:54:36.133 [DBG] SWAP: processRedeem: valid redemption received at 2020-08-08 00:54:36.133 +0000 UTC from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, swapStatus TakerSwapCast => MakerRedeemed
2020-08-08 00:54:36.135 [DBG] SWAP: processRedeem: sending 'redeem' ack request to counterparty 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625
2020-08-08 00:54:36.137 [DBG] AUTH: Recorded order c71b1526beabb8222e4106700f5e44fa3981ecd3f09b0aa406291c7e3a44f59d that has finished processing: user=4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662, time=1596848076137, target=<nil>
2020-08-08 00:54:36.162 [DBG] SWAP: handleRedeem: 'redeem' received from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, order c71b1526beabb8222e4106700f5e44fa3981ecd3f09b0aa406291c7e3a44f59d
2020-08-08 00:54:36.162 [DBG] SWAP: step(user=4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662, match=6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625): ready for user fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d action, status MakerRedeemed, next MatchComplete
2020-08-08 00:54:41.189 [DBG] SWAP: processRedeem: valid redemption received at 2020-08-08 00:54:41.189 +0000 UTC from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625, swapStatus MakerRedeemed => MatchComplete
2020-08-08 00:54:41.191 [DBG] SWAP: processRedeem: sending 'redeem' ack request to counterparty fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625
2020-08-08 00:54:41.192 [DBG] AUTH: Recorded order a41110e76884fe103e27d5d2a050f5728cb968cfddd752c1a51b6954915cbc99 that has finished processing: user=fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d, time=1596848081192, target=<nil>
2020-08-08 00:54:41.669 [DBG] ASSET[dcr]: Run: Processing new block 2115b2c13bb2424315e2962482c2c68c416bb443977705f2aca00453bbe36240
2020-08-08 00:54:41.670 [DBG] ASSET[dcr]: Notifying 1 dcr asset consumers of new block at height 265
2020-08-08 00:54:46.620 [DBG] ASSET[btc]: Run: Processing new block 5113c862b734a7b34e8afccf38885917de5167ad2699d678b79b787b940c412f
2020-08-08 00:54:46.620 [DBG] ASSET[btc]: Notifying 1 btc asset consumers of new block at height 262
2020-08-08 00:54:46.621 [DBG] SWAP: Deleting completed match 6622fe589b2b46f28ffe15f2f344bbd625197840bb664828bfa8c85dcd47a625
2020-08-08 00:54:48.384 [TRC] MKT: Received order f15c0e183ae4573fe2c3dac7b2bbeb55464bed9f8b8806f8d7640948e455f3c0 at 2020-08-08 00:54:48.384 +0000 UTC
2020-08-08 00:54:48.447 [TRC] MKT: Received order 4fc559f5c193d4084496e59ae7a569d9a7a28daaaa0f477b19fcd4c4c5f5fd02 at 2020-08-08 00:54:48.447 +0000 UTC
2020-08-08 00:54:54.000 [TRC] MKT: Preimage request sent for order f15c0e183ae4573fe2c3dac7b2bbeb55464bed9f8b8806f8d7640948e455f3c0
2020-08-08 00:54:54.000 [TRC] MKT: Preimage request sent for order 4fc559f5c193d4084496e59ae7a569d9a7a28daaaa0f477b19fcd4c4c5f5fd02
2020-08-08 00:54:54.000 [TRC] MKT: Good preimage received for order f15c0e183ae4573fe2c3dac7b2bbeb55464bed9f8b8806f8d7640948e455f3c0: 7849400c1ca16ef732ab2f80fa26232a6ddbce4e9aef4c6a9f7c575d82319ced
2020-08-08 00:54:54.001 [TRC] MKT: Good preimage received for order 4fc559f5c193d4084496e59ae7a569d9a7a28daaaa0f477b19fcd4c4c5f5fd02: e65ec9d9ec3540e0d7c9085d26ed7cfdac67afed5565535310a9926e5e903479
2020-08-08 00:54:54.003 [INF] MKT: Collected 2 valid order preimages, missed 0. Commit checksum: eadea51c76bb67663faaed9fbaec0f120ed2622989a2401a690ead74d37fc398
2020-08-08 00:54:54.004 [INF] MKT: Matching complete for market dcr_btc epoch 266141348: 1 matches (0 partial fills), 1 completed OK (not booked), 1 booked, 1 unbooked, 0 failed
2020-08-08 00:54:54.007 [DBG] MKT: Negotiating 1 matches for epoch 266141348:6000
2020-08-08 00:54:54.008 [WRN] SWAP: Unable to determining optimal fee rate for "dcr", using fallback of 10. Err: -32603: no bucket with the minimum required success percentage found
2020-08-08 00:54:54.010 [DBG] SWAP: Optimal fee rate for "btc": 10
2020-08-08 00:54:54.012 [DBG] SWAP: Negotiate: sending 'match' ack request to user 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for 1 matches
2020-08-08 00:54:54.012 [DBG] SWAP: Negotiate: sending 'match' ack request to user fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for 1 matches
2020-08-08 00:54:54.013 [DBG] SWAP: processMatchAcks: 'match' ack received from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for 1 matches
2020-08-08 00:54:54.014 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d (maker=false) for match 3227781362fe63e9efde569a2fd590c76814f614d3284920ae94c5ea6c6da411 (status NewlyMatched)
2020-08-08 00:54:54.014 [DBG] SWAP: processMatchAcks: 'match' ack received from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 for 1 matches
2020-08-08 00:54:54.015 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from 4b4e747bc2a5ad7d0baf6d2b42f6c98033edfdeb20020432f4c7bc7421571662 (maker=true) for match 3227781362fe63e9efde569a2fd590c76814f614d3284920ae94c5ea6c6da411 (status NewlyMatched)
2020-08-08 00:54:57.591 [TRC] MKT: Received order fe9e0c3f19ce8a4f93ef71a97cf4f609afb3f87129563f0849f116a0603a117a at 2020-08-08 00:54:57.591 +0000 UTC
2020-08-08 00:54:57.722 [TRC] MKT: Received order 46aa3325dac457c46c2342c55970e6e8938abf578b98939932eaced50171b019 at 2020-08-08 00:54:57.722 +0000 UTC
2020-08-08 00:55:00.000 [TRC] MKT: Preimage request sent for order 46aa3325dac457c46c2342c55970e6e8938abf578b98939932eaced50171b019
2020-08-08 00:55:00.000 [TRC] MKT: Preimage request sent for order fe9e0c3f19ce8a4f93ef71a97cf4f609afb3f87129563f0849f116a0603a117a
2020-08-08 00:55:00.001 [TRC] MKT: Good preimage received for order fe9e0c3f19ce8a4f93ef71a97cf4f609afb3f87129563f0849f116a0603a117a: 124bead42b6bd509a56d900e51068097e15faf533ec06ab7a72aa0aaeb4f8abc
2020-08-08 00:55:00.001 [TRC] MKT: Good preimage received for order 46aa3325dac457c46c2342c55970e6e8938abf578b98939932eaced50171b019: 0d9dace6e378fe1363c17229858efa252ddb4973a0c11ca672c25beff13b83e9
2020-08-08 00:55:00.002 [INF] MKT: Collected 2 valid order preimages, missed 0. Commit checksum: aa91db2166b6174a3d77e897fcd94c0519d9f3b9b226a37c1dcfb46e4c087cea
2020-08-08 00:55:00.003 [INF] MKT: Matching complete for market dcr_btc epoch 266141349: 1 matches (0 partial fills), 1 completed OK (not booked), 1 booked, 1 unbooked, 0 failed
2020-08-08 00:55:00.007 [DBG] MKT: Negotiating 1 matches for epoch 266141349:6000
2020-08-08 00:55:00.008 [WRN] SWAP: Unable to determining optimal fee rate for "dcr", using fallback of 10. Err: -32603: no bucket with the minimum required success percentage found
2020-08-08 00:55:00.011 [DBG] SWAP: Optimal fee rate for "btc": 10
2020-08-08 00:55:00.012 [DBG] SWAP: Negotiate: sending 'match' ack request to user 9622665526c9d888a8db16fe76da16796958def53deae2d31a759b32a7ceb69f for 1 matches
2020-08-08 00:55:00.012 [DBG] SWAP: Negotiate: sending 'match' ack request to user fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for 1 matches
2020-08-08 00:55:00.013 [DBG] SWAP: processMatchAcks: 'match' ack received from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for 1 matches
2020-08-08 00:55:00.014 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d (maker=false) for match a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9 (status NewlyMatched)
2020-08-08 00:55:00.014 [DBG] SWAP: processMatchAcks: 'match' ack received from 9622665526c9d888a8db16fe76da16796958def53deae2d31a759b32a7ceb69f for 1 matches
2020-08-08 00:55:00.015 [DBG] SWAP: processMatchAcks: storing valid 'match' ack signature from 9622665526c9d888a8db16fe76da16796958def53deae2d31a759b32a7ceb69f (maker=true) for match a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9 (status NewlyMatched)
2020-08-08 00:55:00.289 [DBG] SWAP: handleInit: 'init' received from 9622665526c9d888a8db16fe76da16796958def53deae2d31a759b32a7ceb69f for match a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9, order fe9e0c3f19ce8a4f93ef71a97cf4f609afb3f87129563f0849f116a0603a117a
2020-08-08 00:55:00.289 [DBG] SWAP: step(user=9622665526c9d888a8db16fe76da16796958def53deae2d31a759b32a7ceb69f, match=a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9): ready for user fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d action, status NewlyMatched, next MakerSwapCast
2020-08-08 00:55:00.294 [DBG] SWAP: processInit: valid contract received at 2020-08-08 00:55:00.293 +0000 UTC from 9622665526c9d888a8db16fe76da16796958def53deae2d31a759b32a7ceb69f for match a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9, swapStatus NewlyMatched => MakerSwapCast
2020-08-08 00:55:00.294 [DBG] SWAP: processInit: sending contract 'audit' ack request to counterparty fa21acf013cecff681e6adaa7322dfd7598369221671c7781e4d21bd23d3f39d for match a0483209f9a3da14a6885b7ef8dcf9a4f932c4046ac3f6e9028d84ac20c368c9
2020-08-08 00:55:29.620 [DBG] SWAP: checkInaction(failMatch): swap 9ae7937ae39747044667978628da99231bebd3b9f5185ac1f52377cf5650e9c6 failing (maker fault = true) at NewlyMatched
2020-08-08 00:55:29.622 [DBG] AUTH: Recorded order da482da19194eb15bd9e2865baa09e2dfbbbdfde2ad4b2fa32c185a6d4f2fc38 that has finished processing: user=a4e38f1a4c4b3bd8222e90bfe1a26cf9a30a8e74219479c637f26329d4096a9b, time=1596848129622, target=<nil>
2020-08-08 00:55:29.625 [DBG] AUTH: user 954b5da2a022fde4945080f88b61c1a906a23fbcfe548be8b795932aeaa24c24 penalized for rule 1
2020-08-08 00:55:29.625 [INF] SWAP: revoke: sending the 'revoke_match' request to each client for match 9ae7937ae39747044667978628da99231bebd3b9f5185ac1f52377cf5650e9c6
2020-08-08 01:05:29.626 [INF] SWAP: revoke_match request failed for user a4e38f1a4c4b3bd8222e90bfe1a26cf9a30a8e74219479c637f26329d4096a9b (taker)
2020-08-08 01:05:29.626 [INF] SWAP: revoke_match request failed for user 954b5da2a022fde4945080f88b61c1a906a23fbcfe548be8b795932aeaa24c24 (taker)
Member
There was a problem hiding this comment.
The rpc error 36: coin <> is locked errors were frustrating me too, but I realized that's because I had restarted the test and/or the btc/dcr wallet harnesses without nuking the dcrdex harness. So the server still had those coins locked in orders from a previous run, but the test didn't realize they were locked on the server. I think this was expected behavior if the server/dcrdex harness isn't also nuked between runs.
But if you think that coins were not unlocked server-side when the orders were revoked, that's worth looking into.
Member
Author
There was a problem hiding this comment.
For additional context, another set of 4 trades (3 failures, 1 success) - all failed trades were revoked but I tried re-running the test before the last trade was revoked and got the coin is locked error. Waited a bit, confirmed from dcrdex logs that the last trade was revoked and the tests re-ran without the coin is locked error.
I guess only question is why I had a previous instance where some trades were not revoked. Could be the dcrdex binary I was running is outdated, so will keep an eye on this.
The not enough to cover requested funds error could still occur at any point but it'd more likely mean that the configured account has no funds, rather than the wallet not having funds.
Member
Author
There was a problem hiding this comment.
Noticed this incorrect log bit (always (taker)) btw:
Lines 2068 to 2079 in 8b55845
Member
Author
There was a problem hiding this comment.
I mostly only nuke and restart dcrdex harness without visiting the btc/dcr harnesses. Could it be the dcr/btc wallets still consider the coins locked from before dcrdex re-run? iirc, dcrdex on launch unlocks all coins to start afresh.
In any case, I got the coin is locked error again, so issue's still on master. This time, a failed trade also failed to revoke, match ended at MakerSwapCast.
Member
There was a problem hiding this comment.
Unless the dcrdex psql db is nuked, it will relock order coins on startup. There's no way the server would have coins locked from non-existent orders. I never get this in the wild or in interactive simnet tests anyway.
When you say failed to revoke, does that mean the server didn't revoke it after broadcast timeout, or did one or both of maker or taker fail to revoke it? That's another thing I never see in practice, so repro is needed to be sure it's not just a test harness thing. That said, it could very well be the recent "retiring inactive trade" function getting in the way.
Member
Author
There was a problem hiding this comment.
- iirc, the dcrdex harness script nukes the simnet test db before restarting the binary.
- re failed to revoke, the server did not revoke, at least there was no log message to that effect on dcrdex (for some failed trades anyways), something to watch more closely, I guess.
Member
|
I'm consistently needing to mine an extra block to get the node to include the fee payment txns. i.e. In // The node might not include it if it hasn't processed it in mempool yet.
time.Sleep(500 * time.Millisecond)
// mine drc block(s) to mark fee as paid
err = mineBlocks(dcr.BipID, regRes.ReqConfirms+1) // note the +1Even with a really long sleep before |
Member
Author
|
Weird stuff with getting the fee tx mined, I've noticed (and I think @JoeGruffins too) the fee tx issues. Would commit that |
Member
|
BTW, I suspect |
Member
Author
|
Retesting this branch now (with more verbose logging on the clients), and seeing fee tx rejected issues because of high fee: I'm yet to try with #590 though. |
Member
|
The high 2000000 DCR fallback fee is resolved in #565, which was merged not 12 hrs ago. Probably rebase. Old dexc.db with the high fee rate won't be fixed automatically though. |
Member
Author
|
Another thing to maybe try re fee tx confirmation requiring mining an additional block is: dcrdex/client/core/trade_simnet_test.go Lines 19 to 20 in 6b4bea6 If that solves it, then perhaps it's a simnet issue. Regardless, if mining an additional block kills the issue, then we can mark that resolved. |
Member
Author
I haven't had issues with this though, will bump to 2 minutes to be safe. It's a max value after all, wouldn't wait up to 2 minutes if it doesn't have to, but could mean waiting longer than necessary to detect a failed test.
Ah, increasing the wait time before mining blocks for swaps and redeems from 1 to 5 seconds could be a reason for trade monitoring taking longer than a minute. |
itswisdomagain
force-pushed
the
fix-trade-simnet-tests
branch
from
6b4bea6 to
8c65c85
Compare
itswisdomagain
changed the title
Member
|
The test are failing for me. Results of five tries: results
Restart stimnet harness |
Member
Author
|
@JoeGruffins, more log messages will be helpful, will like to know where the trades are getting stuck. |
Member
|
It fails for me the same way as for @JoeGruffins, although I think the coin lock error is just because of how the harness was being used (not wiping the server's postgresql db in between fresh client and/or wallets). |
Member
|
Note that when #587 goes in shortly, the dcr wallet pass will be "abc" also, so might as well switch that to head off the conflict. |
Member
test logsserver logs |
buck54321
requested changes
Aug 11, 2020
Member
buck54321
left a comment
buck54321
left a comment
There was a problem hiding this comment.
Sorry for not checking in #533. These changes look good, but I did run into a nil pointer at
dcrdex/client/core/trade_simnet_test.go
Lines 500 to 501 in d2c2f0a
logs
2020-08-11 15:15:12.842 [INF] TEST: [client 1] NOW =====> MatchComplete
2020-08-11 15:15:12.842 [INF] TEST: [client 1] updated btc balance diff with +0.001800
2020-08-11 15:15:12.849 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-11 15:15:13.028 [INF] TEST: [client 2] NOW =====> MatchComplete
2020-08-11 15:15:13.031 [INF] TEST: [client 2] Mined 1 blocks for Taker's redeem, match 917e0b54
2020-08-11 15:15:13.623 [TRC] CORE: processing tip change for btc
2020-08-11 15:15:13.776 [DBG] CORE: Ticking 1 trades
2020-08-11 15:15:13.776 [INF] CORE: Retiring inactive order 827657d470c58f2ffb6c5c2c09a535112029a28edcc5b0bd14e6c4235f36b884
2020-08-11 15:15:13.964 [TRC] CORE: processing tip change for btc
2020-08-11 15:15:14.031 [INF] TEST: [client 1] updating balances
2020-08-11 15:15:14.039 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-11 15:15:14.039 [INF] TEST: [client 1] dcr available 70.999947, locked 3.000000
2020-08-11 15:15:14.047 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-11 15:15:14.047 [INF] TEST: [client 1] btc available 84.001477, locked 0.000000
2020-08-11 15:15:14.047 [INF] TEST: [client 1] dcr balance change -12.00002490 is in expected range of -13.00000000 - -12.00000000
2020-08-11 15:15:14.047 [INF] TEST: [client 1] btc balance change 0.00147700 is in expected range of -0.99820000 - 0.00180000
2020-08-11 15:15:14.047 [INF] TEST: [client 2] updating balances
2020-08-11 15:15:14.053 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-11 15:15:14.053 [INF] TEST: [client 2] dcr available 94.999934, locked 3.000000
2020-08-11 15:15:14.060 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-11 15:15:14.060 [INF] TEST: [client 2] btc available 83.998195, locked 0.000000
2020-08-11 15:15:14.060 [INF] TEST: [client 2] btc balance change -0.00180492 is in expected range of -1.00180000 - -0.00180000
2020-08-11 15:15:14.060 [INF] TEST: [client 2] dcr balance change 11.99996150 is in expected range of 11.00000000 - 12.00000000
2020-08-11 15:15:14.060 [INF] TEST: [client 2] checking if refunds are necessary
2020-08-11 15:15:14.060 [INF] TEST: [client 1] checking if refunds are necessary
panic: runtime error: invalid memory address or nil pointer dereference
goroutine 3700 [running]:
sync.(*RWMutex).RLock(...)
/usr/local/go/src/sync/rwmutex.go:48
decred.org/dcrdex/client/core.checkAndWaitForRefunds(0xbdfc80, 0xc001c53b40, 0xf22d20, 0xc001236500, 0x40, 0xc0007fbfa8, 0x5d579e)
/home/buck/programs/dcrdex/client/core/trade_simnet_test.go:501 +0x277
| daemon string | ||
| account string // for dcr wallets | ||
| walletName string // for btc wallets | ||
| pass []byte |
Member
There was a problem hiding this comment.
After to the changes in #587 (merged today), the wallet password could actually be a constant = "abc".
Member
Author
There was a problem hiding this comment.
Thinking of leaving it variable for now, should differing wallet passes become a thing again sometime; more so as wallet passes really should be wallet-specific even though the value might be the same across wallets.
Member
Author
|
@JoeGruffins It appears the issue with your failing tests has to do with Maker's swap not getting the required confirms for taker to broadcast the counterswap. I've seen this before but not sure what the cause really is. There is a test log entry after Maker's swap was broadcasted that shows that a block was mined to confirm the Maker's swap: I'm guessing this might be related to the issue @chappjc reported earlier re needing to mine an extra block to get the node to include the fee payment txns. If so, mining +1 blocks should get the tests passing for you, but something to try first is restarting your asset harnesses (if they've been running for a while before you ran the tests). UPDATE: |
itswisdomagain
force-pushed
the
fix-trade-simnet-tests
branch
from
d2c2f0a to
7430a2e
Compare
Member
|
Much closer now that it's on the mining fix commit. But I got one of the unsigned txn errors for the first time. Sadly, I wasn't rebased on #590 so I didn't get details from |
Member
|
Oh, does this need a fix up now that #548 is merged? I'm seeing: Another issue is I'm seeing |
This comment has been minimized.
This comment has been minimized.
Member
|
Sorry about that last comment about the coin locked error, it was just the dcrdex server harness not reset. However, I hit the balance error again, so I expect it's just because the balance fixes from #548 went in. |
Member
|
Captured the signrawtransaction error (which did not fail the test btw for some reason). wallet.SignTransaction: wallet locked hmm... |
Member
Author
Yeah, wallets are sometimes locked during the test to prevent sending swaps. dcrdex/client/core/trade_simnet_test.go Lines 276 to 283 in 8a9288a |
itswisdomagain
force-pushed
the
fix-trade-simnet-tests
branch
from
7430a2e to
9976921
Compare
itswisdomagain
commented
Aug 15, 2020
Comment on lines
422
to
442
| switch { | ||
| case side == order.Maker && status == order.MakerSwapCast, | ||
| side == order.Taker && status == order.TakerSwapCast: | ||
| assetToMine, swapOrRedeem = tracker.wallets.fromAsset, "swap" | ||
| // Record expected balance changes if we've just sent a swap. | ||
| // Do NOT mine blocks until counter-party captures status change. | ||
| recordBalanceChanges(tracker.wallets.fromAsset.ID, true, match.Match.Quantity, match.Match.Rate) | ||
|
|
||
| case side == order.Maker && status == order.TakerSwapCast, | ||
| side == order.Taker && status == order.MakerSwapCast: | ||
| // Mine block for counter-party's swap. This enables us to | ||
| // proceed with the required follow-up action. | ||
| // Our toAsset == counter-party's fromAsset. | ||
| assetToMine, swapOrRedeem = tracker.wallets.toAsset, "swap" | ||
|
|
||
| case side == order.Maker && status == order.MakerRedeemed, | ||
| side == order.Taker && status == order.MatchComplete: | ||
| recordBalanceChanges(tracker.wallets.toAsset.ID, false, match.Match.Quantity, match.Match.Rate) | ||
| // Mine blocks for redemption since counter-party does not wait | ||
| // for redeem tx confirmations before performing follow-up action. | ||
| assetToMine, swapOrRedeem = tracker.wallets.toAsset, "redeem" |
Member
Author
There was a problem hiding this comment.
Relating to the conversation here #589 (comment).
A previous commit moved swap, redeem tx mining to the counter-party's trade monitoring goroutine. That ensured that party A's swap or redeem is only mined after party B's trade monitoring goroutine has had the chance to handle the status change. In cases where party B should not follow up, we set trade.failErr on party B's trade before mining party A's tx.
As mentioned in the referenced conversation, the exception to the above approach is Taker redeeming Maker's swap without needing to wait for Maker's redeem to get any confs. This sometimes results in Taker redeeming Maker's swap as soon as it is notified of Maker's redeem, and BEFORE Taker's trade monitoring goroutine captures the MakerRedeemed status and mines Maker's redeem tx. In one instance where this happened, Maker's balance did not reflect the income from redeem and caused the test to fail with a balance check error.
Redemption txs are now mined immediately by the issuing party since the counter-party may not wait for the redeem tx to get confirmed before performing their counter-redeem and end up not mining the initial redeem.
I think this needs some more fleshing out but this approach makes sense and works well for now. Delay swap mining to enable counter-party check if they should act or not, while mining redeems right away as a wait doesn't really help no one.
JoeGruffins
reviewed
Aug 17, 2020
Member
JoeGruffins
left a comment
JoeGruffins
left a comment
There was a problem hiding this comment.
Result from five tests:
results
-
Pass
2020-08-17 10:34:25.711 [DBG] CORE[btc]: funding 180000 Satoshis order with coins [9f3cc0d8a1838d01af91af658967175698a1cf456e8149ed7c6d8157b412313d:1]
--- FAIL: TestTrading (5.61s)
--- FAIL: TestTrading/success (1.15s)
trade_simnet_test.go:203: client2 place buy order error: rpc error: error code 36: coin {txid = 9f3cc0d8a1838d01af91af658967175698a1cf456e8149ed7c6d8157b412313d, vout = 1} is locked
FAIL
restart server
3. Pass
restart server
4. Pass
restart server
5.
--- FAIL: TestTrading (164.73s)
--- FAIL: TestTrading/no_maker_swap (1.58s)
trade_simnet_test.go:213: client 2 re-connect DEX error: error paying registration fee: incomplete raw tx signatures
FAIL
exit status 1
FAIL decred.org/dcrdex/client/core 164.820s
More logs for the second failure:
test logs
2020-08-17 10:46:25.772 [INF] TEST: Trades ended at MatchComplete.
2020-08-17 10:46:25.772 [INF] TEST: [client 1] unlocking wallets
2020-08-17 10:46:26.286 [INF] TEST: [client 1] reconnecting DEX for at fault client
2020-08-17 10:46:26.286 [DBG] COMMS: Sending close 1000 (normal) message.
2020-08-17 10:46:26.287 [WRN] CORE: notify: |WARNING| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected
2020-08-17 10:46:26.287 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.287 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.287 [DBG] CORE: Connection closed for 127.0.0.1:17273.
2020-08-17 10:46:26.318 [INF] CORE: notify: |SUCCESS| (conn) DEX connected - DEX at 127.0.0.1:17273 has connected
2020-08-17 10:46:26.318 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.318 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.318 [DBG] CORE: Broadcast timeout = 1m0s, ticking every 20s
2020-08-17 10:46:26.318 [INF] CORE: Connected to DEX server at 127.0.0.1:17273 and listening for messages.
2020-08-17 10:46:26.318 [DBG] COMMS: Sending close 1000 (normal) message.
2020-08-17 10:46:26.318 [DBG] CORE: Connection closed for 127.0.0.1:17273.
2020-08-17 10:46:26.318 [WRN] CORE: notify: |WARNING| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected
2020-08-17 10:46:26.318 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.318 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.388 [INF] CORE: notify: |SUCCESS| (conn) DEX connected - DEX at 127.0.0.1:17273 has connected
2020-08-17 10:46:26.388 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.388 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.388 [DBG] CORE: Broadcast timeout = 1m0s, ticking every 20s
2020-08-17 10:46:26.388 [INF] CORE: Connected to DEX server at 127.0.0.1:17273 and listening for messages.
2020-08-17 10:46:26.393 [INF] CORE: Attempting registration fee payment for SscdPSSrBhdBDzRfS7Dz2pgdRj1v6s9UJxd of 100000000 units of dcr
2020-08-17 10:46:26.394 [WRN] CORE[dcr]: Unable to get optimal fee rate, using fallback of 20: -32603: no bucket with the minimum required success percentage found
2020-08-17 10:46:26.398 [DBG] CORE[dcr]: Change output size = 36, addr = Ssr3vkTJWJvT8k7abBPhYhmVzz5KWgAJTQx
2020-08-17 10:46:26.403 [DBG] CORE[dcr]: 4 signature cycles to converge on fees for tx 3e49978825c7523888639c8282b73db524cc3ec1360df636cebee03c324b01a1: min rate = 20, actual fee rate = 20 (5040 for 251 bytes), change = true
2020-08-17 10:46:26.405 [ERR] CORE: error saving account: failed to create account bucket
2020-08-17 10:46:26.407 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-17 10:46:26.407 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.407 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.407 [INF] CORE: notify: |SUCCESS| (feepayment) Fee payment in progress - Waiting for 1 confirmations before trading at 127.0.0.1:17273
2020-08-17 10:46:26.407 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.407 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.407 [INF] TEST: [client 1] connected DEX 127.0.0.1:17273
2020-08-17 10:46:26.416 [INF] TEST: [client 1] mined 1 dcr blocks for fee payment confirmation
2020-08-17 10:46:26.416 [INF] TEST: [client 1] waiting 12s for fee confirmation notice
2020-08-17 10:46:26.727 [TRC] CORE: processing tip change for dcr
2020-08-17 10:46:26.728 [DBG] CORE: Registration fee txn 3e49978825c7523888639c8282b73db524cc3ec1360df636cebee03c324b01a1:0 now has 1 confirmations.
2020-08-17 10:46:26.728 [INF] CORE: Notifying dex 127.0.0.1:17273 of fee payment.
2020-08-17 10:46:26.737 [DBG] CORE: Authenticated connection to 127.0.0.1:17273, 0 active matches
2020-08-17 10:46:26.737 [INF] CORE: notify: |SUCCESS| (feepayment) Account registered - You may now trade at 127.0.0.1:17273
2020-08-17 10:46:26.737 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.737 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.737 [INF] TEST: [client 1] fee payment confirmed
2020-08-17 10:46:26.737 [INF] TEST: [client 1] updating balances
2020-08-17 10:46:26.738 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-17 10:46:26.738 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.738 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.738 [INF] TEST: [client 1] dcr available 10.998856, locked 12.999975
2020-08-17 10:46:26.741 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-08-17 10:46:26.741 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.741 [ERR] CORE: blocking notification channel
2020-08-17 10:46:26.741 [INF] TEST: [client 1] btc available 84.005908, locked 0.000000
2020-08-17 10:46:26.741 [INF] TEST: [client 2] unlocking wallets
2020-08-17 10:46:26.815 [TRC] CORE: processing tip change for dcr
2020-08-17 10:46:27.254 [INF] TEST: [client 2] reconnecting DEX for at fault client
2020-08-17 10:46:27.255 [DBG] COMMS: Sending close 1000 (normal) message.
2020-08-17 10:46:27.255 [WRN] CORE: notify: |WARNING| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected
2020-08-17 10:46:27.255 [ERR] CORE: blocking notification channel
2020-08-17 10:46:27.255 [DBG] CORE: Connection closed for 127.0.0.1:17273.
2020-08-17 10:46:27.281 [INF] CORE: notify: |SUCCESS| (conn) DEX connected - DEX at 127.0.0.1:17273 has connected
2020-08-17 10:46:27.281 [ERR] CORE: blocking notification channel
2020-08-17 10:46:27.281 [DBG] CORE: Broadcast timeout = 1m0s, ticking every 20s
2020-08-17 10:46:27.281 [INF] CORE: Connected to DEX server at 127.0.0.1:17273 and listening for messages.
2020-08-17 10:46:27.281 [DBG] COMMS: Sending close 1000 (normal) message.
2020-08-17 10:46:27.282 [DBG] CORE: Connection closed for 127.0.0.1:17273.
2020-08-17 10:46:27.285 [WRN] CORE: notify: |WARNING| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected
2020-08-17 10:46:27.285 [ERR] CORE: blocking notification channel
2020-08-17 10:46:27.340 [INF] CORE: notify: |SUCCESS| (conn) DEX connected - DEX at 127.0.0.1:17273 has connected
2020-08-17 10:46:27.340 [ERR] CORE: blocking notification channel
2020-08-17 10:46:27.341 [DBG] CORE: Broadcast timeout = 1m0s, ticking every 20s
2020-08-17 10:46:27.341 [INF] CORE: Connected to DEX server at 127.0.0.1:17273 and listening for messages.
2020-08-17 10:46:27.343 [INF] CORE: Attempting registration fee payment for SsdUPBW84hgJFJZzMfhtvvNzAW991FgVP99 of 100000000 units of dcr
2020-08-17 10:46:27.344 [WRN] CORE[dcr]: Unable to get optimal fee rate, using fallback of 20: -32603: no bucket with the minimum required success percentage found
2020-08-17 10:46:27.348 [ERR] CORE[dcr]: incomplete raw transaction signatures (raw tx: 01000000015116f082624a51ef469c2ee4e10d4e70567773f4662879e1f3d98e6458ff9e440100000000ffffffff0100e1f5050000000000001976a914641176b296190766b3176a9572f2c01e0912917888ac000000000000000001b85feb0b0000000000000000ffffffff00):
2020-08-17 10:46:27.348 [DBG] COMMS: Sending close 1000 (normal) message.
2020-08-17 10:46:27.348 [WRN] CORE: notify: |WARNING| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected
2020-08-17 10:46:27.348 [ERR] CORE: blocking notification channel
--- FAIL: TestTrading (164.73s)
--- FAIL: TestTrading/no_maker_swap (1.58s)
trade_simnet_test.go:213: client 2 re-connect DEX error: error paying registration fee: incomplete raw tx signatures
FAIL
exit status 1
FAIL decred.org/dcrdex/client/core 164.820s
server
2020-08-17 10:46:25.457 [DBG] ASSET[btc]: Notifying 1 btc asset consumers of new block at height 270
2020-08-17 10:46:25.461 [DBG] SWAP: Deleting completed match f250c34921a3dd25d9de2a82e6b411a0ec8d241791ef59785571f3079ce698a9
2020-08-17 10:46:26.287 [TRC] COMM: Websocket output handler done for peer 127.0.0.1
2020-08-17 10:46:26.287 [INF] COMM: Sending 0 queued outgoing messages for 127.0.0.1.
2020-08-17 10:46:26.287 [DBG] COMM: Sent 11 and dropped 0 messages to 127.0.0.1 before shutdown.
2020-08-17 10:46:26.287 [DBG] COMM: Sending close 1000 (normal) message.
2020-08-17 10:46:26.287 [TRC] COMM: Disconnected websocket client 127.0.0.1
2020-08-17 10:46:26.317 [DBG] COMM: New websocket client 127.0.0.1
2020-08-17 10:46:26.317 [TRC] COMM: Starting websocket messaging with peer 127.0.0.1
2020-08-17 10:46:26.318 [TRC] COMM: Websocket output handler done for peer 127.0.0.1
2020-08-17 10:46:26.318 [INF] COMM: Sending 0 queued outgoing messages for 127.0.0.1.
2020-08-17 10:46:26.318 [DBG] COMM: Sent 1 and dropped 0 messages to 127.0.0.1 before shutdown.
2020-08-17 10:46:26.318 [DBG] COMM: Sending close 1000 (normal) message.
2020-08-17 10:46:26.318 [TRC] COMM: Disconnected websocket client 127.0.0.1
2020-08-17 10:46:26.387 [DBG] COMM: New websocket client 127.0.0.1
2020-08-17 10:46:26.388 [TRC] COMM: Starting websocket messaging with peer 127.0.0.1
2020-08-17 10:46:26.392 [INF] AUTH: Created new user account 9d13acb95569b9fc7124af8bfb3ef5a36ccbf4f1479c32022a358cb12fb5c27f with fee address SscdPSSrBhdBDzRfS7Dz2pgdRj1v6s9UJxd
2020-08-17 10:46:26.732 [INF] AUTH: New user registered: acct 9d13acb95569b9fc7124af8bfb3ef5a36ccbf4f1479c32022a358cb12fb5c27f, paid 100000000 to SscdPSSrBhdBDzRfS7Dz2pgdRj1v6s9UJxd
2020-08-17 10:46:26.738 [DBG] AUTH: User 9d13acb95569b9fc7124af8bfb3ef5a36ccbf4f1479c32022a358cb12fb5c27f connected from 127.0.0.1 with 0 pending requests and 0 pending responses/notifications.
2020-08-17 10:46:27.255 [TRC] COMM: Websocket output handler done for peer 127.0.0.1
2020-08-17 10:46:27.255 [INF] COMM: Sending 0 queued outgoing messages for 127.0.0.1.
2020-08-17 10:46:27.255 [DBG] COMM: Sent 11 and dropped 0 messages to 127.0.0.1 before shutdown.
2020-08-17 10:46:27.255 [DBG] COMM: Sending close 1000 (normal) message.
2020-08-17 10:46:27.255 [TRC] COMM: Disconnected websocket client 127.0.0.1
2020-08-17 10:46:27.281 [DBG] COMM: New websocket client 127.0.0.1
2020-08-17 10:46:27.281 [TRC] COMM: Starting websocket messaging with peer 127.0.0.1
2020-08-17 10:46:27.281 [TRC] COMM: Websocket output handler done for peer 127.0.0.1
2020-08-17 10:46:27.282 [INF] COMM: Sending 0 queued outgoing messages for 127.0.0.1.
2020-08-17 10:46:27.282 [DBG] COMM: Sent 1 and dropped 0 messages to 127.0.0.1 before shutdown.
2020-08-17 10:46:27.282 [DBG] COMM: Sending close 1000 (normal) message.
2020-08-17 10:46:27.282 [TRC] COMM: Disconnected websocket client 127.0.0.1
2020-08-17 10:46:27.340 [DBG] COMM: New websocket client 127.0.0.1
2020-08-17 10:46:27.340 [TRC] COMM: Starting websocket messaging with peer 127.0.0.1
2020-08-17 10:46:27.343 [INF] AUTH: Created new user account 411246f10d237b2600afc7a0e1f468ac72bd9a9188fc2a9da6b81bcc3e2f0285 with fee address SsdUPBW84hgJFJZzMfhtvvNzAW991FgVP99
2020-08-17 10:46:27.348 [TRC] COMM: Websocket output handler done for peer 127.0.0.1
2020-08-17 10:46:27.348 [INF] COMM: Sending 0 queued outgoing messages for 127.0.0.1.
2020-08-17 10:46:27.348 [DBG] COMM: Sent 2 and dropped 0 messages to 127.0.0.1 before shutdown.
2020-08-17 10:46:27.348 [DBG] COMM: Sending close 1000 (normal) message.
2020-08-17 10:46:27.348 [TRC] COMM: Disconnected websocket client 127.0.0.1
2020-08-17 10:46:27.364 [ERR] COMM: Websocket receive error from peer 127.0.0.1: websocket: close 1006 (abnormal closure): unexpected EOF
2020-08-17 10:46:27.364 [TRC] COMM: Websocket output handler done for peer 127.0.0.1
2020-08-17 10:46:27.364 [INF] COMM: Sending 0 queued outgoing messages for 127.0.0.1.
2020-08-17 10:46:27.364 [DBG] COMM: Sent 4 and dropped 0 messages to 127.0.0.1 before shutdown.
2020-08-17 10:46:27.364 [DBG] COMM: Sending close 1000 (normal) message.
2020-08-17 10:46:27.364 [TRC] COMM: Disconnected websocket client 127.0.0.1
2020-08-17 10:46:27.510 [DBG] ASSET[dcr]: Notifying 1 dcr asset consumers of new block at height 266
2020-08-17 10:46:31.462 [INF] SWAP: revoke_match request failed for user 94f71bfc8bac48c04a38d31ed1f1272a66df01b80e6e678627be5f43a1d6b591 (taker)
2020-08-17 10:46:37.468 [INF] SWAP: revoke_match request failed for user 94f71bfc8bac48c04a38d31ed1f1272a66df01b80e6e678627be5f43a1d6b591 (taker)
2020-08-17 10:46:37.468 [INF] SWAP: revoke_match request failed for user c7cdd268810909fa724a54b692b44b2b7d8b9a7fd7cb0f46a50636423855379a (taker)
Member
|
Those locked coin errors are expected with no server reinit (pg db wipe), but I think the "incomplete raw tx signatures", which we've determined seems to always be "wallet locked" in these tests is interesting. Do the beginning of the tests need to proactively unlock just in case the test starts with a locked wallet? |
Member
|
This PR's test are passing for me now with the recent changes. I also tested it with the updated harnesses in #607, which are needed for dcrwallet master as of today. However:
|
Member
Author
irrc, the server unlocks those coins after the trade completes successfully or fails, so nuking the db and restarting the server shouldn't be a necessity. Except when running tests back to back, coins locked by the server in a previous test might still be locked because the server hasn't revoked the failed trades yet. How long should it take for a trade with no action from maker/taker to get revoked btw?
Before placing orders for any of the trade tests, the wallets are all unlocked. The only time the wallets are locked is when a test requires a trade to end at dcrdex/client/core/trade_simnet_test.go Lines 248 to 283 in 4e3ae6f
Documented in the test go file: dcrdex/client/core/trade_simnet_test.go Lines 17 to 18 in 4e3ae6f But might be better to even have the test fund the wallets as part of the setup steps. Check the balance, if below what's needed to run all tests, fund, if funding fails, test fails.
@buck54321 mentioned this before, need to drain the notification channel, will add a commit to that effect. |
Member
|
Thanks for noting that the funding issue is documented, it's OK for now just to have the test only be guaranteed to run on the try, but hopefully we can fix that in the future. I'm pretty sure the fee payment confirmation issue is resolved though. Regarding the feed, we might make a TODO to allow closing the feeds, but for now let's drain the feed constantly to avoid all these error logs. If @JoeGruffins is no longer getting errors on the first run, I'm good to merge. |
Member
|
There seem to be at least two races on the
|
chappjc
reviewed
Aug 18, 2020
Member
Author
|
I remember now that I noticed wrong mutex locks in the test file sometime ago that I was planning to correct. Should be fixed now. |
Member
Author
|
Just encountered a scenario where Core retired an order before the server revoked a match for that order (the only match actually): The only implications I see is that |
Member
|
Hmm, we should tweak the "Retiring inactive order" message to include the status and whatever else went into decision. Do you know why it was inactive according to Core if it had not yet been revoked? Was it refunded, I guess? |
Member
Author
|
Yeah, was refunded, I believe. Another set of tests produced these logs (I already cleared the log for the previous one). Trade ended at TakerSwapCast, Maker didn't redeem, Taker refunded after locktime expired and then revoke_match was sent shortly after, order not found. Looking just a little further in the logs, Maker's order was not retired before the revoke_match request came in (it was refunded before the revoke_match request but core had not gotten around to retiring the order): I think in a real-life setting, the revoke_match request will be received before any swaps can be refunded so not really an issue then. |
Member
|
Makes sense. The inaction timeouts that trigger the revoke would be many many orders of magnitude less than the contract expiry. That the thinking? |
- log available and locked balance amounts - increase delay for mining swap and redeem txs to allow other client sufficient time to process the swap or redeem action _before_ responding with follow up action
Introduced a tClient.monitorNotificationFeed method to persistently drain core's NotificationFeed channel to prevent blocking notification feed errors. The added method records all received notifications in a slice to be searched/ scanned subsequently when looking for a particular notification.
Member
Author
Yes. |
itswisdomagain
force-pushed
the
fix-trade-simnet-tests
branch
from
fedda84 to
b1f61a4
Compare
Member
Author
|
I just rebased over master to get the merged changes from #590 and #607 in. Would be helpful if @JoeGruffins (or anyone else) re-encounters the incomplete tx signature error. #607 necessary for running this PR against dcrwallet master. |
chappjc
approved these changes
Aug 18, 2020
Member
chappjc
left a comment
chappjc
left a comment
There was a problem hiding this comment.
Working reliably now on dcrwallet master.
We can continue to improve this or address issues that @JoeGruffins runs into with repeated runs in future work. But now we need to unblock #513 ASAP
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
4 participants
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
Uh oh!
There was an error while loading. Please reload this page.