Question on stack_handler behavior with ib_insync indicating order is cancelled but remains active on IB

[davewsail]

I'm currently at the point of paper trading in production. I'm running into an issue where run_stack_handler creates too many orders and I get more fills than the system expects. From the logs I see that stack_handler submits an order to IB of the correct size but ib_insync both an error and a warning. This is later followed by a warning from stack_handler "Order has been cancelled: not by algo." a few seconds later stack_handler submits an order again (I assume thinking the original order has been cancelled). The problem is that the order actually hasn't been cancelled and is still active on IB. This continues in a loop with multiple orders being submitted to IB and stack_handler thinking they are cancelled because ib_insync is telling it that. ib_insync is returning "Error 10349" which evidently is a market data subscription missing (it is because I was hoping to paper trade without paying the fees). I know I can probably fix this by paying for the subscriptions. But it seems to me that if an order remains active on IB, ib_insync should not indicate cancellation. What ultimately happens is the loop stops when an order is filled. However extra orders are still active on IB which then fill and causes stack_handler to crash and then my orders stacks are a mess.

The above is what I think is happening. I've attached part of the logs where this is happening. My questions are as follows:

1. is there a bug either in stack_handler or ib_insync?
2. post crash, I try to clean-up the order stacks using interactive_order_stack, I "fixed" this by clearing the IB order stack, manually filling the order up the stack, and closing the extra positions that were filled manually. This doesn't seem to fix the integrity of what is in MongoDB however. Is there a better way?

