Cron-plus 2.1.0 - system time change detected?

I get the following error message on my RPI 4 running node-red 3.1 and chronplus.
This cause troubles with my heating system after a variable time of running. 30 min up to 2 hours.
It seems to send undifined value to all rooms.

Log:
20 Nov 20:21:48 - [info] [cronplus:Heating] 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

Is your pi restarting?

I don't think so.
the server reconnects and restarts and then I can reload the web site and it works for a while until next reconnect

This message is key to understand.

It's telling you that something is hammering your node-red (like a loop or a heavy blocking process) and nodejs time hasn't been able to get updates through.

Couple that with your statement of...

... I think something is a miss.

The message you are seeing is telling you something isn't quite right. It's a result/symptom, not a cause.

Are there any other messages in the logs? Signs of restarts or crashes?

what ist the best way to get a meaningful log.
Have not used it before

Assuming you installed using the recommended install script then the command node-red-log will show recent output to the log. Or you may use

node-red-stop
node-red-start

to stop and restart node-red and show the log from the start.

or node-red-reload which does stop then start (and log)

Many thanks for your support!
I reinstalled everything from ground up.
RPI 4, Bullseye, node-red 3.1, all node-red modules, then copied my flows to the fresh RPI and it runs.
But I don't know what caused the problem: :face_with_raised_eyebrow:

Hi Colin,
after one day of error free running I got the same problem.
The log says that there is an inject every 30 sec for global context.
Could this be in conflict with cron-plus?
I mean blocking something.

I found some info regarding time sync with ntp server. It was recommended to increase the RootDistanceMaxSec due to slow network. Does this make sense for you?

Show us the log around the message please, about 10 messages before it and a few after.
Also show us the log from when node-red starts up.

Show us exactly what it says, and where you see it.

