Stops Receiving messages but can still send

[WombatHollow]

NR 2.2.2 Node-red-contrib-telegrambot 11.3.0 Raspbian on a Raspberry Pi 3B

The Node works well initially using Telegram Sender, Telegram Receiver and Telegram Command nodes but after a few days the receiver and Command Nodes stop producing any output to telegram messages but the Sender Node continues to function normally. Originally I restarted the RasPi (as I could do that remotely easily) to recover functionality but also recovered it if I tweak the Telegram Receiver node then just deployed modified Nodes the Telegram Receiver and Command nodes all start working again. When redeployed, both the Receiver and Command Nodes produce an output for the telegram messages sent before redeployment that were not processed then. this is like they are stuck in a queue and redeploy of a Receiver node has un stuck the queue.

Problem has existed for last 12 to 18 months (approx) since I started using the Telegram Nodes

Flow consists of a Sender node, a Receiver Node and 6 Command Nodes that all work initially. There is a Event Node which does nothing (still trying to workout what it does)

Here is the NR JSON for the bot, Receiver and one Command Node [{"id":"f38dbfb9.7221d","type":"telegram command","z":"8689ea2a.fc96b8","name":"","command":"^\\/[Nn][Rr]$","bot":"1637792c.79a397","strict":false,"hasresponse":true,"useregex":true,"removeregexcommand":true,"outputs":2,"x":80,"y":560,"wires":[["14c19955.dc6347","2e389571.edf8ba"],["317ccc1d.ee1234"]]},{"id":"68541946.e07118","type":"telegram receiver","z":"8689ea2a.fc96b8","name":"","bot":"1637792c.79a397","saveDataDir":"","filterCommands":false,"x":130,"y":260,"wires":[["ce8beed4.49563","3c8ebbf9.cc6314"],["15f00161.0ee8bf","d83f843126120f0b"]]},{"id":"1637792c.79a397","type":"telegram bot","botname":"WombatHollow_bot","usernames":"IanHarrison","chatids":"-574707818","baseapiurl":"","updatemode":"polling","pollinterval":"1000","usesocks":false,"sockshost":"","socksport":"6667","socksusername":"anonymous","sockspassword":"","bothost":"","botpath":"","localbotport":"8443","publicbotport":"8443","privatekey":"","certificate":"","useselfsignedcertificate":false,"sslterminated":false,"verboselogging":false}]

[WombatHollow]

A bit more behaviour information on above fault. Appears that redeploying a Receive or Command node does not restart the flow working, but redeploy of the BOT node does get the flow working again. I do get an error when I redeploy the bot, in the debug window of

26/06/2022, 16:46:34node: 1637792c.79a397 msg : string[36] "Error stopping node: Close timed out"

This node id is for the Telegram BOT node (I have deliberately xxx out the NGROK tunnel ID for security)

[windkh]

in version 11.5.0 timeout is set to 10s. please let me know if someting changed

[WombatHollow]

in version 11.5.0 timeout is set to 10s. please let me know if someting changed

OK thanks, I has updated to new version and restarted the RasPi. Will monitor for next few weeks to see if it stops again and report back.

[WombatHollow]

version 11.5.0 did not fix the problem, The Telegram Bot had stopped receiving again this morning when I tried. Again it is around a week after last redeploy of the Flow sheet containing the Telegram Bots Node.

[windkh]

Hm ... these kind of errors are only reported when running on a raspi. No idea why but probably the network drivers behave a little bit differently. Can you maybe try to reduce the polling interval and test again?

[windkh]

Some explanations about your findings: the configuration node that holds the token is responsible for polling messages from the TG server. If polling is disturbed or stopped at all for some reason, then the TG server stores the messages in a buffer. If you redeploy then polling is started again and then you get all messages from the server that were not fetched so far. The sender node is not affected by this as it sends the data via a standard http message. If the network is down, this message is lost and you would get an error. So the question is: what blocks or kills the polling on your raspi.

[WombatHollow]