2025-11-13 09:00:03 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'CLP', 'contract_order_id': 25, 'instrument_order_id': 25} Cut down order from size [0] to [1] because of liquidity
2025-11-13 09:00:06 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Sending order (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2025-11-13 09:00:07 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Created a broker order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children (not yet submitted or written to local DB)
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Going to submit order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children to IB
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Order submitted to IB
2025-11-13 09:00:07 ERROR ib_insync.wrapper Error 10349, reqId 31553: Order TIF was set to DAY based on order preset.
2025-11-13 09:00:07 WARNING ib_insync.wrapper Canceled order: Trade(contract=Contract(secType='FUT', conId=702886860, symbol='6M', lastTradeDateOrContractMonth='20251215', multiplier='500000', exchange='CME', currency='USD', localSymbol='6MZ5', tradingClass='6M'), order=LimitOrder(orderId=31553, clientId=101, action='BUY', totalQuantity=1, lmtPrice=0.054580000000000004, account='DU4025781'), orderStatus=OrderStatus(orderId=31553, status='Cancelled', filled=0.0, remaining=0.0, avgFillPrice=0.0, permId=0, parentId=0, lastFillPrice=0.0, clientId=0, whyHeld='', mktCapPrice=0.0), fills=[], log=[TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 7, 184423, tzinfo=datetime.timezone.utc), status='PendingSubmit', message='', errorCode=0), TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 7, 190468, tzinfo=datetime.timezone.utc), status='Cancelled', message='Error 10349, reqId 31553: Order TIF was set to DAY based on order preset.', errorCode=10349)], advancedError='')
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibContractPositionData'} Reqid 31553: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibFuturesInstrumentData'} Reqid 31553: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibFuturesContractData'} Reqid 31553: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibFuturesContractPriceData'} Reqid 31553: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibStaticData'} Reqid 31553: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:07 DEBUG stack_handler {'component': 'ibExecutionStackData'} Reqid 31553: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:07 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Submitted order to IB (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children
2025-11-13 09:00:07 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 43} Managing trade (Order ID:43) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children with algo 'original-best'
2025-11-13 09:00:07 WARNING stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 43} Order has been cancelled: not by algo
2025-11-13 09:00:07 DEBUG stack_handler {'type': 'run_stack_handler'} Released contract order 27 from algo control
2025-11-13 09:00:12 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'CLP', 'contract_order_id': 25, 'instrument_order_id': 25} Cut down order from size [0] to [1] because of liquidity
2025-11-13 09:00:15 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Sending order (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:[43] to algo sysexecution.algos.algo_original_best.algoOriginalBest
2025-11-13 09:00:15 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Created a broker order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children (not yet submitted or written to local DB)
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Going to submit order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children to IB
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Order submitted to IB
2025-11-13 09:00:15 ERROR ib_insync.wrapper Error 10349, reqId 31568: Order TIF was set to DAY based on order preset.
2025-11-13 09:00:15 WARNING ib_insync.wrapper Canceled order: Trade(contract=Contract(secType='FUT', conId=702886860, symbol='6M', lastTradeDateOrContractMonth='20251215', multiplier='500000', exchange='CME', currency='USD', localSymbol='6MZ5', tradingClass='6M'), order=LimitOrder(orderId=31568, clientId=101, action='BUY', totalQuantity=1, lmtPrice=0.054580000000000004, account='DU4025781'), orderStatus=OrderStatus(orderId=31568, status='Cancelled', filled=0.0, remaining=0.0, avgFillPrice=0.0, permId=0, parentId=0, lastFillPrice=0.0, clientId=0, whyHeld='', mktCapPrice=0.0), fills=[], log=[TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 15, 805758, tzinfo=datetime.timezone.utc), status='PendingSubmit', message='', errorCode=0), TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 15, 808759, tzinfo=datetime.timezone.utc), status='Cancelled', message='Error 10349, reqId 31568: Order TIF was set to DAY based on order preset.', errorCode=10349)], advancedError='')
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibContractPositionData'} Reqid 31568: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibFuturesInstrumentData'} Reqid 31568: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibFuturesContractData'} Reqid 31568: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibFuturesContractPriceData'} Reqid 31568: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibStaticData'} Reqid 31568: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:15 DEBUG stack_handler {'component': 'ibExecutionStackData'} Reqid 31568: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:15 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Submitted order to IB (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children
2025-11-13 09:00:15 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 44} Managing trade (Order ID:44) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children with algo 'original-best'
2025-11-13 09:00:15 WARNING stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 44} Order has been cancelled: not by algo
2025-11-13 09:00:15 DEBUG stack_handler {'type': 'run_stack_handler'} Released contract order 27 from algo control
2025-11-13 09:00:21 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'CLP', 'contract_order_id': 25, 'instrument_order_id': 25} Cut down order from size [0] to [1] because of liquidity
2025-11-13 09:00:24 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Sending order (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:[43, 44] to algo sysexecution.algos.algo_original_best.algoOriginalBest
2025-11-13 09:00:24 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Created a broker order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children (not yet submitted or written to local DB)
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Going to submit order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children to IB
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Order submitted to IB
2025-11-13 09:00:24 ERROR ib_insync.wrapper Error 10349, reqId 31583: Order TIF was set to DAY based on order preset.
2025-11-13 09:00:24 WARNING ib_insync.wrapper Canceled order: Trade(contract=Contract(secType='FUT', conId=702886860, symbol='6M', lastTradeDateOrContractMonth='20251215', multiplier='500000', exchange='CME', currency='USD', localSymbol='6MZ5', tradingClass='6M'), order=LimitOrder(orderId=31583, clientId=101, action='BUY', totalQuantity=1, lmtPrice=0.054580000000000004, account='DU4025781'), orderStatus=OrderStatus(orderId=31583, status='Cancelled', filled=0.0, remaining=0.0, avgFillPrice=0.0, permId=0, parentId=0, lastFillPrice=0.0, clientId=0, whyHeld='', mktCapPrice=0.0), fills=[], log=[TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 24, 802902, tzinfo=datetime.timezone.utc), status='PendingSubmit', message='', errorCode=0), TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 24, 806950, tzinfo=datetime.timezone.utc), status='Cancelled', message='Error 10349, reqId 31583: Order TIF was set to DAY based on order preset.', errorCode=10349)], advancedError='')
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibContractPositionData'} Reqid 31583: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibFuturesInstrumentData'} Reqid 31583: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibFuturesContractData'} Reqid 31583: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibFuturesContractPriceData'} Reqid 31583: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibStaticData'} Reqid 31583: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:24 DEBUG stack_handler {'component': 'ibExecutionStackData'} Reqid 31583: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:24 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Submitted order to IB (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children
2025-11-13 09:00:24 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 45} Managing trade (Order ID:45) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children with algo 'original-best'
2025-11-13 09:00:24 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 45} Switch to aggressive because Adverse price movement
2025-11-13 09:00:24 WARNING stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 45} Order has been cancelled: not by algo
2025-11-13 09:00:24 DEBUG stack_handler {'type': 'run_stack_handler'} Released contract order 27 from algo control
2025-11-13 09:00:31 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'CLP', 'contract_order_id': 25, 'instrument_order_id': 25} Cut down order from size [0] to [1] because of liquidity
2025-11-13 09:00:34 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Sending order (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:[43, 44, 45] to algo sysexecution.algos.algo_original_best.algoOriginalBest
2025-11-13 09:00:34 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Created a broker order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children (not yet submitted or written to local DB)
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Going to submit order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children to IB
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Order submitted to IB
2025-11-13 09:00:34 ERROR ib_insync.wrapper Error 10349, reqId 31598: Order TIF was set to DAY based on order preset.
2025-11-13 09:00:34 WARNING ib_insync.wrapper Canceled order: Trade(contract=Contract(secType='FUT', conId=702886860, symbol='6M', lastTradeDateOrContractMonth='20251215', multiplier='500000', exchange='CME', currency='USD', localSymbol='6MZ5', tradingClass='6M'), order=LimitOrder(orderId=31598, clientId=101, action='BUY', totalQuantity=1, lmtPrice=0.05459000000000001, account='DU4025781'), orderStatus=OrderStatus(orderId=31598, status='Cancelled', filled=0.0, remaining=0.0, avgFillPrice=0.0, permId=0, parentId=0, lastFillPrice=0.0, clientId=0, whyHeld='', mktCapPrice=0.0), fills=[], log=[TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 34, 225829, tzinfo=datetime.timezone.utc), status='PendingSubmit', message='', errorCode=0), TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 34, 228830, tzinfo=datetime.timezone.utc), status='Cancelled', message='Error 10349, reqId 31598: Order TIF was set to DAY based on order preset.', errorCode=10349)], advancedError='')
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibContractPositionData'} Reqid 31598: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibFuturesInstrumentData'} Reqid 31598: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibFuturesContractData'} Reqid 31598: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibFuturesContractPriceData'} Reqid 31598: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibStaticData'} Reqid 31598: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:34 DEBUG stack_handler {'component': 'ibExecutionStackData'} Reqid 31598: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:34 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Submitted order to IB (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children
2025-11-13 09:00:34 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 46} Managing trade (Order ID:46) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children with algo 'original-best'
2025-11-13 09:00:34 WARNING stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 46} Order has been cancelled: not by algo
2025-11-13 09:00:34 DEBUG stack_handler {'type': 'run_stack_handler'} Released contract order 27 from algo control
2025-11-13 09:00:40 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'CLP', 'contract_order_id': 25, 'instrument_order_id': 25} Cut down order from size [0] to [1] because of liquidity
2025-11-13 09:00:43 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Sending order (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:[43, 44, 45, 46] to algo sysexecution.algos.algo_original_best.algoOriginalBest
2025-11-13 09:00:43 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Created a broker order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children (not yet submitted or written to local DB)
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Going to submit order (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children to IB
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibExecutionStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Order submitted to IB
2025-11-13 09:00:43 ERROR ib_insync.wrapper Error 10349, reqId 31613: Order TIF was set to DAY based on order preset.
2025-11-13 09:00:43 WARNING ib_insync.wrapper Canceled order: Trade(contract=Contract(secType='FUT', conId=702886860, symbol='6M', lastTradeDateOrContractMonth='20251215', multiplier='500000', exchange='CME', currency='USD', localSymbol='6MZ5', tradingClass='6M'), order=LimitOrder(orderId=31613, clientId=101, action='BUY', totalQuantity=1, lmtPrice=0.05459000000000001, account='DU4025781'), orderStatus=OrderStatus(orderId=31613, status='Cancelled', filled=0.0, remaining=0.0, avgFillPrice=0.0, permId=0, parentId=0, lastFillPrice=0.0, clientId=0, whyHeld='', mktCapPrice=0.0), fills=[], log=[TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 43, 870927, tzinfo=datetime.timezone.utc), status='PendingSubmit', message='', errorCode=0), TradeLogEntry(time=datetime.datetime(2025, 11, 13, 15, 0, 43, 874918, tzinfo=datetime.timezone.utc), status='Cancelled', message='Error 10349, reqId 31613: Order TIF was set to DAY based on order preset.', errorCode=10349)], advancedError='')
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibContractPositionData'} Reqid 31613: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibFuturesInstrumentData'} Reqid 31613: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibFuturesContractData'} Reqid 31613: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibFuturesContractPriceData'} Reqid 31613: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibStaticData'} Reqid 31613: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:43 DEBUG stack_handler {'component': 'ibExecutionStackData'} Reqid 31613: 10349 Order TIF was set to DAY based on order preset. for None
2025-11-13 09:00:43 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': ''} Submitted order to IB (Order ID:no order ID) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children
2025-11-13 09:00:43 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 47} Managing trade (Order ID:47) Type limit for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:no_children with algo 'original-best'
2025-11-13 09:00:43 WARNING stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'broker_order_id': 47} Order has been cancelled: not by algo
2025-11-13 09:00:43 DEBUG stack_handler {'type': 'run_stack_handler'} Released contract order 27 from algo control
2025-11-13 09:00:46 DEBUG stack_handler {'component': 'mongoContractOrderStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Changed fill qty from [0] to [1] for order (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:[43, 44, 45, 46, 47]
2025-11-13 09:00:46 DEBUG stack_handler {'type': 'run_stack_handler', 'instrument_code': 'MXP', 'contract_date': '20251200'} Updated position of MXP/20251200 from 2 to 3; new position in db is 3
2025-11-13 09:00:46 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Updated position of MXP/20251200 because of trade (Order ID:27) Type best for production/MXP/20251200, qty [1], fill [0]@ price, None Parent:27 Children:[43, 44, 45, 46, 47] ID:27 with fills 1
2025-11-13 09:00:46 DEBUG stack_handler {'type': 'run_stack_handler', 'strategy_name': 'production', 'instrument_code': 'MXP', 'instrument_order_id': 27} Updated position of production MXP from 2 to 3 because of trade (Order ID:27) Type best for production MXP, qty [1], fill [0]@ price, None Parent:no parent Children:[27] 27 fill [1]
2025-11-13 09:00:46 DEBUG stack_handler {'component': 'mongoInstrumentOrderStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'instrument_order_id': 27} Changed fill qty from [0] to [1] for order (Order ID:27) Type best for production MXP, qty [1], fill [0]@ price, None Parent:no parent Children:[27]
2025-11-13 09:00:47 WARNING stack_handler {'component': 'mongoContractOrderStackData', 'strategy_name': 'production', 'instrument_code': 'MXP', 'contract_order_id': 27, 'instrument_order_id': 27} Can't fill order with fill [2] more than trade quantity [1] 
Traceback (most recent call last):
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\orders\base_orders.py", line 205, in fill_order
    assert self.trade.fill_less_than_or_equal_to_desired_trade(fill_qty)
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
AssertionError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\order_stacks\order_stack.py", line 326, in change_fill_quantity_for_order
    new_order.fill_order(
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\orders\base_orders.py", line 207, in fill_order
    raise overFilledOrder(
sysexecution.orders.base_orders.overFilledOrder: Can't fill order with fill [2] more than trade quantity [1] 

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "C:\Users\davew\SynologyDrive\Trading\python\pysystemtrade\sysproduction\linux\scripts/run.py", line 66, in <module>
    func(*args, **kwargs)
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysproduction\run_stack_handler.py", line 11, in run_stack_handler
    price_process.run_process()
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\syscontrol\run_process.py", line 105, in run_process
    self._main_loop_over_methods()
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\syscontrol\run_process.py", line 131, in _main_loop_over_methods
    timer_class.check_and_run(**kwargs)
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\syscontrol\timer_functions.py", line 122, in check_and_run
    self.run_function(**kwargs)
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\syscontrol\timer_functions.py", line 294, in run_function
    self._function(**kwargs)
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\stack_handler\fills.py", line 33, in process_fills_stack
    self.pass_fills_from_broker_to_broker_stack()
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\stack_handler\fills.py", line 40, in pass_fills_from_broker_to_broker_stack
    self.apply_broker_fill_from_broker_to_broker_database(broker_order_id)
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\stack_handler\fills.py", line 68, in apply_broker_fill_from_broker_to_broker_database
    self.apply_broker_order_fills_to_database(
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\stack_handler\fills.py", line 104, in apply_broker_order_fills_to_database
    self.apply_broker_fills_to_contract_order(contract_order_id)
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\stack_handler\fills.py", line 136, in apply_broker_fills_to_contract_order
    self.apply_fills_to_contract_order(
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\stack_handler\fills.py", line 167, in apply_fills_to_contract_order
    self.contract_stack.change_fill_quantity_for_order(
  File "C:\ProgramData\anaconda3\envs\quant_stack_7_25\Lib\site-packages\sysexecution\order_stacks\order_stack.py", line 331, in change_fill_quantity_for_order
    raise overFilledOrder(e)
sysexecution.orders.base_orders.overFilledOrder: Can't fill order with fill [2] more than trade quantity [1] 

[tgibson11]

• is there a bug either in stack_handler or ib_insync?

See ib-api-reloaded/ib_async#190

Note: I am using ib_insync, but maybe we should consider switching if it looks like the ib_async fork is being actively maintained.

I have not seen this issue though. Why not? Is it only related to paper trading?

This probably won't solve your problem, but one thing I always change in the IB API settings (TWS or Gateway): Configure > Settings > API > Precautions > check "Bypass Order Precautions for API Orders". I vaguely recall that it was causing problems for me in the past, but I can't remember the details.

[davewsail]

I do have "Bypass Order Precautions for API Orders" checked already so not that. It may be paper trading or it may be just the market data subscriptions I'm missing. If it is only that, then fine. But my larger concern is if there is another reason an order is not canceled closed-loop, and it happens on a real account. I'm thinking to just change my best_algo option to sysexecution.algos.algo_market.algoMarket to see if that changes behavior. Limit orders are problematic without realtime data clearly.

[davewsail]

So the discussion thread an ib_async that you posted answers the question. IB is reporting an error (vs. a warning) but the order is still active. The solution was to add the error to a list of exceptions that get treated as warnings.

[tgibson11]

2. post crash, I try to clean-up the order stacks using interactive_order_stack, I "fixed" this by clearing the IB order stack, manually filling the order up the stack, and closing the extra positions that were filled manually. This doesn't seem to fix the integrity of what is in MongoDB however. Is there a better way?

Interactive order stack is the right tool, but the exact steps will vary depending on your exact problem.

1. Start by viewing the order stack and positions. (If you need more help, provide the output from this.)
2. Work your way up the stacks and fix the breaks: broker --> contract --> instrument
   a. If there is a break between broker and contract positions, correct it with a balance trade
   b. If there is a break between contract and instrument positions, correct it with an instrument-only balance trade
3. View positions again and verify there are no more breaks.
4. Delete any unwanted orders or clear the order stacks (all of the stacks...I can think of no case where you would want to clear only a single stack)
5. At this point your positions are consistent internally and with IB, but maybe not what they "should" be. You can re-run the strategy order generator or manually enter orders if necessary.

[davewsail]

Thank you Todd. I really appreciate your help and thoughtfulness.