Bug with position internal state

[Tzumx]

Bug Report

We did a lot of testing of the platform recently and executed big amount of orders, and most of them were handled properly, but sometimes (rarely, once per 20-60 orders), we see some unusual behavior that results in incorrect position calculation and brakes our logic.

Expected Behavior

We send our market order and it executed and changes internal position only on real quantity it was filled

Actual Behavior

Sending order sometimes changes internal position twice. For instance, long ETH with 1 token may be calculated as a size of 2 tokens in the nautilus position, even though on the exchange side it was only 1 token.

Steps to Reproduce the Problem

1. Create order (Binance futures in our case), which triggers OrderInitialized event
2. Submit order, which triggers OrderSubmitted event
3. Then observe something unusual: reconciling inferior with OrderFilled event from web sockets, which results in changing position at the same volume twice. So we double our position volume.
4. That only change internal numbers in nautilus strategy, on real account order was filled as necessary with normal volume.

Logs:

[1m2023-02-12T08:14:05.592287866Z][INF] TRADER-001.MySuperStrategy-000: Received on_event: PositionChanged(instrument_id=EOSUSDT-PERP.BINANCE, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, account_id=BINANCE-futures-master, opening_order_id=O-20230212-001-000-203, closing_order_id=None, entry=SELL, side=SHORT, net_qty=-34.2, quantity=34.2, peak_qty=34.2, currency=USDT, avg_px_open=1.052, avg_px_close=0.0, realized_return=0.00000, realized_pnl=0.00000000 USDT, unrealized_pnl=0.00000000 USDT, ts_opened=1676188803363000064, ts_last=1676188803363000064, ts_closed=0, duration_ns=0)
[1m2023-02-12T08:14:05.592270110Z][INF] TRADER-001.MySuperStrategy-000: <--[EVT] PositionChanged(instrument_id=EOSUSDT-PERP.BINANCE, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, account_id=BINANCE-futures-master, opening_order_id=O-20230212-001-000-203, closing_order_id=None, entry=SELL, side=SHORT, net_qty=-34.2, quantity=34.2, peak_qty=34.2, currency=USDT, avg_px_open=1.052, avg_px_close=0.0, realized_return=0.00000, realized_pnl=0.00000000 USDT, unrealized_pnl=0.00000000 USDT, ts_opened=1676188803363000064, ts_last=1676188803363000064, ts_closed=0, duration_ns=0).
[1m2023-02-12T08:14:05.592234238Z][INF] TRADER-001.Portfolio: EOSUSDT-PERP.BINANCE net_position=-34.2
[1m2023-02-12T08:14:05.592168608Z][WRN] TRADER-001.ExecEngine: InvalidStateTrigger: FILLED -> FILLED, did not apply OrderFilled(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, trade_id=500401097, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, order_side=SELL, order_type=MARKET, last_qty=17.1, last_px=1.052 USDT, commission=0.00719568 USDT, liquidity_side=TAKER, ts_event=1676188803363000064)
[1m2023-02-12T08:14:05.592119382Z][WRN] TRADER-001.ExecEngine: InvalidStateTrigger: FILLED -> ACCEPTED, did not apply OrderAccepted(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, ts_event=1676188803363000064)
[1m2023-02-12T08:14:04.471389290Z][INF] TRADER-001.MySuperStrategy-000: Received on_event: PositionOpened(instrument_id=EOSUSDT-PERP.BINANCE, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, account_id=BINANCE-futures-master, opening_order_id=O-20230212-001-000-203, closing_order_id=None, entry=SELL, side=SHORT, net_qty=-17.1, quantity=17.1, peak_qty=17.1, currency=USDT, avg_px_open=1.052, avg_px_close=0.0, realized_return=0.00000, realized_pnl=0.00000000 USDT, unrealized_pnl=0.00000000 USDT, ts_opened=1676188803363000064, ts_last=1676188803363000064, ts_closed=0, duration_ns=0)
[1m2023-02-12T08:14:04.471373842Z][INF] TRADER-001.MySuperStrategy-000: <--[EVT] PositionOpened(instrument_id=EOSUSDT-PERP.BINANCE, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, account_id=BINANCE-futures-master, opening_order_id=O-20230212-001-000-203, closing_order_id=None, entry=SELL, side=SHORT, net_qty=-17.1, quantity=17.1, peak_qty=17.1, currency=USDT, avg_px_open=1.052, avg_px_close=0.0, realized_return=0.00000, realized_pnl=0.00000000 USDT, unrealized_pnl=0.00000000 USDT, ts_opened=1676188803363000064, ts_last=1676188803363000064, ts_closed=0, duration_ns=0).
[1m2023-02-12T08:14:04.471338704Z][INF] TRADER-001.Portfolio: EOSUSDT-PERP.BINANCE net_position=-17.1
[1m2023-02-12T08:14:04.470768506Z][INF] TRADER-001.MySuperStrategy-000: Received on_event: OrderFilled(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, trade_id=0f4ba0ce-a0d5-4e24-8c6f-88f98fc4e749, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, order_side=SELL, order_type=MARKET, last_qty=17.1, last_px=1.052 USDT, commission=0.00719568 USDT, liquidity_side=TAKER, ts_event=1676188803363000064)
[1m2023-02-12T08:14:04.470741676Z][INF] TRADER-001.MySuperStrategy-000: <--[EVT] OrderFilled(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, trade_id=0f4ba0ce-a0d5-4e24-8c6f-88f98fc4e749, position_id=EOSUSDT-PERP.BINANCE-MySuperStrategy-000, order_side=SELL, order_type=MARKET, last_qty=17.1, last_px=1.052 USDT, commission=0.00719568 USDT, liquidity_side=TAKER, ts_event=1676188803363000064).
[1m2023-02-12T08:14:04.470711647Z][WRN] TRADER-001.ExecEngine: Generated inferred OrderFilled(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, trade_id=0f4ba0ce-a0d5-4e24-8c6f-88f98fc4e749, position_id=EOSUSDT-PERP.BINANCE-EXTERNAL, order_side=SELL, order_type=MARKET, last_qty=17.1, last_px=1.052 USDT, commission=0.00719568 USDT, liquidity_side=TAKER, ts_event=1676188803363000064).
[1m2023-02-12T08:14:04.468959743Z][INF] TRADER-001.MySuperStrategy-000: Received on_event: OrderAccepted(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, ts_event=1676188800209999872)
[1m2023-02-12T08:14:04.468932752Z][INF] TRADER-001.MySuperStrategy-000: <--[EVT] OrderAccepted(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, venue_order_id=19601063032, account_id=BINANCE-futures-master, ts_event=1676188800209999872).
[1m2023-02-12T08:14:04.468887428Z][INF] TRADER-001.ExecEngine: Reconciling OrderStatusReport(account_id=BINANCE-futures-master, instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, order_list_id=None, venue_order_id=19601063032, order_side=SELL, order_type=MARKET, contingency_type=NO_CONTINGENCY, time_in_force=GTC, expire_time=None, order_status=FILLED, price=0, trigger_price=None, trigger_type=LAST_TRADE, limit_offset=None, trailing_offset=None, trailing_offset_type=NO_TRAILING_OFFSET, quantity=17.1, filled_qty=17.1, leaves_qty=0.0, display_qty=None, avg_px=1.0520, post_only=False, reduce_only=False, cancel_reason=None, report_id=6a2a4e2f-e100-426d-92e4-337a5c7a474b, ts_accepted=1676188800209999872, ts_triggered=0, ts_last=1676188803363000064, ts_init=1676188804465892750).
[1m2023-02-12T08:14:00.173074325Z][INF] TRADER-001.MySuperStrategy-000: Received on_event: OrderSubmitted(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, account_id=BINANCE-futures-master, ts_event=1676188800172347947)
[1m2023-02-12T08:14:00.173061887Z][INF] TRADER-001.MySuperStrategy-000: <--[EVT] OrderSubmitted(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, account_id=BINANCE-futures-master, ts_event=1676188800172347947).
[1m2023-02-12T08:14:00.156913525Z][INF] TRADER-001.MySuperStrategy-000: [CMD]--> SubmitOrder(order=MarketOrder(SELL 17.1 EOSUSDT-PERP.BINANCE MARKET GTC, status=INITIALIZED, client_order_id=O-20230212-001-000-203, venue_order_id=None, tags=entry), position_id=None, exec_algorithm_spec=None).
[1m2023-02-12T08:14:00.156870666Z][INF] TRADER-001.MySuperStrategy-000: Received on_event: OrderInitialized(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, side=SELL, type=MARKET, quantity=17.1, time_in_force=GTC, post_only=False, reduce_only=False, options={}, emulation_trigger=NO_TRIGGER, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, tags=entry)
[1m2023-02-12T08:14:00.156845110Z][INF] TRADER-001.MySuperStrategy-000: <--[EVT] OrderInitialized(instrument_id=EOSUSDT-PERP.BINANCE, client_order_id=O-20230212-001-000-203, side=SELL, type=MARKET, quantity=17.1, time_in_force=GTC, post_only=False, reduce_only=False, options={}, emulation_trigger=NO_TRIGGER, contingency_type=NO_CONTINGENCY, order_list_id=None, linked_order_ids=None, parent_order_id=None, tags=entry).

