search

chrisleekr / binance-trading-bot

Automated Binance trading bot - Trade multiple cryptocurrencies. Buy low/sell high with Grid Trading. Integrated with TradingView technical analysis
MIT License
5.01k stars 1.09k forks source link

Doubled or missing sell orders since websocket implemented #451

Closed uhliksk closed 2 years ago

uhliksk commented 2 years ago

Version

v0.0.88 (9c2e4f5)

Description

In radnom appearance there are single sell orders counted as two sell orders at once. There is single sell order executed on Binance side resulted into two closed trade records on bot side. This is doubling calculated profitability.

In random appearance there are closed trades executed on Binance side triggering removing last buy price without accounting last sell order thus removing trade grid with calculated 100% loss. This is worsening calculated profitability.

To Reproduce

There are no actual steps to reproduce as the bug is appearing randomly.

Expected Behaviours

Single sell order should be counted as single transaction in closed trades history.

Screenshots

Doubled sell order: image

Missing sell order: image

Additional context

habibalkhabbaz commented 2 years ago

Hello @uhliksk I didn't face this issue but I can imagine how this can happen.

WebSocket is fast and we are calling executeTrailingTrade for each ticker received. This can trigger executeTrailingTrade two times in a short time so that's why the action can be duplicated.

https://github.com/chrisleekr/binance-trading-bot/blob/70b8d0c8c1c81301c2bbd1588770cad78df52e61/app/binance/tickers.js#L65

My suggested solution

Use queue for each symbol to queue the calls of executeTrailingTrade

This is the same for #450

I will try to work on this when I have time

uhliksk commented 2 years ago

Hello @habibalkhabbaz

That's great you found a possible vector of fail. Do you think it will solve also the missing sell orders problem? I didn't catched a log for both incidents as they happend more than 30 minutes ago but I'll try to monitor the bot more frequently to catch how exactly it's been processed.

habibalkhabbaz commented 2 years ago

@uhliksk

I think that's another issue.

I have two question:

  1. What is your Last buy price removal threshold ?
  2. The sell order was initiated from bot or from Binance directly ?
uhliksk commented 2 years ago

@habibalkhabbaz

  1. Last buy price removal threshold is 10 BUSD
  2. The sell order was initiated from bot

Today I even found tripple buy order in Order History executed by bot:

image

I'll try today to migrate the bot to another server with higher performance to see if cpu bottleneck is the issue. Right now it's using 80% of single core.

image

Rayn0r commented 2 years ago

I have seen double orders in 0.0.85 before. It usually happened when the bot was trying to cancel an already placed order because its price had changed. So the second order got executed because the bot had not noticed, that the first one had not been canceled. This way the same grid order got executed twice.

uhliksk commented 2 years ago

@Rayn0r This is something else as those duplicate orders are created at once.

uhliksk commented 2 years ago

@habibalkhabbaz I implemented executeTrailingTrade queueing which resulted in much smaller log clearly indicating function is called less times than with original code. CPU usage also dropped and I haven't seen duplicate orders yet. I'll try running the current code longer to be sure everything is working well. On my original "low performance" server CPU usage dropped from 80% to about 40% on average.

image

habibalkhabbaz commented 2 years ago

@habibalkhabbaz I implemented executeTrailingTrade queueing which resulted in much smaller log clearly indicating function is called less times than with original code. CPU usage also dropped and I haven't seen duplicate orders yet. I'll try running the current code longer to be sure everything is working well. On my original "low performance" server CPU usage dropped from 80% to about 40% on average.

image

Hey @uhliksk

That's great. Today I was thinking of this and I came up with a better solution instead of queuing. Queuing the execution may result a delayed execution and we don't want this to happen.

The new suggested solution

  1. Cache a value when execution just started for a symbol
  2. Remove this value at the end of execution
  3. Check if this value is set at the top of executionTrailingTrade

Sample code

