Web Socket Error on AmazonEchoControl binding every 65 seconds

helmut · June 13, 2020, 8:50am

Thanks for pointing this out, @olialb .

I checked my /etc/default/openhab2, in my case EXTRA_JAVA_OPTS was still there after the crash. I “only” lost all my Things. Items and everything else (as far as I checked) were still there.

One assumption:
One of my bindings (Somfy Tahoma) regularly updates Things for reasons I haven’t understood yet, although nothing in the Things has changed. Probably a full heap, “changed” Things and the attempt to write the “new” Things to disk again produced the loss of my configuration.

I have reinstalled the Echo binding for a few hours just to see, what will happen. Memory usage went up by ~100MB / hour. Deinstalled again, memory consumption stable again.

Wikibear · June 13, 2020, 8:58am

Opened a ticket at gitbhub:

To prevent next crash i stop binding via Karaf.

essjay · June 13, 2020, 9:02am

Just a ‘me too’…
OH 2.5.5
RPi 3B

I will try stopping the binding but of course will lose some functionality.
Main reason I use OH is for its Amazon Echo interoperability.

Overnight Out of Memory
EchoControl binding web socket error every 65s
No configuration corruption

Wikibear · June 13, 2020, 9:12am

This happens in past and no one fix it, 'cause of an issue on amazon server side.
I think something like this must prevent in code that openhab didn’t crash if binding not work or if there is an issue with amazon server.

olialb · June 13, 2020, 9:28am

I stopped the amazan echo controll binding now in karaf console and the memory consumption ist stable and websocket error message gone.
I can confirm: There is a memory leak.

@Wikibear: Thanks for opening a ticket. I totally agree. I hope this time it will be fixed!

detond09 · June 13, 2020, 11:08am

Same issues here on Raspbian with 2.5.5. Waiting for the fix.

essjay · June 13, 2020, 12:06pm

…as expected
disabled binding
no errors

just loss of functionality

olialb · June 13, 2020, 12:09pm

@essjay, yes I miss it already …

J-N-K · June 13, 2020, 2:09pm

Please set jetty to DEBUG mode and show what happens before the exception. It seems to be problem with jetty not being able to close the session

memphiz · June 13, 2020, 2:22pm

2020-06-13 16:17:44.201 [DEBUG] [eclipse.jetty.client.HttpDestination] - Closed HttpDestination[wss://dp-gw-na.amazon.de:443]@74ec1d,queue=0,pool=DuplexConnectionPool@4a3640[c=1/64,a=1,i=0]

2020-06-13 16:17:44.204 [DEBUG] [rg.eclipse.jetty.client.HttpExchange] - Failed HttpExchange@c83c91 req=TERMINATED/null@null res=COMPLETED/java.nio.channels.AsynchronousCloseException@1ba92de: req=false/rsp=true {}

2020-06-13 16:17:44.206 [DEBUG] [org.eclipse.jetty.http.HttpParser ] - close HttpParser{s=START,0 of -1}

2020-06-13 16:17:44.209 [DEBUG] [org.eclipse.jetty.http.HttpParser ] - START --> CLOSE

2020-06-13 16:17:44.212 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response failure HttpResponse[null 0 null]@17d7b19 HttpExchange@c83c91 req=TERMINATED/null@null res=COMPLETED/java.nio.channels.AsynchronousCloseException@1ba92de on HttpChannelOverHTTP@1c6b8d6(exchange=HttpExchange@c83c91 req=TERMINATED/null@null res=COMPLETED/java.nio.channels.AsynchronousCloseException@1ba92de)[send=HttpSenderOverHTTP@5cd40f(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@5dbca6{s=START}],recv=HttpReceiverOverHTTP@14aa869(rsp=FAILURE,failure=java.nio.channels.AsynchronousCloseException)[HttpParser{s=CLOSE,0 of -1}]]: {}

2020-06-13 16:17:44.215 [DEBUG] [rg.eclipse.jetty.client.HttpExchange] - Terminated response for HttpExchange@c83c91 req=TERMINATED/null@null res=TERMINATED/java.nio.channels.AsynchronousCloseException@1ba92de, result: Result[HttpRequest[GET / HTTP/1.1]@617d0e > HttpResponse[null 0 null]@17d7b19] java.nio.channels.AsynchronousCloseException

2020-06-13 16:17:44.217 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Response complete HttpResponse[null 0 null]@17d7b19

2020-06-13 16:17:44.220 [DEBUG] [org.eclipse.jetty.client.HttpChannel] - HttpExchange@c83c91 req=TERMINATED/null@null res=TERMINATED/java.nio.channels.AsynchronousCloseException@1ba92de disassociated true from HttpChannelOverHTTP@1c6b8d6(exchange=null)[send=HttpSenderOverHTTP@5cd40f(req=QUEUED,snd=COMPLETED,failure=null)[HttpGenerator@5dbca6{s=START}],recv=HttpReceiverOverHTTP@14aa869(rsp=FAILURE,failure=java.nio.channels.AsynchronousCloseException)[HttpParser{s=CLOSE,0 of -1}]]

2020-06-13 16:17:44.223 [DEBUG] [org.eclipse.jetty.client.HttpChannel] - Closing, reason: failure - HttpConnectionOverHTTP@14f49d2::DecryptedEndPoint@170dae3{dp-gw-na.amazon.de/52.94.228.85:443<->/172.16.1.34:46938,OPEN,fill=FI,flush=-,to=59450/0}

2020-06-13 16:17:44.225 [DEBUG] [rg.eclipse.jetty.client.HttpReceiver] - Request/Response failed: Result[HttpRequest[GET / HTTP/1.1]@617d0e > HttpResponse[null 0 null]@17d7b19] java.nio.channels.AsynchronousCloseException

2020-06-13 16:17:44.227 [DEBUG] [ocket.client.WebSocketUpgradeRequest] - onComplete() - Result[HttpRequest[GET / HTTP/1.1]@617d0e > HttpResponse[null 0 null]@17d7b19] java.nio.channels.AsynchronousCloseException

2020-06-13 16:17:44.230 [DEBUG] [ocket.client.WebSocketUpgradeRequest] - General Failure
…

Home_Agecra · June 13, 2020, 2:33pm

I am getting the same error as well.

2020-06-13 10:19:50.981 [INFO ] [control.internal.WebSocketConnection] - Web Socket error
java.nio.channels.AsynchronousCloseException: null
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:181) ~[bundleFile:9.4.20.v20190813]
at java.util.ArrayList.forEach(ArrayList.java:1257) [?:1.8.0_201]
at org.eclipse.jetty.client.AbstractConnectionPool.close(AbstractConnectionPool.java:208) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.client.DuplexConnectionPool.close(DuplexConnectionPool.java:237) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.client.HttpDestination.close(HttpDestination.java:385) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.client.HttpClient.doStop(HttpClient.java:260) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:180) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.component.ContainerLifeCycle.doStop(ContainerLifeCycle.java:201) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.websocket.client.WebSocketClient.doStop(WebSocketClient.java:371) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93) [bundleFile:9.4.20.v20190813]
at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection.close(WebSocketConnection.java:159) [bundleFile:?]
at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection$2.run(WebSocketConnection.java:184) [bundleFile:?]
at java.util.TimerThread.mainLoop(Timer.java:555) [?:1.8.0_201]
at java.util.TimerThread.run(Timer.java:505) [?:1.8.0_201]
2020-06-13 10:20:58.441 [INFO ] [control.internal.WebSocketConnection] - Web Socket error
java.nio.channels.AsynchronousCloseException: null
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:181) ~[?:?]
at java.util.ArrayList.forEach(ArrayList.java:1257) [?:1.8.0_201]
at org.eclipse.jetty.client.AbstractConnectionPool.close(AbstractConnectionPool.java:208) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.client.DuplexConnectionPool.close(DuplexConnectionPool.java:237) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.client.HttpDestination.close(HttpDestination.java:385) [bundleFile:9.4.20.v20190813]
at org.eclipse.jetty.client.HttpClient.doStop(HttpClient.java:260) [bund

Kevin_J · June 13, 2020, 2:34pm

I just wanted to say I’m having the same problem. I noticed this morning that my cats were complaining their food dispensers had not turned on and OpenHAB stopped responding which is odd. Normally its been very stable for over a year. I too have a memory leak and logs showed an out of memory error. I disabled the AmazonEchoControl binding and now no more memory leak, no more errors in the log. I just can’t use Alexa to control a lot of my stuff

olialb · June 13, 2020, 4:45pm

I would like to help with that if you give me a link how to set Jetty to DEBUG mode

memphiz · June 13, 2020, 4:58pm

log:set debug org.eclipse.jetty

olialb · June 13, 2020, 5:38pm

Thanks did it and send to @J-N-K

wawa79 · June 13, 2020, 5:53pm

Same problem here since I restarted OH few minutes ago. I rebooted the whole thing but still bugging.

2020-06-13 19:53:13.364 [INFO ] [control.internal.WebSocketConnection] - Web Socket error
java.nio.channels.AsynchronousCloseException: null
	at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:181) ~[?:?]
	at java.util.ArrayList.forEach(Unknown Source) [?:1.8.0_191]
	at org.eclipse.jetty.client.AbstractConnectionPool.close(AbstractConnectionPool.java:208) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.DuplexConnectionPool.close(DuplexConnectionPool.java:237) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.HttpDestination.close(HttpDestination.java:385) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.client.HttpClient.doStop(HttpClient.java:260) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:180) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.component.ContainerLifeCycle.doStop(ContainerLifeCycle.java:201) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.client.WebSocketClient.doStop(WebSocketClient.java:371) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:93) [bundleFile:9.4.20.v20190813]
	at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection.close(WebSocketConnection.java:159) [bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection$2.run(WebSocketConnection.java:184) [bundleFile:?]
	at java.util.TimerThread.mainLoop(Unknown Source) [?:1.8.0_191]
	at java.util.TimerThread.run(Unknown Source) [?:1.8.0_191]

J-N-K · June 13, 2020, 6:08pm

Thanks, unfortunately the log is far too short. Please also set TRACE for amazonechocontrol and show what happens before the exception. It seems that there is a problem shutting down jetty when requests are still running. So I need to see what happens and why the connection is closed.

Zippochonda · June 13, 2020, 7:06pm

Same problem here…

digitaldan · June 13, 2020, 7:11pm

Hi @J-N-K , i turned on TRACE debuging on both org.eclipse.jetty.client.http and on org.openhab.binding.amazonechocontrol , but the only output is the exception others have shared. The Jetty client does print immediately after this exception:

2020-06-13 12:00:01.630 [DEBUG] [y.client.http.HttpConnectionOverHTTP] - Shutdown HttpConnectionOverHTTP@6b06a9ce::DecryptedEndPoint@57bee1e8{dp-gw-na-js.amazon.com/52.94.232.230:443<->/192.168.91.15:47566,OSHUT,fill=FI,flush=-,to=59725/0}
2020-06-13 12:00:01.630 [DEBUG] [y.client.http.HttpConnectionOverHTTP] - Closed HttpConnectionOverHTTP@6b06a9ce::DecryptedEndPoint@57bee1e8{dp-gw-na-js.amazon.com/52.94.232.230:443<->/192.168.91.15:47566,CLOSED,fill=-,flush=-,to=59726/0}

But nothing precedes the exception unfortunately.

essjay · June 13, 2020, 7:12pm

@J-N-K would be happy to try and help but need my hand holding to set TRACE for amazonechocontrol