After a few hours it doesn't update prices and makes decision base on wrong data

alexandrucancescu commented 3 years ago

Description

To Reproduce

I am running this bot on Ubuntu 16.04.7 LTS installed on a physical server.

Today 23.05.2021 at aprox. 11:00 UTC I realised that the current prices shown in the web UI were very old and refreshing the page didn't seem to fix this so I restarted the docker container.

All went ok after this for almost 4 hours. At 15:00 UTC the bot stopped updating the prices in the UI again. I left it running like this for 5 hours and it was stuck with the price from 15:00 UTC for the whole time. Refreshing the page doesn't fix it.

What scares me is that it tries to make decisions based on very old data. In the screenshot below it can be seen that it wants to buy ETH but I don't have USDT in my wallet.

All the other pairs are stuck too, but I only monitored ETH, the other pairs failed to updated around the same time.

Screenshots

Additional context

Ubuntu 16.04.7 LTS

chrisleekr commented 3 years ago

Firstly, before you label as it's a bug, please make sure you did a code analysis of what the root cause is and found there is a bug.

Please check your log and try to determine whether the bot is running or not.

https://github.com/chrisleekr/binance-trading-bot/wiki/Troubleshooting#how-to-get-the-logs-by-installing-bunyan-npm-package

alexandrucancescu commented 3 years ago

The bot is running. I am using a ssh tunnel to access the web UI. I could not find anything of value in the log except that lastCandle is an empty object. Also the log grew to 500MB already, using the ETHUSDT filter. I'll post a section of the log, maybe it holds some valuable info.

[2021-05-23T23:00:00.036Z]  INFO: binance-api/19 on 86097728096e: ▶ TrailingTrade: Start process... (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, debug=true, symbol=ETHUSDT)
[2021-05-23T23:00:00.038Z]  INFO: binance-api/19 on 86097728096e: 🔓 Symbol is not locked - ETHUSDT  (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, debug=true, symbol=ETHUSDT, isLocked=false)
[2021-05-23T23:00:00.039Z]  INFO: binance-api/19 on 86097728096e: Lock ETHUSDT for 5 seconds (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, debug=true, symbol=ETHUSDT)
[2021-05-23T23:00:00.041Z]  INFO: binance-api/19 on 86097728096e: Start step - get-symbol-configuration (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT)
    data: {
      "symbol": "ETHUSDT",
      "isLocked": false,
      "featureToggle": {
        "notifyOrderConfirm": true,
        "notifyDebug": false
      },
      "lastCandle": {},
      "accountInfo": {
        "makerCommission": 10,
        "takerCommission": 10,
        "buyerCommission": 0,
        "sellerCommission": 0,
        "canTrade": true,
        "canWithdraw": true,
        "canDeposit": true,
        "updateTime": 1621787046973,
        "accountType": "SPOT",
        "balances": [
          {
            "asset": "BNB",
            "free": "0.00075161",
            "locked": "0.00000000"
          },
          {
            "asset": "ALGO",
            "free": "94.63475200",
            "locked": "0.00000000"
          },
          {
            "asset": "EUR",
            "free": "0.00360000",
            "locked": "99.99640000"
          }
        ],
        "permissions": [
          "SPOT"
        ]
      },
      "symbolConfiguration": {},
      "indicators": {},
      "symbolInfo": {},
      "openOrders": [],
      "action": "not-determined",
      "baseAssetBalance": {},
      "quoteAssetBalance": {},
      "buy": {},
      "sell": {},
      "saveToCache": true
    }
[2021-05-23T23:00:00.041Z]  INFO: binance-api/19 on 86097728096e: Finding document from MongoDB (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT, helper=mongo, funcName=findOne, collectionName=trailing-trade-common)
    query: {
      "key": "configuration"
    }
[2021-05-23T23:00:00.043Z]  INFO: binance-api/19 on 86097728096e: Found document from MongoDB (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT, helper=mongo, funcName=findOne)
    result: {
      "_id": "60a98e875b575cfbdb884341",
      "key": "configuration",
      "enabled": true,
      "cronTime": "* * * * * *",
      "symbols": [
        "ETHUSDT",
        "XLMUSDT",
        "XRPUSDT",
        "ADAUSDT",
        "ALGOUSDT"
      ],
      "candles": {
        "interval": "15m",
        "limit": 100
      },
      "buy": {
        "enabled": true,
        "maxPurchaseAmount": -1,
        "maxPurchaseAmounts": {
          "USDT": 100,
          "BTC": 0.001,
          "ETH": 0.05,
          "BNB": 0.5
        },
        "triggerPercentage": 1.01,
        "stopPercentage": 1.02,
        "limitPercentage": 1.021
      },
      "sell": {
        "enabled": true,
        "triggerPercentage": 1.06,
        "stopPercentage": 0.98,
        "limitPercentage": 0.979,
        "stopLoss": {
          "enabled": false,
          "maxLossPercentage": 0.8,
          "disableBuyMinutes": 360,
          "orderType": "market"
        }
      },
      "system": {
        "temporaryDisableActionAfterConfirmingOrder": 20
      }
    }
