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.98k stars 453 forks source link

Exception raised during a backtest when the position is flipped from LONG to SHORT #1512

Closed davidsblom closed 6 months ago

davidsblom commented 6 months ago

Bug Report

When running a backtest using a MARGIN account with a NETTING oms type, an exception is raised when the position is flipped from LONG to SHORT. It seems the Quantity is negative, which is odd.

Expected Behavior

No exception. I think the order size is slightly larger than the current long position (but would need to add additional logging to confirm), I would expect a fill order to be executed in this case.

Actual Behavior

The following exception is raised:

  File "nautilus_trader/backtest/engine.pyx", line 914, in nautilus_trader.backtest.engine.BacktestEngine.run
  File "nautilus_trader/backtest/engine.pyx", line 1097, in nautilus_trader.backtest.engine.BacktestEngine._run
  File "nautilus_trader/backtest/exchange.pyx", line 727, in nautilus_trader.backtest.exchange.SimulatedExchange.process_trade_tick
  File "nautilus_trader/backtest/matching_engine.pyx", line 434, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.process_trade_tick
  File "nautilus_trader/backtest/matching_engine.pyx", line 1171, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.iterate
  File "nautilus_trader/execution/matching_core.pyx", line 247, in nautilus_trader.execution.matching_core.MatchingCore.iterate
  File "nautilus_trader/execution/matching_core.pyx", line 274, in nautilus_trader.execution.matching_core.MatchingCore.match_order
  File "nautilus_trader/execution/matching_core.pyx", line 297, in nautilus_trader.execution.matching_core.MatchingCore.match_limit_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 1410, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.fill_limit_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 1448, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.fill_limit_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 1568, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.apply_fills
  File "nautilus_trader/backtest/matching_engine.pyx", line 1684, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.fill_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 2196, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine._generate_order_filled
  File "nautilus_trader/common/component.pyx", line 2510, in nautilus_trader.common.component.MessageBus.send
  File "nautilus_trader/execution/engine.pyx", line 600, in nautilus_trader.execution.engine.ExecutionEngine.process
  File "nautilus_trader/execution/engine.pyx", line 612, in nautilus_trader.execution.engine.ExecutionEngine.process
  File "nautilus_trader/execution/engine.pyx", line 897, in nautilus_trader.execution.engine.ExecutionEngine._handle_event
  File "nautilus_trader/execution/engine.pyx", line 1051, in nautilus_trader.execution.engine.ExecutionEngine._handle_order_fill
  File "nautilus_trader/execution/engine.pyx", line 1145, in nautilus_trader.execution.engine.ExecutionEngine._flip_position
  File "nautilus_trader/model/objects.pyx", line 123, in nautilus_trader.model.objects.Quantity.__init__
ValueError: invalid `value` less than `QUANTITY_MIN` 0.0, was -0.00106

Specifications

cjdsellers commented 6 months ago

Hey @davidsblom

Thanks for the report, I'm wondering if there might be some mismatch here between order quantity precision and instrument size precision. The logic at the beginning of this method is rather simple and quite well tested.

Do you have the risk engine bypassed?

In the mean time I'm adding some more cheap validations into the matching engine to make sure the precisions match.

cjdsellers commented 6 months ago

I've pushed some additional matching engine validations to develop 1aa96a3baed708477005933454abd38d90ff0d58.

Lets see if that turns up some rejects instead of this quantity issue on the position flip.

davidsblom commented 6 months ago

Many thanks! Compiling check latest develop branch. I'll update later here.

davidsblom commented 6 months ago

Just submitted a backtest with version 1.188.0. Will know more by tomorrow.

davidsblom commented 6 months ago

hmm. also failed with 1.188.0. Don't have any warnings in the logs.

