No control of paired devices after binding has been running for hours

[openhab]

No control of paired devices after binding has been running for hours

[ScottKinSF]

Logs from OH2 start until loss of ZigBee device control was noted:

zigbee-logs-20180106.zip

[cdjackson]

Can you provide your system configuration please - eg hardware, memory, processor...

[ScottKinSF]

I have OH2 running on a Raspberry Pi 3 Model B.

[08:09:17] scott@rpi3:~$ cat /proc/cpuinfo 
processor       : 0
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 38.40
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 1
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 38.40
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 2
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 38.40
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

processor       : 3
model name      : ARMv7 Processor rev 4 (v7l)
BogoMIPS        : 38.40
Features        : half thumb fastmult vfp edsp neon vfpv3 tls vfpv4 idiva idivt vfpd32 lpae evtstrm crc32 
CPU implementer : 0x41
CPU architecture: 7
CPU variant     : 0x0
CPU part        : 0xd03
CPU revision    : 4

Hardware        : BCM2835
Revision        : a22082
Serial          : 00000000e84ae36c

[08:12:03] scott@rpi3:~$ cat /proc/meminfo 
MemTotal:        1000312 kB
MemFree:           47052 kB
MemAvailable:     442308 kB
Buffers:           46780 kB
Cached:           431084 kB
SwapCached:          260 kB
Active:           592304 kB
Inactive:         297336 kB
Active(anon):     353412 kB
Inactive(anon):   112220 kB
Active(file):     238892 kB
Inactive(file):   185116 kB
Unevictable:           0 kB
Mlocked:               0 kB
SwapTotal:        102396 kB
SwapFree:          99152 kB
Dirty:               184 kB
Writeback:             0 kB
AnonPages:        411528 kB
Mapped:            43400 kB
Shmem:             53816 kB
Slab:              47292 kB
SReclaimable:      32608 kB
SUnreclaim:        14684 kB
KernelStack:        2960 kB
PageTables:         2672 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:      602552 kB
Committed_AS:     738680 kB
VmallocTotal:    1064960 kB
VmallocUsed:           0 kB
VmallocChunk:          0 kB
CmaTotal:           8192 kB
CmaFree:            6524 kB

[08:15:21] scott@rpi3:~$ uname -a
Linux rpi3 4.9.59-v7+ #1047 SMP Sun Oct 29 12:19:23 GMT 2017 armv7l GNU/Linux

The CC2531 coordinator is plugged into a powered USB hub that is in turn plugged into one of the USB ports on the RPi. The USB port into which the CC2531 coordinator is plugged is /dev/ttyUSBzigbee, which is symlinked to /dev/ttyACM0:

lrwxrwxrwx 1 root root 7 Jan  4 16:24 /dev/ttyUSBzigbee -> ttyACM0
crw-rw---- 1 root dialout 166, 0 Jan  7 08:08 /dev/ttyACM0

[cdjackson]

My guess at the moment is that this is some sort of resource leak. Does everything else continue to run when this happens? If you stop and start the binding, or stop/start OH is there a change in resources?

[ScottKinSF]

All other bindings and the devices they control continue to function correctly. I have controlled devices connected via MQTT (wifi), ZWave and HTTP/UPNP. If I stop then start the binding, I encounter the coordinator/serial problem recently documented in the Zigbee binding thread on community.openhab.org. I was not paying attention to resources before and after restarting OH2. I'll be sure to note same next time I restart OH2.

I updated to the 2.3.0.201801061842 snapshot of the ZigBee binding this morning. Currently it is functioning correctly. All paired devices were found at startup. That was not always the case when starting the 2.3.0.201801042145 release of the binding. Of course for the 20180106 snapshot that's a sample of one so take that information with a large grain of salt.

[cdjackson]

All other bindings and the devices they control continue to function correctly.

Ok, thanks. I had thought that if it was a resource issue, it might also impact other bindings or the system in general. If that's not the case, then I'm not sure where to look.

If I stop then start the binding, I encounter the coordinator/serial problem recently documented in the Zigbee binding thread on community.openhab.org.

What issue is this? I'm not actually aware of anything with the TI dongle (other then #2).