[2021-05-23T23:00:00.044Z]  INFO: binance-api/19 on 86097728096e: Finding document from MongoDB (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT, helper=mongo, funcName=findOne, collectionName=trailing-trade-symbols)
    query: {
      "key": "ETHUSDT-configuration"
    }
[2021-05-23T23:00:00.046Z]  INFO: binance-api/19 on 86097728096e: Found document from MongoDB (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT, helper=mongo, funcName=findOne, result=null)
[2021-05-23T23:00:00.046Z]  INFO: binance-api/19 on 86097728096e: Could not find symbol configuration. (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT)
[2021-05-23T23:00:00.046Z]  INFO: binance-api/19 on 86097728096e: Max purchase amount is set as -1. Need to calculate and override it (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT, symbolBuyMaxPurchaseAmount=-1)
[2021-05-23T23:00:00.051Z]  INFO: binance-api/19 on 86097728096e: Retreived max purchase amount from global configuration (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT, quoteAsset=USDT, newBuyMaxPurchaseAmount=100)
[2021-05-23T23:00:00.051Z]  INFO: binance-api/19 on 86097728096e: Finish step - get-symbol-configuration (version=0.0.66, gitHash=e634670, server=cronjob, job=trailingTrade, uuid=61290ea7-c889-4aea-9057-09cf99cad244, stepName=get-symbol-configuration, symbol=ETHUSDT)
    data: {
      "symbol": "ETHUSDT",
      "isLocked": false,
      "featureToggle": {
        "notifyOrderConfirm": true,
        "notifyDebug": false
      },
      "lastCandle": {},
      "accountInfo": {
        "makerCommission": 10,
        "takerCommission": 10,
        "buyerCommission": 0,
        "sellerCommission": 0,
        "canTrade": true,
        "canWithdraw": true,
        "canDeposit": true,
        "updateTime": 1621787046973,
        "accountType": "SPOT",
        "balances": [
          {
            "asset": "BNB",
            "free": "0.00075161",
            "locked": "0.00000000"
          },
          {
            "asset": "ALGO",
            "free": "94.63475200",
            "locked": "0.00000000"
          },
          {
            "asset": "EUR",
            "free": "0.00360000",
            "locked": "99.99640000"
          }
        ],
        "permissions": [
          "SPOT"
        ]
      },
      "symbolConfiguration": {
        "_id": "60a98e875b575cfbdb884341",
        "key": "configuration",
        "enabled": true,
        "cronTime": "* * * * * *",
        "symbols": [
          "ETHUSDT",
          "XLMUSDT",
          "XRPUSDT",
          "ADAUSDT",
          "ALGOUSDT"
        ],
        "candles": {
          "interval": "15m",
          "limit": 100
        },
        "buy": {
          "enabled": true,
          "maxPurchaseAmount": 100,
          "triggerPercentage": 1.01,
          "stopPercentage": 1.02,
          "limitPercentage": 1.021
        },
        "sell": {
          "enabled": true,
          "triggerPercentage": 1.06,
          "stopPercentage": 0.98,
          "limitPercentage": 0.979,
          "stopLoss": {
            "enabled": false,
            "maxLossPercentage": 0.8,
            "disableBuyMinutes": 360,
            "orderType": "market"
          }
        },
        "system": {
          "temporaryDisableActionAfterConfirmingOrder": 20
        }
      },
      "indicators": {},
      "symbolInfo": {},
      "openOrders": [],
      "action": "not-determined",
      "baseAssetBalance": {},
      "quoteAssetBalance": {},
      "buy": {},
      "sell": {},
      "saveToCache": true
    }

chrisleekr commented 3 years ago

Thanks for more information, @alexandrucancescu

I could not find anything of value in the log except that lastCandle is an empty object

However, let me first explain a bit how the bot is working.

The bot is running the steps for each coin every second. See this code:https://github.com/chrisleekr/binance-trading-bot/blob/master/app/cronjob/trailingTrade.js#L81

Your log is showing the step get-symbol-configuration, which is the very first step before retrieving the last candle value.

The last candle value is getting from the step get-indicators, which is this code: https://github.com/chrisleekr/binance-trading-bot/blob/master/app/cronjob/trailingTrade/step/get-indicators.js#L56

If the bot is running in the background, then it does not prevent actions buy/sell even if the frontend is not working.

I am using a ssh tunnel to access the web UI.

Now, for your issue, what you need to check is whether you are receiving the data from the WebSocket of the bot.

And check your console of the browser.