Karl, we are on a Starlink connection that works very well but does still have odd outages (every few days) of up to a few minutes mostly due to Sattellite availability but occasionally we also get longer outage due weather (as example 30 minutes when a huge thunderstorm passed between us and Ground station)

So outages like this are common on radio based links (we have No wired connections). So what can automatically be done to detect that polling has stopped so when we detect the link is restored we can automatically restart polling.

I use this to remotely open and close secure tunnels from this system to me (somewhere in the internet). They must be initiated from the Pi as we are behind a CGNAT so dynamic IP doesn't work. So if I have no Tunnel open, I have no way to restart NR. Ta

On Wed, 20 Jul. 2022, 5:00 am Karl-Heinz Wind, @.***> wrote:

Some explanations about your findings: the configuration node that holds the token is responsible for polling messages from the TG server. If polling is disturbed or stopped at all for some reason, then the TG server stores the messages in a buffer. If you redeploy then polling is started again and then you get all messages from the server that were not fetched so far. The sender node is not affected by this as it sends the data via a standard http message. If the network is down, this message is lost and you would get an error. So the question is: what blocks or kills the polling on your raspi.

— Reply to this email directly, view it on GitHub https://github.com/windkh/node-red-contrib-telegrambot/issues/253#issuecomment-1189472056, or unsubscribe https://github.com/notifications/unsubscribe-auth/AGDP7BX73VFFGAC7H7MLP7DVU3647ANCNFSM5Y46W4MA . You are receiving this because you authored the thread.Message ID: @.***>

[WombatHollow]

Reduced polling to 3000, and still stopped after a few days. Have just reduced to 5000 and will see.

[WombatHollow]

Went 21 days with polling set at 5000. Not really the fix then. If the issue is node stops polling we need a m3ans to restart it automatically without a redeploy which is not practical where the node is remote.

[pcadminby]

I observe the same problem NR 2.2.2 Node-red-contrib-telegrambot 12.0.0 Ubuntu 20.04.4 LTS sends messages correctly but does not respond to commands. Polling Error (Polling interval 5000)

[windkh]

I could try to implement a kind of "autorestart after x minutes".... but I am not sure if this will help

[windkh]

@WombatHollow could you please turn on verbose logging in the node?

[WombatHollow]

I have upgrade Raspi to Bullseye and NR to 3.0.2 about 14 days ago so are no monitoring Telegram for drop outs. Non so far but there has been work on flows resulting Flows or NR being restarted. Will continue to monitor and if I can get a month continous with no problems then it may be fixed by NR 3.0.2, bullseye . Also just updating this node to 14.3.0

[WombatHollow]

OK, bumped it from 1000 to 2000. Will watch in for next few weeks when in internet range.

Ian

On Mon, 18 July 2022, 05:05 Karl-Heinz Wind, @.***> wrote:

Hm ... these kind of errors are only reported when running on a raspi. No idea why but probably the network drivers behave a little bit differently. Can you maybe try to reduce the polling interval and test again?

— Reply to this email directly, view it on GitHub https://github.com/windkh/node-red-contrib-telegrambot/issues/253#issuecomment-1186594798, or unsubscribe https://github.com/notifications/unsubscribe-auth/AGDP7BSDHKE735TQG3DO553VURN7TANCNFSM5Y46W4MA . You are receiving this because you authored the thread.Message ID: @.***>

[WombatHollow]

OK the fault occured again overnight. Here is a extract from Logs, NB the RBE error is where the ping of 8.8.8.8 and 198.142.152.163 (aka why two warn) doesn't respond with a number aka no internet which looks like two periods of 30 seconds (correlates with what Starlink reports two outages of 3 seconds). THe internet went down at 3:10 for 30 seconds and first bot error reports, it then reports a second error at 3:36 (20 minutes later) when internet was working. After that error the bot appears it may permanently stop polling. 14 Oct 03:10:43 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 03:10:43 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 03:10:48 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 03:10:48 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 03:10:53 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: getaddrin fo EAI_AGAIN api.telegram.org 14 Oct 03:10:53 - [warn] [telegram bot:1637792c.79a397] Network connection may b e down. Trying again. 14 Oct 03:36:06 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECON NRESET 14 Oct 03:36:06 - [warn] [telegram bot:1637792c.79a397] Network connection may b e down. Trying again. 14 Oct 04:46:19 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 04:46:19 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 04:46:24 - [warn] [rbe:Change>5 mSec] no number found in payload 14 Oct 04:46:24 - [warn] [rbe:Change>5 mSec] no number found in payload

