multi: connect response includes active orders by itswisdomagain · Pull Request #677 · decred/dcrdex

itswisdomagain · 2020-09-09T15:50:57Z

server/auth: return list of active orders with connect response (will follow up with spec update)

client/core:

Log error and issue notification for active orders reported by DEX that are
unknown to the client.
Update order statuses where server-reported statuses are different from statuses
recorded by client.
Retrieve correct status using the order_status route for orders considered active by
the client but not returned by the DEX in the connect response.
Delete stale cancel orders if their target orders are returned as active in the connect
response.

Resolves #597.

itswisdomagain · 2020-09-16T17:41:40Z

Converting this to draft to allow #687 go in first, as the new order_status route will find good uses here.

itswisdomagain · 2020-09-16T21:08:55Z

+// Order 1:
+// - Standing order, preimage not revealed, "missed" revoke_order note.
+// - Expect order status to stay at Epoch status before going AWOL and to become
+//   Revoked after re-connecting the DEX. Locked coins should be returned.
+// Order 2:
+// - Non-standing order, preimage revealed, "missed" nomatch or match request (if
+//   matched).
+// - Expect order status to stay at Epoch status before going AWOL and to become
+//   Executed after re-connecting the DEX, even if the order was matched and the
+//   matches got revoked due to client inaction.
+// Order 3:
+// - Standing order, partially matched, booked, revoked due to inaction on a
+//   match.
+// - Expect order status to be Booked before going AWOL and to become Revoked
+//   after re-connecting the DEX. Locked coins should be returned.


These simulated and tested scenarios are 3 of the 4 scenarios documented in the table in #648 (comment) where coins may remain needlessly locked.

itswisdomagain · 2020-09-17T02:10:26Z

