Mysterious Startup notices

[athome]

I am trying to configure a Node-RED startup flow and have tried both of these techniques:

1. https://cookbook.nodered.org/basic/trigger-on-start
2. https://flows.nodered.org/node/node-red-contrib-startup-trigger

It is interesting that I am receiving mysterious startup messages from both flows even though I am not restarting Node-RED.

Is there someplace that I can read about the way the Node-RED startup event is triggered?

Thanks in advance.

[knolleary]

@athome

It is interesting that I am receiving mysterious startup messages

When do you receive the messages? The Inject node will be triggered whenever you do a full deploy. If that is the case, you can use the 'Modified flows' or 'Modified nodes' types of deploy and as long as you haven't modified the flow connected to the Inject node, it won't be retriggered.

[Colin]

@athome

am receiving mysterious startup messages

Do you mean you are seeing the Welcome to Node-red message? If not then show us exactly what you are seeing.

[athome]

I have removed the example code because it nothing more than the start up example from the node red docs. And, it is a distraction from the question.

[Colin]

See this page for how to post flows here, edit your previous post accordingly so we can import it.
Also run node-red-log and leave it running, see whether node-red is restarting when you see the messages.

How to share code or flow json

To share code samples or flow json in this forum, you need to take care to format it properly so that it is displayed correctly. The easiest way to do that is to click the 'Preformatted Text' button in the toolbar: [image] Then paste in your code or flow json. You should end up with three back-tick characters - ``` - on their own line before and after the code. On standard US English keyboards, this is on the same key as the ~ character. [IMG_20181111_155651] Using the backticks will ens…

[athome]

knolleary

I haven't got every use case worked out. Here is what I observe.

1. The startup event is triggered when I deploy the first change of the day.
2. There are times when the timestamp on the start up event indicates that the event was triggered on the same second that a sequence in a completely different workflow is executed.

If there is something that I could read that describes when the event is suppose to trigger, that would be most helpful.

I am on node-red V0.19.4
Ubuntu 16.04 / xenial

[Colin]

You still haven't told us exactly what you mean by startup event. Exactly what are you seeing? If it is something in the node-red log then post it here, along with whatever comes before it.

[athome]

Colin,

Because I can usually, but not always, cause the "startup" event to trigger on demand just by hitting Deploy, I have just now wiggled a debug node on a flow and hit Deploy. The following happens:

1. These few lines, which might be relevant, appear in the log (sudo journalctl -f -n 500 -o cat):
   14 Jun 01:16:02 - [info] Started flows
   14 Jun 01:16:02 - [info] [inject:d8a5c409.704f3] repeat = 10000
   14 Jun 01:16:02 - [info] [inject:ping every 10 min] repeat = 600000
   14 Jun 01:16:02 - [info] [mqtt-broker:home] Connected to broker: mqtt://192.168.14.178:1883
   14 Jun 01:16:02 - [info] [mqtt-broker:home] Connected to broker: water_main_nodered@mqtt://192.168.14.178:1883
   14 Jun 01:16:02 - [warn] [api-current-state:suppress text off] local state cache missing, sending empty payload

2. This appears in the debug console:
   Debug message from a single sequence in its own flow (startup1) that uses the inject method to notify a startup event. The sequence in this flow is copy and paste from the node-red example to which I have added a write to the local log file.
   {"topic":"node-red startup event","payload":"startup event -- flow=startup1","_msgid":"61bb0ff0.eeb26"}

Debug message from a single sequence in its own flow that uses the start-up-trigger-contrib node to notify a startup event.
{"start":"Started","_msgid":"4e860399.7fbadc","payload":"payload from the startup-trigger node in flow startup2undefined"}

3. Both flows have a file write node that captures a simple message when the startup event is triggered:
   2019.6.14 1:16:02: startup event -- flow=startup1
   2019.6.14 1:16:05: payload from the startup-trigger node in flow startup2undefined

As I mentioned, it does not always happen that hitting Deploy will trigger a startup event. I repeated the use case and this appeared in the log (sudo journalctl -f -n 500 -o cat) I did not receive a notice of a startup event in the debug window of the file.
14 Jun 01:34:42 - [info] Stopping modified flows
14 Jun 01:34:42 - [info] Stopped modified flows
14 Jun 01:34:42 - [info] Starting modified flows
14 Jun 01:34:42 - [info] Started modified flows

Hope this helps. Happy to provide any other details as needed.

[Colin]

@athome

These few lines, which might be relevant, appear in the log (sudo journalctl -f -n 500 -o cat):
14 Jun 01:16:02 - [info] Started flows

What is before those lines? Start the log running and leave it going. It is not clear yet whether node-red is restarting (which is what the use of the words startup event suggests) or if it just that some nodes are being restarted when you are not expecting them to.
Note that if you do a Full deploy or deploy the nodes shown then you would expect to see mqtt reconnect and any inject nodes with inject on startup enabled to report the restart.

It might help if you were to make a simple sample flow which shows the problem and explain exactly what you are doing.

[athome]

I am trying to learn how to implement sequences that are triggered by a startup event. As a starting point, i copied the sequence from https://cookbook.nodered.org/basic/trigger-on-start and embellished it by writing the payload to a file and by sending the payload to my phone via the super useful twilio node.

Much to my surprise, i have started receiving startup event texts when they are not expected (i.e. when I am at work, at 04:00 in the morning, and other times when I am not doing any node-red work and am not logged into the machine that hosts node-red.).

The startup page referenced above says:

Discussion

When configured to fire on start, the Inject node will be automatically triggered a few hundred milliseconds after it is deployed. This delay is used to help ensure the rest of the flows have been created and Started by this point.

The node will trigger whenever it is deployed.

Because I am receiving startup texts at 4 in the morning, I would like to know what else besides deploying the trigger node causes a startup event.
If the machine hosting Node-RED has a momentary disconnect from the network, will that cause Node-RED to trigger a start event?
My experience shows me that it is more than starting the node-red service that will trigger a startup event.

This is what I am trying to learn: what are the scenarios will cause this sequence to be triggered? https://cookbook.nodered.org/basic/trigger-on-start

Thanks for your help with this.

Re content from the log, i grabbed log content before and after what I have posted above. (sorry, don't know why the bold text)

<--- JS stacktrace --->
==== JS stack trace =========================================
    0: ExitFrame [pc: 0x2afcf2d4fb5d]
Security context: 0x3bddea79d9f1 <JSObject>
    1: _clone(aka _clone) [0x32acb8458439] [/usr/lib/node_modules/node-red/node_modules/clone/clone.js:~73] [pc=0x2afcf3311404](this=0x115e51d825b1 <undefined>,0x0f2cb3bb8c31 <String[14]: 6411219e.ae246>,0x32acb8458669 <HeapNumber inf>)
    2: _clone(aka _clone) [0x32acb8458439] [/usr/lib/node_modules/node-red/node_modules/clone/clone.js:~73] [pc=0x2afcf3311...
FATAL ERROR: Ineffective mark-compacts near heap limit Allocation failed - JavaScript heap out of memory
 1: 0x944930 node::Abort() [node-red]
 2: 0x9457dc node::OnFatalError(char const*, char const*) [node-red]
 3: 0xb0d01e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [node-red]
 4: 0xb0d254 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [node-red]
 5: 0xf09822  [node-red]
 6: 0xf09928 v8::internal::Heap::CheckIneffectiveMarkCompact(unsigned long, double) [node-red]
 7: 0xf16048 v8::internal::Heap::PerformGarbageCollection(v8::internal::GarbageCollector, v8::GCCallbackFlags) [node-red]
 8: 0xf16b5b v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [node-red]
 9: 0xf19891 v8::internal::Heap::AllocateRawWithRetryOrFail(int, v8::internal::AllocationSpace, v8::internal::AllocationAlignment) [node-red]
10: 0xee3ac4 v8::internal::Factory::NewFillerObject(int, bool, v8::internal::AllocationSpace) [node-red]
11: 0x11994ae v8::internal::Runtime_AllocateInNewSpace(int, v8::internal::Object**, v8::internal::Isolate*) [node-red]
12: 0x2afcf2d4fb5d
2019-06-14 01:15:59 ERROR (MainThread) [aiohttp.server] Unhandled exception
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 448, in start
    await resp.write_eof()
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_response.py", line 444, in write_eof
    await self._payload_writer.write_eof(data)
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/http_writer.py", line 138, in write_eof
    self._write(chunk)
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/http_writer.py", line 67, in _write
    raise ConnectionResetError('Cannot write to closing transport')
ConnectionResetError: Cannot write to closing transport
node-red.service: Main process exited, code=dumped, status=6/ABRT
2019-06-14 01:15:59 ERROR (MainThread) [aiohttp.server] Unhandled exception
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 448, in start
    await resp.write_eof()
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_response.py", line 444, in write_eof
    await self._payload_writer.write_eof(data)
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/http_writer.py", line 138, in write_eof
    self._write(chunk)
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/http_writer.py", line 67, in _write
    raise ConnectionResetError('Cannot write to closing transport')
ConnectionResetError: Cannot write to closing transport
2019-06-14 01:15:59 ERROR (MainThread) [aiohttp.server] Unhandled exception
Traceback (most recent call last):
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_protocol.py", line 448, in start
    await resp.write_eof()
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/web_response.py", line 444, in write_eof
    await self._payload_writer.write_eof(data)
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/http_writer.py", line 138, in write_eof
    self._write(chunk)
  File "/srv/homeassistant/lib/python3.6/site-packages/aiohttp/http_writer.py", line 67, in _write
    raise ConnectionResetError('Cannot write to closing transport')
ConnectionResetError: Cannot write to closing transport
node-red.service: Unit entered failed state.
node-red.service: Failed with result 'core-dump'.
node-red.service: Service hold-off time over, scheduling restart.
Stopped Node-RED.
Started Node-RED.
14 Jun 01:15:59 - [info]
Welcome to Node-RED
===================
14 Jun 01:15:59 - [info] Node-RED version: v0.19.4
14 Jun 01:15:59 - [info] Node.js  version: v11.3.0
14 Jun 01:15:59 - [info] Linux 4.4.0-148-generic x64 LE
14 Jun 01:16:00 - [info] Loading palette nodes
14 Jun 01:16:01 - [info] Dashboard version 2.15.4 started at /ui
14 Jun 01:16:01 - [warn] rpi-gpio : Raspberry Pi specific node set inactive
14 Jun 01:16:01 - [warn] rpi-gpio : Cannot find Pi RPi.GPIO python library
14 Jun 01:16:01 - [info] Settings file  : /home/homemanadmin/.node-red/settings.js
14 Jun 01:16:01 - [info] Context store  : 'default' [module=memory]
14 Jun 01:16:01 - [info] User directory : /home/homemanadmin/.node-red
14 Jun 01:16:01 - [info] Server now running at http://127.0.0.1:1880/
14 Jun 01:16:01 - [info] Active project : nodered-homeassistant
14 Jun 01:16:01 - [info] Flows file     : /home/homemanadmin/.node-red/projects/nodered-homeassistant/flows_homeMan-server.json
14 Jun 01:16:01 - [info] Starting flows
14 Jun 01:16:01 - [info] [sun events:Sunevent] Calculating sun event times for 33.5464796, -112.0974539.
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Initialising job to calculate sunevents
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Calculating times for Fri Jun 14 2019 23:59:59 GMT-0700
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting solarNoon Today at 12:29 PM in 11 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Ignoring nadir, was Today at 12:29 AM, 0 hours ago
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting sunrise Today at 5:19 AM in 4 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting sunset Today at 7:40 PM in 18 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting sunriseEnd Today at 5:22 AM in 4 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting sunsetStart Today at 7:37 PM in 18 hours
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=120955 PROTO=UDP SPT=45447 DPT=10001 LEN=155 
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting dawn Today at 4:50 AM in 3 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting dusk Today at 8:09 PM in 18 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting nauticalDawn Today at 4:14 AM in 2 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting nauticalDusk Today at 8:45 PM in 19 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting nightEnd Today at 3:35 AM in 2 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting night Today at 9:24 PM in 20 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting goldenHourEnd Today at 5:55 AM in 4 hours
14 Jun 01:16:01 - [info] [sun events:Sunevent] [sunevents] Emitting goldenHour Today at 7:04 PM in 17 hours
14 Jun 01:16:02 - [info] [inject:sms_suspend] crontab = 00 09 * * *
14 Jun 01:16:02 - [info] [inject:8629978f.2e5c3] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:cdadb250.cf2348] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:20597ffd.e53a6] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:9833d03d.f7c92] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:a53d1d8c.95ba98] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:312fa6b6.64206a] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:f30cf6a2.b0d848] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:3989ba37.09d486] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:dd6b70c1.c9cda8] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] [inject:7badfdc3.358384] crontab = 55 23 * * *
14 Jun 01:16:02 - [info] Started flows
14 Jun 01:16:02 - [info] [inject:d8a5c409.704f3] repeat = 10000
14 Jun 01:16:02 - [info] [inject:ping every 10 min] repeat = 600000
14 Jun 01:16:02 - [info] [mqtt-broker:home] Connected to broker: mqtt://192.168.14.178:1883
14 Jun 01:16:02 - [info] [mqtt-broker:home] Connected to broker: water_main_nodered@mqtt://192.168.14.178:1883
14 Jun 01:16:02 - [warn] [api-current-state:suppress text off] local state cache missing, sending empty payload
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=807587 PROTO=UDP SPT=46520 DPT=10001 LEN=155 
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=776418 PROTO=UDP SPT=43758 DPT=10001 LEN=155 
2019-06-14 01:16:58 WARNING (SyncWorker_3) [homeassistant.components.tplink.light] Could not read state for 192.168.14.183: Communication error
pam_unix(cron:session): session opened for user root by (uid=0)
(root) CMD (   cd / && run-parts --report /etc/cron.hourly)
pam_unix(cron:session): session closed for user root
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=388968 PROTO=UDP SPT=40833 DPT=10001 LEN=155 
[UFW BLOCK] IN=enp0s25 OUT= MAC=01:00:5e:00:00:01:c0:56:27:cb:c7:ee:08:00 SRC=192.168.14.97 DST=224.0.0.1 LEN=28 TOS=0x00 PREC=0xC0 TTL=1 ID=54494 PROTO=2 
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=524732 PROTO=UDP SPT=33672 DPT=10001 LEN=155 
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=892283 PROTO=UDP SPT=49931 DPT=10001 LEN=155 
2019-06-14 01:18:01 WARNING (SyncWorker_3) [homeassistant.components.tplink.light] Could not read state for 192.168.14.183: Communication error
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=358241 PROTO=UDP SPT=45852 DPT=10001 LEN=155 
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=194673 PROTO=UDP SPT=59154 DPT=10001 LEN=155 
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=28236 PROTO=UDP SPT=52161 DPT=10001 LEN=155 
[UFW BLOCK] IN=enp0s25 OUT= MAC=33:33:00:00:00:01:b4:fb:e4:82:14:cc:86:dd SRC=fe80:0000:0000:0000:b6fb:e4ff:fe82:14cc DST=ff02:0000:0000:0000:0000:0000:0000:0001 LEN=195 TC=0 HOPLIMIT=1 FLOWLBL=1247 PROTO=UDP SPT=59729 DPT=10001 LEN=155 
^C

[knolleary]

@athome

Because I am receiving startup texts at 4 in the morning, I would like to know what else besides deploying the trigger node causes a startup event.

If an Inject node is configured to trigger on start up then it will trigger for the following events:

1. Node-RED has started
2. A Deploy has happened causing the flow to restart

That is it.

When pasting log info, it is useful to format it as code using the formatting toolbar. That stops are unintended formatting for bits being mistaken for markdown formatting. I have edited your previous post to fix the formatting.

I assume you have checked the logs to see if Node-RED is restarting at the times you receive these unexpected messages? The log you have pasted starts with an out of memory error, so there is evidence there that your instance is restarting on occasion itself.

[Colin]

As you can see, node-red is crashing and restarting, hence you see the startup injections again.

@athome

Allocation failed - JavaScript heap out of memory

It seems you are running out of memory, whether you can get a clue what is causing it by looking at the messages in more detail I don't know.

[athome]

Thank you both for the log observations.