Skip to content

app: auto-find redemption when Maker goes dark after Taker swap#513

Merged
chappjc merged 15 commits into
decred:masterfrom
itswisdomagain:auto-find-redemption
Sep 3, 2020
Merged

app: auto-find redemption when Maker goes dark after Taker swap#513
chappjc merged 15 commits into
decred:masterfrom
itswisdomagain:auto-find-redemption

Conversation

@itswisdomagain
Copy link
Copy Markdown
Member

@itswisdomagain itswisdomagain commented Jul 1, 2020

Auto-trigger find redemption for Taker swaps that have gotten at least swapConf confirmations, has neither been redeemed by Maker or refunded to Taker.

The FindRedemption method is refactored to allow batching multiple contract coin ids in one call.

The dcr and btc implementations of the FindRedemption method are also modified to push find redemption requests to a goroutine dedicated to scanning blocks for potential contract spends.

There are 2 motivations for using a separate goroutine for processing find redemption requests:

  • enable loading block txs once for multiple contracts (including multiple batches of contracts from different calls to FindRedemption)
  • keeping the redemption search alive when a contract's spender is not found up till the current best block. When that occurs, the goroutine persistently waits for new blocks and searches them for spending information until all contracts's redemption info are found. Previously, FindRedemption returns "redemption not found" error for such contracts and if the client recalls FindRedemption at a later time, the FindRedemption method rescans blocks that were scanned in the previous attempt.

@chappjc chappjc added the client label Jul 2, 2020
@itswisdomagain itswisdomagain force-pushed the auto-find-redemption branch 2 times, most recently from f684a91 to d72864f Compare July 9, 2020 19:19
@itswisdomagain
Copy link
Copy Markdown
Member Author

