Nuuki
20 December 2024 17:23
1
I've been running Node-Red for a number of years alongside Home Assistant, and overall its been great. However in the last year I've had issues with the NR container crashing. Sometimes it goes a couple of weeks between crashes and sometimes it happens on back to back days. Here's what the logs show me:
16 Dec 21:29:48 - [info] [cronplus:1st of the month] System Time Change Detected - refreshing schedules! If the system time was not changed then this typically occurs due to blocking code elsewhere in your application
16 Dec 21:29:48 - [debug] [cronplus:1st of the month] Refreshing running schedules
16 Dec 21:29:48 - [debug] [cronplus:1st of the month] stopped 'schedule1' ~ 'schedule1'
16 Dec 21:29:48 - [debug] [cronplus:1st of the month] started 'schedule1' ~ 'schedule1'
16 Dec 21:29:48 - [debug] Flushing localfilesystem context scope global
16 Dec 21:29:49 - [info] [mqtt-broker:Mosquitto] Disconnected from broker:
16 Dec 21:29:50 - [info] [server:Home Assistant] Connection closed to
16 Dec 21:29:50 - [red] Uncaught Exception:
16 Dec 21:29:50 - [error] UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "#<Object>".
at throwUnhandledRejectionsMode (node:internal/process/promises:389:7)
at processPromiseRejections (node:internal/process/promises:470:17)
at process.processTicksAndRejections (node:internal/process/task_queues:96:32)http://192.168.1.10http://192.168.1.10:8123
My assumption is that its an issue with a specific node. I've configured a catch node to log any errors to a file and I've set NR logging to debug, but haven't found anything useful.
Any ideas on what I can do so track down the root cause?
Hi @Nuuki
Please include the whole log entry.
This stack trace, doesn't seem to be complete
Nuuki
20 December 2024 17:55
3
My bad. The container had been running for a few days when it crashed - how far back do you want me to go?
The log entry suggests the NodeJS runtime its self, had crashed.
In a normal stack trace, there should be a very good clue as to what Node RED Node, had started the collapse.
Nuuki
20 December 2024 18:22
5
Here's the 30 minutes prior to the crash:
20 Dec 09:00:00 - [debug] [api-call-service:Turn off fan] Calling Service: {"domain":"fan","service":"turn_off","target":{"device_id":"164a7c976f484a8d824eed098f0cd195"}}
20 Dec 09:00:11 - [debug] Flushing localfilesystem context scope global
20 Dec 09:00:11 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:00:41 - [debug] Flushing localfilesystem context scope global
20 Dec 09:01:14 - [debug] Flushing localfilesystem context scope global
20 Dec 09:01:14 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:01:44 - [debug] Flushing localfilesystem context scope global
20 Dec 09:02:14 - [debug] Flushing localfilesystem context scope global
20 Dec 09:02:14 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:02:44 - [debug] Flushing localfilesystem context scope global
20 Dec 09:02:45 - [debug] [api-call-service:Turn OFF] Calling Service: {"domain":"fan","service":"turn_off","target":{"entity_id":"fan.air_purifier"}}
20 Dec 09:03:15 - [debug] Flushing localfilesystem context scope global
20 Dec 09:03:15 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:03:45 - [debug] Flushing localfilesystem context scope global
20 Dec 09:04:15 - [debug] Flushing localfilesystem context scope global
20 Dec 09:04:15 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:04:48 - [debug] Flushing localfilesystem context scope global
20 Dec 09:05:20 - [debug] Flushing localfilesystem context scope global
20 Dec 09:05:20 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:05:50 - [debug] Flushing localfilesystem context scope global
20 Dec 09:06:21 - [debug] Flushing localfilesystem context scope global
20 Dec 09:06:21 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:06:51 - [debug] Flushing localfilesystem context scope global
20 Dec 09:07:21 - [debug] Flushing localfilesystem context scope global
20 Dec 09:07:21 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:07:51 - [debug] Flushing localfilesystem context scope global
20 Dec 09:08:21 - [debug] Flushing localfilesystem context scope global
20 Dec 09:08:21 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:08:53 - [debug] Flushing localfilesystem context scope global
20 Dec 09:09:23 - [debug] Flushing localfilesystem context scope global
20 Dec 09:09:23 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:09:54 - [debug] Flushing localfilesystem context scope global
20 Dec 09:10:24 - [debug] Flushing localfilesystem context scope global
20 Dec 09:10:24 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:10:54 - [debug] Flushing localfilesystem context scope global
20 Dec 09:11:24 - [debug] Flushing localfilesystem context scope global
20 Dec 09:11:24 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:11:55 - [debug] Flushing localfilesystem context scope global
20 Dec 09:12:25 - [debug] Flushing localfilesystem context scope global
20 Dec 09:12:25 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:12:55 - [debug] Flushing localfilesystem context scope global
20 Dec 09:13:26 - [debug] Flushing localfilesystem context scope global
20 Dec 09:13:26 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:13:58 - [debug] Flushing localfilesystem context scope global
20 Dec 09:14:28 - [debug] Flushing localfilesystem context scope global
20 Dec 09:14:28 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:14:58 - [debug] Flushing localfilesystem context scope global
20 Dec 09:15:30 - [debug] Flushing localfilesystem context scope global
20 Dec 09:15:30 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:16:00 - [debug] Flushing localfilesystem context scope global
20 Dec 09:16:30 - [debug] Flushing localfilesystem context scope global
20 Dec 09:16:30 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:17:01 - [debug] Flushing localfilesystem context scope global
20 Dec 09:17:31 - [debug] Flushing localfilesystem context scope global
20 Dec 09:17:31 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:18:01 - [debug] Flushing localfilesystem context scope global
20 Dec 09:18:32 - [debug] Flushing localfilesystem context scope global
20 Dec 09:18:32 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:19:02 - [debug] Flushing localfilesystem context scope global
20 Dec 09:19:33 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:19:33 - [debug] Flushing localfilesystem context scope global
20 Dec 09:20:03 - [debug] Flushing localfilesystem context scope global
20 Dec 09:20:03 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:20:33 - [debug] Flushing localfilesystem context scope global
20 Dec 09:21:04 - [debug] Flushing localfilesystem context scope global
20 Dec 09:21:04 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:21:34 - [debug] Flushing localfilesystem context scope global
20 Dec 09:22:04 - [debug] Flushing localfilesystem context scope global
20 Dec 09:22:04 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:22:34 - [debug] Flushing localfilesystem context scope global
20 Dec 09:23:04 - [debug] Flushing localfilesystem context scope global
20 Dec 09:23:04 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:23:35 - [debug] Flushing localfilesystem context scope global
20 Dec 09:24:05 - [debug] Flushing localfilesystem context scope global
20 Dec 09:24:05 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:24:35 - [debug] Flushing localfilesystem context scope global
20 Dec 09:25:05 - [debug] Flushing localfilesystem context scope global
20 Dec 09:25:05 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:26:08 - [info] [cronplus:1st of the month] System Time Change Detected - refreshing schedules! If the system time was not changed then this typically occurs due to blocking code elsewhere in your application
20 Dec 09:26:08 - [debug] [cronplus:1st of the month] Refreshing running schedules
20 Dec 09:26:08 - [debug] [cronplus:1st of the month] stopped 'schedule1' ~ 'schedule1'
20 Dec 09:26:08 - [debug] [cronplus:1st of the month] started 'schedule1' ~ 'schedule1'
20 Dec 09:26:08 - [debug] Flushing localfilesystem context scope global
20 Dec 09:26:38 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:26:38 - [debug] Flushing localfilesystem context scope global
20 Dec 09:27:11 - [debug] Flushing localfilesystem context scope global
20 Dec 09:27:11 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:27:40 - [debug] [api-call-service:Clear notification] Calling Service: {"domain":"notify","service":"richards_devices","target":{},"data":{"message":"clear_notification","data":{"tag":"close_shower_room_window"}}}
20 Dec 09:27:41 - [debug] Flushing localfilesystem context scope global
20 Dec 09:27:41 - [debug] Flushing localfilesystem context scope d8eb9a92ad88bba2
20 Dec 09:28:14 - [debug] Flushing localfilesystem context scope global
20 Dec 09:28:14 - [debug] Flushing localfilesystem context scope fb3171d8.dbbce
20 Dec 09:28:21 - [info] [server:Home Assistant] Connection closed to http://192.168.1.10:8123
20 Dec 09:28:21 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] getting message { _msgid: '209634a920d36f85' }
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] { language: 'en', ip: '192.168.1.30', volume: 0.45, topic: 'cast', delay: 250 }
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] only sending unspecified request
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] connect to client { language: 'en', ip: '192.168.1.30', volume: 0.45, topic: 'cast', delay: 250, host: '192.168.1.30' }
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] statusCallback
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] getSessions Callback
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] checkVolume { language: 'en', ip: '192.168.1.30', volume: 0.45, topic: 'cast', delay: 250, host: '192.168.1.30', port: 8009, rejectUnauthorized: false }20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] doSetVolume 0.45
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] try to set volume { level: 0.45 }
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] session []
20 Dec 09:28:26 - [debug] [cast-to-client:Volume to 45%] status = { applications: [] }
20 Dec 09:28:26 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:31 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:36 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:41 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:44 - [debug] Flushing localfilesystem context scope global
20 Dec 09:28:46 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:51 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:28:56 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:29:01 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:29:06 - [info] [server:Home Assistant] Connecting to http://192.168.1.10:8123
20 Dec 09:29:06 - [info] [server:Home Assistant] Connected to http://192.168.1.10:8123
20 Dec 09:29:06 - [debug] [server:Home Assistant] States Loaded
20 Dec 09:30:53 - [info] [cronplus:1st of the month] System Time Change Detected - refreshing schedules! If the system time was not changed then this typically occurs due to blocking code elsewhere in your application
20 Dec 09:30:53 - [debug] [cronplus:1st of the month] Refreshing running schedules
20 Dec 09:30:53 - [debug] [cronplus:1st of the month] stopped 'schedule1' ~ 'schedule1'
20 Dec 09:30:53 - [debug] [cronplus:1st of the month] started 'schedule1' ~ 'schedule1'
20 Dec 09:30:53 - [debug] Flushing localfilesystem context scope global
20 Dec 09:30:53 - [info] [mqtt-broker:Mosquitto] Disconnected from broker: http://192.168.1.10
20 Dec 09:30:53 - [debug] [server:Home Assistant] Services Loaded
20 Dec 09:30:53 - [debug] [ha-time:Daniel Lights Out] Destroying cronjob: Fri Dec 20 2024 21:15:00 GMT+0000 (Greenwich Mean Time)
20 Dec 09:30:53 - [debug] [ha-time:Daniel Lights Out +1] Destroying cronjob: Fri Dec 20 2024 22:15:00 GMT+0000 (Greenwich Mean Time)
20 Dec 09:30:53 - [debug] [ha-time:Tabitha Lights Out] Destroying cronjob: Fri Dec 20 2024 21:15:00 GMT+0000 (Greenwich Mean Time)
20 Dec 09:30:53 - [debug] [ha-time:Tabitha Lights Out +1] Destroying cronjob: Fri Dec 20 2024 22:15:00 GMT+0000 (Greenwich Mean Time)
20 Dec 09:30:53 - [debug] [ha-time:Daniel Lights Out] Creating cronjob: 0 15 21 * * *
20 Dec 09:30:53 - [debug] [ha-time:Daniel Lights Out +1] Creating cronjob: 0 15 22 * * *
20 Dec 09:30:53 - [debug] [ha-time:Tabitha Lights Out] Creating cronjob: 0 15 21 * * *
20 Dec 09:30:53 - [debug] [ha-time:Tabitha Lights Out +1] Creating cronjob: 0 15 22 * * *
20 Dec 09:30:54 - [red] Uncaught Exception:
20 Dec 09:30:54 - [error] UnhandledPromiseRejection: This error originated either by throwing inside of an async function without a catch block, or by rejecting a promise which was not handled with .catch(). The promise rejected with the reason "3".
at throwUnhandledRejectionsMode (node:internal/process/promises:389:7)
at processPromiseRejections (node:internal/process/promises:470:17)
at process.processTicksAndRejections (node:internal/process/task_queues:96:32)
Thanks,
Sadly, it seems HA is hiding the lines after..
at process.processTicksAndRejections (node:internal/process/task_queues:96:32)
Without that, its not possible to determine the source failure.
But HA is not showing us the point at which it starts ha-time whatever that is.... (we dont use HA here) - given its 1s after
(so maybe something for HA to look at)
But without the complete stack trace - we won't know I am afraid
1s after
20 Dec 09:30:53 - [debug] [ha-time:Tabitha Lights Out +1] Creating cronjob: 0 15 22 * * *
20 Dec 09:30:54 - [red] Uncaught Exception:
Seems like a HA Node issue (again - its just a guess, without the full stack trace)
EDIT
Seems the source failure might not always be shown, still my only breadcrumb is this ha-time thing
This is also an indicator that perhaps you are either processing some heavy data synchronously (like a for loop in an array) or some widget is processing some heavy synchronous task. Could be related to your troubles. I built that into cron plus to refresh schedules when the clock did not update in a timely manor & left the debug message in because it is a good indicator of trouble.
As for the UnhandledPromiseRejection - i've seen this when a contrib node is not handling the catch of a promise OR passing node.error directly to the catch handler (i.e. bad contrib node)
1 Like
I always thought, the stack trace leads up to the inline exception happening?
const breakMeBaby = () => {
return Promise.reject()
}
breakMeBaby() // Source File, line number in stack trace??
// due to it, not being handled
I clearly need to learn more about stack traces if so (entirely possible)
Cant recall why the stack is not available in certain cases but from memory, its when arrow function are used in callback, async or promise without suitable error handling.
Easy enough to try out - but right now, beer beckons me: its time for black eye Friday.
2 Likes
I am a few Captain M's in (Sorry bit spammy)
