Closed SeverinJB closed 2 years ago
The issue occurred because the alpaca_trade_executor had updates in __trade_updates which were received from the latest short sell (i.e. exiting of a position). As the trades_manager only collects trade updates if there is a pending order, those updates related to exiting a previous position were collected when an order was placed for entering a new position. As a consequence, the positons_manager received the false notification that the pending order was already filled and updated the books accordingly. Ultimately, that allowed the strategy to send an exit signal for a non-existing position.
2022-09-23 18:18:50,262:positions_manager.py:17:INFO:root:order update: fill = {'asset_class': 'us_equity', 'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415', 'cancel_requested_at': None, 'canceled_at': None, 'client_order_id': '7bc398e9-f4ec-412d-8acc-051be9aefb15', 'created_at': '2022-09-23T12:18:01.733834228-04:00', 'expired_at': None, 'extended_hours': False, 'failed_at': None, 'filled_at': '2022-09-23T16:18:49.661147004Z', 'filled_avg_price': '150.15', 'filled_qty': '6', 'hwm': None, 'id': 'df75ad89-2c71-43ff-815f-f32329b0227f', 'legs': None, 'limit_price': '150.15', 'notional': None, 'order_class': '', 'order_type': 'limit', 'qty': '6', 'replaced_at': None, 'replaced_by': None, 'replaces': None, 'side': 'buy', 'status': 'filled', 'stop_price': None, 'submitted_at': '2022-09-23T12:18:01.733290508-04:00', 'symbol': 'AAPL', 'time_in_force': 'day', 'trail_percent': None, 'trail_price': None, 'type': 'limit', 'updated_at': '2022-09-23T12:18:49.663394886-04:00'}
2022-09-23 18:18:50,262:positions_manager.py:84:INFO:root:Open position: <trade_objects.Position object at 0x113e085f8>
2022-09-23 18:18:50,375:strategy_scalping.py:60:INFO:root:exit position
2022-09-23 18:18:50,635:alpaca_trade_executor.py:47:INFO:root:submitted order AAPL
2022-09-23 18:18:51,054:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'new',
'execution_id': '7a097679-b7b8-45bc-a85f-b10fb8209636',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': 'eb6568ec-a4a2-428f-9cfb-b3c843511f01',
'created_at': '2022-09-23T12:18:50.7466797-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': None,
'filled_avg_price': None,
'filled_qty': '0',
'hwm': None,
'id': '60305925-6276-4cda-8fee-172a1fa61216',
'legs': None,
'limit_price': '150.16',
'notional': None,
'order_class': '',
'order_type': 'limit',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'sell',
'status': 'new',
'stop_price': None,
'submitted_at': '2022-09-23T12:18:50.74616515-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'limit',
'updated_at': '2022-09-23T12:18:50.75298925-04:00'},
'timestamp': '2022-09-23T16:18:50.751412131Z'})
2022-09-23 18:19:00,774:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:18:00, close: 150.14, len(database[AAPL]): 32
2022-09-23 18:19:00,778:strategy_scalping.py:41:INFO:root:closes[-2:] = [150.15 150.14], mavg[-2:] = [150.12 150.11095238]
2022-09-23 18:19:01,894:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'fill',
'execution_id': 'c0e57fdf-2067-4819-b55e-bc8f1cdb7c73',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': 'eb6568ec-a4a2-428f-9cfb-b3c843511f01',
'created_at': '2022-09-23T12:18:50.7466797-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': '2022-09-23T16:19:01.259481011Z',
'filled_avg_price': '150.16',
'filled_qty': '6',
'hwm': None,
'id': '60305925-6276-4cda-8fee-172a1fa61216',
'legs': None,
'limit_price': '150.16',
'notional': None,
'order_class': '',
'order_type': 'limit',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'sell',
'status': 'filled',
'stop_price': None,
'submitted_at': '2022-09-23T12:18:50.74616515-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'limit',
'updated_at': '2022-09-23T12:19:01.262034796-04:00'},
'position_qty': '0',
'price': '150.16',
'qty': '6',
'timestamp': '2022-09-23T16:19:01.259481011Z'})
2022-09-23 18:20:00,435:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:19:00, close: 150.1, len(database[AAPL]): 33
[...]
2022-09-23 18:37:00,396:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:36:00, close: 149.8, len(database[AAPL]): 50
2022-09-23 18:37:00,402:strategy_scalping.py:36:INFO:root:buy signal: closes[-2] 149.74 < mavg[-2] 149.8114285714285 closes[-1] 149.8 > mavg[-1] 149.79999999999995
2022-09-23 18:37:00,950:positions_manager.py:100:INFO:root:Open pending order: <trade_objects.Order object at 0x113d43940>
2022-09-23 18:37:01,519:alpaca_trade_executor.py:47:INFO:root:submitted order AAPL
2022-09-23 18:37:01,521:positions_manager.py:17:INFO:root:order update: new = {'asset_class': 'us_equity', 'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415', 'cancel_requested_at': None, 'canceled_at': None, 'client_order_id': 'eb6568ec-a4a2-428f-9cfb-b3c843511f01', 'created_at': '2022-09-23T12:18:50.7466797-04:00', 'expired_at': None, 'extended_hours': False, 'failed_at': None, 'filled_at': None, 'filled_avg_price': None, 'filled_qty': '0', 'hwm': None, 'id': '60305925-6276-4cda-8fee-172a1fa61216', 'legs': None, 'limit_price': '150.16', 'notional': None, 'order_class': '', 'order_type': 'limit', 'qty': '6', 'replaced_at': None, 'replaced_by': None, 'replaces': None, 'side': 'sell', 'status': 'new', 'stop_price': None, 'submitted_at': '2022-09-23T12:18:50.74616515-04:00', 'symbol': 'AAPL', 'time_in_force': 'day', 'trail_percent': None, 'trail_price': None, 'type': 'limit', 'updated_at': '2022-09-23T12:18:50.75298925-04:00'}
2022-09-23 18:37:01,521:positions_manager.py:41:WARNING:root:Unexpected event: new for {'asset_class': 'us_equity', 'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415', 'cancel_requested_at': None, 'canceled_at': None, 'client_order_id': 'eb6568ec-a4a2-428f-9cfb-b3c843511f01', 'created_at': '2022-09-23T12:18:50.7466797-04:00', 'expired_at': None, 'extended_hours': False, 'failed_at': None, 'filled_at': None, 'filled_avg_price': None, 'filled_qty': '0', 'hwm': None, 'id': '60305925-6276-4cda-8fee-172a1fa61216', 'legs': None, 'limit_price': '150.16', 'notional': None, 'order_class': '', 'order_type': 'limit', 'qty': '6', 'replaced_at': None, 'replaced_by': None, 'replaces': None, 'side': 'sell', 'status': 'new', 'stop_price': None, 'submitted_at': '2022-09-23T12:18:50.74616515-04:00', 'symbol': 'AAPL', 'time_in_force': 'day', 'trail_percent': None, 'trail_price': None, 'type': 'limit', 'updated_at': '2022-09-23T12:18:50.75298925-04:00'}
2022-09-23 18:37:01,521:positions_manager.py:17:INFO:root:order update: fill = {'asset_class': 'us_equity', 'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415', 'cancel_requested_at': None, 'canceled_at': None, 'client_order_id': 'eb6568ec-a4a2-428f-9cfb-b3c843511f01', 'created_at': '2022-09-23T12:18:50.7466797-04:00', 'expired_at': None, 'extended_hours': False, 'failed_at': None, 'filled_at': '2022-09-23T16:19:01.259481011Z', 'filled_avg_price': '150.16', 'filled_qty': '6', 'hwm': None, 'id': '60305925-6276-4cda-8fee-172a1fa61216', 'legs': None, 'limit_price': '150.16', 'notional': None, 'order_class': '', 'order_type': 'limit', 'qty': '6', 'replaced_at': None, 'replaced_by': None, 'replaces': None, 'side': 'sell', 'status': 'filled', 'stop_price': None, 'submitted_at': '2022-09-23T12:18:50.74616515-04:00', 'symbol': 'AAPL', 'time_in_force': 'day', 'trail_percent': None, 'trail_price': None, 'type': 'limit', 'updated_at': '2022-09-23T12:19:01.262034796-04:00'}
2022-09-23 18:37:01,521:positions_manager.py:84:INFO:root:Open position: <trade_objects.Position object at 0x113d43d68>
2022-09-23 18:37:01,527:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'new',
'execution_id': '220067e9-ff82-42e3-ae88-67a32e4e6a74',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': 'd08dc492-a8d4-4f30-aac0-897b09cb6000',
'created_at': '2022-09-23T12:37:01.601717189-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': None,
'filled_avg_price': None,
'filled_qty': '0',
'hwm': None,
'id': '56fd6db0-edff-4bc6-86d4-29fe05474605',
'legs': None,
'limit_price': '149.8',
'notional': None,
'order_class': '',
'order_type': 'limit',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'buy',
'status': 'new',
'stop_price': None,
'submitted_at': '2022-09-23T12:37:01.601171659-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'limit',
'updated_at': '2022-09-23T12:37:01.608423309-04:00'},
'timestamp': '2022-09-23T16:37:01.606997802Z'})
2022-09-23 18:37:01,651:strategy_scalping.py:60:INFO:root:exit position
2022-09-23 18:37:01,777:alpaca_trade_executor.py:51:INFO:root:cannot open a short sell while a long buy order is open
2022-09-23 18:37:01,813:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'fill',
'execution_id': '7636fcba-2b65-4b9d-9f98-133fd695a059',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': 'd08dc492-a8d4-4f30-aac0-897b09cb6000',
'created_at': '2022-09-23T12:37:01.601717189-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': '2022-09-23T16:37:01.879569206Z',
'filled_avg_price': '149.78',
'filled_qty': '6',
'hwm': None,
'id': '56fd6db0-edff-4bc6-86d4-29fe05474605',
'legs': None,
'limit_price': '149.8',
'notional': None,
'order_class': '',
'order_type': 'limit',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'buy',
'status': 'filled',
'stop_price': None,
'submitted_at': '2022-09-23T12:37:01.601171659-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'limit',
'updated_at': '2022-09-23T12:37:01.894041754-04:00'},
'position_qty': '6',
'price': '149.78',
'qty': '6',
'timestamp': '2022-09-23T16:37:01.879569206Z'})
2022-09-23 18:37:01,900:strategy_scalping.py:60:INFO:root:exit position
2022-09-23 18:37:02,022:alpaca_trade_executor.py:47:INFO:root:submitted order AAPL
2022-09-23 18:37:02,099:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'new',
'execution_id': 'd19e71b0-0269-4e81-875e-a823d5148de8',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': '8ad64cc0-0573-42d6-8660-efbefa17e76a',
'created_at': '2022-09-23T12:37:02.105905162-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': None,
'filled_avg_price': None,
'filled_qty': '0',
'hwm': None,
'id': 'da4cb1d8-fe1e-4d3e-aded-e335a648ceb2',
'legs': None,
'limit_price': '150.17',
'notional': None,
'order_class': '',
'order_type': 'limit',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'sell',
'status': 'new',
'stop_price': None,
'submitted_at': '2022-09-23T12:37:02.105254622-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'limit',
'updated_at': '2022-09-23T12:37:02.112921562-04:00'},
'timestamp': '2022-09-23T16:37:02.111306586Z'})
2022-09-23 18:38:00,394:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:37:00, close: 149.82, len(database[AAPL]): 51
2022-09-23 18:38:00,401:strategy_scalping.py:41:INFO:root:closes[-2:] = [149.8 149.82], mavg[-2:] = [149.8 149.78904762]
2022-09-23 18:39:00,813:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:38:00, close: 150.08, len(database[AAPL]): 52
2022-09-23 18:39:00,818:strategy_scalping.py:41:INFO:root:closes[-2:] = [149.82 150.08], mavg[-2:] = [149.78904762 149.78571429]
2022-09-23 18:40:01,148:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:39:00, close: 149.995, len(database[AAPL]): 53
2022-09-23 18:40:01,154:strategy_scalping.py:41:INFO:root:closes[-2:] = [150.08 149.995], mavg[-2:] = [149.78571429 149.77880952]
2022-09-23 18:40:34,678:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'canceled',
'execution_id': 'd6b03cd5-1674-443e-9058-6115d964f65b',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': '2022-09-23T12:40:34.502650053-04:00',
'canceled_at': '2022-09-23T16:40:34.506747818Z',
'client_order_id': '8ad64cc0-0573-42d6-8660-efbefa17e76a',
'created_at': '2022-09-23T12:37:02.105905162-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': None,
'filled_avg_price': None,
'filled_qty': '0',
'hwm': None,
'id': 'da4cb1d8-fe1e-4d3e-aded-e335a648ceb2',
'legs': None,
'limit_price': '150.17',
'notional': None,
'order_class': '',
'order_type': 'limit',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'sell',
'status': 'canceled',
'stop_price': None,
'submitted_at': '2022-09-23T12:37:02.105254622-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'limit',
'updated_at': '2022-09-23T12:40:34.509025183-04:00'},
'timestamp': '2022-09-23T16:40:34.506747818Z'})
2022-09-23 18:40:37,232:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'new',
'execution_id': 'a37e1540-99d0-481c-8305-7c136fef9fa6',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': 'e81f6729-ba88-41ac-b759-df194b1e4a60',
'created_at': '2022-09-23T12:40:37.131597848-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': None,
'filled_avg_price': None,
'filled_qty': '0',
'hwm': None,
'id': '97b1fedb-4cfc-47a9-9f78-806072be5e27',
'legs': None,
'limit_price': None,
'notional': None,
'order_class': '',
'order_type': 'market',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'sell',
'status': 'new',
'stop_price': None,
'submitted_at': '2022-09-23T12:40:37.131243957-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'market',
'updated_at': '2022-09-23T12:40:37.137941537-04:00'},
'timestamp': '2022-09-23T16:40:37.136707095Z'})
2022-09-23 18:40:37,430:alpaca_trade_executor.py:66:INFO:root:trade_updates Entity({ 'event': 'fill',
'execution_id': 'f1c6f40a-cfa2-4560-b8dc-6dcdffaf69c6',
'order': { 'asset_class': 'us_equity',
'asset_id': 'b0b6dd9d-8b9b-48a9-ba46-b9d54906e415',
'cancel_requested_at': None,
'canceled_at': None,
'client_order_id': 'e81f6729-ba88-41ac-b759-df194b1e4a60',
'created_at': '2022-09-23T12:40:37.131597848-04:00',
'expired_at': None,
'extended_hours': False,
'failed_at': None,
'filled_at': '2022-09-23T16:40:37.259206428Z',
'filled_avg_price': '149.9',
'filled_qty': '6',
'hwm': None,
'id': '97b1fedb-4cfc-47a9-9f78-806072be5e27',
'legs': None,
'limit_price': None,
'notional': None,
'order_class': '',
'order_type': 'market',
'qty': '6',
'replaced_at': None,
'replaced_by': None,
'replaces': None,
'side': 'sell',
'status': 'filled',
'stop_price': None,
'submitted_at': '2022-09-23T12:40:37.131243957-04:00',
'symbol': 'AAPL',
'time_in_force': 'day',
'trail_percent': None,
'trail_price': None,
'type': 'market',
'updated_at': '2022-09-23T12:40:37.261861026-04:00'},
'position_qty': '0',
'price': '149.9',
'qty': '6',
'timestamp': '2022-09-23T16:40:37.259206428Z'})
2022-09-23 18:41:01,538:alpaca_data_source.py:63:INFO:root:New bar: 2022-09-23 16:40:00, close: 149.95, len(database[AAPL]): 54
Three issues related to the above book keeping issue:
All changes implemented in subtasks - see linked issues.
From the logs, it appears that yuzu attempted to open a short sell (i.e. exit a position) while the order was still pending.
Tasks
_Improve robustness of trade_manager / positionmanager to prevent reoccurrence