Also when I restart the Telegram bot (I change polling interval and restart flow), this error was reported... although didnt stop normal operation being restored. 14 Oct 12:40:53 - [error] [telegram bot:1637792c.79a397] Error stopping node: Close timed out

[windkh]

I will setup a raspi to be able to reproduce that problem....

[windkh]

@WombatHollow I added a new node that allows you to stop and start the bot from within your flow. Maybe you can use this in your flow whenever you detect that the network is down. In that case you can stop the bot and if network is available you can call start.

[WombatHollow]

Thanks, just need a way for NR to detect the BOT has stopped polling (a catch doesn't seem to report this!). What I will do is get NR to restart the Bot each night, that way I will only loose my ability to send commands for rest of that day should it stop.

Ian

On Sun, 16 Oct 2022, 04:10 Karl-Heinz Wind, @.***> wrote:

@WombatHollow https://github.com/WombatHollow I added a new node that allows you to stop and start the bot from within your flow. Maybe you can use this in your flow whenever you detect that the network is down. In that case you can stop the bot and if network is available you can call start.

— Reply to this email directly, view it on GitHub https://github.com/windkh/node-red-contrib-telegrambot/issues/253#issuecomment-1279785330, or unsubscribe https://github.com/notifications/unsubscribe-auth/AGDP7BQE6ELTNFBKO4O6KE3WDLQRDANCNFSM5Y46W4MA . You are receiving this because you were mentioned.Message ID: @.***>

[windkh]

If you want to, you can even restart every few minutes... should not be a problem

[windkh]

Just to find out if it would really work

[windkh]

@WombatHollow I extended the control node for you: now it emits a message after every poll cycle. You can use these messages to detect a timeout.

[windkh]

@WombatHollow maybe this can be used https://flows.nodered.org/node/node-red-contrib-isonline

[WombatHollow]

Thanks, I have implemented that, will detect polling stops then wen internet is up issues message to restart polling. I will up the polling intervanl (from 10 to 1 sec) in order to accelerate testing

[WombatHollow]

Just noticed, the Telegram Control node continues to report every 10 seconds even though polling set to 1000 mSec

[windkh]

Yes I wondered, too. However a long poll times out after 10s when no new messages are available. You can test it when you send something to the bot it returns immediately

[windkh]

@WombatHollow I added a second output to the control to check isOnline

[WombatHollow]

@WombatHollow I added a second output to the control to check isOnline

I would wind that update back. I installed it and Ran OK, but when I enabled the 2nd output, NR started restarting every minute, Disabled 2nd output and redeployed and restarts went away but thereis a red triangle on the control Node stating invalid properties for -interval and -timeout. Here is a portion of logs Started Node-RED graphical event wiring tool. 21 Oct 14:55:06 - [red] Uncaught Exception: 21 Oct 14:55:06 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node -red-contrib-telegrambot/telegrambot/99-telegrambot.js:3024:27) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-tele grambot/telegrambot/99-telegrambot.js:2979:30) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 20.745s CPU time. nodered.service: Scheduled restart job, restart counter is at 23. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 20.745s CPU time. Started Node-RED graphical event wiring tool. 21 Oct 14:55:49 - [red] Uncaught Exception: 21 Oct 14:55:49 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3024:27) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:2979:30) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 21.009s CPU time. nodered.service: Scheduled restart job, restart counter is at 24. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 21.009s CPU time. Started Node-RED graphical event wiring tool.

[WombatHollow]

