Issues with zigbee binding - status undef

supersjel · December 31, 2024, 11:44am

Hi,

I got an issue with the Zigbee binding using a USB Popp USB-stick. It started after the upgrade to 4.3. Can of course be a coincidence since it also upgrades the PI itself and I reboot it just to be sure.

All devices can be controlled normally but reported every 1 or 2 hours a random state. Think a light said it turned on, while actually stayed off. So only OH thought something changed. Since I got rules and sensors using this states, I performed a downgrade to 4.2.3. This somewhat improved the situation but weird behavior regarding the state remained.

The easy way to reproduce strange things is a light with a switch, color temperature and a dimmer (Lidl light).

Start with color temperature 100, turn on, dimmer to 20. Settings are applied and OH shows them.
Now change the color temperature to 90. Setting is applied but OH changes switch and dimmer to UNDEF.
Now turn on switch. Setting is applied but OH shows ON and dimmer 100 (while it still is using the 20)…

So my best guess: something wrong with reading status and the 2 channels. Something similar happens for color lights.

Anyone noticed this behavior? Or had a hint what to try?

I tried initializing the devices. Changed settings on zigbee controller (network size, hardware rts, transmitting power) and settings on the test light (standard to follow, auto to XY). But none of this tweaks helped.

edit: Found this simular issue (2022), but forcing the autoupdate in the item doesn’t solve it.

chris · December 31, 2024, 7:11pm

Please provide a debug log file - this is only “easy to reproduce” if I have these devices - the log file should show what’s happening on your system…

supersjel · January 1, 2025, 12:57pm

Hi @chris

First of all best wishes. Working on it. setting the log level using the GUI killed the functionality for all add-ons (blanc screens now). I’ll check if another reboot revives it. Or maybe use the console.

edit: Nope, killed the entire log system. OH runs but produces no more logging at all.

edit 2: bugger, even redoing the upgrade doesn’t solve it. Seems changes the loglevel permanently destroyed the log system. Will look into console commands but have low hopes now.

edit 3: Ok, might be another bug. Found this post about the log4j2.xml file becoming corrupt. Same here (it ended with Configuration>ation>), so applied solution and now OH is logging again. Enough madness for today, will try again to get zigbee logging tomorrow.

2025-01-01 13:47:15.172 [ERROR] [internal.JSONResponseExceptionMapper] - Unexpected exception occurred while processing REST request.
java.lang.RuntimeException: Unable to set level for logger
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.setLevel(LogServiceLog4j2XmlImpl.java:139) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceImpl.setLevel(LogServiceImpl.java:114) ~[?:?]
        at org.openhab.core.karaf.internal.LoggerResource.putLoggers(LoggerResource.java:106) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
        at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:569) ~[?:?]
        at org.apache.cxf.service.invoker.AbstractInvoker.performInvocation(AbstractInvoker.java:179) ~[bundleFile:3.6.2]
        at org.apache.cxf.service.invoker.AbstractInvoker.invoke(AbstractInvoker.java:96) ~[bundleFile:3.6.2]
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:201) ~[bundleFile:3.6.2]
        at org.apache.cxf.jaxrs.JAXRSInvoker.invoke(JAXRSInvoker.java:104) ~[bundleFile:3.6.2]
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor$1.run(ServiceInvokerInterceptor.java:59) ~[bundleFile:3.6.2]
        at org.apache.cxf.interceptor.ServiceInvokerInterceptor.handleMessage(ServiceInvokerInterceptor.java:96) ~[bundleFile:3.6.2]
        at org.apache.cxf.phase.PhaseInterceptorChain.doIntercept(PhaseInterceptorChain.java:307) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.ChainInitiationObserver.onMessage(ChainInitiationObserver.java:121) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.http.AbstractHTTPDestination.invoke(AbstractHTTPDestination.java:265) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.servlet.ServletController.invokeDestination(ServletController.java:234) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:208) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.servlet.ServletController.invoke(ServletController.java:160) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.servlet.CXFNonSpringServlet.invoke(CXFNonSpringServlet.java:225) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.handleRequest(AbstractHTTPServlet.java:304) ~[bundleFile:3.6.2]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.doPut(AbstractHTTPServlet.java:234) ~[bundleFile:3.6.2]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:520) ~[bundleFile:4.0.4]
        at org.apache.cxf.transport.servlet.AbstractHTTPServlet.service(AbstractHTTPServlet.java:279) ~[bundleFile:3.6.2]
        at org.ops4j.pax.web.service.spi.servlet.OsgiInitializedServlet.service(OsgiInitializedServlet.java:102) ~[bundleFile:?]
        at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:799) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.servlet.ServletHandler$ChainEnd.doFilter(ServletHandler.java:1656) ~[bundleFile:9.4.54.v20240208]
        at org.ops4j.pax.web.service.spi.servlet.OsgiFilterChain.doFilter(OsgiFilterChain.java:113) ~[bundleFile:?]
        at org.ops4j.pax.web.service.jetty.internal.PaxWebServletHandler.doHandle(PaxWebServletHandler.java:334) ~[bundleFile:?]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:143) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:600) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:235) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1624) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:233) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1440) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:188) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:505) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1594) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:186) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1355) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:234) ~[bundleFile:9.4.54.v20240208]
        at org.ops4j.pax.web.service.jetty.internal.PrioritizedHandlerCollection.handle(PrioritizedHandlerCollection.java:96) ~[bundleFile:?]
        at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:722) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:127) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.Server.handle(Server.java:516) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpChannel.lambda$handle$1(HttpChannel.java:487) ~[bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:732) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:479) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:277) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883) [bundleFile:9.4.54.v20240208]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034) [bundleFile:9.4.54.v20240208]
        at java.lang.Thread.run(Thread.java:840) [?:?]
