Doubled or missing sell orders since websocket implemented

[uhliksk]

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:

Missing sell order:

Additional context

[habibalkhabbaz]

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.

binance-trading-bot/app/binance/tickers.js

Line 65 in 70b8d0c

executeTrailingTrade(logger, monitoringSymbol);

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]

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]

@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]

@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:

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.

[Rayn0r]

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]

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

[uhliksk]

@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.

[habibalkhabbaz]

@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.

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]

@uhliksk
Done. I pushed a fix for this.

[uhliksk]

@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]

@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]

@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]

@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).

[uhliksk]

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

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

[habibalkhabbaz]

@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).

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

[habibalkhabbaz]

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

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]

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?

[habibalkhabbaz]

@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]

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

[uhliksk]

@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.

[uhliksk]

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

[habibalkhabbaz]

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

Yes, this is the default setting value.

binance-trading-bot/config/default.json

Line 149 in 70b8d0c

"temporaryDisableActionAfterConfirmingOrder": 20,

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]

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

[uhliksk]

@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]

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

[uhliksk]

@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.

[uhliksk]

@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.

[chrisleekr]

I think the bot received the sell order cancellation over websocket but as there was no price change

Yap, that is what I think as well.

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

Yap, I just tested in my RPi with the test server. It started logging the order update as well.

Btw, when you open the log for the symbol, you can view the data on the right column.
That data is very helpful to debug what is going on.

And when you encounter the same issue, export the log immediately.
Then we can debug with that log.

[uhliksk]

And when you encounter the same issue, export the log immediately. Then we can debug with that log.

Ok, I forgot about that option. Thank you.

[habibalkhabbaz]

You are right @chrisleekr on both scenarios.
I will work on a fix for Scenario 2 when I have time.
After that, beside the added logs & implementing the fix, it can be easily to solve the issue if it's occurred again to @uhliksk

[habibalkhabbaz]

@chrisleekr
I've finished writing the fix but unfortunately I think I have lack in permission. I can't commit the changes to PR #461.

remote: Permission to chrisleekr/binance-trading-bot.git denied to habibalkhabbaz.

I can provide the changes as txt if you like since the changes applied on 2 files only: user.js and user.test.js

[uhliksk]

@chrisleekr Not a sell order bug yet, but just an interesting "double" execution logged.

[chrisleekr]

@uhliksk That is interesting. So there was New/Filled order update almost the same time and it triggered two executeTrailingTrade.
Were you able to export the log when it happens?
If you did, it would be very helpful to debug.

[chrisleekr]

One thing I just noticed is, that the locking symbol didn't work properly.

I may have a workaround, but this workaround is very dodge.
We should implement the queue to fix the fundamental issue.

Let me update workaround first.

[habibalkhabbaz]

Good catch! @uhliksk @chrisleekr

However, I think we still need to check for the orderId and transactTime when we update the order from WebSocket for better stability. What do you think @chrisleekr ? BTW sorry for the interruption xD

Moreover, I was thinking about the queue implementation last few days and I found that the ideal solution is to implement a queue for each symbol so that each symbol will not be waiting for other symbols to complete their job but I think this is not good for the performance.
The other solution is implementing one queue for all symbols but this will make all symbols waiting for their turn in the queue.

Let me know if you have any idea about this @chrisleekr when you have time.

[chrisleekr]

I think we still need to check for the orderId and transactTime when we update the order from WebSocket for better stability

I agree.

The current code - https://github.com/chrisleekr/binance-trading-bot/blob/master/app/cronjob/trailingTrade.js#L39 - only lock the symbol 5 seconds.
I assume the second order update SELL - FILLED came after 5 seconds and execute another trailing trade before finishing the 1st trailing trade execution.
However, I can assume both trailing trade execution got the latest updated order SELL - FILLED.

My plan is to mimic the queue system. If the symbol is locked, I force it to execute the trailing trade 10 seconds later. I will use setTimeout.

As mentioned, this is a workaround. This workaround should be updated when we have a queue.

to implement a queue for each symbol

Agree. Trailing Trade can be executed simultaneously for other symbols. It should just FIFO execution for the same symbol.

So for example, if there is an order update event, then put the job into the queue. If there is the following order update event, then it put the job into the queue again. But it does not execute until finishing the running trailing trade job.

[chrisleekr]

@uhliksk @habibalkhabbaz

Not a sell order bug yet, but just an interesting "double" execution logged.

I have updated trailingTrade to be executed 10 secs later when the symbol is locked. With this code, double execution should be fixed.

See the commit: c05c46c

I've also updated the log UI to be more descriptive.

• The time now displays milliseconds.
• It will display UUID of the execution to be able to determine the log's process.
• And it also displays the step of the log.

With this, just a screenshot may help to understand what is going on.
But again, exporting log is much helpful than this.

[habibalkhabbaz]

