`kraken` live and dark orders don't send correct fill messages, pp doesn't update... etc. #310

goodboy · 2022-05-09T19:05:17Z

just entered via one and none of the following worked in the chart order mode UI:

no fill message received and thus no fill triangle annotation placed on the chart
no position update and thus no pp line
no notification of a fill anywhere..

Looking at these logs i dunno why exactly the UI isn't updating (since the order did clear) but it's likely a messaging or reqid mismatch i'm guessing.

Probably also relates to work described in #290.

`pikerd` logs:

May 09 13:41:19 (emsd, 34778, _emsd_main)) [INFO] piker.clearing._ems _ems.py:787 Received order cmd:
{'account': 'kraken.spot',
 'action': 'buy',
 'brokers': ['kraken'],
 'exec_mode': 'dark',
 'oid': '2169fa61-b143-40cf-984a-3eb6d80bf213',
 'price': 29827.0,
 'size': 0.00419083,
 'symbol': 'xbteur.kraken'}
 
May 09 13:53:07 (emsd, 34778, piker.clearing._ems.clear_dark_triggers)) [INFO] piker.clearing._ems _ems.py:209 Dark order triggered for price 29824.5
Submitting order @ price 29825.0

May 09 13:53:07 (emsd, 34778, piker.clearing._ems.clear_dark_triggers)) [INFO] piker.clearing._ems _ems.py:257 removing pred for 2169fa61-b143-40cf-984a-3eb6d80bf213

May 09 13:53:07 (brokerd.kraken, 34735, piker.brokers.kraken.handle_order_requests)) [INFO] piker.brokers.kraken kraken.py:572 Received order request:
{'action': 'buy', 'oid': '2169fa61-b143-40cf-984a-3eb6d80bf213', 
'account': 'kraken.spot', 'time_ns': 1652118787952366919, 'reqid': None, 
'symbol': 'xbteur', 'price': 29825.0, 'size': 0.00419083}

May 09 13:53:08 (emsd, 34778, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'account': 'kraken.spot',
 'broker_details': {'broker_time': '1652118788.621332', 'name': 'kraken'},
 'external': False,
 'filled': 0.00419083,
 'name': 'status',
 'reason': 'Order filled by kraken',
 'remaining': 0.0,
 'reqid': 'OAH2LZ-IKTGB-5XUK6H',
 'status': 'filled',
 'time_ns': 1652118788689217822}
 
May 09 13:53:08 (emsd, 34778, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'action': 'buy',
 'broker_details': {'name': 'kraken'},
 'broker_time': 1652118788.621332,
 'name': 'fill',
 'price': 29818.6,
 'reqid': 'OAH2LZ-IKTGB-5XUK6H',
 'size': 0.00419083,
 'time_ns': 1652118788697297326}
 
May 09 13:53:08 (emsd, 34778, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'account': 'kraken.spot',
 'name': 'ack',
 'oid': '2169fa61-b143-40cf-984a-3eb6d80bf213',
 'reqid': 'OAH2LZ-IKTGB-5XUK6H'}
 
May 09 14:22:16 (emsd, 34778, piker.clearing._ems.clear_dark_triggers)) [INFO] piker.clearing._ems _ems.py:257 removing pred for 13869f35-3de6-436e-b5e9-6b3d18619d9a

May 09 14:43:59 (emsd, 34778, piker.clearing._ems.clear_dark_triggers)) [INFO] piker.clearing._ems _ems.py:209 Dark order triggered for price 28634.9
Submitting order @ price 28635.4

May 09 14:43:59 (brokerd.kraken, 34735, piker.brokers.kraken.handle_order_requests)) [INFO] piker.brokers.kraken kraken.py:572 Received order request
{'action': 'buy', 'oid': '450245d0-834c-4553-b6be-f0ca47b77338', 'account': 'kraken.spot',
 'time_ns': 1652121839455145816, 'reqid': None, 'symbol': 'xbteur', 'price': 28635.4, 'size': 0.0174082}
 
May 09 14:43:59 (emsd, 34778, piker.clearing._ems.clear_dark_triggers)) [INFO] piker.clearing._ems _ems.py:257 removing pred for 450245d0-834c-4553-b6be-f0ca47b77338

May 09 14:44:00 (emsd, 34778, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'account': 'kraken.spot',
 'name': 'ack',
 'oid': '450245d0-834c-4553-b6be-f0ca47b77338',
 'reqid': 'OOE3AE-SI6II-GJXDUA'}

May 09 14:47:13 (emsd, 34778, _emsd_main)) [INFO] piker.clearing._ems _ems.py:787 Received order cmd:
{'action': 'cancel',
 'oid': '1a89772e-fd50-408a-b9e3-7d77d5cb8439',
 'symbol': 'xbteur.kraken'}
 