Re original problem, it occured again a few nights ago but the little detection circuit detected and restarted the Bot. The Log had more data in it so I have attached it. Restart of Bot was at 20 Oct@ 2:54 AM NR Log Telegram.txt

[windkh]

@WombatHollow I added a second output to the control to check isOnline

I would wind that update back. I installed it and Ran OK, but when I enabled the 2nd output, NR started restarting every minute, Disabled 2nd output and redeployed and restarts went away but thereis a red triangle on the control Node stating invalid properties for -interval and -timeout. Here is a portion of logs Started Node-RED graphical event wiring tool. 21 Oct 14:55:06 - [red] Uncaught Exception: 21 Oct 14:55:06 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node -red-contrib-telegrambot/telegrambot/99-telegrambot.js:3024:27) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-tele grambot/telegrambot/99-telegrambot.js:2979:30) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 20.745s CPU time. nodered.service: Scheduled restart job, restart counter is at 23. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 20.745s CPU time. Started Node-RED graphical event wiring tool. 21 Oct 14:55:49 - [red] Uncaught Exception: 21 Oct 14:55:49 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3024:27) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:2979:30) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 21.009s CPU time. nodered.service: Scheduled restart job, restart counter is at 24. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 21.009s CPU time. Started Node-RED graphical event wiring tool.

What URL did you use?

[windkh]

I reworked the offline and 2nd output code... please try again next version 14.8.6

[WombatHollow]

I was using the default URL. But I did type in interval and timout (defaults). Will try new version later today.

[WombatHollow]

THe problem still exist.

Here is LOG

23 Oct 12:34:03 - [red] Uncaught Exception: 23 Oct 12:34:03 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3010:23) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3076:26) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 1min 13.521s CPU time. nodered.service: Scheduled restart job, restart counter is at 1. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 1min 13.521s CPU time. Started Node-RED graphical event wiring tool. 23 Oct 12:34:46 - [red] Uncaught Exception: 23 Oct 12:34:46 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3010:23) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3076:26) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 21.115s CPU time. nodered.service: Scheduled restart job, restart counter is at 2. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 21.115s CPU time. Started Node-RED graphical event wiring tool. 23 Oct 12:35:29 - [red] Uncaught Exception: 23 Oct 12:35:29 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3010:23) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3076:26) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 21.127s CPU time. nodered.service: Scheduled restart job, restart counter is at 3. Stopped Node-RED graphical event wiring tool. nodered.service: Consumed 21.127s CPU time. Started Node-RED graphical event wiring tool. 23 Oct 12:36:13 - [red] Uncaught Exception: 23 Oct 12:36:13 - [error] TypeError [ERR_INVALID_URL]: Invalid URL at new NodeError (node:internal/errors:387:5) at URL.onParseError (node:internal/url:564:9) at new URL (node:internal/url:640:5) at TelegramControlNode.checkConnection (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3010:23) at Timeout._onTimeout (/home/pi/.node-red/node_modules/node-red-contrib-telegrambot/telegrambot/99-telegrambot.js:3076:26) at listOnTimeout (node:internal/timers:559:17) at processTimers (node:internal/timers:502:7) nodered.service: Main process exited, code=exited, status=1/FAILURE nodered.service: Failed with result 'exit-code'. nodered.service: Consumed 21.918s CPU time.

[windkh]

Can you send me your flow so that I can reproduce it? Or maybe only relevant portions of the flow ...

[WombatHollow]

