First after OS boot Schedex-based action missing

Hi guys,

[
    {
        "id": "c7218fca.498b6",
        "type": "ui_switch",
        "z": "f1073339.c03c3",
        "name": "enable_light",
        "label": "Enable Auto Light",
        "group": "e1a7cd3b.e5b6",
        "order": 1,
        "width": "0",
        "height": "0",
        "passthru": true,
        "decouple": "false",
        "topic": "shm/garden/light/enable",
        "style": "",
        "onvalue": "on",
        "onvalueType": "str",
        "onicon": "",
        "oncolor": "",
        "offvalue": "off",
        "offvalueType": "str",
        "officon": "",
        "offcolor": "",
        "x": 130,
        "y": 1340,
        "wires": [
            [
                "630c0653.41c308",
                "476de067.4fafd"
            ]
        ]
    },
    {
        "id": "3ff722b7.33131e",
        "type": "ui_slider",
        "z": "f1073339.c03c3",
        "name": "light_timeout",
        "label": "Off in {{ value }} min",
        "group": "e1a7cd3b.e5b6",
        "order": 2,
        "width": "0",
        "height": "0",
        "passthru": true,
        "topic": "shm/garden/light/timeout",
        "min": 0,
        "max": "90",
        "step": 1,
        "x": 570,
        "y": 1520,
        "wires": [
            [
                "200ca520.4baf0a"
            ]
        ]
    },
    {
        "id": "eedce02c.25858",
        "type": "ui_switch",
        "z": "f1073339.c03c3",
        "name": "control_light",
        "label": "Garden Light",
        "group": "e1a7cd3b.e5b6",
        "order": 3,
        "width": "5",
        "height": "1",
        "passthru": false,
        "decouple": "true",
        "topic": "shm/garden/light/state",
        "style": "",
        "onvalue": "on",
        "onvalueType": "str",
        "onicon": "",
        "oncolor": "",
        "offvalue": "off",
        "offvalueType": "str",
        "officon": "",
        "offcolor": "",
        "x": 150,
        "y": 1420,
        "wires": [
            [
                "4165cf21.5b645"
            ]
        ]
    },
    {
        "id": "4165cf21.5b645",
        "type": "function",
        "z": "f1073339.c03c3",
        "name": "parse_timeout",
        "func": "// Outputs:\n// Counter_to_display, GPIO control via BigTimer, Counter_to_process\n\n// This beautiful expression doesn't work, gets default 10 always.\n// var delay = typeof(context.get('get_light_timeout') == undefined) ? 10 : flow.get('get_light_timeout');\n// This ugly construction works. :(\ntry{\n    var delay = flow.get('get_light_timeout');\n} catch (er) {\n    var delay = 10;\n}\n\nvar state = context.get('state') || 'ignore';\nvar topic = context.get('topic') || msg.topic;\ncontext.set('topic', topic);\ntopic = context.get('topic');\nnode.status({fill:\"yellow\",shape:\"ring\",text: delay+','+state+','+msg.payload});\n\n// Block loop of messages when off\nif ('off' == msg.payload && 'off' == state) return [null, null, null];\nnode.status({fill:\"yellow\",shape:\"dot\",text: delay+','+state+','+msg.payload});\n\n// Keep msg for next round\nif ('on' == msg.payload) {\n    // Don't count/display if fully manual\n    var m1 = (delay > 0) ? {payload: delay} : null; \n    // Set delay, start countdown, on load\n    context.set('state', 'on');\n    node.status({fill:\"green\", shape:\"dot\", text: delay+','+context.get('state')+','+msg.payload});\n    return [m1, msg, m1];  \n} else if (('off' == msg.payload) || (parseInt(msg.payload) <= 1)) {\n    // off load, reset clear counter\n    context.set('state', 'off');\n    node.status({fill:\"red\",shape:\"dot\",text: delay+','+context.get('state')+','+msg.payload});\n    return [{payload: ' '}, {payload: 'off', topic: topic}, null];\n} else if (parseInt(msg.payload) > 1 && context.get('state') == 'on') {\n    // decrement countdown\n    var m1 = {payload: parseInt(msg.payload)-1};\n    node.status({fill:\"blue\",shape:\"dot\",text: delay+'>'+m1.payload+','+state+','+msg.payload});\n    return [m1, null, m1];\n}\n\n// Unexpected state: look for a bug in reached here.\nnode.status({fill:\"grey\",shape:\"ring\",text: delay+','+state+','+msg.payload+'???'});\nreturn [{payload: ' '}, {payload: 'off', topic: topic}, null];\n",
        "outputs": 3,
        "noerr": 0,
        "x": 160,
        "y": 1480,
        "wires": [
            [
                "5bc20faa.e668c"
            ],
            [
                "eedce02c.25858",
                "ebf3172b.b5b078"
            ],
            [
                "e7b597e2.91cc38"
            ]
        ]
    },
    {
        "id": "200ca520.4baf0a",
        "type": "function",
        "z": "f1073339.c03c3",
        "name": "UI_to_flow_context",
        "func": "flow.set(\"get_light_timeout\", msg.payload);\nreturn null;",
        "outputs": 1,
        "noerr": 0,
        "x": 770,
        "y": 1520,
        "wires": [
            []
        ]
    },
    {
        "id": "7fdf963d.edb9d8",
        "type": "inject",
        "z": "f1073339.c03c3",
        "name": "",
        "topic": "",
        "payload": "10",
        "payloadType": "num",
        "repeat": "",
        "crontab": "",
        "once": true,
        "onceDelay": 0.1,
        "x": 410,
        "y": 1520,
        "wires": [
            [
                "3ff722b7.33131e"
            ]
        ]
    },
    {
        "id": "6956ca6d.a256a4",
        "type": "debug",
        "z": "f1073339.c03c3",
        "name": "light_M",
        "active": true,
        "tosidebar": true,
        "console": true,
        "tostatus": false,
        "complete": "payload",
        "x": 940,
        "y": 1360,
        "wires": []
    },
    {
        "id": "e7b597e2.91cc38",
        "type": "trigger",
        "z": "f1073339.c03c3",
        "op1": "",
        "op2": "",
        "op1type": "nul",
        "op2type": "pay",
        "duration": "1",
        "extend": false,
        "units": "min",
        "reset": "",
        "bytopic": "all",
        "name": "",
        "x": 210,
        "y": 1540,
        "wires": [
            [
                "4165cf21.5b645"
            ]
        ]
    },
    {
        "id": "5bc20faa.e668c",
        "type": "ui_text",
        "z": "f1073339.c03c3",
        "group": "e1a7cd3b.e5b6",
        "order": 0,
        "width": "1",
        "height": "1",
        "name": "counter",
        "label": "",
        "format": "{{msg.payload}}",
        "layout": "row-right",
        "x": 420,
        "y": 1460,
        "wires": []
    },
    {
        "id": "119c4b5c.c57e25",
        "type": "comment",
        "z": "f1073339.c03c3",
        "name": "About timer",
        "info": "BigTimer is a main programmable module.\nAll overrides/manuals come thru it.\n\nAdd control from MQTT or other sensor or other function to the input of the BigTimer.\n\nThe actual status is shown by switch.",
        "x": 730,
        "y": 1280,
        "wires": []
    },
    {
        "id": "630c0653.41c308",
        "type": "change",
        "z": "f1073339.c03c3",
        "name": "switch2timer",
        "rules": [
            {
                "t": "change",
                "p": "payload",
                "pt": "msg",
                "from": "off",
                "fromt": "str",
                "to": "suspended true",
                "tot": "str"
            },
            {
                "t": "change",
                "p": "payload",
                "pt": "msg",
                "from": "on",
                "fromt": "str",
                "to": "suspended false",
                "tot": "str"
            }
        ],
        "action": "",
        "property": "",
        "from": "",
        "to": "",
        "reg": false,
        "x": 190,
        "y": 1380,
        "wires": [
            [
                "ebf3172b.b5b078"
            ]
        ]
    },
    {
        "id": "516cc848.a80b68",
        "type": "exec",
        "z": "f1073339.c03c3",
        "command": "actuators/valve.py -i 4 ",
        "addpay": true,
        "append": "",
        "useSpawn": "false",
        "timer": "",
        "oldrc": false,
        "name": "",
        "x": 720,
        "y": 1360,
        "wires": [
            [
                "6956ca6d.a256a4"
            ],
            [],
            []
        ]
    },
    {
        "id": "16bfb120.90989f",
        "type": "function",
        "z": "f1073339.c03c3",
        "name": "msg2digit",
        "func": "var old = msg.payload;\nnode.status({text: old + '???'});\nif (msg.payload == null) return;\n\nif (msg.payload === true || \n    msg.payload.toLowerCase() == 'open' || \n    msg.payload.toLowerCase() == 'on' ||\n    parseInt(msg.payload) > 0) { msg.payload = 1 }\n    else if (msg.payload === false || \n        msg.payload.toLowerCase() == 'close' || \n        msg.payload.toLowerCase() == 'off' ||\n        parseInt(msg.payload) <= 0) { msg.payload = 0 }\n        else return;\n\nnode.status({text: old + \">>\" + msg.payload});\n\ntry{\n    // Get 2nd word from the end of topic\n    msg.topic = msg.topic.split('/').slice(-2)[0];\n} catch (er) {\n    node.status({text: 'Topic error'});\n    return null;\n}\nnode.status({text: '>>' + old + \",\" + msg.payload});\n\nreturn msg;",
        "outputs": 1,
        "noerr": 0,
        "x": 660,
        "y": 1480,
        "wires": [
            [
                "4c103f26.12e0e"
            ]
        ]
    },
    {
        "id": "4c103f26.12e0e",
        "type": "ui_chart",
        "z": "f1073339.c03c3",
        "name": "",
        "group": "e1a7cd3b.e5b6",
        "order": 0,
        "width": "6",
        "height": "2",
        "label": "Light Log",
        "chartType": "line",
        "legend": "false",
        "xformat": "dd HH:mm",
        "interpolate": "step",
        "nodata": "No data",
        "dot": false,
        "ymin": "0",
        "ymax": "1",
        "removeOlder": 1,
        "removeOlderPoints": "",
        "removeOlderUnit": "604800",
        "cutout": 0,
        "useOneColor": false,
        "colors": [
            "#1f77b4",
            "#aec7e8",
            "#ff7f0e",
            "#2ca02c",
            "#98df8a",
            "#d62728",
            "#ff9896",
            "#9467bd",
            "#c5b0d5"
        ],
        "useOldStyle": false,
        "outputs": 2,
        "x": 820,
        "y": 1480,
        "wires": [
            [
                "8c3defad.985bb"
            ],
            []
        ]
    },
    {
        "id": "8c3defad.985bb",
        "type": "persist in",
        "z": "f1073339.c03c3",
        "name": "light",
        "storageNode": "fb72a845.8c35f8",
        "x": 910,
        "y": 1441,
        "wires": []
    },
    {
        "id": "f21e1664.752f98",
        "type": "persist out",
        "z": "f1073339.c03c3",
        "name": "light",
        "storageNode": "fb72a845.8c35f8",
        "x": 730,
        "y": 1440,
        "wires": [
            [
                "4c103f26.12e0e"
            ]
        ]
    },
    {
        "id": "ebf3172b.b5b078",
        "type": "schedex",
        "z": "f1073339.c03c3",
        "name": "GardenLight",
        "suspended": false,
        "lat": "32",
        "lon": "34",
        "ontime": "dusk",
        "ontopic": "shm/garden/light/state",
        "onpayload": "on",
        "onoffset": "-15",
        "onrandomoffset": 0,
        "offtime": "22:45",
        "offtopic": "shm/garden/light/state",
        "offpayload": "off",
        "offoffset": "30",
        "offrandomoffset": true,
        "mon": true,
        "tue": true,
        "wed": true,
        "thu": true,
        "fri": true,
        "sat": true,
        "sun": true,
        "x": 370,
        "y": 1380,
        "wires": [
            [
                "eedce02c.25858",
                "516cc848.a80b68"
            ]
        ]
    },
    {
        "id": "476de067.4fafd",
        "type": "persist in",
        "z": "f1073339.c03c3",
        "name": "light_enable",
        "storageNode": "f595d218.30e59",
        "x": 310,
        "y": 1300,
        "wires": []
    },
    {
        "id": "397835ad.07002a",
        "type": "persist out",
        "z": "f1073339.c03c3",
        "name": "light_enable",
        "storageNode": "f595d218.30e59",
        "x": 110,
        "y": 1300,
        "wires": [
            [
                "c7218fca.498b6"
            ]
        ]
    },
    {
        "id": "e1a7cd3b.e5b6",
        "type": "ui_group",
        "z": "",
        "name": "Garden: Light",
        "tab": "fd92601d.1a632",
        "order": 1,
        "disp": true,
        "width": "6",
        "collapse": false
    },
    {
        "id": "fb72a845.8c35f8",
        "type": "persist-store",
        "z": "",
        "filename": "garden_light.json",
        "interval": "3600"
    },
    {
        "id": "f595d218.30e59",
        "type": "persist-store",
        "z": "",
        "filename": "light_enable.json",
        "interval": "3600"
    },
    {
        "id": "fd92601d.1a632",
        "type": "ui_tab",
        "z": "",
        "name": "Garden",
        "icon": "local_florist",
        "order": 2
    }
]

