Buy grid stuck after last buy order is not removed from mongodb #560
Assignees
Labels
bug
Something isn't working
Comments
|
Hmm, strange. Are you able to export logs when it happens again? |
|
It just happend even after buy order cancellation:
Now stuck at Grid Trade #1:
I can't export logs as it is freezing my browser when I click Export logs. I'll try to resolve the issue. |
|
It looks like |
|
I tried to log every job start and finish in queue and it is very strage what I found.
Jobs are running as expected, but logged events are overlapping and running before jobs with corresponding IDs were running in queue.
I thought everything is running in the quere but from what I see there are some processes running in parallel before the job is queued? |
|
Now I see those I thought when new buy order is received and then buy order fill is received then in queue will be both events processed. It looks like only the last event is processed in first running job in queue. Second job is practically useless and doing nothing as there is no change since the first queued job has been finished. So it looks like if server is lagging then it can somehow receive next buy order before the job for buy filled is finished? I'm little bit confused about the logic of queue. |
|
I tried to change binance-trading-bot/app/cronjob/trailingTradeHelper/queue.js Lines 16 to 20 in 209d2e0 |
|
Doesn't helped. It's
|
|
Interesting thing is it can fix this automatically if bot is restarted by |
|
It happened again. Log from bot:
|
|
My detailed log about running steps indicated the trailing trade at time of buy order filled on Binance (10:04:41) has been running longer than usual. It looks like a problem is when Binance fill buy order while trailing trade is processing a job. Time on Binance is local, time in log is UTC.
|
|
I think the problem is we are doing changes in mongodb while another job in queue is still running. This can cause some unexpected results. For example if new buy order is still processing in queue when websocket received buy order fill it can make inconsistent state in mongodb removing order before the order has been processed yet in queue. We should do all changes at once in queue or don't use queue at all. Or as a workaround we should not make any changes in mongodb for symbol while symbol is processed in queue. Any changes should be made after the current job in queue is finished to prevent intermediate changes in database state during the job in queue is still running. Or am I wrong? |
|
@chrisleekr What do you think about it? Can changes in mongodb made by websocket while previous job in queue is still running make an inconsistent state which will leave buy order stuck in database if buy order is filled very shortly after new buy order is made? |
|
Current websocket process is:
I think we should implement those steps for websocket:
This will prevent any changes to mongodb while job is running like you can see in this log: |
|
For example: const deleteLastBuyPrice = async (logger, ws, symbol) => {
await mongo.deleteOne(logger, 'trailing-trade-symbols', {
key: `${symbol}-last-buy-price`
});
queue.executeFor(logger, symbol, {
correlationId: _.get(logger, 'fields.correlationId', '')
});Should be: const deleteLastBuyPrice = async (logger, ws, symbol) => {
await queue.pauseQueue(logger, symbol);
await queue.waitForCurrentJobToFinish(logger, symbol);
await mongo.deleteOne(logger, 'trailing-trade-symbols', {
key: `${symbol}-last-buy-price`
});
queue.executeFor(logger, symbol, {
correlationId: _.get(logger, 'fields.correlationId', '')
});
queue.resumeQueue(logger, symbol); |
|
We also should limit number of jobs queued since there is nothing to do after actual state is processed. We should have only one actually running job and one queued job. All other jobs in queue are useless if there is no new change in data to process then.
|
|
I added pause, resume and waitForJob functions to const pause = async (funcLogger, symbol) => {
const logger = funcLogger.child({ helper: 'queue' });
await queues[symbol].pause();
logger.info({ symbol }, `Queue ${symbol} paused`);
};
const resume = async (funcLogger, symbol) => {
const logger = funcLogger.child({ helper: 'queue' });
await queues[symbol].resume();
logger.info({ symbol }, `Queue ${symbol} resumed`);
};
const waitForJob = async (funcLogger, symbol) => {
const logger = funcLogger.child({ helper: 'queue' });
while (await queue[symbol].getActiveCount() > 0) {
await new Promise(resolve => setTimeout(resolve, 10));
}
logger.info({ symbol }, `Queue ${symbol} inactive`);
}; |
|
I changed the code little bit and now it's working as expected. |
|
It looks finally stable. No locks or missing buy/sell orders since queue pause/resume implemented and duplicated queued jobs removed. I'll prepare PR today. Happy new year 2023. 🥳 |
|
@uhliksk Sorry for not getting back to you sooner. I couldn't make time to be in front of the computer. If you push the PR, I will take a look. |
|
While debugging I found there is also error when |
|
There is another glitch when buy order is rapidly filled by multiple partial buys. The order of processing is as expected so I think there is another problem, but I have to research. It looks like fill order has been processed faster than new order so we should apply the hold much sooner than what I applied in fix to prevent out of order processing. If that's true then holdAndExecute() will not be applicable. Edit: It looks like holdAndExecute() is fine where hold() is currently applied. We just need to add hold() and resume() to parts where database is updated, like in
|
|
@chrisleekr This whole block should be inside hold() and resume() pattern? Maybe holdAndResume() function can be created and put that block inside. Same for sale or other long running operations. binance-trading-bot/app/cronjob/trailingTrade/step/place-buy-order.js Lines 416 to 466 in b12aa5c |
|
@chrisleekr Should I create another issue for ^^^ or will we solve everything at once in #562? |
|
Hello @habibalkhabbaz thank you, it looks very promising. It would certainly cover all types of interference we are dealing with when they will be processed in queue. |
|
Sorry, I was wrong. I misunderstood the log because event is logged in bot before it is actually processed. In screenshot of docker log you can see event *652 has been processed after trailing trade has finished so my fix is working as expected. Maybe mongodb itself is processing writes out of order? Should we require acknowledgement of mongodb writes? |
|
|
Interesting. So those block should trigger hold/resume? Then should put inside of the holdAndResume() except the return part.
Update #562 to apply the changes.
Two scenarios.
Yeah, I think you are right. Within 1 second, there were too many writes. |
Sorry, I misinterpretted log. This is not an issue. Please ignore. This block is already in queue so there is no need to hold() and resume(). |
I agree. Order related CRUD is important and should be acked. |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Version
v0.0.96
Description
Sometimes after buy order is filled it is not removed from
trailing-trade-grid-trade-orderswhich will cause another buy order will create secondarySYMBOL-grid-trade-last-buy-orderrecord. After buy order is filled, then one of those records is deleted and one will remain in database. This will cause next buy order is not executed because ofThere is a last gird trade buy order. Wait.. After that the symbol trading is stuck. Not even stop-loss is working as there are buy orders not filled. This can cause significant loss in bear market.To Reproduce
Random error. I tried to log in detail but didn't found the cause why is the
SYMBOL-grid-trade-last-buy-orderrecord not removed from mongodb sometimes.Edit: From what I've seen I think this issue is occuring when buy order is filled very shortly after new buy order is made. In normal slow market this error will not occur as there is plenty of time to process new order before it's filled but in fast market the price can spike so fast it'll trigger buy order filled right after new buy order is created and this will make inconsistent state as websocket is processed while previous job in queue is still running. The probable cause of issue is making changes in database out of order. Changes in database should be part of the job in queue or otherwise we shouldn't use the queue at all.
Expected Behaviours
It should always remove the
SYMBOL-grid-trade-last-buy-orderrecord from mongodb when buy order is filled.Screenshots
Additional context
I tried to log all "deleteOne" transactions which reveals previous
SYMBOL-grid-trade-last-buy-orderwas never asked to be removed from database. I didn't found whyensure-grid-trade-order-executed.jswill skip this. I'm currently trying to log in detail how the buy order is processed line by line, but it's hard to debug as I have to wait until the bug will occur again.The text was updated successfully, but these errors were encountered: