search

nautechsystems / nautilus_trader

A high-performance algorithmic trading platform and event-driven backtester
https://nautilustrader.io
GNU Lesser General Public License v3.0
1.71k stars 402 forks source link

No account registered error for IBKR #1610

Closed benjaminsingleton closed 2 months ago

benjaminsingleton commented 2 months ago

Bug Report

It looks like a bug was introduced in 1.191 that is not present in 1.190. I'm not sure yet if this is specific to the Interactive Brokers adapter or whether it is related to other changes.

Expected Behavior

Able to reconcile existing positions in Interactive Brokers.

Actual Behavior

2024-04-25T02:51:03.955754001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
...
2024-04-25T02:51:03.956474001Z [ERROR] TESTER-001.ExecEngine: Cannot handle order fill: no account found for NASDAQ, OrderFilled(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, trade_id=9c8da2fe-726c-454a-84d2-13e76cb8169b, position_id=AAPL.NASDAQ-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=1200, last_px=185.17 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714013463945493001)

Here are some more comprehensive log differences for the same strategy in 1.190 vs 1.191:

1.190

2024-04-26T01:13:49.187769001Z [INFO] TESTER-001.ExecEngine: Registered ExecutionClient-INTERACTIVE_BROKERS.
2024-04-26T01:13:49.187777001Z [INFO] TESTER-001.ExecEngine: Registered INTERACTIVE_BROKERS for default routing.

1.191

2024-04-25T02:51:03.752673001Z [INFO] TESTER-001.ExecEngine: Registered ExecutionClient-IB
2024-04-25T02:51:03.752682001Z [INFO] TESTER-001.ExecEngine: Registered IB for default routing

1.190