May 09 14:53:05 (emsd, 34778, _emsd_main)) [INFO] piker.clearing._ems _ems.py:787 Received order cmd:
{'action': 'cancel',
 'oid': '450245d0-834c-4553-b6be-f0ca47b77338',
 'symbol': 'xbteur.kraken'}

The text was updated successfully, but these errors were encountered:

goodboy · 2022-05-09T19:14:30Z

The UI was left with just the dotted dark order line where it had been placed originally by the user.

goodboy · 2022-05-09T21:01:30Z

Ok looking at this in more detail my best guess is that it's a race condition with the txid that's returned as a .reqid by kraken?

Since the kraken generated order id is done synchronously in kraken.handle_order_requests() the BrokerdAck that contains the new .reqid (that the ems uses to map the client side) isn't guaranteed to be received before the BrokerdStatus or BrokerdFill messages?

I'm not entirely sure honestly if this is the issue; i really should have captured the client side messaging dialog.. but wasn't thinking.

goodboy · 2022-05-09T21:49:03Z

Ahh yes, looking at the logic that hits in the ems when there is no .oid in the rx msg, what likely happened is this:

order request received by brokerd.kraken
order submitted right away to kraken's order api synchronously and does not return before the order submission is complete
the ws feed receives and relays the order, with txid before the handle_order_requests() task is able to send a BrokerdAck back to the ems (since it's still blocking in the sync .submit_limit(), thus the ems receives a brokerd_msg with .oid == None and more or less the msg is ignored and not relayed.

I'm not actually sure if it ever did, dark orders ever worked in this code.

Solutions:

we can stick an optional .oid in BrokerdFill and BrokerdStatus (or inside the .broker_details sub-dict and then expect backends which have this kind of issue to maintain a map of oid -> reqid themselves
we change kraken to not use the sync order submission API and instead use the websocket system where the submission and thus ems order ack should be returned immediately and msgs won't get out of order.

I need to think a bit on which i prefer, it might actually be ideal to handle both?

goodboy · 2022-05-10T14:58:23Z

further issue, if you try to cancel the stale dark-order from the client side you'll get this tb:

May 09 15:07:08 (emsd, 34778, _emsd_main)) [INFO] piker.clearing._ems _ems.py:787 Received order cmd:
{'action': 'cancel',
 'oid': '2169fa61-b143-40cf-984a-3eb6d80bf213',
 'symbol': 'xbteur.kraken'}
May 09 15:07:08 (emsd, 34778, _emsd_main)) [INFO] piker.clearing._ems _ems.py:826 Submitting cancel for live order {reqid}
May 09 15:07:08 (brokerd.kraken, 34735, piker.brokers.kraken.handle_order_requests)) [INFO] piker.brokers.kraken kraken.py:572 Received order request {'action': 'cancel', 'oid': '2169fa61-b143-40cf-984a-3eb6d80bf213', 'time_ns': 1652123228085191687, 'account': 'kraken.spot', 'reqid': 'OAH2LZ-IKTGB-5XUK6H'}
May 09 15:07:08 (emsd, 34778, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] tractor._portal _portal.py:512 Waiting on final context-task result for
task:238ea51e-b0d7-485c-9487-7c070243efc1
actor:('brokerd.kraken', '07b08efd-64b0-4f92-9e53-c167182d1640')
May 09 15:07:08 (brokerd.kraken, 34735, trio._highlevel_serve_listeners._run_handler)) [WARNING] tractor _actor.py:708 Ignoring msg from [no-longer/un]known context ('emsd', '635ad423-86fa-4f2c-b0a2-1c3023699ebf'):
{'stop': True, 'cid': '238ea51e-b0d7-485c-9487-7c070243efc1'}
May 09 15:07:08 (brokerd.kraken, 34735, tractor._debug.wait_for_parent_stdin_hijack)) [PDB] tractor._debug _debug.py:352 locked context
May 09 15:07:08 (brokerd.kraken, 34735, trades_dialogue)) [PDB] tractor._debug _debug.py:712
Attaching to pdb in crashed actor: ('brokerd.kraken', '07b08efd-64b0-4f92-9e53-c167182d1640')

Traceback (most recent call last):
  File "/home/goodboy/repos/piker/piker/brokers/kraken.py", line 658, in handle_order_requests
    result = resp['result']
