OH3 - http Binding - Thing stuck in HANDLER_CONFIGURATION_PENDING

Add-ons Bindings
1

Does anybody have any idea why my thing is stuck at Uninitialized - HANDLER_CONFIGURATION_PENDING?

I am configuring the thing via text files (see below). The text file configures two things (for different resources on the same nodejs server). The second thing runs, the first one (nodeserver71) does not.

What is particularly weird, I have another .things file (also below) configuring two things, and that file contains exactly the same thing, except with the “71” replaced by “68”. And that thing is working just fine. So I am really at a loss here…

There is nothing in the logs (except the absence of a line saying Using the secure client for thing 'http:url:ochsnerwaermepumpe for nodeserver71); restart of OH, server reboot, clearing of cache did not change anything.

(I have generally been observing some weird behavior with these things; eg both were working at some point, but then eg I moved the homeserver71 thing from the bottom of the file to the top, and it got stuck in uninitialized state; at some other point I noticed a typo in the nodeserver68, corrected it by removing one letter in the thing name, and after saving the text file that thing was also stuck in uninitialized state; not sure how exactly it came back from that)

First .things file → ochsnerwaermepumpe works, nodeserver71 does not

Thing http:url:nodeserver71 "Node Server .71" [
	baseURL="http://192.xxx.xxx.71:3001/ping",
	refresh=60,
	timeout=20000] {
		Channels:
			Type switch : ServerCheck "Nodejs .71 Server Online" [onValue="ON"]
	}

Thing http:url:ochsnerwaermepumpe "Ochsner Wärmepumpe" [
	baseURL="http://192.xxx.xxx.71:3001/web2comsoap",
	refresh=900,
	delay=250,
	timeout=60000] {
		Channels:
			Type number : Aussentemperatur "Außentemperatur" [ stateExtension="?oid=/1/2/4/119/1", stateTransformation="JSONPATH:$./1/2/4/119/1"]
			Type number : Heizungstemperatur "Heizungstemperatur" [ stateExtension="?oid=/1/2/4/119/5", stateTransformation="JSONPATH:$./1/2/4/119/5"]
			Type number : Innentemperatur "Innentemperatur" [ stateExtension="?oid=/1/2/4/119/3", stateTransformation="JSONPATH:$./1/2/4/119/3"]
			Type number : WPRaustemperatur "Wärmepumpe raus Temperatur" [ stateExtension="?oid=/1/2/1/125/4", stateTransformation="JSONPATH:$./1/2/1/125/4"]
			Type number : WPReintemperatur "Wärmepumpe rein Temperatur" [ stateExtension="?oid=/1/2/1/125/5", stateTransformation="JSONPATH:$./1/2/1/125/5"]
			Type number : Ruecklauftemperatur "Rücklauf Temperatur" [ stateExtension="?oid=/1/2/1/125/3", stateTransformation="JSONPATH:$./1/2/1/125/3"]
			Type number : Vorlauftemperatur "Vorlauf Temperatur" [ stateExtension="?oid=/1/2/1/125/1", stateTransformation="JSONPATH:$./1/2/1/125/1"]
			Type number : Warmwassertemperatur "Warmwassertemperatur" [ stateExtension="?oid=/1/2/6/121/1", stateTransformation="JSONPATH:$./1/2/6/121/1"]
	}

Second .things file → both things work, including virtually identical nodeserver68

Thing http:url:nodeserver68 "Node Server .68" [
	baseURL="http://192.xxx.xxx.68:3001/ping",
	refresh=60,
	timeout=20000] {
		Channels:
			Type switch : ServerCheck "Nodejs .68 Server Online" [onValue="ON", offValue=""]
	}

Thing http:url:fenster "Fensterkontakte" [
	baseURL="http://192.xxx.xxx.68:3001/gpio",
	refresh=300,
	timeout=20000] {
		Channels:
			Type switch : FensterOG "Fenster OG" [ stateTransformation="JSONPATH:FensterOG", onValue="1", offValue="0"]
			Type switch : FensterEG "Fenster EG" [ stateTransformation="JSONPATH:FensterEG", onValue="1", offValue="0"]
	}
2

What behaviour do you observe after a complete restart of openHAB?

3

Not really an answer to the particular question but you can use the Network binding for this. I use it to see whose phones are on the house WiFi and which TVs and game consoles are on but it could work for your application.

4

Rebooting the server does not change anything, nodeserver71 is uninitialized, the other three things are online. Nothing in the log, except Using the secure client for thing 'http:url:nodeserver68'. (for nodeserver68 and and the two other things; but nothing about nodeserver71).

grafik
grafik888×139 4.02 KB

5

Thank you. Yes, I had been considering that, but I actually want to make sure the nodejs server instance on that particular Pi is running. So I also want to cover scenarios where the Pi remains up and running, but the node server has stopped functioning.
So my plan B–if I cannot get this working reliably via http Binding–would be to instead update the nodejs server to send a ping via http post to the OH3 REST API.

6

The stuff that’s different about your misbehaving Thing is that it has more parameters (delay=) and more channels.
Cut it down to bare minimum to narrow the scope of possible mistakes, build from there.

7

Thank you. But that particular thing (ochsnerwaermepumpe) you are referring to is actually working fine. It is the thing above which is having issues, and that thing has only one channel. I’ve also tried out commenting-out that complex thing, but it makes no difference.

8

Just to check, because you say ‘server’ but not explicitly openHAB: you restarted openHAB, and not your node server, correct?

9

Correct, I restarted the Pi running OH3.

10

OK, cheers. The only other thing I can see that’s different between 71 and 68 is that you set an explicit (empty) offValue for 68, but not 71. It would be strange if openHAB was choking on this, but may be worth a try.

Just be wary that openHAB sometimes doesn’t load a saved Things file properly, hence my question about restarting. The other option to force proper loading is to do this.

What do the logs say when your Things file is saved? Any complaints?

11

Yes, thank you, I did play around with adding / removing offValue, but it did not make a difference, either.

Interesting suggestion re: corrupting and then uncorrupting the things file. But alas, also did not yield any results.

This is what the log says when the things file is being saved (after corrupting / uncorrupting the things file):

2021-04-01 22:50:31.381 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'nodeServer71.things'

2021-04-01 22:50:31.423 [INFO ] [nding.http.internal.HttpThingHandler] - Using the secure client for thing 'http:url:ochsnerwaermepumpe'.

As you can see, acknowledgement of the ochsnerwaermepumpe thing, but no comment, neither positive nor negative, re: the nodeserver71 thing.

12

Yeah, seems strange.

If this were me, and I’ve got no clue anymore, I would remove the nodeserver71 Thing from the Things file completely, save, and then restart openHAB.

Then build the Thing again, but this time using the UI to ensure no syntax errors creep in. Once that’s working, then transfer back to the Things file.

13

Well, thanks anyway for your time and consideration! Yes, I did do that at the beginning, building the things from scratch, and it worked for a while for both, actually, but it seems to be an non-stable approach. I think I will instead go with my plan B, ie updating via http post to the OH REST API…

14

Just to conclude: After all the failed attempts to get this working, the thing suddenly decided to start working tonight. I have a backup script that shuts down the OH service, runs a backup, and restarts the OH service every night… And for some reason at that restart I got 2021-04-02 04:06:11.415 [INFO ] [nding.http.internal.HttpThingHandler] - Using the secure client for thing 'http:url:nodeserver71'. in the log. Not that I not had tried service restart or server reboot before.

So bottom-line: it works now. No idea why it did not work, no idea why it started to work again…

15

I’m facing a similar problem. I created 2 things, that are online and working fine until I reboot the system.
After a reboot my HTTP Things stuck with status UNINITIALIZED **HANDLER_CONFIGURATION_PENDING**.

Deleting and re-creating brings Things (and channels) back online. After rebooting the system same error occurs.

I set logging level to “DEBUG” but I don’t really understand what’s related to the decribed problem.

Thanks for your help!

2021-06-29 22:34:49.802 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER: --> IN_NAME
2021-06-29 22:34:49.816 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:X-Content-Type-Options --> VALUE
2021-06-29 22:34:49.816 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:X-Content-Type-Options --> IN_VALUE
2021-06-29 22:34:49.816 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:X-Content-Type-Options --> FIELD
2021-06-29 22:34:49.817 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER: --> IN_NAME
2021-06-29 22:34:49.817 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Content-Security-Policy --> VALUE
2021-06-29 22:34:49.817 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Content-Security-Policy --> IN_VALUE
2021-06-29 22:34:49.818 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Content-Security-Policy --> FIELD
2021-06-29 22:34:49.818 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER --> CHUNKED_CONTENT
2021-06-29 22:34:49.818 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response headers HttpResponse[HTTP/1.1 200 OK]@3c52f0
Cache-Control: no-cache
Connection: keep-alive
Transfer-Encoding: chunked
Content-Type: text/xml; charset=UTF-8
Expires: -1
Pragma: no-cache
Keep-Alive: timeout=60, max=300
X-Frame-Options: SAMEORIGIN
X-XSS-Protection: 1; mode=block
X-Content-Type-Options: nosniff
Content-Security-Policy: default-src 'none'; connect-src 'self'; font-src 'self'; frame-src https://service.avm.de https://help.avm.de https://www.avm.de https://avm.de https://assets.avm.de https://clickonce.avm.de http://clickonce.avm.de http://download.avm.de https://download.avm.de 'self'; img-src 'self' https://tv.avm.de https://help.avm.de/images/ http://help.avm.de/images/ data:; script-src 'self' 'unsafe-inline'; style-src 'self' 'unsafe-inline'; frame-ancestors 'self'; media-src 'self'
2021-06-29 22:34:49.819 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response demand=1/1, resume=false
2021-06-29 22:34:49.819 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response headers hasDemand=true HttpResponse[HTTP/1.1 200 OK]@3c52f0
2021-06-29 22:34:49.820 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CHUNKED_CONTENT --> CHUNK_SIZE
2021-06-29 22:34:49.820 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CHUNK_SIZE --> CHUNK
2021-06-29 22:34:49.821 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response content HttpResponse[HTTP/1.1 200 OK]@3c52f0
DirectByteBufferR@1e49bdb[p=799,l=854,c=16384,r=55]={HTTP/1.1 ...\n\r\n37\r\n<<<<devicelist version="1" f...n="7.27"></devicelist>\n>>>\r\n0\r\n\r\nSe...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.821 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response demand=1/1, resume=false
2021-06-29 22:34:49.821 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response content HttpResponse[HTTP/1.1 200 OK]@3c52f0, hasDemand=true
2021-06-29 22:34:49.822 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CHUNK --> CHUNKED_CONTENT
2021-06-29 22:34:49.822 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CHUNKED_CONTENT --> CHUNK_SIZE
2021-06-29 22:34:49.822 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - CHUNK_SIZE --> TRAILER
2021-06-29 22:34:49.823 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - TRAILER --> END
2021-06-29 22:34:49.823 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - reset HttpParser{s=END,0 of -1}
2021-06-29 22:34:49.823 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - END --> START
2021-06-29 22:34:49.824 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response success HttpResponse[HTTP/1.1 200 OK]@3c52f0
2021-06-29 22:34:49.824 [DEBUG] [rg.eclipse.jetty.client.HttpExchange] - Terminated response for HttpExchange@17c7d84{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@fc6908[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@3c52f0[TERMINATED/null]}, result: Result[HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@fc6908 > HttpResponse[HTTP/1.1 200 OK]@3c52f0] null
2021-06-29 22:34:49.824 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response complete HttpResponse[HTTP/1.1 200 OK]@3c52f0
2021-06-29 22:34:49.825 [DEBUG] [org.eclipse.jetty.client.HttpChannel] - HttpExchange@17c7d84{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@fc6908[TERMINATED/null] res=HttpResponse[HTTP/1.1 200 OK]@3c52f0[TERMINATED/null]} disassociated true from HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:34:49.826 [DEBUG] [eclipse.jetty.client.HttpDestination] - Released HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=-,flush=-,to=38/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:34:49.827 [DEBUG] [.jetty.client.AbstractConnectionPool] - Released (true) Entry@155aff9{IDLE, usage=280, multiplex=0/1, pooled=HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=-,flush=-,to=38/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]} Pool@13e08ea[size=1 closed=false]
2021-06-29 22:34:49.827 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Request/Response succeeded: Result[HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@fc6908 > HttpResponse[HTTP/1.1 200 OK]@3c52f0] null
2021-06-29 22:34:49.828 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Parse result=false, failed=false
2021-06-29 22:34:49.828 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Parse complete=true, remaining 0 HttpParser{s=START,0 of -1}
2021-06-29 22:34:49.829 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - queue org.eclipse.jetty.server.AsyncContextState$1@99005c startThread=0
2021-06-29 22:34:49.829 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - run org.eclipse.jetty.server.AsyncContextState$1@99005c in QueuedThreadPool[qtp23105584]@1609030{STARTED,2<=9<=50,i=0,r=-1,q=0}[ReservedThreadExecutor@1178d0f{s=2/4,p=0}]
2021-06-29 22:34:49.829 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@150d9d0[p=0,l=7,c=7,r=7]={<<<event: >>>})
2021-06-29 22:34:49.829 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 0 DirectByteBuffer@7d18b8[p=0,l=0,c=16384,r=0]={<<<>>>HTTP/1.1 ...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.830 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=7,c=32768,r=7]={<<<event: >>>message\nd...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.830 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Read 0 bytes in RetainableByteBuffer@17691c6{DirectByteBuffer@7d18b8[p=0,l=0,c=16384,r=0]={<<<>>>HTTP/1.1 ...\x00\x00\x00\x00\x00\x00\x00},r=1} from SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=-,flush=-,to=42/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:34:49.830 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@3a9ade[p=0,l=7,c=7,r=7]={<<<message>>>})
2021-06-29 22:34:49.830 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Released RetainableByteBuffer@17691c6{DirectByteBuffer@7d18b8[p=0,l=0,c=16384,r=0]={<<<>>>HTTP/1.1 ...\x00\x00\x00\x00\x00\x00\x00},r=0}
2021-06-29 22:34:49.830 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=14,c=32768,r=14]={<<<event: message>>>\ndata: {"...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.831 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@b16f35[p=0,l=1,c=1,r=1]={<<<\n>>>})
2021-06-29 22:34:49.831 [DEBUG] [.eclipse.jetty.io.AbstractConnection] - fillInterested HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=-,flush=-,to=43/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:34:49.831 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=15,c=32768,r=15]={<<<event: message\n>>>data: {"t...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.832 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@f5112f[p=0,l=6,c=6,r=6]={<<<data: >>>})
2021-06-29 22:34:49.832 [DEBUG] [org.eclipse.jetty.io.FillInterest   ] - interested FillInterest@d5496b{AC.ReadCB@1005c0f{HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]}}
2021-06-29 22:34:49.832 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=21,c=32768,r=21]={<<<event: message\ndata: >>>{"topic":...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.832 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - changeInterests p=false 0->1 for SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=0/0}{io=0/1,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:34:49.833 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@1c0d8b8[p=0,l=157,c=157,r=157]={<<<{"topic":"openhab/things/..."ThingStatusInfoEvent"}>>>})
2021-06-29 22:34:49.833 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Queued change lazy=false org.eclipse.jetty.io.ChannelEndPoint$$Lambda$1011/0x970b7c28@4e094 on ManagedSelector@1608a0a{STARTED} id=1 keys=1 selected=0 updates=0
2021-06-29 22:34:49.833 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=178,c=32768,r=178]={<<<event: message\ndata: {"to..."ThingStatusInfoEvent"}>>>/>\n <path...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.833 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Wakeup on submit ManagedSelector@1608a0a{STARTED} id=1 keys=1 selected=0 updates=1
2021-06-29 22:34:49.834 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 woken with none selected
2021-06-29 22:34:49.834 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - sendResponse info=null content=DirectByteBuffer@71216a[p=0,l=178,c=32768,r=178]={<<<event: message\ndata: {"to..."ThingStatusInfoEvent"}>>>/>\n <path...\x00\x00\x00\x00\x00\x00\x00} complete=false committing=false callback=Blocker@90ad62{null}
2021-06-29 22:34:49.834 [DEBUG] [y.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@4a8b80{s=2/4,p=0}@c92fe8 waiting
2021-06-29 22:34:49.834 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 woken up from select, 0/0/1 selected
2021-06-29 22:34:49.834 [DEBUG] [.eclipse.jetty.server.HttpConnection] - generate: NEED_CHUNK for SendCallback@1190eb9[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1184574] (null,[p=0,l=178,c=32768,r=178],false)@COMMITTED
2021-06-29 22:34:49.835 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 processing 0 keys, 1 updates
2021-06-29 22:34:49.835 [DEBUG] [.eclipse.jetty.server.HttpConnection] - generate: FLUSH for SendCallback@1190eb9[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1184574] (null,[p=0,l=178,c=32768,r=178],false)@COMMITTED
2021-06-29 22:34:49.835 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - updateable 1
2021-06-29 22:34:49.835 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@16c82d2{IDLE}->null [HeapByteBuffer@1d1e947[p=0,l=6,c=1024,r=6]={<<<\r\nB2\r\n>>>\n\n\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},DirectByteBuffer@71216a[p=0,l=178,c=32768,r=178]={<<<event: message\ndata: {"to..."ThingStatusInfoEvent"}>>>/>\n <path...\x00\x00\x00\x00\x00\x00\x00}]
2021-06-29 22:34:49.835 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - update org.eclipse.jetty.io.ChannelEndPoint$$Lambda$1011/0x970b7c28@4e094
2021-06-29 22:34:49.836 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@16c82d2{WRITING}->null:IDLE-->WRITING
2021-06-29 22:34:49.836 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - Key interests updated 0 -> 1 on SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=4/0}{io=1/1,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:34:49.836 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 184 SocketChannelEndPoint@12d45e1{l=/192.168.178.25:8080,r=/192.168.178.134:61859,OPEN,fill=-,flush=W,to=15015/30000}{io=0/0,kio=0,kro=1}->HttpConnection@814c2e[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@1decda6{s=COMMITTED}]=>HttpChannelOverHttp@ad016c{s=HttpChannelState@10a4a45{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=3,c=false/false,a=WAITING,uri=//openhab:8080/rest/events?topics=openhab/things/*/*,openhab/links/*/*,age=3433470}
2021-06-29 22:34:49.836 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - updates 0
2021-06-29 22:34:49.837 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - Flushed=true written=184 remaining=0 WriteFlusher@16c82d2{WRITING}->null
2021-06-29 22:34:49.837 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 waiting with 1 keys
2021-06-29 22:34:49.837 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@16c82d2{IDLE}->null:WRITING-->IDLE
2021-06-29 22:34:49.838 [DEBUG] [.eclipse.jetty.server.HttpConnection] - generate: DONE for SendCallback@1190eb9[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1184574] (null,[p=178,l=178,c=32768,r=0],false)@COMMITTED
2021-06-29 22:34:49.838 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - onWriteComplete(false,null) s=OPEN,api=BLOCKED,sc=false,e=null->s=OPEN,api=BLOCKING,sc=false,e=null c=null cb=null w=false
2021-06-29 22:34:49.839 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@dd5765[p=0,l=1,c=1,r=1]={<<<\n>>>})
2021-06-29 22:34:49.839 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=1,c=32768,r=1]={<<<\n>>>vent: mes...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.839 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array HeapByteBuffer@795e78[p=0,l=1,c=1,r=1]={<<<\n>>>})
2021-06-29 22:34:49.840 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush DirectByteBuffer@71216a[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: mess...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:34:49.840 [DEBUG] [org.eclipse.jetty.server.HttpChannel] - sendResponse info=null content=DirectByteBuffer@71216a[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: mess...\x00\x00\x00\x00\x00\x00\x00} complete=false committing=false callback=Blocker@90ad62{null}
2021-06-29 22:34:49.841 [DEBUG] [.eclipse.jetty.server.HttpConnection] - generate: NEED_CHUNK for SendCallback@1190eb9[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1a14497] (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
2021-06-29 22:34:49.841 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SocketChannelEndPoint@12d45e1{l=/192.168.178.25:8080,r=/192.168.178.134:61859,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=1}->HttpConnection@814c2e[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@1decda6{s=COMMITTED}]=>HttpChannelOverHttp@ad016c{s=HttpChannelState@10a4a45{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=3,c=false/false,a=WAITING,uri=//openhab:8080/rest/events?topics=openhab/things/*/*,openhab/links/*/*,age=3433475} idle timeout check, elapsed: 4 ms, remaining: 29996 ms
2021-06-29 22:34:49.841 [DEBUG] [.eclipse.jetty.server.HttpConnection] - generate: FLUSH for SendCallback@1190eb9[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1a14497] (null,[p=0,l=2,c=32768,r=2],false)@COMMITTED
2021-06-29 22:34:49.842 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@16c82d2{IDLE}->null [HeapByteBuffer@1d1e947[p=0,l=5,c=1024,r=5]={<<<\r\n2\r\n>>>\n\n\n\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},DirectByteBuffer@71216a[p=0,l=2,c=32768,r=2]={<<<\n\n>>>ent: mess...\x00\x00\x00\x00\x00\x00\x00}]
2021-06-29 22:34:49.842 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@16c82d2{WRITING}->null:IDLE-->WRITING
2021-06-29 22:34:49.843 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 7 SocketChannelEndPoint@12d45e1{l=/192.168.178.25:8080,r=/192.168.178.134:61859,OPEN,fill=-,flush=W,to=6/30000}{io=0/0,kio=0,kro=1}->HttpConnection@814c2e[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@1decda6{s=COMMITTED}]=>HttpChannelOverHttp@ad016c{s=HttpChannelState@10a4a45{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=3,c=false/false,a=WAITING,uri=//openhab:8080/rest/events?topics=openhab/things/*/*,openhab/links/*/*,age=3433477}
2021-06-29 22:34:49.844 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - Flushed=true written=7 remaining=0 WriteFlusher@16c82d2{WRITING}->null
2021-06-29 22:34:49.844 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@16c82d2{IDLE}->null:WRITING-->IDLE
2021-06-29 22:34:49.845 [DEBUG] [.eclipse.jetty.server.HttpConnection] - generate: DONE for SendCallback@1190eb9[PROCESSING][i=null,cb=org.eclipse.jetty.server.HttpChannel$SendCallback@1a14497] (null,[p=2,l=2,c=32768,r=0],false)@COMMITTED
2021-06-29 22:34:49.846 [DEBUG] [org.eclipse.jetty.server.HttpOutput ] - onWriteComplete(false,null) s=OPEN,api=BLOCKED,sc=false,e=null->s=OPEN,api=BLOCKING,sc=false,e=null c=null cb=null w=false
2021-06-29 22:34:49.846 [DEBUG] [e.jetty.util.thread.QueuedThreadPool] - ran org.eclipse.jetty.server.AsyncContextState$1@99005c in QueuedThreadPool[qtp23105584]@1609030{STARTED,2<=9<=50,i=0,r=-1,q=0}[ReservedThreadExecutor@1178d0f{s=2/4,p=0}]
2021-06-29 22:34:52.115 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SocketChannelEndPoint@102a639{l=/192.168.178.25:8080,r=/192.168.178.134:61856,OPEN,fill=-,flush=-,to=30000/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3bb4c9[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@f7b1d1{s=COMMITTED}]=>HttpChannelOverHttp@162e13a{s=HttpChannelState@9ee70c{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=1,c=false/false,a=WAITING,uri=//openhab:8080/rest/events/states,age=3436235} idle timeout check, elapsed: 30000 ms, remaining: 0 ms
2021-06-29 22:34:52.117 [DEBUG] [org.eclipse.jetty.io.IdleTimeout    ] - SocketChannelEndPoint@102a639{l=/192.168.178.25:8080,r=/192.168.178.134:61856,OPEN,fill=-,flush=-,to=30002/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3bb4c9[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@f7b1d1{s=COMMITTED}]=>HttpChannelOverHttp@162e13a{s=HttpChannelState@9ee70c{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=1,c=false/false,a=WAITING,uri=//openhab:8080/rest/events/states,age=3436237} idle timeout expired
2021-06-29 22:34:52.118 [DEBUG] [org.eclipse.jetty.io.FillInterest   ] - onFail FillInterest@12e98c4{null}
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2021-06-29 22:34:52.121 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - ignored: WriteFlusher@1346a5c{IDLE}->null
java.util.concurrent.TimeoutException: Idle timeout expired: 30000/30000 ms
	at org.eclipse.jetty.io.IdleTimeout.checkIdleTimeout(IdleTimeout.java:171) ~[?:?]
	at org.eclipse.jetty.io.IdleTimeout.idleCheck(IdleTimeout.java:113) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
	at java.lang.Thread.run(Thread.java:829) [?:?]
2021-06-29 22:34:52.125 [DEBUG] [rg.eclipse.jetty.io.AbstractEndPoint] - Ignored idle endpoint SocketChannelEndPoint@102a639{l=/192.168.178.25:8080,r=/192.168.178.134:61856,OPEN,fill=-,flush=-,to=30009/30000}{io=0/0,kio=0,kro=1}->HttpConnection@3bb4c9[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@f7b1d1{s=COMMITTED}]=>HttpChannelOverHttp@162e13a{s=HttpChannelState@9ee70c{s=WAITING rs=ASYNC os=COMMITTED is=IDLE awp=false se=false i=false al=2},r=1,c=false/false,a=WAITING,uri=//openhab:8080/rest/events/states,age=3436244}
2021-06-29 22:35:04.231 [DEBUG] [clipse.jetty.client.HttpConversation] - Exchanges in conversation 1, override=null, listeners=[org.eclipse.jetty.client.HttpRequest$14@1bf314b, org.eclipse.jetty.client.HttpRequest$15@1bc0ada, org.openhab.binding.avmfritz.internal.hardware.FritzAhaContentExchange@116d3c5]
2021-06-29 22:35:04.232 [DEBUG] [eclipse.jetty.client.HttpDestination] - Queued HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac for HttpDestination[http://192.168.178.1]@1f4ee52,queue=1,pool=DuplexConnectionPool@162a8c3[c=0/1/2,a=0,i=1,q=1]
2021-06-29 22:35:04.233 [DEBUG] [.jetty.client.AbstractConnectionPool] - Acquiring create=true on DuplexConnectionPool@162a8c3[c=0/1/2,a=0,i=1,q=1]
2021-06-29 22:35:04.235 [DEBUG] [.jetty.client.AbstractConnectionPool] - Activated Entry@155aff9{INUSE, usage=281, multiplex=1/1, pooled=HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=14402/0}{io=1/1,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]} Pool@13e08ea[size=1 closed=false]
2021-06-29 22:35:04.236 [DEBUG] [eclipse.jetty.client.HttpDestination] - Processing exchange HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[PENDING/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]} on HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=14404/0}{io=1/1,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=null)[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]] of HttpDestination[http://192.168.178.1]@1f4ee52,queue=0,pool=DuplexConnectionPool@162a8c3[c=0/1/2,a=1,i=0,q=0]
2021-06-29 22:35:04.237 [DEBUG] [.eclipse.jetty.client.HttpConnection] - Normalizing true HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac
2021-06-29 22:35:04.239 [DEBUG] [org.eclipse.jetty.client.HttpChannel] - HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[PENDING/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]} associated true to HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[PENDING/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:35:04.240 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Request begin HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac
2021-06-29 22:35:04.241 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Request headers HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac
Accept-Encoding: gzip
User-Agent: Jetty/9.4.40.v20210413
Host: 192.168.178.1
2021-06-29 22:35:04.242 [DEBUG] [org.eclipse.jetty.client.HttpContent] - Advanced content to last chunk
2021-06-29 22:35:04.242 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Generated headers (-1 bytes), chunk (-1 bytes), content (0 bytes) - NEED_HEADER/HttpGenerator@18c0f76{s=START}
2021-06-29 22:35:04.243 [DEBUG] [org.eclipse.jetty.http.HttpGenerator] - generateHeaders GET{u=/webservices/homeautoswitch.lua?switchcmd=getdevicelistinfos&sid=4b48d52ffa09ccd0,HTTP/1.1,h=3,cl=-1} last=true content=HeapByteBuffer@12a0e44[p=0,l=0,c=0,r=0]={<<<>>>}
2021-06-29 22:35:04.244 [DEBUG] [org.eclipse.jetty.http.HttpGenerator] - Accept-Encoding: gzip
User-Agent: Jetty/9.4.40.v20210413
Host: 192.168.178.1


2021-06-29 22:35:04.244 [DEBUG] [org.eclipse.jetty.http.HttpGenerator] - NO_CONTENT
2021-06-29 22:35:04.245 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Generated headers (178 bytes), chunk (-1 bytes), content (0 bytes) - FLUSH/HttpGenerator@18c0f76{s=COMPLETING}
2021-06-29 22:35:04.245 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - write: WriteFlusher@1b2e33a{IDLE}->null [HeapByteBuffer@1f6bad0[p=0,l=178,c=4096,r=178]={<<<GET /webservices/homeauto...Host: 192.168.178.1\r\n\r\n>>>\n\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@13737e8[p=0,l=0,c=0,r=0]={<<<>>>},HeapByteBuffer@12a0e44[p=0,l=0,c=0,r=0]={<<<>>>}]
2021-06-29 22:35:04.246 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1b2e33a{WRITING}->null:IDLE-->WRITING
2021-06-29 22:35:04.247 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - flushed 178 SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=W,to=14415/0}{io=1/1,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[PENDING/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=HEADERS,snd=SENDING,failure=null)[HttpGenerator@18c0f76{s=COMPLETING}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:35:04.248 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - Flushed=true written=178 remaining=0 WriteFlusher@1b2e33a{WRITING}->null
2021-06-29 22:35:04.249 [DEBUG] [org.eclipse.jetty.io.WriteFlusher   ] - update WriteFlusher@1b2e33a{IDLE}->null:WRITING-->IDLE
2021-06-29 22:35:04.249 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Generated headers (-1 bytes), chunk (-1 bytes), content (-1 bytes) - DONE/HttpGenerator@18c0f76{s=END}
2021-06-29 22:35:04.250 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Request committed HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac
2021-06-29 22:35:04.250 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Request success HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac
2021-06-29 22:35:04.251 [DEBUG] [rg.eclipse.jetty.client.HttpExchange] - Terminated request for HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]}, result: null
2021-06-29 22:35:04.252 [DEBUG] [org.eclipse.jetty.client.HttpSender ] - Terminating request HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac
2021-06-29 22:35:04.705 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 woken up from select, 1/1/1 selected
2021-06-29 22:35:04.706 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 processing 1 keys, 0 updates
2021-06-29 22:35:04.707 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - selected 1 channel=java.nio.channels.SocketChannel[connected local=/192.168.178.25:51854 remote=/192.168.178.1:80], selector=sun.nio.ch.EPollSelectorImpl@401dc8, interestOps=1, readyOps=1 SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=458/0}{io=1/1,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]] 
2021-06-29 22:35:04.709 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - onSelected 1->0 r=true w=false for SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=460/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:35:04.711 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - task CEP:SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=461/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]:runFillable:BLOCKING
2021-06-29 22:35:04.712 [DEBUG] [y.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@4a8b80{s=2/4,p=0} tryExecute EatWhatYouKill@1e3cd39/SelectorProducer@1f9d4ab/PRODUCING/p=false/QueuedThreadPool[OH-httpClient-common]@1e79904{STARTED,10<=10<=40,i=4,r=-1,q=0}[ReservedThreadExecutor@4a8b80{s=2/4,p=0}][pc=0,pic=0,pec=1,epc=281]@2021-06-29T22:35:04.712516+02:00
2021-06-29 22:35:04.714 [DEBUG] [y.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@4a8b80{s=1/4,p=0}@c92fe8 offer EatWhatYouKill@1e3cd39/SelectorProducer@1f9d4ab/PRODUCING/p=false/QueuedThreadPool[OH-httpClient-common]@1e79904{STARTED,10<=10<=40,i=4,r=-1,q=0}[ReservedThreadExecutor@4a8b80{s=1/4,p=0}][pc=0,pic=0,pec=1,epc=281]@2021-06-29T22:35:04.714003+02:00
2021-06-29 22:35:04.715 [DEBUG] [y.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@4a8b80{s=1/4,p=0}@c92fe8 task=EatWhatYouKill@1e3cd39/SelectorProducer@1f9d4ab/IDLE/p=true/QueuedThreadPool[OH-httpClient-common]@1e79904{STARTED,10<=10<=40,i=4,r=-1,q=0}[ReservedThreadExecutor@4a8b80{s=1/4,p=0}][pc=0,pic=0,pec=1,epc=281]@2021-06-29T22:35:04.715644+02:00
2021-06-29 22:35:04.716 [DEBUG] [.util.thread.strategy.EatWhatYouKill] - EatWhatYouKill@1e3cd39/SelectorProducer@1f9d4ab/IDLE/p=true/QueuedThreadPool[OH-httpClient-common]@1e79904{STARTED,10<=10<=40,i=4,r=-1,q=0}[ReservedThreadExecutor@4a8b80{s=1/4,p=0}][pc=0,pic=0,pec=1,epc=281]@2021-06-29T22:35:04.715316+02:00 m=EXECUTE_PRODUCE_CONSUME t=CEP:SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=467/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]:runFillable:BLOCKING/BLOCKING
2021-06-29 22:35:04.716 [DEBUG] [.util.thread.strategy.EatWhatYouKill] - EatWhatYouKill@1e3cd39/SelectorProducer@1f9d4ab/IDLE/p=true/QueuedThreadPool[OH-httpClient-common]@1e79904{STARTED,10<=10<=40,i=4,r=-1,q=0}[ReservedThreadExecutor@4a8b80{s=1/4,p=0}][pc=0,pic=0,pec=1,epc=282]@2021-06-29T22:35:04.716587+02:00 tryProduce true
2021-06-29 22:35:04.717 [DEBUG] [org.eclipse.jetty.io.FillInterest   ] - fillable FillInterest@d5496b{AC.ReadCB@1005c0f{HttpConnectionOverHTTP@1005c0f::SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=FI,flush=-,to=468/0}{io=1/0,kio=1,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]}}
2021-06-29 22:35:04.717 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - updateable 0
2021-06-29 22:35:04.717 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - updates 0
2021-06-29 22:35:04.717 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Acquired RetainableByteBuffer@9c17f7{DirectByteBuffer@7d18b8[p=0,l=0,c=16384,r=0]={<<<>>>HTTP/1.1 ...\x00\x00\x00\x00\x00\x00\x00},r=1}
2021-06-29 22:35:04.718 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START DirectByteBuffer@7d18b8[p=0,l=0,c=16384,r=0]={<<<>>>HTTP/1.1 ...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:35:04.718 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Parse result=false, failed=false
2021-06-29 22:35:04.718 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - Key interests updated 1 -> 0 on SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=-,flush=-,to=469/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:35:04.719 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Parse complete=false, remaining 0 HttpParser{s=START,0 of -1}
2021-06-29 22:35:04.719 [DEBUG] [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.EPollSelectorImpl@401dc8 waiting with 1 keys
2021-06-29 22:35:04.720 [DEBUG] [org.eclipse.jetty.io.ChannelEndPoint] - filled 861 DirectByteBuffer@7d18b8[p=0,l=861,c=16384,r=861]={<<<HTTP/1.1 200 OK\r\nCache-Co..."></devicelist>\n\r\n0\r\n\r\n>>>SessionIn...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:35:04.721 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Read 861 bytes in RetainableByteBuffer@9c17f7{DirectByteBuffer@7d18b8[p=0,l=861,c=16384,r=861]={<<<HTTP/1.1 200 OK\r\nCache-Co..."></devicelist>\n\r\n0\r\n\r\n>>>SessionIn...\x00\x00\x00\x00\x00\x00\x00},r=1} from SocketChannelEndPoint@1c7bc1f{l=/192.168.178.25:51854,r=/192.168.178.1:80,OPEN,fill=-,flush=-,to=0/0}{io=0/0,kio=0,kro=1}->HttpConnectionOverHTTP@1005c0f(l:/192.168.178.25:51854 <-> r:/192.168.178.1:80,closed=false)=>HttpChannelOverHTTP@fab624(exchange=HttpExchange@d06388{req=HttpRequest[GET /webservices/homeautoswitch.lua HTTP/1.1]@312dac[TERMINATED/null] res=HttpResponse[null 0 null]@1a95b12[PENDING/null]})[send=HttpSenderOverHTTP@1eb7590(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@18c0f76{s=START}],recv=HttpReceiverOverHTTP@1779277(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]
2021-06-29 22:35:04.721 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - parseNext s=START DirectByteBuffer@7d18b8[p=0,l=861,c=16384,r=861]={<<<HTTP/1.1 200 OK\r\nCache-Co..."></devicelist>\n\r\n0\r\n\r\n>>>SessionIn...\x00\x00\x00\x00\x00\x00\x00}
2021-06-29 22:35:04.722 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - START --> RESPONSE_VERSION
2021-06-29 22:35:04.722 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - RESPONSE_VERSION --> SPACE1
2021-06-29 22:35:04.723 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE1 --> STATUS
2021-06-29 22:35:04.723 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - STATUS --> SPACE2
2021-06-29 22:35:04.723 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - SPACE2 --> REASON
2021-06-29 22:35:04.724 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - REASON --> HEADER
2021-06-29 22:35:04.724 [DEBUG] [clipse.jetty.client.HttpConversation] - Exchanges in conversation 1, override=null, listeners=[org.eclipse.jetty.client.HttpRequest$14@1bf314b, org.eclipse.jetty.client.HttpRequest$15@1bc0ada, org.openhab.binding.avmfritz.internal.hardware.FritzAhaContentExchange@116d3c5]
2021-06-29 22:35:04.725 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response begin HttpResponse[HTTP/1.1 200 OK]@1a95b12
2021-06-29 22:35:04.725 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Cache-Control: no-cache --> IN_VALUE
2021-06-29 22:35:04.726 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Cache-Control: no-cache --> FIELD
2021-06-29 22:35:04.726 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Connection: keep-alive --> IN_VALUE
2021-06-29 22:35:04.726 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Connection: keep-alive --> FIELD
2021-06-29 22:35:04.727 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Transfer-Encoding: chunked --> IN_VALUE
2021-06-29 22:35:04.727 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Transfer-Encoding: chunked --> FIELD
2021-06-29 22:35:04.728 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Content-Type: text/xml; charset=UTF-8 --> IN_VALUE
2021-06-29 22:35:04.728 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Content-Type: text/xml; charset=UTF-8 --> FIELD
2021-06-29 22:35:04.729 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Expires --> VALUE
2021-06-29 22:35:04.729 [DEBUG] [org.eclipse.jetty.http.HttpParser   ] - HEADER:Expires --> IN_VALUE

openHAB 3.1.0
HTTP Binding 3.1.0

16

I have the same problem. Thing created, thing is online, channel created and working. Restarting OpenHAB leads to thing being stuck in UNITIALIZED, HANDLER_CONFIGURATION_PENDING.

Deleting the thing and recreating leads to a working thing until the next OpenHAB reboot.

Is there any news on this problem?

17

I had the same problem with the described behaviour of an http thing in openHAB 3.2.

In my case this was caused by a missing “OffValue” in a switch channel. This worked fine when created, but after reboot the thing stuck with status UNITIALIZED, HANDLER_CONFIGURATION_PENDING.

I removed step by step other channels of the thing without luck. Then I recognized that in one channel the “OffValue” was not specified. This seems to be now mandatory, but I upgraded from 2.6 so maybe in that version the binding reacted different. After setting this “OffValue” to OFF, the thing with 4 channels immediately got online and survived several reboots without problems.

So it seems that some silent errors with configured parameters may prevent an http thing from successfully getting online.

3 Likes