New channel discovery mechanism bugs

[openhab]

New channel discovery mechanism bugs

[cdjackson]

Here is the log where the dongle was offline, but messages were still happening in the background:

Can you confirm that the dongle was offline, but the devices were online? Seems a bit strange. The log is very short so all I can really confirm is there is communications occuring, but I wouldn't expect ESH to pass commands to the ThingHander if it was offline.

Here is an example of the binding trying to communicate with my Hue motion sensor:

There's not much I can say about this - the device is not responding. The sensor seems to be connected to the network via another router (ie not the dongle).
Please can you provide a log that is longer than 1 second - this is a battery device which is sleeping, so at least 10 seconds is needed.

[AfromD]

I am absolutely sure that the dongle was showing offline, not 100% sure about devices.

Although the Hue Motion thing is showing "offline" in paperui, illuminance values seem to be sometimes getting through, as they sometimes shown in paperui and always turn up in the log. The Hue sensor has the habit to update the illuminance on motion, and it still does that. Trigger motion, and no motion shows up in the log, but an updated illuminance reading.

2018-02-15 13:05:42.704 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=10749]
2018-02-15 13:05:42.707 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=10749]
2018-02-15 13:05:42.707 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=10749]
2018-02-15 13:05:42.708 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3]
2018-02-15 13:05:44.172 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=0, reTx=false, data=2F 90 80 A9 FD 29]
2018-02-15 13:05:44.173 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=10749]
2018-02-15 13:05:44.173 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=10749]
2018-02-15 13:05:44.173 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteErrorHandler [status=EMBER_SOURCE_ROUTE_FAILURE, target=10749]
2018-02-15 13:05:44.174 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4]
2018-02-15 13:05:45.250 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=0, reTx=false, data=2F 90 59 82 A2 53 C1 01 02 01 88 17 00 FF AF 02 0F 47 6B 82]
2018-02-15 13:05:45.253 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingRouteRecordHandler [source=41602, sourceEui=001788010201C153, lastHopLqi=255, lastHopRssi=-81, relayList=0F 47]
2018-02-15 13:05:45.254 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingRouteRecordHandler [source=41602, sourceEui=001788010201C153, lastHopLqi=255, lastHopRssi=-81, relayList=0F 47]
2018-02-15 13:05:45.257 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - Unhandled EZSP Frame: EzspIncomingRouteRecordHandler [source=41602, sourceEui=001788010201C153, lastHopLqi=255, lastHopRssi=-81, relayList=0F 47]
2018-02-15 13:05:45.258 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5]
2018-02-15 13:05:45.266 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=0, reTx=false, data=2F 90 45 00 04 01 00 04 02 01 00 01 00 00 C5 FF AF 82 A2 FF FF 08 08 1C 0A 00 00 21 07 0F 06]
2018-02-15 13:05:45.268 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=1024, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=197], lastHopLqi=255, lastHopRssi=-81, sender=41602, bindingIndex=255, addressIndex=255, messageContents=08 1C 0A 00 00 21 07 0F]
2018-02-15 13:05:45.270 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=260, clusterId=1024, sourceEndpoint=2, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=197], lastHopLqi=255, lastHopRssi=-81, sender=41602, bindingIndex=255, addressIndex=255, messageContents=08 1C 0A 00 00 21 07 0F]
2018-02-15 13:05:45.272 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=41602/2, destinationAddress=0/1, profile=0104, cluster=1024, addressMode=null, radius=0, sequence=47, payload=08 1C 0A 00 00 21 07 0F]
2018-02-15 13:05:45.273 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=28, commandId=10]
2018-02-15 13:05:45.276 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Illuminance measurement: 41602/2 -> 0/1, cluster=0400, TID=1C, reports=[Attribute Report: attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=0, attributeValue=3847]]

[AfromD]

I also find spurious occupancy sensing logs, but they are not complete.

So it very much looks like the motion sensor is doing its job, but it is not getting passed on to OH. Offline in paperui, no update of status in paperui, and no rules triggered on motion.

2018-02-15 13:24:36.876 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=5, reTx=false, data=94 90 45 04 04 01 06 04 02 FF 08 00 00 00 45 DD A3 82 A2 FF FF 07 18 3A 0A 00 00 18 00 08]
2018-02-15 13:24:36.877 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - RX EZSP: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=260, clusterId=1030, sourceEndpoint=2, destinationEndpoint=255, options=[], groupId=0, sequence=69], lastHopLqi=221, lastHopRssi=-93, sender=41602, bindingIndex=255, addressIndex=255, messageContents=18 3A 0A 00 00 18 00]
2018-02-15 13:24:36.878 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX: EzspIncomingMessageHandler [type=EMBER_INCOMING_BROADCAST, apsFrame=EmberApsFrame [profileId=260, clusterId=1030, sourceEndpoint=2, destinationEndpoint=255, options=[], groupId=0, sequence=69], lastHopLqi=221, lastHopRssi=-93, sender=41602, bindingIndex=255, addressIndex=255, messageContents=18 3A 0A 00 00 18 00]
2018-02-15 13:24:36.879 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=41602/2, destinationAddress=0/255, profile=0104, cluster=1030, addressMode=null, radius=0, sequence=148, payload=18 3A 0A 00 00 18 00]
2018-02-15 13:24:36.880 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=58, commandId=10]
2018-02-15 13:24:36.881 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Occupancy sensing: 41602/2 -> 0/255, cluster=0406, TID=3A, reports=[Attribute Report: attributeDataType=BITMAP_8_BIT, attributeIdentifier=0, attributeValue=0]]
2018-02-15 13:24:36.883 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0]

