I have been running ib_insync/ib_async in production for over 4 years with few issues. Lately I have seen more and more cases where I receive missing or incorrect positionEvent responses. I checked the ibgateway API logs, and the API looks correct.
Does anyone know why the positionEvent was missed, but incorrect ones continued to be emitted?
Any pointers on how to fix or debug this? What triggers a PositionEvent?
I am considering using the Portfolio position update + recent fills to sanity check the position and cancel orders if there is a mismatch. Is anyone else doing something similar? I'm worried about timing / race conditions of doing this
Here is one recent example, times are Pacific
20240606.081023 Bought 500 WESTW $2.06, correctly received positionEvent, position=500
? 20240606.081023.294 I handle_position_update WESTW, equity=WESTW: Position(account='UXXX', contract=Warrant(conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', exchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), position=500.0, avgCost=2.06)
? 20240606.081023.294 I handle_position_update WESTW new qty=500, was 0
081939 Filled 359 of order to sell 500 WESTW $2.30
? 20240606.081939.129 I handle_position_update WESTW, equity=WESTW: Position(account='UXXX', contract=Warrant(conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', exchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), position=141.0, avgCost=2.06010145)
? 20240606.081939.129 I handle_position_update WESTW new qty=141, was 500
? 20240606.081939.274 I handle_exec_details, trade = WESTW WESTW permId=461612295 orderId=1040716 SELL 500.0 2.3 ref=P-WrtBS Submitted filled=359.0, log(msg=Fill [email protected], status=Submitted 08:19:39)
081939.275 filled remaining 141, position should be 0 now. Fill and commission responses are correct, but a positionEvent was never received
? 20240606.081939.275 I handle_order_status trade summary=WESTW WESTW permId=461612295 orderId=1040716 SELL 500.0 2.3 ref=P-WrtBS Filled filled=500.0, log(msg=Fill [email protected], status=Submitted 08:19:39)
? 20240606.081939.276 I handle_commission_report, fill=Fill(contract=Contract(secType='WAR', conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', exchange='SMART', primaryExchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), execution=Execution(execId='00010196.6661b194.01.01', time=datetime.datetime(2024, 6, 6, 15, 19, 39, tzinfo=datetime.timezone.utc), acctNumber='UXXX', exchange='NASDAQ', side='SLD', shares=359.0, price=2.3, permId=461612295, clientId=1002, orderId=1040716, liquidation=0, cumQty=359.0, avgPrice=2.3, orderRef='P-WrtBS', evRule='', evMultiplier=0.0, modelCode='', lastLiquidity=1, pendingPriceRevision=False), commissionReport=CommissionReport(execId='00010196.6661b194.01.01', commission=0.118976, currency='USD', realizedPNL=86.004596, yield_=0.0, yieldRedemptionDate=0), time=datetime.datetime(2024, 6, 6, 15, 19, 39, 136787, tzinfo=datetime.timezone.utc))
? 20240606.081939.348 I handle_commission_report, fill=Fill(contract=Contract(secType='WAR', conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', exchange='SMART', primaryExchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), execution=Execution(execId='00010196.6661b196.01.01', time=datetime.datetime(2024, 6, 6, 15, 19, 39, tzinfo=datetime.timezone.utc), acctNumber='UXXX', exchange='NASDAQ', side='SLD', shares=141.0, price=2.3, permId=461612295, clientId=1002, orderId=1040716, liquidation=0, cumQty=500.0, avgPrice=2.3, orderRef='P-WrtBS', evRule='', evMultiplier=0.0, modelCode='', lastLiquidity=1, pendingPriceRevision=False), commissionReport=CommissionReport(execId='00010196.6661b196.01.01', commission=0.046729, currency='USD', realizedPNL=33.778964, yield_=0.0, yieldRedemptionDate=0), time=datetime.datetime(2024, 6, 6, 15, 19, 39, 273794, tzinfo=datetime.timezone.utc))
081940 Received portfolio update that correctly shows position is 0
20240606.081940.491 W handle_position_update WESTW new qty=0, was 141 came from PortfolioItem, not Position: PortfolioItem(contract=Warrant(conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', primaryExchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), position=0.0, marketPrice=2.33500005, marketValue=0.0, averageCost=0.0, unrealizedPNL=0.0, realizedPNL=119.78, account='UXXX')
### Over 20 minutes after the trade, received an incorrect positionEvent, no entry in the API logs for this
20240606.085214.112 I handle_position_update WESTW, equity=WESTW: Position(account='UXXX', contract=Warrant(conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', exchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), position=141.0, avgCost=2.06010145)
They continued to come in for hours, there are no corresponding events in the API log. Received another portfolio update over 3 hours later
...
20240606.114602.671 W handle_position_update WESTW new qty=0, was 141 came from PortfolioItem, not Position: PortfolioItem(contract=Warrant(conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', primaryExchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), position=0.0, marketPrice=2.2950001, marketValue=0.0, averageCost=0.0, unrealizedPNL=0.0, realizedPNL=119.78, account='UXXX')
20240606.121238.530 I handle_position_update WESTW, equity=WESTW: Position(account='UXXX', contract=Warrant(conId=582332975, symbol='WEST', lastTradeDateOrContractMonth='20270829', strike=11.5, right='C', multiplier='1', exchange='NASDAQ', currency='USD', localSymbol='WESTW', tradingClass='WEST'), position=141.0, avgCost=2.06010145)
ibgateway API logs relevant entries with this contract id
08:18:46:003 -> ---t7-8-582332975-WEST-WAR-20270829-11.5-C-1-NASDAQ-USD-WESTW-WEST-500-2.33500005-1167.5-2.06010145-137.45-0.0-UXXX-
08:19:38:767 -> ---X61-3-UXXX-582332975-WEST-WAR-20270829-11.5-C-1-NASDAQ-USD-WESTW-WEST-141-2.06010145-
08:19:40:082 -> ---h7-8-582332975-WEST-WAR-20270829-11.5-C-1-NASDAQ-USD-WESTW-WEST-0-2.33500005-0.0-0.0-0.0-119.78-UXXX-
08:32:32:516 -> ---h7-8-582332975-WEST-WAR-20270829-11.5-C-1-NASDAQ-USD-WESTW-WEST-0-2.30500005-0.0-0.0-0.0-119.78-UXXX-
08:33:37:971 -> ---g7-8-582332975-WEST-WAR-20270829-11.5-C-1-NASDAQ-USD-WESTW-WEST-0-2.3299999-0.0-0.0-0.0-119.78-UXXX-
11:46:02:075 -> ---g7-8-582332975-WEST-WAR-20270829-11.5-C-1-NASDAQ-USD-WESTW-WEST-0-2.2950001-0.0-0.0-0.0-119.78-UXXX-