Nice update @chrisleekr

I have a great news also regarding the queue.
I found a way to create multiple queues since they are cheap based on their documentation.
I'll try to implement that and I will open a new PR if everything goes well and after your PR is merged.

[uhliksk]

@chrisleekr I tried to export log but it crashed my browser as I had 480 minutes limit and it was just too big to process I think. I set back to default 30 minutes and I'll try to catch the problem in real time. I like the changes in log visuals as I prefer to make screenshots which are simple and reliable everytime. I'll merge the commit, thank you.

@habibalkhabbaz I prefer parallel processing of queue because using single queue for all symbols will be pretty narrow bottleneck in rush hours I think.

[habibalkhabbaz]

@habibalkhabbaz I prefer parallel processing of queue because using single queue for all symbols will be pretty narrow bottleneck in rush hours I think.

Totally agree @uhliksk
This is exactly what I am going to try but we will have to wait for #461 to be merged to not have conflicts.

[chrisleekr]

@habibalkhabbaz

Once @uhliksk say, there is no more issue, then I will merge in.

[uhliksk]

@chrisleekr I've made a comment in #461, not important issue.

[chrisleekr]

@uhliksk Answered on the PR. So did you encounter any issues so far?
If don't have any issues, then let's merge it.

[uhliksk]

Accidentally I ran a massive test for sell orders recently. :)

I had to do some maintenance on my VM when this happened on almost every pair.

I started VM immediatelly which caused a massive sell-out.

There were 19 sell orders placed and executed in just a few seconds and I can confirm all of them were processed without an issue.

[chrisleekr]

Oh, nice. Very good.

Ok, I will merge in.

[uhliksk]

@chrisleekr Again another batch of 14 sell orders has been closed. I'll check logs for all the sell orders executed recently to see if there are any potential anomalies recorded. I saved whole trailing-trade-logs in case there will be something interesting.

[uhliksk]

Strange thing. There are no new buy orders placed since this 'nuclear meltdown' happend. In docker log there is a bunch of lines like this:

{"name":"binance-api","version":"0.0.88","hostname":"73b0809731b1","pid":45,"gitHash":"unspecified","server":"binance","jobName":"trailingTrade","correlationId":"42fa3feb-f644-4979-8b6d-8e44491792dd","level":50,"err":{"message":"Stop price would trigger immediately.","name":"Error","stack":"Error: Stop price would trigger immediately.\n at /srv/node_modules/binance-api-node/dist/http-client.js:100:17\n at runMicrotasks (<anonymous>)\n at processTicksAndRejections (internal/process/task_queues.js:95:5)\n at async execute (/srv/dist/server.js:1:38463)\n at async /srv/dist/server.js:1:8847\n at async errorHandlerWrapper (/srv/dist/server.js:1:87322)\n at async P (/srv/dist/server.js:1:7295)","code":-2010},"errorCode":-2010,"debug":true,"msg":"⚠ Execution failed.","time":"2022-08-10T12:51:41.677Z","v":0}

[uhliksk]

@chrisleekr I can create another issue as I think this is something not related to problem discussed in this issue.

[chrisleekr]

@uhliksk
Btw, that is a valid error from Binance.

When your order's stop price is higher than the last coin price, the order will not be accepted because it would execute immediately.

[eppenga]

I can confirm that I have the same issue. Also sometimes my stop loss sell orders double up.

Here are some logs:
{
"_id": "63316872d7c6a3394960f1f9",
"symbol": "SOLBUSD",
"msg": "The grid trade #1 sell order will be placed.",
"loggedAt": "2022-09-26T08:53:06.805Z",
"data": {
"helper": "queue",
"jobName": "trailingTrade",
"correlationId": "cddabf88-4971-4d91-af97-058a2a6ab24a",
"stepName": "place-sell-order",
"function": "order",
"orderParams": {
"symbol": "SOLBUSD",
"side": "sell",
"type": "STOP_LOSS_LIMIT",
"quantity": 3.29,
"stopPrice": 33.07,
"price": 33.04,
"timeInForce": "GTC"
}
}
}

And then suddenly the quantity doubles:
{
"_id": "63316a06d7c6a3394960f23a",
"symbol": "SOLBUSD",
"msg": "The grid trade #1 sell order will be placed.",
"loggedAt": "2022-09-26T08:59:50.619Z",
"data": {
"helper": "queue",
"jobName": "trailingTrade",
"correlationId": "95a34487-d0fe-4798-bbb6-a24178b6608f",
"stepName": "place-sell-order",
"function": "order",
"orderParams": {
"symbol": "SOLBUSD",
"side": "sell",
"type": "STOP_LOSS_LIMIT",
"quantity": 6.58,
"stopPrice": 33.13,
"price": 33.1,
"timeInForce": "GTC"
}
}
}

As you can see it jumps from 3.29 to 6.58 faling to sell.