Strange Time Difference in CRON Plus Node Trigger Time & Output

Buckskin · 30 December 2023 21:30

I have noticed a difference of around 11 minutes between the time set for a schedule and the time that it is issued by cronplus. ( output from attached debug node at - 30/12/2023, 21:11:16[node: CRON Schedules] ) I have checked the times on the PC with the browser and the Pi running Node-RED and they are the same. Does anyone have any ideas as to why this might be.

{"triggerTimestamp":2023-12-30T21:00:00.000Z,
 "status":{"type":"static",
           "modified":false,
           "isRunning":true,
           "count":1,
           "limit":0,
           "nextDescription":"in 23 hours 59 minutes 59 seconds",
           "nextDate":"2023-12-31T21:00:00.000Z",
           "nextDateTZ":"31 Dec 2023, 21:00:00 GMT",
           "timeZone":"Europe/London",
           "serverTime":"2023-12-30T21:00:00.028Z",
           "serverTimeZone":"Europe/London",
           "description":"At 21:00"
          },
 "config":{"topic":"schedule/temperature/bedroom",
           "name":"TRV Bedroom Schedule 04",
           "index":5,
           "payloadType":"num",
           "payload":"19",
           "limit":null,
           "expressionType":"cron",
           "expression":"0 0 21 * * * *"
          }
}

Colin · 30 December 2023 22:01

Are you using the latest version of the cronplus node? Check in Manage Palette.
Also if you restart node-red does it recover?

Steve-Mcl · 30 December 2023 22:24

According to this the node fire within 28ms of requested time.

Where do you see this other timestamp? To be certain, attach a debug node set to output to console and check again. Also, is you node-red bogged down/taxed with heavy load? Are you seeing time resync messages in the logs?

Buckskin · 30 December 2023 23:47

Colin, yes to latest version of cronplus (2.1.0), no to 'does it recover'.

Steve the other time stamp is from the attached debug node, see below.
Using top the cpu load for Node-RED runs around 4% with a peak of 27%
No rsync messages

However, I have just discovered that this does NOT happen at every time set schedule (only occasionally which is one I happened to notice). Very weird.

Colin · 31 December 2023 13:38

Is the debug node CRON Schedules connected directly to the cron node?

Also, as Steve suggested, configure the debug node to ouput to Console, which means it will appear in the node-red log. Then you can look back to see what the server time was when it happened.

TotallyInformation · 31 December 2023 13:45

Perhaps you could also supply an image of the relevant part of the flow so we can see what nodes are involved?

Buckskin · 31 December 2023 21:26

