[Bug]: Info in node-red-log: "Error requesting info from the bridge. Reconnect in some secs. undefined" every minute
Michael-K-at-GitHub opened this issue · 1 comments
Node-Red-Contrib-Huemagic-Fork Version
4.2.8
Node JS Version
20.7.0
NPM Version
10.1.0
Node-Red Version
3.1
Operating System
Plain Ubuntu. No docker at al
What happened?
hue-magic-fork is working without problems (lamps, scenes, ...), but is filling up the node red log:
11 Oct 23:39:56 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. undefined
11 Oct 23:39:56 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
11 Oct 23:39:56 - [info] [hue-bridge:Hue Bridge] Connected to bridge
11 Oct 23:39:56 - [info] [hue-bridge:Hue Bridge] Processing bridge resources…
11 Oct 23:39:56 - [info] [hue-bridge:Hue Bridge] Initial emit of resource states…
11 Oct 23:39:57 - [info] [hue-bridge:Hue Bridge] Keeping nodes up-to-date…
11 Oct 23:39:57 - [info] [hue-bridge:Hue Bridge] Subscribing to bridge events…
11 Oct 23:41:08 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. undefined
11 Oct 23:41:08 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
11 Oct 23:41:08 - [info] [hue-bridge:Hue Bridge] Connected to bridge
11 Oct 23:41:08 - [info] [hue-bridge:Hue Bridge] Processing bridge resources…
11 Oct 23:41:08 - [info] [hue-bridge:Hue Bridge] Initial emit of resource states…
11 Oct 23:41:09 - [info] [hue-bridge:Hue Bridge] Keeping nodes up-to-date…
11 Oct 23:41:09 - [info] [hue-bridge:Hue Bridge] Subscribing to bridge events…
11 Oct 23:41:17 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. undefined
11 Oct 23:41:17 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
11 Oct 23:41:17 - [info] [hue-bridge:Hue Bridge] Connected to bridge
11 Oct 23:41:18 - [info] [hue-bridge:Hue Bridge] Processing bridge resources…
11 Oct 23:41:18 - [info] [hue-bridge:Hue Bridge] Initial emit of resource states…
11 Oct 23:41:18 - [info] [hue-bridge:Hue Bridge] Keeping nodes up-to-date…
11 Oct 23:41:18 - [info] [hue-bridge:Hue Bridge] Subscribing to bridge events…
I suspect that the "PERIODICALLY CHECK WETHER BRIDGE IS CONNECTED" check in hue-bridge-config is to blame. It looks to me the check in line 58
API.request({ config: config, resource: "/config", version: 1 })
.then(function(bridgeInformation)
{
scope.startWatchdog();
})
.catch(function(error)
{
if (error.status !== 429) {
scope.log("Error requesting info from the bridge. Reconnect in some secs. " + ((typeof(error.message) == 'undefined') ? JSON.stringify(error) : error.message));
scope.start();
}
...
fails every time,
Interestingly, the nodes still works.
Hue Bridge has the current version 1960062030 with API version 1.60.0
How to reproduce?
Configure a hue bridge config node
Expected behavior:
no periodic log entry
Additional comments?
Additional comments here, if any.
Relevant log output
see aboveAdditional tests (and possible solution)
(1) testing response of bridge, ruling out network issues
requesting /config from the node red server in a loop while hue-magic-fork is having connection issue
while true; do curl http://192.168.1.16/api/keyhere/config; done
works fine, no issues with this requests. hue-magic-fork still shows log entry. So it doesn't look like a network issue
(2) disconnecting bridge (which should change log entry to "Lost connection to bridge"
This leads to an crash of the node red server
12 Oct 00:50:23 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. undefined
12 Oct 00:50:23 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 00:50:23 - [info] [hue-bridge:Hue Bridge] Connected to bridge
12 Oct 00:50:24 - [info] [hue-bridge:Hue Bridge] Processing bridge resources…
12 Oct 00:50:24 - [info] [hue-bridge:Hue Bridge] Initial emit of resource states…
12 Oct 00:50:24 - [info] [hue-bridge:Hue Bridge] Keeping nodes up-to-date…
12 Oct 00:50:24 - [info] [hue-bridge:Hue Bridge] Subscribing to bridge events…
12 Oct 00:51:40 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. {"status":"EHOSTUNREACH","errors":"connect EHOSTUNREACH 192.168.1.16:443"}
12 Oct 00:51:40 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 00:51:40 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. {"status":"EHOSTUNREACH","errors":"connect EHOSTUNREACH 192.168.1.16:443"}
12 Oct 00:51:40 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 00:51:40 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. {"status":"EHOSTUNREACH","errors":"connect EHOSTUNREACH 192.168.1.16:443"}
12 Oct 00:51:40 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 00:51:40 - [red] Uncaught Exception:
12 Oct 00:51:40 - [error] TypeError: Cannot read properties of undefined (reading 'status')
at /home/serveradmin/.node-red/node_modules/node-red-contrib-huemagic/huemagic/utils/api.js:102:37
at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
nodered.service: Main process exited, code=exited, status=1/FAILURE
nodered.service: Failed with result 'exit-code'.
nodered.service: Scheduled restart job, restart counter is at 2.
Stopped Node-RED graphical event wiring tool.
Started Node-RED graphical event wiring tool.
12 Oct 00:52:07 - [info]
Willkommen bei Node-RED
Now its getting interesting: After this node red server restart the log entry no longer occurs.
Disconnecting the bridge now is detected correctly, with no crashing of the node red server.
12 Oct 01:10:48 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. {"status":"EHOSTUNREACH","errors":"connect EHOSTUNREACH 192.168.1.16:443"}
12 Oct 01:10:48 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 01:10:58 - [info] [hue-bridge:Hue Bridge] Error: connect EHOSTUNREACH 192.168.1.16:443
12 Oct 01:11:26 - [info] [hue-bridge:Hue Bridge] Error requesting info from the bridge. Reconnect in some secs. {"status":"EHOSTUNREACH","errors":"connect EHOSTUNREACH 192.168.1.16:443"}
12 Oct 01:11:26 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 01:11:28 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 01:11:29 - [info] [hue-bridge:Hue Bridge] Error: connect EHOSTUNREACH 192.168.1.16:443
12 Oct 01:11:29 - [info] [hue-bridge:Hue Bridge] Error: connect EHOSTUNREACH 192.168.1.16:443
12 Oct 01:11:59 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 01:12:00 - [info] [hue-bridge:Hue Bridge] Error: connect EHOSTUNREACH 192.168.1.16:443
12 Oct 01:12:30 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 01:12:31 - [info] [hue-bridge:Hue Bridge] Error: connect EHOSTUNREACH 192.168.1.16:443
and reconnecting the bridge gets me a correct
12 Oct 01:13:01 - [info] [hue-bridge:Hue Bridge] Initializing the bridge (192.168.1.16)…
12 Oct 01:13:01 - [info] [hue-bridge:Hue Bridge] Connected to bridge
12 Oct 01:13:01 - [info] [hue-bridge:Hue Bridge] Processing bridge resources…
12 Oct 01:13:01 - [info] [hue-bridge:Hue Bridge] Initial emit of resource states…
12 Oct 01:13:02 - [info] [hue-bridge:Hue Bridge] Keeping nodes up-to-date…
12 Oct 01:13:02 - [info] [hue-bridge:Hue Bridge] Subscribing to bridge events…
I suspect that the following has happened here
- I added hue-magic-fork via the palette
- I have configured the bridge in node red
- I had the log entries and the crash
Presumably hue-magic-fork does some initialisation when node red starts. But (from the perspective of hue-magic-fork) I've never started the node red server (!), so the init code was never executed. This would lead to the solution "force restart of node red server after installing hue-magic-fork".
As a workaround: If you see the log entries, restart your node red server (or unplug your hue bridge, thus crashing your node red server, which should then restart, thus repairing the issue).
I will continue to monitor the matter and - if the log entries no longer occur - close the issue afterwards.