KeyError: 'result'

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/home/goodboy/repos/tractor/tractor/_actor.py", line 193, in _invoke
    await chan.send({'return': await coro, 'cid': cid})
  File "/home/goodboy/repos/piker/piker/brokers/kraken.py", line 794, in trades_dialogue
    async with (
  File "/home/goodboy/repos/piker/310/lib/python3.10/site-packages/trio/_core/_run.py", line 815, in __aexit__
    raise combined_error_from_nursery
  File "/home/goodboy/repos/piker/piker/brokers/kraken.py", line 669, in handle_order_requests
    symbol=msg.symbol,
AttributeError: 'BrokerdCancel' object has no attribute 'symbol'

[3] > /home/goodboy/repos/piker/piker/brokers/kraken.py(669)handle_order_requests()
-> symbol=msg.symbol,
(Pdb++)

so it would appear there is also no logic branch to handle already executed orders which later get a cancel request (aka a race condition that can happen).

Relates to the bug discovered in #310, this should avoid out-of-order msgs which do not have a `.reqid` set to be error logged to console. Further, add `pformat()` to kraken logging of ems msging.

goodboy · 2022-05-11T19:47:45Z

Exact same issue with a clearable live order...

So basically the main issue is the event ordering that's relayed to the ems.
Basically it's this:

request for order from kraken api is done sync in .submit_limit()
order is filled and events generated by kraken api
events from kraken api are relayed to ems but before a BrokerdAck has been sent meaning the ems has never mapped the oid to the corresponding .reqid since the sync .submit_limit() hasn't returned yet
the ems gets fill and status msgs that aren't mapped to any existing oid and thus are ignored (well now, there's an error logging for it)
nothing in the UI is updated since those msgs were never forwarded as Status msg types to the UI side
no pp updates take place because the kraken backend code isn't recomputing the pp values from the just executed fill(s)

and now with error logging from 44ad55e

May 11 15:42:34 (emsd, 15943, _emsd_main)) [INFO] piker.clearing._ems _ems.py:799 Received order cmd:
{'account': 'kraken.spot',
 'action': 'buy',
 'brokers': ['kraken'],
 'exec_mode': 'live',
 'oid': '0c2b1db9-93cb-4678-abc1-5c536f2a66fa',
 'price': 27896.7,
 'size': 0.00448082,
 'symbol': 'xbteur.kraken'}
May 11 15:42:34 (emsd, 15943, _emsd_main)) [INFO] piker.clearing._ems _ems.py:918 Sending live order to kraken:
BrokerdOrder(action='buy', oid='0c2b1db9-93cb-4678-abc1-5c536f2a66fa', account='kraken.spot', time_ns=1652298154997921368, reqid=None, symbol='xbteur', price=27896.7, size=0.00448082)
May 11 15:42:34 (brokerd.kraken, 15903, piker.brokers.kraken.handle_order_requests)) [INFO] piker.brokers.kraken kraken.py:573 Received order request:
{'account': 'kraken.spot',
 'action': 'buy',
 'oid': '0c2b1db9-93cb-4678-abc1-5c536f2a66fa',
 'price': 27896.7,
 'reqid': None,
 'size': 0.00448082,
 'symbol': 'xbteur',
 'time_ns': 1652298154997921368}
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'account': 'kraken.spot',
 'broker_details': {'broker_time': '1652298155.308027', 'name': 'kraken'},
 'external': False,
 'filled': 0.00448082,
 'name': 'status',
 'reason': 'Order filled by kraken',
 'remaining': 0.0,
 'reqid': 'OS56CR-24F6I-JXKVQE',
 'status': 'filled',
 'time_ns': 1652298155369302646}
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [ERROR] piker.clearing._ems _ems.py:635 Unknown oid:{oid} for msg:
{'account': 'kraken.spot',
 'broker_details': {'broker_time': '1652298155.308027', 'name': 'kraken'},
 'external': False,
 'filled': 0.00448082,
 'name': 'status',
 'reason': 'Order filled by kraken',
 'remaining': 0.0,
 'reqid': 'OS56CR-24F6I-JXKVQE',
 'status': 'filled',
 'time_ns': 1652298155369302646}Unable to relay message to client side!?
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:732 Execution for None is complete!
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [ERROR] piker.clearing._ems _ems.py:773 Received `brokerd` msg for unknown client with oid: None
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'action': 'buy',
 'broker_details': {'name': 'kraken'},
 'broker_time': 1652298155.308027,
 'name': 'fill',
 'price': 27859.4,
 'reqid': 'OS56CR-24F6I-JXKVQE',
 'size': 0.00448082,
 'time_ns': 1652298155372072463}
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [ERROR] piker.clearing._ems _ems.py:635 Unknown oid:{oid} for msg:
{'action': 'buy',
 'broker_details': {'name': 'kraken'},
 'broker_time': 1652298155.308027,
 'name': 'fill',
 'price': 27859.4,
 'reqid': 'OS56CR-24F6I-JXKVQE',
 'size': 0.00448082,
 'time_ns': 1652298155372072463}Unable to relay message to client side!?
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:754
Fill for None cleared with:
'broker_filled'
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [ERROR] piker.clearing._ems _ems.py:773 Received `brokerd` msg for unknown client with oid: None
May 11 15:42:35 (emsd, 15943, piker.clearing._ems.open_brokerd_trades_dialogue)) [INFO] piker.clearing._ems _ems.py:564 Received broker trade event:
{'account': 'kraken.spot',
 'name': 'ack',
 'oid': '0c2b1db9-93cb-4678-abc1-5c536f2a66fa',
 'reqid': 'OS56CR-24F6I-JXKVQE'}