As below but with the second output of the telegram control Node enabled [ { "id": "f88263fc87b5fc4b", "type": "telegram control", "z": "8689ea2a.fc96b8", "name": "", "bot": "1637792c.79a397", "outputs": 1, "checkconnection": false, "x": 270, "y": 1400, "wires": [ [ "a341b8d60ef60702", "afb38f249833a99a" ] ] }, { "id": "2b5ec9b9931526a5", "type": "debug", "z": "8689ea2a.fc96b8", "name": "Telegrambot", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "true", "targetType": "full", "statusVal": "", "statusType": "auto", "x": 1090, "y": 1480, "wires": [] }, { "id": "5f2f95c672901b9e", "type": "inject", "z": "8689ea2a.fc96b8", "name": "", "props": [ { "p": "payload" }, { "p": "topic", "vt": "str" } ], "repeat": "", "crontab": "", "once": false, "onceDelay": 0.1, "topic": "", "payload": "restart", "payloadType": "str", "x": 90, "y": 1480, "wires": [ [ "f88263fc87b5fc4b" ] ] }, { "id": "a341b8d60ef60702", "type": "trigger", "z": "8689ea2a.fc96b8", "name": "Polling stopped", "op1": "", "op2": "restart", "op1type": "nul", "op2type": "str", "duration": "1", "extend": true, "overrideDelay": false, "units": "min", "reset": "", "bytopic": "all", "topic": "topic", "outputs": 1, "x": 480, "y": 1400, "wires": [ [ "bbde9cb7af096586" ] ] }, { "id": "bbde9cb7af096586", "type": "is online", "z": "8689ea2a.fc96b8", "name": "Wait for internet", "url": "", "action": "1", "x": 680, "y": 1400, "wires": [ [ "75362a7a65163e4d", "2b5ec9b9931526a5" ] ] }, { "id": "75362a7a65163e4d", "type": "switch", "z": "8689ea2a.fc96b8", "name": "", "property": "online", "propertyType": "msg", "rules": [ { "t": "true" }, { "t": "false" } ], "checkall": "true", "repair": false, "outputs": 2, "x": 850, "y": 1340, "wires": [ [ "cb83d456fc8e9be8" ], [ "a341b8d60ef60702" ] ] }, { "id": "18f65248dfea27eb", "type": "inject", "z": "8689ea2a.fc96b8", "name": "", "props": [ { "p": "payload" }, { "p": "topic", "vt": "str" } ], "repeat": "", "crontab": "", "once": false, "onceDelay": 0.1, "topic": "", "payload": "restart", "payloadType": "str", "x": 490, "y": 1480, "wires": [ [ "bbde9cb7af096586" ] ] }, { "id": "c2f22675973398a4", "type": "link out", "z": "8689ea2a.fc96b8", "name": "link out 1", "mode": "link", "links": [ "72b624fe.986dfc" ], "x": 1255, "y": 1400, "wires": [] }, { "id": "20a7603acfd8be94", "type": "change", "z": "8689ea2a.fc96b8", "name": "Set telegram message", "rules": [ { "t": "set", "p": "payload", "pt": "msg", "to": "Telegram Polling restarted", "tot": "str" } ], "action": "", "property": "", "from": "", "to": "", "reg": false, "x": 1120, "y": 1400, "wires": [ [ "c2f22675973398a4" ] ] }, { "id": "b06cdff9ece0ccdd", "type": "comment", "z": "8689ea2a.fc96b8", "name": "Check NR polling OK", "info": "The Telegrambot Node has a issue on a \n Raspi that polling stops periodically. \n It appears this occurs after a outage of \n the internet for a few polling intervals.\nThis detects if polling stops and when the\n internet is restored issues a restart of \n polling.", "x": 120, "y": 1360, "wires": [] }, { "id": "d50f946c733cb9eb", "type": "debug", "z": "8689ea2a.fc96b8", "name": "debug 13", "active": true, "tosidebar": true, "console": false, "tostatus": false, "complete": "payload", "targetType": "msg", "statusVal": "", "statusType": "auto", "x": 700, "y": 1540, "wires": [] }, { "id": "afb38f249833a99a", "type": "change", "z": "8689ea2a.fc96b8", "name": "", "rules": [ { "t": "set", "p": "payload", "pt": "msg", "to": "payload.duration", "tot": "msg" } ], "action": "", "property": "", "from": "", "to": "", "reg": false, "x": 480, "y": 1540, "wires": [ [ "d50f946c733cb9eb" ] ] }, { "id": "cb83d456fc8e9be8", "type": "junction", "z": "8689ea2a.fc96b8", "x": 980, "y": 1400, "wires": [ [ "f88263fc87b5fc4b", "20a7603acfd8be94", "2b5ec9b9931526a5" ] ] }, { "id": "1637792c.79a397", "type": "telegram bot", "botname": "WombatHollow_bot", "usernames": "IanHarrison", "chatids": "-574707818", "baseapiurl": "", "updatemode": "polling", "pollinterval": "1000", "usesocks": false, "sockshost": "", "socksport": "6667", "socksusername": "anonymous", "sockspassword": "", "bothost": "", "botpath": "", "localbotport": "8443", "publicbotport": "8443", "privatekey": "", "certificate": "", "useselfsignedcertificate": false, "sslterminated": false, "verboselogging": true } ]

