Programie / node-red-aircon-rac-wf

Node-RED nodes for interacting with Mitsubishi Aircon RAC-WF WiFi modules
https://flows.nodered.org/node/@programie/node-red-aircon-rac-wf
MIT License
0 stars 0 forks source link

Issue when setting values? #2

Closed qabi closed 1 year ago

qabi commented 1 year ago

Reading from heat pumps has worked well for me for a few days now.

When introducing some writing/updating (and also passing message from set-node to get-node to get updated values from heat pump), I got the following error, that crashes Node-RED entirely:

30 Aug 11:15:05 - [red] Uncaught Exception:
30 Aug 11:15:05 - [error] AxiosError: Request failed with status code 501
at settle (/data/node_modules/@programie/node-red-aircon-rac-wf/node_modules/axios/dist/node/axios.cjs:1909:12)
at IncomingMessage. hand leSt reamEnd (/data/node_modules/@programie/node-red-aircon-rac-wf/node_modules/axios/dist/node/axios.cjs:2989:11)
at IncomingMessage.emit (node: events:539:35)
at endReadableNT (node: internal/streams/readable: 1345:12)
at processTicksAndRejections (node: internal/process/task_queues: 83:21)

Looks like one of the heat pumps returns a HTTP 501 status, for whatever reason, which seems to crash everything.

If I can help fix it or test it, just let me know :)

Programie commented 1 year ago

I never saw any 5xx status codes returned from my devices while sending data to it. I only experienced some timeouts while calling the API of my devices using the get-stat node, but that didn't crash Node-RED in my case.

I will implement some more error handling to prevent crashing Node-RED. I guess, surrounding the axios.post() call with try...catch should fix that.

Programie commented 1 year ago

I tried to reproduce the crash of Node-RED but could not reproduce it.

I tried to produce some errors by sending the request to another server returning an HTTP error status, but that doesn't crash Node-RED either.

I added an inject node sending the current timestamp to a debug node every second and then triggered the setstat node which fails with an error 501. But Node-RED is still running.

That's the output in the debug panel:

image

The .catch() calls in the GetStatNode() and SetStatNode() methods are already catching all thrown exceptions.

Maybe you are using a different version of Node-RED or Node.js?

In my case I'm using the latest official Docker image of Node-RED which is currently using Node-RED v3.0.2 and Node.js v16.20.1.

qabi commented 1 year ago

Interesting. I'm using a Docker image with Node.js version 16.16 and Node-RED version 3.0.2.

Based on the stacktrace I cannot determine where the exception is thrown from, exactly. But it looks like Node-RED is getting an uncaught exception, which seems to crash everything: Uncaught error

It looks like the exception is maybe thrown from an Axios event handler. Maybe an "error" handler can be assigned to Axias, to be certain to get notified of such exceptions - even in an asynchronous context?

I found the following, which might be a starting point to find the problem:

https://stackoverflow.com/questions/70136497/unable-to-handle-404-error-in-axios-with-try-and-catch

https://stackoverflow.com/questions/73593628/how-do-i-get-rid-of-axios-error-uncaught-in-promise

https://stackoverflow.com/questions/74251272/why-does-an-axios-request-error-result-in-an-unhandled-exception-even-though-all

https://www.npmjs.com/package//axios#axios-api (Under 'Handling Errors')

If I can find time for it, I will try to have a look at the code :)

qabi commented 1 year ago

One other idea, a bit of a long-shot: This problem appeared after I made a flow with an injection going to 3 set-nodes, and the output messages of these are passed along to 3 get-nodes. (It is unclear for me what the set-nodes emit).

But since this was the same message being sent to multiple nodes, maybe that could have something to do with it? I have seen strange side-effects from this before.

Programie commented 1 year ago

That's a weird behavior.

In my production Node-RED instance, I'm also doing the same thing: One injection node triggers 3 get-stat nodes and the output is sent to a single function node to store the data to be used later.

The same also happens with the set-stat node (i.e. to power on or off all devices at once). But I didn't experienced any issues related to crashes yet.

I my case, I'm also triggering the get-stat nodes from the set-stat nodes (i.e. the output of the set-stat nodes are directly sent to the get-stat nodes to update my saved state mentioned above after changing it).

Programie commented 1 year ago

As I'm not able to reproduce the issue, I will close this issue.

If it's still happening, you might reopen it and give me some more details how to reproduce it.

qabi commented 1 year ago

I now upgraded to latest Docker image. Node-RED 3.1 and Node.js v16.20.2.

The problem still occurs, but not every time. And it seems it does not occur when only setting to and getting from a single heat pump. But with 3 it does seem to occur fairly often. So I suspect perhaps some kind of race condition. Maybe there is a scope / Axios instance, that is somehow shared for instances of these nodes?

