ccxt: Order Cache falling out of sync, Poloniex

Thanks! A really nice-looking log, I’d put it as an example into “How to submit an issue” section )

it occurred when a bid failed to cancel due to a request timeout

The issue is that it’s got canceled on the exchange side, indeed. I added an explanation on how to handle RequestTimeout exceptions into the manual here: #1870. I’d like to know if you find it enough to answer your question or maybe you have a suggestion how to phrase it in a better language.

I’ve upgraded to 1.10.1074 and I’m still hitting this bug. Here are my logs from most recent run showing where it occurred when a bid failed to cancel due to a request timeout.

DEBUG:root:Canceling Bid # Print message before calling cancelOrder with id '416986457287'
DEBUG:root:poloniex POST https://poloniex.com/tradingApi request timeout poloniex POST https://poloniex.com/tradingApi request timeout
DEBUG:root:------
DEBUG:root:2018-02-10 18:40:02.370603
DEBUG:urllib3.connectionpool:https://api.binance.com:443 "GET /api/v1/depth?symbol=ETHBTC HTTP/1.1" 200 None
DEBUG:urllib3.connectionpool:Starting new HTTPS connection (2): poloniex.com
DEBUG:urllib3.connectionpool:https://poloniex.com:443 "GET /public?command=returnOrderBook&currencyPair=BTC_ETH HTTP/1.1" 200 None
DEBUG:urllib3.connectionpool:https://api.binance.com:443 "GET /api/v3/account?timestamp=1518316802758&recvWindow=5000&signature=14c9f10ae424c72182d72a9a967fea24ee9081fd42d40d67a33f6fd4bdf86e44 HTTP/1.1" 200 None
DEBUG:urllib3.connectionpool:https://poloniex.com:443 "POST /tradingApi HTTP/1.1" 200 None
DEBUG:root:Completed ask orders: 1
DEBUG:root:Completed bid orders: 1
DEBUG:root:Open ask: None
DEBUG:root:Open bid: None
DEBUG:root:Closed ask: {'status': 'canceled', 'timestamp': 1518316474000, 'price': 0.10017855, 'datetime': '2018-02-11T02:34:34.000Z', 'cost': 0.07353471, 'id': u'416984691055', 'info': {'status': 'open', u'orderNumber': u'416984691055', u'type': 'limit', 'price': u'0.10017855', u'rate': u'0.10017855', u'amount': u'0.73403649', u'date': u'2018-02-11 02:34:34', u'total': u'0.07353471', u'margin': 0, 'side': u'sell', u'startingAmount': u'0.80955837'}, 'fee': None, 'trades': None, 'remaining': 0.73403649, 'symbol': u'ETH/BTC', 'amount': 0.80955837, 'type': 'limit', 'side': u'sell', 'filled': 0.07552187999999993}
DEBUG:root:Closed bid: {'status': 'closed', 'info': {'status': 'open', u'orderNumber': u'416986457287', u'type': 'limit', 'price': u'0.09928044', u'rate': u'0.09928044', u'amount': u'0.07966888', u'date': u'2018-02-11 02:39:42', u'total': u'0.00790956', u'margin': 0, 'side': u'buy', u'startingAmount': u'0.07966888'}, 'fee': None, 'timestamp': 1518316782000, 'price': 0.09928044, 'trades': None, 'side': u'buy', 'datetime': '2018-02-11T02:39:42.000Z', 'symbol': u'ETH/BTC', 'amount': 0.07966888, 'cost': 0.007909561460707199, 'type': 'limit', 'id': u'416986457287', 'filled': 0.07966888, 'remaining': 0.0}
# Here you can see order given by id '416986457287' showing that it was filled for 0.0796. The poloniex UI shows that no bid completed during this time. 

This is without any cache reset on my part.

The Manual edits look good. Language is understandable. Thanks for taking the time to dive into this. Really appreciate it as well as everything you guys are doing.

Just to add-in an additional check here for anyone else who looks at this issue later on: in addition to re-trying cancelOrder requests you can also track your balance over time, and only honor filled orders if your balance changed nearby when that order was reported as filled. Both these solutions in tandem should be enough to ensure you don’t falsely act on an order being executed.

Thanks again 😃

Putting aside the issue of the undefined solution since that’s a major change, would fetchOrder after cancelOrder also handle the problem?

It will be fixed in #1849. Still, I’d appreciate if you could create an order, then send a non-blocking cancellation request and then tried to fetch order in verbose mode. We know that Polo responds with pending for subsequent cancellation but I wonder what will it respond with on fetch.

Another thing I have noticed is a great way to get your cache to go out of sync is to call fetchOrders with a limit value.

