search

robcarver17 / pysystemtrade

Systematic Trading in python
GNU General Public License v3.0
2.6k stars 822 forks source link

1.8+ million times: Can't modify limit price for order right now as status isn't good #949

Closed 73ze closed 1 year ago

73ze commented 1 year ago

Hi Everyone!

Monday morning (New York time), my run_stack_handler.txt had 1.8+ million lines with this message (with timestamps over a ~2h timeframe): Can't modify limit price for order right now as status isn't good

The stack handler process did not seem to make any progress after this, including logging, even though the process was still up.

I killed the stack handler process, cleared the entire order stack, regenerated strategy orders, restarted the stack handler, and the process seemed to run normally afterwards.

Has anyone else experienced this? If you are interested, below are some details to help understand the conditions under which this happened:

$ cat -n run_stack_handler.txt
…
    302 2023-01-19 03:10:05 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 280, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 308, 'broker_order_id': 372}  Imbalance ratio for ticker analysisTick(order='B', side_price=        -80.0, mid_price=-81.5, offside_price=-83.0, spread=3.0, side_qty=4.0, offside_qty=190.0, imbalance_ratio=47.5) 47.500000 exceeds t        hreshold 5.000000
…
< Repeat 500+ times>
…
    822 2023-01-19 03:10:25 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 280, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 308, 'broker_order_id': 372}  On ticker analysisTick(order='B', side_price=-80.5, mid_price=        -81.75, offside_price=-83.0, spread=2.5, side_qty=2.0, offside_qty=190.0, imbalance_ratio=95.0) we require size of 3.000000 (our tr        ade 1.000000 * adjustment 3.000000) for a limit order but only 2.000000 available
    823 2023-01-19 03:10:25 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 280, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 308, 'broker_order_id': 372}  Switch to aggressive because Imbalance ratio of 95.000000 exceeds threshold
    824 2023-01-19 03:10:25 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 280, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 308, 'broker_order_id': 372}  Can't modify limit price for order right now as status isn't good
…
< Repeat 1.8+ million times >
…
1830477 2023-01-23 05:20:23 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 294, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 315, 'broker_order_id': 429}  Can't modify limit price for order right now as status isn't g        ood
1830478 2023-01-23 05:20:34 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 294, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 315, 'broker_order_id': 429}  Aggressive execution with limit price desired:-88.000000 actual:-88.000000 last tick oneTick(bid_price=-88.5, ask_price=-88.0, bid_size=25.0, ask_size=7.0)
1830479 2023-01-23 05:21:04 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 294, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 315, 'broker_order_id': 429}  Run out of time: cancelling
…
1830531 2023-01-23 05:21:23 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 294, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrumen        t_code': 'NIFTY', 'contract_order_id': 315, 'instrument_order_id': 320}  Conditions are wrong so doing market trade instead of limit trade
…
robcarver17 commented 1 year ago

No haven't seen this before (I think I would have noticed).

So the algo is trying to change the limit price, which can only be done if the order status is showing as submitted, and for some reason it isn't (line #417 of ib_orders.py).

It seems possible that the logging frenzy caused the thread to subsequently freeze.

It's impossible to tell what is happening under the hood, but a starting point is to add the order status to the error message.

There is a seperate issue about log spamming here. I'll add some simple logic that prevents the same log message being written more than once a minute.

Neithier of these will solve the problem, but if it happens again at least your log files won't die and it will be possible to diagnose what is going on with the status.

73ze commented 1 year ago

Adding more order details to the logs and limiting the frequency of this message sounds great to me and hopefully we can get more insight next time.

Thank you!

oldlore commented 1 year ago

I had the same error last week when I tried to buy EU oil futures but I wasn't allowed to do so due to regulatory restrictions. The log got to 300+ MBs in size. I think the very first error line mentioned the trading restriction and then after that it was just thousands of the same error. There were also several canceled IB trades before it stopped submitting them.

robcarver17 commented 1 year ago

Made the changes above, but obviously reopen if it reoccurs and hopefully it will capture more information.

73ze commented 1 year ago

THANK YOU!

73ze commented 1 year ago

Hello Robert and Everyone,