if (cached value is already set for a symbol) {
 // do nothing because there is uncompleted execution before
 return;
}

// cache the value here

.....steps of execution

// reset cache here

I can create PR to implement this if you like or you can do it as well.

Or if you like we may include the fixes in my last PR which is related.

habibalkhabbaz commented 2 years ago

@uhliksk Done. I pushed a fix for this.

uhliksk commented 2 years ago

@habibalkhabbaz Great. But I think it'll be even better to not just return when execution task is already running but set a flag in cache to indicate there is a skipped attempt to execute and check for this flag at the end of execution. If flag is set then you should clear the flag and reexecute processing again until there is a clear flag at the end of execution. This way missed attempts will not be delayed until an another change is received, but they will be processed asap.

habibalkhabbaz commented 2 years ago

@uhliksk Nice idea! However, re-execute the failed attempt may lead to unexpected result.

WebSocket send updates every 1 second for a symbol. That means the executeTrailingTrade will be called every 1 second (if the symbol is very active) So I think we can simply discard the attempt as I did because we will receive another tick within 1 second and executeTrailingTrade will be called again.

What do you think?

uhliksk commented 2 years ago

@habibalkhabbaz From what I've seen if there is no change in a symbol then executeTrailingTrade is not called for even a minutes. I think it's better to not wait until next call is fired by WebSocket.

uhliksk commented 2 years ago

@habibalkhabbaz Right now I have UNIBUSD not updated for 29 seconds. If there was skipped call with your solution then it will be not processed for those full 29 seconds (and maybe longer).

image

uhliksk commented 2 years ago

@habibalkhabbaz Bad news. Missing sell order bug is still not fixed.

image

Unfortunately I had logging turned off as I thought the problem is finally solved.

habibalkhabbaz commented 2 years ago

@habibalkhabbaz Right now I have UNIBUSD not updated for 29 seconds. If there was skipped call with your solution then it will be not processed for those full 29 seconds (and maybe longer).

image

I understood! Let me think for an improvement for this.

habibalkhabbaz commented 2 years ago

@habibalkhabbaz Bad news. Missing sell order bug is still not fixed.

image

Unfortunately I had logging turned off as I thought the problem is finally solved.

Ohh. Do you use my last PR or your own implemented queue?

uhliksk commented 2 years ago

Ohh. Do you use my last PR or your own implemented queue?

I used my own implemented queue which is even safer than skipping the calls. It's possible those cancelled orders will cancel this final executed sell order when processed?

image

habibalkhabbaz commented 2 years ago

@uhliksk

I am sure that the duplicated orders are solved now and it needs only minor improvement as per your feedback. However, the lost sell order as I said it's another issue. So, let me debug this.

I remember I have had the same problem when I bought a symbol outside the bot and the bot is not running. Then I use the bot only for sell (set last buy price). Like this will result in a lost sell order.

So, I would like to know if DOTBUSD bought using the bot or outside (from Binance directly).

If this is your case, I know the problem and I have a solution for it.

uhliksk commented 2 years ago

@habibalkhabbaz I'm not doing manual orders. Everything, buy or sell, is made by the bot automatically.

uhliksk commented 2 years ago

@habibalkhabbaz The NEARBUSD I posted in screenshots section of this issue had also canceled sell orders. I think this bug is related to bot automatically cancelling sell orders when the price is raising.

image

uhliksk commented 2 years ago

@habibalkhabbaz Is this normal behavior to wait 20 seconds between the sell order is executed and the grid trade is removed?

image

habibalkhabbaz commented 2 years ago

@habibalkhabbaz Is this normal behavior to wait 20 seconds between the sell order is executed and the grid trade is removed?

image

Yes, this is the default setting value.

https://github.com/chrisleekr/binance-trading-bot/blob/70b8d0c8c1c81301c2bbd1588770cad78df52e61/config/default.json#L149

You can change it by using your .env file. 2 seconds for example:

BINANCE_JOBS_TRAILING_TRADE_SYSTEM_TEMPORARY_DISABLE_ACTION_AFTER_CONFIRMING_ORDER=2

I am still trying to know what is the actual issue.

habibalkhabbaz commented 2 years ago

@uhliksk Do you mind if you try the same thing on my last PR? I would like to see how it goes.

uhliksk commented 2 years ago

@habibalkhabbaz I reverted my changes and merged with your PR and also changed .env as you suggested. I'll keep full docker logs to better analyze the issue if it happened again.

habibalkhabbaz commented 2 years ago

@uhliksk Thanks! It will be easier to debug. I am running my bot on that PR too to see how it goes.

uhliksk commented 2 years ago

@habibalkhabbaz Something wrong has happened since I started the code with your PR merged. Some symbols just stopped updating. When I reverted the code it catched the current values immediatelly.

image

uhliksk commented 2 years ago

@habibalkhabbaz There is not even "TrailingTrade: Start process..." logged for those symbols. Interesting thing is when I switched back to PR merged code all the same symbols are stuck again. Is it possible it had somehow didn't deleted the flag from cache and keep thinking the task is still executed?

uhliksk commented 2 years ago

@habibalkhabbaz You should use cache.hset() with TTL value to prevent infinite lock.

habibalkhabbaz commented 2 years ago

@uhliksk Thanks for this good catch. Pushed a fix. You can delete your Redis cache to work as expected. It would be better to continue testing on the same PR to see how it goes.

You can use the following to clear the old cache:

await cache.hdelall('execute-trailing-trade:*');
uhliksk commented 2 years ago

@habibalkhabbaz Since yesterday 53 closed trades without an issue, but there were no multiple cancelled sell orders before the final sell order has been executed. I'll keep logging.

habibalkhabbaz commented 2 years ago

@habibalkhabbaz Since yesterday 53 closed trades without an issue, but there were no multiple cancelled sell orders before the final sell order has been executed. I'll keep logging.

Glad to hear that! Now let's see if the sell order issue already solved or not.

uhliksk commented 2 years ago

@habibalkhabbaz Sell order issue still exist but I didn't catched the log as I was travelled away and I didn't noticed logging stopped working at morning. But I'm suspicious it somehow triggerred "Remove last buy price" before the sell order is processed. I restarted logging and I hope I'll catch the issue with full log next time.

uhliksk commented 2 years ago

@habibalkhabbaz From Binance history I can see the sell order has been set at 13:18:04, then cancelled and new higher sell order has been set at 13:19:30. Then 3 seconds later at 13:19:33 the sell order has been executed and then closed trade has been archived into bot database at 13:19:42.

Second event was very similar. Sell order has been set at 12:44:24, then cancelled and new higher sell order has been set at 13:19:29. Then 9 seconds later at 13:19:38 the sell order has been executed and then closed trade has been archive into bot database at 13:20:36.

uhliksk commented 2 years ago

@habibalkhabbaz From trailing-trade-grid-trade-archive: image

habibalkhabbaz commented 2 years ago

That was sad!

@habibalkhabbaz From trailing-trade-grid-trade-archive: image

It will be helpful for debugging if you can share the whole document to see the buy grids and the sell grids.

uhliksk commented 2 years ago

@habibalkhabbaz I think it's something wrong with symbol locks or something similar which will cause the planned step is skipped and then never processed again because I also found sometimes the sell order is recorded completely in closed trades archive but the grid trade is not reset automatically and symbol is stuck then until I click "Reset Grid Trade" manually. If any operation failed because of lock or some other non-critical issue it should be retried.

image

image

uhliksk commented 2 years ago

@habibalkhabbaz There is no check if transaction has been processed successfully. Result is returned but not processed.

https://github.com/chrisleekr/binance-trading-bot/blob/a9319ad7d65235244571f73efa842ffe1cdae86d/app/cronjob/trailingTradeHelper/configuration.js#L522-L530

