Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

client/core: monotonic OrderBook state updates #4

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

norwnd
Copy link
Owner

@norwnd norwnd commented Mar 8, 2023

Should prevent:

@norwnd
Copy link
Owner Author

norwnd commented Mar 8, 2023

Could go even further and sanity check lower seq bound too (it shouldn't be < prevSeq - which is the last valid known value from previous subscription).

Comment on lines -508 to -512
// May want to re-implement strict sequence checking. Might use these tests
// again.
// {
// label: "Unbook sell order with outdated sequence value",
// orderBook: makeOrderBook(
Copy link
Owner Author

@norwnd norwnd Mar 8, 2023

Choose a reason for hiding this comment

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

Hmm, I see relevant comment here from long time ago, but it doesn't quite answer why these were commented out in the first place ... Anyway, these tests work reasonably well with my changes - which is a good sign :)

@norwnd norwnd force-pushed the client-core-monotonic-book-state-updates branch 2 times, most recently from 30c855f to 866a8cb Compare March 8, 2023 17:10
Comment on lines 591 to 678
note: makeUnbookOrderNote(5, "ob", [32]byte{'d'}),
expected: nil,
wantErr: true,
note: makeUnbookOrderNote(5, "ob", [32]byte{'b'}),
expected: makeOrderBook(
2,
"ob",
[]*Order{
makeOrder([32]byte{'b'}, msgjson.SellOrderNum, 10, 1, 2),
makeOrder([32]byte{'c'}, msgjson.SellOrderNum, 10, 2, 5),
},
make([]*cachedOrderNote, 0),
true,
),
wantErr: false,
Copy link
Owner Author

@norwnd norwnd Mar 8, 2023

Choose a reason for hiding this comment

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

And this "Unbook sell order with future sequence value" test seems to have worked because it was failing due to unknown id error, not the one the name claims to test, note, I changed order ID d->b (it fails like this on master)

Copy link
Owner Author

Choose a reason for hiding this comment

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

Fixed other similar issues (expectation mismatch) I found in these tests too.

@norwnd
Copy link
Owner Author

norwnd commented Mar 9, 2023

I've been running this PR on mainnet, and occasionally I see notes from future:

2023-03-09 05:32:46.634 [ERR] CORE[wss://dex.decred.org:7232/ws]: Read timeout on connection to wss://dex.decred.org:7232/ws.
2023-03-09 05:32:46.634 [DBG] CORE: notify: |POKE| (conn) Server disconnect - dex.decred.org:7232 is disconnected
2023-03-09 05:32:46.634 [INF] CORE[wss://dex.decred.org:7232/ws]: Attempting to reconnect to wss://dex.decred.org:7232/ws...
2023-03-09 05:32:50.850 [TRC] CORE[eth][RPC]: "mainnet.infura.io" reported new tip at height 16788590 (0x7d74ce8d048302eed17efe965254410f670a5447c9d1af2ac97bfcedca87176f)
2023-03-09 05:32:50.900 [DBG] CORE: notify: |POKE| (conn) Server connected - dex.decred.org:7232 is connected
2023-03-09 05:32:50.900 [INF] CORE[wss://dex.decred.org:7232/ws]: Successfully reconnected.
2023/03/09 08:32:50 "GET http://127.0.0.1:5758/api/user HTTP/1.1" from 127.0.0.1:63361 - 200 49557B in 49.374077ms
2023/03/09 08:32:51 "GET http://127.0.0.1:5758/markets HTTP/1.1" from 127.0.0.1:63361 - 200 49343B in 61.085351ms
2023-03-09 05:32:51.029 [TRC] WEB[WS]: message of type 1 received for route unmarket
2023-03-09 05:32:51.039 [TRC] WEB[WS]: message of type 1 received for route loadmarket
2023-03-09 05:32:51.040 [TRC] WEB[WS]: message of type 1 received for route loadcandles
2023-03-09 05:32:51.564 [DBG] CORE[eth]: tip change: 16788589 (0x3d3c701b6ec378d917edba3bf354da4970583a6bd8eda4a02a9783b929fba781) => 16788590 (0x7d74ce8d048302eed17efe965254410f670a5447c9d1af2ac97bfcedca87176f)
2023-03-09 05:32:51.564 [TRC] CORE: Processing tip change for eth
2023-03-09 05:32:51.564 [TRC] CORE: Processing tip change for usdc.eth
2023-03-09 05:32:51.692 [INF] CORE: Server dex.decred.org:7232 supports API version 0.
2023-03-09 05:32:51.692 [DBG] CORE: Server dex.decred.org:7232 broadcast timeout 22m0s. Tick interval 2m45s
2023-03-09 05:32:51.692 [DBG] CORE: Subscribing to the dcr_btc order book for dex.decred.org:7232
2023-03-09 05:32:57.332 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363160 MarketID:dcr_btc OrderID:6d5f1de65bbf62a283bf46f9366f2e938c3566ef744990bc4330f389fb93bfc5} TradeNote:{Side:2 Quantity:4000000000 Rate:93800 TiF:1 Time:1678340083949}} Commit:bec0b22e2c12a72b0021114d160b9c9645cfda4c82aa30146e984e7b1eaed3cc OrderType:1 Epoch:167834008 TargetID:}, err: got sequence number from the future 363160, want exactly 363157 + 1
2023-03-09 05:32:57.335 [TRC] CORE[dcr_btc][book]: Resetting order book from server snapshot seq: 363159
2023-03-09 05:32:57.335 [DBG] CORE[dcr_btc][book]: Processing 0 cached order notes
2023-03-09 05:32:57.437 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363161 MarketID:dcr_btc OrderID:8f381aaed7350b10d04b2faf50e0dd2933bd6f3f2b927008d623927a605d90ad} TradeNote:{Side:1 Quantity:8000000000 Rate:91500 TiF:1 Time:1678340085536}} Commit:8602bbc1eb2de0e9aa1ae50db56c4972136d37eaa076fa2bcd4521181b73a0ed OrderType:1 Epoch:167834008 TargetID:}, err: got sequence number from the future 363161, want exactly 363159 + 1
2023-03-09 05:33:00.727 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363162 MarketID:dcr_btc OrderID:fb256203ebf25fc7a839b91e1d83c28eb98e123000dbe3c57ce5505af821df66} TradeNote:{Side:0 Quantity:0 Rate:0 TiF:0 Time:1678340086745}} Commit:9f9fe12a0fa8bd835cf3783cd8d80e079ce8430f926370a48cf1dd609a1eac21 OrderType:3 Epoch:167834008 TargetID:91843b93066028d4f1d418b48f73b0d4e26915cd013a06bf20bc2198295d28c2}, err: got sequence number from the future 363162, want exactly 363159 + 1
2023-03-09 05:33:00.728 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363163 MarketID:dcr_btc OrderID:714bef4b9b86df6c831668060217cc1a36069e5452db8e71c340ac353daebcd2} TradeNote:{Side:0 Quantity:0 Rate:0 TiF:0 Time:1678340087446}} Commit:743893c2f2ec6ec83cdb33622f154abc6e9f79892bad0f8db97a75bfe545f6e0 OrderType:3 Epoch:167834008 TargetID:6d5f1de65bbf62a283bf46f9366f2e938c3566ef744990bc4330f389fb93bfc5}, err: got sequence number from the future 363163, want exactly 363159 + 1
2023-03-09 05:33:00.728 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363164 MarketID:dcr_btc OrderID:ab39e94d389a9af004a85449100b05d6322ed01535d2ed1c2586cc09bb23253e} TradeNote:{Side:0 Quantity:0 Rate:0 TiF:0 Time:1678340088172}} Commit:0cceb9859aa3fcb4e481c30c400ab6461f571122af1d82e7bc0e4eb65a4262bc OrderType:3 Epoch:167834008 TargetID:5f71c709c56e7f656c0e8907214f26b8904c7d3e69c95160a01cbd8bca2473f4}, err: got sequence number from the future 363164, want exactly 363159 + 1
2023-03-09 05:33:01.564 [ERR] CORE: error updating "eth" balance: pending balance error: balance error: context deadline exceeded
2023-03-09 05:33:01.565 [ERR] CORE: error updating "usdc.eth" balance: pending balance error: balance error: context deadline exceeded
2023-03-09 05:33:07.525 [TRC] CORE[eth][RPC]: Using cached header from "mainnet.infura.io"
2023-03-09 05:33:10.097 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363165 MarketID:dcr_btc OrderID:e8cf14fd3c86fa10bbaedb9edbb1d658b3bc84c9a5d5fc36b96fd838b50affec} TradeNote:{Side:0 Quantity:0 Rate:0 TiF:0 Time:1678340088895}} Commit:f5eb585146cdd9f46e87319159e576ed9be3e9490d5e002bab1d108d735791a8 OrderType:3 Epoch:167834008 TargetID:8f381aaed7350b10d04b2faf50e0dd2933bd6f3f2b927008d623927a605d90ad}, err: got sequence number from the future 363165, want exactly 363159 + 1
2023-03-09 05:33:10.098 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363166 MarketID:dcr_btc OrderID:c93a0b0fa62298e988fb72dd6863d1bb6f6f19a83edf3d90ea875489e1ef919a} TradeNote:{Side:0 Quantity:0 Rate:0 TiF:0 Time:1678340089786}} Commit:3ac3d7c3a4dc4237fe8afecaea9dff09e6d93764b2461b360c7186f5d239f75e OrderType:3 Epoch:167834008 TargetID:135c9f8fc0b7fdcae2c4e1f0a85a66c809338886aaa8e3d8c53b44c3d62fd445}, err: got sequence number from the future 363166, want exactly 363159 + 1
2023-03-09 05:33:10.531 [TRC] CORE[eth][RPC]: "mainnet.infura.io" reported new tip at height 16788591 (0x735528938faffade4c5dc8b10b273455a2f27c5b4611339169d4bf895b03d85e)
2023-03-09 05:33:10.564 [DBG] CORE[eth]: tip change: 16788590 (0x7d74ce8d048302eed17efe965254410f670a5447c9d1af2ac97bfcedca87176f) => 16788591 (0x735528938faffade4c5dc8b10b273455a2f27c5b4611339169d4bf895b03d85e)
2023-03-09 05:33:10.564 [TRC] CORE: Processing tip change for usdc.eth
2023-03-09 05:33:10.564 [TRC] CORE: Processing tip change for eth
2023-03-09 05:33:15.089 [ERR] CORE: Route 'match_proof' notification handler error (DEX dex.decred.org:7232): match proof validation failed: epoch 167834008 match proof note references 8 orders, but local epoch queue is empty
2023-03-09 05:33:15.095 [ERR] CORE[dcr_btc][book]: Unexpected book_order notification encountered: &{OrderNote:{Seq:363167 MarketID:dcr_btc OrderID:5635ec59c8fd4e0c695cd2167d59042c2d7faed10fdfedc7e6a8adc9f959933f} TradeNote:{Side:2 Quantity:4000000000 Rate:93700 TiF:1 Time:1678340080660}}, err: got sequence number from the future 363167, want exactly 363159 + 1
2023-03-09 05:33:15.095 [ERR] CORE[dcr_btc][book]: Unexpected book_order notification encountered: &{OrderNote:{Seq:363168 MarketID:dcr_btc OrderID:6d5f1de65bbf62a283bf46f9366f2e938c3566ef744990bc4330f389fb93bfc5} TradeNote:{Side:2 Quantity:4000000000 Rate:93800 TiF:1 Time:1678340083949}}, err: got sequence number from the future 363168, want exactly 363159 + 1
2023-03-09 05:33:15.095 [ERR] CORE[dcr_btc][book]: Unexpected book_order notification encountered: &{OrderNote:{Seq:363169 MarketID:dcr_btc OrderID:8f381aaed7350b10d04b2faf50e0dd2933bd6f3f2b927008d623927a605d90ad} TradeNote:{Side:1 Quantity:8000000000 Rate:91500 TiF:1 Time:1678340085536}}, err: got sequence number from the future 363169, want exactly 363159 + 1
2023-03-09 05:33:15.127 [ERR] CORE[dcr_btc][book]: Unexpected unbook_order notification encountered: &{Seq:363170 MarketID:dcr_btc OrderID:135c9f8fc0b7fdcae2c4e1f0a85a66c809338886aaa8e3d8c53b44c3d62fd445}, err: got sequence number from the future 363170, want exactly 363159 + 1
2023-03-09 05:33:15.127 [ERR] CORE[dcr_btc][book]: Unexpected unbook_order notification encountered: &{Seq:363171 MarketID:dcr_btc OrderID:5f71c709c56e7f656c0e8907214f26b8904c7d3e69c95160a01cbd8bca2473f4}, err: got sequence number from the future 363171, want exactly 363159 + 1
2023-03-09 05:33:15.127 [ERR] CORE[dcr_btc][book]: Unexpected unbook_order notification encountered: &{Seq:363172 MarketID:dcr_btc OrderID:91843b93066028d4f1d418b48f73b0d4e26915cd013a06bf20bc2198295d28c2}, err: got sequence number from the future 363172, want exactly 363159 + 1
2023-03-09 05:33:15.358 [ERR] CORE[dcr_btc][book]: Unexpected epoch_order notification encountered: &{BookOrderNote:{OrderNote:{Seq:363173 MarketID:dcr_btc OrderID:4ae32e8051da6e81faa4051acf00264b05c8609a4d8c8a7d082110b8037f1421} TradeNote:{Side:0 Quantity:0 Rate:0 TiF:0 Time:1678340104318}} Commit:15e8f8aee66a4125a6737a786bbe78c72ba47ecf3bcd8bbdbdd771474316dd13 OrderType:3 Epoch:167834010 TargetID:5635ec59c8fd4e0c695cd2167d59042c2d7faed10fdfedc7e6a8adc9f959933f}, err: got sequence number from the future 363173, want exactly 363159 + 1

... and so it goes until disconnect 1 min later (not sure if disconect is accidental, or if it's intentional once order book goes stale):

2023-03-09 05:33:47.892 [ERR] CORE[wss://dex.decred.org:7232/ws]: Read timeout on connection to wss://dex.decred.org:7232/ws.
2023-03-09 05:33:47.892 [DBG] CORE: notify: |POKE| (conn) Server disconnect - dex.decred.org:7232 is disconnected
2023-03-09 05:33:47.892 [INF] CORE[wss://dex.decred.org:7232/ws]: Attempting to reconnect to wss://dex.decred.org:7232/ws...

then it reconnects and continues to work without obvious issues. Full log: notes-from-future.txt

So, was relaxing constraint to allow future notifications the most practical way to address it at the time ? If it ain't part of design #1 + #2 + #4 will hopefully fix it (along with ghost orders and whatnot).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

1 participant