windkh
Random restarts of Node-RED caused by Shelly plugin
Hi,
I need some help with an issue I'm encountering.
I'm getting these error messages whenever there's a random restart of NR:
9 Jun 12:38:03 - [red] Uncaught Exception:
9 Jun 12:38:03 - [error] AxiosError: timeout of 5000ms exceeded
at RedirectableRequest.handleRequestTimeout (/home/pi/.node-red/node_modules/axios/lib/adapters/http.js:647:16)
at RedirectableRequest.emit (node:events:519:28)
at Timeout.<anonymous> (/home/pi/.node-red/node_modules/follow-redirects/index.js:210:12)
at listOnTimeout (node:internal/timers:573:17)
at processTimers (node:internal/timers:514:7)
at Axios.request (/home/pi/.node-red/node_modules/axios/lib/core/Axios.js:45:41)
at runNextTicks (node:internal/process/task_queues:60:5)
at listOnTimeout (node:internal/timers:540:9)
at processTimers (node:internal/timers:514:7)
nodered.service: Main process exited, code=exited, status=1/FAILURE
nodered.service: Failed with result 'exit-code'.
nodered.service: Consumed 7min 24.362s CPU time.
nodered.service: Scheduled restart job, restart counter is at 20.
Stopped nodered.service - Node-RED graphical event wiring tool.
nodered.service: Consumed 7min 24.362s CPU time.
Started nodered.service - Node-RED graphical event wiring tool.
9 Jun 12:38:25 - [info]
Welcome to Node-RED
===================
9 Jun 12:38:25 - [info] Node-RED version: v3.1.9
9 Jun 12:38:25 - [info] Node.js version: v20.14.0
9 Jun 12:38:25 - [info] Linux 6.6.31+rpt-rpi-v8 arm64 LE
9 Jun 12:38:25 - [info] Loading palette nodes
9 Jun 12:38:28 - [info] Dashboard version 3.6.5 started at /ui
9 Jun 12:38:28 - [info] Settings file : /home/pi/.node-red/settings.js
9 Jun 12:38:28 - [info] Context store : 'default' [module=memory]
9 Jun 12:38:28 - [info] User directory : /home/pi/.node-red
9 Jun 12:38:28 - [warn] Projects disabled : editorTheme.projects.enabled=false
9 Jun 12:38:28 - [info] Flows file : /home/pi/.node-red/flows.json
9 Jun 12:38:28 - [info] Server now running at http://127.0.0.1:1880/
9 Jun 12:38:28 - [info] Starting flows
9 Jun 12:38:29 - [info] Started flows
Shelly gen1 server is listening on port 20001
Shelly gen2 server is listening on port 10001
My setup:
[
{
"id": "1cb729744d7be53d",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.37",
"description": "Water Heater - Basement",
"mode": "polling",
"server": "",
"outputmode": "event",
"uploadretryinterval": 5000,
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": true,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 750,
"y": 1200,
"wires": [
[]
]
},
{
"id": "5f72fa3adf200141",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.39",
"description": "Water Heater - Work",
"mode": "polling",
"server": "",
"outputmode": "event",
"uploadretryinterval": 5000,
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": true,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 740,
"y": 1260,
"wires": [
[]
]
},
{
"id": "02f241a770528413",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.37",
"description": "Water Heater - Basement",
"mode": "polling",
"server": "04263f2d054cc2a1",
"uploadretryinterval": "5000",
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": false,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 390,
"y": 1340,
"wires": [
[
"4e572747190b24b3"
]
]
},
{
"id": "b81ad76ecee44bcb",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.39",
"description": "Water Heater - Work",
"mode": "polling",
"server": "04263f2d054cc2a1",
"uploadretryinterval": "5000",
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": false,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 380,
"y": 1400,
"wires": [
[
"57eb76c1b3c06e5b"
]
]
},
{
"id": "b67c0231bc6cb96f",
"type": "shelly-gen1",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"hostname": "10.0.10.24",
"description": "Shelly Plug S - Solax Cooling",
"mode": "polling",
"server": "033a6e9acf499057",
"uploadretryinterval": "5000",
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": false,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 1240,
"y": 1280,
"wires": [
[
"4641e7b609b2a776"
]
]
},
{
"id": "753157d6fb24b30a",
"type": "shelly-gen1",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"hostname": "10.0.10.24",
"description": "Shelly Plug S - Solax Cooling",
"mode": "polling",
"server": "",
"outputmode": "event",
"uploadretryinterval": 5000,
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": true,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 1480,
"y": 1200,
"wires": [
[]
]
},
{
"id": "04263f2d054cc2a1",
"type": "shelly-gen2-server",
"port": "10001",
"hostname": "unimatrix"
},
{
"id": "033a6e9acf499057",
"type": "shelly-gen1-server",
"port": "20001",
"hostname": ""
}
]
Can anyone help me figure out what I'm doing wrong?
One just to get status every 1s and one for switching ON / OFF every 15 minutes - water heaters while feed in energy (solar)
@MrMysakovich I can only see a portion of your flow.... you are using the same IP address in different nodes
All of your nodes poll the shelly every 5 seconds which means that it can happen that you poll the same shelly at almost the same time from two nodes.
- Even if two nodes call the shelly at the same time node-red must not crash --> I will try to reproduce that and find a solution
- Can you change the mode of the nodes from "polling" to "callback" or to "none" to crosscheck that the problem comes from my theory.
- Can you send me the full flow?
Yes, because I use the first node for inject every 1s (status) and the second one every 15 minutes for switching ON / OFF.
- Maybe I can add one information more that I use same Shellys in Homebridge too.
- I will try to set it to none.
[
{
"id": "856b984c5428f3bf",
"type": "inject",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"name": "inject 1x za 1s",
"props": [
{
"p": "payload"
},
{
"p": "topic",
"vt": "str"
}
],
"repeat": "1",
"crontab": "",
"once": true,
"onceDelay": "10",
"topic": "",
"payload": "",
"payloadType": "date",
"x": 160,
"y": 1340,
"wires": [
[
"02f241a770528413",
"b81ad76ecee44bcb"
]
]
},
{
"id": "02f241a770528413",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.37",
"description": "Water Heater - Basement",
"mode": "polling",
"server": "04263f2d054cc2a1",
"uploadretryinterval": "5000",
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": false,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 390,
"y": 1340,
"wires": [
[
"4e572747190b24b3"
]
]
},
{
"id": "b81ad76ecee44bcb",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.39",
"description": "Water Heater - Work",
"mode": "polling",
"server": "04263f2d054cc2a1",
"uploadretryinterval": "5000",
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": false,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 380,
"y": 1400,
"wires": [
[
"57eb76c1b3c06e5b"
]
]
},
{
"id": "4e572747190b24b3",
"type": "function",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"name": "Hlavní bojler",
"func": "if (msg.payload.switch0.output === true) {\n msg.payload.switch0.output = \"Zapnuto\";\n} else {\n msg.payload.switch0.output = \"Vypnuto\";\n}\nreturn { payload: msg.payload.switch0.output };",
"outputs": 1,
"timeout": 0,
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 590,
"y": 1340,
"wires": [
[
"10d01ad10ee60225"
]
]
},
{
"id": "57eb76c1b3c06e5b",
"type": "function",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"name": "Vedlejší bojler",
"func": "if (msg.payload.switch0.output === true) {\n msg.payload.switch0.output = \"Zapnuto\";\n} else {\n msg.payload.switch0.output = \"Vypnuto\";\n}\nreturn { payload: msg.payload.switch0.output };",
"outputs": 1,
"timeout": 0,
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 600,
"y": 1400,
"wires": [
[
"c93a18a601770f58"
]
]
},
{
"id": "10d01ad10ee60225",
"type": "ui_text",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"group": "7ab912b224a2e5e9",
"order": 1,
"width": "0",
"height": "0",
"name": "",
"label": "Hlavní bojler",
"format": "{{msg.payload}}",
"layout": "row-spread",
"className": "",
"style": false,
"font": "",
"fontSize": "",
"color": "#000000",
"x": 770,
"y": 1340,
"wires": []
},
{
"id": "c93a18a601770f58",
"type": "ui_text",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"group": "7ab912b224a2e5e9",
"order": 2,
"width": "0",
"height": "0",
"name": "",
"label": "Vedlejší bojler",
"format": "{{msg.payload}}",
"layout": "row-spread",
"className": "",
"style": false,
"font": "",
"fontSize": "",
"color": "#000000",
"x": 780,
"y": 1400,
"wires": []
},
{
"id": "c22d652471825384",
"type": "inject",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"name": "inject 1x za 15 minut",
"props": [
{
"p": "payload"
},
{
"p": "topic",
"vt": "str"
}
],
"repeat": "900",
"crontab": "",
"once": true,
"onceDelay": "60",
"topic": "",
"payload": "",
"payloadType": "date",
"x": 180,
"y": 1200,
"wires": [
[
"ae5a5b2ad4937485",
"44a9fac79d02c5ad"
]
]
},
{
"id": "ae5a5b2ad4937485",
"type": "function",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"name": "Spínání hlavního bojleru",
"func": "var feedin_power = flow.get (\"feedin_power\")\nvar shelly = flow.get(\"shelly\");\n\nvar relayState = {\n relay: 0,\n on: false\n};\n\nif (feedin_power > 1000) {\n relayState.on = true;\n}\n\nif (relayState.on) {\n msg.payload = {\n method: \"Switch.Set\",\n parameters: {\n id: 0,\n on: true\n }\n };\n} else {\n msg.payload = {\n method: \"Switch.Set\",\n parameters: {\n id: 0,\n on: false\n }\n };\n}\n\nreturn msg;\n",
"outputs": 1,
"timeout": 0,
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 430,
"y": 1200,
"wires": [
[
"1cb729744d7be53d"
]
]
},
{
"id": "1cb729744d7be53d",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.37",
"description": "Water Heater - Basement",
"mode": "polling",
"server": "",
"outputmode": "event",
"uploadretryinterval": 5000,
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": true,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 750,
"y": 1200,
"wires": [
[]
]
},
{
"id": "5f72fa3adf200141",
"type": "shelly-gen2",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"hostname": "10.0.10.39",
"description": "Water Heater - Work",
"mode": "polling",
"server": "",
"outputmode": "event",
"uploadretryinterval": 5000,
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": true,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 740,
"y": 1260,
"wires": [
[]
]
},
{
"id": "44a9fac79d02c5ad",
"type": "function",
"z": "04ae3d56e09f0645",
"g": "6913adfeb31ec056",
"name": "Spínání vedlejšího bojleru + HDO",
"func": "var feedin_power = flow.get(\"feedin_power\");\nvar vysledekHDO = global.get(\"vysledekHDO\");\nvar shelly = flow.get(\"shelly\");\n\nif (vysledekHDO === \"NT\") {\n msg.payload = {\n method: \"Switch.Set\",\n parameters: {\n id: 0,\n on: true,\n }\n };\n} else if (feedin_power > 1000) {\n msg.payload = {\n method: \"Switch.Set\",\n parameters: {\n id: 0,\n on: true,\n }\n };\n} else {\n msg.payload = {\n method: \"Switch.Set\",\n parameters: {\n id: 0,\n on: false,\n }\n };\n}\n\nreturn msg;",
"outputs": 1,
"timeout": 0,
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 460,
"y": 1260,
"wires": [
[
"5f72fa3adf200141"
]
]
},
{
"id": "80037bb69b86efc0",
"type": "inject",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"name": "inject 1x za 5s",
"props": [
{
"p": "payload"
},
{
"p": "topic",
"vt": "str"
}
],
"repeat": "5",
"crontab": "",
"once": true,
"onceDelay": "10",
"topic": "",
"payload": "",
"payloadType": "date",
"x": 1020,
"y": 1200,
"wires": [
[
"75faecb7513cc6be"
]
]
},
{
"id": "75faecb7513cc6be",
"type": "function",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"name": "Spínání chlazení střídače",
"func": "var InvTemperature = flow.get(\"InvTemperature\")\nvar shelly = flow.get(\"shelly\");\n\nvar relayState = {\n relay: 0,\n on: false\n};\n\nif (InvTemperature > 46) {\n relayState.on = true;\n}\n\nif (relayState.on) {\n msg.payload = {\n relay: 0,\n on: true\n };\n} else {\n msg.payload = {\n relay: 0,\n on: false\n };\n}\n\nreturn msg;\n",
"outputs": 1,
"timeout": 0,
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 1230,
"y": 1200,
"wires": [
[
"753157d6fb24b30a"
]
]
},
{
"id": "753157d6fb24b30a",
"type": "shelly-gen1",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"hostname": "10.0.10.24",
"description": "Shelly Plug S - Solax Cooling",
"mode": "polling",
"server": "",
"outputmode": "event",
"uploadretryinterval": 5000,
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": true,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 1480,
"y": 1200,
"wires": [
[]
]
},
{
"id": "59d2db7e33eb38b6",
"type": "inject",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"name": "inject 1x za 1s",
"props": [
{
"p": "payload"
},
{
"p": "topic",
"vt": "str"
}
],
"repeat": "1",
"crontab": "",
"once": true,
"onceDelay": "10",
"topic": "",
"payload": "",
"payloadType": "date",
"x": 1020,
"y": 1280,
"wires": [
[
"b67c0231bc6cb96f"
]
]
},
{
"id": "b67c0231bc6cb96f",
"type": "shelly-gen1",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"hostname": "10.0.10.24",
"description": "Shelly Plug S - Solax Cooling",
"mode": "polling",
"server": "033a6e9acf499057",
"uploadretryinterval": "5000",
"pollinginterval": "5000",
"pollstatus": false,
"getstatusoncommand": false,
"devicetype": "Relay",
"devicetypemustmatchexactly": false,
"outputs": 1,
"x": 1240,
"y": 1280,
"wires": [
[
"4641e7b609b2a776"
]
]
},
{
"id": "4641e7b609b2a776",
"type": "function",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"name": "Chlazení střídače",
"func": "if (msg.payload.relays[0].ison === true) {\n msg.payload.relays[0].ison = \"Zapnuto\";\n} else {\n msg.payload.relays[0].ison = \"Vypnuto\";\n}\nreturn { payload: msg.payload.relays[0].ison };",
"outputs": 1,
"timeout": "",
"noerr": 0,
"initialize": "",
"finalize": "",
"libs": [],
"x": 1470,
"y": 1280,
"wires": [
[
"27d7bf6139036df6"
]
]
},
{
"id": "27d7bf6139036df6",
"type": "ui_text",
"z": "04ae3d56e09f0645",
"g": "4471973aed0d711c",
"group": "b95997595a206299",
"order": 3,
"width": "0",
"height": "0",
"name": "",
"label": "Chlazení střídače",
"format": "{{msg.payload}}",
"layout": "row-spread",
"className": "",
"style": false,
"font": "",
"fontSize": "",
"color": "#000000",
"x": 1670,
"y": 1280,
"wires": []
},
{
"id": "04263f2d054cc2a1",
"type": "shelly-gen2-server",
"port": "10001",
"hostname": "unimatrix"
},
{
"id": "7ab912b224a2e5e9",
"type": "ui_group",
"name": "Vyhřívání bojlerů",
"tab": "c28c1c92b7ceb034",
"order": 4,
"disp": true,
"width": "9",
"collapse": false,
"className": ""
},
{
"id": "033a6e9acf499057",
"type": "shelly-gen1-server",
"port": "20001",
"hostname": ""
},
{
"id": "b95997595a206299",
"type": "ui_group",
"name": "Střídač",
"tab": "c28c1c92b7ceb034",
"order": 7,
"disp": true,
"width": "9",
"collapse": false,
"className": ""
},
{
"id": "c28c1c92b7ceb034",
"type": "ui_tab",
"name": "FVE",
"icon": "dashboard",
"order": 1,
"disabled": false,
"hidden": false
}
]
@MrMysakovich I am running your flow here and it seems to work fine... after what time did you get the restarts?
@MrMysakovich I see that you trigger your node with an inject node. And at the same time you poll the device every 5000ms. This does not really make sense to do it twice. Either you use mode none and the inject node or you remove the inject node and let the shelly node poll for you. In addition to that: if you only want to be noticed when the some switch is triggered then you better use callback mode. Until now your flow works here without problems. Do you use additional flows that may cause additional CPU load or do you run the flow on a low performance hardware like a raspberry?
@windkh I already have it set to "none" and it still restarts Node-RED with the same log output (even Shelly node sometimes says 5000 ms time exceeded even when I have set polling to "none") I have in the same flow also modbus-getter to Solax Hybrid G4 and I read live data from it. Running Node-RED on Raspberry Pi 4B 8GB ram - Homebridge image.
Ok then it means that sending the command request to the shelly timed out. I assume that you are running the raspi via wifi?
No, wired and I never had problem with Shelly through Homebridge. Really don’t know why it happens :/ Btw Shelly connection is stable.
@MrMysakovich I just tried to reproduce the problem: if I just remove the shelly from the network I get exactly the same output. However node-red does not restart here.
@windkh please install V10.25.1 I change a few timeout. If it happens again please send me the node-red log
@windkh I updated it. Thank you. Lets see it in few days. Maybe it could be caused that Homebridge image doesn't work well together with Node-RED?
@MrMysakovich well the call stack is the same as mine here but my node-red does not restart. I wrap all requests to the shelly with a try catch to avoid that node-red will crash. In you callstack it seems that there was no catch somewhere. In my code I could not find the problem as there are many requests that could cause that. So I added unique timeouts to every request 5001, 5002, ... so we will probably see more in the next stack trace...
@windkh So it crashed again, but unfortunately I do not have logs, because somehow logging stopped working. Could you help me please to setup settings.js to log everything?
I got this in NR:
The main problem is that I get the NR log as a service from the Homebridge terminal, and the logging is active until I exit the window.
18 Jun 13:11:54 - [warn] [shelly-gen1:b67c0231bc6cb96f] timeout of 5012ms exceeded
18 Jun 13:13:48 - [warn] [shelly-gen2:b81ad76ecee44bcb] AxiosError: timeout of 5022ms exceeded
18 Jun 13:48:54 - [warn] [shelly-gen1:b67c0231bc6cb96f] timeout of 5012ms exceeded
18 Jun 13:59:06 - [warn] [shelly-gen1:b67c0231bc6cb96f] timeout of 5012ms exceeded
18 Jun 14:58:06 - [warn] [shelly-gen2:02f241a770528413] AxiosError: timeout of 5022ms exceeded
This time there was no restart of NR.
UPDATE: So far, Node-RED hasn't rebooted yet. Let’s see in few more days.
I had a look at my node-red logs for another reason but found the same crashes as @MrMysakovich.
My setup: node-red 3.1.8 with node-red-contrib-shelly 10.25.1 running on a Raspberry Pi 4 which is connected via cable to my LAN. Two Shellies (Plus 2PM and Plus1) where one of them is outside in the garage with a low Wifi signal.
In the logs I have about one to two exceptions with a restart of node-red. Here are the latest four:
Jun 21 12:44:14 raspi-red Node-RED[7797]: 21 Jun 12:44:14 - [red] Uncaught Exception:
Jun 21 12:44:14 raspi-red Node-RED[7797]: 21 Jun 12:44:14 - [error] AxiosError: timeout of 5022ms exceeded
Jun 21 12:44:14 raspi-red Node-RED[7797]: at RedirectableRequest.handleRequestTimeout (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3123:1>
Jun 21 12:44:14 raspi-red Node-RED[7797]: at RedirectableRequest.emit (node:events:517:28)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at Timeout.<anonymous> (/home/flo/.node-red/node_modules/follow-redirects/index.js:210:12)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at listOnTimeout (node:internal/timers:569:17)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at process.processTimers (node:internal/timers:512:7)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at Axios.request (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3876:41)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at runNextTicks (node:internal/process/task_queues:60:5)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at listOnTimeout (node:internal/timers:538:9)
Jun 21 12:44:14 raspi-red Node-RED[7797]: at process.processTimers (node:internal/timers:512:7)
Jun 22 18:10:22 raspi-red Node-RED[8998]: 22 Jun 18:10:22 - [red] Uncaught Exception:
Jun 22 18:10:22 raspi-red Node-RED[8998]: 22 Jun 18:10:22 - [error] AxiosError: timeout of 5022ms exceeded
Jun 22 18:10:22 raspi-red Node-RED[8998]: at RedirectableRequest.handleRequestTimeout (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3123:1>
Jun 22 18:10:22 raspi-red Node-RED[8998]: at RedirectableRequest.emit (node:events:517:28)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at Timeout.<anonymous> (/home/flo/.node-red/node_modules/follow-redirects/index.js:210:12)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at listOnTimeout (node:internal/timers:569:17)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at process.processTimers (node:internal/timers:512:7)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at Axios.request (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3876:41)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at runNextTicks (node:internal/process/task_queues:60:5)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at listOnTimeout (node:internal/timers:538:9)
Jun 22 18:10:22 raspi-red Node-RED[8998]: at process.processTimers (node:internal/timers:512:7)
Jun 22 19:18:24 raspi-red Node-RED[11241]: 22 Jun 19:18:24 - [red] Uncaught Exception:
Jun 22 19:18:24 raspi-red Node-RED[11241]: 22 Jun 19:18:24 - [error] AxiosError: timeout of 5022ms exceeded
Jun 22 19:18:24 raspi-red Node-RED[11241]: at RedirectableRequest.handleRequestTimeout (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3123:>
Jun 22 19:18:24 raspi-red Node-RED[11241]: at RedirectableRequest.emit (node:events:517:28)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at Timeout.<anonymous> (/home/flo/.node-red/node_modules/follow-redirects/index.js:210:12)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at listOnTimeout (node:internal/timers:569:17)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at process.processTimers (node:internal/timers:512:7)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at Axios.request (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3876:41)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at runNextTicks (node:internal/process/task_queues:60:5)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at listOnTimeout (node:internal/timers:538:9)
Jun 22 19:18:24 raspi-red Node-RED[11241]: at process.processTimers (node:internal/timers:512:7)
Jun 23 01:07:22 raspi-red Node-RED[11356]: 23 Jun 01:07:22 - [red] Uncaught Exception:
Jun 23 01:07:22 raspi-red Node-RED[11356]: 23 Jun 01:07:22 - [error] AxiosError: timeout of 5022ms exceeded
Jun 23 01:07:22 raspi-red Node-RED[11356]: at RedirectableRequest.handleRequestTimeout (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3123:>
Jun 23 01:07:22 raspi-red Node-RED[11356]: at RedirectableRequest.emit (node:events:517:28)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at Timeout.<anonymous> (/home/flo/.node-red/node_modules/follow-redirects/index.js:210:12)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at listOnTimeout (node:internal/timers:569:17)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at process.processTimers (node:internal/timers:512:7)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at Axios.request (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3876:41)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at runNextTicks (node:internal/process/task_queues:60:5)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at listOnTimeout (node:internal/timers:538:9)
Jun 23 01:07:22 raspi-red Node-RED[11356]: at process.processTimers (node:internal/timers:512:7)
It's always 5022 ms timeout. I hope this helps you find the problem.
New update: Although writing logs doesn't work in my setup now, Node-RED keeps restarting.
@MrMysakovich I released 10.25.2 a few minutes ago. I refactored some internal things, please give it a try... maybe it works now. Please let me know ....
So NR has rebooted randomly again today. Somehow I didn't catch the log (logging in NR still doesn’t work)
With version 10.25.2 I had a reboot today as well:
Jun 25 16:26:14 raspi-red Node-RED[26941]: 25 Jun 16:26:14 - [red] Uncaught Exception:
Jun 25 16:26:14 raspi-red Node-RED[26941]: 25 Jun 16:26:14 - [error] AxiosError: timeout of 5022ms exceeded
Jun 25 16:26:14 raspi-red Node-RED[26941]: at RedirectableRequest.handleRequestTimeout (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3123:>
Jun 25 16:26:14 raspi-red Node-RED[26941]: at RedirectableRequest.emit (node:events:517:28)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at Timeout.<anonymous> (/home/flo/.node-red/node_modules/follow-redirects/index.js:210:12)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at listOnTimeout (node:internal/timers:569:17)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at process.processTimers (node:internal/timers:512:7)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at Axios.request (/home/flo/.node-red/node_modules/axios/dist/node/axios.cjs:3876:41)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at runNextTicks (node:internal/process/task_queues:60:5)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at listOnTimeout (node:internal/timers:538:9)
Jun 25 16:26:14 raspi-red Node-RED[26941]: at process.processTimers (node:internal/timers:512:7)
Jun 25 16:26:14 raspi-red systemd[1]: nodered.service: Main process exited, code=exited, status=1/FAILURE
Jun 25 16:26:14 raspi-red systemd[1]: nodered.service: Failed with result 'exit-code'.
Jun 25 16:26:14 raspi-red systemd[1]: nodered.service: Consumed 16min 28.310s CPU time.
Jun 25 16:26:34 raspi-red systemd[1]: nodered.service: Scheduled restart job, restart counter is at 1.
Jun 25 16:26:34 raspi-red systemd[1]: Stopped nodered.service - Node-RED graphical event wiring tool.
Jun 25 16:26:34 raspi-red systemd[1]: nodered.service: Consumed 16min 28.310s CPU time.
Jun 25 16:26:34 raspi-red systemd[1]: Started nodered.service - Node-RED graphical event wiring tool.
Jun 25 16:26:35 raspi-red Node-RED[29068]: 25 Jun 16:26:35 - [info]
Jun 25 16:26:35 raspi-red Node-RED[29068]: Welcome to Node-RED
Jun 25 16:26:35 raspi-red Node-RED[29068]: ===================
Jun 25 16:26:35 raspi-red Node-RED[29068]: 25 Jun 16:26:35 - [info] Node-RED version: v3.1.8
Jun 25 16:26:35 raspi-red Node-RED[29068]: 25 Jun 16:26:35 - [info] Node.js version: v18.20.3
Jun 25 16:26:35 raspi-red Node-RED[29068]: 25 Jun 16:26:35 - [info] Linux 6.6.28+rpt-rpi-v8 arm64 LE
Jun 25 16:26:35 raspi-red Node-RED[29068]: 25 Jun 16:26:35 - [info] Loading palette nodes
Jun 25 16:26:38 raspi-red Node-RED[29068]: 25 Jun 16:26:38 - [info] Settings file : /home/flo/.node-red/settings.js
@MrMysakovich I tried to reproduce it but failed. I can force a timeout using a shelly simulation and I get the callstack below which looks similar to your one. But it does not crash node-red.
Interestingly the line numbers are different. E.g. http.js:647:16 in my callstack, in your one axios.cjs:3123 see below. So I ask myself what axios version is in your folder /home/flo/.node-red/node_modules/axios/package.json
Mine is "1.6.8" (the latest one available is 1.7.2=
26 Jun 21:53:24 - [warn] [shelly-gen2:e8443a89795c5ba5] AxiosError: timeout of 5022ms exceeded
at RedirectableRequest.handleRequestTimeout (C:\Users\wind.node-red\node_modules\node-red-contrib-shelly\node_modules\axios\lib\adapters\http.js:647:16)
at RedirectableRequest.emit (node:events:517:28)
at Timeout.
I'd really like to help fix this error, I'm curious about the cause. I'm a software developer myself, but I mainly work with .NET and C, only little JavaScript.
I don't know about JavaScript's promises and how a try-catch around an async call behaves, but your code looks like it should catch the timeout exception.
The differences in the stack traces probably result from the type of Node-RED installation. I guess that the code in axios/lib/adapters is transpiled into the single file axios/dist/node/axios.cjs. If you compare axios/lib/adapters/http.js at line 640 with axios/dist/node/axios.cjs at line 3160, it's the same code:
req.setTimeout(timeout, function handleRequestTimeout() {
if (isDone) return;
let timeoutErrorMessage = config.timeout ? 'timeout of ' + config.timeout + 'ms exceeded' : 'timeout exceeded';
const transitional = config.transitional || transitionalDefaults;
if (config.timeoutErrorMessage) {
timeoutErrorMessage = config.timeoutErrorMessage;
}
reject(new AxiosError(
timeoutErrorMessage,
transitional.clarifyTimeoutError ? AxiosError.ETIMEDOUT : AxiosError.ECONNABORTED,
config,
req
));
abort();
});
I am relatively new to Node-RED. I installed it just 3 months ago. Therefore I still have the whole log :)
So here's a little timeline I reconstructed from the log:
Right from the start I installed node-red-contrib-shelly 10.18.0 and node-red-dashboard 3.6.5 on April 2nd.
The first uncaught exception occured on June 5th in the morning. I didn't notice it, only just a few days ago when I commented here.
I upgraded node-red-contrib-shelly to 10.25.0 on the same day of the exception (June 5th) in the evening (after the exception).
Upgraded node-red-contrib-shelly to 10.25.1 on June 17th.
Upgraded node-red-contrib-shelly to 10.25.2 on June 24th.
The last package I installed was node-red-node-email 2.2.1 on May 29th.
Since then my Node-RED ran without manual restarts/reboots until the first exception on June 5th.
Overall I have 46 uncaught exceptions in my log which restarted Node-RED.
Interestingly, there are 2 axios timeouts just as warnings without stack traces and no restart of Node-RED:
Jun 26 17:23:11 raspi-red Node-RED[30131]: 26 Jun 17:23:11 - [warn] [shelly-gen2:11f2d076facb62a1] Error: AxiosError: timeout of 5000ms exceeded
...
Jun 27 06:59:35 raspi-red Node-RED[32011]: 27 Jun 06:59:35 - [warn] [shelly-gen2:11f2d076facb62a1] Error: AxiosError: timeout of 5000ms exceeded
I hope this helps. If you want, I can send you the whole logfile by mail.
My Node-RED is installed through this script:
bash <(curl -sL https://raw.githubusercontent.com/node-red/linux-installers/master/deb/update-nodejs-and-nodered) --node20
on Homebridge Image
I'd really like to help fix this error, I'm curious about the cause. I'm a software developer myself, but I mainly work with .NET and C, only little JavaScript.
I don't know about JavaScript's promises and how a try-catch around an async call behaves, but your code looks like it should catch the timeout exception.
The differences in the stack traces probably result from the type of Node-RED installation. I guess that the code in
axios/lib/adaptersis transpiled into the single fileaxios/dist/node/axios.cjs. If you compareaxios/lib/adapters/http.jsat line 640 withaxios/dist/node/axios.cjsat line 3160, it's the same code:req.setTimeout(timeout, function handleRequestTimeout() { if (isDone) return; let timeoutErrorMessage = config.timeout ? 'timeout of ' + config.timeout + 'ms exceeded' : 'timeout exceeded'; const transitional = config.transitional || transitionalDefaults; if (config.timeoutErrorMessage) { timeoutErrorMessage = config.timeoutErrorMessage; } reject(new AxiosError( timeoutErrorMessage, transitional.clarifyTimeoutError ? AxiosError.ETIMEDOUT : AxiosError.ECONNABORTED, config, req )); abort(); });I am relatively new to Node-RED. I installed it just 3 months ago. Therefore I still have the whole log :)
So here's a little timeline I reconstructed from the log:
Right from the start I installed node-red-contrib-shelly 10.18.0 and node-red-dashboard 3.6.5 on April 2nd.
The first uncaught exception occured on June 5th in the morning. I didn't notice it, only just a few days ago when I commented here.
I upgraded node-red-contrib-shelly to 10.25.0 on the same day of the exception (June 5th) in the evening (after the exception).
Upgraded node-red-contrib-shelly to 10.25.1 on June 17th.
Upgraded node-red-contrib-shelly to 10.25.2 on June 24th.
The last package I installed was node-red-node-email 2.2.1 on May 29th.
Since then my Node-RED ran without manual restarts/reboots until the first exception on June 5th.
Overall I have 46 uncaught exceptions in my log which restarted Node-RED.
Interestingly, there are 2 axios timeouts just as warnings without stack traces and no restart of Node-RED:
Jun 26 17:23:11 raspi-red Node-RED[30131]: 26 Jun 17:23:11 - [warn] [shelly-gen2:11f2d076facb62a1] Error: AxiosError: timeout of 5000ms exceeded ... Jun 27 06:59:35 raspi-red Node-RED[32011]: 27 Jun 06:59:35 - [warn] [shelly-gen2:11f2d076facb62a1] Error: AxiosError: timeout of 5000ms exceededI hope this helps. If you want, I can send you the whole logfile by mail.
@floppes ok then let's try to do a teams meeting where we can talk about options. Right now I am not happy with the web requests implementation in the nodes. In the beginning I used to use "request" which then was deprecated. I turned to axios which supported async await. So probably I will rewrite the code in the function shellyRequestAsync completely... however before I can not explain where the error comes from it does not make sense to refactor it. We need to find a way to force that bug to appear more frequently. I guess chances are high to eliminate it then.
Ok, we can try a Teams meeting. From your name I guess you are German like me? You can e-mail me your preferred time for a meeting: floppes [at] gmx [dot] de
Another thing that came to my mind: I enabled authentication in my Shelly devices a few weeks ago. It must have been June 4th because that's when I have the first entry of this kind:
[warn] [shelly-gen2:2a27b195c3b1b31c] Error: Unauthorized /rpc/Shelly.GetStatus
That was the night before the first uncaught exception!
I am still getting this error from time to time (58 times in total) even though the credentials are stored in the nodes.
I will disable authentication now. Maybe this is the cause for the exceptions...