Fix sandbox venue order id creation

[davidsblom]

Pull Request

Fix venue_order_id checks when submitting orders with the sandbox.

Type of change

Delete options that are not relevant.

• [x] Bug fix (non-breaking change which fixes an issue)

How has this change been tested?

Locally running the sandbox with Bybit datafeed.

[davidsblom]

@cjdsellers not sure if this is the best approach. My thinking is that the venue_order_id is generated in multiple locations (order accepted, filled, updated, cancel) but the order itself is not updated in all these locations. Storing the generated venue_order_ids works around this issue.

Any idea why the order itself is not modified? That would be a smaller code change, and also doesn't introduce additional public methods.

By the way, happy to add more unit tests to proof the correctness. I'll wait a bit to hear your thoughts.

[davidsblom]

@rsmb7z curious to know if this fixes your issue as well.

[rsmb7z]

@rsmb7z curious to know if this fixes your issue as well.

The problem still persists. Additionally, it's worth noting that despite encountering the error, the system successfully opens the position. However, a notable concern arises as the same order is filled twice.

2024-05-10T19:08:28.309908400Z [INFO] SANDBOX-001.Portfolio: Updated AccountState(account_id=IDEALPRO-001, account_type=MARGIN, base_currency=USD, is_reported=False, balances=[AccountBalance(total=1_000_000.00 USD, locked=0.00 USD, free=1_000_000.00 USD)], margins=[], event_id=7d39e660-afc4-454a-ab27-cb6dde0771fb)
2024-05-10T19:08:28.309922100Z [INFO] SANDBOX-001.MyBreakoutStrategy: <--[EVT] OrderAccepted(instrument_id=EUR/USD.IDEALPRO, client_order_id=O-20240510-1908-001-000-1, venue_order_id=IDEALPRO-1-001, account_id=IDEALPRO-001, ts_event=1715368108309108401)
2024-05-10T19:08:28.310689600Z [INFO] SANDBOX-001.Portfolio: EUR/USD.IDEALPRO net_position=-100000.00
2024-05-10T19:08:28.310715400Z [INFO] SANDBOX-001.Portfolio: EUR/USD.IDEALPRO margin_maint=0.00 USD
2024-05-10T19:08:28.310774400Z [INFO] SANDBOX-001.Portfolio: Updated AccountState(account_id=IDEALPRO-001, account_type=MARGIN, base_currency=USD, is_reported=False, balances=[AccountBalance(total=1_000_000.00 USD, locked=0.00 USD, free=1_000_000.00 USD)], margins=[], event_id=c0e628af-5213-4f70-830a-ef87e5274672)
2024-05-10T19:08:28.310784300Z [INFO] SANDBOX-001.MyBreakoutStrategy: <--[EVT] PositionOpened(instrument_id=EUR/USD.IDEALPRO, position_id=EUR/USD.IDEALPRO-MyBreakoutStrategy-000, account_id=IDEALPRO-001, opening_order_id=O-20240510-1908-001-000-1, closing_order_id=None, entry=SELL, side=SHORT, signed_qty=-100000.0, quantity=100_000.00, peak_qty=100_000.00, currency=USD, avg_px_open=1.07732, avg_px_close=0.0, realized_return=0.00000, realized_pnl=0.00 USD, unrealized_pnl=0.00 USD, ts_opened=1715368108309108401, ts_last=1715368108309108401, ts_closed=0, duration_ns=0)
2024-05-10T19:08:28.310341100Z [ERROR] SANDBOX-001.ExecEngine: Error on applying OrderFilled(trader_id=SANDBOX-001, strategy_id=MyBreakoutStrategy-000, instrument_id=EUR/USD.IDEALPRO, client_order_id=O-20240510-1908-001-000-1, venue_order_id=IDEALPRO-1-002, account_id=IDEALPRO-001, trade_id=IDEALPRO-1-013, position_id=EUR/USD.IDEALPRO-MyBreakoutStrategy-000, order_side=SELL, order_type=LIMIT, last_qty=100_000.00, last_px=1.07732 USD, commission=0.00 USD, liquidity_side=TAKER, event_id=e2b4f9a1-3f00-41c7-a3f7-f47f54673d52, ts_event=1715368108309108401, ts_init=1715368108309108401) to LimitOrder(SELL 100_000.00 EUR/USD.IDEALPRO LIMIT @ 1.07710 GTD 2024-05-10T19:08:25.183Z, status=ACCEPTED, client_order_id=O-20240510-1908-001-000-1, venue_order_id=IDEALPRO-1-001, position_id=None, tags=['IBOrderTags:{"whatIf":false,"ocaGroup":"","ocaType":0,"allOrNone":false,"activeStartTime":"","activeStopTime":"","goodAfterTime":"","outsideRth":true}'])
ValueError(The 'self.venue_order_id' <class 'nautilus_trader.model.identifiers.VenueOrderId'> of IDEALPRO-1-001 was not equal to the 'event.venue_order_id' <class 'nautilus_trader.model.identifiers.VenueOrderId'> of IDEALPRO-1-002)
Traceback (most recent call last):
  File "nautilus_trader\\execution\\engine.pyx", line 1007, in nautilus_trader.execution.engine.ExecutionEngine._apply_event_to_order
  File "nautilus_trader\\model\\orders\\base.pyx", line 946, in nautilus_trader.model.orders.base.Order.apply
  File "nautilus_trader\\core\\correctness.pyx", line 306, in nautilus_trader.core.correctness.Condition.equal