[{"id":"478c1b5fa1192521","type":"debug","z":"e469483c47c63a11","g":"13f199cebc7ed83c","name":"CRON Schedules","active":true,"tosidebar":true,"console":true,"tostatus":true,"complete":"true","targetType":"full","statusVal":"payload","statusType":"auto","x":700,"y":2400,"wires":[]},{"id":"38bfb3e47b0a30e7","type":"mqtt out","z":"e469483c47c63a11","g":"13f199cebc7ed83c","name":"CRON Connection","topic":"","qos":"1","retain":"false","respTopic":"","contentType":"","userProps":"","correl":"","expiry":"","broker":"ee05e0d9.9118e","x":690,"y":2460,"wires":[]},{"id":"9232a3871a04e1e3","type":"cronplus","z":"e469483c47c63a11","g":"13f199cebc7ed83c","name":"Smart Socket & TRV Schedule","outputField":"payload","timeZone":"","storeName":"","commandResponseMsgOutput":"output2","defaultLocation":"","defaultLocationType":"default","outputs":2,"options":[{"name":"Infrared Light On","topic":"zigbee2mqtt/Smart Socket 05/set","payloadType":"json","payload":"{\"state\": \"on\"}","expressionType":"cron","expression":"0  0 22 * * *","location":"51.164570 -0.1152285","offset":"0","solarType":"selected","solarEvents":"sunset"},{"name":"Infrared Light Off","topic":"zigbee2mqtt/Smart Socket 05/set","payloadType":"json","payload":"{\"state\": \"off\"}","expressionType":"cron","expression":"0 59 23 * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Bedroom Schedule 01","topic":"schedule/temperature/bedroom","payloadType":"num","payload":"19","expressionType":"cron","expression":"0 30 07 * * * *","location":"51.16483515962793 -0.1148870587348938","offset":"0","solarType":"selected","solarEvents":"sunrise,sunset"},{"name":"TRV Bedroom Schedule 02","topic":"schedule/temperature/bedroom","payloadType":"num","payload":"18","expressionType":"cron","expression":"0 0 10 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Bedroom Schedule 03","topic":"schedule/temperature/bedroom","payloadType":"num","payload":"18","expressionType":"cron","expression":"0 0 15 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Bedroom Schedule 04","topic":"schedule/temperature/bedroom","payloadType":"num","payload":"19","expressionType":"cron","expression":"0 0 21 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Bedroom Schedule 05","topic":"schedule/temperature/bedroom","payloadType":"num","payload":"18","expressionType":"cron","expression":"0 0 22 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Bedroom Schedule 06","topic":"schedule/temperature/bedroom","payloadType":"num","payload":"15","expressionType":"cron","expression":"0 0 23 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Dining Room Schedule 01","topic":"schedule/temperature/dining room","payloadType":"num","payload":"19","expressionType":"cron","expression":"0 30 07 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Dining Room Schedule 02","topic":"schedule/temperature/dining room","payloadType":"num","payload":"20","expressionType":"cron","expression":"0 0 09 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Dining Room Schedule 03","topic":"schedule/temperature/dining room","payloadType":"num","payload":"18","expressionType":"cron","expression":"0 0 10 * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Dining Room Schedule 04","topic":"schedule/temperature/dining room","payloadType":"num","payload":"20","expressionType":"cron","expression":"0 30 12 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Dining Room Schedule 05","topic":"schedule/temperature/dining room","payloadType":"num","payload":"18","expressionType":"cron","expression":"0 0 20 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"TRV Dining Room Schedule 06","topic":"schedule/temperature/dining room","payloadType":"num","payload":"15","expressionType":"cron","expression":"0 0 23 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"Hall Dehumidifier On","topic":"zigbee2mqtt/Smart Socket 04/set","payloadType":"json","payload":"{\"state\": \"on\"}","expressionType":"cron","expression":"0 30 00 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"Hall Dehumidifier Off","topic":"zigbee2mqtt/Smart Socket 04/set","payloadType":"json","payload":"{\"state\": \"off\"}","expressionType":"cron","expression":"0 30 06 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"},{"name":"Christmas Tree Lights On","topic":"zigbee2mqtt/Smart Socket 07/set","payloadType":"json","payload":"{\"state\": \"on\"}","expressionType":"cron","expression":"0 30 16 * * * *","location":"51.164570 -0.1152285","offset":"0","solarType":"selected","solarEvents":"sunset"},{"name":"Christmas Tree Lights Off","topic":"zigbee2mqtt/Smart Socket 07/set","payloadType":"json","payload":"{\"state\": \"off\"}","expressionType":"cron","expression":"0 30 22 * * * *","location":"","offset":"0","solarType":"all","solarEvents":"sunrise,sunset"}],"x":190,"y":2480,"wires":[["38bfb3e47b0a30e7","478c1b5fa1192521"],[]]},{"id":"ee05e0d9.9118e","type":"mqtt-broker","name":"MQTT","broker":"192.168.1.21","port":"1883","clientid":"","autoConnect":true,"usetls":false,"compatmode":false,"protocolVersion":"4","keepalive":"60","cleansession":true,"birthTopic":"","birthQos":"0","birthPayload":"","birthMsg":{},"closeTopic":"","closeQos":"0","closePayload":"","closeMsg":{},"willTopic":"","willQos":"0","willPayload":"","willMsg":{},"userProps":"","sessionExpiry":""}]

The other wires are just from inject nodes

Buckskin · 1 January 2024 22:03

After further investigation

The log output

1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Socket 02] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Socket 02/get_status","payload":{"dps":1,"operation":"GET"},"qos":0,"retain":false,"_msgid":"6b594be730b3fc9c","_event":"node:35dd2a750f3dcc54"}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Socket 01] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Socket 01/get_status","payload":{"dps":1,"operation":"GET"},"qos":0,"retain":false,"_msgid":"7a863539be14d470","_event":"node:bd92833b898a5fa1"}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 04] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 04/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"67b18165269ae9ba","_event":"node:ecf989e2658169ef"}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 03] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 03/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"0793141e44d0b90a","_event":"node:89facfcc9acb2d7f"}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 01] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 02/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"3aa85ed7ec658498","_event":"node:ab21a3ca71f4cf58"}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 02] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 01/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"ba0a0ef90c6023c9","_event":"node:04ff964ec1a301c5"}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 04] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":970,"23":550,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Socket 02] Data from device  [event:data]: {"devId":"6000521040f520e55ff8","dps":{"1":true,"9":0,"18":1400,"19":2203,"20":2317,"21":1,"22":731,"23":29823,"24":20489,"25":1015}}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:data]: {"devId":"6000521040f520dee7f7","dps":{"1":true,"9":0,"18":43,"19":46,"20":2366,"21":1,"22":726,"23":30333,"24":20639,"25":1010}}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 02] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":1000,"23":1000,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 01] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":890,"23":500,"24":"00f003e80302","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 20:59:45 - [info] [tuya-smart-device:Smart Bulb 03] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":1000,"23":0,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 20:59:46 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":42,"19":42},"t":1704142785}
1 Jan 20:59:51 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"19":48},"t":1704142790}
1 Jan 20:59:52 - [info] [tuya-smart-device:Smart Socket 02] Data from device  [event:dp-refresh]: {"devId":"6000521040f520e55ff8","dps":{"18":1582,"19":2126,"20":2351},"t":1704142792}
1 Jan 20:59:54 - [info] [tuya-smart-device:Smart Socket 02] Data from device  [event:dp-refresh]: {"devId":"6000521040f520e55ff8","dps":{"18":1419,"19":2358},"t":1704142794}
1 Jan 20:59:56 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":41,"19":44,"20":2345},"t":1704142796}
1 Jan 21:00:00 - [info] [debug:CRON Schedules]
{
  cronplus: {
    triggerTimestamp: 1704142800000,
    status: {
      type: 'static',
      modified: false,
      isRunning: true,
      count: 1,
      limit: 0,
      nextDescription: 'in 23 hours 59 minutes 59 seconds',
      nextDate: 2024-01-02T21:00:00.000Z,
      nextDateTZ: '02 Jan 2024, 21:00:00 GMT',
      timeZone: 'Europe/London',
      serverTime: 2024-01-01T21:00:00.029Z,
      serverTimeZone: 'Europe/London',
      description: 'At 21:00'
    },
    config: {
      topic: 'schedule/temperature/bedroom',
      name: 'TRV Bedroom Schedule 04',
      index: 5,
      payloadType: 'num',
      payload: '19',
      limit: null,
      expressionType: 'cron',
      expression: '0 0 21 * * * *'
    }
  },
  topic: 'schedule/temperature/bedroom',
  scheduledEvent: true,
  payload: 19,
  _msgid: '74a704e68662f7c3'
}
1 Jan 21:00:01 - [info] [tuya-smart-device:Smart Socket 02] Data from device  [event:dp-refresh]: {"devId":"6000521040f520e55ff8","dps":{"18":1406,"19":2219,"20":2323},"t":1704142801}
1 Jan 21:00:07 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":40,"19":47,"20":2355},"t":1704142807}
1 Jan 21:00:09 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":41,"19":44},"t":1704142809}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Socket 02] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Socket 02/get_status","payload":{"dps":1,"operation":"GET"},"qos":0,"retain":false,"_msgid":"2a2cf33965030858","_event":"node:35dd2a750f3dcc54"}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Socket 01] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Socket 01/get_status","payload":{"dps":1,"operation":"GET"},"qos":0,"retain":false,"_msgid":"9d8e7a1c89c38498","_event":"node:bd92833b898a5fa1"}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Socket 02] Data from device  [event:data]: {"devId":"6000521040f520e55ff8","dps":{"1":true,"9":0,"18":1406,"19":2219,"20":2323,"21":1,"22":731,"23":29823,"24":20489,"25":1015}}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:data]: {"devId":"6000521040f520dee7f7","dps":{"1":true,"9":0,"18":41,"19":44,"20":2355,"21":1,"22":726,"23":30333,"24":20639,"25":1010}}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 04] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 04/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"d981456f1f91555a","_event":"node:ecf989e2658169ef"}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 03] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 03/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"e37c8cd3edabca25","_event":"node:89facfcc9acb2d7f"}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 01] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 02/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"563316eff628c29c","_event":"node:ab21a3ca71f4cf58"}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 02] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 01/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"6c4dc243daa27a8f","_event":"node:04ff964ec1a301c5"}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 04] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":970,"23":550,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 02] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":1000,"23":1000,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 01] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":890,"23":500,"24":"00f003e80302","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:15 - [info] [tuya-smart-device:Smart Bulb 03] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":1000,"23":0,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:18 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":43,"19":47,"20":2366},"t":1704142818}
1 Jan 21:00:27 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":39,"19":43,"20":2355},"t":1704142827}
1 Jan 21:00:29 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":42,"19":46},"t":1704142829}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Socket 02] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Socket 02/get_status","payload":{"dps":1,"operation":"GET"},"qos":0,"retain":false,"_msgid":"d602125a64f1dd7f","_event":"node:35dd2a750f3dcc54"}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Socket 01] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Socket 01/get_status","payload":{"dps":1,"operation":"GET"},"qos":0,"retain":false,"_msgid":"a38a5f2dd9604f3c","_event":"node:bd92833b898a5fa1"}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Socket 02] Data from device  [event:data]: {"devId":"6000521040f520e55ff8","dps":{"1":true,"9":0,"18":1406,"19":2219,"20":2323,"21":1,"22":731,"23":29823,"24":20489,"25":1015}}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 04] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 04/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"9a01ced4015f86ba","_event":"node:ecf989e2658169ef"}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 04] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":970,"23":550,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 03] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 03/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"8808846f39f2033a","_event":"node:89facfcc9acb2d7f"}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 01] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 02/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"a40e130d3180796f","_event":"node:ab21a3ca71f4cf58"}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 02] Recieved input : {"topic":"tuya2mqtt/device_status/Smart Bulb 01/get_status","payload":{"dps":20,"operation":"GET"},"qos":0,"retain":false,"_msgid":"76a53dc55530dd88","_event":"node:04ff964ec1a301c5"}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 02] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":1000,"23":1000,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 03] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":1000,"23":0,"24":"000003e803e8","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Bulb 01] Data from device  [event:data]: {"dps":{"20":false,"21":"white","22":890,"23":500,"24":"00f003e80302","25":"000e0d0000000000000000c80000","26":0}}
1 Jan 21:00:45 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:data]: {"devId":"6000521040f520dee7f7","dps":{"1":true,"9":0,"18":42,"19":46,"20":2355,"21":1,"22":726,"23":30333,"24":20639,"25":1010}}
1 Jan 21:00:54 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"19":42,"20":2338},"t":1704142854}
1 Jan 21:00:56 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":43,"19":46},"t":1704142856}
1 Jan 21:01:10 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":40,"19":50,"20":2355},"t":1704142870}
1 Jan 21:01:12 - [info] [tuya-smart-device:Smart Socket 01] Data from device  [event:dp-refresh]: {"devId":"6000521040f520dee7f7","dps":{"18":42,"19":46},"t":1704142872}