Caused by: org.xml.sax.SAXParseException: Premature end of file.
        at com.sun.org.apache.xerces.internal.parsers.DOMParser.parse(DOMParser.java:262) ~[?:?]
        at com.sun.org.apache.xerces.internal.jaxp.DocumentBuilderImpl.parse(DocumentBuilderImpl.java:342) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.loadConfig(LogServiceLog4j2XmlImpl.java:229) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.loadConfig(LogServiceLog4j2XmlImpl.java:209) ~[?:?]
        at org.apache.karaf.log.core.internal.LogServiceLog4j2XmlImpl.setLevel(LogServiceLog4j2XmlImpl.java:98) ~[?:?]
        ... 56 more

chris · January 1, 2025, 7:28pm

Happy New Year

I think I saw someone else had this issue. It was caused by a corrupted log4j2.xml file if I remember correctly.

supersjel · January 2, 2025, 9:24am

Goodmorning @chris! Yeah, found that post. It seems to me that the GUI has trouble with the zigbee because the class names overlap. This time I changed settings one by one and noticed that (for example) changing the org.openhab.binding.zigbee also changes a bunch of others in deeper classes. I suspect if you change them all at the same time (as I did before) they interfere.

Back to my issue. Since I upgraded again in an attempt to fix the logs, I also retested my bug. So on 4.3.1 the channels on a light work perfect. So when changing one of the items color temperature, color, dimmer or switch doesn’t make the others UNDEF. However the original bug that made me downgrade returns. The lights get random states, so a switch might show as ON while no command was issued. In fact, even though it’s shown as ON the light in fact remains OFF. This happens for all light bulbs with color temperature or dimmer capability. If it is only a switch on/off type it’s ok. The rule controlling lights was disabled, since all these false readings made it actually turn on lights at night. And maybe more interesting, there are different patterns in the fake ON/OFF states. Most of them seem periodic. As a double check, none of them match with the period/timings of the disabled rule.

When downgrading to 4.2.x this behavior disappears so I suspect this is a new bug. I kept the log for the little testscenario I used in the start of the post. But for now I turned of all lights and will wait for a fake turn on and see if something shows in the log. I assume you prefer the fix the current version. Maybe it’s also related to another post about Google Assistent issues. I read due to increased traffic on the cloud services. All these fake states also show in Google Home. So maybe this traffic increase is related.

Got one. So it thinks at 2025-01-02 09:52:05.147 the color is updated (it’s a RGB led string) and decides it must be turned on. The bug could be … if I look at the items the switch is now ON but bot color and dimmer item remain empty. Maybe they should be updated too? Else the next time the zigbee light sends its status OH thinks again it is a change of value?

I’ll perform one more test on this version. I’ll set the color/dimmer channel myself and see if it keeps getting fake states.

edit : that’s a nono. Changing color doesn’t work on the ledstrip. So that makes the next step a downgrade again.

events.log:
2025-01-02 09:52:05.150 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Inloopkast_Switch' updated to ON
2025-01-02 09:52:05.151 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Inloopkast_Switch' changed from OFF to ON