Sample test run for maker ghost after redeem
=== RUN   TestTrading/maker_ghost_after_redeem                                                                                                      
2020-07-09 23:07:33.148 [INF] TEST: [client 1] unlocking wallets                                                                                    
2020-07-09 23:07:33.670 [INF] TEST: [client 1] updating balances                                                                                    
2020-07-09 23:07:33.692 [INF] TEST: [client 2] unlocking wallets                                                                                    
2020-07-09 23:07:34.239 [INF] TEST: [client 2] updating balances                                                                                    
2020-07-09 23:07:34.743 [INF] TEST: [client 1] placed order selling 5.00000000 dcr at 0.00025000 btc/dcr (3f96c17d)                                 
2020-07-09 23:07:34.956 [INF] TEST: [client 2] placed order buying 5.00000000 dcr at 0.00025000 btc/dcr (5ef5b58a)                                  
2020-07-09 23:07:34.956 [INF] TEST: [client 2] Waiting 12s for matches on order 5ef5b58a                                                            
2020-07-09 23:07:34.970 [INF] TEST: [client 1] Waiting 12s for matches on order 3f96c17d                                                            
2020-07-09 23:07:36.041 [INF] TEST: [client 2] 1 match(es) received for order 5ef5b58a                                                              
2020-07-09 23:07:36.041 [INF] TEST: [client 2] Maker on match eabdfbaa, amount 5.00000000 dcr                                                       
2020-07-09 23:07:36.042 [INF] TEST: [client 1] 1 match(es) received for order 3f96c17d                                                              
2020-07-09 23:07:36.042 [INF] TEST: [client 1] Taker on match eabdfbaa, amount 5.00000000 dcr                                                       
2020-07-09 23:07:36.107 [INF] TEST: [client 2] NOW =====> MakerSwapCast                                                                             
2020-07-09 23:07:37.120 [INF] TEST: [client 2] Mined 1 blocks for Maker's swap, match eabdfbaa                                                      
2020-07-09 23:07:37.120 [INF] TEST: [client 2] updated btc balance diff with -0.001250                                                              
2020-07-09 23:07:38.555 [INF] TEST: [client 1] NOW =====> MakerSwapCast                                                                             
2020-07-09 23:07:38.624 [INF] TEST: [client 1] NOW =====> TakerSwapCast                                                                             
2020-07-09 23:07:38.629 [INF] TEST: [client 2] NOW =====> TakerSwapCast                                                                             
2020-07-09 23:07:39.640 [INF] TEST: [client 1] Mined 1 blocks for Taker's swap, match eabdfbaa                                                      
2020-07-09 23:07:39.640 [INF] TEST: [client 1] updated dcr balance diff with -5.000000                                                              
2020-07-09 23:07:39.640 [INF] TEST: [client 2] b0bf0a78: trade TakerSwapCast paused at %!s(MISSING)                                                 
2020-07-09 23:07:39.640 [INF] TEST: [client 2] Maker: disconnecting DEX before redeeming Taker's swap                                               
2020-07-09 23:07:39.644 [INF] TEST: [client 1] a4b83252: trade TakerSwapCast paused at %!s(MISSING)                                                 
2020-07-09 23:07:40.142 [ERR] CORE: notify: |ERROR| (order) Redemption error - Error encountered sending redemptions worth 5.00000000 dcr on order 5ef5b58a - Order: 5ef5b58a7499be7b136d101923394004e98ec1cb84d8a1b1c0c4a82615995351
2020-07-09 23:07:40.143 [ERR] CORE: 127.0.0.1:17273 tick error: 127.0.0.1:17273 tick: redeemMatches - order 5ef5b58a7499be7b136d101923394004e98ec1cb84d8a1b1c0c4a82615995351 - error sending 'redeem' message for match eabdfbaa78203d25b8e18a7f6349b30d3c3b278b7de961920d677112a9b75ab3: cannot send on a broken connection
2020-07-09 23:07:40.143 [INF] TEST: [client 2] NOW =====> MakerRedeemed
2020-07-09 23:07:41.179 [INF] TEST: [client 2] Mined 1 blocks for Maker's redeem, match eabdfbaa
2020-07-09 23:07:41.179 [INF] TEST: [client 2] updated dcr balance diff with +5.000000
2020-07-09 23:07:41.862 [INF] TEST: [client 1] NOW =====> MakerRedeemed
2020-07-09 23:07:50.090 [ERR] CORE: notify: |ERROR| (order) Redemption error - Error encountered sending redemptions worth 0.00125000 btc on order 3f96c17d - Order: 3f96c17d80ce5f338dec15cb5c2d4ff8380680b79722041971aaa47ad4e3b24f
2020-07-09 23:07:50.090 [ERR] CORE: 127.0.0.1:17273 tick: redeemMatches - order 3f96c17d80ce5f338dec15cb5c2d4ff8380680b79722041971aaa47ad4e3b24f - error sending 'redeem' message for match eabdfbaa78203d25b8e18a7f6349b30d3c3b278b7de961920d677112a9b75ab3: rpc error: 25: expected other party to act
2020-07-09 23:07:50.090 [INF] TEST: [client 1] NOW =====> MatchComplete
2020-07-09 23:07:51.096 [INF] TEST: [client 1] Mined 1 blocks for Taker's redeem, match eabdfbaa
2020-07-09 23:07:51.096 [INF] TEST: [client 1] updated btc balance diff with +0.001250
2020-07-09 23:07:52.097 [INF] TEST: [client 1] updating balances
2020-07-09 23:07:52.108 [INF] TEST: [client 1] dcr balance change -5.00002500 is in expected range of -6.00000000 - -5.00000000
2020-07-09 23:07:52.108 [INF] TEST: [client 1] btc balance change 0.00099160 is in expected range of -0.99875000 - 0.00125000
2020-07-09 23:07:52.108 [INF] TEST: [client 2] updating balances
2020-07-09 23:07:52.139 [INF] TEST: [client 2] dcr balance change 4.99971650 is in expected range of 4.00000000 - 5.00000000
2020-07-09 23:07:52.139 [INF] TEST: [client 2] btc balance change -0.00147300 is in expected range of -1.00125000 - -0.00125000
2020-07-09 23:07:52.139 [INF] TEST: Trades completed. Maker went dark at MakerRedeemed, Taker continued till MatchComplete.
--- PASS: TestTrading (23.60s)
    --- PASS: TestTrading/maker_ghost_after_redeem (18.99s)
