Init handler caller repeatedly, added maybe not called

Developer Programs Writing Edge Drivers
1

I’m getting started with writing edge drivers, so I might be doing a few things wrong.

My workflow to test my code is (I’m interested if there are better ways!):

  • manually switch my device back to the default driver
  • uninstall my custom driver from my hub, package my latest code, publish it to my channel, install the driver to my hub
  • start logcat for my driver
  • manually switch my device to my custom driver

When I do this, the init lifecycle is called repeatedly every 6s from the lost. That sounded unexpected.

Here’s a snippet of the repeated logs I see:

TRACE Gui-s Z-Wave Lock  Setup driver zwave_lock with lifecycle handlers: [...]
TRACE Gui-s Z-Wave Lock  Setup driver zwave_lock with Capability handlers: [...]
TRACE Gui-s Z-Wave Lock  Setup driver zwave_lock with Z-Wave handlers: [...]
TRACE Gui-s Z-Wave Lock  Z-Wave Device: [...]
TRACE Gui-s Z-Wave Lock  Received event with handler _resync
TRACE Gui-s Z-Wave Lock  Received event with handler environment_info
DEBUG Gui-s Z-Wave Lock  Z-Wave hub node ID environment changed.
TRACE Gui-s Z-Wave Lock  Found DeviceLifecycleDispatcher handler in zwave_lock
PRINT Gui-s Z-Wave Lock  Init handler called
INFO Gui-s Z-Wave Lock  <ZwaveDevice: [...] [07] (Yale Door Lock)> emitting event: [...]

The last two lines being triggered by code I wrote.

I could not tell whether the debug statement Z-Wave hub node ID environment changed. was something unusual.

Additionally, I never see the print statement I’ve put in the added or driverSwitched lifecycle handler, but I sometimes - not always - see logs such as

INFO Gui-s Z-Wave Lock  <ZwaveDevice: [...] [07] (Yale Door Lock)> received lifecycle event: added

so I could not tell what was happening for those.

2

Apparently (from bisecting my changes) I had

print(json.encode(device))

in a function called in all those handlers and this caused the above behavior. Maybe this is causing issues, but I was not seeing any logs pointing to a related error.

3

Hi @gsabran

The Flows of life cycles have been changing in these 2 years.
At the moment,
The driver execution lifecycles flows are different depending on:

  • If you install the driver and then pair the device:

    • init, added, doConfigure, some times infoChanged

  • if you install the driver and then add the first device with driver change:

    • init, added, driverSwitched

  • in your installed driver then you add the second or following devices with driver change:

    • added, driverSwitched, init

  • If you install a new version of the driver overwritten the old one, with CLI or automatic:

    • init

It is necessary to test all these flows in a new driver, even doing a reboot of the hub to see how the capabilities and all variables are initialized.

The normal flow when I am already debugging is to install the new version with the CLI on top of the previous version with the device already installed.

2 Likes
4

I don’t see init before added in my LAN drivers. IF I see added it is always before init. However, I frequently see devices that never have added called. This is easy to replicate if creating numerous devices quickly. I’m fairly sure I can also cause init to not be called as well if creating devices rapidly.

5

Hi,

In the logs, the message “lifecycle: init has been received” is often not seen, but it is executed.

I have also seen that sometimes the added cycle is shown in the log first and then the init cycle and other times the other way around or duplicates in some log of a user of a CO sensor.

The infoChange is executed many times before starting to install the new version and other times it is not executed.
I can say that at this moment what I know is that I know nothing!

I also think that the order in which the logs are displayed in the CLI does not always correspond to the actual order in which it is happening. I think I read something about this quite a while ago, said by a team member, but I can’t find it.

I usually put a print in the custom code of the lifecycle functions to see if they are executed and the possible real order.

On these topics, every time I ask why I detect something strange or that has changed, with rare exceptions, silence is the answer.
You may have better luck if you ask.

I can’t find an explanation for this, added and init life cycles duplicates and an unusual order: added, init, after doConfigure.

My only possible explanation is that the order shown in the log is not real.

2023-10-09T17:59:16.354547486+00:00 TRACE Zigbee Smoke/CO Detector Mc Received event with handler device_lifecycle
2023-10-09T17:59:16.387922153+00:00 TRACE Zigbee Smoke/CO Detector Mc Zigbee Device: 16da7b77-07e9-4a71-b145-687cc3db1063
Manufacturer: Trust Model: COSensor-EM
[1]: server: Basic, PowerConfiguration, Identify, IASZone | client: OTAUpgrade
2023-10-09T17:59:16.388810153+00:00 INFO Zigbee Smoke/CO Detector Mc <ZigbeeDevice: 16da7b77-07e9-4a71-b145-687cc3db1063 [0x19C9] (Trust CO Detector)> received lifecycle event: added
2023-10-09T17:59:16.390520153+00:00 TRACE Zigbee Smoke/CO Detector Mc Received event with handler device_lifecycle
2023-10-09T17:59:16.391721819+00:00 INFO Zigbee Smoke/CO Detector Mc <ZigbeeDevice: 16da7b77-07e9-4a71-b145-687cc3db1063 [0x19C9] (Trust CO Detector)> received lifecycle event: doConfigure
2023-10-09T17:59:16.395833153+00:00 TRACE Zigbee Smoke/CO Detector Mc <ZigbeeDevice: 16da7b77-07e9-4a71-b145-687cc3db1063 [0x19C9] (Trust CO Detector)> received unhandled lifecycle event: added
2023-10-09T17:59:16.399208153+00:00 DEBUG Zigbee Smoke/CO Detector Mc Trust CO Detector device thread event handled
2023-10-09T17:59:16.420207819+00:00 TRACE Zigbee Smoke/CO Detector Mc <ZigbeeDevice: 16da7b77-07e9-4a71-b145-687cc3db1063 [0x19C9] (Trust CO Detector)> received unhandled lifecycle event: init
2023-10-09T17:59:16.423215819+00:00 DEBUG Zigbee Smoke/CO Detector Mc Trust CO Detector device thread event handled

6

Apart from a brief dabble with single device LAN drivers, my current interest is in Edge drivers that implement local VIRTUAL devices. I do remember reading that added was supposed to come first and the Edge reference documentation still clearly states that it will generate an init when it completes, but I have always found the order to be init then added on creating devices.

I note that the library mentions a ‘temporary workaround to prevent double initing until “added” message behavior is changed’, which is to use device_cache[device_uuid] as a test for a device already existing and to only queue up an init after an added if it is falsey.