openhab / org.openhab.binding.zigbee

openHAB binding for ZigBee
Eclipse Public License 2.0
73 stars 111 forks source link

BJ 6711 U relay state not updated #49

Closed weakfl closed 5 years ago

weakfl commented 6 years ago

As discussed in the community thread, the state of the Busch-Jaeger 6711 U relay does not get updated in OH if the physical switch is used to change its state.

Here's the requested log: oh_zigbee_binding_debug.log.zip

I've also changed the state of the relay to on/off twice. First time via OH, second time via the physical switch, should be at the end of the log.

cdjackson commented 6 years ago
D85DEF11A1002826: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, modelId=RM01, zigbee_networkaddress=45692, zigbee_powersource=MAINS, zigbee_stkversion=1, zigbee_datecode=20161209, zigbee_zclversion=1, vendor=Busch-Jaeger, zigbee_appversion=1, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS, RECHARGABLE_BATTERY, DISPOSABLE_BATTERY], hardwareVersion=0}

D85DEF11A1001973: ZigBee node property discovery complete: {zigbee_logicaltype=ROUTER, zigbee_powerlevel=FULL, modelId=RM01, zigbee_networkaddress=31084, zigbee_powersource=MAINS, zigbee_stkversion=1, zigbee_datecode=20161209, zigbee_zclversion=1, vendor=Busch-Jaeger, zigbee_appversion=1, zigbee_powermode=RECEIVER_ON_IDLE, zigbee_powersources=[MAINS, RECHARGABLE_BATTERY, DISPOSABLE_BATTERY], hardwareVersion=0}

I'll move the conversation off the forum for this - it'll be easier to track...

Is there now an XML generated in the /userdata/zigbee folder? Can you post it please?

cdjackson commented 6 years ago

Just for my reference...

Device information...

2017-12-03 10:04:16.226 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [45692/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=45692, length=20, simpleDescriptor=SimpleDescriptor [endpoint=18, profileId=C05E, deviceId=0, deviceVersion=2, inputClusterList=[0, 4, 3, 5, 6, 8], outputClusterList=[]]]
2017-12-03 10:04:16.245 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting input clusters [0, 4, 3, 5, 6, 8]
2017-12-03 10:04:16.259 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting cluster BASIC as server
2017-12-03 10:04:16.262 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting cluster GROUPS as server
2017-12-03 10:04:16.263 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting cluster IDENTIFY as server
2017-12-03 10:04:16.329 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting cluster SCENES as server
2017-12-03 10:04:16.332 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting cluster ON_OFF as server
2017-12-03 10:04:16.391 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/18: Setting cluster LEVEL_CONTROL as server

2017-12-03 10:04:16.525 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: SimpleDescriptorResponse [45692/0 -> 0/0, cluster=8004, TID=NULL, status=SUCCESS, nwkAddrOfInterest=45692, length=28, simpleDescriptor=SimpleDescriptor [endpoint=10, profileId=C05E, deviceId=2064, deviceVersion=2, inputClusterList=[0, 4096], outputClusterList=[4096, 3, 6, 8, 4, 5, 768, 25]]]
2017-12-03 10:04:16.530 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting input clusters [0, 4096]
2017-12-03 10:04:16.532 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster BASIC as server
2017-12-03 10:04:16.533 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster TOUCHLINK as server
2017-12-03 10:04:16.535 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting output clusters [4096, 3, 6, 8, 4, 5, 768, 25]
2017-12-03 10:04:16.538 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster TOUCHLINK as client
2017-12-03 10:04:16.540 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster IDENTIFY as client
2017-12-03 10:04:16.541 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster ON_OFF as client
2017-12-03 10:04:16.552 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster GROUPS as client
2017-12-03 10:04:16.553 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster SCENES as client
2017-12-03 10:04:16.606 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster COLOR_CONTROL as client
2017-12-03 10:04:16.688 [DEBUG] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 45692/10: Setting cluster OTA_UPGRADE as client

Bind / Reporting commands [Level control]...

2017-12-03 10:04:16.812 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: BindRequest [0/0 -> 45692/18, cluster=0021, TID=15, srcAddress=D85DEF11A1002826, srcEndpoint=18, bindCluster=8, dstAddrMode=3, dstAddress=000D6F000D03D29E, dstEndpoint=1]
2017-12-03 10:04:18.655 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: BindResponse [45692/0 -> 0/0, cluster=8021, TID=NULL, status=SUCCESS]

2017-12-03 10:04:17.492 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Level Control: 0/0 -> 45692/18, cluster=0008, TID=1B, records=[Attribute Reporting Configuration Record: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, minimumReportingInterval=1, maximumReportingInterval=600, reportableChange=1, timeoutPeriod=0]]
2017-12-03 10:04:18.447 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Level Control: 45692/18 -> 0/0, cluster=0008, TID=1B, records=[Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0, Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0, Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0, Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0]]

Frames observed -:


2017-12-03 11:45:23.435 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/1, profile=49246, cluster=6, addressMode=null, radius=0, sequence=0, payload=18 1B 0A 00 00 10 00]
2017-12-03 11:45:23.475 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/1, profile=49246, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 1C 0A 00 00 20 FE]
weakfl commented 6 years ago

There are two xml files, I guess you're only interested in the zigbee-network.xml but here are both anyway: zigbee-network-xml.zip

cdjackson commented 6 years ago

Thanks - they should be the same. The most recent version I changed the name from zigbee-network, to add the coordinator uid to the end so that there can be more than one coordinator without conflict.

cdjackson commented 6 years ago

From the above it seems that the binding and reporting are configured (for the level command at least - I've not looked through every channel yet)...

Can you tell me what time you changed the relay position manually? (probably not ;) ). Alternatively, can you provide a short log that basically just shows what happens when you press the button.

weakfl commented 6 years ago

Should be at the end of the previous log. However, here's what's in the log when pressing the button a couple of times (not much though I'm afraid):

2017-12-03 11:43:04.572 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: ManagementRoutingRequest returned null
2017-12-03 11:43:04.645 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: done.
2017-12-03 11:43:04.647 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: Ending mesh update
2017-12-03 11:44:04.510 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: Starting mesh update
2017-12-03 11:44:04.513 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementLqiRequest [0/0 -> 0/0, cluster=0031, TID=D0, startIndex=0]
2017-12-03 11:44:04.517 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0, cluster=49, addressMode=DEVICE, radius=31, sequence=208, payload=00 00]
2017-12-03 11:44:04.521 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=0, sourceEp=0, destEp=0, profileId=0, clusterId=49, messageData=00 00, messageId=null]
2017-12-03 11:44:04.524 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 93
2017-12-03 11:44:14.528 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: ManagementLqiRequest returned null
2017-12-03 11:44:14.530 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: IeeeAddressRequest [0/0 -> 0/0, cluster=0001, TID=D1, nwkAddrOfInterest=0, requestType=1, startIndex=0]
2017-12-03 11:44:14.533 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0, cluster=1, addressMode=DEVICE, radius=31, sequence=209, payload=00 00 00 01 00]
2017-12-03 11:44:14.537 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=0, sourceEp=0, destEp=0, profileId=0, clusterId=1, messageData=00 00 00 01 00, messageId=null]
2017-12-03 11:44:14.540 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 94
2017-12-03 11:44:24.543 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: Ieee Address request returned null
2017-12-03 11:44:24.545 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ManagementRoutingRequest [0/0 -> 0/0, cluster=0032, TID=D2, startIndex=0]
2017-12-03 11:44:24.548 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/0, destinationAddress=0/0, profile=0, cluster=50, addressMode=DEVICE, radius=31, sequence=210, payload=00 00]
2017-12-03 11:44:24.550 [DEBUG] [ngle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=0, sourceEp=0, destEp=0, profileId=0, clusterId=50, messageData=00 00, messageId=null]
2017-12-03 11:44:24.552 [DEBUG] [gesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 95
2017-12-03 11:44:34.555 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: ManagementRoutingRequest returned null
2017-12-03 11:44:34.626 [DEBUG] [nal.ZigBeeNetworkStateSerializerImpl] - Saving ZigBee network state: done.
2017-12-03 11:44:34.629 [DEBUG] [tems.zigbee.ZigBeeNetworkMeshMonitor] - 0: Ending mesh update
weakfl commented 6 years ago

I don't know if it's relevant, but the physical switch actually has two buttons (or maybe two sides is more appropriate). Right side is for turning the relay on, left side for turning it off.

cdjackson commented 6 years ago

This logging isn't related to the device :( . I guess that means the device isn't sending anything.

Hmm - something else is wrong as the TX queue is increasing in size. Can you ZIP up the log again please so I can take a better look?

Thanks.

weakfl commented 6 years ago

I guess that means the device isn't sending anything.

That doesn't sound good :)

I've attached a log from restarting OH earlier today until now. However, I had set the log level to ERROR for a while, sorry. Let me know if you need a fresh debug log and I'll restart OH and let it run for a while.

oh_log_2017-12-03_12-01.log.zip

cdjackson commented 6 years ago

Thanks.

So, good news, and bad news...

Firstly, the log doesn't show the error that I was looking for - the TX queue seems to be stalled and you will need to restart the binding to solve this. If this happens again, please post the log (the indicator is the log entry TX Telegesis queue: 96 - basically this number should normally only be 1/2/3 sort of level (maybe more for short periods, but it should not just increase like I see in your log.

Good news though - I do see the commands in your log that I suspect are from the switches - it's from just after the log you attached above. It looks like they are using the ZLL profile so are bing dropped by the binding (easy issue to solve) - I need to decode the messages to see what they are - I think they are the reports I was looking for so there's some hope :)

If I provide you a debug version are you able to give it a try?

weakfl commented 6 years ago

If this happens again, please post the log (the indicator is the log entry TX Telegesis queue: 96 - basically this number should normally only be 1/2/3 sort of level (maybe more for short periods, but it should not just increase like I see in your log.

Ok, thanks for the info. I'll restart OH with debug log level and if I notice something like that I'll post the log.

Good news though - I do see the commands in your log that I suspect are from the switches - it's from just after the log you attached above. It looks like they are using the ZLL profile so are bing dropped by the binding (easy issue to solve) - I need to decode the messages to see what they are - I think they are the reports I was looking for so there's some hope :)

Nice đź‘Ť

If I provide you a debug version are you able to give it a try?

If you could provide a jar I'll be happy to test it. I haven't set up an OH development environment, so unfortunately I can't build myself.

cdjackson commented 6 years ago

A test version is here. Let me know if this works, and if not please provide another short log showing any messages from the device...

weakfl commented 6 years ago

Thanks Chris, I'll test it and report back.

Regarding the issue with the growing TX queue, this has happened again since the last restart. Here's a full debug log since the last OH restart: oh_zigbee_binding_debug_03122017_1434.log.zip

cdjackson commented 6 years ago

Thanks. What hardware/software are you using as a matter of interest (shouldn’t matter, but useful to know just in case).

On 3 Dec 2017, at 13:42, weakfl notifications@github.com wrote:

Thanks Chris, I'll test it and report back.

Regarding the issue with the growing TX queue, this has happened again since the last restart. Here's a full debug log since the last OH restart: oh_zigbee_binding_debug_03122017_1434.log.zip https://github.com/openhab/org.openhab.binding.zigbee/files/1524772/oh_zigbee_binding_debug_03122017_1434.log.zip — You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zigbee/issues/49#issuecomment-348770011, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_kQz_ly7LUAjcA5Wgtdb4x-OAzAXyiks5s8qVAgaJpZM4Qzpso.

weakfl commented 6 years ago

Raspi with stretch:

Raspberry Pi 3 Model B Rev 1.2
Raspbian GNU/Linux 9 (stretch)
Linux raspberrypi 4.9.59-v7+ #1047 SMP Sun Oct 29 12:19:23 GMT 2017 armv7l GNU/Linux
weakfl commented 6 years ago

Unfortunately it's not working with the test version either. I've used the OH app first to determine everything is still working as expected. Then I've used a combination of physical/software.

Here's a brief timeline of what I did:

15:26 ON then OFF - openhab app
15:27 ON - physical switch
15:30 OFF - physical switch
15:31 ON - openhab app
15:31 OFF - physical switch

And the log: oh_zigbee_binding_debug_03122017_1535.log.zip

weakfl commented 6 years ago

Just to make sure I've used the right version, the link you posted above was broken but I figured the correct URL should be http://www.cd-jackson.com/downloads/openhab2/org.openhab.binding.zigbee_2.2.0.201712031320.jar

cdjackson commented 6 years ago

I've fixed the link, but looks fine (seems if I don't add http on the front of the link, github assumes it's a local address!).

Anyway, with these logs, I don't see the ZLL messages I saw before, so the version doesn't matter. In your original log, they might not have been directly linked to the button presses as I'm not sure they were at the same time given you originally didn't post them as something that happened when the button was pressed. Your log when you said you changed the switch was at 11:44:04 to 11:44:34, but the ZLL frames are at 11:45:23 so I guess it's not linked and we're back to the "nothing is being sent" situation :(

weakfl commented 6 years ago

so I guess it's not linked and we're back to the "nothing is being sent" situation :(

I'm afraid you're right as I don't see any Received message or Incoming message events in the log when I press the switch. I could contact BJ and try to get some infos. This looks like a major oversight to me, I thought one of the advantages of zigbee would be some kind of "back channel" compared to cheaper 433 mhz relays.

Do you think polling could work to update the relay state in OH, even if the state update wouldn't be immediate?

Another route might be the switch attached to the relay. I'm still a bit puzzled by those. I was expecting the switches to be discoverable as separate zigbee devices (just like the battery powered switch), but they're not showing up in the inbox. Especially because some of the switches have two/four rockers with the top rocker switching the relay and the other rockers being usable for scenes...

Maybe you'll be able find out more when you receive the switch you've ordered.

Anyway, thank you so much for taking the time to look into the issue!

cdjackson commented 6 years ago

I thought one of the advantages of zigbee would be some kind of "back channel" compared to cheaper 433 mhz relays.

Well, this is something that ZigBee does have, so there’s two possibilities - one is that I’m not configuring the switch correctly, or the other is that the switch doesn’t support this. The switch is responding to both the Bind and ConfigureReporting commands, so I think it supports them. I do see something a bit strange with the response, so I’ll check this to make sure I’m not sending something wrong.

Do you think polling could work to update the relay state in OH, even if the state update wouldn't be immediate?

Yes - I can add this - the device is reporting when polled so it will work.

Another route might be the switch attached to the relay. I'm still a bit puzzled by those. I was expecting the switches to be discoverable as separate zigbee devices (just like the battery powered switch), but they're not showing up in the inbox.

The inbox will show devices - so 1 physical device = 1 thing. If there is separate functions to a device, these will then be shown as separate channels.

This device has 2 endpoints - I’m not currently handling the client clusters and these are on the second endpoint so we should be able to look at these as well. Give me a day or two to look at this as it will require a small amount more work.

Maybe you'll be able find out more when you receive the switch you've ordered.

That arrived this morning, but unfortunately it’s not so useful as it seems likely it only speaks ZLL - I need to find more time to play with that though. I have some other devices that might do a similar thing so I might power up one of them.

Anyway, thank you so much for taking the time to look into the issue!

You’re welcome - and thanks for the debugging…

I will look at a few more things and will get back to you...

weakfl commented 6 years ago

Great, so there's still hope :)

That arrived this morning, but unfortunately it’s not so useful as it seems likely it only speaks ZLL - I need to find more time to play with that though. I have some other devices that might do a similar thing so I might power up one of them.

One note about the battery powered switch. You should be able to "pair" it with a ZLL device like a HUE bulb. I did pair my battery powered switch with one of the relays today and it became ONLINE in OH. It worked for a while and then suddenly stopped. I'm only guessing here, but it might be the same issue you described regarding the CT motion sensor (removing itself from the network). Thought I'll let you know, just in case...

cdjackson commented 6 years ago

Great, so there's still hope :)

Always (well, for now ;) ).

I've found a small bug, but it only confirms that the device is responding correctly to the ConfigureReporting command and the above is incorrectly displayed - it doesn't change anything though...

One note about the battery powered switch. You should be able to "pair" it with a ZLL device like a HUE bulb.

Yep, I know that, but that's not what I wanted to do (but thanks).

That said, if I can do this with a Hue bulb, and use the remote to control the bulb, it might help debug the reporting... I'll try this out...

cdjackson commented 6 years ago

If you get a chance, please give this version a try. It will hopefully give you another switch channel (switch out) - it probably won't do anything, but if it sends any commands (or anything!!) when you click the switch, I'd be interested to see the log...

Thanks.

weakfl commented 6 years ago

Thanks for the update Chris, I gave it a quick try. Unfortunately instead of increasing the channel count to 3 channels, the test version actually decreased the channel count to just one dimmer/switch_level channel. The second channel (switch_onoff) disappeared. I still pressed the physical switch but didn't notice anything particular in the log.

However, I accidentally made an interesting discovery reverting to the snapshot version. I even double checked to make sure I wasn't fooled by item persistence:

So on OH startup the relay/item state seems to be initialized correctly?

cdjackson commented 6 years ago

Ok, thanks for testing - I’ll tae another look at this.

Yes - it will show correct status on status. As mentioned earlier the polling was working in the log - the binding polls on initialisation so that it knows the status.

cdjackson commented 6 years ago

I got my ands, and ors mixed up which is why it reduced the channels rather than adding them. I’ll update and provide a new test shortly...

cdjackson commented 6 years ago

Here's another version to test... Again, I don't expect it to work - you should get an extra channel this time I hope and I'd be interested to see what the log shows (if anything) when you click the buttons.

weakfl commented 6 years ago

Thanks Chris, and sorry for the late reply. I got caught up at the office today...

The new test version was quite a success, but maybe not as expected :)

As I've mentioned I have two relays installed, one with a 1-channel switch attached and one with a 2-channel switch. The 1-channel relay got one new channel, the 2-channel relay got two(!). All are Switch (out) channels.

I created some dummy switch items and started pressing buttons. I think the switches which are turning the relay on/off didn't do anything, but maybe you can take a look at this log to make sure. There were some TelegesisReceiveMessageEvents, but I think they were unrelated.

However, the second channel on the 2-channel switch definitely does something:

1:06:50.021 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 30 31 30 34 2C 30 31 2C 30 42 2C 30 30 30 36 2C 30 33 3A 11 D9 01 2C 2D 33 38 2C 46 46
21:06:50.035 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 D9 01, rssi=-56, lqi=255]
21:06:50.049 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 D9 01, rssi=-56, lqi=255]
21:06:50.063 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/11, destinationAddress=0/1, profile=0104, cluster=6, addressMode=null, radius=0, sequence=0, payload=11 D9 01]
21:06:50.075 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=217, commandId=1]
21:06:50.088 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: OnCommand [On/Off: 31084/11 -> 0/1, cluster=0006, TID=D9]
21:06:52.540 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 30 31 30 34 2C 30 31 2C 30 42 2C 30 30 30 36 2C 30 33 3A 11 DA 00 2C 2D 34 31 2C 46 46
21:06:52.551 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 DA 00, rssi=-65, lqi=255]
21:06:52.562 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 DA 00, rssi=-65, lqi=255]
21:06:52.573 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/11, destinationAddress=0/1, profile=0104, cluster=6, addressMode=null, radius=0, sequence=0, payload=11 DA 00]
21:06:52.582 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=218, commandId=0]
21:06:52.589 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: OffCommand [On/Off: 31084/11 -> 0/1, cluster=0006, TID=DA]

It didn't change the state of the switch item attached to the chanel, but it is obviously sending messages đź‘Ť

cdjackson commented 6 years ago

Thanks - this is roughly what I expected (although I’ve not thought through the issue about the 2 button switch). I was expecting to see this response below though, so that’s good. I’ll try and take a better look at this tomorrow and work out what’s next.

Thanks.

On 5 Dec 2017, at 20:24, weakfl notifications@github.com wrote:

Thanks Chris, and sorry for the late reply. I got caught up at the office today...

The new test version was quite a success, but maybe not as expected :)

As I've mentioned I have two relays installed, one with a 1-channel switch attached and one with a 2-channel switch. The 1-channel relay got one new channel, the 2-channel relay got two(!). All are Switch (out) channels.

I created some dummy switch items and started pressing buttons. I think the switches which are turning the relay on/off didn't do anything, but maybe you can take a look at this log https://github.com/openhab/org.openhab.binding.zigbee/files/1532771/zigbee_debug_05122017_2118.log.zip to make sure. There were some TelegesisReceiveMessageEvents, but I think they were unrelated.

However, the second chanel on the 2-channel switch definitely does something:

1:06:50.021 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 30 31 30 34 2C 30 31 2C 30 42 2C 30 30 30 36 2C 30 33 3A 11 D9 01 2C 2D 33 38 2C 46 46 21:06:50.035 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 D9 01, rssi=-56, lqi=255] 21:06:50.049 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 D9 01, rssi=-56, lqi=255] 21:06:50.063 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/11, destinationAddress=0/1, profile=0104, cluster=6, addressMode=null, radius=0, sequence=0, payload=11 D9 01] 21:06:50.075 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=217, commandId=1] 21:06:50.088 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: OnCommand [On/Off: 31084/11 -> 0/1, cluster=0006, TID=D9] 21:06:52.540 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 30 31 30 34 2C 30 31 2C 30 42 2C 30 30 30 36 2C 30 33 3A 11 DA 00 2C 2D 34 31 2C 46 46 21:06:52.551 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 DA 00, rssi=-65, lqi=255] 21:06:52.562 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=260, destinationEp=1, sourceEp=11, clusterId=6, messageData=11 DA 00, rssi=-65, lqi=255] 21:06:52.573 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/11, destinationAddress=0/1, profile=0104, cluster=6, addressMode=null, radius=0, sequence=0, payload=11 DA 00] 21:06:52.582 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=218, commandId=0] 21:06:52.589 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: OffCommand [On/Off: 31084/11 -> 0/1, cluster=0006, TID=DA] It didn't change the state of the switch item attached to the chanel, but it is obviously sending messages đź‘Ť

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zigbee/issues/49#issuecomment-349429802, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_kQ3zCQrSMdXzbzRThsTjuUZ4VrHB8ks5s9aaagaJpZM4Qzpso.

weakfl commented 6 years ago

Chris, any chance you could add the response of the reporting configuration to the log?

I'm wondering if reporting of attribute changes is configured correctly.

Looking at ZclCluster.java, line 296:

return setReporting(attribute, minInterval, maxInterval, null);

null is set as reportableChange.

How can this work? I have to admit I only took a brief look at the docs (quite a read), but here's what puzzles me:

uAttributeReportableChange is the minimum change in the attribute value that will cause an attribute report to be issued


So it might be interesting to check the configuration response to see if it's correct...

cdjackson commented 6 years ago

The responses are already logged.

There are also two different implementations of this - and it depends on what type of command as to what is used. The null on the end is sometimes used - you will see this in the actual implementation of setReporting - it depends if the command is considered an analogue command or not. If we are talking about OnOff, then this is not an analogue command, and the last argument is not used. If we talk about dimmers, then it is -:

clusterOnOff.setOnOffReporting(1, 600); clusterLevelControl.setCurrentLevelReporting(1, 600, 1)

In any case, the response is logged already so you should see the responses in the log (as well as the commands).

On 27 Dec 2017, at 07:09, weakfl notifications@github.com wrote:

Chris, any chance you could add the response of the reporting configuration to the log?

I'm wondering if reporting of attribute changes is configured correctly.

Looking at ZclCluster.java, line 296:

return setReporting(attribute, minInterval, maxInterval, null); null is set as reportableChange.

How can this work? I have to admit I only took a brief look at the docs (quite a read), but here's what puzzles me:

uAttributeReportableChange is the minimum change in the attribute value that will cause an attribute report to be issued

So it might be interesting to check the configuration response to see if it's correct... — You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zigbee/issues/49#issuecomment-354111619, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_kQ3zp3qtaQ6QeG5-J8LyL_Dyq74igks5tEkFygaJpZM4Qzpso.

cdjackson commented 6 years ago

Also, if you look earlier, you can see where I pulled some of the information from your logs, including the responses to these commands -:

2017-12-03 10:04:17.492 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Level Control: 0/0 -> 45692/18, cluster=0008, TID=1B, records=[Attribute Reporting Configuration Record: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, minimumReportingInterval=1, maximumReportingInterval=600, reportableChange=1, timeoutPeriod=0]]
2017-12-03 10:04:18.447 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Level Control: 45692/18 -> 0/0, cluster=0008, TID=1B, records=[Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0, Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0, Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0, Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0]]
weakfl commented 6 years ago

Ok, thanks for clearing that up.

And sorry, I must have missed that. It's in the log:

2017-12-27 15:26:14.603 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Level Control: 31084/18 -> 0/0, cluster=0008, TID=1C, status=null, records=[Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0]]
2017-12-27 15:26:16.017 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [On/Off: 31084/18 -> 0/0, cluster=0006, TID=24, status=null, records=[Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0]]

2017-12-27 15:26:14.817 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [Level Control: 45692/18 -> 0/0, cluster=0008, TID=20, status=null, records=[Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0]]
2017-12-27 15:26:17.081 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ConfigureReportingResponse [On/Off: 45692/18 -> 0/0, cluster=0006, TID=28, status=null, records=[Attribute Status Record: status=SUCCESS, direction=false, attributeIdentifier=0]]

However, the ConfigureReportingCommand for On/Off doesn't seem to set a reportableChange?

2017-12-27 15:26:13.996 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Level Control: 0/0 -> 31084/18, cluster=0008, TID=1C, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=600, reportableChange=1]]]

2017-12-27 15:26:14.289 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [Level Control: 0/0 -> 45692/18, cluster=0008, TID=20, records=[AttributeReportingConfigurationRecord: [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=600, reportableChange=1]]]

2017-12-27 15:26:15.806 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [On/Off: 0/0 -> 31084/18, cluster=0006, TID=24, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=600]]]

2017-12-27 15:26:16.362 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ConfigureReportingCommand [On/Off: 0/0 -> 45692/18, cluster=0006, TID=28, records=[AttributeReportingConfigurationRecord: [attributeDataType=BOOLEAN, attributeIdentifier=0, direction=0, minimumReportingInterval=1, maximumReportingInterval=600]]]
weakfl commented 6 years ago

Sorry, you said that:

If we are talking about OnOff, then this is not an analogue command, and the last argument is not used.

cdjackson commented 6 years ago

No problem - it’s always good when people take a look over things as I can always miss something ;)

I’m just back from holiday this morning so will try and catch up with things over the coming days...