The flow I am using:

[{"id":"4c08c0f958692225","type":"inject","z":"439027e44ac233e5","name":"","props":[{"p":"payload"},{"p":"topic","vt":"str"}],"repeat":"","crontab":"","once":false,"onceDelay":0.1,"topic":"","payload":"","payloadType":"date","x":100,"y":360,"wires":[["2d14c18fb0cdd2fd"]]},{"id":"2d14c18fb0cdd2fd","type":"function","z":"439027e44ac233e5","name":"Heatpump control","func":"let powerPrice = global.get(\"powerPrice\");\nvar turnOn = powerPrice.score < 3; // todo: use something else? Tarifs? Virtual power price threshold?\n\n// todo: react to changing conditions. But not too often.\n\nvar msg = {\n    \"topic\": \"HeatpumpControl\",\n    \"payload\": {\n        \"operation\": turnOn\n    }\n};\n\n// todo: cycle how many are turned on, and which. Depending on temperature?\n// todo: increase temperature when power is cheap/free\n// todo: base on virtual price?\n\nreturn msg;","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":310,"y":360,"wires":[["88b34874574b6272","c4afcde537571f9c","8e4a2305efb1ae61"]]},{"id":"88b34874574b6272","type":"mitsubishi-aircon-setstat","z":"439027e44ac233e5","host":"192.168.1.223","operatorId":"","deviceId":"","name":"VP3","x":490,"y":400,"wires":[["13f6513f3eae8508"]]},{"id":"c4afcde537571f9c","type":"mitsubishi-aircon-setstat","z":"439027e44ac233e5","host":"192.168.1.222","operatorId":"","deviceId":"","name":"VP2","x":490,"y":360,"wires":[["be5c55cab45bff59"]]},{"id":"8e4a2305efb1ae61","type":"mitsubishi-aircon-setstat","z":"439027e44ac233e5","host":"192.168.1.221","operatorId":"","deviceId":"","name":"VP1","x":490,"y":320,"wires":[["5bba671804b58ec9"]]},{"id":"13f6513f3eae8508","type":"function","z":"439027e44ac233e5","name":"topic","func":"return {topic:\"V3\", payload: msg.payload};","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":670,"y":200,"wires":[["a048903632f2ebd7"]]},{"id":"be5c55cab45bff59","type":"function","z":"439027e44ac233e5","name":"topic","func":"return {topic:\"V2\", payload: msg.payload};","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":670,"y":140,"wires":[["5010d0b982994e45"]]},{"id":"5bba671804b58ec9","type":"function","z":"439027e44ac233e5","name":"topic","func":"return {topic:\"V1\", payload: msg.payload};","outputs":1,"noerr":0,"initialize":"","finalize":"","libs":[],"x":670,"y":80,"wires":[["ceea7a3b89b9cf38"]]},{"id":"ceea7a3b89b9cf38","type":"mitsubishi-aircon-getstat","z":"439027e44ac233e5","host":"192.168.1.221","operatorId":"","deviceId":"","name":"VP1","x":830,"y":80,"wires":[["d5d3190b91f5f06f","2451f6c193fbb59a","7877c252a6c58d5d"]]},{"id":"5010d0b982994e45","type":"mitsubishi-aircon-getstat","z":"439027e44ac233e5","host":"192.168.1.222","operatorId":"","deviceId":"","name":"VP2","x":830,"y":140,"wires":[["d5d3190b91f5f06f","2451f6c193fbb59a","886376f56f39e787"]]},{"id":"a048903632f2ebd7","type":"mitsubishi-aircon-getstat","z":"439027e44ac233e5","host":"192.168.1.223","operatorId":"","deviceId":"","name":"VP3","x":830,"y":200,"wires":[["d5d3190b91f5f06f","2451f6c193fbb59a","6dcd742e4f6cb1ce"]]},{"id":"6dcd742e4f6cb1ce","type":"change","z":"439027e44ac233e5","name":"VP3 on?","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload.operation","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":1120,"y":240,"wires":[["b22ad661ee04f1dd"]]},{"id":"b22ad661ee04f1dd","type":"ui_led","z":"439027e44ac233e5","order":5,"group":"67d6053aacf44f3a","width":4,"height":1,"label":"Varmepumpe 3","labelPlacement":"left","labelAlignment":"left","colorForValue":[{"color":"#cc4c3d","value":"true","valueType":"bool"},{"color":"#92939a","value":"false","valueType":"bool"}],"allowColorForValueInMessage":false,"shape":"circle","showGlow":true,"name":"Varmepumpe 3","x":1400,"y":240,"wires":[]},{"id":"b932a2a59920debb","type":"ui_led","z":"439027e44ac233e5","order":3,"group":"67d6053aacf44f3a","width":4,"height":1,"label":"Varmepumpe 2","labelPlacement":"left","labelAlignment":"left","colorForValue":[{"color":"#cc4c3d","value":"true","valueType":"bool"},{"color":"#92939a","value":"false","valueType":"bool"}],"allowColorForValueInMessage":false,"shape":"circle","showGlow":true,"name":"Varmepumpe 2","x":1400,"y":200,"wires":[]},{"id":"047b0f74fcf7f732","type":"ui_led","z":"439027e44ac233e5","order":1,"group":"67d6053aacf44f3a","width":4,"height":1,"label":"Varmepumpe 1","labelPlacement":"left","labelAlignment":"left","colorForValue":[{"color":"#cc4c3d","value":"true","valueType":"bool"},{"color":"#92939a","value":"false","valueType":"bool"}],"allowColorForValueInMessage":false,"shape":"circle","showGlow":true,"name":"Varmepumpe 1","x":1400,"y":160,"wires":[]},{"id":"886376f56f39e787","type":"change","z":"439027e44ac233e5","name":"VP2 on?","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload.operation","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":1120,"y":200,"wires":[["b932a2a59920debb"]]},{"id":"7877c252a6c58d5d","type":"change","z":"439027e44ac233e5","name":"VP1 on?","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload.operation","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":1120,"y":160,"wires":[["047b0f74fcf7f732"]]},{"id":"2451f6c193fbb59a","type":"change","z":"439027e44ac233e5","name":"Energy","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload.electric","tot":"msg"},{"t":"set","p":"topic","pt":"msg","to":"msg.topic & \"Energy\"","tot":"jsonata"}],"action":"","property":"","from":"","to":"","reg":false,"x":1110,"y":100,"wires":[["4135b6ad6422695b"]]},{"id":"d5d3190b91f5f06f","type":"change","z":"439027e44ac233e5","name":"indoorTemp","rules":[{"t":"set","p":"payload","pt":"msg","to":"payload.indoorTemp","tot":"msg"}],"action":"","property":"","from":"","to":"","reg":false,"x":1130,"y":60,"wires":[["4135b6ad6422695b"]]},{"id":"4135b6ad6422695b","type":"ui_chart","z":"439027e44ac233e5","name":"","group":"67d6053aacf44f3a","order":7,"width":7,"height":4,"label":"Temperaturer","chartType":"line","legend":"true","xformat":"HH:mm:ss","interpolate":"linear","nodata":"","dot":false,"ymin":"0","ymax":"25","removeOlder":"24","removeOlderPoints":"","removeOlderUnit":"3600","cutout":0,"useOneColor":false,"useUTC":false,"colors":["#1f77b4","#aec7e8","#ff7f0e","#2ca02c","#98df8a","#d62728","#ff9896","#9467bd","#c5b0d5"],"outputs":1,"useDifferentColor":false,"className":"","x":1390,"y":60,"wires":[[]]},{"id":"67d6053aacf44f3a","type":"ui_group","name":"Lager","tab":"509c667d01bac035","order":2,"disp":false,"width":"7","collapse":false,"className":""},{"id":"509c667d01bac035","type":"ui_tab","name":"Varme","icon":"dashboard","disabled":false,"hidden":false}]
Programie commented 1 year ago