I use several instances of Schedex in my home automation with NR over Raspi 3B+ Jessie. The flow example is above. Similar flows work for watering and lighting jobs. For some reason, after OS boot the Schedex reports the correct next action (waved with blue), but the first-after-OS-boot action doesn't work. Second and further actions work like a charm.

As workarounds I used to use one of following:

  • WA1: Just wait until next action. This is from several hours to few days, depends on programmed schedule.
  • WA2: Manually node-red-stop --> node-red-start via SSH after the OS boot completed.

The problem initially was spotted about year and half ago. Fortunately, RasPI reboots don't happen often, so the pain is minor... and this took me a while to gather courage to share this problem with the community. All this time I could not correlate it with any reason. Not sure the correlation above is relevant. What do you think? What can be a root cause?

Recently, I noticed on other RasPIs, not running NR, but running my own software.
If my software loads before NTP is synced with the pool, then the synced time isn't taken into account, until next sync at night time.
The NTP sometimes lags to sync due to network imperfections: delay in DHCP or DNS response, interruptions/delay in WiFi link, etc.

Maybe the same reason causes Schedex to skip the first action?
Maybe Schedex is just a victim of NR provided time?
Is there a way to delay the NR start after OS boot? I want to give the NTP a chance to get synced time first and then start the NR.

Any idea is welcome.
Thank you.

The switch2timer change node sets it programmatically ?

Looking at the documentation of the node:

It is very important to note that properties set programmatically in this manner are transient. They will not persist over a NodeRED restart or redeploy!

For ntp, do you have the "wait for network" option set in raspi-config ?

Both switch2timer change node and parse_timeout function node pass programmatic commands to Schedex when needed. After boot the switch2timer change node enables the Schedex automatic mode (suspended false). Therefore, Schedex shows correct planned time of ON and OFF. Just the first action doesn't go for some reason...
Same happens after node-red-stop/start and it works OK. So maybe the difference in full power off/on.

I think it was disabled. I enabled it. Thanks for the hint.

UPDATE: Enabling "Wait for network" solved the problem of first action after boot.