Web Socket Error on AmazonEchoControl binding every 65 seconds

Yes, that‘s expected if you cancel a running request. But you should no longer see the OOM issue.

Edit: the main problem still is that the websocket connection fails. I don‘t know if this is a problem on Amazon‘s end or something we do wrong. I merely fixed the memory and thread leaks when closing the connection. One could think of reducing the log-message to debug, as the binding tries to reconnect anyway.

I think Jan solved the heap memory problem. I guess the web-socket-message still appears (might be a problem at Amazon side) but it seems the heap memory isn’t increasing anymore (which will cause the system to halt with “out of memory error”)

Thanks for your work. :+1:

I can filter out the logs for now. Would it make a difference by editing my config to eliminate some of the control features and see if the web socket error goes away?

Any suggestion how to filter this out?

thanks again
Andrea

log:set off org.openhab.binding.amazonechocontrol

thank you :slight_smile:

btw any connection between this issue and the issue we are facing from a while in this binding?

2020-06-10 19:28:50.753 [WARN ] [trol.internal.handler.AccountHandler] - handling of websockets fails
org.openhab.binding.amazonechocontrol.internal.HttpException: GET url 'https://alexa.amazon.it/api/activities?startTime=1591810130510&size=10&offset=1' failed: Bad Request
	at org.openhab.binding.amazonechocontrol.internal.Connection.makeRequest(Connection.java:644) ~[bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.Connection.makeRequestAndReturnString(Connection.java:499) ~[bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.Connection.makeRequestAndReturnString(Connection.java:494) ~[bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.Connection.getActivities(Connection.java:938) ~[bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.handler.AccountHandler.handlePushActivity(AccountHandler.java:773) ~[bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.handler.AccountHandler.handleWebsocketCommand(AccountHandler.java:718) ~[bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.handler.AccountHandler.webSocketCommandReceived(AccountHandler.java:706) [bundleFile:?]
	at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection$Listener.onWebSocketBinary(WebSocketConnection.java:404) [bundleFile:?]
	at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onBinaryMessage(JettyListenerEventDriver.java:103) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.message.SimpleBinaryMessage.messageComplete(SimpleBinaryMessage.java:68) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.events.JettyListenerEventDriver.onBinaryFrame(JettyListenerEventDriver.java:74) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:145) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.WebSocketSession.incomingFrame(WebSocketSession.java:321) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.extensions.ExtensionStack.incomingFrame(ExtensionStack.java:202) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.Parser.notifyFrame(Parser.java:226) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.Parser.parseSingleFrame(Parser.java:262) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.readParse(AbstractWebSocketConnection.java:582) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:441) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.websocket.common.io.AbstractWebSocketConnection.onFillable(AbstractWebSocketConnection.java:428) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:426) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:320) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:158) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:103) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:117) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:367) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:782) [bundleFile:9.4.20.v20190813]
	at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:918) [bundleFile:9.4.20.v20190813]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

OFF is probably a bit too much. Setting the Loglevel to WARN should be enough.

1 Like

Maybe. It could be that something changed on Amazon‘s side that lets the request fail (as in your log) and also prevents a successful connection (which results in the OOM here).

It would be very interesting if the lastVoiceCommand feature still works, because it seems the binding is not receiving it anymore. Maybe this has something to do with the “request fail”.

@J-N-K Thanks for your work :slight_smile:

it fixit for me

Here the lastVoiceCommand channel isn’t working anymore. I’ve checked my logs…
The channel stopped working at the same time the Websocket problem occurred.

I think the webSocket connection is not established so the binding is not able to receive anything. I checked against the web service established on the alexa page via firefox but for now everything looks like whats done in the code. I will try to find the reason. If lastVoiceCommand won’t work, also any feature which receive something from the server via webSocket shouldn’t work anymore. For example device status from a light connected to amazon. Only services which sends something without webSocket like tts. Correct me if i am wrong^^

3 Likes

My changes are in this PR: https://github.com/openhab/openhab-addons/pull/7919. If you need help creating a PR for your improvements, please contact me via PN, I don’t think it belongs in this thread.

Edit: Does anyone know when exactly the problem started? Maybe Amazon updated a certificate or something which is unknown?

Very big thanks!

shouldn’t then all be affected ?

Maybe it depends on the region where you are located (or where your account is registered).

I just checked my logfiles and it happend from time to time in the past. The first occurance of the error on my side was at:

2020-05-23 04:22:09.899 (UTC) (1 time)
2020-05-29 10:22:29.853 (UTC) (2 times)
2020-06-09 10:54:04.093 (UTC) (3 times)

and now continuously since

2020-06-12 07:38:19.670 (UTC)

The first OOM occured on

2020-06-13 00:43:21.730 (UTC)

I am using the api-url: https://alexa.amazon.de/api

EDIT: I converted CEST-timestamp to UTC

My oom starts at 1:30 at Saturday night. I think the error must start 00:00 between Friday and Saturday.
Times are local German time.

In past there where some threads here with same error, but most of them went OK afterwhile.

I can narrow down the point in time when the symptoms started between June 12th 03:30am and June 13th 03:30am (CEST), see also my explanation here.

In addition thank you for the memory/thread leak fix.

@andyzle What are you looking at? The first oom or the first “Web Socket error”?