2024-05-10T19:08:29.583734600Z [INFO] SANDBOX-001.MyBreakoutStrategy: Received Bar(EUR/USD.IDEALPRO-15-SECOND-MID-EXTERNAL,1.07730,1.07735,1.07730,1.07735,0.00,1715368095000000000):rev=False
2024-05-10T19:08:29.698492300Z [INFO] SANDBOX-001.Portfolio: EUR/USD.IDEALPRO margin_init=0.00 USD
2024-05-10T19:08:29.698514200Z [INFO] SANDBOX-001.Portfolio: Updated AccountState(account_id=IDEALPRO-001, account_type=MARGIN, base_currency=USD, is_reported=False, balances=[AccountBalance(total=1_000_000.00 USD, locked=0.00 USD, free=1_000_000.00 USD)], margins=[], event_id=c1790bc9-dec1-49cf-b608-463ee8dd007e)
2024-05-10T19:08:29.698519900Z [INFO] SANDBOX-001.MyBreakoutStrategy: <--[EVT] OrderFilled(instrument_id=EUR/USD.IDEALPRO, client_order_id=O-20240510-1908-001-000-1, venue_order_id=IDEALPRO-1-001, account_id=IDEALPRO-001, trade_id=IDEALPRO-1-015, position_id=EUR/USD.IDEALPRO-MyBreakoutStrategy-000, order_side=SELL, order_type=LIMIT, last_qty=100_000.00, last_px=1.07710 USD, commission=0.00 USD, liquidity_side=MAKER, ts_event=1715368110000000000)
2024-05-10T19:08:29.698628300Z [INFO] SANDBOX-001.Portfolio: EUR/USD.IDEALPRO net_position=-200000.00
2024-05-10T19:08:29.698641500Z [INFO] SANDBOX-001.Portfolio: EUR/USD.IDEALPRO margin_maint=0.00 USD
2024-05-10T19:08:29.698645700Z [INFO] SANDBOX-001.Portfolio: Updated AccountState(account_id=IDEALPRO-001, account_type=MARGIN, base_currency=USD, is_reported=False, balances=[AccountBalance(total=1_000_000.00 USD, locked=0.00 USD, free=1_000_000.00 USD)], margins=[], event_id=db303571-6a20-4752-9135-d76741a38aac)
2024-05-10T19:08:29.698661800Z [INFO] SANDBOX-001.MyBreakoutStrategy: <--[EVT] PositionChanged(instrument_id=EUR/USD.IDEALPRO, position_id=EUR/USD.IDEALPRO-MyBreakoutStrategy-000, account_id=IDEALPRO-001, opening_order_id=O-20240510-1908-001-000-1, closing_order_id=None, entry=SELL, side=SHORT, signed_qty=-200000.0, quantity=200_000.00, peak_qty=200_000.00, currency=USD, avg_px_open=1.07721, avg_px_close=0.0, realized_return=0.00000, realized_pnl=0.00 USD, unrealized_pnl=22.00 USD, ts_opened=1715368108309108401, ts_last=1715368110000000000, ts_closed=0, duration_ns=0)
2024-05-10T19:08:29.698733300Z [WARN] SANDBOX-001.ExecEngine: InvalidStateTrigger: FILLED -> EXPIRED, did not apply OrderExpired(instrument_id=EUR/USD.IDEALPRO, client_order_id=O-20240510-1908-001-000-1, venue_order_id=IDEALPRO-1-001, account_id=IDEALPRO-001, ts_event=1715368110000000000)

