From 7f3e7d27409fd7355db9ae4f8fe9a346cd50c712 Mon Sep 17 00:00:00 2001 From: =?utf8?q?Isma=C3=ABl=20Bouya?= Date: Sun, 25 Mar 2018 19:09:05 +0200 Subject: [PATCH] Handle timeouts for order creations --- portfolio.py | 79 +++++++- test.py | 501 +++++++++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 572 insertions(+), 8 deletions(-) diff --git a/portfolio.py b/portfolio.py index 69e3755..9c58676 100644 --- a/portfolio.py +++ b/portfolio.py @@ -1,9 +1,7 @@ from datetime import datetime -from decimal import Decimal as D, ROUND_DOWN -from ccxt import ExchangeError, InsufficientFunds, ExchangeNotAvailable, InvalidOrder, OrderNotCached, OrderNotFound from retry import retry - -# FIXME: correctly handle web call timeouts +from decimal import Decimal as D, ROUND_DOWN +from ccxt import ExchangeError, InsufficientFunds, ExchangeNotAvailable, InvalidOrder, OrderNotCached, OrderNotFound, RequestTimeout class Computation: computations = { @@ -414,6 +412,9 @@ class Trade: for mouvement in order.mouvements: self.market.report.print_log("{}\t\t{}".format(ind, mouvement)) +class RetryException(Exception): + pass + class Order: def __init__(self, action, amount, rate, base_currency, trade_type, market, trade, close_if_possible=False): @@ -430,6 +431,7 @@ class Order: self.close_if_possible = close_if_possible self.id = None self.tries = 0 + self.start_date = None def as_json(self): return { @@ -475,18 +477,18 @@ class Order: def finished(self): return self.status.startswith("closed") or self.status == "canceled" or self.status == "error" - @retry(InsufficientFunds) + @retry((InsufficientFunds, RetryException)) def run(self): self.tries += 1 symbol = "{}/{}".format(self.amount.currency, self.base_currency) amount = round(self.amount, self.market.ccxt.order_precision(symbol)).value + action = "market.ccxt.create_order('{}', 'limit', '{}', {}, price={}, account={})".format(symbol, self.action, amount, self.rate, self.account) if self.market.debug: - self.market.report.log_debug_action("market.ccxt.create_order('{}', 'limit', '{}', {}, price={}, account={})".format( - symbol, self.action, amount, self.rate, self.account)) + self.market.report.log_debug_action(action) self.results.append({"debug": True, "id": -1}) else: - action = "market.ccxt.create_order('{}', 'limit', '{}', {}, price={}, account={})".format(symbol, self.action, amount, self.rate, self.account) + self.start_date = datetime.now() try: self.results.append(self.market.ccxt.create_order(symbol, 'limit', self.action, amount, price=self.rate, account=self.account)) except InvalidOrder: @@ -494,6 +496,19 @@ class Order: self.status = "closed" self.mark_finished_order() return + except RequestTimeout as e: + if not self.retrieve_order(): + if self.tries < 5: + self.market.report.log_error(action, message="Retrying after timeout", exception=e) + # We make a specific call in case retrieve_order + # would raise itself + raise RetryException + else: + self.market.report.log_error(action, message="Giving up {} after timeouts".format(self), exception=e) + self.status = "error" + return + else: + self.market.report.log_error(action, message="Timeout, found the order") except InsufficientFunds as e: if self.tries < 5: self.market.report.log_error(action, message="Retrying with reduced amount", exception=e) @@ -585,6 +600,54 @@ class Order: self.market.report.log_error("cancel_order", message="Already cancelled order", exception=e) self.fetch() + def retrieve_order(self): + symbol = "{}/{}".format(self.amount.currency, self.base_currency) + amount = round(self.amount, self.market.ccxt.order_precision(symbol)).value + start_timestamp = self.start_date.timestamp() - 5 + + similar_open_orders = self.market.ccxt.fetch_orders(symbol=symbol, since=start_timestamp) + for order in similar_open_orders: + if (order["info"]["margin"] == 1 and self.account == "exchange") or\ + (order["info"]["margin"] != 1 and self.account == "margin"): + i_m_tested = True # coverage bug ?! + continue + if order["info"]["side"] != self.action: + continue + amount_diff = round( + abs(D(order["info"]["startingAmount"]) - amount), + self.market.ccxt.order_precision(symbol)) + rate_diff = round( + abs(D(order["info"]["rate"]) - self.rate), + self.market.ccxt.order_precision(symbol)) + if amount_diff != 0 or rate_diff != 0: + continue + self.results.append({"id": order["id"]}) + return True + + similar_trades = self.market.ccxt.fetch_my_trades(symbol=symbol, since=start_timestamp) + # FIXME: use set instead of sorted(list(...)) + for order_id in sorted(list(map(lambda x: x["order"], similar_trades))): + trades = list(filter(lambda x: x["order"] == order_id, similar_trades)) + if any(x["timestamp"] < start_timestamp for x in trades): + continue + if any(x["side"] != self.action for x in trades): + continue + if any(x["info"]["category"] == "exchange" and self.account == "margin" for x in trades) or\ + any(x["info"]["category"] == "marginTrade" and self.account == "exchange" for x in trades): + continue + trade_sum = sum(D(x["info"]["amount"]) for x in trades) + amount_diff = round(abs(trade_sum - amount), + self.market.ccxt.order_precision(symbol)) + if amount_diff != 0: + continue + if (self.action == "sell" and any(D(x["info"]["rate"]) < self.rate for x in trades)) or\ + (self.action == "buy" and any(D(x["info"]["rate"]) > self.rate for x in trades)): + continue + self.results.append({"id": order_id}) + return True + + return False + class Mouvement: def __init__(self, currency, base_currency, hash_): self.currency = currency diff --git a/test.py b/test.py index ea1fd9a..5b9e2b4 100644 --- a/test.py +++ b/test.py @@ -3213,6 +3213,507 @@ class OrderTest(WebMockTestCase): self.assertEqual(5, self.m.report.log_error.call_count) self.m.report.log_error.assert_called_with(mock.ANY, message="Giving up Order(buy long 0.00096060 ETH at 0.1 BTC [pending])", exception=mock.ANY) + self.m.reset_mock() + with self.subTest(request_timeout=True): + order = portfolio.Order("buy", portfolio.Amount("ETH", "0.001"), + D("0.1"), "BTC", "long", self.m, "trade") + with self.subTest(retrieved=False), \ + mock.patch.object(order, "retrieve_order") as retrieve: + self.m.ccxt.create_order.side_effect = [ + portfolio.RequestTimeout, + portfolio.RequestTimeout, + { "id": 123 }, + ] + retrieve.return_value = False + order.run() + self.m.ccxt.create_order.assert_has_calls([ + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + ]) + self.assertEqual(3, self.m.ccxt.create_order.call_count) + self.assertEqual(3, order.tries) + self.m.report.log_error.assert_called() + self.assertEqual(2, self.m.report.log_error.call_count) + self.m.report.log_error.assert_called_with(mock.ANY, message="Retrying after timeout", exception=mock.ANY) + self.assertEqual(123, order.id) + + self.m.reset_mock() + order = portfolio.Order("buy", portfolio.Amount("ETH", "0.001"), + D("0.1"), "BTC", "long", self.m, "trade") + with self.subTest(retrieved=True), \ + mock.patch.object(order, "retrieve_order") as retrieve: + self.m.ccxt.create_order.side_effect = [ + portfolio.RequestTimeout, + ] + def _retrieve(): + order.results.append({"id": 123}) + return True + retrieve.side_effect = _retrieve + order.run() + self.m.ccxt.create_order.assert_has_calls([ + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + ]) + self.assertEqual(1, self.m.ccxt.create_order.call_count) + self.assertEqual(1, order.tries) + self.m.report.log_error.assert_called() + self.assertEqual(1, self.m.report.log_error.call_count) + self.m.report.log_error.assert_called_with(mock.ANY, message="Timeout, found the order") + self.assertEqual(123, order.id) + + self.m.reset_mock() + order = portfolio.Order("buy", portfolio.Amount("ETH", "0.001"), + D("0.1"), "BTC", "long", self.m, "trade") + with self.subTest(retrieved=False), \ + mock.patch.object(order, "retrieve_order") as retrieve: + self.m.ccxt.create_order.side_effect = [ + portfolio.RequestTimeout, + portfolio.RequestTimeout, + portfolio.RequestTimeout, + portfolio.RequestTimeout, + portfolio.RequestTimeout, + ] + retrieve.return_value = False + order.run() + self.m.ccxt.create_order.assert_has_calls([ + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + mock.call('ETH/BTC', 'limit', 'buy', D('0.0010'), account='exchange', price=D('0.1')), + ]) + self.assertEqual(5, self.m.ccxt.create_order.call_count) + self.assertEqual(5, order.tries) + self.m.report.log_error.assert_called() + self.assertEqual(5, self.m.report.log_error.call_count) + self.m.report.log_error.assert_called_with(mock.ANY, message="Giving up Order(buy long 0.00100000 ETH at 0.1 BTC [pending]) after timeouts", exception=mock.ANY) + self.assertEqual("error", order.status) + + def test_retrieve_order(self): + with self.subTest(similar_open_order=True): + order = portfolio.Order("buy", portfolio.Amount("ETH", "0.001"), + D("0.1"), "BTC", "long", self.m, "trade") + order.start_date = datetime.datetime(2018, 3, 25, 15, 15, 55) + + self.m.ccxt.order_precision.return_value = 8 + self.m.ccxt.fetch_orders.return_value = [ + { # Wrong amount + 'amount': 0.002, 'cost': 0.1, + 'datetime': '2018-03-25T15:15:51.000Z', + 'fee': None, 'filled': 0.0, + 'id': '1', + 'info': { + 'amount': '0.002', + 'date': '2018-03-25 15:15:51', + 'margin': 0, 'orderNumber': '1', + 'price': '0.1', 'rate': '0.1', + 'side': 'buy', 'startingAmount': '0.002', + 'status': 'open', 'total': '0.0002', + 'type': 'limit' + }, + 'price': 0.1, 'remaining': 0.002, 'side': 'buy', + 'status': 'open', 'symbol': 'ETH/BTC', + 'timestamp': 1521990951000, 'trades': None, + 'type': 'limit' + }, + { # Margin + 'amount': 0.001, 'cost': 0.1, + 'datetime': '2018-03-25T15:15:51.000Z', + 'fee': None, 'filled': 0.0, + 'id': '2', + 'info': { + 'amount': '0.001', + 'date': '2018-03-25 15:15:51', + 'margin': 1, 'orderNumber': '2', + 'price': '0.1', 'rate': '0.1', + 'side': 'buy', 'startingAmount': '0.001', + 'status': 'open', 'total': '0.0001', + 'type': 'limit' + }, + 'price': 0.1, 'remaining': 0.001, 'side': 'buy', + 'status': 'open', 'symbol': 'ETH/BTC', + 'timestamp': 1521990951000, 'trades': None, + 'type': 'limit' + }, + { # selling + 'amount': 0.001, 'cost': 0.1, + 'datetime': '2018-03-25T15:15:51.000Z', + 'fee': None, 'filled': 0.0, + 'id': '3', + 'info': { + 'amount': '0.001', + 'date': '2018-03-25 15:15:51', + 'margin': 0, 'orderNumber': '3', + 'price': '0.1', 'rate': '0.1', + 'side': 'sell', 'startingAmount': '0.001', + 'status': 'open', 'total': '0.0001', + 'type': 'limit' + }, + 'price': 0.1, 'remaining': 0.001, 'side': 'sell', + 'status': 'open', 'symbol': 'ETH/BTC', + 'timestamp': 1521990951000, 'trades': None, + 'type': 'limit' + }, + { # Wrong rate + 'amount': 0.001, 'cost': 0.15, + 'datetime': '2018-03-25T15:15:51.000Z', + 'fee': None, 'filled': 0.0, + 'id': '4', + 'info': { + 'amount': '0.001', + 'date': '2018-03-25 15:15:51', + 'margin': 0, 'orderNumber': '4', + 'price': '0.15', 'rate': '0.15', + 'side': 'buy', 'startingAmount': '0.001', + 'status': 'open', 'total': '0.0001', + 'type': 'limit' + }, + 'price': 0.15, 'remaining': 0.001, 'side': 'buy', + 'status': 'open', 'symbol': 'ETH/BTC', + 'timestamp': 1521990951000, 'trades': None, + 'type': 'limit' + }, + { # All good + 'amount': 0.001, 'cost': 0.1, + 'datetime': '2018-03-25T15:15:51.000Z', + 'fee': None, 'filled': 0.0, + 'id': '5', + 'info': { + 'amount': '0.001', + 'date': '2018-03-25 15:15:51', + 'margin': 0, 'orderNumber': '1', + 'price': '0.1', 'rate': '0.1', + 'side': 'buy', 'startingAmount': '0.001', + 'status': 'open', 'total': '0.0001', + 'type': 'limit' + }, + 'price': 0.1, 'remaining': 0.001, 'side': 'buy', + 'status': 'open', 'symbol': 'ETH/BTC', + 'timestamp': 1521990951000, 'trades': None, + 'type': 'limit' + } + ] + result = order.retrieve_order() + self.assertTrue(result) + self.assertEqual('5', order.results[0]["id"]) + self.m.ccxt.fetch_my_trades.assert_not_called() + self.m.ccxt.fetch_orders.assert_called_once_with(symbol="ETH/BTC", since=1521983750) + + self.m.reset_mock() + with self.subTest(similar_open_order=False, past_trades=True): + order = portfolio.Order("buy", portfolio.Amount("ETH", "0.001"), + D("0.1"), "BTC", "long", self.m, "trade") + order.start_date = datetime.datetime(2018, 3, 25, 15, 15, 55) + + self.m.ccxt.order_precision.return_value = 8 + self.m.ccxt.fetch_orders.return_value = [] + self.m.ccxt.fetch_my_trades.return_value = [ + { # Wrong timestamp 1 + 'amount': 0.0006, + 'cost': 0.00006, + 'datetime': '2018-03-25T15:15:14.000Z', + 'id': '1-1', + 'info': { + 'amount': '0.0006', + 'category': 'exchange', + 'date': '2018-03-25 15:15:14', + 'fee': '0.00150000', + 'globalTradeID': 1, + 'orderNumber': '1', + 'rate': '0.1', + 'total': '0.00006', + 'tradeID': '1-1', + 'type': 'buy' + }, + 'order': '1', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983714, + 'type': 'limit' + }, + { # Wrong timestamp 2 + 'amount': 0.0004, + 'cost': 0.00004, + 'datetime': '2018-03-25T15:16:54.000Z', + 'id': '1-2', + 'info': { + 'amount': '0.0004', + 'category': 'exchange', + 'date': '2018-03-25 15:16:54', + 'fee': '0.00150000', + 'globalTradeID': 2, + 'orderNumber': '1', + 'rate': '0.1', + 'total': '0.00004', + 'tradeID': '1-2', + 'type': 'buy' + }, + 'order': '1', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983814, + 'type': 'limit' + }, + { # Wrong side 1 + 'amount': 0.0006, + 'cost': 0.00006, + 'datetime': '2018-03-25T15:15:54.000Z', + 'id': '2-1', + 'info': { + 'amount': '0.0006', + 'category': 'exchange', + 'date': '2018-03-25 15:15:54', + 'fee': '0.00150000', + 'globalTradeID': 1, + 'orderNumber': '2', + 'rate': '0.1', + 'total': '0.00006', + 'tradeID': '2-1', + 'type': 'sell' + }, + 'order': '2', + 'price': 0.1, + 'side': 'sell', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983754, + 'type': 'limit' + }, + { # Wrong side 2 + 'amount': 0.0004, + 'cost': 0.00004, + 'datetime': '2018-03-25T15:16:54.000Z', + 'id': '2-2', + 'info': { + 'amount': '0.0004', + 'category': 'exchange', + 'date': '2018-03-25 15:16:54', + 'fee': '0.00150000', + 'globalTradeID': 2, + 'orderNumber': '2', + 'rate': '0.1', + 'total': '0.00004', + 'tradeID': '2-2', + 'type': 'buy' + }, + 'order': '2', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983814, + 'type': 'limit' + }, + { # Margin trade 1 + 'amount': 0.0006, + 'cost': 0.00006, + 'datetime': '2018-03-25T15:15:54.000Z', + 'id': '3-1', + 'info': { + 'amount': '0.0006', + 'category': 'marginTrade', + 'date': '2018-03-25 15:15:54', + 'fee': '0.00150000', + 'globalTradeID': 1, + 'orderNumber': '3', + 'rate': '0.1', + 'total': '0.00006', + 'tradeID': '3-1', + 'type': 'buy' + }, + 'order': '3', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983754, + 'type': 'limit' + }, + { # Margin trade 2 + 'amount': 0.0004, + 'cost': 0.00004, + 'datetime': '2018-03-25T15:16:54.000Z', + 'id': '3-2', + 'info': { + 'amount': '0.0004', + 'category': 'marginTrade', + 'date': '2018-03-25 15:16:54', + 'fee': '0.00150000', + 'globalTradeID': 2, + 'orderNumber': '3', + 'rate': '0.1', + 'total': '0.00004', + 'tradeID': '3-2', + 'type': 'buy' + }, + 'order': '3', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983814, + 'type': 'limit' + }, + { # Wrong amount 1 + 'amount': 0.0005, + 'cost': 0.00005, + 'datetime': '2018-03-25T15:15:54.000Z', + 'id': '4-1', + 'info': { + 'amount': '0.0005', + 'category': 'exchange', + 'date': '2018-03-25 15:15:54', + 'fee': '0.00150000', + 'globalTradeID': 1, + 'orderNumber': '4', + 'rate': '0.1', + 'total': '0.00005', + 'tradeID': '4-1', + 'type': 'buy' + }, + 'order': '4', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983754, + 'type': 'limit' + }, + { # Wrong amount 2 + 'amount': 0.0004, + 'cost': 0.00004, + 'datetime': '2018-03-25T15:16:54.000Z', + 'id': '4-2', + 'info': { + 'amount': '0.0004', + 'category': 'exchange', + 'date': '2018-03-25 15:16:54', + 'fee': '0.00150000', + 'globalTradeID': 2, + 'orderNumber': '4', + 'rate': '0.1', + 'total': '0.00004', + 'tradeID': '4-2', + 'type': 'buy' + }, + 'order': '4', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983814, + 'type': 'limit' + }, + { # Wrong price 1 + 'amount': 0.0006, + 'cost': 0.000066, + 'datetime': '2018-03-25T15:15:54.000Z', + 'id': '5-1', + 'info': { + 'amount': '0.0006', + 'category': 'exchange', + 'date': '2018-03-25 15:15:54', + 'fee': '0.00150000', + 'globalTradeID': 1, + 'orderNumber': '5', + 'rate': '0.11', + 'total': '0.000066', + 'tradeID': '5-1', + 'type': 'buy' + }, + 'order': '5', + 'price': 0.11, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983754, + 'type': 'limit' + }, + { # Wrong price 2 + 'amount': 0.0004, + 'cost': 0.00004, + 'datetime': '2018-03-25T15:16:54.000Z', + 'id': '5-2', + 'info': { + 'amount': '0.0004', + 'category': 'exchange', + 'date': '2018-03-25 15:16:54', + 'fee': '0.00150000', + 'globalTradeID': 2, + 'orderNumber': '5', + 'rate': '0.1', + 'total': '0.00004', + 'tradeID': '5-2', + 'type': 'buy' + }, + 'order': '5', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983814, + 'type': 'limit' + }, + { # All good 1 + 'amount': 0.0006, + 'cost': 0.00006, + 'datetime': '2018-03-25T15:15:54.000Z', + 'id': '7-1', + 'info': { + 'amount': '0.0006', + 'category': 'exchange', + 'date': '2018-03-25 15:15:54', + 'fee': '0.00150000', + 'globalTradeID': 1, + 'orderNumber': '7', + 'rate': '0.1', + 'total': '0.00006', + 'tradeID': '7-1', + 'type': 'buy' + }, + 'order': '7', + 'price': 0.1, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983754, + 'type': 'limit' + }, + { # All good 2 + 'amount': 0.0004, + 'cost': 0.000036, + 'datetime': '2018-03-25T15:16:54.000Z', + 'id': '7-2', + 'info': { + 'amount': '0.0004', + 'category': 'exchange', + 'date': '2018-03-25 15:16:54', + 'fee': '0.00150000', + 'globalTradeID': 2, + 'orderNumber': '7', + 'rate': '0.09', + 'total': '0.000036', + 'tradeID': '7-2', + 'type': 'buy' + }, + 'order': '7', + 'price': 0.09, + 'side': 'buy', + 'symbol': 'ETH/BTC', + 'timestamp': 1521983814, + 'type': 'limit' + }, + ] + + result = order.retrieve_order() + self.assertTrue(result) + self.assertEqual('7', order.results[0]["id"]) + self.m.ccxt.fetch_orders.assert_called_once_with(symbol="ETH/BTC", since=1521983750) + + self.m.reset_mock() + with self.subTest(similar_open_order=False, past_trades=False): + order = portfolio.Order("buy", portfolio.Amount("ETH", "0.001"), + D("0.1"), "BTC", "long", self.m, "trade") + order.start_date = datetime.datetime(2018, 3, 25, 15, 15, 55) + + self.m.ccxt.order_precision.return_value = 8 + self.m.ccxt.fetch_orders.return_value = [] + self.m.ccxt.fetch_my_trades.return_value = [] + result = order.retrieve_order() + self.assertFalse(result) @unittest.skipUnless("unit" in limits, "Unit skipped") class MouvementTest(WebMockTestCase): -- 2.41.0