2024-04-26T01:13:49.738580001Z [DEBUG] TESTER-001.ExecEngine: [RECV][RPT] ExecutionMassStatus(client_id=INTERACTIVE_BROKERS, account_id=INTERACTIVE_BROKERS-DU1234567, venue=INTERACTIVE_BROKERS, order_reports={VenueOrderId('AAPL.NASDAQ'): OrderStatusReport(account_id=INTERACTIVE_BROKERS-DU1234567, instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, order_list_id=None, venue_order_id=AAPL.NASDAQ, order_side=BUY, order_type=MARKET, contingency_type=NO_CONTINGENCY, time_in_force=FOK, expire_time=None, order_status=FILLED, price=None, trigger_price=None, trigger_type=NO_TRIGGER, limit_offset=None, trailing_offset=None, trailing_offset_type=NO_TRAILING_OFFSET, quantity=1_200, filled_qty=1_200, leaves_qty=0, display_qty=None, avg_px=185.17, post_only=False, reduce_only=False, cancel_reason=None, report_id=5d192a1f-666f-4373-a995-8f2e046546a5, ts_accepted=1714094029440501001, ts_triggered=0, ts_last=1714094029440501001, ts_init=1714094029440501001), VenueOrderId('BTC/USD.PAXOS'): OrderStatusReport(account_id=INTERACTIVE_BROKERS-DU1234567, instrument_id=BTC/USD.PAXOS, client_order_id=BTC/USD.PAXOS, order_list_id=None, venue_order_id=BTC/USD.PAXOS, order_side=BUY, order_type=MARKET, contingency_type=NO_CONTINGENCY, time_in_force=FOK, expire_time=None, order_status=FILLED, price=None, trigger_price=None, trigger_type=NO_TRIGGER, limit_offset=None, trailing_offset=None, trailing_offset_type=NO_TRAILING_OFFSET, quantity=0.05159349, filled_qty=0.05159349, leaves_qty=0.00000000, display_qty=None, avg_px=42908.56, post_only=False, reduce_only=False, cancel_reason=None, report_id=ac1768c3-eabd-4fbc-a65f-c39114ccccf0, ts_accepted=1714094029440501001, ts_triggered=0, ts_last=1714094029440501001, ts_init=1714094029440501001)}, fill_reports={}, position_reports={InstrumentId('AAPL.NASDAQ'): [PositionStatusReport(account_id=INTERACTIVE_BROKERS-DU1234567, instrument_id=AAPL.NASDAQ, venue_position_id=None, position_side=LONG, quantity=1_200, signed_decimal_qty=1200, report_id=7a4663d4-c8c2-4f9a-85db-98d5daf9cc51, ts_last=1714094029682576001, ts_init=1714094029682576002)], InstrumentId('BTC/USD.PAXOS'): [PositionStatusReport(account_id=INTERACTIVE_BROKERS-DU1234567, instrument_id=BTC/USD.PAXOS, venue_position_id=None, position_side=LONG, quantity=0.05159349, signed_decimal_qty=0.05159349, report_id=d9279b93-9c27-40ae-98af-0e0c9d581f9f, ts_last=1714094029737241001, ts_init=1714094029737241002)]}, report_id=0c4dd589-5e0f-4054-8723-fcf315cc18a4, ts_init=1714094029435012001).
2024-04-26T01:13:49.738598001Z [INFO] TESTER-001.ExecEngine: Reconciling ExecutionMassStatus for INTERACTIVE_BROKERS.
2024-04-26T01:13:49.738607001Z [INFO] TESTER-001.ExecEngine: Reconciling order for ClientOrderId('AAPL.NASDAQ')...
2024-04-26T01:13:49.738655001Z [INFO] TESTER-001.ExecEngine: Generating order ClientOrderId('AAPL.NASDAQ')
2024-04-26T01:13:49.738903001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderInitialized(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, side=BUY, type=MARKET, quantity=1_200, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'expire_time_ns': 0}, emulation_trigger=NO_TRIGGER, trigger_instrument_id=None, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, exec_algorithm_id=None, exec_algorithm_params=None, exec_spawn_id=None, tags=EXTERNAL).
2024-04-26T01:13:49.738926001Z [DEBUG] TESTER-001.Cache: Added MarketOrder(BUY 1_200 AAPL.NASDAQ MARKET GTC, status=INITIALIZED, client_order_id=AAPL.NASDAQ, venue_order_id=None, position_id=None, tags=EXTERNAL).
2024-04-26T01:13:49.738996001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderAccepted(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=INTERACTIVE_BROKERS-DU1234567, ts_event=1714094029440501001).
2024-04-26T01:13:49.739701001Z [WARN] TESTER-001.ExecEngine: Generated inferred OrderFilled(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=INTERACTIVE_BROKERS-DU1234567, trade_id=3646bbec-22a1-478d-ba98-5285f1e6938c, position_id=AAPL.NASDAQ-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=1200, last_px=185.17 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714094029440501001).
2024-04-26T01:13:49.739857001Z [DEBUG] TESTER-001.Cache: Indexed PositionId('AAPL.NASDAQ-EXTERNAL'), client_order_id=AAPL.NASDAQ, strategy_id=EXTERNAL).
2024-04-26T01:13:49.739866001Z [DEBUG] TESTER-001.Cache: Added Position(id=AAPL.NASDAQ-EXTERNAL, strategy_id=EXTERNAL).
2024-04-26T01:13:49.740057001Z [INFO] TESTER-001.Portfolio: AAPL.NASDAQ net_position=1200
2024-04-26T01:13:49.740083001Z [DEBUG] TESTER-001.Portfolio: Cannot calculate unrealized PnL: no prices for AAPL.NASDAQ.

1.191