[AfromD]

Here's a 10 minute log around above snippet
10minlog.txt

[cdjackson]

I am absolutely sure that the dongle was showing offline, not 100% sure about devices.

I thought that when a bridge goes offline, that ESH also takes the things attached to the bridge offline as well - maybe not though (although it seems strange not to).

So it very much looks like the motion sensor is doing its job, but it is not getting passed on to OH

What channels are created for the device?

Here's a 10 minute log around above snippets

Thanks. I'll take a detailed look at this

[AfromD]

zigbee:device:3e5f29cf:001788010201C153:001788010201C153_1_switch_onoff
zigbee:device:3e5f29cf:001788010201C153:001788010201C153_2_battery_level
zigbee:device:3e5f29cf:001788010201C153:001788010201C153_2_measurement_illuminance
zigbee:device:3e5f29cf:001788010201C153:001788010201C153_2_measurement_temperature
zigbee:device:3e5f29cf:001788010201C153:001788010201C153_2_sensor_occupancy

[cdjackson]

Here's a 10 minute log around above snippet

Is this log filtered in some way? Do any channels at all update their values? It's a slightly strange log.

[AfromD]

No it's not filtered. When I control lights, the state is updated in paperui. The motion sensor is not updated and its thing is shown as offline. everything else (under power) is shown as online.

[cdjackson]

Can you provide a longer log - complete with initialisation. At the moment I'm second guessing what's happening with the short logs. Thanks.

[AfromD]

I have restarted OH and now I am getting these entries for three devices:

2018-02-15 23:24:41.927 [DEBUG] [internal.ZigBeeNodeServiceDiscoverer] - 001788010201C153: Node service discovery request NEIGHBORS failed. Retry 40, wait 73610ms before retry.

Two devices are actually offline, since they have no power, and the third is the Hue motion sensor.

What is a bit strange, is that these devices are now all shown as "online" in Paperui. Since the two lamps have been off power since before the restart, there is no possibility that they have been online since the restart. They both show a "dimmer" as the only channel. The Hue motion sensor shows the 5 channels as above.

Contrary to before, the Hue motion sensor now doesn't log any motion or luminance events.
openhab.log

[AfromD]

I have now completely removed the thing, restarted OH. After that, OH wouldn't put the motion sensor in the inbox any more. After rejoining it via a reset of the motion sensor, OH is communicating with it, but it is not getting any channels.
Huenewjoin.txt

[cdjackson]

Can you tell me what the different devices are -:
1150
9093
18191
27819
29299
33387
41602
45202
48977

[AfromD]

1150 Osram smart+ switchable outlet
9093 Hue white and color E14 bulb
18191 Trust color E27 bulb
27819 Hue white and color E27 bulb
29299 Hue white and color E14 bulb
33387 Hue white and color LED strip
41602 Seems to be an older instance of the Hue motion sensor
45202 Couldn't find anything in old logs
48977 Trust color E27 bulb (not powered at time of the log)

[AfromD]

Updated to the newest version just now, and Hue motion sensor is now found. Voltage channel seems to be working. There is an unclear switch channel, which results in an error in the log. I think it is something that Philips uses for settings, this might be what #100 is referring to.

2018-02-21 14:12:05.999 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010201C153: Command for channel zigbee:device:3e5f29cf:001788010201c153:001788010201C153_1_switch_onoff --> ON
2018-02-21 14:12:06.000 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 001788010201C153: Exception sending command to channel zigbee:device:3e5f29cf:001788010201c153:001788010201C153_1_switch_onoff
java.lang.NullPointerException: null
	at org.openhab.binding.zigbee.internal.converter.ZigBeeConverterSwitchOnoff.handleCommand(ZigBeeConverterSwitchOnoff.java:139) [270:org.openhab.binding.zigbee:2.2.0.201802192145]
	at org.openhab.binding.zigbee.handler.ZigBeeThingHandler$3.run(ZigBeeThingHandler.java:432) [270:org.openhab.binding.zigbee:2.2.0.201802192145]
	at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [?:?]
	at java.util.concurrent.FutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Unknown Source) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [?:?]
	at java.lang.Thread.run(Unknown Source) [?:?]

[AfromD]

With the 2.3 version from februari 26th, Hue motion sensor shows as offline again.

[cdjackson]

Please provide more information. It's probably not related to the version, but possibly the device is leaving the network. Hard to comment without information though.

[AfromD]

Sorry, didn't investigate further, was working with grafana and noticed it disappeared since I changed to the new binding. It's there now after another restart. Maybe there was a conflict, didn't uninstall the older version in karaf first time I updated the binding.

[cdjackson]

I propose to close this as it is 18 months old and there have been a lot of changes in the binding and underlying libraries.

If the problem persists then I'd probably suggest to open a new issue unless it is clear that it is exactly the same.