[WombatHollow]

And the red triangle is still their, even though I entered values (double the default)

[windkh]

@WombatHollow thanks for the flow, I guess I found a bug in the configuration of the control node. Sorry for inconvenience... please try 14.8.7 and report back.

[WombatHollow]

OK, Control node now appears to work OK.
Albeit I have enabled the 2nd output, I am only monitoring it...still using the flow logic above, just set the monitor URL to apt.telegram.org.

[WombatHollow]

Logs from last night, had a spell around 4PM, but the Telegram BOT 'EFATAL: Error: read ECONNRESET' but didn't loose it's polling of Telegram, nor was a restart of the Bot triggered by the flow (see above). Starlink modem showed only 35 seconds of internet connection downtime overnight. Node-red flows (Ping) only detected one instance of internet ping timeout (at 26 Oct 03:57:37, the RBE warning is because ping returned a non number).

`26 Oct 03:52:16 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 03:52:16 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 03:55:29 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 03:55:29 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 03:55:52 - [warn] [rbe:Change>5 mSec] no number found in payload 26 Oct 03:55:56 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ETIMEDOUT 26 Oct 03:55:56 - [warn] [telegram bot:1637792c.79a397] Unknown error. Trying again. Unhandled rejection RequestError: Error: read ETIMEDOUT at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 03:55:57 - [warn] [rbe:Change>5 mSec] no number found in payload 26 Oct 03:56:00 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 03:56:00 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 03:57:08 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 03:57:08 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 03:57:37 - [warn] [rbe:Change>5 mSec] no number found in payload 26 Oct 03:57:39 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 03:57:39 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 03:58:04 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 03:58:04 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) 26 Oct 04:03:51 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 26 Oct 04:03:51 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21)

`

[windkh]

@WombatHollow thanks, so the bot continued polling which is good.

The errors you can see in the log are generated by the polling loop inside the bot lib. The offline detection is some loop that runs next to the polling loop as a kind of watch dog. This one triggers if the first locks up.

So during last night the bot did not crash, is that correct?

[WombatHollow]

No, botmwas still working in the morning. My time out detector was not triggered (as it wait for longer), so I guess your restart inside control node restore polling first. Wasn't aware you had instigated restart function, thanks for that.

Will monitor and when happy remove my extra restart functionality.

On Wed, 26 Oct 2022, 20:02 Karl-Heinz Wind, @.***> wrote:

@WombatHollow https://github.com/WombatHollow thanks, so the bot continued polling which is good.

The errors you can see in the log are generated by the polling loop inside the bot lib. The offline detection is some loop that runs next to the polling loop as a kind of watch dog. This one triggers if the first locks up.

So during last night the bot did not crash, is that correct?

— Reply to this email directly, view it on GitHub https://github.com/windkh/node-red-contrib-telegrambot/issues/253#issuecomment-1291723593, or unsubscribe https://github.com/notifications/unsubscribe-auth/AGDP7BST4UHYB5G2AQN6OWDWFDXRLANCNFSM5Y46W4MA . You are receiving this because you were mentioned.Message ID: @.***>

[WombatHollow]

Sorry but problem persists, jut not so often. Stopped again last night, Bot sends but does not receive messages. The Control Node just says Connected, and reports on the second output 'Online'. Nothing comes out of the First output.