Finally, I was able to reproduce the issue. I will have a deeper look into it.

Programie commented 1 year ago

I found the cause of the issue and fixed it.

Looks like a nested Promise is not caught in the parent .catch(). In my case, the set-stat node first retrieves the data (getAirconStat()) from the aircon and then sends the data to it (setAirconStat()). The getAirconStat() method returns a Promise and also has a .catch() chained to it. But the nested setAirconStat() didn't had the .catch() chained to it as I thought the parent .catch() already catches the nested one as well (which doesn't seem to be the case).

I've also added a .catch() to the Promise returned by setAirconStat() and now I couldn't reproduce the issue anymore. See e4b8600 for more details.

The fix is contained in version 1.1.1.

qabi commented 1 year ago

Nice! Looks like it doesn't crash any more. But strangely I get 501 responses to all attempts to set a value:

"AxiosError: Request failed with status code 501"

The payload to the set node has only one property: { "operation": true }

Programie commented 1 year ago

The 501 response sounds a bit strange.

Do you get that response only from a single heat pump (i.e. it's working for the other ones)? If that's the case, are there any differences between them (model, firmware version, etc.)?

You could change the log level of Node-RED to debug in your settings.js to see some more details. In that case, the node will also log the data sent to the device and received from it.

qabi commented 1 year ago

I seems I am not getting the 501 any more, but it could be due to the state of the system - like no need to turn of heat pumps, and thus possibly not hitting whatever the problem is. I will notify here, if/when I see this again, and can perhaps troubleshoot it further :)