PASS
ok      decred.org/dcrdex/client/core   23.675s

@itswisdomagain itswisdomagain force-pushed the auto-find-redemption branch from 754fa7d to a4f992b Compare July 9, 2020 23:37
Comment thread client/core/trade_simnet_test.go Outdated
@itswisdomagain itswisdomagain marked this pull request as ready for review July 16, 2020 00:54
Copy link
Copy Markdown
Member

@chappjc chappjc left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

You mentioned the complexity added with the new async design, and I do think it is too complex. We should explore other ways to make FindRedemption not blocking, but the always-running goroutine isn't ideal. I've noted that the loop in that goroutine just spins presently.

I'm ok with FindRedemption starting a goroutine, perhaps with a findRedemptionReq slice as an input to the goroutine.

Comment thread client/asset/btc/btc.go Outdated
@itswisdomagain itswisdomagain marked this pull request as draft August 1, 2020 09:17
@chappjc
Copy link
Copy Markdown
Member

chappjc commented Aug 10, 2020

I'd like to prioritize this PR over #589 unless that creates a challenge.

@itswisdomagain
Copy link
Copy Markdown
Member Author

Yeah, been meaning to get back on this. Will revisit in < 24 hrs and clean it up.

Comment thread client/asset/dcr/dcr.go Outdated
@itswisdomagain itswisdomagain force-pushed the auto-find-redemption branch 3 times, most recently from e2dbfef to 055ec29 Compare August 14, 2020 03:36
@itswisdomagain
Copy link
Copy Markdown
Member Author

itswisdomagain commented Aug 14, 2020

I feel better about the FindRedemption flow now, but looks like #589 is gonna have to get in first so I can re-run the findredemption simnet tests to verify all is good before marking this ready for review. Actually both #589 and #548 will need to go in for trade simnet tests to pass.

@itswisdomagain itswisdomagain force-pushed the auto-find-redemption branch 4 times, most recently from d3b8b4b to c0ef178 Compare August 19, 2020 00:44
@itswisdomagain itswisdomagain marked this pull request as ready for review August 19, 2020 00:47
Copy link
Copy Markdown
Member

@chappjc chappjc left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I'm still considering the role of Core vs trackedTrade in the goroutine mgmt, but some suggestions...

Comment thread client/asset/interface.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/dcr/dcr.go Outdated
Comment thread client/asset/dcr/dcr.go Outdated
Comment thread client/asset/dcr/dcr.go Outdated
Comment thread client/asset/dcr/dcr.go Outdated
Comment thread client/asset/dcr/dcr.go Outdated
Comment thread client/core/trade.go Outdated
Comment thread client/core/trade.go
Comment thread client/core/trade.go Outdated
@itswisdomagain
Copy link
Copy Markdown
Member Author

itswisdomagain commented Aug 22, 2020

I rebased over master for go 1.15 checks and refactored the FindRedemption methods to accept single swap coin IDs instead of in batches and return a result chan. Also added code in the asset shutdown methods to close open channels when ctx is canceled. Code isn't ridiculously simple but reads better to me.

I might be able to further improve the FindRedemption implementation on dcr by using cfilters to determine the blocks that likely spend a contract and only fetch txs for those blocks. Will wait for review first.

Oh, there's one more stuff for me to look into - determining the block to begin scanning from on re-orgs.

Copy link
Copy Markdown
Member

@JoeGruffins JoeGruffins left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This review isn't complete. Will finish asap, just posting what I've got so far.

Comment thread client/asset/btc/btc.go
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Copy link
Copy Markdown
Member