This is the stacktrace.

  File "nautilus_trader/backtest/engine.pyx", line 916, in nautilus_trader.backtest.engine.BacktestEngine.run
  File "nautilus_trader/backtest/engine.pyx", line 1093, in nautilus_trader.backtest.engine.BacktestEngine._run
  File "nautilus_trader/backtest/exchange.pyx", line 728, in nautilus_trader.backtest.exchange.SimulatedExchange.process_trade_tick
  File "nautilus_trader/backtest/matching_engine.pyx", line 441, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.process_trade_tick
  File "nautilus_trader/backtest/matching_engine.pyx", line 1227, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.iterate
  File "nautilus_trader/execution/matching_core.pyx", line 247, in nautilus_trader.execution.matching_core.MatchingCore.iterate
  File "nautilus_trader/execution/matching_core.pyx", line 274, in nautilus_trader.execution.matching_core.MatchingCore.match_order
  File "nautilus_trader/execution/matching_core.pyx", line 297, in nautilus_trader.execution.matching_core.MatchingCore.match_limit_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 1466, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.fill_limit_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 1504, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.fill_limit_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 1628, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.apply_fills
  File "nautilus_trader/backtest/matching_engine.pyx", line 1745, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine.fill_order
  File "nautilus_trader/backtest/matching_engine.pyx", line 2257, in nautilus_trader.backtest.matching_engine.OrderMatchingEngine._generate_order_filled
  File "nautilus_trader/common/component.pyx", line 2211, in nautilus_trader.common.component.MessageBus.send
  File "nautilus_trader/execution/engine.pyx", line 600, in nautilus_trader.execution.engine.ExecutionEngine.process
  File "nautilus_trader/execution/engine.pyx", line 612, in nautilus_trader.execution.engine.ExecutionEngine.process
  File "nautilus_trader/execution/engine.pyx", line 897, in nautilus_trader.execution.engine.ExecutionEngine._handle_event
  File "nautilus_trader/execution/engine.pyx", line 1051, in nautilus_trader.execution.engine.ExecutionEngine._handle_order_fill
  File "nautilus_trader/execution/engine.pyx", line 1145, in nautilus_trader.execution.engine.ExecutionEngine._flip_position
  File "nautilus_trader/model/objects.pyx", line 123, in nautilus_trader.model.objects.Quantity.__init__
ValueError: invalid `value` less than `QUANTITY_MIN` 0.0, was -0.00101

These are the last log messages:

2023-09-25T01:17:44.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1882, venue_order_id=BINANCE-1-1882, account_id=BINANCE-001, ts_event=1695604664000000312).
2023-09-25T01:17:44.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=42.57115253 USDT
2023-09-25T01:17:45.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=48.68123476 USDT, free=999_951.04806432 USDT)], margins=[MarginBalance(initial=42.57115253 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=67280da8-fa66-4f90-bc67-6fd30e5dd968).
2023-09-25T01:17:45.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1883, venue_order_id=BINANCE-1-1883, account_id=BINANCE-001, ts_event=1695604664000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderPendingCancel(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1882, venue_order_id=BINANCE-1-1882, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderPendingCancel(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1883, venue_order_id=BINANCE-1-1883, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1884, side=BUY, type=LIMIT, quantity=0.01424, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '1584.09', 'display_qty': None, '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=None).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1884, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1885, side=SELL, type=LIMIT, quantity=0.01262, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '1585.05', 'display_qty': None, '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=None).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1885, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=20.00720544 USDT
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=26.11728767 USDT, free=999_973.61201141 USDT)], margins=[MarginBalance(initial=20.00720544 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=96dc17c5-c296-4f06-8c7d-2f6681046e74).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderCanceled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1882, venue_order_id=BINANCE-1-1882, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=0.00000000 USDT
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=6.11008223 USDT, free=999_993.61921685 USDT)], margins=[MarginBalance(initial=0.00000000 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=8b68d85c-bb7c-48ad-9dd3-2f227416ac09).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderCanceled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1883, venue_order_id=BINANCE-1-1883, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=22.56195309 USDT
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=28.67203532 USDT, free=999_971.05726376 USDT)], margins=[MarginBalance(initial=22.56195309 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=118b1792-ef08-4f93-aed3-e6180053bbc4).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1884, venue_order_id=BINANCE-1-1884, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:17:55.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=42.56928476 USDT
2023-09-25T01:17:56.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=48.67936699 USDT, free=999_951.04993209 USDT)], margins=[MarginBalance(initial=42.56928476 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=d4732a52-e070-4e8f-ba1b-a72958a4c137).
2023-09-25T01:17:56.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1885, venue_order_id=BINANCE-1-1885, account_id=BINANCE-001, ts_event=1695604675000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderPendingCancel(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1884, venue_order_id=BINANCE-1-1884, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderPendingCancel(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1885, venue_order_id=BINANCE-1-1885, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1886, side=BUY, type=LIMIT, quantity=0.01424, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '1583.86', 'display_qty': None, '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=None).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1886, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1887, side=SELL, type=LIMIT, quantity=0.01262, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '1584.98', 'display_qty': None, '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=None).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1887, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=20.00733167 USDT
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=26.11741390 USDT, free=999_973.61188518 USDT)], margins=[MarginBalance(initial=20.00733167 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=77aa8a13-49a2-419a-88bf-a8e8cb67c45f).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderCanceled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1884, venue_order_id=BINANCE-1-1884, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=0.00000000 USDT
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=6.11008223 USDT, free=999_993.61921685 USDT)], margins=[MarginBalance(initial=0.00000000 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=4ef76473-e163-43a9-b1a6-bf0dba28d402).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderCanceled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0117-001-000-1885, venue_order_id=BINANCE-1-1885, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=22.55867723 USDT
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=28.66875946 USDT, free=999_971.06053962 USDT)], margins=[MarginBalance(initial=22.55867723 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=41452f84-85f9-4153-b42b-1d40f761a67b).
2023-09-25T01:18:05.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1886, venue_order_id=BINANCE-1-1886, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:06.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=42.56512532 USDT
2023-09-25T01:18:06.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=48.67520755 USDT, free=999_951.05409153 USDT)], margins=[MarginBalance(initial=42.56512532 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=0e155271-2de1-42f6-97c8-9eeaf095f493).
2023-09-25T01:18:06.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1887, venue_order_id=BINANCE-1-1887, account_id=BINANCE-001, ts_event=1695604685000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderPendingCancel(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1886, venue_order_id=BINANCE-1-1886, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderPendingCancel(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1887, venue_order_id=BINANCE-1-1887, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1888, side=BUY, type=LIMIT, quantity=0.01424, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '1583.88', 'display_qty': None, '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=None).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1888, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1889, side=SELL, type=LIMIT, quantity=0.01262, time_in_force=GTC, post_only=False, reduce_only=False, quote_quantity=False, options={'price': '1584.68', 'display_qty': None, '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=None).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderSubmitted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1889, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=20.00644809 USDT
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=26.11653032 USDT, free=999_973.61276876 USDT)], margins=[MarginBalance(initial=20.00644809 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=d39e28ad-f7f8-4e01-9a14-cc16ed6c5fc8).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderCanceled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1886, venue_order_id=BINANCE-1-1886, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=0.00000000 USDT
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=6.11008223 USDT, free=999_993.61921685 USDT)], margins=[MarginBalance(initial=0.00000000 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=c4b97d45-0e6b-4a30-8460-546883bb8994).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderCanceled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1887, venue_order_id=BINANCE-1-1887, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=22.55896209 USDT
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=28.66904432 USDT, free=999_971.06025476 USDT)], margins=[MarginBalance(initial=22.55896209 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=193d6153-835a-419a-9ec9-9218cda19282).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1888, venue_order_id=BINANCE-1-1888, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:10.000000312Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=42.56162342 USDT
2023-09-25T01:18:11.000000312Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72929908 USDT, locked=48.67170565 USDT, free=999_951.05759343 USDT)], margins=[MarginBalance(initial=42.56162342 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=43e539bd-8319-46e5-b217-c013e70f3586).
2023-09-25T01:18:11.000000312Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderAccepted(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1889, venue_order_id=BINANCE-1-1889, account_id=BINANCE-001, ts_event=1695604690000000312).
2023-09-25T01:18:11.488000000Z [INFO] TRADER-000.Portfolio: ETHUSDT.BINANCE margin_init=42.56162342 USDT
2023-09-25T01:18:11.488000000Z [INFO] TRADER-000.Portfolio: Updated AccountState(account_id=BINANCE-001, account_type=MARGIN, base_currency=None, is_reported=False, balances=[AccountBalance(total=999_999.72239625 USDT, locked=48.67170565 USDT, free=999_951.05069060 USDT)], margins=[MarginBalance(initial=42.56162342 USDT, maintenance=6.11008223 USDT, instrument_id=ETHUSDT.BINANCE)], event_id=12f0a5d8-a9ff-4b52-a43f-d9d4b7b28313).
2023-09-25T01:18:11.488000000Z [INFO] TRADER-000.ReinforcementLearningMarketMakerStrategy: <--[EVT] OrderFilled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1889, venue_order_id=BINANCE-1-1889, account_id=BINANCE-001, trade_id=BINANCE-1-179, position_id=ETHUSDT.BINANCE-ReinforcementLearningMarketMakerStrategy-000, order_side=SELL, order_type=LIMIT, last_qty=0.01, last_px=1584.68 USDT, commission=0.00183823 USDT, liquidity_side=MAKER, ts_event=1695604691488000000).
cjdsellers commented 6 months ago