cdjackson commented 6 years ago

I did find a bug in the bind method - I suspect it won't help, but let's see. I'll get this merged in the next day or so - just waiting for another PR for color to be merged first...

weakfl commented 6 years ago

Thanks Chris, I'll let you know if it changes anything. It would be great if the state updates would be immediate, but in the end it isn't much more than an inconvenience if I'm honest. If the battery switches and the other channels on the multi-channel switches would work it would be more beneficial.

Btw, there's a typo in the readme, Busch-Jaegar should be Busch-Jaeger.

cdjackson commented 6 years ago

Thanks. The next version will add faster polling, although it might not help you at the moment as it will speed polling based on responses to the bind/reporting. If these work, then it will use slow polling - if there’s an error then it will increase. I’ll make this configurable at some point.

The switches haven’t been addressed yet, but the underlying code is in the library to handle this so we’ll also add this soon...

cdjackson commented 6 years ago

I've just created a PR to try and receive command responses from the client clusters (ie the switches) - I'd be interested to see if it helps with this issue.

weakfl commented 6 years ago

Great timing, I was going to get a E27 lamp for my other issue this moment, so I'll test this when I'm back.

Does this also mean the 2-channel and battery powered switches should be supported when the PR is merged?

cdjackson commented 6 years ago

Does this also mean the 2-channel and battery powered switches should be supported when the PR is merged?

Yes - at least that's what I'm hoping for at least ;)

If it's not working, a log would be appreciated - I can't fully test this as I've not got any devices :)

weakfl commented 6 years ago

Did you trigger a build yet Chris? Last build on cloudbees is from 15 hours ago.

cdjackson commented 6 years ago

I’ve just triggered it. I’ve had an “on/off” day myself as I’ve been rewiring part of the consumer unit so turn the power off for a while to do some changes, then back on again to allow the UPS to charge… I’m now done for the day :)

On 21 Jan 2018, at 17:37, weakfl notifications@github.com wrote:

Did you trigger a build yet Chris? Last build on cloudbees is from 15 hours ago.

— You are receiving this because you commented. Reply to this email directly, view it on GitHub https://github.com/openhab/org.openhab.binding.zigbee/issues/49#issuecomment-359265671, or mute the thread https://github.com/notifications/unsubscribe-auth/AA_kQzibmUC-uVHJh0014NHoojv_TTWdks5tM3W9gaJpZM4Qzpso.

weakfl commented 6 years ago

Thanks, enjoy the rest of your evening ;)

weakfl commented 6 years ago

A few observations from a first test (still needs more testing):

weakfl commented 6 years ago

I forgot, didn't help with the state update issue unfortunately

cdjackson commented 6 years ago

I think I'll dig out some of my Ubisys devices which I think will look the same with respect to the clusters supported. That will allow me to test the consolidation here as I'm not sure I understand what's going on from your report ;)

So the second channel is the one with no load? Great - that was the main thing this was meant to fix :)

weakfl commented 6 years ago

That will allow me to test the consolidation here as I'm not sure I understand what's going on from your report ;)

Well, the relay was reporting two channels before you introduced channel consolidation (on/off + level). After consolidation on/off was gone and only the level channel was left. Now both channels are back :)

So the second channel is the one with no load? Great - that was the main thing this was meant to fix :)

Yep, the second button on the switch with no load is now working, nice work. Already controlling the terrace awning with it ;)

EDIT:

cdjackson commented 6 years ago

Now both channels are back :)

Strange - so there is an on/off and a dimmer channel? I'll try and set up one a device here that might allow me to test at least a bit.

weakfl commented 6 years ago

Strange - so there is an on/off and a dimmer channel?

Yep. We've talked about this, my guess is that BJ is using the same firmware for the simple and the dimmable relays, maybe with some minor modifications. It doesn't make much sense, both channels are just switching the relay on and off.

Btw, I've ordered one of the dimmable relays too. I guess it should work out of the box, but I'll let you know.