@JoeGruffins JoeGruffins left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Continued. I skipped over client/asset/dcr as it looked similar to client/asset/btc, and my comments would probably be similar.

Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/asset/btc/btc.go Outdated
Comment thread client/core/trade.go Outdated
Comment thread client/core/trade.go Outdated
Comment thread client/core/trade.go Outdated
Comment thread client/core/trade.go Outdated
Comment thread client/core/trade.go Outdated
@itswisdomagain
Copy link
Copy Markdown
Member Author

I'll be taking off the last commit in this branch (9d6b684) as the buck of the changes there do not directly relate to this PR. I've moved those bits to a new PR to be reviewed separately.

Until that PR is finalized though, and given that auto-redemption should only be performed on revoked matches, there's a chance the auto-redemption and auto-refund will not be performed for some revoked matches, if the revoke_match request is not received.

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 1, 2020

Are you saying that refund and auto-redeem won't even be possible without a revoke_match? refunds at least were able to happen regardless of setting it as revoked, as long as lock time expired. And as for auto-redeems, we want to get some trades unstuck that are in just this case where no revoke_match messages was received (sent while offline). Can a reasonable delay be implemented simply to get by this until match_status? EDIT: I guess I'm ok with just setting missing matches revoked as in f414d47 for this PR, but I do think that refunds should continue to work as long as lock time is expired regardless of revoked status being known.

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 1, 2020

Tried the harness test, but ended up with

--- FAIL: TestTrading (24.85s)
    --- FAIL: TestTrading/success (15.51s)
        trade_simnet_test.go:205: btc balance change not in expected range -1.00180000 - -0.00180000, got 0.04816178

Confirmed on fresh harnesses. Is this related to #648?

Not sure if there's a critical missing unlock, but one possible issue is letting the dcrdex server harness open the markets on the first full epoch. @JoeGruffins brought this to light and I added a message from MKT like [INF] MKT: Market dcr_btc now accepting orders, epoch 106598031:15000.

However, it's not working for me either:

2020-09-01 09:31:12.091 [ERR] CORE: failed to start redemption search for match 2d87b63211331abe0ff0c3fcf516a0c7c95ceb15f9bc986550df9a2a4cdc0d0f, btc contract 376a4fbe0fb04ec5d51d459c59dc61b6d132a0c152e3f58d1399666fca7b16e8:0: invalid contract tx hex: EOF
2020-09-01 09:31:32.086 [TRC] CORE: Checking match 2d87b63211331abe0ff0c3fcf516a0c7c95ceb15f9bc986550df9a2a4cdc0d0f (Taker) in status TakerSwapCast. Order: f48f42125dc062fb6f231bfe0c3d6ca859e61ded5a79d492f13f7c76a7b08cee, Refund coin: , Script: 6382012088a820e489f91c42bb66de686d965de007fa513747987622d17fee3768b9512605c2de8876a9141e019f9c50d484c95c03a2549c8c953fd97a1c096704e85a4e5fb17576a9144df5ba976fe56db170f4540358d0d3cdf11b62776888ac
2020-09-01 09:31:32.087 [TRC] CORE: Match 2d87b63211331abe0ff0c3fcf516a0c7c95ceb15f9bc986550df9a2a4cdc0d0f not swappable: failErr = <nil>, revoked = true
2020-09-01 09:31:32.089 [DBG] CORE: Ready to find counter-party redemption for match 2d87b63211331abe0ff0c3fcf516a0c7c95ceb15f9bc986550df9a2a4cdc0d0f, order f48f42125dc062fb6f231bfe0c3d6ca859e61ded5a79d492f13f7c76a7b08cee (Taker)
2020-09-01 09:31:32.091 [ERR] CORE: failed to start redemption search for match 2d87b63211331abe0ff0c3fcf516a0c7c95ceb15f9bc986550df9a2a4cdc0d0f, btc contract 376a4fbe0fb04ec5d51d459c59dc61b6d132a0c152e3f58d1399666fca7b16e8:0: invalid contract tx hex: EOF
2020-09-01 09:31:33.294 [INF] TEST: [client 2] incomplete trade: order f48f4212, match b34285f9, status TakerSwapCast, side Taker
    trade_simnet_test.go:310: client 2 reported 1 incomplete trades for order f48f4212 after 2m0s