Thanks @davidsblom

This rules out a precision mismatch then at least.

cjdsellers commented 6 months ago

Having said that, looks like there's a difference in the precisions:

 OrderInitialized(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1889, side=SELL, type=LIMIT, quantity=0.01262

Precision is 5

vs

OrderFilled(instrument_id=ETHUSDT.BINANCE, client_order_id=O-20230925-0118-001-000-1889, venue_order_id=BINANCE-1-1889, account_id=BINANCE-001, trade_id=BINANCE-1-179, position_id=ETHUSDT.BINANCE-ReinforcementLearningMarketMakerStrategy-000, order_side=SELL, order_type=LIMIT, last_qty=0.01

Precision is 2 for some reason?

We just need to figure out how/where this can happen.

davidsblom commented 6 months ago

Interesting. I'm using quote ticks and trade ticks for the backtest. Are the fills triggered by the trade ticks?

cjdsellers commented 6 months ago

I can't see enough of the logs or know enough about your data to say for sure, but fills can be triggered by either.

Are you consistently using the same instrument for the data? It looks like the size precision for ETHUSDT should be 4 for spot, and 3 for futures?

davidsblom commented 6 months ago

Browsing through the logs I see fills with precision 2 and 5, which is really strange. Closing the issue for now, it is probably related to my setup somehow.

davidsblom commented 6 months ago

@cjdsellers Thanks for your help! Much appreciated

cjdsellers commented 6 months ago

Thanks @davidsblom

Although its not just your setup, you've exposed a loophole here where data can have a different precision to what the instrument defines for execution.

I'm determining where the best place is to validate this right now, likely in the matching engine for each fill (these are very cheap int comparisons).

cjdsellers commented 6 months ago

I think I know what it might be there, do you have different size precisions for quote ticks vs trade ticks?

davidsblom commented 6 months ago

Checking

davidsblom commented 6 months ago

just started the debugger, trade ticks and quote ticks seem to be of precision 5 after reading the data from the catalog.

(Pdb) quote_ticks[0]
QuoteTick(ETHUSDT.BINANCE,1924.50,1924.51,30.81650,10.14810,1688256000071267729)
(Pdb) trade_ticks[0]
TradeTick(ETHUSDT.BINANCE,1913.80,0.05270,SELLER,d66047d5765e46c280967d3585319443,1688270159992999936)
(Pdb) trade_ticks[-1]
TradeTick(ETHUSDT.BINANCE,1937.49,0.02350,BUYER,4c49b4c9b0a0484cbdcc5add0e8a7079,1688342400000000000)
(Pdb) trade_ticks[-1].size
Quantity('0.02350')
(Pdb) trade_ticks[-1].size.precision
5
(Pdb) quote_ticks[-1].size.precision
*** AttributeError: 'nautilus_trader.model.data.QuoteTick' object has no attribute 'size'
(Pdb) quote_ticks[-1].bid_size.precision
5
(Pdb) quote_ticks[-1].ask_size.precision
5
(Pdb
cjdsellers commented 6 months ago

OK thanks for the info.

cjdsellers commented 6 months ago

Can you see from your logs the first instance of where a size precision has become 2?

davidsblom commented 6 months ago

Let me know how I can help. I can do some further digging later.

cjdsellers commented 6 months ago

Hey @davidsblom

I've added some additional validations into the matching engine, so now instead of the position flip issue you should see a runtime error like this (in this case its a price precision but we also validate the size precision):

RuntimeError: Invalid price precision for fill 1 when instrument price precision is 2. Check that the data price precision matches the 1.166811431-19248890-None.BETFAIR instrument.

I had a good look through all of the flows and couldn't find any bugs, so at this point seems like a mismatch between data and instrument precisions.

davidsblom commented 6 months ago

Great! Thanks for the update. I'll give it another try later.

davidsblom commented 6 months ago

Quick update, this issue is most probably indeed dataset dependent. For local debugging, I've regenerated the catalog which doesn't have the mentioned issue with different precisions. So probably discard my latest comment. Would need to download the catalog from Azure to confirm the actual precisions.

davidsblom commented 6 months ago

Confirming that I now run into the following error (as expected).

RuntimeError: Invalid size precision for fill 2 when instrument size precision is 5. Check that the data size precision matches the ETHUSDT.BINANCE instrument.

this catalog was generated with an older version of NT, so apparently there has been a fix for this already to solve the cause of the problem.