We did some investigation, and our guess is this:

inferred event is generated from _generate_inferred_fill ← _reconcile_order_report ← _reconcile_report which through msgbus getting from _send_order_status_report ← _generate_external_order_report from [execution.py](https://github.com/nautechsystems/nautilus_trader/blob/97ee22e98afa0017faeeb2cdd325e65dc6eb2514/nautilus_trader/adapters/binance/spot/execution.py#L743)

So it could be because of somehow missed strategy_id for that order in the cache.

Let us know if you need more details, we are still in the process of investigating and trying to fix this issue, happy to provide more info if you have any ideas of what it can be.

Specifications

• OS platform: Ubuntu 20.04 LTS, Mac
• Python version: 3.11.1
• nautilus_trader version: version: 1.168
• Tested on AMD Ryzen 9 5950X, 4*32GB and local PCs

[cjdsellers]

Hi @Tzumx

Thanks for the detailed report!

I agree this is probably being caused by a strategy_id which cannot be recovered from the cache for some reason. We recently had a large refactoring of the Binance adapter which is pending release very soon.

Are you able to try your testing again from v1.169.0 on the develop branch? Alternatively I hope to have this version released sometime this week.

If you find the same behavior then I can dig further.

[cjdsellers]

The new version is now released.

I'm just after a little more information, is your strategy purely automated - or are you also sending external orders from a GUI or from a source external to Nautilus?

[Tzumx]

The new version is now released.

I'm just after a little more information, is your strategy purely automated - or are you also sending external orders from a GUI or from a source external to Nautilus?

Sorry for the late answer: Yes, strategy is automated fully and all orders are executed only from internal logic

Thanks for the new version, we are going to test on it

[cjdsellers]

Hi Tzumx,

Did you manage to get any further with your testing?

[cjdsellers]

I think I have a good idea of why this occurs, its a race condition between submitting the order and during the round trip latency the orders in-flight check loop detects an order in-flight and also requests status. Then the order status report comes back and generates a fill event along with the event coming in over the websocket.

To test this theory you could turn of the inflight checks:

LiveExecEngineConfig(inflight_check_interval_ms=0)

Or, increase the inflight_check_threshold_ms (I've actually bumped up the default to 2_000 ms now).

[cjdsellers]

I think the make this even more robust so there's no race condition, we need to check if any trade ID has already been processed. I'll have think about it.

[Tzumx]

Thanks for your investigation in that question, now I'm running on last version - no bug still, but it happens not often, so I'll continue to observe and for sure will try your advice

[cjdsellers]

So we still think the above is the most likely explanation, also I originally set the two config defaults back to front. It should check with the exchange more often, but allow a larger threshold before actually attempting a reconciliation - as there is a race condition here which could be caused by any number of things.

Note the new defaults and improved docs:

class LiveExecEngineConfig(ExecEngineConfig, frozen=True):
    """
    Configuration for ``LiveExecEngine`` instances.

    The purpose of the in-flight order check is for live reconciliation, events
    emitted from the exchange may have been lost at some point - leaving an order
    in an intermediate state, the check can recover these events via status reports.

    Parameters
    ----------
    reconciliation : bool, default True
        If reconciliation is active at start-up.
    reconciliation_lookback_mins : NonNegativeInt, optional
        The maximum lookback minutes to reconcile state for.
        If ``None`` or 0 then will use the maximum lookback available from the venues.
    inflight_check_interval_ms : NonNegativeInt, default 2_000
        The interval (milliseconds) between checking whether in-flight orders
        have exceeded their time-in-flight threshold.
        This should not be set less than the `inflight_check_interval_ms`.
    inflight_check_threshold_ms : NonNegativeInt, default 5_000
        The threshold (milliseconds) beyond which an in-flight orders status
        is checked with the venue.
        As a rule of thumb, you shouldn't consider reducing this setting unless you
        are colocated with the venue (to avoid the potential for race conditions).
    qsize : PositiveInt, default 10_000
        The queue size for the engines internal queue buffers.
    """

    reconciliation: bool = True
    reconciliation_lookback_mins: Optional[NonNegativeInt] = None
    inflight_check_interval_ms: NonNegativeInt = 2_000
    inflight_check_threshold_ms: NonNegativeInt = 5_000
    qsize: PositiveInt = 10_000

So closing this for now unless you discover this continues to occur with the new settings (in which case please re-open).