The debug output

As you can see the log shows the bedroom schedule occurring at the correct time (21:00) but there is no sign of the dining room schedule due at the same time. The debug output shows BOTH scheduled outputs 34 minutes later

UnborN · 1 January 2024 22:33

I looked at the flow you shared and i dont see another schedule set for 21:00 except the one that executed.
There's one for 9:00 though (schedule/temperature/dining room) but that is in the morning

I think the Debug window shows the time of the computer that you are browsing the Editor from and not the time of the node-red server. Can you check the times between the two if they are off ?

Buckskin · 1 January 2024 23:23

You are quite right, the dining room is 20:00 ( I assumed because of the debug time, but you know what that does)

I have checked the times, and they are both exactly the same. I should also point out that ;
a. This disparity in the debug and log output does not always happen
b. The actual output happens at the correct time (I checked the 20:00 dining room scheduled output and in the log it happened at - 20:00)

So the question is, if the browser is not running does debug store its messages until it is?

UnborN · 1 January 2024 23:47

maybe now they are .. but you mentioned in your first post that node-red is running on a PI.
From what i know the Raspberry PI doesnt have an RTC (real time clock) and relies on keeping its time in sync through NTP (Network Time Protocol) ? so it needs an internet connection to sync.

Maybe the issue happens when you restart the pi and until it gets its correct time from NTP,
a schedule executes at the wrong time ? just throwing ideas for something to check.

