core: fix locktime handling by buck54321 · Pull Request #438 · decred/dcrdex

buck54321 · 2020-06-01T19:24:23Z

Locktime was not being set correctly. The server intentionally sets the msgjson.Match.ServerTime based on the match epoch so that locktime can be based off of a common point for both maker and taker. Plus, taker wasn't setting their locktime correctly when constructing the contract, which is now fixed.

chappjc · 2020-06-01T19:28:13Z

+		lockTime := matchTime.Add(time.Hour * 24).UTC().Unix()
 		if dbMatch.Side == order.Maker {
 			proof.Secret = encode.RandomBytes(32)
 			secretHash := sha256.Sum256(proof.Secret)
 			proof.SecretHash = secretHash[:]
+			lockTime = matchTime.Add(time.Hour * 48).UTC().Unix()


Yikes good catch. But I feel like we should have these two constant times somewhere in a common server-client package (no law that says these couldn't be 2 hr / 4 hr).

I actually thought about making them DEX cfg variables.

no law that says these couldn't be 2 hr / 4 hr

They need to guarantee (probabilistically) SwapConf confirmations within the taker's locktime. And since SwapConf is a variable, we need to be generous.

Regarding making these constants, one reason I had in mind for making them dex cfg variables is to enable testing refund scenarios in #432.

An alternative would be declaring as var instead of const so the test code can change the values to something much shorter for test purposes.

A couple other reasons to consider making the locktimes dex cfg variables:

If we make them dex cfg variables, it'd be easier for clients to know what's expected in terms of swap locktimes (just check the dex cfg to know what locktime to set). Short of that, we'd need to add those values to the spec so all parties know what's expected.

Since swapConf is a dex cfg variable, it'd also make sense to make the locktime similarly variable and we could add some validation code to ensure that the set locktimes are sane and generous.

@itswisdomagain You make some good arguments for making lock times config settings. Let's consider that for future work.

JoeGruffins · 2020-06-02T07:06:34Z

Had this happen for the first time while testing this pr. Don't know if it's because of this pr or not.

2020-06-02 15:55:00.522 [DBG] CORE: notify: |POKE| (order) Order placed - buying 1.00000000 dcr (5a56aa6f) - Order: 5a56aa6f02ff3ef8cdc5bf607965526df937ba5a3aa6412d18f03dbfcf9a6f1d
2020-06-02 15:55:00.525 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-06-02 15:55:04.832 [DBG] CORE: notify: |POKE| (order) Order placed - selling 1.00000000 dcr (3dd901f0) - Order: 3dd901f004165dce0d8f66c95a1b526242d393d2498d3a11e1f2c611096a01a2
2020-06-02 15:55:04.858 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-06-02 15:55:10.000 [DBG] CORE: notify: |POKE| (order) Preimage sent - match cycle has begun for order 5a56aa6f - Order: 5a56aa6f02ff3ef8cdc5bf607965526df937ba5a3aa6412d18f03dbfcf9a6f1d
2020-06-02 15:55:10.000 [DBG] CORE: notify: |POKE| (order) Preimage sent - match cycle has begun for order 3dd901f0 - Order: 3dd901f004165dce0d8f66c95a1b526242d393d2498d3a11e1f2c611096a01a2
2020-06-02 15:55:10.005 [TRC] CORE: notify: |DATA| (epoch) - Index: 159108091
2020-06-02 15:55:15.001 [ERR] COMMS: No handler found for response: {"type":2,"id":2,"payload":{"result":null,"error":{"code":28,"message":"unknown response ID"}}}
2020-06-02 15:55:15.005 [TRC] CORE: notify: |DATA| (epoch) - Index: 159108091
2020-06-02 15:55:15.005 [ERR] CORE: match proof csum mismatch for epoch 159108090: expected a62a7b0e8c2b0de25225d54d49a1b2e63b26f18d6668b8dc77285f0f58d3ebeb, got 72825906367d9690f1f1fff250a912d17131b191f0ed908490ff3f4560956fa6

Following this my sell order disappeared from the books and the graph. I do see it in my orders, where it still says booked. dexcctl also shows it as status 2, which is booked maybe.

I was able to make another sell order right after this that went through fine and became a trade.

When trying to cancel the order by clicking X:

2020-06-02 16:14:29.208 [ERR] WEB: error cancelling order 3dd901f004165dce0d8f66c95a1b526242d393d2498d3a11e1f2c611096a01a2: rpc error: 29: target order not known

And a screenshot. You can see my sell order is missing in the books.

chappjc · 2020-06-02T18:22:01Z

@JoeGruffins Check the server logs please, if this is your local server. The error indicates that a response message from your client had a msg ID that did not match one of the known server initiated requests IDs. There is a preimage collection bug fixed in 700e145, but I don't think that's what happened.

JoeGruffins · 2020-06-03T00:06:57Z

server logs:

2020-06-02 15:54:53.436 [DBG] AUTH: User 5648eef5c384c8aad1def70cf261d2d65674fab314ea2e6c5a8ca8e33c663b92 connected from 127.0.0.1.
2020-06-02 15:55:00.515 [TRC] MKT: Received order 5a56aa6f02ff3ef8cdc5bf607965526df937ba5a3aa6412d18f03dbfcf9a6f1d at 2020-06-02 06:55:00.515 +0000 UTC
2020-06-02 15:55:04.824 [TRC] MKT: Received order 3dd901f004165dce0d8f66c95a1b526242d393d2498d3a11e1f2c611096a01a2 at 2020-06-02 06:55:04.824 +0000 UTC
2020-06-02 15:55:10.000 [TRC] MKT: Preimage request sent for order 5a56aa6f02ff3ef8cdc5bf607965526df937ba5a3aa6412d18f03dbfcf9a6f1d
2020-06-02 15:55:10.000 [TRC] MKT: Preimage request sent for order 3dd901f004165dce0d8f66c95a1b526242d393d2498d3a11e1f2c611096a01a2
2020-06-02 15:55:10.000 [TRC] MKT: Good preimage received for order 5a56aa6f02ff3ef8cdc5bf607965526df937ba5a3aa6412d18f03dbfcf9a6f1d: d34e1bceeece4a01ad046ed6b1fa578596c2d5db8e73f8af9584c343f00945b4
2020-06-02 15:55:15.000 [INF] MKT: Collected 1 valid order preimages, missed 1. Commit checksum: a62a7b0e8c2b0de25225d54d49a1b2e63b26f18d6668b8dc77285f0f58d3ebeb
2020-06-02 15:55:15.000 [INF] AUTH: user 5648eef5c384c8aad1def70cf261d2d65674fab314ea2e6c5a8ca8e33c663b92 penalized for rule 4, but not enforcing it
2020-06-02 15:55:15.001 [INF] MKT: Matching complete for market dcr_btc epoch 159108090: 0 matches (0 partial fills), 0 completed OK (not booked), 1 booked, 0 unbooked, 0 failed

buck54321 · 2020-06-03T14:28:38Z

Are you able to reproduce this, @JoeGruffins?

chappjc · 2020-06-03T17:54:31Z

Smells like a bug, maybe a race, with the comms or auth routers registering a handler keyed by request id vs. a response coming back too fast. I didn't come across anything fishy though.

JoeGruffins · 2020-06-04T08:19:18Z

I have not been able to reproduce that specific error yet, but I have been able to get "ghost orders" another way. Just firing them off pretty fast using dexcctl, I started getting this error:

552a0:0) paying to mjviTwuzRsfTWSwgZv87rmNGLA4hxNCUNB for order 5443d83504dfd37895eae187cf7a08c3ff18d9e1ac7236cefff03afeeeb42b23...
2020-06-04 17:13:21.989 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. 689b78b600390e910d8e4282f20cb7480ae1e5a6b00bdfd14bd0231be379b3de:5
2020-06-04 17:13:21.989 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. 56d003dbb3c0d0231fcf87d44215245e4d8459ae61edd1b27741f51d0aa6b2de:0
2020-06-04 17:13:21.990 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. a1c50f360e0002823d081f724bb89eaf006e8e979c0597394b39771bc7b759ef:1
2020-06-04 17:13:21.990 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. e8bf1ceab54ae258a8c3ac24c62b394865beabedd844b37930ef539344f15c33:1
2020-06-04 17:13:21.990 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. 0f5924abead19babc15575202c917f0e8d26a86a213ba8804c60b511f6fdd2c8:0
2020-06-04 17:13:21.991 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. 43dd6383c81d37179e39ab937f7ad17c34a42e54ff75b92dc0f61003215d38d2:0
2020-06-04 17:13:21.991 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. 291cc56cab6d91d74815691a2eeac47bac890f0710104935902d0dad772a57aa:1
2020-06-04 17:13:21.991 [DBG] CORE[dcr]: ignoring output from listlockunspent that wasn't found with gettxout. f9d19ad948810097e8c3cef0d7b6f61469e6a6d355afb6f284fe3b7f793f33f5:0

And now I have untouchable orders:

JoeGruffins · 2020-06-04T08:28:44Z

I have reproduced the COMMS error on master, just making a lot of orders. I'm not sure why it is happening sometimes.

documented in #446

JoeGruffins

The problems I encountered are in master.

chappjc

Looks good, but I noticed a discrepancy in the 'match' route payload field names from the spec vs msgjson.Match, namely it's tserver in the struct tag and timestamp in the spec. The fields are also out of order, but that doesn't really matter. We can either revise the struct tags or sneak in a spec fix since it's not substantial. Either way, I feel like it would be a good idea to revise the spec's description of the time stamp to explicitly state that the lock times should be derived from that time. Maybe even refer to the 'match' payload from the atomic swap section of the spec.

chappjc · 2020-06-04T15:29:54Z

+		lockTime := matchTime.Add(dex.LockTimeTaker).UTC().Unix()
 		if dbMatch.Side == order.Maker {
 			proof.Secret = encode.RandomBytes(32)
 			secretHash := sha256.Sum256(proof.Secret)
 			proof.SecretHash = secretHash[:]
+			lockTime = matchTime.Add(dex.LockTimeMaker).UTC().Unix()


Regarding spec clarifications, I think we should also formalize the ms -> second translation of lock time from the match time. Seems to be a round down.

buck54321 · 2020-06-05T21:54:36Z

I've got a spec tweaks roundup branch working where I'll address the spec changes.

chappjc · 2020-06-09T16:25:39Z

 	auth.AuditSig = audit.Sig
 	proof.CounterScript = audit.Contract
+	matchTime := encode.UnixTimeMilli(int64(auth.MatchStamp))
+	reqLockTime := matchTime.Add(dex.LockTimeMaker).Truncate(time.Millisecond) // counterparty = maker, their locktime = 48 hours.


Shouldn't reqLockTime be second resolution, not millisecond?

Also, I feel like both client and server should perhaps be using the same function like NextSecond from dex or a common package to take a time or a ms stamp and return the next second. That way they can both be guaranteed to do the same thing with the match stamp.

Shouldn't reqLockTime be second resolution, not millisecond?

Of course it should.

Also, I feel like both client and server should perhaps be using the same function like NextSecond from dex or a common package to take a time or a ms stamp and return the next second. That way they can both be guaranteed to do the same thing with the match stamp.

I'm not understanding the use of "next" here. Won't truncate be the "previous" second?

"next" meaning the ceil operation or the opposite of truncate, round up I guess. But as long as everything is consistent it doesn't matter which direction up/down and I see that 9b39f6f makes it super clear now

i.e. in swap.go we now have

reqLockTime = encode.DropMilliseconds(stepInfo.match.matchTime.Add(dex.LockTimeMaker))

and in client/core/trade.go we have

reqLockTime := encode.DropMilliseconds(matchTime.Add(dex.LockTimeMaker))

which makes it super clear that the same thing is computed on both ends.

chappjc reviewed Jun 1, 2020

View reviewed changes

JoeGruffins approved these changes Jun 4, 2020

View reviewed changes

Comment thread client/core/trade.go Outdated

chappjc reviewed Jun 4, 2020

View reviewed changes

Comment thread client/core/trade.go

itswisdomagain mentioned this pull request Jun 9, 2020

Add simnet trading tests #432

Merged

buck54321 added 5 commits June 9, 2020 09:31

fix locktime handling

b50b696

server too

6f3f3f0

use constants in client

67b74a9

constants in one more place

8afaab3

truncate locktime for comparison. fix some rebase issues

ea283d6

buck54321 force-pushed the locktime branch from 308b9f9 to ea283d6 Compare June 9, 2020 15:06

chappjc reviewed Jun 9, 2020

View reviewed changes

truncate to seconds with encode package function

9b39f6f

chappjc approved these changes Jun 9, 2020

View reviewed changes

chappjc merged commit ab3dff2 into decred:master Jun 9, 2020

chappjc mentioned this pull request Jun 12, 2020

CORE: match proof csum mismatch #446

Closed

chappjc mentioned this pull request Jun 25, 2020

multi: match fee rates and smart fees #505

Merged

Conversation

buck54321 commented Jun 1, 2020

Uh oh!

chappjc Jun 1, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

itswisdomagain Jun 1, 2020

Choose a reason for hiding this comment

Uh oh!

buck54321 Jun 1, 2020

Choose a reason for hiding this comment

Uh oh!

itswisdomagain Jun 9, 2020

Choose a reason for hiding this comment

Uh oh!

chappjc Jun 9, 2020

Choose a reason for hiding this comment

Uh oh!

JoeGruffins commented Jun 2, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

chappjc commented Jun 2, 2020

Uh oh!

JoeGruffins commented Jun 3, 2020

Uh oh!

buck54321 commented Jun 3, 2020

Uh oh!

chappjc commented Jun 3, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

JoeGruffins commented Jun 4, 2020

Uh oh!

JoeGruffins commented Jun 4, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

JoeGruffins left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

chappjc left a comment • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

chappjc Jun 4, 2020

Choose a reason for hiding this comment

Uh oh!

Uh oh!

buck54321 commented Jun 5, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

chappjc Jun 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

buck54321 Jun 9, 2020 • edited by chappjc Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

chappjc Jun 9, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

4 participants

chappjc Jun 1, 2020 •

edited

Loading

JoeGruffins commented Jun 2, 2020 •

edited

Loading

chappjc commented Jun 3, 2020 •

edited

Loading

JoeGruffins commented Jun 4, 2020 •

edited

Loading

JoeGruffins left a comment •

edited

Loading

chappjc left a comment •

edited

Loading

buck54321 commented Jun 5, 2020 •

edited

Loading

chappjc Jun 9, 2020 •

edited

Loading

buck54321 Jun 9, 2020 •

edited by chappjc

Loading

chappjc Jun 9, 2020 •

edited

Loading