[ScottKinSF]

There does seem to be evidence of a memory resource issue. Over the past several hours I have been randomly checking the runset size of the OH2 process ():

[09:14:18]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 17 140876 302304 0 08:00 ?        00:12:58 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[09:14:21]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 17 140876 302304 0 08:00 ?        00:12:59 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[09:47:41]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 15 140876 302336 0 08:00 ?        00:16:53 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[09:48:13]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 15 140876 302336 0 08:00 ?        00:16:56 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[10:24:22]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 14 140876 302708 0 08:00 ?        00:21:12 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[11:36:51]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 13 140878 302756 0 08:00 ?        00:29:42 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[11:36:54]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 13 140878 302756 0 08:00 ?        00:29:42 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[11:37:28]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 13 140878 302756 0 08:00 ?        00:29:45 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

[12:23:45]
UID        PID  PPID  C    SZ   RSS PSR STIME TTY          TIME CMD
openhab  19925     1 13 140878 302796 0 08:00 ?        00:35:08 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

RSS has steadily increased from 302.304 MB at 09:14 local time to 302.796 MB at 12:24 local time (running the 2.3.0.201801061842 snapshot of the ZigBee binding). Of course, there is no information here to determine which OH2 thread(s) is(are) responsible.

[ScottKinSF]

Running without an operational issue for two days now, but the run set size of the OH2 process has continued increasing. It is now reported as 317.28 MB.

Tue Jan  9 08:14:58
openhab  19925     1 11 142680 317280 0 Jan07 ?        05:44:13 /usr/bin/java -Dopenhab.home=/usr/share/openhab2 -Dopenhab.conf=/etc/openhab2 -Dopenhab.runtime=/usr/share/openhab2/runtime -Dopenhab.userdata=/var/lib/openhab2 -Dopenhab.logdir=/var/log/openhab2 -Dfelix.cm.dir=/var/lib/openhab2/config -Djetty.host=0.0.0.0 -Djetty.http.compliance=RFC2616 -Dorg.ops4j.pax.web.listening

I'm not a bona fide java programmer, so I don't know whether or not there is a finer grained way to monitor the OH2 process's memory usage. Any help there?

[cdjackson]

I think that an increase in resource use is probably perfectly normal over time. For sure under a Linux system, the system will use all the memory - that doesn’t mean there’s any sort of problem. I’m not sure how the JVM works in this respect and when the garbage collection runs.

[ScottKinSF]

This morning I noticed that all ZigBee end devices had stopped responding to commands. I captured and uploaded the logs here.

zigbee-logs-20180110.zip

[cdjackson]

There's nothing obviously wrong with the binding. Even at the end of the logging there's no sign of things not working - commands are being sent to devices and responses are being returned. Some devices appear like they might be timing out, but others are working.

This is a poll at the end of the log - looks fine -:

2018-01-10 06:00:46.890 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE18140306E556: Polling...
2018-01-10 06:00:46.894 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE18140306E556: Polling zigbee:device:b0ec0a7d:b0ce18140306e556:B0CE18140306E556_1_switch_level
2018-01-10 06:00:46.896 [DEBUG] [.zsmartsystems.zigbee.zcl.ZclCluster] - readSync request: ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=0]
2018-01-10 06:00:46.898 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [Level Control: 0/0 -> 49606/1, cluster=0008, TID=0A, identifiers=[0]]
2018-01-10 06:00:46.901 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=10, commandId=0]
2018-01-10 06:00:46.903 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=49606/1, profile=0104, cluster=8, addressMode=DEVICE, radius=31, sequence=10, payload=00 0A 00 00 00]
2018-01-10 06:00:46.906 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=15, apiId=24 01, data=FE 0F 24 01 C6 C1 01 01 08 00 0A 30 1F 05 00 0A 00 00 00 0F, checksum=0F, error=false) 
2018-01-10 06:00:47.070 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2018-01-10 06:00:47.073 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 00 01 0A CC)
2018-01-10 06:00:47.075 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=SUCCESS(0), TransID=10)
2018-01-10 06:00:47.079 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_INCOMING_MSG (FE 1C 44 81 00 00 08 00 C6 C1 01 01 00 27 00 E3 9B 19 00 00 08 18 0A 01 00 00 00 20 00 C6 C1 1D B1)
2018-01-10 06:00:47.081 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: Packet: subsystem=null, length=28, apiId=44 81, data=FE 1C 44 81 00 00 08 00 C6 C1 01 01 00 27 00 E3 9B 19 00 00 08 18 0A 01 00 00 00 20 00 C6 C1 1D B1, checksum=B1, error=false
2018-01-10 06:00:47.084 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=49606/1, destinationAddress=0/1, profile=0104, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 0A 01 00 00 00 20 00]
2018-01-10 06:00:47.086 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=10, commandId=1]
2018-01-10 06:00:47.089 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [Level Control: 49606/1 -> 0/1, cluster=0008, TID=0A, records=[ReadAttributeStatusRecord [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, status=SUCCESS, attributeValue=0]]]
2018-01-10 06:00:47.098 [DEBUG] [converter.ZigBeeConverterSwitchLevel] - B0CE18140306E556: ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=0]
2018-01-10 06:00:47.102 [DEBUG] [converter.ZigBeeBaseChannelConverter] - B0CE18140306E556: Channel zigbee:device:b0ec0a7d:b0ce18140306e556:B0CE18140306E556_1_switch_level updated to 0

But sending a command to a device shortly after comes back with a response that the device is not found on the network -:

2018-01-10 06:00:57.926 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - B0CE181403019F87: Command for channel zigbee:device:b0ec0a7d:b0ce181403019f87:B0CE181403019F87_1_color_color --> 26
2018-01-10 06:00:57.931 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MoveToLevelWithOnOffCommand [Level Control: 0/0 -> 2938/1, cluster=0008, TID=0B, level=66, transitionTime=10]
2018-01-10 06:00:57.940 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=11, commandId=4]
2018-01-10 06:00:57.945 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=2938/1, profile=0104, cluster=8, addressMode=DEVICE, radius=31, sequence=11, payload=01 0B 04 42 0A 00]
2018-01-10 06:00:57.947 [DEBUG] [31.network.impl.CommandInterfaceImpl] - ->  AF_DATA_REQUEST (Packet: subsystem=null, length=16, apiId=24 01, data=FE 10 24 01 7A 0B 01 01 08 00 0B 30 1F 06 01 0B 04 42 0A 00 28, checksum=28, error=false) 
2018-01-10 06:00:58.073 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-  AF_DATA_SRSP (FE 01 64 01 00 64)
2018-01-10 06:01:04.082 [DEBUG] [31.network.impl.CommandInterfaceImpl] - <-- AF_DATA_CONFIRM (FE 03 44 80 CD 01 0B 00)
2018-01-10 06:01:04.085 [DEBUG] [31.network.impl.CommandInterfaceImpl] - Received Async Cmd: AF_DATA_CONFIRM(Endpoint=1, Status=Z_NWK_NO_ROUTE(205), TransID=11)

I don't see a problem here with the binding.

[chrissfoot]

I see this same issue unfortunately. I get it all working before I go to bed and by the morning nothing responds but my logs look exactly the same as Scott's, everything looks like it's working fine but the lights never actually carry out the commands. A restart of openhab seems to be the only thing that fixes this. Other bindings (z-wave for ex) are still working before the restart.

[rbi]

I have the same issue with a Qivicon USB stick which I operate with the Telegesis driver. When restarting OpenHAB everything works fine until at some point nothing reacts anymore. Receiving works fine though.

I have this problem with the plugin version that comes with OpenHAB 2.3.

[cdjackson]

Please provide information on your network - type and number of devices, distances etc.

…

On 11 Jun 2018, at 07:07, Raik Bieniek ***@***.***> wrote: I have the same issue with a Qivicon USB stick which I operate with the Telegesis driver. When restarting OpenHAB everything works fine until at some point nothing reacts anymore. Receiving works fine though. I have this problem with the plugin version that comes with OpenHAB 2.3. — You are receiving this because you commented. Reply to this email directly, view it on GitHub, or mute the thread.

[rbi]

