core: don't fail match on misses and redeem errors

* failErr tweaks and default debug logging

* de-group suspect matches. retry until bcast timeout

client/cmd/dexc/ui/config.go

@@ -24,7 +24,7 @@ const (
 	defaultRPCKeyFile  = "rpc.key"
 	defaultWebAddr     = "localhost:5758"
 	configFilename     = "dexc.conf"
-	defaultLogLevel    = "info"
+	defaultLogLevel    = "debug"
 )
 
 var (

client/core/core.go

@@ -44,6 +44,7 @@ const (
 	// regConfirmationsPaid is used to indicate completed registration to
 	// (*Core).setRegConfirms.
 	regConfirmationsPaid uint32 = math.MaxUint32
+	tickCheckDivisions          = 3
 )
 
 var (
@@ -1479,6 +1480,30 @@ func (c *Core) ReconfigureWallet(appPW []byte, assetID uint32, cfg map[string]st
 	details := fmt.Sprintf("Configuration for %s wallet has been updated.", unbip(assetID))
 	c.notify(newWalletConfigNote("Wallet Configuration Updated", details, db.Success, wallet.state()))
 
+	// Clear any existing tickGovernors for suspect matches.
+	c.connMtx.RLock()
+	defer c.connMtx.RUnlock()
+	for _, dc := range c.conns {
+		dc.tradeMtx.RLock()
+		for _, t := range dc.trades {
+			if t.Base() != assetID && t.Quote() != assetID {
+				continue
+			}
+			isFromAsset := t.wallets.fromAsset.ID == assetID
+			t.mtx.Lock()
+			for _, m := range t.matches {
+				if m.tickGovernor != nil &&
+					((m.suspectSwap && isFromAsset) || (m.suspectRedeem && !isFromAsset)) {
+
+					m.tickGovernor.Stop()
+					m.tickGovernor = nil
+				}
+			}
+			t.mtx.Unlock()
+		}
+		dc.tradeMtx.RUnlock()
+	}
+
 	return nil
 }
 
@@ -2733,7 +2758,6 @@ func (c *Core) authDEX(dc *dexConnection) error {
 		for _, match := range missing {
 			c.log.Warnf("DEX %s did not report active match %s on order %s - assuming revoked.",
 				dc.acct.host, match.id, oid)
-			match.failErr = fmt.Errorf("order not reported by the server on connect")
 			// Must have been revoked while we were gone. Flag to allow recovery
 			// and subsequent retirement of the match and parent trade.
 			match.MetaData.Proof.SelfRevoked = true
@@ -3215,22 +3239,24 @@ func (c *Core) resumeTrades(dc *dexConnection, trackers []*trackedTrade) assetMa
 				}
 			}
 			if needsAuditInfo {
+				// Check for unresolvable states.
 				if len(counterSwap) == 0 {
-					match.failErr = fmt.Errorf("missing counter-swap, order %s, match %s", tracker.ID(), match.id)
+					match.swapErr = fmt.Errorf("missing counter-swap, order %s, match %s", tracker.ID(), match.id)
 					notifyErr("Match status error", "Match %s for order %s is in state %s, but has no maker swap coin.", dbMatch.Side, tracker.token(), dbMatch.Status)
 					continue
 				}
 				counterContract := metaData.Proof.CounterScript
 				if len(counterContract) == 0 {
-					match.failErr = fmt.Errorf("missing counter-contract, order %s, match %s", tracker.ID(), match.id)
+					match.swapErr = fmt.Errorf("missing counter-contract, order %s, match %s", tracker.ID(), match.id)
 					notifyErr("Match status error", "Match %s for order %s is in state %s, but has no maker swap contract.", dbMatch.Side, tracker.token(), dbMatch.Status)
 					continue
 				}
 				auditInfo, err := wallets.toWallet.AuditContract(counterSwap, counterContract)
 				if err != nil {
-					c.log.Debugf("Match %v status %v, refunded = %v, revoked = %v", match.id, match.MetaData.Status,
-						len(match.MetaData.Proof.RefundCoin) > 0, match.MetaData.Proof.IsRevoked())
-					match.failErr = fmt.Errorf("audit error, order %s, match %s: %v", tracker.ID(), match.id, err)
+					c.log.Debugf("AuditContract error for match %v status %v, refunded = %v, revoked = %v: %v",
+						match.id, match.MetaData.Status, len(match.MetaData.Proof.RefundCoin) > 0, match.MetaData.Proof.IsRevoked(), err)
+					match.swapErr = fmt.Errorf("audit error, order %s, match %s: %v", tracker.ID(), match.id, err)
+					match.MetaData.Proof.SelfRevoked = true
 					notifyErr("Match recovery error", "Error auditing counter-party's swap contract (%v) during swap recovery on order %s: %v",
 						tracker.token(), coinIDString(wallets.toAsset.ID, counterSwap), err)
 					continue
@@ -3470,7 +3496,7 @@ func (c *Core) connectDEX(acctInfo *db.AccountInfo) (*dexConnection, error) {
 		connMaster:   connMaster,
 		assets:       assets,
 		cfg:          dexCfg,
-		tickInterval: bTimeout / 3,
+		tickInterval: bTimeout / tickCheckDivisions,
 		books:        make(map[string]*bookie),
 		acct:         newDEXAccount(acctInfo),
 		marketMap:    marketMap,

client/core/core_test.go

@@ -201,11 +201,12 @@ func testDexConnection() (*dexConnection, *TWebsocket, *dexAccount) {
 			},
 			Fee: tFee,
 		},
-		notify:    func(Notification) {},
-		marketMap: map[string]*Market{tDcrBtcMktName: mkt},
-		trades:    make(map[order.OrderID]*trackedTrade),
-		epoch:     map[string]uint64{tDcrBtcMktName: 0},
-		connected: true,
+		tickInterval: time.Millisecond * 1000 / 3,
+		notify:       func(Notification) {},
+		marketMap:    map[string]*Market{tDcrBtcMktName: mkt},
+		trades:       make(map[order.OrderID]*trackedTrade),
+		epoch:        map[string]uint64{tDcrBtcMktName: 0},
+		connected:    true,
 	}, conn, acct
 }
 
@@ -493,11 +494,15 @@ type TXCWallet struct {
 	signCoinErr       error
 	lastSwaps         *asset.Swaps
 	swapReceipts      []asset.Receipt
+	swapCounter       int
+	swapErr           error
 	auditInfo         asset.AuditInfo
 	auditErr          error
 	refundCoin        dex.Bytes
 	refundErr         error
 	redeemCoins       []dex.Bytes
+	redeemCounter     int
+	redeemErr         error
 	badSecret         bool
 	fundedVal         uint64
 	fundedSwaps       uint64
@@ -583,11 +588,19 @@ func (w *TXCWallet) FundingCoins([]dex.Bytes) (asset.Coins, error) {
 }
 
 func (w *TXCWallet) Swap(swaps *asset.Swaps) ([]asset.Receipt, asset.Coin, uint64, error) {
+	w.swapCounter++
 	w.lastSwaps = swaps
+	if w.swapErr != nil {
+		return nil, nil, 0, w.swapErr
+	}
 	return w.swapReceipts, w.changeCoin, tSwapFeesPaid, nil
 }
 
 func (w *TXCWallet) Redeem([]*asset.Redemption) ([]dex.Bytes, asset.Coin, uint64, error) {
+	w.redeemCounter++
+	if w.redeemErr != nil {
+		return nil, nil, 0, w.redeemErr
+	}
 	return w.redeemCoins, &tCoin{id: []byte{0x0c, 0x0d}}, tRedemptionFeesPaid, nil
 }
 
@@ -1654,14 +1667,11 @@ func TestLogin(t *testing.T) {
 		t.Fatalf("final Login error: %v", err)
 	}
 
-	if tracker.matches[missingID].failErr == nil {
-		t.Errorf("failErr not set for missing match tracker")
-	}
 	if !tracker.matches[missingID].MetaData.Proof.SelfRevoked {
 		t.Errorf("SelfRevoked not true for missing match tracker")
 	}
-	if tracker.matches[matchID].failErr != nil {
-		t.Errorf("failErr set for non-missing match tracker")
+	if tracker.matches[matchID].swapErr != nil {
+		t.Errorf("swapErr set for non-missing match tracker")
 	}
 	if tracker.matches[matchID].MetaData.Proof.IsRevoked() {
 		t.Errorf("IsRevoked true for non-missing match tracker")
@@ -4575,6 +4585,29 @@ func TestReconfigureWallet(t *testing.T) {
 	}
 	tXyzWallet.unlockErr = nil
 
+	// For the last success, make sure that we also clear any related
+	// tickGovernors.
+	match := &matchTracker{
+		suspectSwap:  true,
+		tickGovernor: time.NewTimer(time.Hour),
+	}
+	tCore.conns[tDexHost].trades[order.OrderID{}] = &trackedTrade{
+		Order: &order.LimitOrder{
+			P: order.Prefix{
+				BaseAsset: assetID,
+			},
+		},
+		wallets: &walletSet{
+			fromAsset:  &dex.Asset{ID: assetID},
+			fromWallet: &xcWallet{AssetID: assetID},
+			toAsset:    &dex.Asset{},
+			toWallet:   &xcWallet{},
+		},
+		matches: map[order.MatchID]*matchTracker{
+			order.MatchID{}: match,
+		},
+	}
+
 	// Success
 	err = tCore.ReconfigureWallet(tPW, assetID, newSettings)
 	if err != nil {
@@ -4585,6 +4618,10 @@ func TestReconfigureWallet(t *testing.T) {
 	if len(settings) != 1 || settings["def"] != "456" {
 		t.Fatalf("settings not stored")
 	}
+
+	if match.tickGovernor != nil {
+		t.Fatalf("tickGovernor not removed")
+	}
 }
 
 func TestSetWalletPassword(t *testing.T) {
@@ -5239,3 +5276,186 @@ func TestMatchStatusResolution(t *testing.T) {
 		}
 	}
 }
+
+func TestSuspectTrades(t *testing.T) {
+	rig := newTestRig()
+	dc := rig.dc
+	tCore := rig.core
+
+	dcrWallet, tDcrWallet := newTWallet(tDCR.ID)
+	tCore.wallets[tDCR.ID] = dcrWallet
+	btcWallet, tBtcWallet := newTWallet(tBTC.ID)
+	tCore.wallets[tBTC.ID] = btcWallet
+	walletSet, _ := tCore.walletSet(dc, tDCR.ID, tBTC.ID, true)
+
+	lo, dbOrder, preImg, _ := makeLimitOrder(dc, true, 0, 0)
+	oid := lo.ID()
+	mkt := dc.market(tDcrBtcMktName)
+	tracker := newTrackedTrade(dbOrder, preImg, dc, mkt.EpochLen, rig.core.lockTimeTaker, rig.core.lockTimeMaker,
+		rig.db, rig.queue, walletSet, nil, rig.core.notify)
+	dc.trades[oid] = tracker
+
+	newMatch := func(side order.MatchSide, status order.MatchStatus) *matchTracker {
+		return &matchTracker{
+			id:     ordertest.RandomMatchID(),
+			prefix: lo.Prefix(),
+			trade:  lo.Trade(),
+			MetaMatch: db.MetaMatch{
+				MetaData: &db.MatchMetaData{
+					Proof: db.MatchProof{
+						Auth: db.MatchAuth{
+							MatchStamp: encode.UnixMilliU(time.Now()),
+							AuditStamp: encode.UnixMilliU(time.Now()),
+						},
+					},
+					Status: status,
+				},
+				Match: &order.UserMatch{
+					Side:    side,
+					Address: ordertest.RandomAddress(),
+					Status:  status,
+				},
+			},
+		}
+	}
+
+	var swappableMatch1, swappableMatch2 *matchTracker
+	setSwaps := func() {
+		swappableMatch1 = newMatch(order.Maker, order.NewlyMatched)
+		swappableMatch2 = newMatch(order.Taker, order.MakerSwapCast)
+		_, auditInfo := tMsgAudit(oid, swappableMatch2.id, ordertest.RandomAddress(), 1, encode.RandomBytes(32))
+		auditInfo.coin.confs = tDCR.SwapConf
+		swappableMatch2.counterSwap = auditInfo
+		tDcrWallet.swapCounter = 0
+		tracker.matches = map[order.MatchID]*matchTracker{
+			swappableMatch1.id: swappableMatch1,
+			swappableMatch2.id: swappableMatch2,
+		}
+	}
+	setSwaps()
+
+	// Initial success
+	_, err := tCore.tick(tracker)
+	if err != nil {
+		t.Fatalf("swap tick error: %v", err)
+	}
+
+	setSwaps()
+	tDcrWallet.swapErr = tErr
+	_, err = tCore.tick(tracker)
+	if err == nil || !strings.Contains(err.Error(), "error sending swap transaction") {
+		t.Fatalf("swap error not propagated, err = %v", err)
+	}
+	if tDcrWallet.swapCounter != 1 {
+		t.Fatalf("never swapped")
+	}
+
+	// Both matches should be marked as suspect and have tickGovernors in place.
+	tracker.mtx.Lock()
+	for i, m := range []*matchTracker{swappableMatch1, swappableMatch2} {
+		if !m.suspectSwap {
+			t.Fatalf("swappable match %d not suspect after failed swap", i+1)
+		}
+		if m.tickGovernor == nil {
+			t.Fatalf("swappable match %d has no tick meterer set", i+1)
+		}
+	}
+	tracker.mtx.Unlock()
+
+	// Ticking right away again should do nothing.
+	tDcrWallet.swapErr = nil
+	_, err = tCore.tick(tracker)
+	if err != nil {
+		t.Fatalf("tick error during metered swap tick: %v", err)
+	}
+	if tDcrWallet.swapCounter != 1 {
+		t.Fatalf("swapped during metered tick")
+	}
+
+	// But once the tickGovernors expire, we should succeed with two separate
+	// requests.
+	tracker.mtx.Lock()
+	swappableMatch1.tickGovernor = nil
+	swappableMatch2.tickGovernor = nil
+	tracker.mtx.Unlock()
+	_, err = tCore.tick(tracker)
+	if err != nil {
+		t.Fatalf("tick error while swapping suspect matches: %v", err)
+	}
+	if tDcrWallet.swapCounter != 3 {
+		t.Fatalf("suspect swap matches not run or not run separately. expected 2 new calls to Swap, got %d", tDcrWallet.swapCounter-1)
+	}
+
+	var redeemableMatch1, redeemableMatch2 *matchTracker
+	setRedeems := func() {
+		redeemableMatch1 = newMatch(order.Maker, order.TakerSwapCast)
+		redeemableMatch2 = newMatch(order.Taker, order.MakerRedeemed)
+		_, auditInfo := tMsgAudit(oid, redeemableMatch1.id, ordertest.RandomAddress(), 1, encode.RandomBytes(32))
+		auditInfo.coin.confs = tBTC.SwapConf
+		redeemableMatch1.counterSwap = auditInfo
+		tBtcWallet.redeemCounter = 0
+		tracker.matches = map[order.MatchID]*matchTracker{
+			redeemableMatch1.id: redeemableMatch1,
+			redeemableMatch2.id: redeemableMatch2,
+		}
+		rig.ws.queueResponse(msgjson.RedeemRoute, redeemAcker)
+		rig.ws.queueResponse(msgjson.RedeemRoute, redeemAcker)
+	}
+	setRedeems()
+
+	// Initial success
+	tBtcWallet.redeemCoins = []dex.Bytes{encode.RandomBytes(36), encode.RandomBytes(36)}
+	_, err = tCore.tick(tracker)
+	if err != nil {
+		t.Fatalf("redeem tick error: %v", err)
+	}
+	if tBtcWallet.redeemCounter != 1 {
+		t.Fatalf("never redeemed")
+	}
+
+	setRedeems()
+	tBtcWallet.redeemErr = tErr
+	_, err = tCore.tick(tracker)
+	if err == nil || !strings.Contains(err.Error(), "error sending redeem transaction") {
+		t.Fatalf("redeem error not propagated. err = %v", err)
+	}
+	if tBtcWallet.redeemCounter != 1 {
+		t.Fatalf("never redeemed")
+	}
+
+	// Both matches should be marked as suspect and have tickGovernors in place.
+	tracker.mtx.Lock()
+	for i, m := range []*matchTracker{redeemableMatch1, redeemableMatch2} {
+		if !m.suspectRedeem {
+			t.Fatalf("redeemable match %d not suspect after failed swap", i+1)
+		}
+		if m.tickGovernor == nil {
+			t.Fatalf("redeemable match %d has no tick meterer set", i+1)
+		}
+	}
+	tracker.mtx.Unlock()
+
+	// Ticking right away again should do nothing.
+	tBtcWallet.redeemErr = nil
+	_, err = tCore.tick(tracker)
+	if err != nil {
+		t.Fatalf("tick error during metered redeem tick: %v", err)
+	}
+	if tBtcWallet.redeemCounter != 1 {
+		t.Fatalf("redeemed during metered tick %d", tBtcWallet.redeemCounter)
+	}
+
+	// But once the tickGovernors expire, we should succeed with two separate
+	// requests.
+	tracker.mtx.Lock()
+	redeemableMatch1.tickGovernor = nil
+	redeemableMatch2.tickGovernor = nil
+	tracker.mtx.Unlock()
+	_, err = tCore.tick(tracker)
+	if err != nil {
+		t.Fatalf("tick error while redeeming suspect matches: %v", err)
+	}
+	if tBtcWallet.redeemCounter != 3 {
+		t.Fatalf("suspect redeem matches not run or not run separately. expected 2 new calls to Redeem, got %d", tBtcWallet.redeemCounter-1)
+	}
+}