2024-04-25T02:51:03.953953001Z [DEBUG] TESTER-001.ExecEngine: [RECV][RPT] ExecutionMassStatus(client_id=IB, account_id=IB-DU1234567, venue=INTERACTIVE_BROKERS, order_reports={VenueOrderId('AAPL.NASDAQ'): OrderStatusReport(account_id=IB-DU1234567, instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, order_list_id=None, venue_order_id=AAPL.NASDAQ, order_side=BUY, order_type=MARKET, contingency_type=NO_CONTINGENCY, time_in_force=FOK, expire_time=None, order_status=FILLED, price=None, trigger_price=None, trigger_type=NO_TRIGGER, limit_offset=None, trailing_offset=None, trailing_offset_type=NO_TRAILING_OFFSET, quantity=1_200, filled_qty=1_200, leaves_qty=0, display_qty=None, avg_px=185.17, post_only=False, reduce_only=False, cancel_reason=None, report_id=61624aac-be41-4b58-91cd-26f57aba6dd0, ts_accepted=1714013463945493001, ts_triggered=0, ts_last=1714013463945493001, ts_init=1714013463945493001), VenueOrderId('BTC/USD.PAXOS'): OrderStatusReport(account_id=IB-DU1234567, instrument_id=BTC/USD.PAXOS, client_order_id=BTC/USD.PAXOS, order_list_id=None, venue_order_id=BTC/USD.PAXOS, order_side=BUY, order_type=MARKET, contingency_type=NO_CONTINGENCY, time_in_force=FOK, expire_time=None, order_status=FILLED, price=None, trigger_price=None, trigger_type=NO_TRIGGER, limit_offset=None, trailing_offset=None, trailing_offset_type=NO_TRAILING_OFFSET, quantity=0.05159349, filled_qty=0.05159349, leaves_qty=0.00000000, display_qty=None, avg_px=42908.56, post_only=False, reduce_only=False, cancel_reason=None, report_id=7a5fe544-6523-4fdf-8c87-3b267eed1106, ts_accepted=1714013463945493001, ts_triggered=0, ts_last=1714013463945493001, ts_init=1714013463945493001)}, fill_reports={}, position_reports={InstrumentId('AAPL.NASDAQ'): [PositionStatusReport(account_id=IB-DU1234567, instrument_id=AAPL.NASDAQ, venue_position_id=None, position_side=LONG, quantity=1_200, signed_decimal_qty=1200, report_id=2c9c0f0f-51f4-4419-b15d-0063a53e7506, ts_last=1714013463950672001, ts_init=1714013463950672002)], InstrumentId('BTC/USD.PAXOS'): [PositionStatusReport(account_id=IB-DU1234567, instrument_id=BTC/USD.PAXOS, venue_position_id=None, position_side=LONG, quantity=0.05159349, signed_decimal_qty=0.05159349, report_id=f4abdcf7-7e6a-4ea2-85db-1386a36089d2, ts_last=1714013463953082001, ts_init=1714013463953082002)]}, report_id=975179f4-50ad-47ca-a3c9-640414042269, ts_init=1714013463943010001)
2024-04-25T02:51:03.953964001Z [INFO] TESTER-001.ExecEngine: Reconciling ExecutionMassStatus for INTERACTIVE_BROKERS
2024-04-25T02:51:03.953967001Z [INFO] TESTER-001.ExecEngine: Reconciling order for ClientOrderId('AAPL.NASDAQ')
2024-04-25T02:51:03.953970001Z [INFO] TESTER-001.ExecEngine: Generating order ClientOrderId('AAPL.NASDAQ')
2024-04-25T02:51:03.954565001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderInitialized(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, side=BUY, type=MARKET, quantity=1_200, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'expire_time_ns': 0}, emulation_trigger=NO_TRIGGER, trigger_instrument_id=None, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, exec_algorithm_id=None, exec_algorithm_params=None, exec_spawn_id=None, tags=EXTERNAL)
2024-04-25T02:51:03.954595001Z [DEBUG] TESTER-001.Cache: Added MarketOrder(BUY 1_200 AAPL.NASDAQ MARKET GTC, status=INITIALIZED, client_order_id=AAPL.NASDAQ, venue_order_id=None, position_id=None, tags=EXTERNAL)
2024-04-25T02:51:03.954919001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderAccepted(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, ts_event=1714013463945493001)
2024-04-25T02:51:03.955754001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
2024-04-25T02:51:03.956433001Z [WARN] TESTER-001.ExecEngine: Generated inferred OrderFilled(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, trade_id=9c8da2fe-726c-454a-84d2-13e76cb8169b, position_id=AAPL.NASDAQ-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=1200, last_px=185.17 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714013463945493001)
2024-04-25T02:51:03.956454001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
2024-04-25T02:51:03.956474001Z [ERROR] TESTER-001.ExecEngine: Cannot handle order fill: no account found for NASDAQ, OrderFilled(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, trade_id=9c8da2fe-726c-454a-84d2-13e76cb8169b, position_id=AAPL.NASDAQ-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=1200, last_px=185.17 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714013463945493001)