--- FAIL: TestTrading (225.02s)
    --- PASS: TestTrading/no_maker_redeem (82.40s)
    --- FAIL: TestTrading/maker_ghost_after_redeem (138.04s)

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 1, 2020

Got it to work, but it doesn't seem perfectly robust:

2020-09-01 10:02:22.668 [INF] TEST: Trades completed. Maker went dark at MakerRedeemed, Taker continued till MatchComplete.
--- PASS: TestTrading (268.70s)
    --- PASS: TestTrading/success (14.44s)
    --- PASS: TestTrading/no_maker_swap (3.75s)
    --- PASS: TestTrading/no_taker_swap (84.08s)
    --- PASS: TestTrading/no_maker_redeem (80.00s)
    --- PASS: TestTrading/maker_ghost_after_redeem (81.91s)

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 1, 2020

Something seems off with tip change:

2020-09-01 10:37:02.642 [INF] TEST: [client 2] Mined 2 blocks for Taker's swap, match 9a887a98
2020-09-01 10:37:03.339 [DBG] CORE[dcr]: tip change: 188 (000bbce29ec8206db97ee1fc323ba02d77cc44bf3662a8642ac9b1526038ac92) => 189 (001a8ec50a13de71a1d5557975995517b7131a04be26f22747d08f5562c41941)
2020-09-01 10:37:03.339 [TRC] CORE: processing tip change for dcr
2020-09-01 10:37:03.341 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-09-01 10:37:03.573 [DBG] CORE[dcr]: tip change: 188 (000bbce29ec8206db97ee1fc323ba02d77cc44bf3662a8642ac9b1526038ac92) => 190 (0019455a0a5129816ffca0ba3e246d4e57e599f4759e0cae3b3122280a390aa9)
2020-09-01 10:37:03.573 [TRC] CORE: processing tip change for dcr

2020-09-01 10:37:04.339 [DBG] CORE[dcr]: tip change: 189 (001a8ec50a13de71a1d5557975995517b7131a04be26f22747d08f5562c41941) => 191 (0014215179af8b39d6345bc38822395ebbbf3b1905c7a47d4fda1e06f705086f)
2020-09-01 10:37:04.339 [TRC] CORE: processing tip change for dcr
2020-09-01 10:37:04.573 [DBG] CORE[dcr]: tip change: 190 (0019455a0a5129816ffca0ba3e246d4e57e599f4759e0cae3b3122280a390aa9) => 191 (0014215179af8b39d6345bc38822395ebbbf3b1905c7a47d4fda1e06f705086f)
2020-09-01 10:37:04.573 [TRC] CORE: processing tip change for dcr
2020-09-01 10:37:04.574 [TRC] CORE: notify: |DATA| (balance) balance updated

2020-09-01 10:37:10.399 [DBG] CORE[btc]: tip change: 212 (14a0b9f80e4dc00ffc8b544d1bcf1c0efc2234e565a13e593a1c6764380b4b8f) => 214 (693adc1aa66694e3ab184f231749b2814b0af299f60129b460e18ea669f25015)
2020-09-01 10:37:10.399 [TRC] CORE: processing tip change for btc
2020-09-01 10:37:10.401 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-09-01 10:37:10.626 [DBG] CORE[btc]: tip change: 212 (14a0b9f80e4dc00ffc8b544d1bcf1c0efc2234e565a13e593a1c6764380b4b8f) => 214 (693adc1aa66694e3ab184f231749b2814b0af299f60129b460e18ea669f25015)
2020-09-01 10:37:10.626 [TRC] CORE: processing tip change for btc
2020-09-01 10:37:10.629 [TRC] CORE: notify: |DATA| (balance) balance update

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 1, 2020

