Web Socket Error on AmazonEchoControl binding every 65 seconds

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

Zippochonda · June 13, 2020, 7:18pm

@essjay

log:set TRACE org.openhab.binding.amazonechocontrol

Trinitus01 · June 13, 2020, 7:57pm

Hi,
there is a method called “initPongTimeoutTimer” which try to close the webSocketClient every 60 seconds. I removed the timer and the error went away. I dont know if this also fix the memory issue, i will see tomorrow. The binding itself seems to be broken for some components but i only use announcements, they still work after the changes. It seems there is a request which never returns a response, so it crashes if it tries to close the websocket during this process, could this be? It would explain that amazon is the reason why it crashes, maybe, maybe not.

yab · June 13, 2020, 7:58pm

Same problems here. I can provide an openhab.log for the last days - standard loglevel only. But lots of other amazon echo related WARNs etc. Maybe you find some valuable information.

openhab.log (968.0 KB)

There are other warnings from zigbee issues (Telegesis stick vs two LED-controlers), which are unrelated to the amazon echo problem. Just ignore them.

essjay · June 13, 2020, 8:01pm

@Zippochonda thanks
12000 line in log in 15 mins! Wasn’t expecting that!

Have sent some of it to @J-N-K

AlexMartin13 · June 13, 2020, 9:02pm

I’d like to test this too. How does one go about disabling a method timer?

fuslwusl · June 13, 2020, 9:25pm

Got the same problem with the amazonechocontrol binding.

[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_232]
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_232]
at java.util.TimerThread.run(Timer.java:505) [?:1.8.0_232]

Is there already a fix available?

Trinitus01 · June 13, 2020, 9:31pm

You have to change the code and compile the binding to create a new jar file.