Repeatedly "Sending order ((Order ID:230) Type best for _ROLL_PSEUDO_STRATEGY/......"

[oldlore]

Repeatedly "Sending order ((Order ID:230) Type best for _ROLL_PSEUDO_STRATEGY/......"

[oldlore]

Same thing today trying to force roll NIKKEI

2023-09-05 00:09:19 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-09-05 00:09:31 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-09-05 00:09:44 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-09-05 00:09:57 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-09-05 00:10:10 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-09-05 00:10:22 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest
2023-09-05 00:10:35 DEBUG stack_handler {'strategy_name': '_ROLL_PSEUDO_STRATEGY', 'instrument_code': 'NIKKEI', 'contract_order_id': 231, 'instrument_o
rder_id': 237} Sending order (Order ID:231) Type best for _ROLL_PSEUDO_STRATEGY/NIKKEI/20230900_20231200, qty [-1, 1], fill [0, 0]@ price, None Parent:
237 Children:no_children to algo sysexecution.algos.algo_original_best.algoOriginalBest

I had another Force roll for US5 and it just executed a few minutes ago. Not sure why NIKKEI failed today and GAS_US_mini failed last week.

[robcarver17]

Could be connected to #1200

[robcarver17]

I don't use FORCE much nowadays, but as a test I just executed the roll in VIX as a FORCE and it worked fine....

OK so looking at the code:

        log.debug(
            "Sending order %s to algo %s"
            % (
                str(contract_order_to_trade_with_algo_set),
                contract_order_to_trade_with_algo_set.algo_to_use,
            )
        )

        algo_class_to_call = self.add_controlling_algo_to_order(
            contract_order_to_trade_with_algo_set
        )
        algo_instance = algo_class_to_call(
            self.data, contract_order_to_trade_with_algo_set
        )

        # THIS LINE ACTUALLY SENDS THE ORDER TO THE ALGO
        placed_broker_order_with_controls = algo_instance.submit_trade()

        if placed_broker_order_with_controls is missing_order:
            # important we do this or order will never execute
            #  if no issue here will be released once order filled
            self.contract_stack.release_order_from_algo_control(
                contract_order_to_trade_with_algo_set.order_id
            )
            return missing_order

It looks like a slient failure (no log made) inside algo_instance.submit_trade()

In turn that must come from prepare_and_submit_trade() within algo_original_best:

placed_broker_order_with_controls = self.prepare_and_submit_trade()
        if placed_broker_order_with_controls is missing_order:
            return missing_order

Looking at that:

        ## check order type is 'best' not 'limit' or 'market'
        if not contract_order.order_type == best_order_type: ### NOT A SILENT FAILURE
            log.critical(
                "Order has been allocated to algo 'original-best' but order type is %s"
                % str(contract_order.order_type)
            )
            return missing_order

        cut_down_contract_order = (
            contract_order.reduce_trade_size_proportionally_so_smallest_leg_is_max_size(
                SIZE_LIMIT
            )
        )
        if cut_down_contract_order.trade != contract_order.trade:
           ### NOT SILENT
            log.debug(
                "Cut down order to size %s from %s because of algo size limit"
                % (str(contract_order.trade), str(cut_down_contract_order.trade))
            )

        ticker_object = self.data_broker.get_ticker_object_for_order(
            cut_down_contract_order
        )
        try:
            okay_to_do_limit_trade = limit_trade_viable(
                ticker_object=ticker_object,
                data=data,
                order=cut_down_contract_order,
                log=log,
            )
        except missingData:
           ### COULD BE HERE SILENT
            ## Safer not to trade at all
            return missing_order

        if okay_to_do_limit_trade:

            # create and issue limit order
            broker_order_with_controls = (
                self.get_and_submit_broker_order_for_contract_order(
                    cut_down_contract_order,
                    order_type=limit_order_type,
                    limit_price_from=limit_price_from_offside_price,
                    ticker_object=ticker_object,
                )
            )
        else:
            # do a market order
            ### NOT SILENT
            log.debug(
                "Conditions are wrong so doing market trade instead of limit trade"
            )
           ## COULD RETURN missingorder
            broker_order_with_controls = (
                self.get_and_submit_broker_order_for_contract_order(
                    cut_down_contract_order, order_type=market_order_type
                )
            )

        return broker_order_with_controls

We will get a silent failure if limit_trade_viable raises missingData, or inside get_and_submit_broker_order_for_contract_order.

Consider first limit_trade_viable:

    raise_adverse_size_issue = adverse_size_issue(
        ticker_object, wait_for_valid_tick=True, log=log
    )

    if raise_adverse_size_issue:
        log.debug("Limit trade not viable")
        return False

    # or if not enough time left
    if is_market_about_to_close(data, order=order, log=log):

        log.debug(
            "Market about to close or stack handler nearly close - doing market order"
        )
        return False

But nothing inside those raises missingData (so we could argue that try/except isn't needed?!)

So inside get_and_submit_broker_order_for_contract_order we have:

        try:
            collected_prices = self.get_market_data_for_order_modifies_ticker_object(
                ticker_object, contract_order
            )
        except missingData:
            # no data available, no can do
            return missing_order

OK, get_market_data_for_order_modifies_ticker_object:

        try:
            reference_tick = (
                ticker_object.wait_for_valid_bid_and_ask_and_return_current_tick(
                    wait_time_seconds=10
                )
            )
        except missingData:
            log.warning(
                "Can't get market data for %s so not trading with limit order %s"
                % (contract_order.instrument_code, str(contract_order))
            )
            raise

... but that doesn't fail silently?!

[tgibson11]

FWIW, I don't think this is any kind of silent failure.

I think the order is submitted to IB. IB cancels the order (for whatever reason). Stack handler sees that the DB broker order doesn't have any more matching order at IB, so releases it from the algo. But there was never a fill, so the contract order remains...next time around another broker order is submitted. Repeat.

I looked at this code a few weeks ago...I can point you to the precise logic if necessary...just not off the top of my head while I'm eating breakfast.

[tgibson11]

The behavior of resubmitting the order is not obviously wrong to me...maybe it could be improved, but it's an unexpected situation, and the desired behavior would depend a lot on why the order was canceled...

And that, to me, is the more interesting question...what is it specifically about these orders that IB doesn't like?

[robcarver17]

The behavior of resubmitting the order is not obviously wrong to me...maybe it could be improved, but it's an unexpected situation, and the desired behavior would depend a lot on why the order was canceled...

And that, to me, is the more interesting question...what is it specifically about these orders that IB doesn't like?

... my gut feeling is it doesn't like spread orders in certain markets but would be good to know which ones!