Deconz : OpenClose sensor does not always update

ledeste21 · August 21, 2020, 7:41pm

Hello,
I got my conbee 2 for a while now and everything is fine, but I got this annoying issue with the openhab binding that I was not able to fix.
When a OpenClose sensor change state, I can see it in Phoscon gui, I can see it in the Deconz REST API but, sometime, the event is never registered into openhab. This become even more ridiculous when it lost some “open” state and then save 2 “closed” state in a raw in my db…

I got many other devices, temperature sensor, light, humidity, pressure, power plug etc, none seem to have this kind of issue (but to be faire, they all update way more often, and if one state miss, that’s not as annoying)

I was not able to find anything suspicious in openhab log, but the deconz binding is really verbose…

Does anyone had this issue too?
Is there a way to “force update” deconz things state?

Thanks a lot

J-N-K · August 22, 2020, 6:24am

No, there is no polling. But it would be interesting to know what the Deconz REST API reports as state. And if possible if the change was reported via websocket messages. I fear that probably the state change is not sent out via the websocket.

ledeste21 · August 22, 2020, 8:28am

Goog idea indeed.

So for more info, I started a nodejs server that was listening that was logging the websocket info.

I’m not really sure about what I find here. For exemple when I close/open my window, I only got one “open” event.
But if I then close it and does not open it, I got two close event for example.
I’ll filter on my device ID to have a more clear logs and let you know.

But for now, I was at least able to get one “open” event, without any change in openhab
The event look like

  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T08:20:36.931',
     lowbattery: false,
     open: true,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }

and my thing is configured like this
`Thing deconz:openclosesensor:deconz_bridge:openclosesensor_01 "Contact sensor 1" (deconz:deconz:deconz_bridge) @ "Maison" [ uid="ec:1b:bd:ff:fe:6f:2f:a5-01-0500", id="46" ]`

And my item :
`Contact     Bedroom_ContactSensor_Open           "Fenetre chambre Open/close"      (Home, FF, FF_Bedroom)    {channel="deconz:openclosesensor:deconz_bridge:openclosesensor_01:open"}`

J-N-K · August 22, 2020, 8:34am

What is in the openHAB log? Is the message received there? You need to enable trace logging to the the message.

ledeste21 · August 22, 2020, 8:43am

I’m trying to find anything but this is super verbose :s

ledeste21 · August 22, 2020, 8:58am

I think I’ve found the event in openhab log

I have found another deconz device that was updated and by looking at the surrounding log I found that

So it look like I can search with the end of my device uuid so I did make a search in the few last minutes of logs
I have once again close and open my windows.

The web socket said something like this to me

  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T08:39:33.220',
     lowbattery: false,
     open: false,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T08:39:45.154',
     lowbattery: false,
     open: true,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ config: { battery: 100, on: true, reachable: true },
  e: 'changed',
  id: '46',
  r: 'sensors',
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }

And in the log, I was able to find 2 group of 3 occurrence of the end of this device uuid at the same times

