Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Exception processing Telegesis frame #53

Closed
weakfl opened this issue Dec 8, 2017 · 10 comments
Closed

Exception processing Telegesis frame #53

weakfl opened this issue Dec 8, 2017 · 10 comments

Comments

@weakfl
Copy link
Contributor

weakfl commented Dec 8, 2017

Hey Chris, wasn't sure if this is of interest for you but I figured you can always close the issue if it isn't 😉

This came up in the log today playing around with the latest nightly version of the binding (2.2.0.201712080732):

12:35:43.921 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=260, destinationEp=0, sourceEp=10, clusterId=25, messageData=10 19 01 02 00 86, rssi=-97, lqi=255]
12:35:43.939 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=260, destinationEp=0, sourceEp=10, clusterId=25, messageData=10 19 01 02 00 86, rssi=-97, lqi=255]
12:35:43.957 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/10, destinationAddress=0/0, profile=0104, cluster=25, addressMode=null, radius=0, sequence=0, payload=10 19 01 02 00 86]
12:35:43.973 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=25, commandId=1]
12:35:43.994 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [OTA Upgrade: 45692/10 -> 0/0, cluster=0019, TID=19, records=[Read Attribute Status Record: attributeDataType=null, attributeIdentifier=2, status=134, attributeValue=null]]
12:35:44.036 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - D85DEF11A1002826: OTA firmware request timeout
12:35:44.047 [DEBUG] [iscovery.ZigBeeNodePropertyDiscoverer] - 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=[RECHARGABLE_BATTERY, DISPOSABLE_BATTERY, MAINS], hardwareVersion=0}
12:35:44.082 [DEBUG] [gbee.discovery.ZigBeeDiscoveryService] - D85DEF11A1002826: Update ZigBee device zigbee:device with bridge zigbee:coordinator_telegesis:49455deb
12:36:07.678 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 43 30 35 45 2C 30 31 2C 31 32 2C 30 30 30 36 2C 30 37 3A 18 D9 0A 00 00 10 00 2C 2D 34 36 2C 46 46
12:36:07.717 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 D9 0A 00 00 10 00, rssi=-70, lqi=255]
12:36:07.749 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 D9 0A 00 00 10 00, rssi=-70, lqi=255]
12:36:07.769 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/18, destinationAddress=0/1, profile=C05E, cluster=6, addressMode=null, radius=0, sequence=0, payload=18 D9 0A 00 00 10 00]
12:36:07.788 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Exception processing Telegesis frame: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 D9 0A 00 00 10 00, rssi=-70, lqi=255]: 
java.lang.ArrayIndexOutOfBoundsException: 7
    at com.zsmartsystems.zigbee.serialization.DefaultDeserializer.readZigBeeType(DefaultDeserializer.java:170) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.zcl.ZclFieldDeserializer.deserialize(ZclFieldDeserializer.java:79) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.zdo.command.MatchDescriptorRequest.deserialize(MatchDescriptorRequest.java:205) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.ZigBeeNetworkManager.receiveZdoCommand(ZigBeeNetworkManager.java:595) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.ZigBeeNetworkManager.receiveCommand(ZigBeeNetworkManager.java:550) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.dongle.telegesis.ZigBeeDongleTelegesis.telegesisEventReceived(ZigBeeDongleTelegesis.java:573) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisFrameHandler.notifyEventReceived(TelegesisFrameHandler.java:364) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisFrameHandler.access$300(TelegesisFrameHandler.java:38) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
    at com.zsmartsystems.zigbee.dongle.telegesis.internal.TelegesisFrameHandler$1.run(TelegesisFrameHandler.java:125) [206:org.openhab.binding.zigbee:2.2.0.201712080732]
12:36:07.908 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 43 30 35 45 2C 30 31 2C 31 32 2C 30 30 30 38 2C 30 37 3A 18 DA 0A 00 00 20 01 2C 2D 35 35 2C 46 46
12:36:07.925 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 DA 0A 00 00 20 01, rssi=-85, lqi=255]
12:36:07.945 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 DA 0A 00 00 20 01, rssi=-85, lqi=255]
12:36:07.991 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/18, destinationAddress=0/1, profile=C05E, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 DA 0A 00 00 20 01]
12:36:08.008 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - Incoming message did not translate to command.
12:36:17.578 [DEBUG] [stems.zigbee.ZigBeeNetworkMeshMonitor] - 0: Starting mesh update
@cdjackson
Copy link
Contributor