I have:

• 5x OSRAM SMART+ Plug
• 1x OSRAM SMART+ Classic B40 (E14 bulb)
• 1x TRADFRI bulb E27 WS opal 980lm
• 2x Philips Hue E14 color bulbs
• 2x Philips Hue Dimer remotes
• 1x OSRAM SMART+ Mini remote
• 3x Heiman TH-T_V15 temperature/humidity sensors (which have problems with reconnecting after restarting OpenHAB but thats another story I guess).

Most things are located in the same room as the Qivicon Stick. Some are in another room with one wall between.

I have restarted OpenHAB about 11 hours ago with debug logging enabled. It still works while yesterday it didn't last 2 hours until the error happened. If it happens again I can provide logs.

Yesterday I enabled the debug logging when the error occured. When switching on a light I got a log similar to this one:
2018-06-11 17:49:05.215 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A79BBC: Command for channel zigbee:device:0000025C:7cb03eaa00a79bbc:7CB03EAA00A79BBC_3_switch_level --> 75
and after that nothing. If I switch a light on now I get many more logs.

[cdjackson]

Thanks - that’s useful. So we an say it’s a reasonably busy network which is what I wanted to see. This might be an issue for which a user on the forum has identified a possible fix. I’ve got a PR ready to go for this, but to test will require some manual work. Keep an eye on the repository over the next day or so and I’ll describe the update. It would be interesting to get your feedback.

…

On 11 Jun 2018, at 16:52, Raik Bieniek ***@***.***> wrote: I have: 5x OSRAM SMART+ Plug 1x OSRAM SMART+ Classic B40 (E14 bulb) 1x TRADFRI bulb E27 WS opal 980lm 2x Philips Hue E14 color bulbs 2x Philips Hue Dimer remotes 1x OSRAM SMART+ Mini remote 3x Heiman TH-T_V15 temperature/humidity sensors (which have problems with reconnecting after restarting OpenHAB but thats another story I guess). Most things are located in the same room as the Qivicon Stick. Some are in another room with one wall between. I have restarted OpenHAB about 11 hours ago with debug logging enabled. It still works while yesterday it didn't last 2 hours until the error happened. If it happens again I can provide logs. Yesterday I enabled the debug logging when the error occured. When switching on a light I got a log similar to this one: 2018-06-11 17:49:05.215 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 7CB03EAA00A79BBC: Command for channel zigbee:device:0000025C:7cb03eaa00a79bbc:7CB03EAA00A79BBC_3_switch_level --> 75 and after that nothing. If I switch a light on now I get many more logs. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#78 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA_kQ71iIrlyhU2NQWgFMxKVTiMK3KTcks5t7pIxgaJpZM4RVczs>.

[rbi]

That sounds great. 👍 I will be busy the rest of the week but next week I can test it.

[cdjackson]

Thanks.

…

On 11 Jun 2018, at 17:52, Raik Bieniek ***@***.***> wrote: That sounds great. 👍 I will be busy the rest of the week but next week I can test it. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#78 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA_kQ1HEPrLDuZvTfVuQwbptIN56T1obks5t7qBbgaJpZM4RVczs>.

[rbi]

I was staring at the same code as you've touched in your pull request. Maybe there is a deadlock between synchronisation on CommandResultFuture and commandExecutions in ZigBeeNetworkManager but I didn't figure out when get is called on the future so I may be wrong. Here is my theory:

• Some thread is in removeCommandExecution and has the monitor on commandExecutions
• It tries to get the monitor on the future but another thread has it.
• The other thread just wok up from CommandResultFuture#get line unit.timedWait so it has the monitor on the future again
• The result is null so it calls removeCommandExecution which tries to get the monitor on commandExecutions
• dead lock

[cdjackson]

Yes, this is what the PR I just created is meant to address. I’ll hopefully merge this tomorrow and will then generate an updated library.

…