Steps to Reproduce the Problem

  1. Add positions in IBKR
  2. Start NT

Specifications

rsmb7z commented 2 months ago

@benjaminsingleton Because factory name is now overriding hence special treatment of Portfolio might not be working. Do you still experience if you make any of the following changes? a) Set node.portfolio.set_specific_venue(Venue("IB")) (because factory name according to your logs is 'IB') b) Set factory name to INTERACTIVE_BROKERS which is the value of IB_VENUE

benjaminsingleton commented 2 months ago

This got my code working again:

b) Set factory name to INTERACTIVE_BROKERS which is the value of IB_VENUE

But this didn't:

a) Set node.portfolio.set_specific_venue(Venue("IB")) (because factory name according to your logs is 'IB')

2024-04-26T02:19:25.220031001Z [INFO] TESTER-001.ExecEngine: Reconciling ExecutionMassStatus for INTERACTIVE_BROKERS
2024-04-26T02:19:25.220034001Z [INFO] TESTER-001.ExecEngine: Reconciling order for ClientOrderId('AAPL.NASDAQ')
2024-04-26T02:19:25.220035001Z [INFO] TESTER-001.ExecEngine: Generating order ClientOrderId('AAPL.NASDAQ')
2024-04-26T02:19:25.220506001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderInitialized(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, side=BUY, type=MARKET, quantity=1_200, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'expire_time_ns': 0}, emulation_trigger=NO_TRIGGER, trigger_instrument_id=None, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, exec_algorithm_id=None, exec_algorithm_params=None, exec_spawn_id=None, tags=EXTERNAL)
2024-04-26T02:19:25.220644001Z [DEBUG] TESTER-001.Cache: Added MarketOrder(BUY 1_200 AAPL.NASDAQ MARKET GTC, status=INITIALIZED, client_order_id=AAPL.NASDAQ, venue_order_id=None, position_id=None, tags=EXTERNAL)
2024-04-26T02:19:25.220939001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderAccepted(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, ts_event=1714097965209516001)
2024-04-26T02:19:25.221667001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
2024-04-26T02:19:25.222006001Z [WARN] TESTER-001.ExecEngine: Generated inferred OrderFilled(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, trade_id=0edb8a82-65f9-4db6-b900-9428c46b5fb3, position_id=AAPL.NASDAQ-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=1200, last_px=185.17 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714097965209516001)
2024-04-26T02:19:25.222023001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
2024-04-26T02:19:25.222044001Z [ERROR] TESTER-001.ExecEngine: Cannot handle order fill: no account found for NASDAQ, OrderFilled(instrument_id=AAPL.NASDAQ, client_order_id=AAPL.NASDAQ, venue_order_id=AAPL.NASDAQ, account_id=IB-DU1234567, trade_id=0edb8a82-65f9-4db6-b900-9428c46b5fb3, position_id=AAPL.NASDAQ-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=1200, last_px=185.17 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714097965209516001)
2024-04-26T02:19:25.222053001Z [INFO] TESTER-001.ExecEngine: Reconciling order for ClientOrderId('BTC/USD.PAXOS')
2024-04-26T02:19:25.222057001Z [INFO] TESTER-001.ExecEngine: Generating order ClientOrderId('BTC/USD.PAXOS')
2024-04-26T02:19:25.222086001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderInitialized(instrument_id=BTC/USD.PAXOS, client_order_id=BTC/USD.PAXOS, side=BUY, type=MARKET, quantity=0.05159349, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'expire_time_ns': 0}, emulation_trigger=NO_TRIGGER, trigger_instrument_id=None, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, exec_algorithm_id=None, exec_algorithm_params=None, exec_spawn_id=None, tags=EXTERNAL)
2024-04-26T02:19:25.222090001Z [DEBUG] TESTER-001.Cache: Added MarketOrder(BUY 0.05159349 BTC/USD.PAXOS MARKET GTC, status=INITIALIZED, client_order_id=BTC/USD.PAXOS, venue_order_id=None, position_id=None, tags=EXTERNAL)
2024-04-26T02:19:25.222104001Z [DEBUG] TESTER-001.ExecEngine: Generated OrderAccepted(instrument_id=BTC/USD.PAXOS, client_order_id=BTC/USD.PAXOS, venue_order_id=BTC/USD.PAXOS, account_id=IB-DU1234567, ts_event=1714097965209516001)
2024-04-26T02:19:25.222107001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
2024-04-26T02:19:25.222133001Z [WARN] TESTER-001.ExecEngine: Generated inferred OrderFilled(instrument_id=BTC/USD.PAXOS, client_order_id=BTC/USD.PAXOS, venue_order_id=BTC/USD.PAXOS, account_id=IB-DU1234567, trade_id=419e00e0-5dfa-4559-9724-6e35e22d325f, position_id=BTC/USD.PAXOS-EXTERNAL, order_side=BUY, order_type=MARKET, last_qty=0.05159349, last_px=42908.56 USD, commission=0.00 USD, liquidity_side=TAKER, ts_event=1714097965209516001)
2024-04-26T02:19:25.222140001Z [ERROR] TESTER-001.Portfolio: Cannot update order: no account registered for IB-DU1234567
rsmb7z commented 2 months ago