Right. It won’t cause any harm now because in their current state neither Liqui nor Polo limit number of returned orders but we surely need to keep it in mind in case they start too.

Ok, I finally figured out what’s going on.

I’ve been running into an issue with my Poloniex trades where fetchOrders will occasionally incorrectly return an order as completed and filled even though it was not… When I go to the Poloniex Trade History on the site, there is no corresponding trade.

I’m assuming what is happening here is the order is not found during the fetchOpenOrders call, and that results in the order in the cache being marked as ‘closed’, and the ‘filled’ attribute gets set equal to the ‘amount’ value.

You’re absolutely right! And it does related to cancelOrder.

So when you cancel an order and then you fetch (open) orders, the order is not in the cache indeed. So ccxt marks it as ‘closed’ although it was canceled in reality. It would be more appropriate to set the status to undefined because we really don’t know what happened to that order but I would be not quite comfortable with that.

Is there a best practice that I should follow that would circumvent this problem? Did the cache rework that I see referenced in 569 occur? If not, can I help with the cache rework?

Looks like cancelOrder needs to catch CancelPending exception and force update the cache.

I’m going to have to wait until Binance trades are back up to report back on the impact of removing the cache reset.

Following up with @mkutny, I ran the following:

print p.createLimitSellOrder('ETH/BTC', 1.0, 1000)
print p.createLimitBuyOrder('BCH/ETH', 1.0, 0.0001)
print p.fetchOrders('ETH/BTC')

because I only had balance in ETH to test with, but it should map to your example (note I have here a buy and a sell vs two buys). Also, I’m not sure how you’re able to get your orders to go through with such low amounts and prices – I always get an error indicating the trade amount must be larger, hence the different values I’m using here.

Output:

{'status': 'open', 'timestamp': 1518108203212, 'price': 1000.0, 'datetime': '2018-02-08T16:43:23.212Z', 'cost': 0.0, 'id': u'415899251581', 'info': {'status': 'open', 'amount': 1.0, u'resultingTrades': [], u'orderNumber': u'415899251581', 'timestamp': 1518108203212, 'price': 1000.0, 'type': 'limit', 'side': 'sell'}, 'fee': None, 'trades': [], 'side': 'sell', 'symbol': u'ETH/BTC', 'amount': 1.0, 'type': 'limit', 'remaining': 1.0, 'filled': 0.0}
{'status': 'open', 'timestamp': 1518108205849, 'price': 0.0001, 'datetime': '2018-02-08T16:43:25.849Z', 'cost': 0.0, 'id': u'26100270793', 'info': {'status': 'open', 'amount': 1.0, u'resultingTrades': [], u'orderNumber': u'26100270793', 'timestamp': 1518108205849, 'price': 0.0001, 'type': 'limit', 'side': 'buy'}, 'fee': None, 'trades': [], 'side': 'buy', 'symbol': u'BCH/ETH', 'amount': 1.0, 'type': 'limit', 'remaining': 1.0, 'filled': 0.0}
[{'status': 'open', 'timestamp': 1518108201000, 'price': 1000.0, 'datetime': '2018-02-08T16:43:21.000Z', 'cost': 1000.0, 'id': u'415899251581', 'info': {'status': 'open', u'orderNumber': u'415899251581', u'type': 'limit', 'price': u'1000.00000000', u'rate': u'1000.00000000', u'amount': u'1.00000000', u'date': u'2018-02-08 16:43:21', u'total': u'1000.00000000', u'margin': 0, 'side': u'sell', u'startingAmount': u'1.00000000'}, 'fee': None, 'trades': None, 'remaining': 1.0, 'symbol': u'ETH/BTC', 'amount': 1.0, 'type': 'limit', 'side': u'sell', 'filled': 0.0}]

In my original examples I am calling fetchOrders by symbol, but all orders I’m placing or fetching fall under the same symbol. So I’m not sure whatever you’re bug you’re investigating over at #1830 is related.

Also it’s worth mentioning that I reset the cache every 15 minutes, with self.poloniex.orders = {}.

This was worth mentioning from the very beginning, as this is most likely the reason for the inconsistencies above %)

Proper order caching relies on info in .orders, so if you drop it regularly – you will have a regular crash. It wasn’t designed to be dropped at all. You can probably safely remove the already-closed orders, if you’re not interested in them, but you can’t just set self.poloniex.orders = {}. The order cache is used to track order statuses, because Poloniex has a very poor API and doesn’t offer any endpoints for closed orders. The order cache is used to distinguish closed orders from remembered open orders. It is not the same as browser cache.

Have you tried not resetting the cache?