https://github.com/chrisleekr/binance-trading-bot/blob/a9319ad7d65235244571f73efa842ffe1cdae86d/app/cronjob/trailingTrade/step/remove-last-buy-price.js#L128-L129

uhliksk commented 2 years ago

If sell order is executed and not written to db successfully it can cause the issue with sell orders and potentially many other issues. I think I should create new issue for the problem.

uhliksk commented 2 years ago

@habibalkhabbaz There is not even write concern enabled. I'll create new issue to fix this.

https://github.com/chrisleekr/binance-trading-bot/blob/a9319ad7d65235244571f73efa842ffe1cdae86d/app/helpers/mongo.js#L231-L237

uhliksk commented 2 years ago

@habibalkhabbaz I found it was introduced by purpose in #288.

habibalkhabbaz commented 2 years ago

Hello @uhliksk Yes, this is intended change to make MongoDB fast.

I think we have to check for the main reason which is why the sell executed order is not saved to DB.

The sell order should be saved directly after placing it and will be archived later if executed.

https://github.com/chrisleekr/binance-trading-bot/blob/a9319ad7d65235244571f73efa842ffe1cdae86d/app/cronjob/trailingTrade/step/place-sell-order.js#L199

So the question is: is it really not saved and why not?. We have to investigate this.

uhliksk commented 2 years ago

So the question is: is it really not saved and why not?. We have to investigate this.

Hello @habibalkhabbaz

What do you think can cause too big delay between the sell order executed and the last buy price removed? When I posted the smaller part of this log, I didn't noticed there is huge gap for more than 2 minutes. In other cases there is 20 seconds gap based on BINANCE_JOBS_TRAILING_TRADE_SYSTEM_TEMPORARY_DISABLE_ACTION_AFTER_CONFIRMING_ORDER.

image

chrisleekr commented 2 years ago

@uhliksk

What do you think can cause too big delay between the sell order executed and the last buy price removed?

That is because the last buy price is not removed immediately after the sell order is executed, which is the intended behaviour. It will be removed in the next tick after determining whether to remove the last buy price or not. Before WebSocket implementation, it would be okay because it would run the execution immediately. However, it's relying on the tick now. I assume the tick delay causes the gap between the sell order and the last buy price. This issue will not happen to symbols that are busy like BTCUSDT, but it may happen to some coins which are not busy.

This issue should be resolved when the queue is implemented.

uhliksk commented 2 years ago

@habibalkhabbaz Today's event is even stranger as the sell order has been cancelled internally right before it had to be processed as executed sell order.

image

image

image

image

uhliksk commented 2 years ago

@habibalkhabbaz It's possible we are hunting MongoDB memory issue here. I'm using Hyper-V with Dynamic Memory enabled for binance-bot VM. I'll try to switch to fixed memory configuration. I've never had an issue with this VM configuration but binance-bot is probably much more resource hungry in rush hours than any other application I've ever used in my VMs.

https://groups.google.com/g/mongodb-user/c/MapX1Ug_gsI/m/meJvWVAfFQAJ

If that's the issue then still bot should find and process sell order even if it missed it's own event or even when sold manually to keep track of profitability.

uhliksk commented 2 years ago

@habibalkhabbaz This is top from around the time this issue has happened. It doesn't look like a memory issue but I'll still try to switch to fixed memory allocation for this VM.

image

habibalkhabbaz commented 2 years ago

Hello @uhliksk My suggestion is to put the following line in your .env file:

BINANCE_LOG_LEVEL=ERROR

This line will make the logger log only errors to console which will lower the memory usage and issues. Try it and let's see if it will solve the current issue or not!

However, what I prefer is to remove all docker containers and restart everything from scratch if you can. This will make sure you don't have data stuck here and there.

uhliksk commented 2 years ago

Hello @habibalkhabbaz

I'm doing docker system prune from time to time. I'll try the log level option you suggested. Thank you.