10:39:33.232 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - filled 199 DirectByteBuffer@39449740[p=0,l=199,c=4096,r=199]={<<<\x81~\x00\xC3{"e":"changed...2f:a5-01-0500"}>>>c:b0:3e:aa:0a:02:...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:33.232 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - Key interests updated 1 -> 0 on SocketChannelEndPoint@40d29b0b{/192.168.1.50:443<->/192.168.1.50:51022,OPEN,fill=-,flush=-,to=10616/0}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@1dda79be[s=ConnectionState@3ffcdba3[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@1c7bdd20[IDLE][queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@48a50767[ExtensionStack,s=START,c=0,len=311,f=null]]
10:39:33.233 [DEBUG] [common.io.AbstractWebSocketConnection] - Filled 199 bytes - DirectByteBuffer@39449740[p=0,l=199,c=4096,r=199]={<<<\x81~\x00\xC3{"e":"changed...2f:a5-01-0500"}>>>c:b0:3e:aa:0a:02:...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:33.233 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 waiting with 1 keys
10:39:33.233 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Parsing 199 bytes
10:39:33.234 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT OpCode TEXT, fin=true rsv=...
10:39:33.235 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Payload Length: 195 - Parser@48a50767[ExtensionStack,s=PAYLOAD_LEN_BYTES,c=0,len=195,f=TEXT[len=0,fin=true,rsv=...,masked=false]]
10:39:33.235 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Window: DirectByteBuffer@490d5c48[p=0,l=195,c=195,r=195]={<<<{"e":"changed","i...2f:a5-01-0500"}>>>}

and

10:39:45.170 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - filled 198 DirectByteBuffer@39449740[p=0,l=198,c=4096,r=198]={<<<\x81~\x00\xC2{"e":"changed...2f:a5-01-0500"}>>>77-01-0400"}0a:02...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:45.170 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 waiting with 1 keys
10:39:45.171 [DEBUG] [common.io.AbstractWebSocketConnection] - Filled 198 bytes - DirectByteBuffer@39449740[p=0,l=198,c=4096,r=198]={<<<\x81~\x00\xC2{"e":"changed...2f:a5-01-0500"}>>>77-01-0400"}0a:02...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:45.172 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Parsing 198 bytes
10:39:45.173 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT OpCode TEXT, fin=true rsv=...
10:39:45.173 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Payload Length: 194 - Parser@48a50767[ExtensionStack,s=PAYLOAD_LEN_BYTES,c=0,len=194,f=TEXT[len=0,fin=true,rsv=...,masked=false]]
10:39:45.174 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Window: DirectByteBuffer@e936d7e[p=0,l=194,c=194,r=194]={<<<{"e":"changed","i...2f:a5-01-0500"}>>>}

For exemple, this is what the log look like when it update my humidity sensor

10:39:53.451 [DEBUG] [ket.common.events.AbstractEventDriver] - incomingFrame(TEXT[len=165,fin=true,rsv=...,masked=false])
10:39:53.452 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - filled 166 DirectByteBuffer@39449740[p=0,l=166,c=4096,r=166]={<<<\x81~\x00\xA2{"e":"changed...7f:e4-01-0405"}>>>2"}:"Smart plug",...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:53.453 [DEBUG] [common.io.AbstractWebSocketConnection] - Filled 166 bytes - DirectByteBuffer@39449740[p=0,l=166,c=4096,r=166]={<<<\x81~\x00\xA2{"e":"changed...7f:e4-01-0405"}>>>2"}:"Smart plug",...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:53.453 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@3399bb67[p=0,l=169,c=32768,r=169]={<<<event: message\nda...mStateEvent"}\n\n>>>foEvent"}\n\nent"}\n...ule entre 0 (fr} complete=false committing=false callback=Blocker@2c2b651a{null}
10:39:53.454 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Shadow_Temperature_LastUpdated changed from 2020-08-22T10:32:21.175+0200 to 2020-08-22T10:39:53.435+0200
10:39:53.454 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Parsing 166 bytes
10:39:53.454 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@54da2756[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@22150704] generate: FLUSH (null,[p=0,l=169,c=32768,r=169],false)@COMMITTED
10:39:53.455 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT OpCode TEXT, fin=true rsv=...
10:39:53.455 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 175 SocketChannelEndPoint@457d83a8{/192.168.1.30:57902<->/192.168.1.50:8080,OPEN,fill=-,flush=W,to=2254/30000}{io=0/0,kio=0,kro=1}->HttpConnection@48c81a80[p=HttpParser{s=END,0 of -1},g=HttpGenerator@460fede9{s=COMMITTED}]=>HttpChannelOverHttp@423071f0{r=8,c=true,c=false/false,a=ASYNC_WAIT,uri=//192.168.1.50:8080/rest/events,age=918677}
10:39:53.455 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Payload Length: 162 - Parser@48a50767[ExtensionStack,s=PAYLOAD_LEN_BYTES,c=0,len=162,f=TEXT[len=0,fin=true,rsv=...,masked=false]]
10:39:53.456 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=175 remaining=0 WriteFlusher@52f38139{WRITING}->null
10:39:53.456 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Window: DirectByteBuffer@2ebb546c[p=0,l=162,c=162,r=162]={<<<{"e":"changed","i...7f:e4-01-0405"}>>>}
10:39:53.457 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@54da2756[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@22150704] generate: DONE (null,[p=169,l=169,c=32768,r=0],false)@COMMITTED
10:39:53.457 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Parsed Frame: TEXT[len=162,fin=true,rsv=...,masked=false]
10:39:53.458 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@3399bb67[p=0,l=200,c=32768,r=200]={<<<event: message\nda...mStateEvent"}\n\n>>>20-08-22T10:39:17...ule entre 0 (fr} complete=false committing=false callback=Blocker@2c2b651a{null}
10:39:53.458 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Notify ExtensionStack[queueSize=0,extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]
10:39:53.458 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@54da2756[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@5031d1e3] generate: FLUSH (null,[p=0,l=200,c=32768,r=200],false)@COMMITTED
10:39:53.458 [DEBUG] [ket.common.events.AbstractEventDriver] - incomingFrame(TEXT[len=162,fin=true,rsv=...,masked=false])
10:39:53.459 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 206 SocketChannelEndPoint@457d83a8{/192.168.1.30:57902<->/192.168.1.50:8080,OPEN,fill=-,flush=W,to=2/30000}{io=0/0,kio=0,kro=1}->HttpConnection@48c81a80[p=HttpParser{s=END,0 of -1},g=HttpGenerator@460fede9{s=COMMITTED}]=>HttpChannelOverHttp@423071f0{r=8,c=true,c=false/false,a=ASYNC_WAIT,uri=//192.168.1.50:8080/rest/events,age=918681}
10:39:53.460 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=206 remaining=0 WriteFlusher@52f38139{WRITING}->null
10:39:53.460 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - filled 0 DirectByteBuffer@39449740[p=0,l=0,c=4096,r=0]={<<<>>>\x81~\x00\xA2{"e":"changed...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:53.460 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@54da2756[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@5031d1e3] generate: DONE (null,[p=200,l=200,c=32768,r=0],false)@COMMITTED
10:39:53.461 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Shadow_Humidity changed from 63.46 % to 63.42 %

And this is what I got after a “2f:a5-01-0500” log + few secondes

10:39:33.232 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - filled 199 DirectByteBuffer@39449740[p=0,l=199,c=4096,r=199]={<<<\x81~\x00\xC3{"e":"changed...2f:a5-01-0500"}>>>c:b0:3e:aa:0a:02:...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:33.232 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - Key interests updated 1 -> 0 on SocketChannelEndPoint@40d29b0b{/192.168.1.50:443<->/192.168.1.50:51022,OPEN,fill=-,flush=-,to=10616/0}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@1dda79be[s=ConnectionState@3ffcdba3[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@1c7bdd20[IDLE][queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@48a50767[ExtensionStack,s=START,c=0,len=311,f=null]]
10:39:33.233 [DEBUG] [common.io.AbstractWebSocketConnection] - Filled 199 bytes - DirectByteBuffer@39449740[p=0,l=199,c=4096,r=199]={<<<\x81~\x00\xC3{"e":"changed...2f:a5-01-0500"}>>>c:b0:3e:aa:0a:02:...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:33.233 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 waiting with 1 keys
10:39:33.233 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Parsing 199 bytes
10:39:33.234 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT OpCode TEXT, fin=true rsv=...
10:39:33.235 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Payload Length: 195 - Parser@48a50767[ExtensionStack,s=PAYLOAD_LEN_BYTES,c=0,len=195,f=TEXT[len=0,fin=true,rsv=...,masked=false]]
10:39:33.235 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Window: DirectByteBuffer@490d5c48[p=0,l=195,c=195,r=195]={<<<{"e":"changed","i...2f:a5-01-0500"}>>>}
10:39:33.236 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Parsed Frame: TEXT[len=195,fin=true,rsv=...,masked=false]
10:39:33.236 [DEBUG] [eclipse.jetty.websocket.common.Parser] - CLIENT Notify ExtensionStack[queueSize=0,extensions=[],incoming=org.eclipse.jetty.websocket.common.WebSocketSession,outgoing=org.eclipse.jetty.websocket.client.io.WebSocketClientConnection]
10:39:33.237 [DEBUG] [ket.common.events.AbstractEventDriver] - incomingFrame(TEXT[len=195,fin=true,rsv=...,masked=false])
10:39:33.237 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - filled 0 DirectByteBuffer@39449740[p=0,l=0,c=4096,r=0]={<<<>>>\x81~\x00\xC3{"e":"changed...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
10:39:33.238 [DEBUG] [g.eclipse.jetty.io.AbstractConnection] - fillInterested WebSocketClientConnection@1dda79be::SocketChannelEndPoint@40d29b0b{/192.168.1.50:443<->/192.168.1.50:51022,OPEN,fill=-,flush=-,to=5/0}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@1dda79be[s=ConnectionState@3ffcdba3[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@1c7bdd20[IDLE][queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@48a50767[ExtensionStack,s=START,c=0,len=195,f=null]]
10:39:33.239 [DEBUG] [org.eclipse.jetty.io.FillInterest    ] - interested FillInterest@3e282561{AC.ReadCB@1dda79be{WebSocketClientConnection@1dda79be::SocketChannelEndPoint@40d29b0b{/192.168.1.50:443<->/192.168.1.50:51022,OPEN,fill=FI,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->WebSocketClientConnection@1dda79be[s=ConnectionState@3ffcdba3[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@1c7bdd20[IDLE][queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@48a50767[ExtensionStack,s=START,c=0,len=195,f=null]]}}
10:39:33.239 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - changeInterests p=false 0->1 for SocketChannelEndPoint@40d29b0b{/192.168.1.50:443<->/192.168.1.50:51022,OPEN,fill=FI,flush=-,to=0/0}{io=0/1,kio=0,kro=1}->WebSocketClientConnection@1dda79be[s=ConnectionState@3ffcdba3[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@1c7bdd20[IDLE][queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@48a50767[ExtensionStack,s=START,c=0,len=195,f=null]]
10:39:33.240 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Queued change org.eclipse.jetty.io.ChannelEndPoint$1@5cc061fa on ManagedSelector@233c442e{STARTED} id=1 keys=1 selected=0 updates=0
10:39:33.241 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Wakeup on submit ManagedSelector@233c442e{STARTED} id=1 keys=1 selected=0 updates=1
10:39:33.241 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 woken with none selected
10:39:33.241 [DEBUG] [ty.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@6fc9044{s=1/1,p=0}@12b88422 size 1 > capacity
10:39:33.242 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 woken up from select, 0/0/1 selected
10:39:33.242 [DEBUG] [se.jetty.util.thread.QueuedThreadPool] - ran ReservedThreadExecutor@6fc9044{s=1/1,p=0}@12b88422 in QueuedThreadPool[ESH-httpClient-deconz-deconz_bridge]@2280784d{STARTED,5<=6<=10,i=0,r=1,q=0}[ReservedThreadExecutor@6fc9044{s=1/1,p=0}]
10:39:33.242 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 processing 0 keys, 1 updates
10:39:33.243 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - updateable 1
10:39:33.244 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - update org.eclipse.jetty.io.ChannelEndPoint$1@5cc061fa
10:39:33.244 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - Key interests updated 0 -> 1 on SocketChannelEndPoint@40d29b0b{/192.168.1.50:443<->/192.168.1.50:51022,OPEN,fill=FI,flush=-,to=5/0}{io=1/1,kio=1,kro=1}->WebSocketClientConnection@1dda79be[s=ConnectionState@3ffcdba3[OPENED],f=org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection$Flusher@1c7bdd20[IDLE][queueSize=0,aggregateSize=-1,terminated=null],g=Generator[CLIENT,validating],p=Parser@48a50767[ExtensionStack,s=START,c=0,len=195,f=null]]
10:39:33.245 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - updates 0
10:39:33.245 [DEBUG] [org.eclipse.jetty.io.ManagedSelector ] - Selector sun.nio.ch.WindowsSelectorImpl@744afdc9 waiting with 1 keys
10:39:35.055 [DEBUG] [org.eclipse.jetty.io.IdleTimeout     ] - SocketChannelEndPoint@457d83a8{/192.168.1.30:57902<->/192.168.1.50:8080,OPEN,fill=-,flush=-,to=7056/30000}{io=0/0,kio=0,kro=1}->HttpConnection@48c81a80[p=HttpParser{s=END,0 of -1},g=HttpGenerator@460fede9{s=COMMITTED}]=>HttpChannelOverHttp@423071f0{r=8,c=true,c=false/false,a=ASYNC_WAIT,uri=//192.168.1.50:8080/rest/events,age=900277} idle timeout check, elapsed: 7056 ms, remaining: 22944 ms
10:39:36.012 [DEBUG] [org.eclipse.jetty.server.HttpChannel ] - sendResponse info=null content=DirectByteBuffer@3399bb67[p=0,l=180,c=32768,r=180]={<<<event: message\nda...usInfoEvent"}\n\n>>>ent"}\n\ndValue\\":\\...ule entre 0 (fr} complete=false committing=false callback=Blocker@2c2b651a{null}
10:39:36.013 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@54da2756[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@3238ebe] generate: FLUSH (null,[p=0,l=180,c=32768,r=180],false)@COMMITTED
10:39:36.014 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint ] - flushed 186 SocketChannelEndPoint@457d83a8{/192.168.1.30:57902<->/192.168.1.50:8080,OPEN,fill=-,flush=W,to=8015/30000}{io=0/0,kio=0,kro=1}->HttpConnection@48c81a80[p=HttpParser{s=END,0 of -1},g=HttpGenerator@460fede9{s=COMMITTED}]=>HttpChannelOverHttp@423071f0{r=8,c=true,c=false/false,a=ASYNC_WAIT,uri=//192.168.1.50:8080/rest/events,age=901236}
10:39:36.016 [DEBUG] [org.eclipse.jetty.io.WriteFlusher    ] - Flushed=true written=186 remaining=0 WriteFlusher@52f38139{WRITING}->null
10:39:36.017 [DEBUG] [g.eclipse.jetty.server.HttpConnection] - org.eclipse.jetty.server.HttpConnection$SendCallback@54da2756[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@3238ebe] generate: DONE (null,[p=180,l=180,c=32768,r=0],false)@COMMITTED
10:39:38.005 [DEBUG] [su.litvak.chromecast.api.v2.Channel  ] -  --> {"type":"GET_STATUS","requestId":1742}

J-N-K · August 22, 2020, 9:06am

You don‘t need debug on jetty, trace on org.openhab.binding.deconz would be interesting

ledeste21 · August 22, 2020, 9:07am

ah I dont know how to do that, I only did a log:set TRACE in the openhab console. I’ll look at it and make this test again

J-N-K · August 22, 2020, 9:12am

First reset that log:set DEFAULT, then log:set TRACE org.openhab.binding.deconz. This only sets the log-Level for a specific bundle.

ledeste21 · August 22, 2020, 9:13am

oh, thanks a lot, I did not though this was this simple ^^’

ledeste21 · August 22, 2020, 9:20am

I’m not sure to have made the right action. I know see fewer log with only some deconz related [TRACE] one.
But nothing relevant at first

For the same test, the websocket events:

{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:16:18.456',
     lowbattery: false,
     open: false,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:16:19.669',
     lowbattery: false,
     open: false,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:16:34.591',
     lowbattery: false,
     open: true,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }

And the whole logs:

11:16:00.158 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Server_cron_last_heartbeat' received command 2020-08-22T11:16:00.000+0200
11:16:00.159 [INFO ] [smarthome.event.ItemStateChangedEvent] - Server_cron_last_heartbeat changed from 2020-08-22T11:15:00.000+0200 to 2020-08-22T11:16:00.000+0200
11:16:01.700 [TRACE] [nz.internal.handler.LightThingHandler] - deconz:onofflight:deconz_bridge:plug_06 received LightMessage{hascolor=null, ctmax=null, ctmin=null, type=null, state=null, e='changed', r='lights', t='event', id='6', manufacturername='', modelid='', name='', swversion='', ep='', uniqueid='7c:b0:3e:aa:00:b2:78:97-03'}
11:16:04.489 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:powersensor:deconz_bridge:plug_15_power received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=0.0, battery=null, consumption=null, voltage=0.0, current=0.0, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:04.487'}
11:16:04.491 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_2_LastUpdated changed from 2020-08-22T11:15:32.881+0200 to 2020-08-22T11:16:04.487+0200
11:16:05.477 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:powersensor:deconz_bridge:plug_14_power received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=0.0, battery=null, consumption=null, voltage=0.0, current=0.0, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:05.476'}
11:16:05.479 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_1_LastUpdated changed from 2020-08-22T11:15:33.858+0200 to 2020-08-22T11:16:05.476+0200
11:16:06.819 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:lightsensor:deconz_bridge:lightsensor_02 received SensorState{dark=false, daylight=true, lightlevel=38302, lux=6762, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:06.817'}
11:16:06.822 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Light_Sensor_Lightlux changed from 11910.0 lx to 6762.0 lx
11:16:06.823 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Light_Sensor_LightLevel changed from 40760 to 38302
11:16:06.824 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Light_Sensor_LastUpdated changed from 2020-08-22T11:15:41.980+0200 to 2020-08-22T11:16:06.817+0200
11:16:19.607 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:lightsensor:deconz_bridge:lightsensor_03 received SensorState{dark=true, daylight=false, lightlevel=4772, lux=3, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:19.606'}
11:16:19.610 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_Sensor_2_Lightlux changed from 5.0 lx to 3.0 lx
11:16:19.611 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_Sensor_2_LightLevel changed from 6990 to 4772
11:16:19.612 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_Sensor_2_LastUpdated changed from 2020-08-22T11:15:14.829+0200 to 2020-08-22T11:16:19.606+0200
11:16:22.943 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:lightsensor:deconz_bridge:lightsensor_01 received SensorState{dark=false, daylight=false, lightlevel=13011, lux=20, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:22.938'}
11:16:22.946 [INFO ] [smarthome.event.ItemStateChangedEvent] - Entryway_LightSensor_Lightlux changed from 36.0 lx to 20.0 lx
11:16:22.947 [INFO ] [smarthome.event.ItemStateChangedEvent] - Entryway_LightSensor_Level changed from 15564 to 13011
11:16:22.948 [INFO ] [smarthome.event.ItemStateChangedEvent] - Entryway_LightSensor_LastUpdated changed from 2020-08-22T10:21:21.112+0200 to 2020-08-22T11:16:22.938+0200
11:16:22.951 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:presencesensor:deconz_bridge:presencesensor_01 received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=false, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:22.938'}
11:16:29.757 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:powersensor:deconz_bridge:plug_15_power received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=1.0, battery=null, consumption=null, voltage=0.0, current=0.0, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:29.754'}
11:16:29.760 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_2_LastUpdated changed from 2020-08-22T11:16:04.487+0200 to 2020-08-22T11:16:29.754+0200
11:16:29.760 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_2 changed from 0.0 W to 1.0 W
11:16:30.743 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:powersensor:deconz_bridge:plug_14_power received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=0.0, battery=null, consumption=null, voltage=0.0, current=0.0, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:30.742'}
11:16:30.746 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_1_LastUpdated changed from 2020-08-22T11:16:05.476+0200 to 2020-08-22T11:16:30.742+0200
11:16:36.631 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:lightsensor:deconz_bridge:lightsensor_02 received SensorState{dark=false, daylight=true, lightlevel=40775, lux=11951, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:36.630'}
11:16:36.635 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Light_Sensor_Lightlux changed from 6762.0 lx to 11951.0 lx
11:16:36.636 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Light_Sensor_LightLevel changed from 38302 to 40775
11:16:36.637 [INFO ] [smarthome.event.ItemStateChangedEvent] - FrontYard_Light_Sensor_LastUpdated changed from 2020-08-22T11:16:06.817+0200 to 2020-08-22T11:16:36.630+0200
11:16:38.449 [TRACE] [nz.internal.handler.LightThingHandler] - deconz:onofflight:deconz_bridge:plug_02 received LightMessage{hascolor=null, ctmax=null, ctmin=null, type=null, state=null, e='changed', r='lights', t='event', id='1', manufacturername='', modelid='', name='', swversion='', ep='', uniqueid='7c:b0:3e:aa:0a:06:7d:23-03'}
11:16:39.547 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:lightsensor:deconz_bridge:lightsensor_03 received SensorState{dark=true, daylight=false, lightlevel=6990, lux=5, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:39.545'}
11:16:39.550 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_Sensor_2_Lightlux changed from 3.0 lx to 5.0 lx
11:16:39.551 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_Sensor_2_LightLevel changed from 4772 to 6990
11:16:39.552 [INFO ] [smarthome.event.ItemStateChangedEvent] - Light_Sensor_2_LastUpdated changed from 2020-08-22T11:16:19.606+0200 to 2020-08-22T11:16:39.545+0200
11:16:40.309 [TRACE] [nz.internal.handler.LightThingHandler] - deconz:onofflight:deconz_bridge:plug_10 received LightMessage{hascolor=null, ctmax=null, ctmin=null, type=null, state=null, e='changed', r='lights', t='event', id='10', manufacturername='', modelid='', name='', swversion='', ep='', uniqueid='7c:b0:3e:aa:0a:00:2f:4e-03'}
11:16:41.937 [TRACE] [nz.internal.handler.LightThingHandler] - deconz:onofflight:deconz_bridge:plug_09 received LightMessage{hascolor=null, ctmax=null, ctmin=null, type=null, state=null, e='changed', r='lights', t='event', id='9', manufacturername='', modelid='', name='', swversion='', ep='', uniqueid='7c:b0:3e:aa:0a:00:4e:9e-03'}
11:16:57.320 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:powersensor:deconz_bridge:plug_15_power received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=0.0, battery=null, consumption=null, voltage=0.0, current=0.0, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:57.319'}
11:16:57.322 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_2_LastUpdated changed from 2020-08-22T11:16:29.754+0200 to 2020-08-22T11:16:57.319+0200
11:16:57.323 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_2 changed from 1.0 W to 0.0 W
11:16:58.309 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:powersensor:deconz_bridge:plug_14_power received SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=0.0, battery=null, consumption=null, voltage=0.0, current=0.0, status=null, buttonevent=null, gesture=null, lastupdated='2020-08-22T09:16:58.307'}
11:16:58.312 [INFO ] [smarthome.event.ItemStateChangedEvent] - Power_1_LastUpdated changed from 2020-08-22T11:16:30.742+0200 to 2020-08-22T11:16:58.307+0200
11:17:00.155 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Server_cron_last_heartbeat' received command 2020-08-22T11:17:00.000+0200
11:17:00.156 [INFO ] [smarthome.event.ItemStateChangedEvent] - Server_cron_last_heartbeat changed from 2020-08-22T11:16:00.000+0200 to 2020-08-22T11:17:00.000+0200

J-N-K · August 22, 2020, 9:56am

It seems the message gets lost somewhere. I have added additional debugging for that. Please update the bundle:

update org.openhab.binding.deconz https://janessa.me/esh/org.openhab.binding.deconz-2.5.8-SNAPSHOT.jar

on the same console where you set the log level and repeat the steps above.

ledeste21 · August 22, 2020, 10:04am

oh damn, I was not expecting live update, and for sure not a one this easy to use. Thanks a lot you’re awesome!

But, I SWEAR I did nothing else than what you told told me to, just update the binding and log the output.
Once again, go and close/open windows

But this time…

11:57:49.204 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:openclosesensor:deconz_bridge:openclosesensor_01 received SensorMessage{type='', config=null, state=SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=false, fire=null, water=null, alarm=null, tampered=false, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, valve=null, lastupdated='2020-08-22T09:57:49.202', xy=null}, e='changed', r='sensors', t='event', id='46', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='ec:1b:bd:ff:fe:6f:2f:a5-01-0500'}
11:57:49.207 [INFO ] [smarthome.event.ItemStateChangedEvent] - Bedroom_ContactSensor_Open changed from OPEN to CLOSED
11:57:49.208 [INFO ] [smarthome.event.ItemStateChangedEvent] - Bedroom_ContactSensor_LastUpdated changed from 2020-08-22T11:16:34.591+0200 to 2020-08-22T11:57:49.202+0200
11:57:50.413 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"e":"changed","id":"46","r":"sensors","state":{"lastupdated":"2020-08-22T09:57:50.412","lowbattery":false,"open":false,"tampered":false},"t":"event","uniqueid":"ec:1b:bd:ff:fe:6f:2f:a5-01-0500"}
11:57:50.414 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:openclosesensor:deconz_bridge:openclosesensor_01 received SensorMessage{type='', config=null, state=SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=false, fire=null, water=null, alarm=null, tampered=false, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, valve=null, lastupdated='2020-08-22T09:57:50.412', xy=null}, e='changed', r='sensors', t='event', id='46', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='ec:1b:bd:ff:fe:6f:2f:a5-01-0500'}
11:57:50.416 [INFO ] [smarthome.event.ItemStateChangedEvent] - Bedroom_ContactSensor_LastUpdated changed from 2020-08-22T11:57:49.202+0200 to 2020-08-22T11:57:50.412+0200
11:57:52.602 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"attr":{"lastannounced":"2020-08-05T02:09:33Z","lastseen":"2020-08-22T09:57Z","manufacturername":"Heiman","modelid":"TS0121","name":"Smart plug 14 sèche linge","swversion":null,"type":"Smart plug","uniqueid":"84:2e:14:ff:fe:df:a1:97-01"},"e":"changed","id":"14","r":"lights","t":"event","uniqueid":"84:2e:14:ff:fe:df:a1:97-01"}
11:57:52.603 [TRACE] [internal.netutils.WebSocketConnection] - Couldn't find light listener for id 14
11:58:00.128 [INFO ] [smarthome.event.ItemCommandEvent     ] - Item 'Server_cron_last_heartbeat' received command 2020-08-22T11:58:00.000+0200
11:58:00.129 [INFO ] [smarthome.event.ItemStateChangedEvent] - Server_cron_last_heartbeat changed from 2020-08-22T11:57:00.000+0200 to 2020-08-22T11:58:00.000+0200
11:58:00.199 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"e":"changed","id":"46","r":"sensors","state":{"lastupdated":"2020-08-22T09:58:00.197","lowbattery":false,"open":true,"tampered":false},"t":"event","uniqueid":"ec:1b:bd:ff:fe:6f:2f:a5-01-0500"}
11:58:00.200 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:openclosesensor:deconz_bridge:openclosesensor_01 received SensorMessage{type='', config=null, state=SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=true, fire=null, water=null, alarm=null, tampered=false, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, valve=null, lastupdated='2020-08-22T09:58:00.197', xy=null}, e='changed', r='sensors', t='event', id='46', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='ec:1b:bd:ff:fe:6f:2f:a5-01-0500'}
11:58:00.202 [INFO ] [smarthome.event.ItemStateChangedEvent] - Bedroom_ContactSensor_Open changed from CLOSED to OPEN

At first I was just happy to find some log, but then I noticed the Bedroom_ContactSensor_Open changed from OPEN to CLOSED So yeah, this time it worked.

I still had the websocket listener open but I did not see anything different here

  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:57:49.202',
     lowbattery: false,
     open: false,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:57:50.412',
     lowbattery: false,
     open: false,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:58:00.197',
     lowbattery: false,
     open: true,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }
{ e: 'changed',
  id: '46',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T09:58:01.377',
     lowbattery: false,
     open: true,
     tampered: false },
  t: 'event',
  uniqueid: 'ec:1b:bd:ff:fe:6f:2f:a5-01-0500' }

I’ll make some other tests and let you know if somehow, it break again (it was “working” up to ~14h yesterday and was not updating since in any of my tests)

J-N-K · August 22, 2020, 10:14am

How many sensors and lights do you have? I have an idea what might happen if there are many devices.

The problem is that it can‘t be reproduced easily and different sensors could be affected. If you see something like Couldn't find sensor listener for id in the log, then I can probably fix it. No need to look in older logs, I just introduced it now.

You can try restart org.openhab.binding.deconz and see if you can get it to fail.

ledeste21 · August 22, 2020, 10:22am

I indeed saw some Couldn't find sensor listener for but only for device that I didnt make things to in the openhab conf.
I dont really know how many device I got, something like 14 power plug, 2 switch and 17 sensor at least, as it’s what I was able to count in the phoscon GUI, but I know everything did not appear here.

But yeah, it’s pretty hard to debug this flooded zigbee env.
With the “restart” it still work super fine…

But as said befor, it was already working fine at first. When i setted it up I had done some tests and the status was correctly updated in openhab.
So maybe this is an issue that only appear “after a while” or something?

As I’m not able to reproduce it anymore, I think I’ll not be able to provide any useful information about this
I just hope I did not make some obvious mistake on my side tho…

I’ll let it run like that and let you know if the issue reappear.

If you have any other suggestion, let me know

ledeste21 · August 22, 2020, 5:08pm

Hello back. I have no idea if it’s the same issue, but I’ll take it.
One of my temperature sensor suddenly stop reporting.

It was fine for days, but nothing since today, 4h ago.
At first I tough “maybe it’s just lazy right now” but in the phoscon gui it was up to date So I double check with my new knowledge and here is what I found:

First, the Thing is like:
Thing deconz:temperaturesensor:deconz_bridge:temperaturesensor_06 "Température Bureau" (deconz:deconz:deconz_bridge) @ "Maison" [ uid="00:15:8d:00:04:85:53:a8-01-0402", id="30" ]

I got an item like this:
Number:Temperature Office_Temperature "Temperature" (Home, GF, GF_Office, Temperature_Sensor) {channel="deconz:temperaturesensor:deconz_bridge:temperaturesensor_06:temperature"}

And it look like this in the deconz rest api:

    "30": {
      "config": {
        "battery": 91,
        "offset": 0,
        "on": true,
        "reachable": true
      },
      "ep": 1,
      "etag": "8c8d970d2d7eca502e8a31c5d14d1568",
      "lastseen": "2020-08-22T16:12Z",
      "manufacturername": "LUMI",
      "modelid": "lumi.weather",
      "name": "Multi Sensor bureau",
      "state": {
        "lastupdated": "2020-08-22T16:12:24.616",
        "temperature": 2718
      },
      "swversion": "20191205",
      "type": "ZHATemperature",
      "uniqueid": "00:15:8d:00:04:85:53:a8-01-0402"
    }

I started to listen to the websocket for id 30 and tail the openhab log, then click the sensor “what’s up” button (way easier to debug this one as it is right beside me at least)

I got this in the websocket

  e: 'changed',
  id: '30',
  r: 'sensors',
  t: 'event',
  uniqueid: '00:15:8d:00:04:85:53:a8-01-0402' }
{ e: 'changed',
  id: '30',
  r: 'sensors',
  state:
   { lastupdated: '2020-08-22T17:04:37.686', temperature: 2800 },
  t: 'event',
  uniqueid: '00:15:8d:00:04:85:53:a8-01-0402' }

And this in the openhab log

19:04:37.689 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:humiditysensor:deconz_bridge:humiditysensor_06 received SensorMessage{type='', config=SensorConfig{on=true, reachable=true, battery=91, temperature=null, heatsetpoint=null, mode=null, offset=0}, state=null, e='changed', r='sensors', t='event', id='32', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='00:15:8d:00:04:85:53:a8-01-0405'}
19:04:37.690 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"e":"changed","id":"32","r":"sensors","state":{"humidity":5199,"lastupdated":"2020-08-22T17:04:37.686"},"t":"event","uniqueid":"00:15:8d:00:04:85:53:a8-01-0405"}
19:04:37.692 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:humiditysensor:deconz_bridge:humiditysensor_06 received SensorMessage{type='', config=null, state=SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=5199.0, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=null, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, valve=null, lastupdated='2020-08-22T17:04:37.686', xy=null}, e='changed', r='sensors', t='event', id='32', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='00:15:8d:00:04:85:53:a8-01-0405'}
19:04:37.693 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"config":{"battery":91,"offset":0,"on":true,"reachable":true},"e":"changed","id":"30","r":"sensors","t":"event","uniqueid":"00:15:8d:00:04:85:53:a8-01-0402"}
19:04:37.694 [TRACE] [internal.netutils.WebSocketConnection] - Couldn't find sensor listener for id 30
19:04:37.696 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"e":"changed","id":"30","r":"sensors","state":{"lastupdated":"2020-08-22T17:04:37.686","temperature":2800},"t":"event","uniqueid":"00:15:8d:00:04:85:53:a8-01-0402"}
19:04:37.697 [TRACE] [internal.netutils.WebSocketConnection] - Couldn't find sensor listener for id 30
19:04:37.699 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"config":{"battery":91,"on":true,"reachable":true},"e":"changed","id":"31","r":"sensors","t":"event","uniqueid":"00:15:8d:00:04:85:53:a8-01-0403"}
19:04:37.699 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:pressuresensor:deconz_bridge:pressuresensor_06 received SensorMessage{type='', config=SensorConfig{on=true, reachable=true, battery=91, temperature=null, heatsetpoint=null, mode=null, offset=null}, state=null, e='changed', r='sensors', t='event', id='31', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='00:15:8d:00:04:85:53:a8-01-0403'}
19:04:37.701 [TRACE] [internal.netutils.WebSocketConnection] - Raw data received by websocket: {"e":"changed","id":"31","r":"sensors","state":{"lastupdated":"2020-08-22T17:04:37.686","pressure":1011},"t":"event","uniqueid":"00:15:8d:00:04:85:53:a8-01-0403"}
19:04:37.701 [TRACE] [ternal.handler.SensorBaseThingHandler] - deconz:pressuresensor:deconz_bridge:pressuresensor_06 received SensorMessage{type='', config=null, state=SensorState{dark=null, daylight=null, lightlevel=null, lux=null, temperature=null, humidity=null, open=null, fire=null, water=null, alarm=null, tampered=null, vibration=null, carbonmonoxide=null, pressure=1011, presence=null, power=null, battery=null, consumption=null, voltage=null, current=null, status=null, buttonevent=null, gesture=null, valve=null, lastupdated='2020-08-22T17:04:37.686', xy=null}, e='changed', r='sensors', t='event', id='31', manufacturername='', modelid='', name='', swversion='', ep='', lastseen='null', uniqueid='00:15:8d:00:04:85:53:a8-01-0403'}

(the sensor have multiple id as it act as temperature but also pressure and humidity sensor.)

And yeah, what do you mean Couldn't find sensor listener for id 30 duh?
I did not touch anything else, as I pretty sure a restart would fix that

Does this new data could help in anyway?

J-N-K · August 22, 2020, 5:13pm

Yes. Please try to update once again. I (hopefully) implemented a fix for that.

ledeste21 · August 22, 2020, 5:14pm

with the same command ?
update org.openhab.binding.deconz https://janessa.me/esh/org.openhab.binding.deconz-2.5.8-SNAPSHOT.jar
right ?

ledeste21 · August 22, 2020, 5:16pm

as expected, right after the restart the sensor start reporting again and yoloed to its current state

J-N-K · August 22, 2020, 5:25pm

Let‘s see if it really fixes the issue. There is a map that stores the id and the corresponding thing handler, so that incoming messages can be routed to the correct handler. If many handlers are added at the same time, it could be that one addition is lost. That‘s not predictable, so each time a different handler could be affected (or none at all). That‘s why it happens more often with many handlers.