Ahhh, look at the order of the tests in a failing case:

    trade_simnet_test.go:205: btc balance change not in expected range -0.99820000 - 0.00180000, got 0.00302416
--- FAIL: TestTrading (240.79s)
    --- PASS: TestTrading/no_taker_swap (82.20s)
    --- PASS: TestTrading/no_maker_redeem (80.00s)
    --- PASS: TestTrading/maker_ghost_after_redeem (61.92s)
    --- FAIL: TestTrading/success (11.93s)

vs. passing

2020-09-01 10:02:22.668 [INF] TEST: Trades completed. Maker went dark at MakerRedeemed, Taker continued till MatchComplete.
--- PASS: TestTrading (268.70s)
    --- PASS: TestTrading/success (14.44s)
    --- PASS: TestTrading/no_maker_swap (3.75s)
    --- PASS: TestTrading/no_taker_swap (84.08s)
    --- PASS: TestTrading/no_maker_redeem (80.00s)
    --- PASS: TestTrading/maker_ghost_after_redeem (81.91s)

If they must be run in a certain order, that needs to be addressed. Either (1) merge the tests into one, (2) use subtests (t.Run), or (3) modify the test so that they may be run in any order.
EDIT: oh you use subtests, but a map range... that can be fixed easily

Comment thread client/core/trade_simnet_test.go Outdated
@itswisdomagain
Copy link
Copy Markdown
Member Author

Tried the harness test, but ended up with

--- FAIL: TestTrading (24.85s)
    --- FAIL: TestTrading/success (15.51s)
        trade_simnet_test.go:205: btc balance change not in expected range -1.00180000 - -0.00180000, got 0.04816178

Confirmed on fresh harnesses. Is this related to #648?

Haven't narrowed it down but likely. The primary motivation for forcing coin unlocking for spent outputs in #648 was because of #453 and #471. The issue should be fixed now in dcrwallet anyways.

@itswisdomagain
Copy link
Copy Markdown
Member Author

itswisdomagain commented Sep 1, 2020

Are you saying that refund and auto-redeem won't even be possible without a revoke_match?

Yes. A revoke_match request is currently the only way a client knows to abandon natural match negotiations, unless the client is restarted. I do agree with your earlier thought to not take recovery steps such as refunds and auto-redeem unless the server has revoked the match.

refunds at least were able to happen regardless of setting it as revoked, as long as lock time expired.

Yes, and while it is unlikely to happen, if it does happen that a match is not revoked after taker's locktime expires, taker's refund will effectively cause the natural settlement process to fail. In general, I'd prefer to not auto-refund until the match is revoked AND locktime expires. This is not implemented yet though, so refunds will be executed once locktime expires.

And as for auto-redeems, we want to get some trades unstuck that are in just this case where no revoke_match messages was received (sent while offline). Can a reasonable delay be implemented simply to get by this until match_status?

Something like auto-redeem after waiting for taker's redeem X minutes past the time of taker's swap swapConf'th confirms?
UPDATE: It's reasonable to expect that a client will need to reconnect if it missed a revoke_match request. If so, it might be possible to detect revoked matches by comparing known matches with matches returned in the reconnect response .

EDIT: I guess I'm ok with just setting missing matches revoked as in f414d47 for this PR.

Yeah, setting missed matches as revoked is very relevant regardless of the need (or lack thereof) to auto-redeem. Since it's not directly related to this PR, I want to keep it out and add it to say #648 where there's already some work to definitely identify failed matches and revoked orders for the purpose of coin unlocking.

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 1, 2020

Chatted this out in matrix:

  • we are going to keep refunds working regardless of revocation status (lock time expired means match is revoked with near certainty)
  • have connect response set "missing" matches as revoked so these can be auto-redeemed on reconnect or restart
  • no attempts at delay times for auto-redeem, just the revoked flag, which may be set via revoke_match or the missing matches handling in the previous point

