Orders accepted and not filled in SANDBOX

[HeidXC]

Bug Report

When I test with trade tick and quote in sandbox mode, e.g. a market maker it opened two orders every tick. I observed two issues here:

1. all my orders status were not reported after they are submitted so none of them filled
2. the orders are supposed to send out after a tick but they seems got batched and sent out all at once.

Expected Behavior

Orders filled/rejected after submission according to following trade/quote.
Orders submitted at once without any batch behaviour

Actual Behavior

Orders submission were batched(10 ticks opened 20 orders first submission at 2024-05-27T03:30:48.608281221Z to last submission at 1m2024-05-27T03:30:48.618151288Z) and their status were not reported after submission so none of them filled:

[1m2024-05-27T03:30:48.608281221Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: [CMD]--> SubmitOrder(order=LimitOrder(SELL 515 XXXXXXXX-PERP.BINANCE LIMIT @ 0.16676 GTC, status=INITIALIZED, client_order_id=O-20240527-0330-001-000-1
...........
[1m2024-05-27T03:30:48.618151288Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: [CMD]--> SubmitOrder(order=LimitOrder(SELL 515 xxxxxxxx-PERP.BINANCE LIMIT @ 0.16676 GTC, status=INITIALIZED, client_order_id=O-20240527-0330-001-000-19, venue_order_id=None, position_id=None, tags=None), position_id=None)

[1m2024-05-27T03:30:48.618783463Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=xxxx-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-1, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m
�[1m2024-05-27T03:30:48.618803273Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=xxxxx-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-2, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m
�[1m2024-05-27T03:30:48.618810138Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=xxxx-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-3, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m
�[1m2024-05-27T03:30:48.618815444Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=xxxx-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-4, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m
....
....
�[1m2024-05-27T03:30:48.619189179Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-18, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m
�[1m2024-05-27T03:30:48.619194088Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-19, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m
�[1m2024-05-27T03:30:48.619198760Z�[0m [INFO] TESTER-001.DoubleMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=-PERP.BINANCE, client_order_id=O-20240527-0330-001-000-20, account_id=BINANCE-001, ts_event=1716780648614607627)�[0m

....
�[1m2024-05-27T03:30:55.382429066Z�[0m �[94m[INFO] TESTER-001.ExecClient-BINANCE: Query ClientOrderId('O-20240527-0330-001-000-10')�[0m
�[1m2024-05-27T03:30:55.382792012Z�[0m �[94m[INFO] TESTER-001.ExecClient-BINANCE: Query ClientOrderId('O-20240527-0330-001-000-11')�[0m
...
�[1m2024-05-27T03:30:55.383395831Z�[0m �[1;33m[WARN] TESTER-001.ExecClient-BINANCE: Did not receive OrderStatusReport from request�[0m
�[1m2024-05-27T03:30:55.383404423Z�[0m �[1;33m[WARN] TESTER-001.ExecClient-BINANCE: Did not receive OrderStatusReport from request�[0m
�[1m2024-05-27T03:30:55.383409309Z�[0m �[1;33m[WARN] TESTER-001.ExecClient-BINANCE: Did not receive OrderStatusReport from request�[0m

[cjdsellers]

Hey @VeraLyu

I just need to gather some more information here to know how to investigate.

Did you redact the logs in any way, did you submit orders for an instrument which you had also subscribed to data for?

Could you double check the strategy logic if 10 orders were submitted after one tick, instead of 2?

[HeidXC]

Yes, I cut part of the log to avoid messing up. and yes, I subscribed trade tick and quote for the sym.
I set n_orders to 10 make sure 10 ticks will be executed (just for easier observation of the behavior)

   def check_and_open_position(self):
        if self.n_orders == 0:
            return
        # open position need to be fast
        self.market_long_size = calc_market_size(self.trades_data[self.long_sym], 50, True) 
        self.market_short_size = calc_market_size(self.trades_data[self.short_sym], 50, False)

        self.order_size = min(self.market_long_size, self.market_short_size)

        buy_price = self.long_quote[-1].ask_price.as_decimal() - self.instrument_long.price_increment.as_decimal()
        sell_price = self.short_quote[-1].bid_price.as_decimal() + self.instrument_short.price_increment.as_decimal()

        self.sell(False, sell_price, self.order_size) #bool controls if it is market or limit order
        self.buy(True, buy_price, self.order_size)

def on_trade_tick(self, tick: TradeTick) -> None:
        self.log.info(f'trade tick coming in {tick}')
        instrument_id = tick.instrument_id.value

        self.trades_data[instrument_id].append({
            'price': float(tick.price.as_decimal()),
            'size': float(tick.size.as_decimal()),
            'buyer_mm': tick.aggressor_side == AggressorSide.SELLER,
            'ts_event': tick.ts_event,
        })
        if self.open_period_end:
            self.check_and_close_position()
        
        #TODO: gathering data needs to be start in advance to picking
        elif len(self.trades_data[self.long_sym]) > self.start_calculation_len and len(self.trades_data[self.short_sym]) > self.start_calculation_len:
            self.check_and_open_position()

[HeidXC]

not sure if it is because I used timeForce parameter

order = self.order_factory.limit(
                instrument_id=self.instrument_id,
                order_side=OrderSide.SELL,
                price=Price(price, precision=self.instrument.price_precision),
                quantity=self.instrument.make_qty(quantity),
                time_in_force=TimeInForce.GTC,
            )

[cjdsellers]

I don't think the time in force matters here. Are you able to provide a basic MRE strategy I could run with the Binance sandbox example to help debug this?

[HeidXC]

I don't think the time in force matters here. Are you able to provide a basic MRE strategy I could run with the Binance sandbox example to help debug this?

Thanks a lot, I will try to narrow down myself first to save your time. Besides the batch problem, any idea why most order requests did not receive status report? It continuously queries the orders' status but no response came back.

[1m2024-05-27T03:31:03.389387441Z�[0m �[94m[INFO] TESTER-001.ExecClient-BINANCE: Query ClientOrderId('O-20240527-0330-001-000-9')�[0m
�[1m2024-05-27T03:31:03.389577918Z�[0m �[1;33m[WARN] TESTER-001.ExecClient-BINANCE: Did not receive OrderStatusReport from request

[cjdsellers]

It would be because the live trading node is setup to work with live venues in the first instance.

We're starting to discover how the simulated exchange isn't working entirely to spec as a live venue. So there is no current method which will handle generating an order status report from the simulated exchange.

As for why order accepted events weren't generated - this is what we have to determine next.

[HeidXC]

It would be because the live trading node is setup to work with live venues in the first instance.

We're starting to discover how the simulated exchange isn't working entirely to spec as a live venue. So there is no current method which will handle generating an order status report from the simulated exchange.

As for why order accepted events weren't generated - this is what we have to determine next.

Do you mean it is expected behavior for simulated exchange to not get order status report because we didn't make stub for it (with order fill part still works for sandbox). Or do you suggest after testing with backtest mode I need to switch directly to live instead of using sandbox mode?

[cjdsellers]

The SimulatedExchange has no path for generating an order status report - and it may not make sense to add one either because we already have the order in the cache so know the status. This issue is stemming from OrderAccepted events not being generated, as far as I can guess.

I think its perfectly reasonable you should be able to test with the sandbox after backtesting. I'm still uncertain if this is a regression - or if we're just uncovering additional cases which need handling.

[cjdsellers]

Hey @VeraLyu

This issue is now fixed on develop from cbfc703.

It's a fairly simplistic "internal" config change which means there will be no delay in generating order accepted events, or processing other trading commands when operating in a sandbox mode.

Eventually we're going to want latency more accurately modeled in the sandbox (currently latency to the simulated exchange will be microseconds), but I've resisted the urge to go down that feature expansion track for the moment - I'll create a ticket though.

[HeidXC]

Hey @VeraLyu

This issue is now fixed on develop from cbfc703.

It's a fairly simplistic "internal" config change which means there will be no delay in generating order accepted events, or processing other trading commands when operating in a sandbox mode.

Eventually we're going to want latency more accurately modeled in the sandbox (currently latency to the simulated exchange will be microseconds), but I've resisted the urge to go down that feature expansion track for the moment - I'll create a ticket though.

Thanks a lot! I will test with it later after I finished my current strategy backtest