openhab.log
2025-01-02 09:52:05.120 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: FA
2025-01-02 09:52:05.120 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: DE
2025-01-02 09:52:05.121 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 79
2025-01-02 09:52:05.121 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 83
2025-01-02 09:52:05.121 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: FC
2025-01-02 09:52:05.122 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 7D
2025-01-02 09:52:05.130 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 5E
2025-01-02 09:52:05.130 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 1F
2025-01-02 09:52:05.131 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 94
2025-01-02 09:52:05.131 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: ED
2025-01-02 09:52:05.131 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 0D
2025-01-02 09:52:05.132 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 97
2025-01-02 09:52:05.132 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX: 7E
2025-01-02 09:52:05.133 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=83 90 01 45 00 00 04 01 08 00 01 01 40 01 00 00 5D 74 B9 5C A9 FF FF 07 18 1A 0A 00 00 20 33 06]
2025-01-02 09:52:05.133 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0008, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5D], lastHopLqi=116, lastHopRssi=-71, sender=A95C, bindingIndex=255, addressIndex=255, messageContents=18 1A 0A 00 00 20 33]
2025-01-02 09:52:05.134 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH added EZSP frame to receive queue. Queue length 1
2025-01-02 09:52:05.134 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH took EZSP frame from receive queue. Queue length 0
2025-01-02 09:52:05.134 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2025-01-02 09:52:05.135 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH TX: 84
2025-01-02 09:52:05.135 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH TX: 30
2025-01-02 09:52:05.135 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0008, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=5D], lastHopLqi=116, lastHopRssi=-71, sender=A95C, bindingIndex=255, addressIndex=255, messageContents=18 1A 0A 00 00 20 33]
2025-01-02 09:52:05.135 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH TX: FC
2025-01-02 09:52:05.136 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH TX: 7E
2025-01-02 09:52:05.137 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=A95C/1, destinationAddress=0000/1, profile=0104, cluster=0008, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=5D, rssi=-71, lqi=74, payload=18 1A 0A 00 00 20 33]
2025-01-02 09:52:05.138 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 588E81FFFEFBD897: Node update. NWK Address=NULL
2025-01-02 09:52:05.139 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 588E81FFFEFBD897: Node A95C is not updated from ZigBeeNode [state=ONLINE, IEEE=588E81FFFEFBD897, NWK=----, endpoints=[]]
2025-01-02 09:52:05.139 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=1A, commandId=10]
2025-01-02 09:52:05.140 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: A95C/1 -> 0000/1, cluster=0008, TID=1A, reports=[AttributeReport [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=51]]]
2025-01-02 09:52:05.142 [TRACE] [com.zsmartsystems.zigbee.ZigBeeNode ] - 588E81FFFEFBD897: ZigBeeNode.commandReceived(ReportAttributesCommand [Level Control: A95C/1 -> 0000/1, cluster=0008, TID=1A, reports=[AttributeReport [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=51]]])
2025-01-02 09:52:05.143 [TRACE] [.zsmartsystems.zigbee.ZigBeeEndpoint] - 588E81FFFEFBD897: Endpoint 1. ZigBeeEndpoint.commandReceived(ReportAttributesCommand [Level Control: A95C/1 -> 0000/1, cluster=0008, TID=1A, reports=[AttributeReport [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=51]]])
2025-01-02 09:52:05.143 [TRACE] [.zsmartsystems.zigbee.zcl.ZclCluster] - A95C/1: ZclCluster.handleCommand(ReportAttributesCommand [Level Control: A95C/1 -> 0000/1, cluster=0008, TID=1A, reports=[AttributeReport [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=51]]])
2025-01-02 09:52:05.144 [TRACE] [.zsmartsystems.zigbee.zcl.ZclCluster] - A95C/1: ZclCluster.handleAttributeReport([AttributeReport [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=51]])
2025-01-02 09:52:05.144 [TRACE] [.zsmartsystems.zigbee.zcl.ZclCluster] - A95C/1: Attribute 0 in Server cluster 8 updated to 51
2025-01-02 09:52:05.145 [TRACE] [.zsmartsystems.zigbee.zcl.ZclCluster] - A95C/1: ZclCluster.notifyAttributeListener org.openhab.binding.zigbee.internal.converter.ZigBeeConverterColorColor@168c86a of ZclAttribute [cluster=Level Control, id=0, name=Current Level, dataType=UNSIGNED_8_BIT_INTEGER, lastValue=51, lastReportTime=Thu Jan 02 09:52:05 CET 2025, implemented=true] with value 51
2025-01-02 09:52:05.147 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 588E81FFFEFBD897: Channel zigbee:device:zigbee:588e81fffefbd897:588E81FFFEFBD897_1_color updated to 36.822,65.60600,20
2025-01-02 09:52:05.148 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 588E81FFFEFBD897: Updating ZigBee channel state zigbee:device:zigbee:588e81fffefbd897:588E81FFFEFBD897_1_color to 36.822,65.60600,20
2025-01-02 09:52:05.149 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:zigbee:588e81fffefbd897 in 14430 seconds
2025-01-02 09:52:05.250 [TRACE] [e.ember.internal.ash.AshFrameHandler] - ASH: TX EZSP queue size: 1
2025-01-02 09:52:05.251 [TRACE] [e.ember.internal.ash.AshFrameHandler] - TX ASH EZSP: EzspNetworkStateRequest [networkId=0]
2025-01-02 09:52:05.251 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=4, reTx=false, data=84 00 01 18 00]
2