@itswisdomagain
Copy link
Copy Markdown
Member Author

If anyone is reviewing right away, one more change left:

  • ensure the redeems search is aborted/removed in all cases

Comment thread client/core/trade.go
dbMatch, metaData, proof, _ := match.parts()
if match.failErr != nil || len(proof.RefundCoin) != 0 {
log.Debugf("Match %v not redeemable: failErr = %v, RefundCoin = %v",
log.Tracef("Match %v not redeemable: failErr = %v, RefundCoin = %v",
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's just be certain that failErr is logged elsewhere when it is set to something non-nil.

Copy link
Copy Markdown
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do you mind if I get to this in a subsequent work? I plan to look into this variable more when working on setting missing matches as revoked, would likely be a good place to do this.

Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sure. It looks like there's a c.notify for any such error anyway.

@itswisdomagain
Copy link
Copy Markdown
Member Author

I've narrowed down the cause of tests failing periodically with unmet btc balance expectations in #658. It's not the order of the tests because even with the new ordered pattern, I've had tests fail at the beginning (TestTrading/success).

Opened that issue to track the bug further and subsequently get a fix in.

@itswisdomagain
Copy link
Copy Markdown
Member Author

itswisdomagain commented Sep 2, 2020

In trackedTrade.revokeMatch

dcrdex/client/core/trade.go

Lines 999 to 1008 in 38443f3

// Send out a data notification with the revoke information.
cancelOrder := &Order{
Host: t.dc.acct.host,
MarketID: t.mktID,
Type: order.CancelOrderType,
Stamp: encode.UnixMilliU(time.Now()),
Epoch: corder.Epoch,
TargetID: corder.ID, // the important part for the frontend
}
t.notify(newOrderNote("revoke", "", db.Data, cancelOrder))

Don't understand why a cancelOrder is created for a revoked match. Revoked matches don't usually have an accompanying cancel order.

Was reading simnet trading test logs when I saw

[WRN] CORE: notify: |WARNING| (order) Match revoked - Match bff390df has been revoked - Order: d987de79998bd3fffcc5039210395b8747eab4f039eae6c515346a04760eae78
[TRC] CORE: notify: |DATA| (order) revoke - Order: 
[WRN] CORE: Match bff390dfc81b90c054c1ccd27483f3655da2f82929988fa9d547fd3c01b727da revoked in status TakerSwapCast for order d987de79998bd3fffcc5039210395b8747eab4f039eae6c515346a04760eae78

And the middle log message stood out.

@itswisdomagain
Copy link
Copy Markdown
Member Author

itswisdomagain commented Sep 2, 2020

Balance check issues should be resolved now.

I modified findRedemptionsInBlockRange to also search mempool if some contract redemptions are not found in the searched block range. Deals with cases where a mined contract is redeemed in a mempool tx.

The auto-redeem simnet tests currently cover a scenario where maker redeems, taker does not receive the redemption details, taker attempts refund because locktime expired on his swap (will need to extend the taker swap locktime to prevent this), the refund failed because the contract txout is spent and so find redemption is triggered even though the match has not been revoked.
The find redemption attempt succeeds and taker is able to redeem maker's swap. Notifying the DEX of taker's redemption returns a expected other party to act error. The redeem request should be resent but won't be resent because the match was marked revoked when maker's redemption was found.

Other scenarios I'll like to test out include:

  • Keeping maker's redemption in mempool to see If taker auto finds it. I ran into this a moment ago and the test failed because taker did not search mempool for redemption of a mined contract.
  • Disable maker redemption, wait for match to be revoked, start finding redemption, wait for locktime to expire, refund, see if find redemption sees the refunds and errors (and the error is properly handled) or gets canceled before it does.

Not necessary to hold this PR up for those anyways, in case I don't get those additional tests in before next review. Can add them subsequently.

@chappjc
Copy link
Copy Markdown
Member

chappjc commented Sep 2, 2020

Since the taker's redeem that follows a successful location of the maker/counterparty redeem and secret is done indirectly (findMakersRedemption sets status to MakerRedeemed, stores the redemption coin ID and secret, and let's the next tick() do the redeem as if it were a normal redeem in the negotiation), we end up with a lot of misleading errors in the log after broadcasting the redeem:

[DBG] CORE: Redeemable match 222d0e90e2a7efef80c69d97afa6de40139636eb321130556b9ee686b1aa0d2d for order 6a8e1bdf1d3108fbe97a89760938f3e18c99cd77b499b5c5bd621a8724ffd566 (Taker)
[INF] CORE: Broadcasted redeem transaction spending 1 contracts for order 6a8e1bdf1d3108fbe97a89760938f3e18c99cd77b499b5c5bd621a8724ffd566, paying to 3501ecf8a03a43c37dc5777967515c21fa8ffb81c4c5ed80dca980f101c5b3cf:0 (btc)
[INF] CORE: Match 222d0e90e2a7efef80c69d97afa6de40139636eb321130556b9ee686b1aa0d2d complete: sell 500000000 dcr
[ERR] CORE: notify: |ERROR| (order) Redemption error - Error encountered sending redemptions worth 0.00125000 btc on order 6a8e1bdf - Order: 6a8e1bdf1d3108fbe97a89760938f3e18c99cd77b499b5c5bd621a8724ffd566
[ERR] CORE: 127.0.0.1:17273 tick: {redeemMatches - order 6a8e1bdf1d3108fbe97a89760938f3e18c99cd77b499b5c5bd621a8724ffd566 - {{error sending 'redeem' message for match 222d0e90e2a7efef80c69d97afa6de40139636eb321130556b9ee686b1aa0d2d: rpc error: error code 26: expected other party to act}}}

This seems to be because after redeemMatches actually does the redeem txn (logging "Broadcasted redeem" above), it goes on to call finalizeRedeemAction, which tries to tell the server about the redeem. Since finalizeRedeemAction has other important actions including setting MatchComplete and the proof.TakerRedeem's coinID and storing the match in DB, I'm wondering if the signAndRequest if else block can be skipped if proof.IsRevoked because there is no reason to send a 'redeem' request to the server when it was not actually requested and/or the match is long revoked.

Copy link
Copy Markdown
Member

@buck54321 buck54321 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I love the blocking FindRedemption. This is go from me. Tested in the wild by modifying a single line at

if !proof.IsRevoked {

to read instead

if !proof.IsRevoked && match.Match.Side == order.Taker {

and then trading with myself. A few minutes after the maker redeemed (a little longer than I expected with broadcast timeout being just 1 minute by default), the server revoked the match, the client marked it as revoked, then at the next tick it successfully redeemed the counter swap.

Comment on lines +235 to +243
// block may get modified concurrently, lock mtx before reading fields.
c.blockchainMtx.RLock()
defer c.blockchainMtx.RUnlock()
return json.Marshal(&verboseBlockTxs{
Hash: block.Hash,
Height: uint64(block.Height),
NextHash: block.NextHash,
Tx: block.RawTx,
})
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Are blocks actually being modified, or just replaced? If it's the latter, the locking isn't needed.

Comment thread client/asset/interface.go
Comment on lines +118 to +120
// NOTE: This could potentially be a long and expensive operation if performed
// long after the swap is broadcast; might be better executed from a goroutine.
FindRedemption(ctx context.Context, coinID dex.Bytes) (redemptionCoin, secret dex.Bytes, err error)
Copy link
Copy Markdown
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This warning is apt, but really it's just a feature of the method that needs standardizing rather than a NOTE:. The description can say something like "FindRedemption blocks until the redemption is found."

@chappjc chappjc merged commit 269ba0b into decred:master Sep 3, 2020
@itswisdomagain itswisdomagain deleted the auto-find-redemption branch September 14, 2020 08:20
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

4 participants