Issue with test switch from Ezlo bridge

If the logs are rotating too quickly, you can increase the number of lines per file with a single line in the Lua Startup:

luup.attr_set ("openLuup.Logfile.Lines", 20000)

Test done log sent device is 20021, just as it is easier to trigger. To clarify test switch and test dimmer both causing issues

Hi @ElCid,

So if I understand your setup,

  1. you created virtual devices on your Ezlo using their test_plugin? Dimmers, switched etc.
  2. you installed the EzloBridge on openLuup and created virtual devices mimicking the Ezlo virtual devices
  3. created reactor sensors to use the virtual devices as triggers?

So i would first check that if you operate the virtual devices on the Ezlo, the status on openLuup changes accordingly. Then only base your Reactor triggers on those variables.

Note that the Ezlo virtual devices are not behaving as real devices do, so not all variables changed on an action on a zwave device may change on a virtual one. I noticed several items missing on the virtual devices of the Ezlo plugin.

Cheers Rene

Hi Rene

The devices on both ALTUI and Ezlo plus UI update each other when switched on/ off from either device.

The virtual dimmer does not update Status but does loadLevelStatus.
The virtual switch does update Status. Cheers

Just for info.
The icon issues has been fixed, for some reason the png files where all 0 bytes. I re fetched the image icons and all is displayed correctly.

A real dimmer device does have an on/off status as well, but the virtual on Ezlo does not. This means that the virtual copy on openLuup will not have a Status variable or if it does that it will not be updated.

Please make sure this is not the source of your problems.

Cheers Rene

OK. So hereā€™s Reactor placing the watch on the Status variable for device 20021 at startup:

2020-12-23 08:31:06.102   luup_log:10: Reactor(evaluateCondition:3564): evaluateCondition("cond10gjkab7","grppyrz6h6",cdata,14)
2020-12-23 08:31:06.105   luup_log:10: Reactor(evaluateCondition:3571): evaluateCondition() condstate { evaledge={ t=1608710981(2020-12-23.08:09:41), f=1608711684(2020-12-23.08:21:24) }, stateedge={ t=1608711064(2020-12-23.08:11:04), f=1608711083(2020-12-23.08:11:23) }, id="cond10gjkab7", evalstamp=1608711684(2020-12-23.08:21:24), lastvalue="0", evalstate=false, priorvalue="1", valuestamp=1608711083(2020-12-23.08:11:23), matchcount=6, laststate=false, statestamp=1608711083(2020-12-23.08:11:23) }
2020-12-23 08:31:06.106   luup_log:10: Reactor(addServiceWatch:621): addServiceWatch() adding system watch for "20021/urn:upnp-org:serviceId:SwitchPower1/Status"
2020-12-23 08:31:06.107   luup.variable_watch:: callback=reactorWatch, watching=20021.urn:upnp-org:serviceId:SwitchPower1.Status
2020-12-23 08:31:06.108   luup_log:10: Reactor(addServiceWatch:626): addServiceWatch() subscribing "14" to "20021/urn:upnp-org:serviceId:SwitchPower1/Status"

And hereā€™s what happens when device 20021 is modified:

2020-12-23 08:31:29.599 luup.variable_set:: 20021.urn:upnp-org:serviceId:SwitchPower1.Status was: 0 now: 1 #hooks:0
2020-12-23 08:31:29.602 luup.variable_set:: 20021.urn:upnp-org:serviceId:SwitchPower1.Target was: 0 now: 1 #hooks:0
2020-12-23 08:31:30.015 openLuup.server:: request completed (5340 bytes, 1 chunks, 11202 ms) tcp{client}: 0xfcee7e8
2020-12-23 08:31:30.018 openLuup.io.server:: HTTP:3480 connection closed openLuup.server.receive closed tcp{client}: 0xfcee7e8
2020-12-23 08:31:31.178 openLuup.io.server:: HTTP:3480 connection from 192.168.1.10 tcp{client}: 0xfe831c8
2020-12-23 08:31:31.181 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=712276147&Timeout=60&MinimumDelay=1500&_=1608712191044 HTTP/1.1 tcp{client}: 0xfe831c8
2020-12-23 08:31:32.700 luup.variable_set:: 20021.urn:upnp-org:serviceId:SwitchPower1.Status was: 1 now: 0 #hooks:0
2020-12-23 08:31:32.702 luup.variable_set:: 20021.urn:upnp-org:serviceId:SwitchPower1.Target was: 1 now: 0 #hooks:0
2020-12-23 08:31:32.812 openLuup.server:: request completed (5340 bytes, 1 chunks, 1627 ms) tcp{client}: 0xfe831c8
2020-12-23 08:31:33.981 openLuup.server:: GET /data_request?id=lu_status2&output_format=json&DataVersion=712276149&Timeout=60&MinimumDelay=1500&_=1608712191045 HTTP/1.1 tcp{client}: 0xfe831c8