[davidsblom]

Thanks for testing. Don't fully understand yet what is the cause. Probably indeed a race condition.

[cjdsellers]

Hey @davidsblom

Thanks for the investigation here.

I think we don't want to start expanding the matching core into a cache, minimally its just holding and processing orders. The OrderMatchingEngine actually has access to the cache, and there is a method for fetching the venue_order_id for a client_order_id.

cpdef VenueOrderId venue_order_id(self, ClientOrderId client_order_id)

I'll do a pass of the matching engine and see if the venue_order_id generation can be simplified / consolidated / improved.

The order is updated at the execution engine (because that is where it's updated for live as well, the venue can't apply events), but I think I can take your idea here and persist the venue_order_id to the cache as soon as its generated, so that the same one is then used whenever it's found to be None on the order.

[cjdsellers]

I pushed a change here which basically achieves the same thing, consolidating the generation logic and immediately caching any generated ID.

This has tightened up the ID invariants so I also had to update many tests to ensure venue order IDs align - which is a good sign. This error message "should never occur" now, and it's also clearer why:

ValueError: Existing ClientOrderId('O-19700101-0000-000-None-1') for VenueOrderId('1') did not match the given ClientOrderId('O-19700101-0000-000-None-2'). If you are writing a test then try a different `venue_order_id`, otherwise this is probably a bug.

Let me know if this fixes the sandbox issues, then I can update the release notes.

[rsmb7z]

Let me know if this fixes the sandbox issues, then I can update the release notes.

Would test once market open.

[davidsblom]

Awesome! I'll test it a bit later this weekend.

[davidsblom]

The error doesn't appear anymore in the logs. Still seeing this warning in the logs (which was also still there with my hacky fix).

2024-05-11T06:55:40.030922001Z [WARN] PAPER-TRADING-001.ExecEngine: InvalidStateTrigger: FILLED -> FILLED, did not apply OrderFilled(instrument_id=BTCUSDT-LINEAR.BYBIT, client_order_id=O-20240511-0655-001-000-197, venue_order_id=BYBIT-617-153, account_id=BYBIT-001, trade_id=BYBIT-617-244, position_id=BTCUSDT-LINEAR.BYBIT-ReinforcementLearningMarketMakerStrategy-000, order_side=BUY, order_type=LIMIT, last_qty=0.002, last_px=60_943.91 USDT, commission=0.0244 USDT, liquidity_side=MAKER, ts_event=1715410540000000000)

So closing this issue. The InvalidStateTrigger probably deserves some more investigation later.

[davidsblom]

Closed the PR a little bit too fast. Still waiting for @rsmb7z to confirm but cannot reopen anymore.

[cjdsellers]

Cool thanks @davidsblom I think there may still be some race conditions in here considering the real-time data aspect.

[davidsblom]

Unfortunately the error still occured. Created an issue to keep track of it. #1636

[rsmb7z]

Closed the PR a little bit too fast. Still waiting for @rsmb7z to confirm but cannot reopen anymore.

Works perfectly without any errors.