From my telegram reports, Restart was applied (by my in activity detector) at 0:29 and later at 4:09. The Control Node reported offline (timeout) at 0:10, 0:29, 0:35 and 3:55 but each time was back online in the same minute. According to Star Link Modem, total down time in a last 12 hours including this drop outs were 97 seconds

Log is as follows `

at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31)
at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22)
at Request.emit (node:events:513:28)
at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8)
at ClientRequest.emit (node:events:513:28)
at TLSSocket.socketErrorListener (node:_http_client:481:9)
at TLSSocket.emit (node:events:513:28)
at emitErrorNT (node:internal/streams/destroy:157:8)
at emitErrorCloseNT (node:internal/streams/destroy:122:3)
at processTicksAndRejections (node:internal/process/task_queues:83:21)

4 Nov 04:09:21 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: read ECONNRESET 4 Nov 04:09:21 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: read ECONNRESET at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21)

` Appling a restart to control node makes no change.

Editing the BOT (I change polling interval a small amount) and redeploying the flow restores functionality including Control Node reporting on first output.

[windkh]

@WombatHollow thanks for your detailed report. The one thing that is really strange: A restart via control node does not help, only a redeploy? Hm ...

[windkh]

I guess that I must handle this ECONNRESET internally. Maybe I can catch that somewhere and try to reestablish the connection automatically...

[WombatHollow]

I do see a few other Errors in the log, they might be related, this one was EAI_AGAIN 11 Nov 13:08:19 - [warn] [telegram bot:1637792c.79a397] EFATAL: Error: getaddrinfo EAI_AGAIN api.telegram.org 11 Nov 13:08:19 - [warn] [telegram bot:1637792c.79a397] Network connection may be down. Trying again. Unhandled rejection RequestError: Error: getaddrinfo EAI_AGAIN api.telegram.org at new RequestError (/home/pi/.node-red/node_modules/request-promise-core/lib/errors.js:14:15) at Request.plumbing.callback (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:87:29) at Request.RP$callback [as _callback] (/home/pi/.node-red/node_modules/request-promise-core/lib/plumbing.js:46:31) at self.callback (/home/pi/.node-red/node_modules/request/request.js:185:22) at Request.emit (node:events:513:28) at Request.onRequestError (/home/pi/.node-red/node_modules/request/request.js:877:8) at ClientRequest.emit (node:events:513:28) at TLSSocket.socketErrorListener (node:_http_client:481:9) at TLSSocket.emit (node:events:513:28) at emitErrorNT (node:internal/streams/destroy:157:8) at emitErrorCloseNT (node:internal/streams/destroy:122:3) at processTicksAndRejections (node:internal/process/task_queues:83:21) This one was associated with the Control Node reporting Offline, then Online and then my detection circuit detected no activity and imposed a restart all within that 13:08 minute timeslot

[windkh]

Yes the logs are ceeated when there is a problem. But I guess only the error indicating connection reset causes the problems you described

[windkh]

@WombatHollow Error: getaddrinfo EAI_AGAIN api.telegram.org This means that the network was down when the node tried to get the latest messages from the telegram server

ECONNRESET means that the node called the server but while waiting for the response the network was lost (not sure about that interpretation)

ETIMEDOUT means that the network was ok but the response was not received in time which could indicate that the network was ok but either the telegram server does not answer or the network is broken far away ...

Indeed the node creates a longpoll of 10s which means that the GET call to telegram is blocked for max of 10 seconds on the server side. If messages arrive at the TG server then the response is created within that 10s or a timeout is created without returning any messages ... the node will then continue polling after a while with the next long poll.

[windkh]

@WombatHollow One idea that you could try when the connection can only be restored using a warm reload