@akbooer, notice it says #hooks: 0, even though Reactor made the call and openLuup appears to have confirmed the watch was put in place, and yet thereā€™s no callback logged from Reactor. Reactor has a generic debug log statement at the entry to its watch callback that logs the call and its parameters before it does any processing or filtering, and there are no log entries for the callback. Weā€™re not getting called.

I suspect thereā€™s an issue with the BinaryLight services at the time the watch is being put in place, and openLuup is taking that code path where the service isnā€™t defined on the device.

Of note: Reactor is device 10, and the eZLO Bridge is device 24, so Reactor is starting before the eZLO Bridge, and in the absence of ZWave to wait for, Reactor will start immediately (on Vera Luup, it holds on until the ZWave network reports ready). Could this be a race condition where the services havenā€™t initialized yet on the higher-numbered device(s)?

Note also @ElCid is now on openLuup 201219

I wouldnā€™t call it a race condition, but thatā€™s almost definitely what is happening. It rather depends on how the Ezlo bridge starts up, whether it perhaps delays its initialisation of child devicesā€¦

Devices are all created from the user_data.json file before the Lua Startup is run, and before the scheduler is started or device init() called. Depending on what luup.chdev.append() has to do with the child devices, it may also recreate device variables. Deleteing a variable would do the same thing, since all the variable numbering will change. Watches would be lost in the process.

Your great detective work makes this the smoking gun. A fix would be to delay startup of reactor until after others. Alternatively (thinking on my feet, or, rather, at my keyboard, as I write) ensuring that the Ezlo bridge runs earlier than Reactor.

This now rings very loud alarm bells in my head, since I now recall that this is exactly what the openLuup scheduler prioritisation is for. Take a look at the openLuup > Scheduler > startup page. Important devices have a priority set. This should include all bridges (Vera, ZWay, ā€¦) but does the Ezlo bridge have a priority??

A couple of things here.

First, I would ask that the code path issue in placing the watch be fixed. It doesnā€™t make sense to me that it would place a device watch if the service wasnā€™t given, or a service watch if the variable isnā€™t found, but it doesnā€™t place a device watch if the service isnā€™t found when the watch was called upon. If this worked, I think the startup timing wouldnā€™t matter, it would simply place a device watch instead of a variable watch, but Reactor filters for what it cares about anyway, so it makes no difference to Reactor that the watch is less specific.

With regard to startup timing, my fear is that we will never get it right because we have no idea if the eZLO device being bridged is even up and running and the eZLO plugin can initialize its children. It may have to wait a very long time, if the eZLO device isnā€™t available at the instant the bridge plugin is started. That timing is non-deterministic, so any delay put in Reactor or change in the order of initialization seems like a ā€œworks most of the timeā€ thing, and thatā€™s not something I really accept from Reactor, and I donā€™t think most users do either.

So I think attacking the timing isnā€™t as effective as tackling the boundary condition that is currently unhandled and being allowed to drop through.

I would agree.

Nevertheless, I have published an update to the development branch (v20.12.23) which includes a startup priority for the Ezlo bridge.

Please do try it, and see if this is a temporary band-aid.

If thatā€™s the case, than why not just watch any device of interest, rather than specific services/variables?

Hi AK,

The Ezlo bridge first needs to establish a connection with the Ezlo and pull the data before the chdev.create can be called. Just as the VeraBridge logic works. I recall Reactor was one of the reasons why VeraBridge devices got started first.

Just installed the development version and the EzloBridge is still started after reactor, i.e. based on the device number.

Cheers Rene

ā€¦better memory than I !!

Show me the openLuup > Scheduler > startup page. Is there a priority for your plugin (I may have got something wrong)?

No priority no.

And looking at openLuup github development branch i do not see an updated file?

My bad. Forgot to push the release. Itā€™s there now. Apologies.

No problem. Test VM does updates and restarts in seconds :slight_smile:

I see the priority is now set and the EzloBridge starts before others like VeraBridge. Top notch.

After recreating the conditions on Status and LoadLevelStatus in the reactor sensor it all works like a charm.

Cheers Rene

This is not a fix, guys. If the eZLO device canā€™t be contacted or is slow, the late initialization will cause the watches to fail and Reactor wonā€™t react without its watches.

That is no different than for the VeraBridge and so far it has not led to problems. And from experience, the Ezlo websocket interface is faster than polling a Vera using http.

The only effect is that these devices startup will delay the start up of other devices by a few seconds.

Cheers Rene

And what if the eZLO (or Vera) canā€™t be contacted at all?