22 Nov 15:08:36 - [debug] Flushing localfilesystem context scope global
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 0, static: false, opt: {"command":"add","name":"DGWZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGWZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGWZ-7' ~ 'DGWZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 1, static: false, opt: {"command":"add","name":"DGWZ-12","expression":"0 0 12 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGWZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGWZ-12' ~ 'DGWZ-12'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 2, static: false, opt: {"command":"add","name":"DGWZ-16","expression":"0 0 16 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGWZ","type":"soll","value":"20"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGWZ-16' ~ 'DGWZ-16'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 3, static: false, opt: {"command":"add","name":"DGWZ-21","expression":"0 0 21 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGWZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGWZ-21' ~ 'DGWZ-21'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 4, static: false, opt: {"command":"add","name":"DGSZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGSZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGSZ-7' ~ 'DGSZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 5, static: false, opt: {"command":"add","name":"DGSZ-18","expression":"0 0 18 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGSZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGSZ-18' ~ 'DGSZ-18'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 6, static: false, opt: {"command":"add","name":"DGSZ-22","expression":"0 0 22 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGSZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGSZ-22' ~ 'DGSZ-22'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 7, static: false, opt: {"command":"add","name":"DGGZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGGZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGGZ-7' ~ 'DGGZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 8, static: false, opt: {"command":"add","name":"DGGZ-18","expression":"0 0 18 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGGZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGGZ-18' ~ 'DGGZ-18'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 9, static: false, opt: {"command":"add","name":"DGBZ-7","expression":"0 25 6 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGBZ","type":"soll","value":"20"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGBZ-7' ~ 'DGBZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 10, static: false, opt: {"command":"add","name":"DGBZ-10","expression":"0 0 10 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGBZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGBZ-10' ~ 'DGBZ-10'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 11, static: false, opt: {"command":"add","name":"DGBZ-18","expression":"0 0 18 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGBZ","type":"soll","value":"19"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGBZ-18' ~ 'DGBZ-18'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 12, static: false, opt: {"command":"add","name":"DGBZ-22","expression":"0 0 22 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGBZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGBZ-22' ~ 'DGBZ-22'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 13, static: false, opt: {"command":"add","name":"DGBZ-ZH","expression":"0 15 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"DGBZ","type":"ZH","value":"on"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'DGBZ-ZH' ~ 'DGBZ-ZH'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 14, static: false, opt: {"command":"add","name":"EGWZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGWZ-7' ~ 'EGWZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 15, static: false, opt: {"command":"add","name":"EGWZ-9","expression":"0 0 9 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWZ","type":"soll","value":"20"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGWZ-9' ~ 'EGWZ-9'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 16, static: false, opt: {"command":"add","name":"EGWZ-13","expression":"0 0 13 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWZ","type":"soll","value":"20"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGWZ-13' ~ 'EGWZ-13'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 17, static: false, opt: {"command":"add","name":"EGWZ-16","expression":"0 0 16 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGWZ-16' ~ 'EGWZ-16'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 18, static: false, opt: {"command":"add","name":"EGWZ-20","expression":"0 0 20 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGWZ-20' ~ 'EGWZ-20'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 19, static: false, opt: {"command":"add","name":"EGWZ-23","expression":"0 30 22 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGWZ-23' ~ 'EGWZ-23'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 20, static: false, opt: {"command":"add","name":"EGSZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGSZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGSZ-7' ~ 'EGSZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 21, static: false, opt: {"command":"add","name":"EGSZ-10","expression":"0 0 10 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGSZ","type":"soll","value":"16"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGSZ-10' ~ 'EGSZ-10'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 22, static: false, opt: {"command":"add","name":"EGAZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGAZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGAZ-7' ~ 'EGAZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 23, static: false, opt: {"command":"add","name":"EGAZ-9","expression":"0 0 9 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGAZ","type":"soll","value":"19"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGAZ-9' ~ 'EGAZ-9'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 24, static: false, opt: {"command":"add","name":"EGAZ-20","expression":"0 0 20 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGAZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGAZ-20' ~ 'EGAZ-20'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 25, static: false, opt: {"command":"add","name":"EGAZ-23","expression":"0 0 23 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGAZ","type":"soll","value":"18"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGAZ-23' ~ 'EGAZ-23'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 26, static: false, opt: {"command":"add","name":"EGBZ-7","expression":"0 25 6 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGBZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGBZ-7' ~ 'EGBZ-7'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 27, static: false, opt: {"command":"add","name":"EGBZ-10","expression":"0 0 10 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGBZ","type":"soll","value":"20"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGBZ-10' ~ 'EGBZ-10'
22 Nov 15:09:55 - [debug] [cronplus:Heating] createTask - index: 28, static: false, opt: {"command":"add","name":"EGBZ-18","expression":"0 0 18 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGBZ","type":"soll","value":"21"}}
22 Nov 15:09:55 - [debug] [cronplus:Heating] started 'EGBZ-18' ~ 'EGBZ-18'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 29, static: false, opt: {"command":"add","name":"EGBZ-23","expression":"0 0 23 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGBZ","type":"soll","value":"18"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'EGBZ-23' ~ 'EGBZ-23'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 30, static: false, opt: {"command":"add","name":"EGBZ-ZH","expression":"0 45 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGBZ","type":"ZH","value":"on"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'EGBZ-ZH' ~ 'EGBZ-ZH'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 31, static: false, opt: {"command":"add","name":"EGKU-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGKU","type":"soll","value":"16"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'EGKU-7' ~ 'EGKU-7'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 32, static: false, opt: {"command":"add","name":"EGKU-23","expression":"0 0 23 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGKU","type":"soll","value":"16"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'EGKU-23' ~ 'EGKU-23'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 33, static: false, opt: {"command":"add","name":"EGWR-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWR","type":"soll","value":"21"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'EGWR-7' ~ 'EGWR-7'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 34, static: false, opt: {"command":"add","name":"EGWR-23","expression":"0 0 23 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"EGWR","type":"soll","value":"18"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'EGWR-23' ~ 'EGWR-23'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 35, static: false, opt: {"command":"add","name":"UGBU-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBU","type":"soll","value":"20"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBU-7' ~ 'UGBU-7'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 36, static: false, opt: {"command":"add","name":"UGBU-9","expression":"0 0 9 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBU","type":"soll","value":"20"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBU-9' ~ 'UGBU-9'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 37, static: false, opt: {"command":"add","name":"UGBU-20","expression":"0 0 20 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBU","type":"soll","value":"20"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBU-20' ~ 'UGBU-20'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 38, static: false, opt: {"command":"add","name":"UGBU-23","expression":"0 0 23 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBU","type":"soll","value":"18"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBU-23' ~ 'UGBU-23'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 39, static: false, opt: {"command":"add","name":"UGBZ-7","expression":"0 0 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBZ","type":"soll","value":"18"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBZ-7' ~ 'UGBZ-7'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 40, static: false, opt: {"command":"add","name":"UGBZ-23","expression":"0 0 23 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBZ","type":"soll","value":"18"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBZ-23' ~ 'UGBZ-23'
22 Nov 15:09:56 - [debug] [cronplus:Heating] createTask - index: 41, static: false, opt: {"command":"add","name":"UGBZ-ZH","expression":"0 45 7 * * * *","expressionType":"cron","payloadType":"json","payload":{"room":"UGBZ","type":"ZH","value":"off"}}
22 Nov 15:09:56 - [debug] [cronplus:Heating] started 'UGBZ-ZH' ~ 'UGBZ-ZH'
22 Nov 15:10:01 - [info] [cronplus:Heating] 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
22 Nov 15:10:01 - [debug] [cronplus:Heating] Refreshing running schedules
22 Nov 15:10:01 - [debug] [cronplus:Heating] stopped 'DGWZ-7' ~ 'DGWZ-7'
22 Nov 15:10:01 - [debug] [cronplus:Heating] started 'DGWZ-7' ~ 'DGWZ-7'
22 Nov 15:10:01 - [debug] [cronplus:Heating] stopped 'DGWZ-12' ~ 'DGWZ-12'

What log settting should I use when node-red starts?
At the moment I have set Trace which puts out many lines when it starts all flows

Info probably.

There are a lot of tasks added to the cronplus node just before the problem occurs, is that something that happens regularly?

Also look back in /var/log/syslog to 15:10 and see what it says about the time change.

this happens only at start.
it is the daily temp profile for 12 rooms.
UG means basement, EG first floor and DG attic floor

I am not quite sure, but I think the problem started after an full-upgrade of Bullseye
does this make sense to you?
After the reinstallation yesterday morning it worked quite well for about 24 hours.
before that reinstallation the problems occured about every 30 to 60 min.
Today only once but I restarted quite often.
As I mentioned before, could context storage (save to file every 30 sec) be a blocking problem?

this could be the problem:

22 Nov 18:37:35 - [error] TypeError: Cannot read properties of undefined (reading 'devices')
    at NetatmoDashboard._inputCallback (/home/pi/.node-red/node_modules/node-red-contrib-netatmo-dashboard/netatmo-dashboard.js:96:19)
    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: Consumed 1min 8.848s CPU time.
nodered.service: Scheduled restart job, restart counter is at 1.
Stopped Node-RED graphical event wiring tool.
nodered.service: Consumed 1min 8.848s CPU time.
Started Node-RED graphical event wiring tool.
22 Nov 18:37:57 - [info]
Willkommen bei Node-RED
===================
22 Nov 18:37:57 - [info] Node-RED Version: v3.1.0
22 Nov 18:37:57 - [info] Node.js  Version: v18.17.1
22 Nov 18:37:57 - [info] Linux 6.1.21-v8+ arm LE
22 Nov 18:37:58 - [info] Paletten-Nodes werden geladen
22 Nov 18:38:00 - [info] Dashboard version 3.6.1 started at /ui
22 Nov 18:38:01 - [info] Einstellungsdatei: /home/pi/.node-red/settings.js
22 Nov 18:38:01 - [info] HTTP-Statisch: /home/pi/.node-red/node-red-static > /
22 Nov 18:38:01 - [info] Kontextspeicher: memoryOnly [module=memory]
22 Nov 18:38:01 - [info] Kontextspeicher: file [module=localfilesystem]
22 Nov 18:38:01 - [info] Benutzerverzeichnis: /home/pi/.node-red
22 Nov 18:38:01 - [warn] Projekte deaktiviert: editorTheme.projects.enabled=false
22 Nov 18:38:01 - [info] Flow-Datei: /home/pi/.node-red/flows.json
22 Nov 18:38:01 - [info] Server wird jetzt auf http://127.0.0.1:1880/ ausgeführt
22 Nov 18:38:02 - [warn]
---------------------------------------------------------------------
Die Datei mit den Flow-Credentials wird mit einem vom System
generierten Schlüssel verschlüsselt.
Wenn der vom System generierte Schlüssel aus irgendeinem Grund
verloren geht, kann die Datei mit den Credentials nicht
wiederhergestellt werden. Sie muss dann gelöscht und die
Credentials müssen erneut eingestellt werden.
Es sollte ein eigener Schlüssel mit Hilfe der Option
'credentialSecret' in der Einstellungsdatei vorgegeben werden.
Node-RED wird dann die Datei mit den Flow-Credentials
bei der nächsten Ãbernahme (deploy) einer Ã
                                            nderung erneut
verschlüsseln.
---------------------------------------------------------------------
22 Nov 18:38:02 - [info] Flows werden gestartet
22 Nov 18:38:05 - [info] Flows sind gestartet
22 Nov 18:38:06 - [info] [mqtt-broker:99603ece.52e2a] Verbindung zum Broker mqtt://10.0.0.43:1883 aufgebaut

Part of the problem at least. Reading Node Red crashes · Issue #21 · guidone/node-red-contrib-netatmo-dashboard · GitHub it appears that the node is no longer supported. You might need to find an alternative node.

... or fork the node and fix those issues.

As it looks like, some optional chaining operators could make a number of people happy! :wink:

line 96: _(data?.body?.devices).each(function (station) {

The mysterious callback could then e.g. be replaced by reject.

line 46:         reject(error);
1 Like

Hi Ralph,

I am not experienced enough to change something in Github.
Would very much apreciate if you could help me doing this?

Hannes