The last 2 commits are to enable me test with the order_status feature (cherry-picked the commit from #687). Will likely get edited a little bit more and force-pushed before this will be ready for review. I expect #687 will go in and I'll rebase this branch over the updated master before this becomes ready for review.

itswisdomagain · 2020-09-17T03:11:07Z

I'm satisfied with the workings of this branch as is. I was able to simulate some of the problematic conditions described in #648 (comment) using the webserver on master branch and get decent but incomplete resolution without the order_status route and complete resolution with the order_status route. Details below:

Master branch

2 clients, each with 2 orders stuck at an incorrect status and had funds locked.

Client 1, Problem Order 1: Limit order, not matched and became booked. Client received nomatch request and set the status to Booked. Client went offline and the order got matched while client was away. Match got revoked due to client inaction (client was maker) and the order got revoked. revoke_order messages are not currently sent for revoked orders and even if they were, client would have missed the message. Order got stucked at status Booked with funds locked.
Client 1, Problem Order 2: Limit order, not matched and became booked. Client submitted cancel order, sent preimage for the cancel order but missed the cancel match message. Order was canceled on the server but client is unaware. Order got stucked at status Booked with funds locked.
Client 2, Problem Order 1: Market order, client went offline before sending preimage. Order got revoked without client knowing. {Clients are currently not informed of orders revoked due to reimage misses. If the client was unable or unwilling to send the preimage, no reason to expect the client to properly handle an order revoked message.} Order got stuck at status Epoch with funds locked.
Client 2, Problem Order 2: Market order, client went offline after sending preimage. Order wasn't matched, became Executed but client missed the nomatch message. Order got stuck at status Epoch with funds locked.

Testing resolution with `87b781c` (connect response includes active orders + order.PreimageRevealed)

Client 1, Problem Order 1: Resolved against active orders in connect response, became Revoked ✅
Client 1, Problem Order 2: Resolved against active orders in connect response, became Canceled ☑️ (with guess work, assumed order was canceled because t.cancel != nil).
Client 2, Problem Order 1: Resolved against active orders in connect response, became Executed ❌ ( 87b781c assumes preimage was sent for all orders, so market order with preimage sent = Executed)
Client 2, Problem Order 2: Resolved against active orders in connect response, became Executed ✅
All stuck orders retired, locked funds returned.

Reconcilation logs

Client 1 Logs:
2020-09-16 23:36:07.086 [INF] CORE: loaded 2 incomplete orders
2020-09-16 23:36:07.114 [DBG] CORE: Authenticated connection to 127.0.0.1:40, 0 active orders, 0 active matches
2020-09-16 23:36:07.114 [DBG] CORE: Order cd638decba73c0d3c8586abd1f31278a8263af2bef24cf9281b20d71b2e1a290 updated from recorded status epoch to inactive status canceled
2020-09-16 23:36:07.114 [DBG] CORE[dcr]: returning coins [8fe6dd46f34f85e03195851f7cca7616ca60f78f1d38c84efe71d3a37726f96b:0]
2020-09-16 23:36:07.115 [DBG] CORE: Authenticated connection to localhost:40, 0 active orders, 0 active matches
2020-09-16 23:36:07.115 [DBG] CORE: Order ec53001d3cc11a121dfbc003ace830d2c4b9cad5237da7a1b25d1d6626e2fdf7 updated from recorded status booked to inactive status revoked
2020-09-16 23:36:07.115 [DBG] CORE[btc]: returning coins [64260e5ab227f99d6cc1b7b02702099a9cf403c91f1392e9e43ffb8ad1acad17:1]
2020-09-16 23:36:07.119 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-16 23:36:07.120 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-16 23:36:12.052 [INF] CORE: Retiring inactive order cd638decba73c0d3c8586abd1f31278a8263af2bef24cf9281b20d71b2e1a290 in status canceled
2020-09-16 23:36:12.055 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-09-16 23:36:12.056 [INF] CORE: Retiring inactive order ec53001d3cc11a121dfbc003ace830d2c4b9cad5237da7a1b25d1d6626e2fdf7 in status revoked
2020-09-16 23:36:12.060 [TRC] CORE: notify: |DATA| (balance) balance updated

Client 2 Logs:
2020-09-16 23:36:58.127 [INF] CORE: loaded 2 incomplete orders
2020-09-16 23:36:58.146 [DBG] CORE: Authenticated connection to 127.0.0.1:40, 0 active orders, 0 active matches
2020-09-16 23:36:58.146 [DBG] CORE: Authenticated connection to localhost:40, 0 active orders, 0 active matches
2020-09-16 23:36:58.146 [DBG] CORE: Order e0ef5cf0fd8ee598d0c13155ca405311aa4af74d421243eb8890d94f711098f2 updated from recorded status epoch to inactive status executed
2020-09-16 23:36:58.146 [DBG] CORE[btc]: returning coins [bc83c5fea01a9bea526a4716618f7b45331d7b710136e42d55f86f86ddbecca2:1]
2020-09-16 23:36:58.146 [DBG] CORE: Order 11c3390f2150cb87f87f1c02399d58d32f7a23482d6d306266743c4cf068af7d updated from recorded status epoch to inactive status executed
2020-09-16 23:36:58.146 [DBG] CORE[dcr]: returning coins [c6343b6837b1d8eab0fa6aee57ffd836f19a1f2a8693d5756e65a09b3c5bab51:1]
2020-09-16 23:36:58.149 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-16 23:36:58.150 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-16 23:37:00.249 [INF] CORE: Retiring inactive order e0ef5cf0fd8ee598d0c13155ca405311aa4af74d421243eb8890d94f711098f2 in status executed
2020-09-16 23:37:00.253 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-09-16 23:37:00.257 [INF] CORE: Retiring inactive order 11c3390f2150cb87f87f1c02399d58d32f7a23482d6d306266743c4cf068af7d in status executed
2020-09-16 23:37:00.259 [TRC] CORE: notify: |DATA| (balance) balance updated

Testing resolution with `a729612` (connect response includes active orders - order.PreimageRevealed + order_status)

Client 1, Problem Order 1: Resolved against active orders in connect response, became Revoked ✅
Client 1, Problem Order 2: Resolved against active orders in connect response, became Canceled ✅
Client 2, Problem Order 1: Resolved against active orders in connect response, became Revoked ✅
Client 2, Problem Order 2: Resolved against active orders in connect response, became Executed ✅
All stuck orders retired, locked funds returned. Fill updated for client 1's first order that got matched and revoked due to client inaction.

Reconcilation logs

Client 1 Logs:
2020-09-17 02:26:07.506 [INF] CORE: loaded 2 incomplete orders
2020-09-17 02:26:07.548 [DBG] CORE: Authenticated connection to 127.0.0.1:40, 0 active orders, 0 active matches
2020-09-17 02:26:07.549 [DBG] CORE: Authenticated connection to localhost:40, 0 active orders, 0 active matches
2020-09-17 02:26:07.549 [DBG] CORE: Requesting order status for 1 trades from DEX 127.0.0.1:40
2020-09-17 02:26:07.549 [DBG] CORE: Requesting order status for 1 trades from DEX localhost:40
2020-09-17 02:26:07.579 [DBG] CORE: Order cd638decba73c0d3c8586abd1f31278a8263af2bef24cf9281b20d71b2e1a290 updated from recorded status epoch to new status canceled reported by DEX 127.0.0.1:40
2020-09-17 02:26:07.579 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-17 02:26:07.581 [DBG] CORE: Order ec53001d3cc11a121dfbc003ace830d2c4b9cad5237da7a1b25d1d6626e2fdf7 updated from recorded status booked to new status revoked reported by DEX localhost:40
2020-09-17 02:26:07.581 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-17 02:26:21.179 [INF] CORE: Retiring inactive order cd638decba73c0d3c8586abd1f31278a8263af2bef24cf9281b20d71b2e1a290 in status canceled
2020-09-17 02:26:21.180 [INF] CORE: Retiring inactive order ec53001d3cc11a121dfbc003ace830d2c4b9cad5237da7a1b25d1d6626e2fdf7 in status revoked
2020-09-17 02:26:21.180 [DBG] CORE[btc]: returning coins [64260e5ab227f99d6cc1b7b02702099a9cf403c91f1392e9e43ffb8ad1acad17:1]
2020-09-17 02:26:21.180 [DBG] CORE[dcr]: returning coins [8fe6dd46f34f85e03195851f7cca7616ca60f78f1d38c84efe71d3a37726f96b:0]
2020-09-17 02:26:21.186 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-09-17 02:26:21.187 [TRC] CORE: notify: |DATA| (balance) balance updated

Client 2 Logs:
2020-09-17 02:28:33.108 [INF] CORE: loaded 2 incomplete orders
2020-09-17 02:28:33.131 [DBG] CORE: Authenticated connection to 127.0.0.1:40, 0 active orders, 0 active matches
2020-09-17 02:28:33.131 [DBG] CORE: Authenticated connection to localhost:40, 0 active orders, 0 active matches
2020-09-17 02:28:33.131 [DBG] CORE: Requesting order status for 1 trades from DEX 127.0.0.1:40
2020-09-17 02:28:33.131 [DBG] CORE: Requesting order status for 1 trades from DEX localhost:40
2020-09-17 02:28:33.140 [DBG] CORE: Order 11c3390f2150cb87f87f1c02399d58d32f7a23482d6d306266743c4cf068af7d updated from recorded status epoch to new status executed reported by DEX 127.0.0.1:40
2020-09-17 02:28:33.140 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-17 02:28:33.142 [DBG] CORE: Order e0ef5cf0fd8ee598d0c13155ca405311aa4af74d421243eb8890d94f711098f2 updated from recorded status epoch to new status revoked reported by DEX localhost:40
2020-09-17 02:28:33.142 [DBG] CORE: notify: |POKE| (dex_auth) Orders reconciled with DEX - Statuses updated for 1 orders.
2020-09-17 02:28:44.340 [INF] CORE: Retiring inactive order 11c3390f2150cb87f87f1c02399d58d32f7a23482d6d306266743c4cf068af7d in status executed
2020-09-17 02:28:44.341 [DBG] CORE[dcr]: returning coins [c6343b6837b1d8eab0fa6aee57ffd836f19a1f2a8693d5756e65a09b3c5bab51:1]
2020-09-17 02:28:44.340 [INF] CORE: Retiring inactive order e0ef5cf0fd8ee598d0c13155ca405311aa4af74d421243eb8890d94f711098f2 in status revoked
2020-09-17 02:28:44.341 [DBG] CORE[btc]: returning coins [bc83c5fea01a9bea526a4716618f7b45331d7b710136e42d55f86f86ddbecca2:1]
2020-09-17 02:28:44.346 [TRC] CORE: notify: |DATA| (balance) balance updated
2020-09-17 02:28:44.347 [TRC] CORE: notify: |DATA| (balance) balance updated

itswisdomagain · 2020-09-17T03:13:54Z

I'm gonna leave this as is for now until #687 goes in, then I'll clean it up and mark ready for review.

chappjc · 2020-09-18T02:49:01Z

Excellent analysis and summary of resolutions in that table. Certainly seems like the proper resolution is w/o the PreimageRevealed flag (although the v1 OrderProof "soft upgrade" was a clever approach) - order_status allows no db scheme changes, and correct status updates.

I'm pretty happy happy with PR #687 , and looking at this a bit it looks like querying for status of cancel orders may not be needed. Thoughts about that? We do still need to deal with cancel orders in epoch status, even if indirectly (checking the status of the targeted order instead).

itswisdomagain · 2020-09-18T14:25:41Z

Iirc, the only reason a cancel order will not get matched to the target order is if the cancel order's preimage was not sent or if the target order gets completely matched before the cancel order is processed.

If that's correct, we can infer the final status of the cancel order without querying for it:

REVOKED: If the target order is returned with the connect response, implying the target order is NEITHER executed nor canceled. If the target order is still booked, the cancel order's preimage was not sent.
EXECUTED: If the target order is NOT returned with the connect response, implying the target order is EITHER executed or canceled. We already query the status for such orders using the order_status route, so we'll know if the target order is executed or canceled. That will help determine if the cancel order was matched or unmatched.

Make sense?

chappjc · 2020-09-18T14:28:31Z

Client can also disappear after providing the cancel order's preimage, but before getting a match/nomatch back. A very brief window, but has happened several times. But even in this case it sounds like we can make the same inferences.

itswisdomagain · 2020-09-18T14:33:14Z

Right. We won't need to rely on the match/nomatch to determine the status of the cancel order. We just need to know the current status of the target order, if the target order is canceled, we know we missed a match request on the cancel order. If the target order is executed, we missed the preimage request or the nomatch request for the cancel order.

Reading that again, looks like we can't completely infer. If the target order is executed, it could be that the cancel order's preimage was not received and the target order went on to match completely; or it was received but the target order got executed before the cancel order was processed.

itswisdomagain · 2020-09-18T14:36:12Z

We can safely retire stale cancel orders anyway, but we would need the order_status route to account for cancel orders if we want to know the final status of the cancel order.

Basically, we can retire the cancel order if the target order

is no longer booked (now executed, revoked or canceled)
is booked but the cancel order's epoch ended a while ago.

The second case allows the client to submit another cancel order if they wish. The second case also means the cancel order was revoked.

chappjc · 2020-09-18T14:51:31Z

I want to say that we don't care what the cancel order status is as long as we know what happened with the trade, but I have a feeling that's going to haunt us. That said, I'm ok with moving forward with #687 without the ability to query cancel order statuses directly. We can modify that behavior as needed.

itswisdomagain · 2020-09-21T22:57:41Z

Marking this as ready for review. Feature complete now, just want to push another commit that refactors the db methods and types used in preparing the active orders for the connect response and the order_status response.

JoeGruffins

Simnet tests stopped twice in the same place:

--- FAIL: TestOrderStatusReconciliation (283.01s)
    trade_simnet_test.go:641: status not updated for client 2 order b9617f72b6cf122d796c9e01d509ccd750a86877629dd618f4d87266ff9abd88, expected revoked, got epoch

itswisdomagain · 2020-09-22T08:24:18Z

@JoeGruffins simnet issue should be fixed now. Noticed it a while ago and just force-pushed 😬 the fix. Didn't think anyone had eyes on this yet.

buck54321

Just a cursory look with some questions and suggestions.

buck54321 · 2020-09-22T11:52:50Z

+		oid := trade.ID()
+		previousStatus := trade.metaData.Status
+		newStatus := order.OrderStatus(msgOrder.Status)
+		trade.Trade().SetFill(msgOrder.Fill)


We've been careful other places to set fill based on our known matches, and I think that's the right approach. I wouldn't want to blindly accept the server's word on anything.

Well, the server is also the entity that provides the match info we need to set the fill client-side currently. As long as we have the server signing these messages, shouldn't we be safe? We're also relying on / blindly accepting the order status from the server, if the server wants to play games with the client, the server can do that with the status returned alone, i.e. if we decide to not return the fill.

Although I do have a concern with the client potentially not having details for some matches relating to the order that would have made this fill amount update necessary. If the client has all the matches for the order (even in wrong statuses, which can be corrected with the coming match_status work), the client can calculate and set the fill amount appropriately without requiring this info from the server.

An example to illustrate my above concern is an Epoch limit order getting partially matched while the client is away, client misses the match request, the match gets revoked while client is away say due to maker (the other user) inaction, client's order gets booked, and on reconnect, we're setting the fill to 30% but without any match info to back it up.

It's more just about having a single definition for the fill value. If the definition is "the sum value of all known matches", then that's what it should be. It shouldn't be "Either the sum of all known matches, or whatever the server told us, depending on what happened last".

I see the fill value as the amount we know to be filled; and we typically gather this value from match requests sent by the server. If there are other ways to determine the value, I have no objection to it. Unless, like you say, if it is the sum value of all known matches, then we only set fill based on known matches. I think I'm okay either direction. Any preference?

Simpler is better. 1 fewer field and 1 fewer definition to track is my preference. Should also avoid accepting the server as a source of truth. It wouldn't be terrible to check the server's reported fill value against our own just for verification and logging purposes, but it's hard to justify the extra field just for logging. I really think we should just remove the field from msgjson.OrderStatus until we find a compelling reason to include it.

chappjc · 2020-09-25T23:43:57Z

A couple of races:

==================
WARNING: DATA RACE
Write at 0x00c0012ba1b0 by goroutine 86:
  runtime.mapassign()
      /home/jon/go115/src/runtime/map.go:571 +0x0
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation.func4()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:485 +0x844
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:57 +0x94

Previous write at 0x00c0012ba1b0 by goroutine 67:
  ??()
      -:0 +0xffffffffffffffff
  go.etcd.io/bbolt.(*Tx).Commit()
      /home/jon/go/pkg/mod/go.etcd.io/bbolt@v1.3.5/tx.go:185 +0x3aa
  go.etcd.io/bbolt.(*DB).Update()
      /home/jon/go/pkg/mod/go.etcd.io/bbolt@v1.3.5/db.go:701 +0x17d
  go.etcd.io/bbolt.(*DB).Update-fm()
      /home/jon/go/pkg/mod/go.etcd.io/bbolt@v1.3.5/db.go:677 +0x4b
  decred.org/dcrdex/client/db/bolt.(*BoltDB).withBucket()
      /home/jon/github/decred/dcrdex/client/db/bolt/db.go:1141 +0xd6
  decred.org/dcrdex/client/db/bolt.(*BoltDB).walletsUpdate()
      /home/jon/github/decred/dcrdex/client/db/bolt/db.go:1039 +0xb5
  decred.org/dcrdex/client/db/bolt.(*BoltDB).UpdateBalance()
      /home/jon/github/decred/dcrdex/client/db/bolt/db.go:975 +0xdb
  decred.org/dcrdex/client/core.(*Core).walletBalances()
      /home/jon/github/decred/dcrdex/client/core/core.go:1045 +0x3b9
  decred.org/dcrdex/client/core.(*Core).updateBalances()
      /home/jon/github/decred/dcrdex/client/core/core.go:1080 +0x12a
  decred.org/dcrdex/client/core.(*Core).updateAssetBalance()
      /home/jon/github/decred/dcrdex/client/core/core.go:1092 +0x469
  decred.org/dcrdex/client/core.(*Core).Trade()
      /home/jon/github/decred/dcrdex/client/core/core.go:2206 +0x3ce
  decred.org/dcrdex/client/core.(*tClient).placeOrder()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:1245 +0x5a6
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation.func3()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:435 +0xbe
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:57 +0x94

Goroutine 86 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:54 +0x73
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:458 +0x91b
  testing.tRunner()
      /home/jon/go115/src/testing/testing.go:1127 +0x202

Goroutine 67 (finished) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:54 +0x73
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:432 +0x7b1
  testing.tRunner()
      /home/jon/go115/src/testing/testing.go:1127 +0x202
==================
==================
WARNING: DATA RACE
Write at 0x00c0012ba1e0 by goroutine 86:
  runtime.mapassign()
      /home/jon/go115/src/runtime/map.go:571 +0x0
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation.func4()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:486 +0x8b3
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:57 +0x94

Previous write at 0x00c0012ba1e0 by goroutine 67:
  ??()
      -:0 +0xffffffffffffffff
  go.etcd.io/bbolt.(*Tx).Commit()
      /home/jon/go/pkg/mod/go.etcd.io/bbolt@v1.3.5/tx.go:185 +0x3aa
  go.etcd.io/bbolt.(*DB).Update()
      /home/jon/go/pkg/mod/go.etcd.io/bbolt@v1.3.5/db.go:701 +0x17d
  go.etcd.io/bbolt.(*DB).Update-fm()
      /home/jon/go/pkg/mod/go.etcd.io/bbolt@v1.3.5/db.go:677 +0x4b
  decred.org/dcrdex/client/db/bolt.(*BoltDB).withBucket()
      /home/jon/github/decred/dcrdex/client/db/bolt/db.go:1141 +0xd6
  decred.org/dcrdex/client/db/bolt.(*BoltDB).walletsUpdate()
      /home/jon/github/decred/dcrdex/client/db/bolt/db.go:1039 +0xb5
  decred.org/dcrdex/client/db/bolt.(*BoltDB).UpdateBalance()
      /home/jon/github/decred/dcrdex/client/db/bolt/db.go:975 +0xdb
  decred.org/dcrdex/client/core.(*Core).walletBalances()
      /home/jon/github/decred/dcrdex/client/core/core.go:1045 +0x3b9
  decred.org/dcrdex/client/core.(*Core).updateBalances()
      /home/jon/github/decred/dcrdex/client/core/core.go:1080 +0x12a
  decred.org/dcrdex/client/core.(*Core).updateAssetBalance()
      /home/jon/github/decred/dcrdex/client/core/core.go:1092 +0x469
  decred.org/dcrdex/client/core.(*Core).Trade()
      /home/jon/github/decred/dcrdex/client/core/core.go:2206 +0x3ce
  decred.org/dcrdex/client/core.(*tClient).placeOrder()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:1245 +0x5a6
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation.func3()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:435 +0xbe
  golang.org/x/sync/errgroup.(*Group).Go.func1()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:57 +0x94

Goroutine 86 (running) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:54 +0x73
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:458 +0x91b
  testing.tRunner()
      /home/jon/go115/src/testing/testing.go:1127 +0x202

Goroutine 67 (finished) created at:
  golang.org/x/sync/errgroup.(*Group).Go()
      /home/jon/go/pkg/mod/golang.org/x/sync@v0.0.0-20190423024810-112230192c58/errgroup/errgroup.go:54 +0x73
  decred.org/dcrdex/client/core.TestOrderStatusReconciliation()
      /home/jon/github/decred/dcrdex/client/core/trade_simnet_test.go:432 +0x7b1
  testing.tRunner()
      /home/jon/go115/src/testing/testing.go:1127 +0x202
==================

- Log error and issue notification for active orders reported by DEX that are unknown to the client. - Update order statuses where server-reported statuses are different from statuses recorded by client. - Set statuses to Executed, Canceled or Revoked for orders considered active by the client but not returned by the DEX in the connect response. TODO: implement an `order_status` route to accurately determine current statuses for such orders. Also, set OrderProof.PreimageRevealed when client responds to preimage requests.

Also modify trade simnet test cases to run distinctly, wtih new clients created for each test case, to prevent spillages across test cases.

…uses

…erStatus

itswisdomagain · 2020-09-28T10:42:58Z

Still failing for me at trade_simnet_test.go:631: status not updated for client 2 order ab6568957defb85e522eb372542c92248a0ac60c22b5d6b3210e51561100113f, expected revoked, got epoch

I'm getting this again, and I know why. I reduced the wait-before-reconnect time to just BroadcastTimeout+2 Seconds, which is cutting it close as inaction checks kick in after BroadcastTimeout. In one test case, I saw from the dcrdex logs that the last order was revoked 12 seconds after the client reconnected, so when the client reconnected, the server still had the order booked.

JoeGruffins · 2020-09-29T00:09:50Z

Still the failure for simnet test.

--- FAIL: TestOrderStatusReconciliation (160.60s)
    trade_simnet_test.go:650: status not updated for client 2 order 83d1ee4bc7f7007383e976d1a3b2449860678205ccc5b919beb2f49e8dbb363a, expected revoked, got epoch
FAIL
exit status 1
FAIL    decred.org/dcrdex/client/core   402.266s
[joe@hyrule core]$ git log
commit ecbb7ac3669d2ec446b6e1fb241ca716580078ad (HEAD -> 677)
Author: Wisdom Arerosuoghene <wisdom.arerosuoghene@gmail.com>
Date:   Tue Sep 29 00:39:26 2020 +0100

    validate order_status requests

itswisdomagain · 2020-09-29T21:23:46Z

@JoeGruffins, I think it might be a timing issue for your tests. Can you check if your dcrdex logs show the order getting revoked after the tests fail? If so, try increasing the wait-before-reconnect timeout here and let's see if that gets the tests passing for you. I'm cutting it a little close there with 2*bTimeout but I expect that should be enough time for the server to detect and revoke orders for at-fault matches.

Also a good idea to restart the dcrdex harness between tests to prevent previous orders on the book messing up the test.

Btw, I've recently only ran the TestOrderStatusReconciliation test specifically using go test ./client/core -v -tags harness -race -run "TestOrderStatusReconciliation" -count 1. See if that works for you?

chappjc

My review items are addressed.

But the core's harness tests still fail for me:

trade_simnet_test.go:650: status not updated for client 2 order 6109169027aa12cbebf71c815727613b4649639407a94cca70196d5f04b081ff, expected revoked, got epoch
...
--- FAIL: TestOrderStatusReconciliation (162.28s)

@JoeGruffins and I both consistently have trouble with the tests, but we'll have to continue investigating on the status-integ branch when this is merged. To merge status-integ with master, we will have another PR for that, on which we can test again.

chappjc · 2020-09-30T16:25:28Z

Going to merge since code looks good and TestOrderStatusReconciliation does pass when run alone (-run TestOrderStatusReconciliation), but we need to identify the reason for it's failure when the entire core harness test suite is run.

itswisdomagain force-pushed the detect-order-statuses branch from df865a6 to bf301eb Compare September 9, 2020 15:53

itswisdomagain marked this pull request as ready for review September 14, 2020 20:03

itswisdomagain force-pushed the detect-order-statuses branch 2 times, most recently from d6fd5f6 to 7613348 Compare September 14, 2020 23:57

itswisdomagain marked this pull request as draft September 16, 2020 17:41

itswisdomagain commented Sep 16, 2020

View reviewed changes

itswisdomagain force-pushed the detect-order-statuses branch from 5bce26b to a729612 Compare September 17, 2020 02:19

chappjc added the high priority label Sep 18, 2020

itswisdomagain mentioned this pull request Sep 19, 2020

server/{auth,db}: add order_status route #687

Merged

itswisdomagain force-pushed the detect-order-statuses branch from a729612 to b5678de Compare September 21, 2020 20:25

itswisdomagain marked this pull request as ready for review September 21, 2020 22:57

itswisdomagain commented Sep 21, 2020

View reviewed changes

Comment thread server/auth/auth.go Outdated

Comment thread client/core/core_test.go Outdated

Comment thread client/core/core_test.go

Comment thread client/core/trade.go Outdated

itswisdomagain commented Sep 22, 2020

View reviewed changes

Comment thread client/core/core.go

JoeGruffins reviewed Sep 22, 2020

View reviewed changes

Comment thread client/core/trade.go Outdated

Comment thread server/db/driver/pg/internal/orders.go Outdated

Comment thread server/db/driver/pg/orders.go Outdated

itswisdomagain force-pushed the detect-order-statuses branch from 5de3c35 to dc35ddf Compare September 22, 2020 08:18

buck54321 reviewed Sep 22, 2020

View reviewed changes

itswisdomagain changed the base branch from master to status-integ September 22, 2020 21:19

buck54321 mentioned this pull request Sep 23, 2020

server/multi: remove server-side message caching #699

Merged

itswisdomagain added 12 commits September 28, 2020 11:10

server/{auth,db}: connect response return active orders

f5fe8a8

simnet: add trading test for order status reconciliation

1cb421a

Also modify trade simnet test cases to run distinctly, wtih new clients created for each test case, to prevent spillages across test cases.

determine correct order statuses using order_status route

ad6539d

retire OrderProof.PreimageRevealed field

aba81c4

retire stale cancel orders if target orders are still active

f4efff0

cleanup

15d1654

server/{auth,db},multi: combine and refactor UserOrders and OrderStat…

8db756c

…uses

undo OrderArchiver.UserOrders changes, rename msgjson/db.Order to Ord…

ed92e9b

…erStatus

update core.reconcileTrades comment and test

933fe1d

client/core: connect response - process matches before order statuses

41d382d

fix OrderArchiver.userOrderStatusesFromTable ctx cancellation bug

7ec4155

itswisdomagain force-pushed the detect-order-statuses branch from 434ebb0 to c7c9841 Compare September 28, 2020 10:12

review

7342b4f

itswisdomagain force-pushed the detect-order-statuses branch from c7c9841 to 7342b4f Compare September 28, 2020 10:16

simnet TestOrderStatusReconciliation: check locked balance return

c4d2d42

buck54321 requested changes Sep 28, 2020

View reviewed changes

validate order_status requests

ecbb7ac

remove Fill from server OrderStatus

d6942a1

buck54321 approved these changes Sep 30, 2020

View reviewed changes

chappjc approved these changes Sep 30, 2020

View reviewed changes

chappjc merged commit bdbb8cb into decred:status-integ Sep 30, 2020

chappjc mentioned this pull request Sep 30, 2020

core: match status resolution #704

Merged

itswisdomagain deleted the detect-order-statuses branch October 1, 2020 08:37

chappjc mentioned this pull request Oct 2, 2020

integration: order and status checks, no pending server messages #716

Merged

Conversation

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

Uh oh!

Uh oh!

itswisdomagain commented Sep 16, 2020

Uh oh!

itswisdomagain Sep 16, 2020

Choose a reason for hiding this comment

Uh oh!

itswisdomagain commented Sep 17, 2020

Uh oh!

itswisdomagain commented Sep 17, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Master branch

Testing resolution with 87b781c (connect response includes active orders + order.PreimageRevealed)

Testing resolution with a729612 (connect response includes active orders - order.PreimageRevealed + order_status)

Uh oh!

itswisdomagain commented Sep 17, 2020

Uh oh!

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

Uh oh!

Uh oh!

itswisdomagain commented Sep 18, 2020

Uh oh!

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

Uh oh!

Uh oh!

itswisdomagain commented Sep 18, 2020

Uh oh!

itswisdomagain commented Sep 18, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

chappjc commented Sep 18, 2020

Uh oh!

itswisdomagain commented Sep 21, 2020

Uh oh!

Uh oh!

Uh oh!

Uh oh!

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!

Uh oh!

Uh oh!

itswisdomagain commented Sep 22, 2020

Uh oh!

buck54321 left a comment

Choose a reason for hiding this comment

Uh oh!

buck54321 Sep 22, 2020

Choose a reason for hiding this comment

Uh oh!

itswisdomagain Sep 22, 2020

Choose a reason for hiding this comment

Uh oh!

buck54321 Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

itswisdomagain Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

buck54321 Sep 28, 2020

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

chappjc commented Sep 25, 2020

Uh oh!

itswisdomagain commented Sep 28, 2020

Uh oh!

Uh oh!

Uh oh!

itswisdomagain commented Sep 9, 2020 •

edited

Loading

itswisdomagain commented Sep 17, 2020 •

edited

Loading

Testing resolution with `87b781c` (connect response includes active orders + order.PreimageRevealed)

Testing resolution with `a729612` (connect response includes active orders - order.PreimageRevealed + order_status)

chappjc commented Sep 18, 2020 •

edited

Loading

chappjc commented Sep 18, 2020 •

edited

Loading

itswisdomagain commented Sep 18, 2020 •

edited

Loading

JoeGruffins left a comment •

edited

Loading