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

goodboy commented 2 years ago

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'}

goodboy commented 2 years ago

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

goodboy commented 2 years ago

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 commented 2 years ago

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 commented 2 years ago

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).

goodboy commented 2 years ago

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 https://github.com/pikers/piker/pull/302/commits/44ad55e0c70adeaf068f4781e44750479913c5a6

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'}

pikers / piker