Relates to the bug discovered in #310, this should avoid out-of-order msgs which do not have a `.reqid` set to be error logged to console. Further, add `pformat()` to kraken logging of ems msging.

Moves to using the new `piker.pp` apis to both store real-time trade events in a ledger file as well emit position update msgs (which were not in this backend at all prior) when new orders clear (aka fill). In terms of outstanding issues, - solves the pp update part of the bugs reported in #310 - starts a msg case block in prep for #293 Details of rework: - move the `subscribe()` ws fixture to module level and `partial()` in the client token instead of passing it to the instance; in prep for removal of the `.token` attr from the `NoBsWs` wrapper. - drop `make_auth_sub()` since it was too thin and we can just do it all succinctly in `subscribe()` - filter trade update msgs to those not yet stored int the toml ledger - much better kraken api msg unpacking using new `match:` synax B) Resolves #311

Move to using the websocket API for all order control ops and dropping the sync rest api approach which resulted in a bunch of buggy races. Further this gets us must faster (batch) order cancellation for free and a simpler ems request handler loop. We now heavily leverage the new py3.10 `match:` syntax for all kraken-side API msg parsing and processing and handle both the `openOrders` and `ownTrades` subscription streams. We also block "order editing" (by immediate cancellation) for now since the EMS isn't entirely yet equipped to handle brokerd side `.reqid` changes (which is how kraken implements so called order "updates" or "edits") for a given order-request dialog and we may want to even consider just implementing "updates" ourselves via independent cancel and submit requests? Definitely something to ponder. Alternatively we can "masquerade" such updates behind the count-style `.oid` remapping we had to implement anyway (kraken's limitation) and maybe everything will just work? Further details in this patch: - create 2 tables for tracking the EMS's `.oid` (uui4) value to `int`s that kraken expects (for `reqid`s): `ids` and `reqmsgs` which enable local lookup of ems uids to piker-backend-client-side request ids and received order messages. - add `openOrders` sub support which more or less directly relays to equivalent `BrokerdStatus` updates and calc the `.filled` and `.remaining` values based on cleared vlm updates. - add handler blocks for `[add/edit/cancel]OrderStatus` events including error msg cases. - don't do any order request response processing in `handle_order_requests()` since responses are always received via one (or both?) of the new ws subs: `ownTrades` and `openOrders` and thus such msgs are now handled in the response relay loop. Relates to #290 Resolves #310, #296

goodboy added bug guille broke it prolly clearing auction and mm tech: EMS, OMS, algo-trading labels May 9, 2022

goodboy self-assigned this May 9, 2022

goodboy changed the title ~~kraken dark orders don't send correct fill messages, pp doesn't update... etc.~~ kraken **live and dark** orders don't send correct fill messages, pp doesn't update... etc. May 11, 2022

goodboy mentioned this issue Jul 3, 2022

Kraken ledger pps #346

Merged

goodboy mentioned this issue Jul 5, 2022

Kraken ws orders #349

Merged

12 tasks

goodboy closed this as completed in 00378c3 Aug 6, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

`kraken` live and dark orders don't send correct fill messages, pp doesn't update... etc. #310

`kraken` live and dark orders don't send correct fill messages, pp doesn't update... etc. #310

goodboy commented May 9, 2022 •

edited

Loading

goodboy commented May 9, 2022

goodboy commented May 9, 2022

goodboy commented May 9, 2022 •

edited

Loading

goodboy commented May 10, 2022

goodboy commented May 11, 2022 •

edited

Loading

kraken **live and dark** orders don't send correct fill messages, pp doesn't update... etc. #310

kraken **live and dark** orders don't send correct fill messages, pp doesn't update... etc. #310

Comments

goodboy commented May 9, 2022 • edited Loading

pikerd logs:

goodboy commented May 9, 2022

goodboy commented May 9, 2022

goodboy commented May 9, 2022 • edited Loading

goodboy commented May 10, 2022

goodboy commented May 11, 2022 • edited Loading

`kraken` live and dark orders don't send correct fill messages, pp doesn't update... etc. #310

`kraken` live and dark orders don't send correct fill messages, pp doesn't update... etc. #310

goodboy commented May 9, 2022 •

edited

Loading

`pikerd` logs:

goodboy commented May 9, 2022 •

edited

Loading

goodboy commented May 11, 2022 •

edited

Loading