Yep - certainly of interest and I will take a look at this tomorrow - should be easy to solve as you've provided all the information I think I should need :)

This was referenced Dec 8, 2017
Merged
Merged
@cdjackson
Copy link
Contributor

zsmartsystems/com.zsmartsystems.zigbee#149

@cdjackson
Copy link
Contributor

I hope this should be fixed - the build is in progress at the moment.

@weakfl
Copy link
Contributor Author

weakfl commented Dec 8, 2017

Nice, thanks. I‘ll keep an eye on the log when the new build is available.

@weakfl
Copy link
Contributor Author

weakfl commented Dec 9, 2017

Just wanted to confirm this is now fixed (profile=C05E):

12:16:14.877 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 F5 0A 00 00 10 00, rssi=-72, lqi=255]
12:16:14.897 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/18, destinationAddress=0/1, profile=C05E, cluster=6, addressMode=null, radius=0, sequence=0, payload=18 F5 0A 00 00 10 00]
12:16:14.916 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=245, commandId=10]
12:16:14.937 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 31084/18 -> 0/1, cluster=0006, TID=F5, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
12:16:14.957 [DEBUG] [.converter.ZigBeeConverterSwitchOnoff] - D85DEF11A1001973: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false]
12:16:14.963 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 37 39 36 43 2C 43 30 35 45 2C 30 31 2C 31 32 2C 30 30 30 38 2C 30 37 3A 18 F6 0A 00 00 20 01 2C 2D 34 38 2C 46 46
12:16:14.991 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 F6 0A 00 00 20 01, rssi=-72, lqi=255]
12:16:15.011 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=31084, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 F6 0A 00 00 20 01, rssi=-72, lqi=255]
12:16:15.030 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/18, destinationAddress=0/1, profile=C05E, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 F6 0A 00 00 20 01]
12:16:15.047 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=246, commandId=10]
12:16:15.067 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 31084/18 -> 0/1, cluster=0008, TID=F6, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=1]]
12:16:15.087 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=1] from D85DEF11A1001973
12:16:26.441 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 42 32 37 43 2C 43 30 35 45 2C 30 31 2C 31 32 2C 30 30 30 36 2C 30 37 3A 18 E1 0A 00 00 10 00 2C 2D 35 35 2C 46 46
12:16:26.473 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 E1 0A 00 00 10 00, rssi=-85, lqi=255]
12:16:26.513 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 E1 0A 00 00 10 00, rssi=-85, lqi=255]
12:16:26.551 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/1, profile=C05E, cluster=6, addressMode=null, radius=0, sequence=0, payload=18 E1 0A 00 00 10 00]
12:16:26.583 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=225, commandId=10]
12:16:26.603 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=E1, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
12:16:26.622 [DEBUG] [.converter.ZigBeeConverterSwitchOnoff] - D85DEF11A1002826: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false]
12:16:26.623 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 42 32 37 43 2C 43 30 35 45 2C 30 31 2C 31 32 2C 30 30 30 38 2C 30 37 3A 18 E2 0A 00 00 20 FE 2C 2D 35 35 2C 46 46
12:16:26.655 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 E2 0A 00 00 20 FE, rssi=-85, lqi=255]
12:16:26.675 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 E2 0A 00 00 20 FE, rssi=-85, lqi=255]
12:16:26.694 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/1, profile=C05E, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 E2 0A 00 00 20 FE]
12:16:26.711 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=226, commandId=10]
12:16:26.731 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 45692/18 -> 0/1, cluster=0008, TID=E2, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]
12:16:26.751 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254] from D85DEF11A1002826

@cdjackson
Copy link
Contributor

cdjackson commented Dec 9, 2017 via email

@weakfl
Copy link
Contributor Author

weakfl commented Dec 9, 2017

