Incorrect status reported on deployment

[drmibell]

When the node is first deployed, the status shown in the editor under the node is correct, but that caught by the status node is not. You can see this in the flow posted in the NR Forum at Show Schedex Time on Dashboard. It's not clear how the status caught by the status node could be different from the one shown in the editor, but that seems to be happening.

[biddster]

Thanks for the report, I'll look into it.

[biddster]

What version of schedex are you using @drmibell ?

[drmibell]

Good question. I believe it was v1.5.1 when I noticed this. I haven't checked with the current version.

[drmibell]

I just checked, and I see the same behavior with v1.6.2.

[biddster]

Hi @drmibell. I've put a log statement in whenever we set the status so you can see the behaviour when starting and re-deploying:

17 Jun 20:32:29 - [info] Server now running at http://127.0.0.1:1880/
17 Jun 20:32:29 - [info] Starting flows
17 Jun 20:32:29 - [info] [schedex:thisisaname] setting status: ON 2019-06-17 21:21 OFF 2019-06-18 20:29
17 Jun 20:32:29 - [info] Started flows
17 Jun 20:32:37 - [info] Stopping flows
17 Jun 20:32:37 - [info] [schedex:thisisaname] setting status: Scheduling suspended - manual mode only
17 Jun 20:32:37 - [info] Stopped flows
17 Jun 20:32:37 - [info] Starting flows
17 Jun 20:32:37 - [info] [schedex:thisisaname] setting status: ON 2019-06-17 21:21 OFF 2019-06-18 20:29
17 Jun 20:32:37 - [info] Started flows

As you can see it's called once on NR start. It's then called when stopping. I wonder if it's the stopping message that's confusing things?

[drmibell]

I think you are on to something. HOWEVER, why send status when stopping and why that particular message? More important, in the flow I posted,

[{"id":"a1743981.9668a","type":"status","z":"2190ec65.0a5c6c","name":"","scope":["167e4a09.e16596"],"x":460,"y":240,"wires":[["340245c2.df088a","ab8afb68.12d9a"]]},{"id":"167e4a09.e16596","type":"schedex","z":"2190ec65.0a5c6c","name":"","suspended":false,"lat":"","lon":"","ontime":"07:28","ontopic":"","onpayload":"on","onoffset":0,"onrandomoffset":0,"offtime":"goldenHour","offtopic":"","offpayload":"off","offoffset":0,"offrandomoffset":0,"mon":true,"tue":true,"wed":true,"thu":true,"fri":true,"sat":true,"sun":true,"x":480,"y":180,"wires":[["f580fb61.db8dc8"]]},{"id":"340245c2.df088a","type":"ui_text","z":"2190ec65.0a5c6c","group":"409c9c1e.fbbbe4","order":0,"width":0,"height":0,"name":"","label":"Status","format":"{{status.text}}","layout":"row-spread","x":610,"y":240,"wires":[]},{"id":"7fdd6dbb.39066c","type":"inject","z":"2190ec65.0a5c6c","name":"","topic":"","payload":"info","payloadType":"str","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":290,"y":180,"wires":[["167e4a09.e16596"]]},{"id":"fc9c6bcc.2d71e8","type":"inject","z":"2190ec65.0a5c6c","name":"","topic":"","payload":"on","payloadType":"str","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":290,"y":220,"wires":[["167e4a09.e16596"]]},{"id":"ab8afb68.12d9a","type":"debug","z":"2190ec65.0a5c6c","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","x":610,"y":280,"wires":[]},{"id":"9245161.12389e8","type":"inject","z":"2190ec65.0a5c6c","name":"","topic":"","payload":"off","payloadType":"str","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":290,"y":260,"wires":[["167e4a09.e16596"]]},{"id":"b2fc1a5c.db82e8","type":"inject","z":"2190ec65.0a5c6c","name":"","topic":"","payload":"toggle","payloadType":"str","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":290,"y":300,"wires":[["167e4a09.e16596"]]},{"id":"f580fb61.db8dc8","type":"debug","z":"2190ec65.0a5c6c","name":"","active":true,"tosidebar":true,"console":false,"tostatus":false,"complete":"true","x":670,"y":180,"wires":[]},{"id":"32c2d5e4.803ee2","type":"inject","z":"2190ec65.0a5c6c","name":"","topic":"","payload":"","payloadType":"date","repeat":"","crontab":"","once":false,"onceDelay":0.1,"x":120,"y":140,"wires":[["8590a270.9af608"]]},{"id":"8590a270.9af608","type":"change","z":"2190ec65.0a5c6c","name":"set ontime","rules":[{"t":"set","p":"payload","pt":"msg","to":"{\"ontime\":\"sunrise\"}","tot":"json"}],"action":"","property":"","from":"","to":"","reg":false,"x":270,"y":140,"wires":[["167e4a09.e16596"]]},{"id":"409c9c1e.fbbbe4","type":"ui_group","z":"","name":"Timer","tab":"32fae57a.692b52","disp":true,"width":"6","collapse":false},{"id":"32fae57a.692b52","type":"ui_tab","z":"","name":"Home","icon":"dashboard","disabled":false,"hidden":false}]

the status node does not seem to catch the status sent when starting the flows, only the (confusing) one sent when stopping.

[biddster]

Schedex cleans up when the node is stopped. The cleanup code is the suspend code, it's the same thing. I've tweaked it here so it doesn't send the message on shutdown but the problem with the status node remains.

I'll be honest, I'd never used the status node until now. Wonder if there's a status length constraint?

[biddster]

Nope - no restrictions. Looks like it's a deployment order issue. I think when schedex is deployed and immediately updates the status, the status node isn't deployed, so it can't handle the status change.

Things work as intended if I delay the status update in schedex by a second. That's a hack of course, I'm not sure what the actual solution is just yet.

[drmibell]

Your hack may be the only answer, at least for now. I've looked at a couple of other nodes that display status when first deployed, and the status node does not catch the initial status for any of them. I haven't found your hacked code on GitHub, but I assume your callback (setTimeout?) gives the flow enough time to deploy fully before the status update event occurs. Since the status node connects only to nodes on the same tab, there is no obvious way to control the deployment order. I'll try a few more experiments and probably post something on the forum to see whether the developers can take a look at this.

[biddster]

I've not pushed the code @drmibell.

It does sound like one for the NR devs.