openhabian running openHAB 3.2.0 Build #2469 on a Pi4 4GB with a 32GB SD Card
Ember EM35x Coordinator
I have about 50 Zigbee devices in my setup … on a reboot it takes 45-60 minutes for the network discovery to complete (meaning all devices have moved from the Unknown to Online state)
Is this consistent with others with a similar setup?
Probably what you are seeing is how long it takes for the devices to send updates so the binding knows they are alive. I thought it assumed they were ONLINE on startup rather than waiting for input, but maybe not.
That said, without a log I can’t be sure…
I’m pretty sure they are always Unknown until they say Online … the system is coming up now and I just tested a few sensors that are in the Unknown state and they dont respond to activity.
Not sure what level of logs would be useful. This is 100% repeatable so I can gather any logs you need.
This is the basic log (probably worthless 
) that shows the Unknown state transitioning.
2021-09-11 12:37:42.451 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f000597e5d5' changed from UNKNOWN to ONLINE
2021-09-11 12:37:49.624 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae5ee' changed from UNKNOWN to ONLINE
Yes, of course - when the system starts, the state is unknown until it is online - that’s correct.
This is perfectly normal and exactly the same for every binding. The OH core sets the state to unknown on startup. This is NOT the same as the thing being unknown and doesn’t infer discovery is required - it’s just the thing state that is unknown by OH.
Please take a look at the binding docs - there is a section there on logging (what to do when things don’t go as planned).
I think you misunderstood me Chris … I know how to enable various zigbee logs and can turn them all on and restart the system if that’s what you want. I thought you might want something more specific. I have 50 zigbee devices and it takes ~1 hour to get all the devices to ONLINE. Do you need just the log of one of the devices from restart to when it goes ONLINE?
This is happening with every restart so I’m assuming it is all normal, but if you think it should happen much faster than essentially 1 minute per device, then its definitely worth looking into since it’s totally repeatable.
If you want the entire log it’s no problem.
I want to see the logging from startup until the devices go online so I can see what is happening. Please don’t try and filter the logs to just one device - it makes it totally impossible to see what is happening. I don’t know if that one device is going slow, or if the system is slowed down by activity with other devices. I need to see the full picture if all devices are taking an hour to come online as there shouldn’t be much/any discovery taking place.
It might be as simple as the devices not being set to ONLINE until the first data is received from the device (which could take an hour). If so, I might change this so that the binding assumes the devices are online until it fails to respond. It also depends on the type of device what will happen so it’s not exactly simple unfortunately.
The reported Thing status is really in the “so what” category, except that this part sounds bad. You mean if you open a door or something, no report gets to openHAB?
How about if you send an active ON command to a light or something while parent Thing UNKNOWN?
Ok Chris, here are the openhab and event logs for the period from boot to last device. Ember bridge comes online at 13:46:48 and the last zigbee devices goes Online at 14:43:25
Here is a link to the openhab.log:
https://drive.google.com/file/d/1c2kysG09gD361V7Z8kFD_XSnvyr4-vp0/view?usp=sharing
events.log (174.1 KB)
Correct, for a door sensor, nothing was reported until the Thing goes Online … a light that was in Unknown state didn’t turn on right away, but did so a few moments later and then the Thing showed Online (not sure if it was just about to go Online anyway) … maybe the act of turning it On, woke it up and it reported?
anyway, just posted the logs.
So looking over the log, it seems most of the devices are online within a couple of minutes.
It does look like devices aren’t marked online until the binding receives something from them. I’m not really surprised about this - the ZWave binding was originally written in the same way, but I changed it a couple of years back to assume devices are online until the fail to report - after this they are marked offline, and then must send a report to come online. From the logs, I’m pretty sure this is what’s happening, but I’ll check the code later.
I checked the code, and it is already written in this way. As soon as the initialisation is complete it is marked ONLINE. There are a few commands that get sent to the devices, so if the device doesn’t respond then this doesn’t happen.
For most of your devices, this works fine, but at least one device is not responding to commands sent by the dongle, so that’s why it is taking time.
Thanks Chris - Just getting back to this … been side tracked on other things … So to follow up:
You are saying that in my setup, after around 5 minutes, even though the devices are not marked as ONLINE, they in fact should react to commands.
Is there something that, programmatically, I can query to know it has reached that state? (i.e. when I can send commands and have them take effect)
you say:
Does that mean if I can identify that device(s), the system will be ready faster?
But even if they think they are ONLINE, they dont react to any commands or send any status until they are actually marked ONLINE, which is 45-60 minutes. That can’t be normal.
Sorry - I missed your earlier message…
Well, in the log you provided, the devices WERE marked as online after a couple of minutes.
I think it’s possible to find if a device is online, but I’m not sure to be honest.
As seen in the log above, and as I already said, most devices come online pretty quickly, but at least one device is not contactable by the dongle, and therefore it will not be set online, and also if the dongle can’t communicate, it will not be possible to send commands.
The device will send status updates irrespective of the state, and in fact I believe that as soon as a status update is received, it will be set online anyway.
In the log you provided above to show this issue, this was not the case - the devices came online within a couple of minutes (most much faster). It’s therefore unclear to me why it takes so long if that is actually the case.
If devices are not responding, as we saw in the log above for at least one device, then the binding will not mark it online. You need to find out why this is happening as it clearly will not respond to commands if the dongle is unable to communicate with the device.
Ok … I think we’re talking passed each other … I can provide another log but this is 100% repeatable and it was the case in the log I sen t … after maybe 15 minutes 25% of the devices are marked ONLINE. If they are marked ONLINE (i am talking about in the UI), then I should(and I can) send them commands and they react… but it is a slow process to get them all online (a few dont have batteries so I assume those few will never come online)…
But you’re statement that looking at the logs shows 90% were up within 5 minutes is not correct.
How do I confirm this so we are on the same page? Can you tell me what to look for so I can look at the detailed zigbee logs myself to know? i.e. what log line tells you the device is ONLINE? I am looking at my basic log now and devices are slowly trickling in at about 1 a minute, meaning I get the lines:
2021-09-21 16:10:41.816 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:coordinator_ember:ZigBee_Bridge' changed from UNKNOWN to ONLINE
2021-09-21 16:13:21.452 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae631' changed from UNKNOWN to ONLINE
2021-09-21 16:13:24.904 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001cd5243e' changed from UNKNOWN to ONLINE
2021-09-21 16:13:27.821 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae5ee' changed from UNKNOWN to ONLINE
2021-09-21 16:14:11.701 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b000106d27f' changed from UNKNOWN to ONLINE
2021-09-21 16:14:15.490 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:742DB793-539A-4C31-88D3-491950F784EA' changed from UNKNOWN to ONLINE
2021-09-21 16:14:17.036 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001cd526b3' changed from UNKNOWN to ONLINE
2021-09-21 16:14:54.686 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b00226a5a4e' changed from UNKNOWN to ONLINE
2021-09-21 16:15:14.090 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b00226a3dbf' changed from UNKNOWN to ONLINE
2021-09-21 16:16:02.698 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:286d9700010ce870' changed from UNKNOWN to ONLINE
2021-09-21 16:13:21.452 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae631' changed from UNKNOWN to ONLINE
2021-09-21 16:13:24.904 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001cd5243e' changed from UNKNOWN to ONLINE
2021-09-21 16:13:27.821 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae5ee' changed from UNKNOWN to ONLINE
2021-09-21 16:14:11.701 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b000106d27f' changed from UNKNOWN to ONLINE
2021-09-21 16:14:15.490 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:742DB793-539A-4C31-88D3-491950F784EA' changed from UNKNOWN to ONLINE
2021-09-21 16:14:17.036 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001cd526b3' changed from UNKNOWN to ONLINE
2021-09-21 16:14:54.686 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b00226a5a4e' changed from UNKNOWN to ONLINE
2021-09-21 16:15:14.090 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b00226a3dbf' changed from UNKNOWN to ONLINE
2021-09-21 16:16:02.698 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:286d9700010ce870' changed from UNKNOWN to ONLINE
2021-09-21 16:16:09.994 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:smartthings_motionv4:ZigBee_Bridge:24fd5b000103859e' changed from UNKNOWN to ONLINE
2021-09-21 16:16:50.207 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b002269cb1e' changed from UNKNOWN to ONLINE
2021-09-21 16:17:08.210 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b000107e804' changed from UNKNOWN to ONLINE
2021-09-21 16:17:08.705 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b00010b859e' changed from UNKNOWN to ONLINE
2021-09-21 16:13:21.452 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae631' changed from UNKNOWN to ONLINE
2021-09-21 16:13:24.904 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001cd5243e' changed from UNKNOWN to ONLINE
2021-09-21 16:13:27.821 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f00044ae5ee' changed from UNKNOWN to ONLINE
2021-09-21 16:14:11.701 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b000106d27f' changed from UNKNOWN to ONLINE
2021-09-21 16:14:15.490 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'chromecast:audiogroup:742DB793-539A-4C31-88D3-491950F784EA' changed from UNKNOWN to ONLINE
2021-09-21 16:14:17.036 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001cd526b3' changed from UNKNOWN to ONLINE
2021-09-21 16:14:54.686 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b00226a5a4e' changed from UNKNOWN to ONLINE
2021-09-21 16:15:14.090 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b00226a3dbf' changed from UNKNOWN to ONLINE
2021-09-21 16:16:02.698 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:286d9700010ce870' changed from UNKNOWN to ONLINE
2021-09-21 16:16:09.994 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:smartthings_motionv4:ZigBee_Bridge:24fd5b000103859e' changed from UNKNOWN to ONLINE
2021-09-21 16:16:50.207 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b002269cb1e' changed from UNKNOWN to ONLINE
2021-09-21 16:17:08.210 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b000107e804' changed from UNKNOWN to ONLINE
2021-09-21 16:17:08.705 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b00010b859e' changed from UNKNOWN to ONLINE
2021-09-21 16:17:49.399 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b0022ed3562' changed from UNKNOWN to ONLINE
2021-09-21 16:19:06.874 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:24fd5b00010211e8' changed from UNKNOWN to ONLINE
2021-09-21 16:19:29.588 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:000d6f0011166758' changed from UNKNOWN to ONLINE
2021-09-21 16:19:40.061 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b0022344592' changed from UNKNOWN to ONLINE
2021-09-21 16:20:14.694 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:device:ZigBee_Bridge:00124b001b78d267' changed from UNKNOWN to ONLINE
2021-09-21 16:21:25.376 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'zigbee:smartthings_motionv4:ZigBee_Bridge:24fd5b0001038348' changed from UNKNOWN to ONLINE
As you can see, the first one goest ONLINE at 16:10:41 … then the last one in this log, not my system, goes ONLINE at 16:21:25… I am still waiting for 2/3rd of the devices to go ONLINE.
Well, I’m only going on the log, and looking at the Zigbee state - maybe this isn’t the same as OH state.
2021-09-11 13:46:48.537 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000B3D30F5: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:48.741 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000A7BA835: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:49.505 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD6A9C6: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:50.665 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B000108787A: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:50.718 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B000106D27F: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:50.779 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B00223444E6: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:50.802 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD526B3: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:50.906 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000B2E7519: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:53.323 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B0001038382: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:55.572 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - B0CE18140338DC6E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:57.769 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F00044AE631: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:57.889 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - B0CE1814033963D1: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:57.896 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - E20DB9FFFE0A46CC: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:57.940 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 286D97000106DAF9: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:58.096 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B0001038595: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:58.506 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - E20DB9FFFE0A4625: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:46:59.893 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000B2D9BBD: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:01.083 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 286D9700010CF001: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:01.272 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F00044AE5EE: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:02.044 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD5243E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:02.067 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F000597E5D5: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:03.776 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B00010211E8: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:04.760 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B000103859E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:05.921 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F00057D2DAE: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:06.852 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B0001019EF1: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:09.243 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 286D9700010924C8: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:09.812 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F00057D2FE7: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:12.734 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B00010390E6: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:14.015 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 286D9700010CD427: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:14.902 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B00010BB6D2: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:16.048 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B00226A5A4E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:21.942 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F00057B7384: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:26.245 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - B0CE18140338ABC5: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:26.342 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B00010208ED: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:26.417 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 286D97000106DB00: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:30.313 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 286D9700010CE870: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:34.821 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B00010B859E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:39.249 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B000107E804: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:40.868 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD6AC8A: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:43.297 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001B62576B: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:44.070 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F00056B307E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:47:58.937 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B00226A3DBF: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:48:17.781 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B00226D6ED3: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:48:20.715 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B002269CB1E: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:48:46.556 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD5234F: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:49:04.935 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 000D6F0011166758: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:49:08.688 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 24FD5B0001038348: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:49:09.755 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - E20DB9FFFE09BC44: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:49:14.682 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B00226D6B45: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:49:15.228 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B0022ED3562: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:49:31.418 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD6AD13: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:50:47.053 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001CD6AAFA: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:50:52.874 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001B627AA0: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:51:00.474 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B00223667DB: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:51:36.099 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - 00124B001B78D267: Node state updated from UNKNOWN to ONLINE
2021-09-11 13:56:21.582 [DEBUG] [com.zsmartsystems.zigbee.ZigBeeNode ] - E20DB9FFFE0A70D9: Node state updated from UNKNOWN to ONLINE
I think this ties up with what I said above -:
I see that actually the last device is 5 minutes after this, so I might have missed one entry last time, but still, this is 10 minutes for 56 devices to come online - not 50 minutes.
As I said though, there were some devices that were not communicating - clearly devices that aren’t communicating will not come online - or they might come online if the binding receives a report from them, but obviously they still will not be able to be commanded.
Devices that do not communicate are always going to be a problem, and there’s not a lot I can do to help with that unfortunately. If the devices don’t communicate, then they don’t complete the startup part of the binding so will not be ONLINE.
Ok, clearly it is not. If you look at the events.log that lines up with the openhab.log I sent, you will see that it takes about an hour. And, more importantly, until I get the “ab.event.ThingStatusInfoChangedEvent” the zigbee device cannot communicate. That’s the key issue. If it was just the UI not showing ONLINE, I wouldn’t be as concerned (although that would be bad too).
So, how to figure this out? What info / logs do we need?
Probably the issue is what I’ve said - some devices are not responding quickly or at all. If communications is poor, then, well, things won’t work too well. The system can only handle a small number of simultaneous transactions (around 5 from memory for standard Ember devices). If some of these devices aren’t communicating, then things will start to queue up and it becomes quite difficult to separate out what’s happening.
It may also be that your dongle can only handle a certain number of routes, or devices, and this can cause a lot more traffic on the network as route discovery starts to take over. I can’t really comment too much on this, but I spent some time a year or so back improving performance with large networks for a large German company, and it also required changes to the dongle configuration and firmware.
I count around 675 timed out transactions in this log - I’m not sure why all these are timing out as it’s clearly hard to work through all this. It might be routing, or certain devices or device types and I don’t really have the time at the moment to try and work this all through.
Probably we’d need to see a sniffer log, but it’s not likely to be simple to decipher what’s happening I suspect.
Ok thanks Chris … this is all very depressing. I moved all my devices off of SmartThings to avoid being subject to their corporate whims and the cloud … the zigbee network was about the same with the controllers in the same location and the network would be usable in a few minutes. I suspect the dongle itself must be the most likely culprit. this is why I asked the question in my original post:
Would be interested to know.
I have created a simple SmartThings bridge (had trouble with the SmartThings binding) and I will slowly move devices back over to SmartThings to see if I can improve the OH startup time (and also shitty performance of some sensors/lights) which is likely related.
By the way, after the network converges, the performance is mostly fine. i.e. they do eventually figure out how to form a mesh and communicate effectively.