Nope .. you only get msgs if you have the browser open.

Buckskin · 2 January 2024 00:06

Pi very rarely gets restarted, so not that - but good thinking

Yes, I thought that was the case but it still remains that I got a debug message an hour & a half after the event. I checked the logs and the Pi never restarted on its own either

Steve-Mcl · 2 January 2024 09:51

So is it safe to say:

Cron-plus IS triggering at the correct time on the PI
1. the PI console logs at the correct time.
Sometimes you see debug message IN THE BROWSER late?

Can I also assume when this happens you have the node-red editor page open (somewhere) and

the browser in focus & tab is active?
the browser in is not in focus or the tab is inactive?
does the computer with the browser go into sleep mode?

TotallyInformation · 2 January 2024 10:37

Or the browser tab itself.

Steve-Mcl · 2 January 2024 10:41

I think you are referring to a tab itself going into sleep mode (which is where I am leading this thread without being too loaded up front)

to clarify the point: tabs can go into sleep mode.

TotallyInformation · 2 January 2024 10:53

Sorry, I meant to say that both the browser tab AND the OS can go to sleep such that no activity will be seen until they wake up.

Buckskin · 3 January 2024 01:20

Part 1: 1 & 2 - correct
Part 2: Browser not always in focus but tab is open, again not necessarily in focus
The OS doesn't go to sleep but the tab sometimes does.