And for this one the fake update pattern.

chris · January 2, 2025, 9:40am

I’m not really sure what you refer to here? What class names overlap? I mean, class names are hierarchical, so they shouldn’t overlap as such, and you should be able to add multiple classes.

I don’t have any colour temp lights here, but I have 8 (I think) dimmers and they all work fine here (not saying there’s no issue, but I’ve not seen this reported as a more widespread problem which I would expect if all dimmers didn’t work).

Now,I have 0 colour bulbs, and there was a change to the colour channel handlers a couple of months back, so I could be more convinced of an issue there…

So from the log, it shows that the device reported the brightness was 51 (so around 20%). The colour is updated to be HSB showing 20% (I don’t know what it was before, but the B part looks correct).

Now - are you saying that the bulb was actually off? If so, this could indeed be a bug in the channel handler. In zigbee, the brightness can be reported as a non-zero level, even if the lamp is off, and the binding should keep track of the on/off state (but maybe this is broken).

Note that you don’t generally need to set logging to TRACE - it generates a lot more data and generally is of little use most of the time.

supersjel · January 2, 2025, 11:10am

Just that. So when you change org.openhab.binding.zigbee it also changes org.openhab.binding.zigbee.xbee. My assumption is that if you change value on both something goes wrong in the “processing loop” with creates invalid XML. As long as you only change one at a time this doesn’t happen.

Now you mention it. I’ve got one plug dimmer, checked it and this one works fine. Maybe the combination of both channels is “fatal”.

And I searched the forum and couldn’t find anything similar. Only one thread about a change in the color channel but that was regarding the slider in de GUI. Maybe most people only set values and never read them. Or most use the mqtt-zigbee setup. Or it’s specific for my hardware/installation/setup.

I think this was the acual color, so the strip was only reporting it’s current state.

This could be a valid hint for someone maintaining the binding. You know of someone we can tag that could confirm or discard this idea?

That I noticed I was lazy and thought lets get all in one go.

supersjel · January 2, 2025, 12:47pm

Me again, did the downgrade. This time to 4.2.2 since you mentioned a couple of months ago.

Result the same as 4.2.3. No spontaneous state changes, so when OFF it keeps OFF. But now the other bug appears again. If I set the color temperature to 60, dimmer to 20 and switch to ON all items report values. Now I change the color temperature to 40 and both dimmer and switch go to UNDEF. This time logs on debug level, still a lot. But in the last lines the binding sets dimmer/switch to UNDEF. Maybe because ‘Node 0A58 is not updated’ but I lack knowledge of the zigbee protocol so my guess might be useless.


events.log:

2025-01-02 13:23:45.923 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Hang_ColorTemperature' updated to 40
2025-01-02 13:23:45.945 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Hang_Switch' updated to UNDEF
2025-01-02 13:23:45.946 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Hang_Switch' changed from ON to UNDEF
2025-01-02 13:23:45.947 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Hang_Dimmer' updated to UNDEF
2025-01-02 13:23:45.948 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Hang_Dimmer' changed from 20 to UNDEF
2025-01-02 13:23:45.948 [INFO ] [openhab.event.GroupStateUpdatedEvent] - Group 'Bank1' updated to OFF through Hang_Switch
2025-01-02 13:23:45.949 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Hang_ColorTemperature' updated to 40

openhab.log:

2025-01-02 13:23:38.955 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=1, reTx=false, data=A0 90 01 59 00 96 52 9A 93 F1 FE FF 81 8E 58 64 B5 01 88 90]
2025-01-02 13:23:38.956 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
2025-01-02 13:23:38.956 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=5296, sourceEui=588E81FFFEF1939A, lastHopLqi=100, lastHopRssi=-75, relayList=9088]
2025-01-02 13:23:39.014 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=1, reTx=false, data=A0 90 01 45 00 00 04 01 08 00 01 01 40 01 00 00 98 64 B5 96 52 FF FF 07 18 64 0A 00 00 20 FE 04]
2025-01-02 13:23:39.015 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
2025-01-02 13:23:39.015 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0008, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=98], lastHopLqi=100, lastHopRssi=-75, sender=5296, bindingIndex=255, addressIndex=255, messageContents=18 64 0A 00 00 20 FE]
2025-01-02 13:23:39.016 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=5296/1, destinationAddress=0000/1, profile=0104, cluster=0008, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=98, rssi=-75, lqi=64, payload=18 64 0A 00 00 20 FE]
2025-01-02 13:23:39.017 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 588E81FFFEF1939A: Node update. NWK Address=NULL
2025-01-02 13:23:39.018 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 588E81FFFEF1939A: Node 5296 is not updated from ZigBeeNode [state=ONLINE, IEEE=588E81FFFEF1939A, NWK=----, endpoints=[]]
2025-01-02 13:23:39.019 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=64, commandId=10]
2025-01-02 13:23:39.019 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Level Control: 5296/1 -> 0000/1, cluster=0008, TID=64, reports=[AttributeReport [attributeDataType=UNSIGNED_8_BIT_INTEGER, attributeIdentifier=0, attributeValue=254]]]
2025-01-02 13:23:39.069 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=A1 00 01 18 00]
2025-01-02 13:23:39.076 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=A1 80 01 18 00 02]
2025-01-02 13:23:39.076 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2025-01-02 13:23:40.071 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=3, reTx=false, data=A2 00 01 18 00]
2025-01-02 13:23:40.078 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=3, reTx=false, data=A2 80 01 18 00 02]
2025-01-02 13:23:40.079 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2025-01-02 13:23:41.072 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=3, ackNum=4, reTx=false, data=A3 00 01 18 00]
2025-01-02 13:23:41.080 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=4, reTx=false, data=A3 80 01 18 00 02]
2025-01-02 13:23:41.081 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
2025-01-02 13:23:42.074 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=4, ackNum=5, reTx=false, data=A4 00 01 18 00]
2025-01-02 13:23:42.082 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=5, reTx=false, data=A4 80 01 18 00 02]
2025-01-02 13:23:42.083 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
2025-01-02 13:23:43.076 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=5, ackNum=6, reTx=false, data=A5 00 01 18 00]
2025-01-02 13:23:43.083 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=6, reTx=false, data=A5 80 01 18 00 02]
2025-01-02 13:23:43.084 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
2025-01-02 13:23:44.078 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=6, ackNum=7, reTx=false, data=A6 00 01 18 00]
2025-01-02 13:23:44.085 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=7, reTx=false, data=A6 80 01 18 00 02]
2025-01-02 13:23:44.086 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
2025-01-02 13:23:45.079 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=7, ackNum=0, reTx=false, data=A7 00 01 18 00]
2025-01-02 13:23:45.086 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=0, reTx=false, data=A7 80 01 18 00 02]
2025-01-02 13:23:45.087 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
2025-01-02 13:23:45.668 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFE802FB3: Polling 1 channels
2025-01-02 13:23:45.669 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFE802FB3: Polling zigbee:device:zigbee:ec1bbdfffe802fb3:EC1BBDFFFE802FB3_11_switch
2025-01-02 13:23:45.675 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: ReadAttributesCommand [On/Off: 0000/0 -> 0D9F/11, cluster=0006, TID=5C, identifiers=[0]]
2025-01-02 13:23:45.677 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=5C, commandId=0]
2025-01-02 13:23:45.678 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=0D9F/11, profile=0104, cluster=0006, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7E, rssi=--, lqi=--, payload=00 5C 00 00 00]
2025-01-02 13:23:45.679 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0D9F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=11, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7E], messageTag=5C, messageContents=00 5C 00 00 00]
2025-01-02 13:23:45.680 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=0, ackNum=1, reTx=false, data=A8 00 01 34 00 00 9F 0D 04 01 06 00 01 0B 40 11 00 00 7E 5C 05 00 5C 00 00 00]
2025-01-02 13:23:45.690 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=1, reTx=false, data=A8 80 01 34 00 00 4F]
2025-01-02 13:23:45.691 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
2025-01-02 13:23:45.692 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=4F]
2025-01-02 13:23:45.711 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=1, reTx=false, data=A8 90 01 59 00 9F 0D B3 2F 80 FE FF BD 1B EC C4 CD 00]
2025-01-02 13:23:45.712 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2025-01-02 13:23:45.712 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0D9F, sourceEui=EC1BBDFFFE802FB3, lastHopLqi=196, lastHopRssi=-51, relayList=]
2025-01-02 13:23:45.713 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=1, reTx=false, data=A8 90 01 59 00 9F 0D B3 2F 80 FE FF BD 1B EC C8 CE 00]
2025-01-02 13:23:45.714 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2025-01-02 13:23:45.714 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0D9F, sourceEui=EC1BBDFFFE802FB3, lastHopLqi=200, lastHopRssi=-50, relayList=]
2025-01-02 13:23:45.773 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=1, reTx=false, data=A8 90 01 45 00 00 04 01 06 00 0B 01 00 01 00 00 00 C4 CD 9F 0D FF FF 08 18 5C 01 00 00 00 10 01 02]
2025-01-02 13:23:45.774 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
2025-01-02 13:23:45.775 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=11, destinationEndpoint=1, options=[EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=00], lastHopLqi=196, lastHopRssi=-51, sender=0D9F, bindingIndex=255, addressIndex=255, messageContents=18 5C 01 00 00 00 10 01]
2025-01-02 13:23:45.775 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0D9F/11, destinationAddress=0000/1, profile=0104, cluster=0006, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=00, rssi=-51, lqi=C4, payload=18 5C 01 00 00 00 10 01]
2025-01-02 13:23:45.776 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=5, ackNum=1, reTx=false, data=A8 90 01 3F 00 00 9F 0D 04 01 06 00 01 0B 40 11 00 00 4F 5C 00 00]
2025-01-02 13:23:45.776 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFE802FB3: Node update. NWK Address=NULL
2025-01-02 13:23:45.778 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=6, notRdy=false]
2025-01-02 13:23:45.779 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - EC1BBDFFFE802FB3: Node 0D9F is not updated from ZigBeeNode [state=ONLINE, IEEE=EC1BBDFFFE802FB3, NWK=----, endpoints=[]]
2025-01-02 13:23:45.780 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=5C, commandId=1]
2025-01-02 13:23:45.781 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReadAttributesResponse [On/Off: 0D9F/11 -> 0000/1, cluster=0006, TID=5C, records=[ReadAttributeStatusRecord [status=SUCCESS, attributeIdentifier=0, attributeDataType=BOOLEAN, attributeValue=true]]]
2025-01-02 13:23:45.784 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0D9F, apsFrame=EmberApsFrame [profileId=0104, clusterId=0006, sourceEndpoint=1, destinationEndpoint=11, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=4F], messageTag=5C, status=EMBER_SUCCESS, messageContents=]
2025-01-02 13:23:45.786 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=5C state=RX_ACK
2025-01-02 13:23:45.787 [DEBUG] [converter.ZigBeeBaseChannelConverter] - EC1BBDFFFE802FB3: Channel zigbee:device:zigbee:ec1bbdfffe802fb3:EC1BBDFFFE802FB3_11_switch updated to ON
2025-01-02 13:23:45.789 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - EC1BBDFFFE802FB3: Updating ZigBee channel state zigbee:device:zigbee:ec1bbdfffe802fb3:EC1BBDFFFE802FB3_11_switch to ON
2025-01-02 13:23:45.791 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:zigbee:ec1bbdfffe802fb3 in 1830 seconds
2025-01-02 13:23:45.792 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 842E14FFFE19677F: Command for channel zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature --> 40 [PercentType]
2025-01-02 13:23:45.797 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX CMD: MoveToColorTemperatureCommand [Color Control: 0000/0 -> 0A58/1, cluster=0300, TID=5D, colorTemperature=212, transitionTime=10]
2025-01-02 13:23:45.798 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX ZCL: ZclHeader [frameType=CLUSTER_SPECIFIC_COMMAND, manufacturerSpecific=false, direction=CLIENT_TO_SERVER, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=5D, commandId=10]
2025-01-02 13:23:45.799 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - TX APS: ZigBeeApsFrame [sourceAddress=0000/1, destinationAddress=0A58/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=8, apsSecurity=false, ackRequest=true, apsCounter=7F, rssi=--, lqi=--, payload=01 5D 0A D4 00 0A 00]
2025-01-02 13:23:45.800 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 842E14FFFE19677F: Channel zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature waiting for response to 40
2025-01-02 13:23:45.800 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - ASH TX EZSP: EzspSendUnicastRequest [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0A58, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7F], messageTag=5D, messageContents=01 5D 0A D4 00 0A 00]
2025-01-02 13:23:45.801 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=1, ackNum=6, reTx=false, data=A9 00 01 34 00 00 58 0A 04 01 00 03 01 01 40 11 00 00 7F 5D 07 01 5D 0A D4 00 0A 00]
2025-01-02 13:23:45.811 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=6, ackNum=2, reTx=false, data=A9 80 01 34 00 00 50]
2025-01-02 13:23:45.812 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=7, notRdy=false]
2025-01-02 13:23:45.812 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspSendUnicastResponse [networkId=0, status=EMBER_SUCCESS, sequence=50]
2025-01-02 13:23:45.871 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=7, ackNum=2, reTx=false, data=A9 90 01 59 00 58 0A 7F 67 19 FE FF 14 2E 84 C4 CD 01 9F 0D]
2025-01-02 13:23:45.872 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=0, notRdy=false]
2025-01-02 13:23:45.872 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0A58, sourceEui=842E14FFFE19677F, lastHopLqi=196, lastHopRssi=-51, relayList=0D9F]
2025-01-02 13:23:45.891 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=0, ackNum=2, reTx=false, data=A9 90 01 59 00 58 0A 7F 67 19 FE FF 14 2E 84 C8 CE 01 9F 0D]
2025-01-02 13:23:45.892 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=1, notRdy=false]
2025-01-02 13:23:45.892 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0A58, sourceEui=842E14FFFE19677F, lastHopLqi=200, lastHopRssi=-50, relayList=0D9F]
2025-01-02 13:23:45.893 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=1, ackNum=2, reTx=false, data=A9 90 01 59 00 58 0A 7F 67 19 FE FF 14 2E 84 C8 CE 01 9F 0D]
2025-01-02 13:23:45.894 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=2, notRdy=false]
2025-01-02 13:23:45.894 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingRouteRecordHandler [networkId=0, source=0A58, sourceEui=842E14FFFE19677F, lastHopLqi=200, lastHopRssi=-50, relayList=0D9F]
2025-01-02 13:23:45.912 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=2, ackNum=2, reTx=false, data=A9 90 01 45 00 00 04 01 00 03 01 01 40 01 00 00 7E C8 CE 58 0A FF FF 05 08 5D 0B 0A 00 04]
2025-01-02 13:23:45.912 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=3, notRdy=false]
2025-01-02 13:23:45.913 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7E], lastHopLqi=200, lastHopRssi=-50, sender=0A58, bindingIndex=255, addressIndex=255, messageContents=08 5D 0B 0A 00]
2025-01-02 13:23:45.913 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0A58/1, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=7E, rssi=-50, lqi=C8, payload=08 5D 0B 0A 00]
2025-01-02 13:23:45.913 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=3, ackNum=2, reTx=false, data=A9 90 01 3F 00 00 58 0A 04 01 00 03 01 01 40 11 00 00 50 5D 00 00]
2025-01-02 13:23:45.914 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 842E14FFFE19677F: Node update. NWK Address=NULL
2025-01-02 13:23:45.914 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=4, notRdy=false]
2025-01-02 13:23:45.915 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 842E14FFFE19677F: Node 0A58 is not updated from ZigBeeNode [state=ONLINE, IEEE=842E14FFFE19677F, NWK=----, endpoints=[]]
2025-01-02 13:23:45.916 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=false, manufacturerCode=0, sequenceNumber=5D, commandId=11]
2025-01-02 13:23:45.917 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: DefaultResponse [Color Control: 0A58/1 -> 0000/1, cluster=0300, TID=5D, commandIdentifier=10, statusCode=SUCCESS]
2025-01-02 13:23:45.918 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspMessageSentHandler [networkId=0, type=EMBER_OUTGOING_DIRECT, indexOrDestination=0A58, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ADDRESS_DISCOVERY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=50], messageTag=5D, status=EMBER_SUCCESS, messageContents=]
2025-01-02 13:23:45.918 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 842E14FFFE19677F: Channel zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature received SUCCESS in response to 40
2025-01-02 13:23:45.919 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 842E14FFFE19677F: Channel zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature updated to 40
2025-01-02 13:23:45.919 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX STA: msgTag=5D state=RX_ACK
2025-01-02 13:23:45.920 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 842E14FFFE19677F: Updating ZigBee channel state zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature to 40
2025-01-02 13:23:45.921 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:zigbee:842e14fffe19677f in 14430 seconds
2025-01-02 13:23:45.932 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - <-- RX ASH frame: AshFrameData [frmNum=4, ackNum=2, reTx=false, data=A9 90 01 45 00 00 04 01 00 03 01 01 40 01 00 00 7F C4 CD 58 0A FF FF 0C 18 3F 0A 07 00 21 D4 00 08 00 30 02 04]
2025-01-02 13:23:45.933 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameAck [ackNum=5, notRdy=false]
2025-01-02 13:23:45.933 [DEBUG] [zigbee.dongle.ember.ZigBeeDongleEzsp] - RX EZSP: EzspIncomingMessageHandler [networkId=0, type=EMBER_INCOMING_UNICAST, apsFrame=EmberApsFrame [profileId=0104, clusterId=0300, sourceEndpoint=1, destinationEndpoint=1, options=[EMBER_APS_OPTION_RETRY, EMBER_APS_OPTION_ENABLE_ROUTE_DISCOVERY], groupId=0, sequence=7F], lastHopLqi=196, lastHopRssi=-51, sender=0A58, bindingIndex=255, addressIndex=255, messageContents=18 3F 0A 07 00 21 D4 00 08 00 30 02]
2025-01-02 13:23:45.934 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX APS: ZigBeeApsFrame [sourceAddress=0A58/1, destinationAddress=0000/1, profile=0104, cluster=0300, addressMode=DEVICE, radius=0, apsSecurity=false, ackRequest=false, apsCounter=7F, rssi=-51, lqi=C4, payload=18 3F 0A 07 00 21 D4 00 08 00 30 02]
2025-01-02 13:23:45.935 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 842E14FFFE19677F: Node update. NWK Address=NULL
2025-01-02 13:23:45.936 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - 842E14FFFE19677F: Node 0A58 is not updated from ZigBeeNode [state=ONLINE, IEEE=842E14FFFE19677F, NWK=----, endpoints=[]]
2025-01-02 13:23:45.936 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX ZCL: ZclHeader [frameType=ENTIRE_PROFILE_COMMAND, manufacturerSpecific=false, direction=SERVER_TO_CLIENT, disableDefaultResponse=true, manufacturerCode=0, sequenceNumber=3F, commandId=10]
2025-01-02 13:23:45.937 [DEBUG] [tsystems.zigbee.ZigBeeNetworkManager] - RX CMD: ReportAttributesCommand [Color Control: 0A58/1 -> 0000/1, cluster=0300, TID=3F, reports=[AttributeReport [attributeDataType=UNSIGNED_16_BIT_INTEGER, attributeIdentifier=7, attributeValue=212], AttributeReport [attributeDataType=ENUMERATION_8_BIT, attributeIdentifier=8, attributeValue=2]]]
2025-01-02 13:23:45.941 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 842E14FFFE19677F: Channel zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_color updated to UNDEF
2025-01-02 13:23:45.941 [DEBUG] [converter.ZigBeeBaseChannelConverter] - 842E14FFFE19677F: Channel zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature updated to 40
2025-01-02 13:23:45.942 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 842E14FFFE19677F: Updating ZigBee channel state zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_color to UNDEF
2025-01-02 13:23:45.942 [DEBUG] [ng.zigbee.handler.ZigBeeThingHandler] - 842E14FFFE19677F: Updating ZigBee channel state zigbee:device:zigbee:842e14fffe19677f:842E14FFFE19677F_1_colortemperature to 40
2025-01-02 13:23:45.943 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:zigbee:842e14fffe19677f in 14430 seconds
2025-01-02 13:23:45.945 [DEBUG] [.zigbee.handler.ZigBeeIsAliveTracker] - IsAlive Tracker scheduled task for thingUID=zigbee:device:zigbee:842e14fffe19677f in 14430 seconds
2025-01-02 13:23:47.081 [DEBUG] [e.ember.internal.ash.AshFrameHandler] - --> TX ASH frame: AshFrameData [frmNum=2, ackNum=5, reTx=false, data=AA 00 01 18 00]

chris · January 2, 2025, 7:06pm

I don’t think this is specific to zigbee, and I don’t think it’s the cause of the issue. The whole system is like this - we also have org.openhab and orgg.openhab.binding. These also “overlap”. This is how the logging system works and I don’t see any problem with this.

It’s not an issue with combined channels - I suspect it’s the colour channel. You shouldn’t have a dimmer if you have a colour channel since the binding won’t (or shouldn’t) provide both.

I am the binding maintainer.

chris · January 2, 2025, 7:30pm

I’ve opened an issue -:

I think I’ve also found the regression so will create a PR soon. It was introduced in #855.

chris · January 2, 2025, 7:45pm

FTR.

supersjel · January 3, 2025, 9:09am

@chris Thanx for the help, if you release it and need help testing let me know. I’ve got a range of zigbee devices of different brand and type (just buy what is cheap at a moment).

chris · January 5, 2025, 10:52pm

Thanks. This fix should be in the next release of 4.3 - probably in the middle of January.