search

decred / dcrdex

The Decred Decentralized Exchange (DEX), powered by atomic-swaps.
Other
187 stars 100 forks source link

trade_simnet_test: Sometimes error with `dcr balance change not in expected range` #1064

Closed JoeGruffins closed 2 years ago

JoeGruffins commented 3 years ago 
--- FAIL: TestResendPendingRequests (69.42s)
    trade_simnet_test.go:823: [client 2] dcr balance change not in expected range 19.00000000 - 20.00000000, got 9.99996150
--- FAIL: TestTradeSuccess (71.90s)
    trade_simnet_test.go:875: [client 2] dcr balance change not in expected range 39.00000000 - 40.00000000, got 19.99996150
full test logs ``` go test -v -count=1 -tags harness -run TestResendPendingRequests === RUN TestResendPendingRequests 2021-04-21 14:14:44.348 [INF] TEST: === SETUP 2021-04-21 14:14:44.349 [INF] CORE:1[DB]: creating new version 3 database 2021-04-21 14:14:44.349 [DBG] CORE:1: new client core created 2021-04-21 14:14:44.349 [INF] TEST: [client 1] Core created 2021-04-21 14:14:44.349 [INF] CORE:1: Starting DEX client core 2021-04-21 14:14:44.349 [INF] CORE:1: Successfully connected to 0 out of 0 DEX servers 2021-04-21 14:14:44.385 [INF] TEST: [client 1] Core initialized 2021-04-21 14:14:44.420 [TRC] CORE:1[dcr]: Fallback fees set at 20 atoms/byte 2021-04-21 14:14:44.420 [TRC] CORE:1[dcr]: Fees rate limit set at 100 atoms/byte 2021-04-21 14:14:44.420 [TRC] CORE:1[dcr]: Redeem conf target set to 1 blocks 2021-04-21 14:14:44.420 [INF] CORE:1[dcr]: Setting up new DCR wallet at 127.0.0.1:19581 with TLS certificate "/home/joe/dextest/dcr/trading1/rpc.cert". 2021-04-21 14:14:44.422 [INF] CORE:1[dcr]: Connected to Decred wallet at 127.0.0.1:19581 2021-04-21 14:14:44.423 [INF] CORE:1[dcr]: Connected to dcrwallet (JSON-RPC API v8.5.0) proxying dcrd (JSON-RPC API v6.2.0) on SimNet 2021-04-21 14:14:44.429 [INF] CORE:1: Created dcr wallet. Balance available = 135299942104 / locked = 0 / locked in contracts = 0, Deposit address = SsfULLhyyhXokh4UnA3fUGEshQE3AhEs3dm 2021-04-21 14:14:44.429 [TRC] CORE:1: notify: |DATA| (walletstate) 2021-04-21 14:14:44.429 [INF] TEST: [client 1] Connected dcr wallet 2021-04-21 14:14:44.450 [INF] CORE:1[btc]: Setting up new btc wallet at localhost:20557/wallet/. 2021-04-21 14:14:44.450 [TRC] CORE:1[btc]: Fallback fees set at 100 Satoshis/vbyte 2021-04-21 14:14:44.450 [TRC] CORE:1[btc]: Fees rate limit set at 1400 sats/byte 2021-04-21 14:14:44.450 [TRC] CORE:1[btc]: Redeem conf target set to 2 blocks 2021-04-21 14:14:44.521 [INF] CORE:1: Created btc wallet. Balance available = 136002747140 / locked = 0 / locked in contracts = 0, Deposit address = bcrt1q3ckm8m3fhx4f9v8u5zq9aq4kpmdrgjkvkggx2m 2021-04-21 14:14:44.521 [TRC] CORE:1: notify: |DATA| (walletstate) 2021-04-21 14:14:44.521 [INF] TEST: [client 1] Connected btc wallet 2021-04-21 14:14:44.589 [DBG] CORE:1: Setting server api version to 0. 2021-04-21 14:14:44.589 [DBG] CORE:1: Server 127.0.0.1:17273 broadcast timeout 1m0s. Tick interval 7.5s 2021-04-21 14:14:44.589 [INF] CORE:1: Connected to DEX server at 127.0.0.1:17273 and listening for messages. 2021-04-21 14:14:44.589 [DBG] CORE:1[wss://127.0.0.1:17273/ws]: Sending close 1000 (normal) message. 2021-04-21 14:14:44.654 [DBG] CORE:1: notify: |POKE| (conn) DEX connected - DEX at 127.0.0.1:17273 has connected 2021-04-21 14:14:44.655 [DBG] CORE:1: Setting server api version to 0. 2021-04-21 14:14:44.655 [DBG] CORE:1: Server 127.0.0.1:17273 broadcast timeout 1m0s. Tick interval 7.5s 2021-04-21 14:14:44.655 [INF] CORE:1: Connected to DEX server at 127.0.0.1:17273 and listening for messages. 2021-04-21 14:14:44.686 [INF] CORE:1: Attempting registration fee payment to SsXHUKcWV1SRw2pFAddfVKqEvZqVDmXWszN, account ID 4ef39dbc3b6a9c8e85bf807c3a9f881ac383134f04da28636d2ab9999d3d9f02, of 100000000 units of dcr. Do NOT manually send funds to this address even if this fails. 2021-04-21 14:14:44.687 [TRC] CORE:1[dcr]: Obtained local estimate for 1-conf fee rate, 11 2021-04-21 14:14:44.693 [DBG] CORE:1[dcr]: Change output size = 36, addr = SsZv2qBh1pk2SMMN5qDA2VAfTncyaTKmWz3 2021-04-21 14:14:44.696 [DBG] CORE:1[dcr]: 3 signature cycles to converge on fees for tx da4675b74062190f29d40de54fb0c09ec06153b1397c2f49cf9352b5f925926d: min rate = 11, actual fee rate = 11 (2761 for 251 bytes), change = true 2021-04-21 14:14:44.701 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:14:44.701 [INF] CORE:1: notify: |SUCCESS| (feepayment) Fee payment in progress - Waiting for 1 confirmations before trading at 127.0.0.1:17273 2021-04-21 14:14:44.701 [INF] TEST: [client 1] Sent registration fee to DEX 127.0.0.1:17273 2021-04-21 14:14:44.714 [INF] TEST: [client 1] Mined 1 dcr blocks for fee payment confirmation 2021-04-21 14:14:44.714 [INF] TEST: [client 1] Waiting 1m12s for fee confirmation notice 2021-04-21 14:14:45.424 [DBG] CORE:1[dcr]: tip change: 648 (4d3f96c46766b37fbc1e80d58e4ec41db314a605fbf7b800cacf35326c81b67e) => 649 (590314ac4a2f8f0dffd6cc33bbca406b311f92398ec8ddb0250d7cf2c0bde5e8) 2021-04-21 14:14:45.424 [TRC] CORE:1: processing tip change for dcr 2021-04-21 14:14:45.425 [DBG] CORE:1: Registration fee txn da4675b74062190f29d40de54fb0c09ec06153b1397c2f49cf9352b5f925926d:0 now has 1 confirmations. 2021-04-21 14:14:45.425 [INF] CORE:1: Notifying dex 127.0.0.1:17273 of fee payment. 2021-04-21 14:14:45.426 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:14:45.440 [DBG] CORE:1: Authenticated connection to 127.0.0.1:17273, acct 4ef39dbc3b6a9c8e85bf807c3a9f881ac383134f04da28636d2ab9999d3d9f02, 0 active orders, 0 active matches, score 0 2021-04-21 14:14:45.440 [INF] CORE:1: notify: |SUCCESS| (feepayment) Account registered - You may now trade at 127.0.0.1:17273 2021-04-21 14:14:45.465 [INF] TEST: [client 1] Fee payment confirmed 2021-04-21 14:14:45.465 [INF] CORE:2[DB]: creating new version 3 database 2021-04-21 14:14:45.465 [DBG] CORE:2: new client core created 2021-04-21 14:14:45.465 [INF] TEST: [client 2] Core created 2021-04-21 14:14:45.465 [INF] CORE:2: Starting DEX client core 2021-04-21 14:14:45.465 [INF] CORE:2: Successfully connected to 0 out of 0 DEX servers 2021-04-21 14:14:45.514 [INF] TEST: [client 2] Core initialized 2021-04-21 14:14:45.540 [TRC] CORE:2[dcr]: Fallback fees set at 20 atoms/byte 2021-04-21 14:14:45.541 [TRC] CORE:2[dcr]: Fees rate limit set at 100 atoms/byte 2021-04-21 14:14:45.541 [TRC] CORE:2[dcr]: Redeem conf target set to 1 blocks 2021-04-21 14:14:45.541 [INF] CORE:2[dcr]: Setting up new DCR wallet at 127.0.0.1:19582 with TLS certificate "/home/joe/dextest/dcr/trading2/rpc.cert". 2021-04-21 14:14:45.542 [INF] CORE:2[dcr]: Connected to Decred wallet at 127.0.0.1:19582 2021-04-21 14:14:45.543 [INF] CORE:2[dcr]: Connected to dcrwallet (JSON-RPC API v8.5.0) proxying dcrd (JSON-RPC API v6.2.0) on SimNet 2021-04-21 14:14:45.548 [INF] CORE:2: Created dcr wallet. Balance available = 167299927202 / locked = 0 / locked in contracts = 0, Deposit address = Sss12jCfmkSWvFV56CrcBXdubesTDKLheBR 2021-04-21 14:14:45.548 [TRC] CORE:2: notify: |DATA| (walletstate) 2021-04-21 14:14:45.548 [INF] TEST: [client 2] Connected dcr wallet 2021-04-21 14:14:45.567 [INF] CORE:2[btc]: Setting up new btc wallet at localhost:20556/wallet/gamma. 2021-04-21 14:14:45.567 [TRC] CORE:2[btc]: Fallback fees set at 100 Satoshis/vbyte 2021-04-21 14:14:45.567 [TRC] CORE:2[btc]: Fees rate limit set at 1400 sats/byte 2021-04-21 14:14:45.567 [TRC] CORE:2[btc]: Redeem conf target set to 2 blocks 2021-04-21 14:14:45.580 [INF] CORE:2: Created btc wallet. Balance available = 44396998317 / locked = 0 / locked in contracts = 0, Deposit address = bcrt1qvukqz9ccsw7cy960t4lmgfepslege37tg2a45q 2021-04-21 14:14:45.580 [TRC] CORE:2: notify: |DATA| (walletstate) 2021-04-21 14:14:45.580 [INF] TEST: [client 2] Connected btc wallet 2021-04-21 14:14:45.604 [DBG] CORE:2: Setting server api version to 0. 2021-04-21 14:14:45.604 [DBG] CORE:2: Server 127.0.0.1:17273 broadcast timeout 1m0s. Tick interval 7.5s 2021-04-21 14:14:45.604 [INF] CORE:2: Connected to DEX server at 127.0.0.1:17273 and listening for messages. 2021-04-21 14:14:45.604 [DBG] CORE:2[wss://127.0.0.1:17273/ws]: Sending close 1000 (normal) message. 2021-04-21 14:14:45.654 [DBG] CORE:2: notify: |POKE| (conn) DEX connected - DEX at 127.0.0.1:17273 has connected 2021-04-21 14:14:45.654 [DBG] CORE:2: Setting server api version to 0. 2021-04-21 14:14:45.654 [DBG] CORE:2: Server 127.0.0.1:17273 broadcast timeout 1m0s. Tick interval 7.5s 2021-04-21 14:14:45.654 [INF] CORE:2: Connected to DEX server at 127.0.0.1:17273 and listening for messages. 2021-04-21 14:14:45.657 [INF] CORE:2: Attempting registration fee payment to Ssh8uPVpejfgdnVkjyh2x9hC1SCpYZurRzg, account ID 3d99f47b6d76006bbdafefdcc31de9d5407ce471c5725a15c16a3e41ea3b6ea0, of 100000000 units of dcr. Do NOT manually send funds to this address even if this fails. 2021-04-21 14:14:45.657 [TRC] CORE:2[dcr]: Obtained local estimate for 1-conf fee rate, 11 2021-04-21 14:14:45.664 [DBG] CORE:2[dcr]: Change output size = 36, addr = SsrryWjoUQTN3KHgiDAPfqsqchuXiN26SSb 2021-04-21 14:14:45.665 [DBG] CORE:2[dcr]: 2 signature cycles to converge on fees for tx 97035ed0618295ab209a8c1a8a58e775ec13c38ec82d9a5c643ef053b1d63f9f: min rate = 11, actual fee rate = 11 (2772 for 252 bytes), change = true 2021-04-21 14:14:45.669 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:14:45.669 [INF] CORE:2: notify: |SUCCESS| (feepayment) Fee payment in progress - Waiting for 1 confirmations before trading at 127.0.0.1:17273 2021-04-21 14:14:45.669 [INF] TEST: [client 2] Sent registration fee to DEX 127.0.0.1:17273 2021-04-21 14:14:45.677 [INF] TEST: [client 2] Mined 1 dcr blocks for fee payment confirmation 2021-04-21 14:14:45.677 [INF] TEST: [client 2] Waiting 1m12s for fee confirmation notice 2021-04-21 14:14:46.424 [DBG] CORE:1[dcr]: tip change: 649 (590314ac4a2f8f0dffd6cc33bbca406b311f92398ec8ddb0250d7cf2c0bde5e8) => 650 (5c15ede825bb992a7305e982ec26b3b72b29fc4e7245ffe650672efb7943818e) 2021-04-21 14:14:46.424 [TRC] CORE:1: processing tip change for dcr 2021-04-21 14:14:46.425 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.544 [DBG] CORE:2[dcr]: tip change: 649 (590314ac4a2f8f0dffd6cc33bbca406b311f92398ec8ddb0250d7cf2c0bde5e8) => 650 (5c15ede825bb992a7305e982ec26b3b72b29fc4e7245ffe650672efb7943818e) 2021-04-21 14:14:46.544 [TRC] CORE:2: processing tip change for dcr 2021-04-21 14:14:46.545 [DBG] CORE:2: Registration fee txn 97035ed0618295ab209a8c1a8a58e775ec13c38ec82d9a5c643ef053b1d63f9f:0 now has 1 confirmations. 2021-04-21 14:14:46.545 [INF] CORE:2: Notifying dex 127.0.0.1:17273 of fee payment. 2021-04-21 14:14:46.546 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.559 [DBG] CORE:2: Authenticated connection to 127.0.0.1:17273, acct 3d99f47b6d76006bbdafefdcc31de9d5407ce471c5725a15c16a3e41ea3b6ea0, 0 active orders, 0 active matches, score 0 2021-04-21 14:14:46.560 [INF] CORE:2: notify: |SUCCESS| (feepayment) Account registered - You may now trade at 127.0.0.1:17273 2021-04-21 14:14:46.678 [INF] TEST: [client 2] Fee payment confirmed 2021-04-21 14:14:46.678 [INF] TEST: === SETUP COMPLETED 2021-04-21 14:14:46.678 [INF] TEST: [client 1] updating balances 2021-04-21 14:14:46.680 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.680 [INF] TEST: [client 1] dcr available 1351.999393, immature 0.000000, locked 0.000000 2021-04-21 14:14:46.681 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.681 [INF] TEST: [client 1] btc available 1360.027471, immature 0.002497, locked 0.000000 2021-04-21 14:14:46.681 [INF] TEST: [client 2] updating balances 2021-04-21 14:14:46.683 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.683 [INF] TEST: [client 2] dcr available 1671.999244, immature 0.000000, locked 0.000000 2021-04-21 14:14:46.684 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.684 [INF] TEST: [client 2] btc available 443.969983, immature 0.000000, locked 0.000000 2021-04-21 14:14:46.731 [INF] CORE:1[dcr]: Funding 10 DCR order with coins [e4e5a9bc965e223547cb70d7babd3b3637473cf8d0be55969acdbab65a130ce5:0] worth 24 2021-04-21 14:14:46.739 [DBG] CORE:1: notify: |POKE| (order) Order placed - selling 10.00000000 dcr, rate = 0.00025000 (5e0f317e) - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:14:46.740 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.740 [INF] TEST: [client 1] placed order selling 10.00000000 dcr at 0.00025000 btc/dcr (5e0f317eb828e643) 2021-04-21 14:14:46.770 [DBG] CORE:2[btc]: Attempting to fund order for 0.0025 btc, maxFeeRate = 100, max swaps = 1 2021-04-21 14:14:46.783 [INF] CORE:2[btc]: Funding 0.0025 btc order with coins [f7e82027e87dffe5ca64beab0217a5c77c7f10391d477086e4ef3bafd1b5a04f:1] worth 0.96998317 2021-04-21 14:14:46.791 [DBG] CORE:2: notify: |POKE| (order) Order placed - buying 10.00000000 dcr, rate = 0.00025000 (b16a516b) - Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:14:46.792 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:14:46.792 [INF] TEST: [client 2] placed order buying 10.00000000 dcr at 0.00025000 btc/dcr (b16a516b33c8142b) 2021-04-21 14:14:46.792 [INF] TEST: [client 2] Waiting up to 30s for matches on order b16a516b 2021-04-21 14:14:46.792 [INF] TEST: [client 1] Waiting up to 30s for matches on order 5e0f317e 2021-04-21 14:15:00.000 [DBG] CORE:2: Received preimage request for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 with known commitment ee5bd866c9a3071f00f40d7a0fda6fea49f491b73460f454a3363c014f8a0455 2021-04-21 14:15:00.001 [TRC] CORE:2: notify: |DATA| (order) preimage sent - Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:15:00.000 [DBG] CORE:1: Received preimage request for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 with known commitment cf908b1e4296b12c8f74180fa1bc24a433ff053087053200ffde7738ceed056a 2021-04-21 14:15:00.001 [DBG] CORE:2: async processPreimageRequest for b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 succeeded 2021-04-21 14:15:00.001 [TRC] CORE:1: notify: |DATA| (order) preimage sent - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:15:00.001 [DBG] CORE:1: async processPreimageRequest for 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 succeeded 2021-04-21 14:15:00.019 [DBG] CORE:1: Registering match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 (Taker) in status NewlyMatched 2021-04-21 14:15:00.019 [DBG] CORE:2: Registering match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 (Maker) in status NewlyMatched 2021-04-21 14:15:00.019 [INF] CORE:2: Starting negotiation for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 with swap fee rate = 1, quantity = 1000000000 2021-04-21 14:15:00.019 [DBG] CORE:2: Trade order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 matched with 1 orders: +1000000000 filled, total fill 1000000000 / 1000000000 (100.0%) 2021-04-21 14:15:00.019 [TRC] CORE:2: notify: |DATA| (match) new_match 2021-04-21 14:15:00.019 [DBG] CORE:2: notify: |POKE| (order) Matches made - Buy order on dcr-btc 100.0% filled (b16a516b) - Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:15:00.019 [INF] CORE:1: Starting negotiation for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 with swap fee rate = 10, quantity = 1000000000 2021-04-21 14:15:00.019 [DBG] CORE:2: Swappable match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 (Maker) 2021-04-21 14:15:00.019 [DBG] CORE:1: Trade order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 matched with 1 orders: +1000000000 filled, total fill 1000000000 / 1000000000 (100.0%) 2021-04-21 14:15:00.019 [TRC] CORE:1: notify: |DATA| (match) new_match 2021-04-21 14:15:00.019 [DBG] CORE:1: notify: |POKE| (order) Matches made - Sell order on dcr-btc 100.0% filled (5e0f317e) - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:15:00.035 [DBG] CORE:2[btc]: Change output size = 31, addr = bcrt1q5xp3csgajg4z940gfhp7czr89awwemma3h7qph 2021-04-21 14:15:00.036 [DBG] CORE:2[btc]: 2 signature cycles to converge on fees for tx 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc: min rate = 1, actual fee rate = 1 (153 for 153 bytes), change = true 2021-04-21 14:15:00.037 [INF] CORE:2: Broadcasted transaction with 1 swap contracts for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227. Fee rate = 1. Receipts (btc): [413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0] 2021-04-21 14:15:00.037 [DBG] CORE:2: Saving change coin 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:1 (btc) to DB for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:15:00.037 [INF] CORE:2: Contract coin 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0 (btc), value = 250000, refundable at 2021-04-21 05:16:00 +0000 UTC (script = 6382012088a82015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914be0f6a066852d5a70e32ddacd5c3f662149197d4670410b57f60b17576a9148eff699170794c78a27af562af5d9cf9453e6f246888ac) 2021-04-21 14:15:00.037 [TRC] CORE:2: Contract coin 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0 secret = 317b09295e6a2c182cd9a9c65426e630af923203299631bc33b25372c209bfe8 2021-04-21 14:15:00.037 [INF] CORE:2: Notifying DEX 127.0.0.1:17273 of our btc swap contract 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0 for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f 2021-04-21 14:15:00.037 [DBG] CORE:2: notify: |POKE| (order) Swaps initiated - Sent swaps worth 0.00250000 btc on order b16a516b - Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:15:00.039 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:00.042 [INF] TEST: [client 1] 1 match(es) received for order 5e0f317e 2021-04-21 14:15:00.042 [INF] TEST: [client 2] 1 match(es) received for order b16a516b 2021-04-21 14:15:00.042 [INF] TEST: [client 1] Taker on match 89119099, amount 10.00000000 dcr 2021-04-21 14:15:00.042 [INF] TEST: [client 2] Maker on match 89119099, amount 10.00000000 dcr 2021-04-21 14:15:00.043 [DBG] CORE:2: Received valid ack for 'init' request for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f 2021-04-21 14:15:00.043 [TRC] CORE:1: Still searching for counterparty's contract coin 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0 (btc) for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f. 2021-04-21 14:15:00.293 [INF] TEST: [client 2] NOW =====> MakerSwapCast 2021-04-21 14:15:00.293 [INF] TEST: [client 2] updated btc balance diff with -0.002500 2021-04-21 14:15:00.293 [INF] TEST: [client 2] trade for order b16a516b, match 89119099 monitored successfully till MakerSwapCast, side Maker 2021-04-21 14:15:00.655 [TRC] CORE:2: Checking match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f (Maker) in status MakerSwapCast. Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227, Refund coin: , Script: 6382012088a82015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914be0f6a066852d5a70e32ddacd5c3f662149197d4670410b57f60b17576a9148eff699170794c78a27af562af5d9cf9453e6f246888ac, Revoked: false 2021-04-21 14:15:00.655 [TRC] CORE:2: Match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f not swappable: swapErr = take no further action, revoked = false, metered = false 2021-04-21 14:15:00.655 [TRC] CORE:2: Match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f not redeemable: swapErr = take no further action, RefundCoin = , metered = false 2021-04-21 14:15:00.657 [INF] CORE:2: Contract for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f with swap coin 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0 (btc) has an expiry time of 2021-04-21 05:16:00 +0000 UTC (59s), not yet expired. 2021-04-21 14:15:04.351 [INF] CORE:1: Audited contract (btc: 413112dde5bbb666124ce58c28f03e8543f6f0dc54d7318bbe3adad0d6dc5fdc:0) paying to bcrt1qhc8k5png2t26wr3jmkkdtslkvg2fr975jal2nd for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0, match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f, with tx data = true 2021-04-21 14:15:04.351 [TRC] CORE:1: notify: |DATA| (match) audit 2021-04-21 14:15:04.544 [INF] TEST: [client 1] NOW =====> MakerSwapCast 2021-04-21 14:15:04.557 [INF] TEST: [client 1] Mined 1 blocks for Maker's swap, match 89119099 2021-04-21 14:15:04.557 [INF] TEST: [client 1] trade for order 5e0f317e, match 89119099 monitored successfully till MakerSwapCast, side Taker 2021-04-21 14:15:04.557 [INF] TEST: [client 1] resumed trade negotiations from MakerSwapCast 2021-04-21 14:15:04.557 [INF] TEST: [client 1] invalidated taker matches, waiting for init request error 2021-04-21 14:15:04.557 [INF] TEST: [client 2] resumed trade negotiations from MakerSwapCast 2021-04-21 14:15:04.575 [DBG] CORE:2[btc]: tip change: 452 (3c393f7d8887ecdd35cf4d5736543eb06724f3ffde1da4e06eec544e5f3f6a20) => 453 (6d9502e456746fc6fb7f4e0b530f348edafc11ecd00021ec4f964183c4d42902) 2021-04-21 14:15:04.575 [TRC] CORE:2: processing tip change for btc 2021-04-21 14:15:04.576 [TRC] CORE:2: notify: |DATA| (match) confirms 2021-04-21 14:15:04.579 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:05.456 [DBG] CORE:1[btc]: tip change: 452 (3c393f7d8887ecdd35cf4d5736543eb06724f3ffde1da4e06eec544e5f3f6a20) => 453 (6d9502e456746fc6fb7f4e0b530f348edafc11ecd00021ec4f964183c4d42902) 2021-04-21 14:15:05.456 [TRC] CORE:1: processing tip change for btc 2021-04-21 14:15:05.457 [TRC] CORE:1: notify: |DATA| (match) counterconfirms 2021-04-21 14:15:05.457 [DBG] CORE:1: Swappable match 663059540ccfbbf1452d689875e978176dcfbec24fc2659a779efa1bc5291060 for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 (Taker) 2021-04-21 14:15:05.464 [DBG] CORE:1[dcr]: Change output size = 36, addr = Ssfz7qxrLhSVWCgWikdentyhtCSumF8BKR5 2021-04-21 14:15:05.466 [DBG] CORE:1[dcr]: 3 signature cycles to converge on fees for tx d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0: min rate = 10, actual fee rate = 10 (2490 for 249 bytes), change = true 2021-04-21 14:15:05.470 [DBG] CORE:1[dcr]: returning coins [e4e5a9bc965e223547cb70d7babd3b3637473cf8d0be55969acdbab65a130ce5:0] 2021-04-21 14:15:05.472 [INF] CORE:1: Broadcasted transaction with 1 swap contracts for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0. Fee rate = 10. Receipts (dcr): [d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:0] 2021-04-21 14:15:05.472 [DBG] CORE:1: Saving change coin d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:1 (dcr) to DB for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:15:05.472 [INF] CORE:1: Contract coin d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:0 (dcr), value = 1000000000, refundable at 2021-04-21 05:15:30 +0000 UTC (script = 6382012088c02015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914c03dc10e25aba5350b361207cbf643be81e2d72c6704f2b47f60b17576a914eeb3cf14ec02d29c44e3ad9406ce9007d883a7d26888ac) 2021-04-21 14:15:05.472 [INF] CORE:1: Notifying DEX 127.0.0.1:17273 of our dcr swap contract d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:0 for match 663059540ccfbbf1452d689875e978176dcfbec24fc2659a779efa1bc5291060 2021-04-21 14:15:05.472 [DBG] CORE:1: notify: |POKE| (order) Swaps initiated - Sent swaps worth 10.00000000 dcr on order 5e0f317e - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:15:05.473 [ERR] CORE:1: notify: |ERROR| (order) Swap error - Error notifying DEX of swap for match 663059540ccfbbf1452d689875e978176dcfbec24fc2659a779efa1bc5291060: error sending 'init' message: rpc error: error code 6: unknown match ID - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:15:05.473 [INF] TEST: [client 1] taker matches restored, now monitoring trade to completion 2021-04-21 14:15:05.473 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:05.474 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:05.724 [INF] TEST: [client 1] NOW =====> TakerSwapCast 2021-04-21 14:15:05.724 [INF] TEST: [client 1] updated dcr balance diff with -10.000000 2021-04-21 14:15:07.155 [TRC] CORE:1: Checking match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f (Taker) in status TakerSwapCast. Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0, Refund coin: , Script: 6382012088c02015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914c03dc10e25aba5350b361207cbf643be81e2d72c6704f2b47f60b17576a914eeb3cf14ec02d29c44e3ad9406ce9007d883a7d26888ac, Revoked: false 2021-04-21 14:15:07.155 [INF] CORE:1: Notifying DEX 127.0.0.1:17273 of our dcr swap contract d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:0 for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f 2021-04-21 14:15:07.156 [TRC] CORE:1: notify: |DATA| (match) confirms 2021-04-21 14:15:07.157 [INF] CORE:1: Contract for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f with swap coin d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:0 (dcr) has an expiry time of 2021-04-21 05:15:30 +0000 UTC (23s), not yet expired. 2021-04-21 14:15:07.160 [DBG] CORE:1: Received valid ack for 'init' request for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f 2021-04-21 14:15:07.161 [INF] CORE:2: Audited contract (dcr: d3c6534694354b74bea61b7f615fd8afb221a0c5b511a0e80ad80ed4a4a324a0:0) paying to SsmskQWKn3KBi9rnx6sS21n33ViQ15c73D9 for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227, match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f, with tx data = true 2021-04-21 14:15:07.161 [TRC] CORE:2: notify: |DATA| (match) audit 2021-04-21 14:15:07.307 [INF] TEST: [client 2] NOW =====> TakerSwapCast 2021-04-21 14:15:07.322 [INF] TEST: [client 2] Mined 1 blocks for Taker's swap, match 89119099 2021-04-21 14:15:07.322 [INF] TEST: [client 2] trade for order b16a516b, match 89119099 monitored successfully till TakerSwapCast, side Maker 2021-04-21 14:15:07.322 [INF] TEST: [client 2] trade paused for maker at TakerSwapCast 2021-04-21 14:15:07.322 [INF] TEST: [client 2] trade resumed for maker, matches invalidated, waiting for redeem request error 2021-04-21 14:15:07.424 [DBG] CORE:1[dcr]: tip change: 650 (5c15ede825bb992a7305e982ec26b3b72b29fc4e7245ffe650672efb7943818e) => 651 (38c94448eae6809c3c6bfa4911edbb647187db66f39ee500ad8b578c31ef881b) 2021-04-21 14:15:07.424 [TRC] CORE:1: processing tip change for dcr 2021-04-21 14:15:07.425 [TRC] CORE:1: notify: |DATA| (match) confirms 2021-04-21 14:15:07.428 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:07.545 [DBG] CORE:2[dcr]: tip change: 650 (5c15ede825bb992a7305e982ec26b3b72b29fc4e7245ffe650672efb7943818e) => 651 (38c94448eae6809c3c6bfa4911edbb647187db66f39ee500ad8b578c31ef881b) 2021-04-21 14:15:07.545 [TRC] CORE:2: processing tip change for dcr 2021-04-21 14:15:07.546 [TRC] CORE:2: notify: |DATA| (match) counterconfirms 2021-04-21 14:15:07.546 [DBG] CORE:2: Redeemable match a474460cd8413e8772cdacb4331b15906438bf619e4a7703eff9eed182b9cdae for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 (Maker) 2021-04-21 14:15:07.548 [TRC] CORE:2[dcr]: Obtained local estimate for 1-conf fee rate, 11 2021-04-21 14:15:07.554 [INF] CORE:2: Broadcasted redeem transaction spending 1 contracts for order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227, paying to 4c505da2472a9448df7711790f1677834897d0cbe8108ebf33a6a244b4accd0f:0 (dcr) 2021-04-21 14:15:07.554 [INF] CORE:2: Match a474460cd8413e8772cdacb4331b15906438bf619e4a7703eff9eed182b9cdae complete: buy 1000000000 dcr 2021-04-21 14:15:07.554 [INF] CORE:2: Notifying DEX 127.0.0.1:17273 of our dcr swap redemption 4c505da2472a9448df7711790f1677834897d0cbe8108ebf33a6a244b4accd0f:0 for match a474460cd8413e8772cdacb4331b15906438bf619e4a7703eff9eed182b9cdae 2021-04-21 14:15:07.554 [DBG] CORE:2: notify: |POKE| (order) Match complete - Redeemed 10.00000000 dcr on order b16a516b - Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:15:07.556 [ERR] CORE:2: notify: |ERROR| (order) Swap error - Error notifying DEX of redemption for match a474460cd8413e8772cdacb4331b15906438bf619e4a7703eff9eed182b9cdae: error sending 'redeem' message: rpc error: error code 6: unknown match ID - Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227 2021-04-21 14:15:07.556 [INF] TEST: [client 2] maker matches restored, now monitoring trade to completion 2021-04-21 14:15:07.556 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:07.557 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:07.807 [INF] TEST: [client 2] NOW =====> MakerRedeemed 2021-04-21 14:15:07.807 [INF] TEST: [client 2] updated dcr balance diff with +10.000000 2021-04-21 14:15:07.926 [INF] TEST: [client 2] Mined 1 blocks for Maker's redeem, match 89119099 2021-04-21 14:15:08.154 [TRC] CORE:2: Checking match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f (Maker) in status MakerRedeemed. Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227, Refund coin: , Script: 6382012088a82015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914be0f6a066852d5a70e32ddacd5c3f662149197d4670410b57f60b17576a9148eff699170794c78a27af562af5d9cf9453e6f246888ac, Revoked: false 2021-04-21 14:15:08.155 [INF] CORE:2: Notifying DEX 127.0.0.1:17273 of our dcr swap redemption 4c505da2472a9448df7711790f1677834897d0cbe8108ebf33a6a244b4accd0f:0 for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f 2021-04-21 14:15:08.159 [DBG] CORE:2: Received valid ack for 'redeem' request for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f) 2021-04-21 14:15:08.162 [INF] CORE:1: Notified of maker's redemption (dcr: 4c505da2472a9448df7711790f1677834897d0cbe8108ebf33a6a244b4accd0f:0) and validated secret for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0... 2021-04-21 14:15:08.162 [DBG] CORE:1: Redeemable match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 (Taker) 2021-04-21 14:15:08.166 [TRC] CORE:1[btc]: Obtained local estimate for 2-conf fee rate, 2 2021-04-21 14:15:08.173 [INF] CORE:1: Broadcasted redeem transaction spending 1 contracts for order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0, paying to 5fd913846accfd01e81f1ba154573db2ccda3e470fe2899a132e14defe8fc3fe:0 (btc) 2021-04-21 14:15:08.173 [INF] CORE:1: Match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f complete: sell 1000000000 dcr 2021-04-21 14:15:08.173 [INF] CORE:1: Notifying DEX 127.0.0.1:17273 of our btc swap redemption 5fd913846accfd01e81f1ba154573db2ccda3e470fe2899a132e14defe8fc3fe:0 for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f 2021-04-21 14:15:08.173 [DBG] CORE:1: notify: |POKE| (order) Match complete - Redeemed 0.00250000 btc on order 5e0f317e - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:15:08.175 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:08.176 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:08.224 [INF] TEST: [client 1] NOW =====> MatchComplete 2021-04-21 14:15:08.224 [INF] TEST: [client 1] updated btc balance diff with +0.002500 2021-04-21 14:15:08.246 [INF] TEST: [client 1] Mined 1 blocks for Taker's redeem, match 89119099 2021-04-21 14:15:08.246 [INF] TEST: [client 1] trade for order 5e0f317e, match 89119099 monitored successfully till MatchComplete, side Taker 2021-04-21 14:15:08.306 [INF] TEST: [client 2] NOW =====> MatchComplete 2021-04-21 14:15:08.306 [INF] TEST: [client 2] updated dcr balance diff with +10.000000 2021-04-21 14:15:08.424 [DBG] CORE:1[dcr]: tip change: 651 (38c94448eae6809c3c6bfa4911edbb647187db66f39ee500ad8b578c31ef881b) => 652 (4b52b250fa4f44228d81c268a1b3b1de662c0c3b1a1a459ee4c70bac9f9efd97) 2021-04-21 14:15:08.424 [TRC] CORE:1: processing tip change for dcr 2021-04-21 14:15:08.425 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:08.456 [DBG] CORE:1[btc]: tip change: 453 (6d9502e456746fc6fb7f4e0b530f348edafc11ecd00021ec4f964183c4d42902) => 454 (1c8bc29e032ba19f9321d926f09220c93d8aa122fdb5ea7e3cedbcbdb304f393) 2021-04-21 14:15:08.456 [TRC] CORE:1: processing tip change for btc 2021-04-21 14:15:08.458 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:08.541 [INF] TEST: [client 2] Mined 1 blocks for Maker's redeem, match 89119099 2021-04-21 14:15:08.541 [INF] TEST: [client 2] trade for order b16a516b, match 89119099 monitored successfully till MatchComplete, side Maker 2021-04-21 14:15:08.544 [DBG] CORE:2[dcr]: tip change: 651 (38c94448eae6809c3c6bfa4911edbb647187db66f39ee500ad8b578c31ef881b) => 652 (4b52b250fa4f44228d81c268a1b3b1de662c0c3b1a1a459ee4c70bac9f9efd97) 2021-04-21 14:15:08.544 [TRC] CORE:2: processing tip change for dcr 2021-04-21 14:15:08.545 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:08.574 [DBG] CORE:2[btc]: tip change: 453 (6d9502e456746fc6fb7f4e0b530f348edafc11ecd00021ec4f964183c4d42902) => 454 (1c8bc29e032ba19f9321d926f09220c93d8aa122fdb5ea7e3cedbcbdb304f393) 2021-04-21 14:15:08.574 [TRC] CORE:2: processing tip change for btc 2021-04-21 14:15:08.576 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.424 [DBG] CORE:1[dcr]: tip change: 652 (4b52b250fa4f44228d81c268a1b3b1de662c0c3b1a1a459ee4c70bac9f9efd97) => 653 (19a6084ac1f7b2af8d7aa13ef405f75432bd494e2c2972c1e5892716fcfa620b) 2021-04-21 14:15:09.424 [TRC] CORE:1: processing tip change for dcr 2021-04-21 14:15:09.425 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.542 [INF] TEST: [client 1] updating balances 2021-04-21 14:15:09.544 [DBG] CORE:2[dcr]: tip change: 652 (4b52b250fa4f44228d81c268a1b3b1de662c0c3b1a1a459ee4c70bac9f9efd97) => 653 (19a6084ac1f7b2af8d7aa13ef405f75432bd494e2c2972c1e5892716fcfa620b) 2021-04-21 14:15:09.544 [TRC] CORE:2: processing tip change for dcr 2021-04-21 14:15:09.544 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.544 [INF] TEST: [client 1] btc available 1360.029969, immature 0.002497, locked 0.000000 2021-04-21 14:15:09.545 [TRC] CORE:1: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.545 [INF] TEST: [client 1] dcr available 1341.999369, immature 0.000000, locked 0.000000 2021-04-21 14:15:09.545 [INF] TEST: [client 1] dcr balance change -10.00002490 is in expected range of -11.00000000 - -10.00000000 2021-04-21 14:15:09.545 [INF] TEST: [client 1] btc balance change 0.00249714 is in expected range of -0.99750000 - 0.00250000 2021-04-21 14:15:09.545 [INF] TEST: [client 2] updating balances 2021-04-21 14:15:09.545 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.547 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.547 [INF] TEST: [client 2] dcr available 1681.999206, immature 0.000000, locked 0.000000 2021-04-21 14:15:09.548 [TRC] CORE:2: notify: |DATA| (balance) balance updated 2021-04-21 14:15:09.548 [INF] TEST: [client 2] btc available 443.967482, immature 0.000000, locked 0.000000 trade_simnet_test.go:823: [client 2] dcr balance change not in expected range 19.00000000 - 20.00000000, got 9.99996150 2021-04-21 14:15:09.548 [DBG] CORE:1: notify: |POKE| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected 2021-04-21 14:15:09.548 [DBG] CORE:1[wss://127.0.0.1:17273/ws]: Sending close 1000 (normal) message. 2021-04-21 14:15:09.548 [DBG] CORE:2: notify: |POKE| (conn) DEX disconnected - DEX at 127.0.0.1:17273 has disconnected 2021-04-21 14:15:09.548 [DBG] CORE:2[wss://127.0.0.1:17273/ws]: Sending close 1000 (normal) message. 2021-04-21 14:15:09.548 [TRC] CORE:2: Checking match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f (Maker) in status MatchComplete. Order: b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227, Refund coin: , Script: 6382012088a82015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914be0f6a066852d5a70e32ddacd5c3f662149197d4670410b57f60b17576a9148eff699170794c78a27af562af5d9cf9453e6f246888ac, Revoked: false 2021-04-21 14:15:09.548 [DBG] CORE:2: Retiring inactive order b16a516b33c8142bac20457f019a7dd231804beef2550df155fa02cd37104227. Unlocking coins = false 2021-04-21 14:15:09.548 [INF] CORE:2: Locking DCR wallet 2021-04-21 14:15:09.549 [INF] CORE:2: Locking BTC wallet 2021-04-21 14:15:09.549 [INF] CORE:2: DEX client core off 2021-04-21 14:16:08.175 [ERR] CORE:1: notify: |ERROR| (order) Swap error - Error notifying DEX of redemption for match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f: error sending 'redeem' message: timed out waiting for "redeem" response - Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 2021-04-21 14:16:08.175 [TRC] CORE:1: Checking match 8911909925e1fc2acc0f1b7401242a26d92212f0aac326f559c4a804fdeb2f3f (Taker) in status MatchComplete. Order: 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0, Refund coin: , Script: 6382012088c02015a31ab7a8280b5a581d57f6034caab1189f03e0319b057144d0c256e33465c68876a914c03dc10e25aba5350b361207cbf643be81e2d72c6704f2b47f60b17576a914eeb3cf14ec02d29c44e3ad9406ce9007d883a7d26888ac, Revoked: false 2021-04-21 14:16:08.175 [WRN] CORE:1: Shutting down with active order 5e0f317eb828e6430350effa950933576d8cb7ad0c17d174969086f0c1ed4ba0 in status executed. 2021-04-21 14:16:08.175 [INF] CORE:1: Locking DCR wallet 2021-04-21 14:16:08.176 [INF] CORE:1: Locking BTC wallet 2021-04-21 14:16:08.177 [INF] CORE:1: DEX client core off 2021-04-21 14:16:08.177 [INF] TEST: [client 1] Client 1 done 2021-04-21 14:16:08.177 [INF] TEST: [client 2] Client 2 done --- FAIL: TestResendPendingRequests (83.83s) FAIL exit status 1 FAIL decred.org/dcrdex/client/core 83.871s ```
JoeGruffins commented 3 years ago

It looks like the expected range is +10 randomly for some reason...

JoeGruffins commented 3 years ago

I'm guessing monitorTrackedTrade Is doing recordBalanceChanges one too many times sometimes. You can see updated dcr balance diff with +10.000000 printing twice when it fails. Will look into it more tomorrow unless someone else has the answer.

JoeGruffins commented 3 years ago

It fails when client 2 makes it to NOW =====> MakerRedeemed which is sometimes.

JoeGruffins commented 3 years ago

Hit again... So not solved.

itswisdomagain commented 3 years ago

Had that quite recently. Resolved with this commit. Can you confirm if that solves it for you?

JoeGruffins commented 3 years ago

@itswisdomagain I'll let you know after I run them a few more times.

JoeGruffins commented 3 years ago

Was able to hit while testing #1192:

    trade_simnet_test.go:885: [client 2] dcr balance change not in expected range 39.00000000 - 40.00000000, got 19.99996150
...
--- FAIL: TestTradeSuccess (15.14s)
JoeGruffins commented 2 years ago

I'm quite sure this was a result of missing some statuses which should be fixed with #1909