On 11 Jun 2018, at 19:11, Raik Bieniek ***@***.***> wrote: I was staring at the same code as you've touched in your pull request. Maybe there is a deadlock between synchronisation on CommandResultFuture and commandExecutions in ZigBeeNetworkManager but I didn't figure out when get is called on the future so I may be wrong. Here is my theory: Some thread is in removeCommandExecution and has the monitor on commandExecutions It tries to get the monitor on the future but another thread has it. The other thread just wok up from CommandResultFuture#get line unit.timedWait so it has the monitor on the future again The result is null so it calls removeCommandExecution which tries to get the monitor on commandExecutions dead lock — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#78 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA_kQ-EGrefaCUTbOlQCg3HanN-tKtUEks5t7rLXgaJpZM4RVczs>.

[rbi]

Thanks for the merge. I do not think that the pull request fixes the root cause. The problematic code in CommandResultFuture and removeCommandExecution which both try to get the same two locks remains.

I can look into it a bit further when I have more time.

Edit: What I think of is somethink like that:

• There should be no need to hold an commandExecutions list. As I understand it, it is only necessary to unregister listeners that will most likely never get a response. As each listener is called on each command anyway the listener itself could check if it has timed out and unregister itself.
• The future should have no need to unregister the listener. If the future times out it just returns null as it does. The listener may be still registered but it will unregister it self later. I guess there is some ZigBee spec that says "A command must be confirmed after x seconds." or something so although the listener may be still registered it will never fire if the timeout in the future is high enough.

[rbi]

I've committed the changes I described in a branch:

Diff

I haven't tested it yet so there is no pull request. I can test it next week.

[cdjackson]

Thanks, I’ll take a look, and generally agree with your comments. Please discuss this in the appropriate repository - ie let’s not discuss the issue here when it’s in the other repository. I’d suggest to open an issue there with your comments.

…

On 12 Jun 2018, at 23:01, Raik Bieniek ***@***.***> wrote: I've committed the changes I described in a branch: Diff <zsmartsystems/com.zsmartsystems.zigbee@master...rbi:simplify_command_listener_unregistration> I haven't tested it yet so there is no pull request. I can test it next week. — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#78 (comment)>, or mute the thread <https://github.com/notifications/unsubscribe-auth/AA_kQ4KShamGk4Y8JoFK_lpKNGyuVd4eks5t8DpEgaJpZM4RVczs>.

[rbrueckner82]

I have the same issue with a cc2531 stick. When restarting OpenHAB everything works fine until at some point nothing reacts anymore. Receiving works fine though and all Devices are Online but all the Bulbs not working.

Raspberry Pi3 cc2531

5x Xiaomi WSDCGQ11LM
2x Xiaomi MCCGQ11LM
2x Xiaomi RTCGQ11LM
2x Philips 7199960PH
3x Philips 9290012573A
1x Philips 9290012607

Use this with OpenHAB 2.3.

Any Solution for this Issue, ist there an Update for openHAB Zigbee Binding?

Thanks!

[cdjackson]

ist there an Update for openHAB Zigbee Binding?

Yes, you are using a very old version of the binding (6 months or more now!). I would strongly recommend to upgrade - I don't know if it will solve the issue, but running such an old version will certainly not help!

[rbrueckner82]

OK, can you send me an link for the current binding? I use the latest 2.3 Docker image from the Docker hub!

Thanks!

[cdjackson]

Please check the openhab documentation - it explains how to install the different versions.

[rbrueckner82]

yes of course, but for the Upgrade to the right/current version i need the URL

bundle:install httpS://*

and i can`t find this, Sorry!

[AngelosF]

@rbrueckner82
user help at the forum please: https://community.openhab.org/
developer help at github

[cdjackson]

It depends on what system you are running - the documentation should tell you how to upgrade, and as pointed out by @AngelosF the forum is a better place for general help topics.

[ScottKinSF]

The zigbee binding has been working quite well for me since roughly the start of the 2.4.0-SNAPSHOT releases. I wish I had paid more attention to when this issue stopped occurring for me, but I can't say with any certainty at what point that was.

[cdjackson]

There have been a lot of changes in the binding and underlying libraries to improve stability over the past 18 months. Closing this due to inactivity.

[ScottKinSF]

Working well for me. My production system has had no issues and my test system that I recently updated to 2.5.0.M2 is still running without issue since 1st boot this morning (> 12 hours ago.)