FYI, apparently getting the same (or similar?) issue today while trying to "Force" roll IRON. The more detailed logs Robert kindly added last week appear. This has generated ~1 million duplicates of this line over the course of ~4h. Likely the reason also why the stack handler process is not making progress (for now, I'll restart it after clearing the entire stack as last week):

Can't modify limit price for order, error Order can't be modified as status is PreSubmitted, not in ['Submitted']

Below is an except of logs showing lifecycle of this IRON order.

2023-01-31 00:15:10 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': '', 'instrument_order_id': ''}  'Best' order so allocating to original_best
2023-01-31 00:15:10 {'type': 'stack_handler', 'component': 'mongoInstrumentOrderStackData', 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'instrument_order_id': ''}  New order (Order ID:no order ID) Type Zero-roll-order for _ROLL_PSEUDO_STRATEGY IRON, qty [0], fill [0]@ price, None Parent:no parent Children:no_children LOCKED putting on Instrument order stack: mongoData connection for INSTRUMENT_ORDER_STACK/DU5885087, localhost with 2 active orders
2023-01-31 00:15:10 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'instrument_order_id': ''}  Added parent order with ID 346 (Order ID:no order ID) Type Zero-roll-order for _ROLL_PSEUDO_STRATEGY IRON, qty [0], fill [0]@ price, None Parent:no parent Children:no_children LOCKED to stack
2023-01-31 00:15:10 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'instrument_order_id': 346, 'contract_order_id': ''}  Put child order (Order ID:no order ID) Type best for _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400, qty [-1, 1], fill [0, 0]@ price, None Parent:346 Children:no_children LOCKED on stack with ID 341 from parent order (Order ID:no order ID) Type Zero-roll-order for _ROLL_PSEUDO_STRATEGY IRON, qty [0], fill [0]@ price, None Parent:no parent Children:no_children LOCKED
2023-01-31 01:25:02 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'instrument_order_id': 346}  Sending order (Order ID:341) Type best for _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400, qty [-1, 1], fill [0, 0]@ price, None Parent:346 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-01-31 01:25:04 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'instrument_order_id': 346}  Created a broker order (Order ID:no order ID) Type limit for _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400, qty [-1, 1], fill [0, 0]@ price, None Parent:341 Children:no_children (not yet submitted or written to local DB)
2023-01-31 01:25:04 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'component': 'ibExecutionStackData', 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': ''}  Going to submit order (Order ID:no order ID) Type limit for _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400, qty [-1, 1], fill [0, 0]@ price, None Parent:341 Children:no_children to IB
2023-01-31 01:25:04 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'component': 'ibExecutionStackData', 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': ''}  Order submitted to IB
2023-01-31 01:25:04 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'instrument_order_id': 346, 'broker_order_id': ''}  Submitted order to IB (Order ID:no order ID) Type limit for _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400, qty [-1, 1], fill [0, 0]@ price, None Parent:341 Children:no_children
2023-01-31 01:25:04 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': 514}  Managing trade (Order ID:514) Type limit for _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400, qty [-1, 1], fill [0, 0]@ price, None Parent:341 Children:no_children with algo 'original-best'
2023-01-31 01:25:34 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': 514}  Passive execution with limit price desired:0.800000 actual:0.800000 last tick oneTick(bid_price=0.7, ask_price=0.8, bid_size=242.0, ask_size=325.0)
2023-01-31 01:26:36 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': 514}  Switch to aggressive because Adverse price movement
2023-01-31 01:26:36 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': 514}  Can't modify limit price for order, error Order can't be modified as status is PreSubmitted, not in ['Submitted']
2023-01-31 01:26:36 {'type': 'stack_handler', 'broker': 'IB', 'clientid': 336, 'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'IRON', 'contract_order_id': 341, 'broker_order_id': 514}  Can't modify limit price for order, error Order can't be modified as status is PreSubmitted, not in ['Submitted']
<repeat ~800.000+ times until 5AM>

It starts with the algo algoOriginalBest but then we Switch to aggressive because Adverse price movement and the system can't modify the order.

Looking at the logs in detail, we see that the 'contract_order_id': 341 gets assigned 'broker_order_id': 514, strongly suggesting it was indeed submitted. The log line Managing trade (Order ID:514) seems to confirm that too.

But when I inspect the broker orders in the database now (using interactive diagnostics option 5/55), it does not show 'broker_order_id': 514 (it only shows other similar unfilled orders created yesterday for IRON with ids up to 513):

: Enter date and time in format %Y-%m-%d eg '2023-01-31' OR '%Y-%m-%d %H:%M:%S' eg '2023-01-31 15:31:36'
 OR [Enter an integer to go back N calendar days]OR [Enter a string for period, eg 'YTD', '3M', '2B']1
              fill_datetime                                           key    trade    fill price
512 2023-01-30 19:45:04.197  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
513 2023-01-30 19:45:04.248  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
486 2023-01-30 19:45:02.871  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
487 2023-01-30 19:45:02.922  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
488 2023-01-30 19:45:02.973  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
489 2023-01-30 19:45:03.024  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
490 2023-01-30 19:45:03.075  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
491 2023-01-30 19:45:03.126  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
492 2023-01-30 19:45:03.178  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
493 2023-01-30 19:45:03.230  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
494 2023-01-30 19:45:03.280  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
495 2023-01-30 19:45:03.331  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
496 2023-01-30 19:45:03.382  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
497 2023-01-30 19:45:03.433  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
498 2023-01-30 19:45:03.483  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
499 2023-01-30 19:45:03.534  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
500 2023-01-30 19:45:03.585  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
501 2023-01-30 19:45:03.636  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
502 2023-01-30 19:45:03.687  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
503 2023-01-30 19:45:03.738  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
503 2023-01-30 19:45:03.738  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
504 2023-01-30 19:45:03.789  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
505 2023-01-30 19:45:03.840  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
506 2023-01-30 19:45:03.892  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
507 2023-01-30 19:45:03.942  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
508 2023-01-30 19:45:03.992  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
509 2023-01-30 19:45:04.044  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
510 2023-01-30 19:45:04.095  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
511 2023-01-30 19:45:04.146  _ROLL_PSEUDO_STRATEGY/IRON/20230300_20230400  [-1, 1]  [0, 0]  None
50: Optimal position history (instruments for strategy)
51: Actual position history (instruments for strategy)
52: Actual position history (contracts for instrument)
53: List of historic instrument level orders (for strategy)
54: List of historic contract level orders (for strategy and instrument)
55: List of historic broker level orders (for strategy and instrument)
56: View individual order

Would you not expect this broker order 514 to be in the database? Would this be the reason the order is not seen as Submitted by the time we try to modify it?

Reporting this before I know more in case someone else has the same. Also attached the full log ( presubmitted_state.run_stack_handler.2023-01-31.txt.gz ) in case that is useful.

tgibson11 commented 1 year ago

From https://interactivebrokers.github.io/tws-api/order_submission.html:

PreSubmitted - indicates that a simulated order type has been accepted by the IB system and that this order has yet to be elected. The order is held in the IB system until the election criteria are met. At that time the order is transmitted to the order destination as specified.

Seems like whatever exchange IRON trades on doesn't allow limit orders, and IB is simulating a limit order for you.

Can't modify limit price for order, error Order can't be modified as status is PreSubmitted, not in ['Submitted']

Seems like pysystemtrade should probably handle PreSubmitted the same as Submitted

robcarver17 commented 1 year ago

The 'submitted' log line just means that we've sent the order through to the IB API. But that doesn't mean IB have actually submitted it to the market, and that is what is happened here. I would imagine that you have some kind of trading restriction, that is holding the order in pre submitted stage. Or as @tgibson11 says it is due to a limit order being simulated.

(I'm fairly confident that I have traded Iron myself with limit orders, so I am not sure that theory is correct)

Try submitting the order through ib_insync directly just to make sure it isn't a pysystemtrade problem, and keep a close eye on the IB gateway log. Then if it is not obvious what is going wrong, try submitting the order manually through IB web trader. You may need to contact IB support or put someting on the ib_insync message board.

Why isn't the broker order in the database? That's because orders are only added to the historic order database when they are filled or cancelled; if things just hang in mid air then they won't be. Normally at the end of the day any orders that remain unfilled are cleared off the stack, and then passed to historic order database, but if the stack handler crashes this won't happen. If you had run interactive_order_stack with the option to do 'end of day' stuff, that would - I think - have added the unfilled order(s) to the historic DB.

And finally, what is really annoying is that my fix to stop duplicate logging doesn't seem to have worked...

73ze commented 1 year ago

Thank you very much for the insight and very helpful suggestions @tgibson11 and @robcarver17.

robcarver17 commented 1 year ago

From https://interactivebrokers.github.io/tws-api/order_submission.html:

PreSubmitted - indicates that a simulated order type has been accepted by the IB system and that this order has yet to be elected. The order is held in the IB system until the election criteria are met. At that time the order is transmitted to the order destination as specified.

Seems like whatever exchange IRON trades on doesn't allow limit orders, and IB is simulating a limit order for you.

Can't modify limit price for order, error Order can't be modified as status is PreSubmitted, not in ['Submitted']

Seems like pysystemtrade should probably handle PreSubmitted the same as Submitted

I'm not sure we should do that as it will cause problems in the vast majority of cases where it is a trading restriction or closed market (that we've missed for some reason) that's causing the order to stick in pre-submitted.

tgibson11 commented 1 year ago

I'm not sure we should do that as it will cause problems in the vast majority of cases where it is a trading restriction or closed market (that we've missed for some reason) that's causing the order to stick in pre-submitted.

Yeah, I was taking IB at their word re the meaning of PreSubmitted. But if it can mean other things too, then maybe that wouldn't be a great idea.

robcarver17 commented 1 year ago

If the problem is, as you say, that Iron can't be traded with limit orders then this is a better solution #969