ib-async@groups.io

#77

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-

#90

Hey honestly, I have always found positionEvent to not be so good and have a lot of latency so I personally keep track of position logic on my own. The most accurate thing is to use and use

trade.fillEvent +=

or ?

ib.execDetailsEvent+=

?to update your positions, BUT be careful since for combos it triggers for the entire combo and for each leg so you also need some logic that?

Fill.contract.secType!='BAG' (if you are only worried about positions)

#105

I don’t have much to add except to say that he’s 100% correct. I do the exact the same. Glad to hear others are doing what I do too

#106

Thanks, that is helpful

I had position = 800, order to sell 800, it initially filled 692/800
115708.497 positionEvent, position=108
115708.506 execDetailsEvent, Fill shares=692, cumQty=692, fill time=115707
115708.508 trade.fillEvent, Fill shares=692, cumQty=692, fill time=115707
115708.520 orderStatusEvent, filled=692
115708.535 execDetailsEvent, Fill shares=108, cumQty=800, fill time=115707
115708.537 trade.fillEvent, Fill shares=108, cumQty=800, fill time=115707
115708.540 orderStatusEvent, filled=800
Never received positionEvent, position=0

My current logic, which tries to work around the positionEvent bugginess, but is flawed, marks my position as verified if the positionEvent matches either all fills since the last verified time or an updatePortfolioEvent. In this case,

start: position = 800, verified
The first positionEvent sets position = 108, not verified
The first execDetailsEvent with the 692 fill makes it go back to verified as of the positionEvent time of 115708.497
The second execDetailsEvent with the 108 fill arrives, but the fill time of 115707 is before the time I verified the position, so I ignore it. This is wrong because the first positionEvent arrived after the remaining fill, even though it did not include it.

It sounds like I should just assume positionEvent is flawed and ignore it and only rely on execDetailsEvent or trade.fillEvent. Does that sound right?

Show quoted text

On Fri, Jul 12, 2024 at 8:08?PM nkulki via <nkulki=[email protected]> wrote:

I don’t have much to add except to say that he’s 100% correct. I do the exact the same. Glad to hear others are doing what I do too

开云体育

Incorrect