And also try to access via local URL: http://0.0.0.0:8080

Let me know how it goes.

chrisleekr commented 3 years ago

@alexandrucancescu Please close the issue if your issue is resolved.

alexandrucancescu commented 3 years ago

I checked dev tools, and I can confirm that the server sends old data. The price of all signs is not updated and the server sends 1 hour old data.

Also, I will post some screenshot to show that the bot takes action using invalid data. It bought ALGO and has the trigger price for selling at 0.9785. The price of ALGO/USDT when I took the screenshot was 0.9794 but no order was placed, as the bot was making the decision based on the price from 1 hour ago.

Maybe Binance API blocks the requests after some time, but nothing shows in the logs. Also it wouldn't make sense for this to be the case, as restarting the container solves the problem everytime.

alexandrucancescu commented 3 years ago

If additional logs would be of any help I can post them. Put I have to wait a few hours until the bot gets stuck again.

And also try to access via local URL: http://0.0.0.0:8080

The server that is running the docker container is in another location. I am however using ssh port forwarding, which never raised any issues for me in the past.

ssh me@server_ip -L 8080:0.0.0.0:8080

Then I access http://localhost:8080 from Chrome.

Also this is most likely not an issued with the connection between the client and server because the client keeps receiving web socket data from the server even after the price gets stuck.

chrisleekr commented 3 years ago

@alexandrucancescu

I am running the bot in RPi 4. It has been running for 4 days. I don't have and never had that kind of issue. So definitely something else is going on.

I checked dev tools, and I can confirm that the server sends old data. The price of all signs is not updated and the server sends 1 hour old data.

The bot is receiving the current price from Binance WebSocket, which is running separately. And it saves the latest candle to cache.

https://github.com/chrisleekr/binance-trading-bot/blob/master/app/server-binance.js#L40

If the bot didn't receive the candle from Binance WebSocket, it automatically tries to re-connect.

https://github.com/chrisleekr/binance-trading-bot/blob/master/app/server-binance.js#L75

Here are some things you can do:

Add the following environment parameter to .env and re-launch the docker-compose
```
BINANCE_FEATURE_TOGGLE_NOTIFY_DEBUG=true
```
This feature toggle will send you more slack messages, which you may not want to receive it. Just set it up for now until you have that issue again.
When you find the price is not updating anymore, go to the server and run the following commands and paste them here
```
 reset; docker logs binance-bot -f --tail=100  | bunyan -c 'this.server == "binance"'
```

alexandrucancescu commented 3 years ago

Thanks. I will do that in a few days. Right now I am hunting some coins and can't afford to let it get stuck so I set up a crontab to restart the docker image every hour.

Is is ok if I leave the issue open until I get the time to debug it further?

chrisleekr commented 3 years ago

@alexandrucancescu Right, so crontab had fixed the issue.

Is is ok if I leave the issue open until I get the time to debug it further?

I prefer to close the issue for now and if you find that happening again, then re-open it. And we still don't know this is a bug of the bot, so I suggest changing the label to question.

alexandrucancescu commented 3 years ago

I don’t know if crontab fixed the issue. I just implemented the periodic restart. Keeping an eye on the bot it usually gets stuck after ~4 hours so I hope this is a good workaround.

alexandrucancescu commented 3 years ago

Ok, I managed to enable notifications by slack, and left it to run for a few hours, after it got stuck again I checked slack and I got the following error:

Next I'll run the command you provided and post the logs.

reset; docker logs binance-bot -f --tail=100  | bunyan -c 'this.server == "binance"'

alexandrucancescu commented 3 years ago

binance.log

alexandrucancescu commented 3 years ago

The error EAI_AGAIN is related to Docker and DNS from what I could gather from this issue. I am not using a VPN but added the DNS servers into /etc/docker/daemon.json nonetheless and will wait to see if this fixes it. Have you ever encountered this in Docker before?

chrisleekr commented 3 years ago

EAI_AGAIN is the message that your bot couldn't connect Binance API.

I can see from your log that your bot cannot receive the WebSocket data from Binance WebSocket.

[2021-05-26T19:41:35.780Z]  INFO: binance-api/18 on 01e20f6f3b31: Existing opened socket for candles found, clean first (version=0.0.66, gitHash=e634670, server=binance)
[2021-05-26T19:41:36.783Z]  WARN: binance-api/18 on 01e20f6f3b31: Binance candle is not received in last mintues. Reconfigure websocket (version=0.0.66, gitHash=e634670, server=binance, debug=true)

Since Binance WebSocket does not give you why your bot cannot receive the data, I suspect a time sync issue or MTU issue.

Can you first try to fix MTU and see how it goes?

chrisleekr commented 3 years ago

Close the issue as I didn't hear from you 3 days. Reopen if the issue persists.

chrisleekr / binance-trading-bot