dex/order,client/asset: fix UserMatch DB serialization, and change address assumption#531
Conversation
buck54321
left a comment
buck54321
left a comment
There was a problem hiding this comment.
Just some draft comments. Sorry if I commented on things that were not meant to be permanent.
chappjc
changed the title
This comment has been minimized.
This comment has been minimized.
| ServerTime: encode.UnixMilliU(match.Epoch.End()), | ||
| Address: addr, | ||
| FeeRateBase: match.BaseRate, // contract txn fee rate if user is selling | ||
| FeeRateQuote: match.QuoteRate, // contract txn fee rate if user is buying |
There was a problem hiding this comment.
ServerTime (used for client's lock time calculations) was also unset.
| var takerSell sql.NullBool | ||
| var takerAddr, makerAddr sql.NullString | ||
| err := rows.Scan(&m.ID, &takerSell, &m.Active, | ||
| err := rows.Scan(&m.ID, &m.Active, &takerSell, |
There was a problem hiding this comment.
These booleans were switched. Caught by the AllActiveUserMatches test that now uses this function.
There was a problem hiding this comment.
Not related to this pr, but I am able to get "stuck" and unable to trade sometimes:
[joe@hyrule dexcctl]$ ./dexcctl -ua -Pbb trade 127.0.0.1:7232 true true 42 0 100000000 1000000 false
App password:
unable to trade: rpc error: 35: coin {txid = 084558ca27a30318de6840134c2a2cd513cc37e8f82b9f9c03431edf10c52eb5, vout = 2} is locked
At one point hit this error:
2020-07-09 11:15:33.062 [ERR] CORE: notify: |ERROR| (order) Swap error - Error encountered sending a swap output(s) worth 0.22000000 btc on order 3087a710 - Order: 3087a7104de06fd894629dc27fcd0aa620fd714b53290444680dec8e2b73c610
2020-07-09 11:15:33.062 [ERR] CORE: 127.0.0.1:7232 tick: swapMatches order 3087a7104de06fd894629dc27fcd0aa620fd714b53290444680dec8e2b73c610 - btc coin 0000000000000000000000000000000000000000000000000000000000000000:0 not found
and
2020-07-09 11:31:00.058 [DBG] CORE: swappable match c5d2519843dc145d2bad19a95c13c07303719b5c14e860f4855c3f7e56f089b9
2020-07-09 11:31:00.073 [DBG] CORE[btc]: Change output size = 31, addr = bcrt1qhggzepsnake4kux8v7vgpgs22l8vkqd76z389y
2020-07-09 11:31:00.075 [DBG] CORE[btc]: 2 signature cycles to converge on fees for tx 67301cc74bd11c0dd20b672205c8324269d0658b07413f6b9b94c8d635c54ee7: min rate = 4, actual fee rate = 4 (892 for 223 bytes), change = true
2020-07-09 11:31:00.077 [ERR] CORE: notify: |ERROR| (order) Swap error - Error encountered sending a swap output(s) worth 2.00000000 btc on order ce80fe12 - Order: ce80fe12ffcf7bf28aea48a7ddcb501af6723e8c32a920f184145c865f2e3ef6
2020-07-09 11:31:00.077 [ERR] CORE: 127.0.0.1:7232 tick: swapMatches order ce80fe12ffcf7bf28aea48a7ddcb501af6723e8c32a920f184145c865f2e3ef6 - error sending swap transaction: -26: txn-mempool-conflict (code 18)
| if dbMatch.Side == order.Taker && metaData.Status == order.MakerRedeemed { | ||
| return true | ||
| } | ||
| log.Debugf("match side = %v, status = %v", dbMatch.Side, metaData.Status) |
There was a problem hiding this comment.
This is kind of loud when status = MatchComplete
There was a problem hiding this comment.
Agreed. These should be remove from the tracked trades. It's part of why I'm always pushing for more logging, because otherwise things like this can be neglected.
| log.Debugf("refundable match %v", match.id) | ||
| refunds = append(refunds, match) | ||
| default: | ||
| log.Debugf("match not ready for action: %v", match.id) |
There was a problem hiding this comment.
Maybe this doesn't need to log if status = MatchComplete?
There was a problem hiding this comment.
Such a match should be removed, but that's out of scope for this PR.
|
Regarding the coin is locked errors, @buck54321 is assessing that in #525 but it's not quite ready. Would like repro details for the BTC |
|
Adding one more error: server |
|
The double spend error ( The Lines 701 to 711 in f3e94af t.change and t.coins in this function.
The |
Aren't those |
Yes, that's from the server. We know that the client is not locking and unlocking as needed, yet, so the server may be correct here. There may be coin locking/unlocking issues to resolve on the server, but if the client tries to use coins that it should have locked, but which the server had correctly locked, this error from the server makes sense. |
This is #446. Resolved in #541 I have no idea about the preimage error. Need more context and repro info. EDIT: The preimage error seems to be a |
buck54321
left a comment
buck54321
left a comment
There was a problem hiding this comment.
Nice improvements. More logging is nice.
| if checkRate > feeRate*3 { | ||
| return nil, nil, fmt.Errorf("final fee rate for %s, %d, is seemingly outrageous, target = %d", |
There was a problem hiding this comment.
Did someone see an error when it was 2?
There was a problem hiding this comment.
No, but I think before it was comparing rate with total fee (was checkRate > float64(feeRate*uint64(size)*2, with the size multiplied there) so it's hard to know if double rate will sometimes be too strict especially if the rate is very low to begin with. I was actually thinking about removing this though since btc doesn't do the same check and above it also verifies checkFee != lastFee.
| // for _, match := range matches { | ||
| // match.tracker.tick() | ||
| // } |
There was a problem hiding this comment.
Was considering ticking the matches now rather than waiting for the ticker in listen. Just removing the comment though as i don't want to muddle the responsibilities for doing this.
|
|
||
| func userMatches(ctx context.Context, dbe *sql.DB, tableName string, aid account.AccountID) ([]*db.MatchData, error) { | ||
| func userMatches(ctx context.Context, dbe *sql.DB, tableName string, aid account.AccountID, includeInactive bool) ([]*db.MatchData, error) { | ||
| stmt := fmt.Sprintf(internal.RetrieveUserMatches, tableName) |
There was a problem hiding this comment.
Can you switch on includeInactive to use internal.RetrieveActiveUserMatches here?
| Status: order.OrderStatus(intCoder.Uint16(oBkt.Get(statusKey))), | ||
| Host: string(oBkt.Get(dexKey)), | ||
| ChangeCoin: oBkt.Get(changeKey), | ||
| ChangeCoin: oBkt.Get(changeKey), // what if it was stored as nil? |
There was a problem hiding this comment.
Good point. Should be storing nil interface. Should also favor len(change) == 0 over nil check throughout.
There was a problem hiding this comment.
Since ChangeCoin is a order.CoinID, which is a []byte, I guess I'm pointing out here that oBkt.Get(changeKey) may or may not return nil vs []byte{}... just need to check and see since I'm not that familiar with bbolt. Maybe this is just fine and ChangeCoin will come back nil... dunno.
There was a problem hiding this comment.
Just confirmed that putting nil comes back as []byte{} instead. 84db38c The len(change) == 0 checks in higher level code is also a good idea that I'll get on as well. EDIT: Actually, the checks for ChangeCoin do seem to be on length rather than nil, unlike with RefundCoin.
There was a problem hiding this comment.
Ah. Yep, bbolt will return nil for nil and []byte{} for []byte{}.
There was a problem hiding this comment.
Pushed a commit to do length checks in favor of nil checks anyway. e2e6908
But I observed that bolt returns []byte{} always, even when nil is stored. That is, in 84db38c, if you get rid of that if len(changeCoin) == 0 I added in decodeOrderBucket, it would never set the returned dexdb.OrderMetaData.ChangeCoin to nil even if you've stored it that way.
There was a problem hiding this comment.
Hmmm. My test revealed otherwise.
func TestThis(t *testing.T) {
boltdb := newTestDB(t)
bktID := []byte("abc")
k := []byte("k")
err := boltdb.Update(func(tx *bbolt.Tx) error {
bkt, err := tx.CreateBucketIfNotExists(bktID)
if err != nil {
return err
}
err = bkt.Put(k, []byte{})
if err != nil {
return err
}
b := bkt.Get(k)
fmt.Println("[]byte{} is nil?", b == nil)
err = bkt.Put(k, nil)
if err != nil {
return err
}
b = bkt.Get(k)
fmt.Println("nil is nil?", b == nil)
return nil
})
if err != nil {
t.Fatalf("Update error: %v", err)
}
}There was a problem hiding this comment.
Oh, not good. That means (*BoltDB).Get is broken for nil.
But I am not seeing why the bkt.Get from decodeOrderBucket will not return nil, only []byte{}.
There was a problem hiding this comment.
Well, actually we seemed to have stumbled on some undefined behavior in bolt. For a stored nil slice, you will receive either an empty non-nil slice or a nil slice, depending on whether the Cursor retrieves the value from the "page" or "node", respectively.
In the "retrieve value from page" branch, it uses (*leafPageElement).value > unsafeByteSlice to get the value byte slice, which always results in a non-nil slice:
https://github.com/etcd-io/bbolt/blob/232d8fc87f50244f9c808f4745759e08a304c029/unsafe.go#L27
This is all it can do because a leafPageElement only knows the "size" and 0 does not disambiguate nil from empty non-nil slice. https://github.com/etcd-io/bbolt/blob/232d8fc87f50244f9c808f4745759e08a304c029/page.go#L115-L120
I don't see a fix for bolt, other than possibly to revise their use of inode to always return []byte{} when len(inode.value) is zero rather than returning whatever was stored there (nil or []byte{}).
I'll make a minimal repro to demonstrate, but it seems simple to hit with enough entries in the same bucket by committing the update txn.
There was a problem hiding this comment.
With orders:
func TestOrderChange(t *testing.T) {
boltdb := newTestDB(t)
// Create an account to use.
acct := dbtest.RandomAccountInfo()
err := boltdb.CreateAccount(acct)
if err != nil {
t.Fatalf("CreateAccount error: %v", err)
}
ord := randOrderForMarket(randU32(), randU32())
mordIn := &db.MetaOrder{
MetaData: &db.OrderMetaData{
Status: 3,
Host: acct.Host,
Proof: db.OrderProof{DEXSig: randBytes(73)},
},
Order: ord,
}
fmt.Printf("%#v\n", mordIn.MetaData.ChangeCoin)
fmt.Printf("%#v\n", mordIn.MetaData.Proof.Preimage)
err = boltdb.UpdateOrder(mordIn)
if err != nil {
t.Fatalf("error inserting order: %v", err)
}
mord, err := boltdb.Order(ord.ID())
if err != nil {
t.Fatalf("unable to retrieve order by id")
}
fmt.Printf("%#v\n", mord.MetaData.ChangeCoin) // incorrect
fmt.Printf("%#v\n", mord.MetaData.Proof.Preimage) // correct
if mord.MetaData.ChangeCoin != nil {
t.Errorf("ChangeCoin was not nil: %#v", mord.MetaData.ChangeCoin)
}
}Just plain bolt:
func TestNilValue(t *testing.T) {
tDir, _ := ioutil.TempDir("", "dbtest")
defer os.RemoveAll(tDir)
tDbFile := filepath.Join(tDir, "bolt.db")
boltdb, err := bbolt.Open(tDbFile, 0600, nil)
if err != nil {
t.Fatal(err)
}
bktID := []byte("bucket")
nk := []byte("nilkey")
ek := []byte("emptykey")
err = boltdb.Update(func(tx *bbolt.Tx) error {
bkt, err := tx.CreateBucketIfNotExists(bktID)
if err != nil {
return err
}
err = bkt.Put(nk, nil)
if err != nil {
return err
}
// (*Cursor).keyValue retrieves value from node, returning the nil byte
// slice from inode.value.
b := bkt.Get(nk)
if b != nil {
return fmt.Errorf("not nil, %#v", b)
}
err = bkt.Put(ek, []byte{})
if err == nil {
return err
}
b = bkt.Get(ek)
if b == nil {
return fmt.Errorf("not []byte{}, %#v", b)
}
return nil
})
// Commit "spills" to pages.
if err != nil {
t.Fatalf("Update error: %v", err)
}
err = boltdb.View(func(tx *bbolt.Tx) error {
bkt := tx.Bucket(bktID)
// (*Cursor).keyValue retrieves value from page via unsafeByteSlice,
// always creating a non-nil byte slice.
b := bkt.Get(nk)
if b != nil {
// Fails here.
t.Errorf("not nil, %#v", b)
}
b = bkt.Get(ek)
if b == nil {
// OK here.
t.Errorf("not []byte{}, %#v", b)
}
return nil
})
if err != nil {
t.Fatalf("View error: %v", err)
}
}| t.change = change | ||
| t.coins[hex.EncodeToString(change.ID())] = change | ||
| t.metaData.ChangeCoin = []byte(change.ID()) | ||
| t.db.SetChangeCoin(t.ID(), t.metaData.ChangeCoin) // TODO: lock the change coin in the wallet if the order is still on the book | ||
| if change != nil { | ||
| log.Debugf("storing change coin %v", change.String()) | ||
| t.change = change | ||
| t.coins[hex.EncodeToString(change.ID())] = change | ||
| t.metaData.ChangeCoin = []byte(change.ID()) | ||
| t.db.SetChangeCoin(t.ID(), t.metaData.ChangeCoin) // TODO: lock the change coin in the wallet if the order is still on the book | ||
| } |
There was a problem hiding this comment.
I think we'd still want to save the change coin if it's nil, no? We don't want to append it to t.coins though.
There was a problem hiding this comment.
Hmm, yeah t.change = nil would still be desirable, but change.ID() would of course panic with t.metaData.ChangeCoin = []byte(change.ID()). Probably OK to handle this with an else with t.metaData.ChangeCoin = nil. EDIT: like 0144938
BTW, this gets to the other comment about ChangeCoin: oBkt.Get(changeKey) where I'm not certain that oBkt.Put(nil) comes back as nil. Just need to check that.
client log |
|
@JoeGruffins Thanks for the additional context. That helps a lot, notice the order of these messages indicates the server requested the preimage "before" the client placed the order: This suggests that the client is submitting the order to the server before registering it's own order where the preimage request handler can find it. |
|
Looks like the sequence in |
|
@buck54321 Great. We can track the issue in #544. |
buck54321
left a comment
buck54321
left a comment
There was a problem hiding this comment.
Looks like the asset.Swaps in client/asset/btc/livetest/regnet_test.go and client/asset/dcr/simnet_test.go both need to have the FeeRate set. Can probably just use the MaxFeeRate from the dex.Asset.
Otherwise, this seems good to go.
| dbMatch, metaData, proof, _ := match.parts() | ||
| if match.failErr != nil || proof.RefundCoin != nil { | ||
| if match.failErr != nil || len(proof.RefundCoin) != 0 { | ||
| log.Debugf("Match %v not redeemable: failErr = %v, RefundCoin = %v", |
There was a problem hiding this comment.
I might go a Tracef here. This will be the case for most matches.
There was a problem hiding this comment.
If failErr is set, that's pretty helpful to log. RefundCoin being set should be unusual too, but less important to log.
| dbMatch, _, proof, _ := match.parts() | ||
| if match.refundErr != nil || proof.RefundCoin != nil { | ||
| if match.refundErr != nil || len(proof.RefundCoin) != 0 { | ||
| log.Debugf("Match %v not refundable: refundErr = %v, RefundCoin = %v", |
| /* | ||
| func TestNilValue(t *testing.T) { | ||
| tDir, _ := ioutil.TempDir("", "dbtest") | ||
| defer os.RemoveAll(tDir) |
There was a problem hiding this comment.
If you want to leave this comment, let's drop a link to this convo and a short explanation.
There was a problem hiding this comment.
It's in a play now instead: https://play.golang.org/p/eU3x9oYeYfk
This comment has been minimized.
This comment has been minimized.
chappjc
force-pushed
the
btc-fee-cycles
branch
2 times, most recently
from
5815012 to
9990b2e
Compare
client/asset/btc: tweak and log sendWithReturn client/asset/dcr: integer fee check in sendwithReturn client/asset: set asset.Swaps.FeeRate in simnet harness tests
server/db: replace ActiveMatches with AllActiveUserMatches server/auth: use AllActiveUserMatches in handleConnect The msgjson.Matches sent with the connect response need the match time, base fee rate, and quote fee rates set. server/auth: handleConnect must send 2 match msgs if the user is both sides server/db/driver/pg: remove (*Archiver).ActiveMatches
client/core: still store nil change coin client/core: cleanup client/core: match logging log and check fee received from server client/core: convert slice nil => length checks
client/db/bolt: fix dropped errors in filteredOrders and filteredMatches client/db/bolt: order change tests and demo of bbolt ambiguity bug
4 participants
Resolves #529
The
order.UserMatchwas not being serialized with the newFeeRateSwapfield so it was being loaded from DB as 0 by default.In addition, the
'connect'response was not setting either base or quote fee rates, but it was also missing the recently addedMatchTimethat the client needs for lock time computation.The server/db changes provide the data needed by
(*AuthManager).handleConnectto provide this new match data to clients on connect.In client/asset/{dcr,btc},
(*ExchangeWallet).sendWithReturnwas assuming a certain change address format when computing the updated tx size. This fixes that and refactors a bit so the functions mirror each other more closely, and to log more information about the generated transaction and its fees.EDIT: Another
'connect'bug was that only one msgjson.Match was being sent if the user was on both sides of the match. This is fixed to send two matches now as is done when the matches are initially made.Even with this though the client will fail to act if. Finally, the dex/encode package is updated to load empty data pushes as nil instead is a zero length non-nil slice.dexcis restart inTakerSwapCaststatus.