@cjdsellers It is because the name doesn't match here after 'Implement custom client IDs'. Because the name can be customized now and dynamically setting may not work in other cases as well (at the moment) i.e if user tries run more than one-adapters, it may be less confusing if we require the user to explicity set_specific_venue as specified in example.

cjdsellers commented 2 months ago

Yes, good catch @rsmb7z and we parse the custom name here.

Then I think we shouldn't rely on this hard coded string (I note the "temporary" comment there too), but should check if factory is an instance of either InteractiveBrokersDataExecClientFactory or InteractiveBrokersLiveExecClientFactory?

But then following onto L268 we set a specific venue of Venue("InteractiveBrokers"). Will this still work with multiple Interactive Brokers clients?

rsmb7z commented 2 months ago

But then following onto L268 we set a specific venue of Venue("InteractiveBrokers"). Will this still work with multiple Interactive Brokers clients?

The problem I believe is we only have one Portfolio, while it may not raise any errors, multiple ExecCients would be sending their own balance updates and calculations maynot be as expected within Portfolio. Some more info is tracked in #1051.

we parse the custom name here.

Then I think we shouldn't rely on this hard coded string (I note the "temporary" comment there too), but should check if factory is an instance of either InteractiveBrokersDataExecClientFactory or InteractiveBrokersLiveExecClientFactory?

Both of the L202 and L268 would be removed and for ExecClient dynamic addition can be done when the Factory is IB, if you prefer that way.

benjaminsingleton commented 2 months ago

In node_builder.py, should we check if name == 'INTERACTIVE_BROKERS' instead of InteractiveBrokers so it matches IB_VENUE here?

rsmb7z commented 2 months ago

I have pushed the fix in #1616.

benjaminsingleton commented 2 months ago

Thank you!