[{"id":"a7eb189d.f5e538","type":"comment","z":"759ef5a1.faa53c","name":"Warm reboot","info":"","x":330,"y":120,"wires":[]},{"id":"a06415d6.7ed3c8","type":"function","z":"759ef5a1.faa53c","name":"Request Token","func":"msg.payload = {\n \"client_id\": \"node-red-editor\",\n \"grant_type\": \"password\",\n \"scope\": \"*\",\n \"username\": \"engineer\",\n \"password\": \"Pa$$w0rd\"\n}\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":340,"y":170,"wires":[["47aa4d07.5bae94"]]},{"id":"649f96c6.bc9128","type":"inject","z":"759ef5a1.faa53c","name":"Manual reload","repeat":"","crontab":"","once":false,"onceDelay":"","topic":"","payload":"","payloadType":"str","x":130,"y":170,"wires":[["a06415d6.7ed3c8"]]},{"id":"47aa4d07.5bae94","type":"http request","z":"759ef5a1.faa53c","name":"Token","method":"POST","ret":"txt","paytoqs":"ignore","url":"http://localhost:1880/auth/token","tls":"","persist":false,"proxy":"","authType":"","credentials":{},"x":490,"y":170,"wires":[["d69beb8b.7008a8"]],"info":"Note:\nEnsure the path is correct\nif httpAdminRoot: '/admin' is activated then \nthis needs to be added to\nhttp://localhost:1880/"},{"id":"d69beb8b.7008a8","type":"function","z":"759ef5a1.faa53c","name":"Confirm token","func":"// get the status of the request\nvar status = msg.statusCode;\n\nvar token = '';\nmsg.headers ={};\n\n//let node = feedback;\n\nswitch(status){\n case 200:\n node.log(\"Secure restart\");\n token = JSON.parse(msg.payload);\n token = 'Bearer '+token.access_token;\n msg.headers = {\n \"Authorization\": token,\n \"Node-RED-Deployment-Type\":\"reload\"\n }\n//msg.payload =\"\";\n break;\n case 204:\n node.log(\"Secure without restart\");\n break;\n case 400:\n node.warn(\"Bad request\");\n break;\n case 401:\n node.warn(\"Not authorized\");\n break;\n case 403:\n node.warn(\"Forbidden\");\n break;\n case 404:\n node.log(\"Unsecure restart\");\n msg.headers = {\n \"Node-RED-Deployment-Type\":\"reload\"\n }\n break;\n case 409:\n node.warn(\"Version mismatch\");\n break;\n case 500:\n node.error(\"Server Error\");\n break;\n default:\n node.warn(\"Unknown Error\");\n break;\n}\n\nmsg.payload = \"\";\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","x":640,"y":170,"wires":[["ccd455c1.f34318"]],"info":"Restart of Node-Red flows.\nWill check if the action needs security or not.\nNote: if the first 5 attemps return a statuscode 403 'forbidden'\nthen the server will break and only way to recover is then to\nrestart the service"},{"id":"ccd455c1.f34318","type":"http request","z":"759ef5a1.faa53c","name":"Restart","method":"POST","ret":"txt","paytoqs":"ignore","url":"http://localhost:1880/flows","tls":"","persist":false,"proxy":"","authType":"","credentials":{},"x":800,"y":170,"wires":[[]],"info":"Note:\nEnsure the path is correct\nif httpAdminRoot: '/admin' is activated then \nthis needs to be added to\nhttp://localhost:1880/"}]

[WombatHollow]

Well suddenly this Bot has gone from frequent polling errors as above, and losing 5% of sent messages. Problems remained after update of Node to v18, NR to 3.1.0. Then a week ago, Send errors dropped to 0% and reported Telegram BOT stopping also went to 0. What changed

1. I uninstalled the Telegram Node from NR and reinstalled it fresh and inserted the nodes required back into my Flow;
2. I created a now BOT through Telegrams BotFather, but I haven't used it (yep probably a red herring);

I then had a look at the FLOW JSON at this point, and from 3 months ago for differences and found 3

1. THe Node ID had changed and is of the new format.
2. a line "d": true, no longer exists
3. I no longer specified any Chatid's in the Bot node (previously one of the 3 in use was specified).

I haven't yet tried to update node to v20 again (see issue #343 )