I have just selected the tab and have received a load of cronplus messages from 20:00 to 00:30, the time is currently 01:07.

The browser is Edge in Windows 11 with Node-RED running on a Pi with Bookworm (not that I think that makes any difference). There was no message indicating that the tab was asleep, but as I noted, as soon as I clicked on the tab I got a lot of debug messages (all CRON schedules since this is the only active debug node) This would seem to indicate that somewhere debug messages are being stored and only get a timestamp when released.

UnborN · 3 January 2024 16:27

In Edge Settings / System and performance there are some options to disable the sleeping tabs
or Add Node-red site in the list to Never put these sites to sleep

dceejay · 3 January 2024 17:36

I think the net is that the actual cron event is happening at the correct time. The debug sidebar is showing incorrect timestamp as that is added at display time and the events are being queued somewhere as the browser tab is asleep.

Buckskin · 3 January 2024 18:51

Thanks Andy, the tab going to sleep is not really a problem, nor is the fact that sometimes debug is showing the cronplus output some time after the event.

Because of the questions asked I have confidence that the ACTUAL cronplus output is occurring when it should.

@dceejay that is my take on the issue, not really a problem, just an interesting happening that would be good to get an answer for.

Topic		Replies	Views
Cronplus Sunset General	62	465	6 January 2024
Timerswitch triggering at wrong time, timezone offset? General	4	1482	1 March 2020
Cronplus help Not using local time General	8	315	30 March 2021
Time Triggered Inject Ussie General	5	316	17 October 2021
Using the time in node red General	21	11990	7 April 2021

Strange Time Difference in CRON Plus Node Trigger Time & Output

Related Topics