Thanks. Does this help at all with the other issue?

Yes and no, it's kind of strange. Maybe you can make sense of it, because I really can't 😞

  1. Used OH App to turn the relay ON:
13:27:21.441 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'LivingroomLights1' received command ON
13:27:21.444 [DEBUG] [ing.zigbee.handler.ZigBeeThingHandler] - D85DEF11A1002826: Command for channel zigbee:device:49455deb:d85def11a1002826:D85DEF11A1002826_18_switch_onoff --> ON
13:27:21.468 [INFO ] [smarthome.event.ItemStateChangedEvent] - LivingroomLights1 changed from OFF to ON
13:27:21.505 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX CMD: OnCommand [On/Off: 0/0 -> 45692/18, cluster=0006, TID=0F]
13:27:21.538 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=15, commandId=1]
13:27:21.560 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0/1, destinationAddress=45692/18, profile=0104, cluster=6, addressMode=DEVICE, radius=31, sequence=15, payload=01 0F 01]
13:27:21.579 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis send: TelegesisSendUnicastCommand [address=45692, sourceEp=0, destEp=18, profileId=260, clusterId=6, messageData=01 0F 01, messageId=null]
13:27:21.599 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TX Telegesis queue: 1
13:27:21.612 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS TX: Data 41 54 2B 53 45 4E 44 55 43 41 53 54 42 3A 30 33 2C 42 32 37 43 2C 30 30 2C 31 32 2C 30 31 30 34 2C 30 30 30 36 0D 01 0F 01 0D 0A
13:27:21.786 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 53 45 51 3A 35 30
13:27:21.795 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 4F 4B
13:27:21.805 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis command complete: TelegesisSendUnicastCommand [address=45692, sourceEp=0, destEp=18, profileId=260, clusterId=6, messageData=01 0F 01, messageId=80, status=SUCCESS]
13:27:21.825 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 41 43 4B 3A 35 30
13:27:21.836 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisAckMessageEvent [messageId=80]
13:27:21.848 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisAckMessageEvent [messageId=80]
13:27:21.860 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Unhandled Telegesis Frame: TelegesisAckMessageEvent [messageId=80]
13:27:21.875 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 42 32 37 43 2C 30 31 30 34 2C 30 30 2C 31 32 2C 30 30 30 36 2C 30 35 3A 18 0F 0B 01 00 2C 2D 35 36 2C 46 46
13:27:21.891 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=260, destinationEp=0, sourceEp=18, clusterId=6, messageData=18 0F 0B 01 00, rssi=-86, lqi=255]
13:27:21.912 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=260, destinationEp=0, sourceEp=18, clusterId=6, messageData=18 0F 0B 01 00, rssi=-86, lqi=255]
13:27:21.931 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/0, profile=0104, cluster=6, addressMode=null, radius=0, sequence=0, payload=18 0F 0B 01 00]
13:27:21.950 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=15, commandId=11]
13:27:21.971 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [On/Off: 45692/18 -> 0/0, cluster=0006, TID=0F, commandIdentifier=1, statusCode=SUCCESS]

  1. Used the physical switch to turn the relay OFF:

    • Item state not updated
    • Nothing in the log

  2. Waited a few minutes if something turns up in the log, but didn't

  3. Used physical switch to turn relay ON and OFF:

13:36:26.783 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 F1 0A 00 00 10 00, rssi=-89, lqi=255]
13:36:26.822 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=6, messageData=18 F1 0A 00 00 10 00, rssi=-89, lqi=255]
13:36:26.843 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/1, profile=C05E, cluster=6, addressMode=null, radius=0, sequence=0, payload=18 F1 0A 00 00 10 00]
13:36:26.861 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=241, commandId=10]
13:36:26.882 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=F1, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
13:36:26.905 [DEBUG] [.converter.ZigBeeConverterSwitchOnoff] - D85DEF11A1002826: ZigBee attribute reports ZclAttribute [cluster=ON_OFF, id=0, name=OnOff, dataType=BOOLEAN, lastValue=false]
13:36:26.907 [DEBUG] [egesis.internal.TelegesisFrameHandler] - TELEGESIS RX: Data 52 58 3A 42 32 37 43 2C 43 30 35 45 2C 30 31 2C 31 32 2C 30 30 30 38 2C 30 37 3A 18 F2 0A 00 00 20 FE 2C 2D 36 30 2C 46 46
13:36:26.933 [INFO ] [smarthome.event.ItemStateChangedEvent] - LivingroomLights1 changed from ON to OFF
13:36:26.947 [DEBUG] [egesis.internal.TelegesisFrameHandler] - Telegesis event received: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 F2 0A 00 00 20 FE, rssi=-96, lqi=255]
13:36:26.970 [DEBUG] [ongle.telegesis.ZigBeeDongleTelegesis] - Telegesis RX: TelegesisReceiveMessageEvent [ieeeAddress=null, networkAddress=45692, profileId=49246, destinationEp=1, sourceEp=18, clusterId=8, messageData=18 F2 0A 00 00 20 FE, rssi=-96, lqi=255]
13:36:26.990 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=45692/18, destinationAddress=0/1, profile=C05E, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 F2 0A 00 00 20 FE]
13:36:27.009 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=242, commandId=10]
13:36:27.029 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 45692/18 -> 0/1, cluster=0008, TID=F2, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]
13:36:27.050 [DEBUG] [.converter.ZigBeeConverterSwitchLevel] - ZigBee attribute reports ZclAttribute [cluster=LEVEL_CONTROL, id=0, name=CurrentLevel, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=254] from D85DEF11A1002826
13:36:29.154 [DEBUG] [gbee.internal.ZigBeeNetworkDiscoverer] - 51223: Discovery request IEEE_ADDRESS failed. Wait before retry.
  1. Item state in OH APP now updated to OFF !!!

I think the events are not related to pressing the physical switch but are just random status updates sent by the relay.

I have the same messages from the other relay (note the sourceAddress is different), and I didn't touch the switch of that relay at all:

13:46:15.413 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=31084/18, destinationAddress=0/1, profile=C05E, cluster=8, addressMode=null, radius=0, sequence=0, payload=18 08 0A 00 00 20 01]
13:46:15.432 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=8, commandId=10]

Same from the relay I used for testing (again, didn't touch it since the pervious event 10 minutes ago):

13:46:26.935 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=243, commandId=10]
13:46:26.956 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=F3, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]

@weakfl
Copy link
Contributor Author

weakfl commented Dec 9, 2017 •
edited
Loading

I just noticed these status updates seem to occur every 10 minutes from both relays.
Log entries from my "testing" relay:

13:26:26.876 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=EF, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
13:26:27.019 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 45692/18 -> 0/1, cluster=0008, TID=F0, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]

13:36:26.882 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=F1, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
13:36:27.029 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 45692/18 -> 0/1, cluster=0008, TID=F2, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]

13:46:26.956 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=F3, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
13:46:27.094 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 45692/18 -> 0/1, cluster=0008, TID=F4, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]

13:56:26.965 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [On/Off: 45692/18 -> 0/1, cluster=0006, TID=F5, reports=[Attribute Report: attributeDataType=BOOLEAN, attributeIdentifier=0, attributeValue=false]]
13:56:27.097 [DEBUG] [rtsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 45692/18 -> 0/1, cluster=0008, TID=F6, reports=[Attribute Report: attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]

This also explains the behaviour described in my previous post, just look at the timestamps...

@cdjackson
Copy link
Contributor

cdjackson commented Dec 9, 2017 via email

@weakfl
Copy link
Contributor Author

weakfl commented Dec 9, 2017

Exactly and it's definitely progress as it works for both states, ON and OFF.

Just turned they relay on via physical switch, waited for the status update at 14:16 -> item state successfully updated in OH.

saukijan pushed a commit to Hahn-Schickard/org.openhab.binding.zigbee that referenced this issue Dec 11, 2017
@cdjackson
Change ZDO response matcher to use NWKAddrOfInterest where available (o…
e5acf06 
…penhab#53)

Signed-off-by: Chris Jackson <chris@cd-jackson.com>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@weakfl @cdjackson