search

windkh / node-red-contrib-shelly

Shelly control nodes for node red.
MIT License
31 stars 21 forks source link

Random restarts of Node-RED caused by Shelly plugin #157

Open MrMysakovich opened 3 weeks ago

MrMysakovich commented 3 weeks ago

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?

windkh commented 3 weeks ago

Thanks for reporting. I wonder why you have two nodes with the same IP?

MrMysakovich commented 3 weeks ago

One just to get status every 1s and one for switching ON / OFF every 15 minutes - water heaters while feed in energy (solar)

windkh commented 3 weeks ago

@MrMysakovich I can only see a portion of your flow.... you are using the same IP address in different nodes image

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.

  1. 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
  2. Can you change the mode of the nodes from "polling" to "callback" or to "none" to crosscheck that the problem comes from my theory.
  3. Can you send me the full flow?
MrMysakovich commented 3 weeks ago

Yes, because I use the first node for inject every 1s (status) and the second one every 15 minutes for switching ON / OFF.

  1. Maybe I can add one information more that I use same Shellys in Homebridge too.
  2. I will try to set it to none.
  3. [
{
    "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
}
]
windkh commented 2 weeks ago

@MrMysakovich I am running your flow here and it seems to work fine... after what time did you get the restarts?

windkh commented 2 weeks ago

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

MrMysakovich commented 2 weeks ago

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

windkh commented 2 weeks ago

Ok then it means that sending the command request to the shelly timed out. I assume that you are running the raspi via wifi?

MrMysakovich commented 2 weeks ago

No, wired and I never had problem with Shelly through Homebridge. Really don’t know why it happens :/ Btw Shelly connection is stable.

windkh commented 2 weeks ago

@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 commented 2 weeks ago

@windkh please install V10.25.1 I change a few timeout. If it happens again please send me the node-red log

MrMysakovich commented 2 weeks ago

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

windkh commented 2 weeks ago

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

MrMysakovich commented 2 weeks ago

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

windkh commented 2 weeks ago

@MrMysakovich can you not just copy the output of the console?

MrMysakovich commented 2 weeks ago

I got this in NR:

image

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.

MrMysakovich commented 1 week ago

UPDATE: So far, Node-RED hasn't rebooted yet. Let’s see in few more days.

floppes commented 1 week ago

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.

MrMysakovich commented 1 week ago

New update: Although writing logs doesn't work in my setup now, Node-RED keeps restarting.

windkh commented 1 week ago

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

MrMysakovich commented 1 week ago

@windkh Thank you really much, we will see in a few days...

MrMysakovich commented 1 week ago

So NR has rebooted randomly again today. Somehow I didn't catch the log (logging in NR still doesn’t work)

floppes commented 1 week ago

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
windkh commented 1 week ago

thanks for the log... I need to think about how to solve it...

windkh commented 6 days ago

@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. (C:\Users\wind.node-red\node_modules\follow-redirects\index.js:210:12) at listOnTimeout (node:internal/timers:569:17) at processTimers (node:internal/timers:512:7) at Axios.request (C:\Users\wind.node-red\node_modules\node-red-contrib-shelly\node_modules\axios\lib\core\Axios.js:45:41) at runNextTicks (node:internal/process/task_queues:60:5) at listOnTimeout (node:internal/timers:538:9) at processTimers (node:internal/timers:512:7)

floppes commented 6 days ago

I have axios version 1.6.8 as well.

floppes commented 6 days ago

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.

MrMysakovich commented 6 days ago

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

windkh commented 5 days ago

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.

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

floppes commented 4 days ago

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

windkh commented 2 days ago

@floppes Ok let's schedule a meeting maybe today or tomorrow in the evening... when the rest of my familiy occupies the TV ;)

windkh commented 2 days ago

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

About the unauthorized thing: this is the text from the response of the shelly. So it seems to be reachable but denies the password. I can only speculate why....

windkh commented 2 days ago

@floppes while watching soccer I refactored the nodes so that every node has its own axios instance. Please install 10.26.0 and report if it helped.

floppes commented 2 days ago

Thanks, I'd like to keep it running for a few more days without authentication. Since I disabled authentication, I had no more exceptions. Only about 60 times these warnings:

Jun 30 12:38:53 raspi-red Node-RED[33890]: 30 Jun 12:38:53 - [warn] [shelly-gen2:2a27b195c3b1b31c] Error: AxiosError: timeout of 5000ms exceeded
Jun 30 12:38:53 raspi-red Node-RED[33890]: 30 Jun 12:38:53 - [warn] [shelly-gen2:11f2d076facb62a1] Error: AxiosError: timeout of 5022ms exceeded

That's probably when my Wifi was down.

Please send me an e-mail so we can setup a meeting. I'd like to keep this information private ;)