chrisleekr commented 2 years ago

@habibalkhabbaz Today's event is even stranger as the sell order has been cancelled internally right before it had to be processed as eell order.

@uhliksk is it possible you can export the logs? So can see what actually happened?

I can see a possible scenario. @habibalkhabbaz correct me if I am wrong.

When the order is executed, from WebSocket, the bot will receive executionReport

What we need to confirm is, first, was your bot received the WebSocket event? Unfortunately, it hasn't been recorded in the database, so we wouldn't know at this point. Hence, I have added this PR and will be merged to the master - https://github.com/chrisleekr/binance-trading-bot/pull/460

If it happens again, we should be able to see what happened.

Ah, while I am writing, I found a flow.

Sorry. I keep mumble-jumble.

Let me tidy up.

I opened a new PR - https://github.com/chrisleekr/binance-trading-bot/pull/461 This is to fix Scenario 1.

Once the order is executed or cancelled whatever happened to the order, it should receive the event via WebSocket. https://github.com/chrisleekr/binance-trading-bot/blob/master/app/binance/user.js#L39 The order is updated in the database; however, the trailing trade is not executed after the order is updated.

This can cause unexpected behaviour, which I think it shouldn't. But it will make the flow correctly.

The 2nd scenario will need the detailed log from @uhliksk

@habibalkhabbaz Please verify my scenario.

Normally, this is the flow we would expect how the bot behaves.

11:00:26 New sell order is placed
11:00:45 Logged "The order will be cancelled". This log assumed logged from https://github.com/chrisleekr/binance-trading-bot/blob/master/app/cronjob/trailingTrade/step/handle-open-orders.js#L178
??:??:?? Received order update event. The last order is updated as cancelled
11:00:47 New sell order is placed
??:??:?? Received order update event. The last order is updated as filled
??:??:?? Process filled order - https://github.com/chrisleekr/binance-trading-bot/blob/master/app/cronjob/trailingTrade/step/ensure-grid-trade-order-executed.js#L289

However, for some reason, the process is messed up. I think the most suspect issue is not executing trailingTrade immediately, but there could be another reason.

So what I assume to happen is the below process.

11:00:26 New sell order is placed
11:00:45 Logged "The order will be cancelled". This log assumed logged from https://github.com/chrisleekr/binance-trading-bot/blob/master/app/cronjob/trailingTrade/step/handle-open-orders.js#L178
11:00:47 New sell order is placed
??:??:?? Received order update event. The last order is updated as filled
??:??:?? Received order update event. The last order is updated as cancelled
11:00:50 Processed cancelled order 
11:01:21 The last buy price is removed

I think when we update the last order, we should compare the timestamp and orderId and make sure we have the last order recording as the last order. https://github.com/chrisleekr/binance-trading-bot/blob/master/app/binance/user.js#L64

What do you think @habibalkhabbaz? If you think my theory is valid, then you can update it in my branch - https://github.com/chrisleekr/binance-trading-bot/pull/461

@uhliksk you can try with my branch and see if we can get more logs + the fix is working or not.

uhliksk commented 2 years ago

@chrisleekr I'm sorry but I don't have full log again. I'm saving log over samba to another machine as the log generated by the bot is massive in my instance and I didn't noticed it filled dedicated partition. Last 50 MB stored locally are just a few last seconds of log which is not helpful.

I think the bot received the sell order cancellation over websocket but as there was no price change, it was not processed by executeTrailingTrade˙. Then the bot placed new sell order and sell order was executed on Binance. Sell order execution means the price has changed and this caused executeTrailingTrade has been fired and previously received sell order cancellation has been processed. Then finally with sell order cancelled on bot side and balance updated, the last buy price has been removed. If that's how the issue happened then your fix should be working well.

Checking orderId will also be fine to prevent removing wrong order by delayed sell order cancellation report.

I'll try to run with your branch to see it the issue will occur again in next few days. Thank you.