Web Socket Error on AmazonEchoControl binding every 65 seconds

Add-ons Bindings
177

One more report using OH 2.4: 2.5.5 docker restarts randomly

with that I would conclude
=> it’s independent of OH 2.4, 2.5.X
=> independent of the amazoncontrol binding version ( apart of the OOM problem )

It also was mentioned if the certificate would have been renewed.
I connected to https://dp-gw-na.amazon.com/ via browser and checked the certificate:
Validity: Not Before 1/30/2020, 1:00:00 AM (Central European Summer Time)
=> so that was not changed either

someone on the internet mentioned having problems because his fritzbox protection of minors ( URL/content filter ) was blocking some amazon server. => I think this cannot be the reason ( at least not for the wireshark/tcpdump that was done some posts above as not all requests to that server are blocked.

178

Ram Swap usage for last 7 days (All time in IST)

image
image912×345 30.2 KB

Ram Swap Usage for last 24 hr

image
image931×422 24.8 KB

Ram Swap Usage Post jar fix

image
image920×367 19.7 KB

179

In the meantime I also updated to 2.5.6-SNAPSHOT fix, having a bit of a problem now.

My Amazon account already lost the connection twice and was not able to login again, also after reboot it needed some time to get the account online, not sure if I will do a clean installation tomorrow.

180

Interesting that you guys also lost the things as I did. I checked this morning and had to add them manually again and upgraded to 2.5 afterwards as I thought the new version might be more stable.

Reading through this it might not have been the 2.4 version but the echo binding instead. Will also disable it for now as adding the things was quiet time-consuming.

Running on a raspberrypi zero w for two years and never lost things before.

Strange enough despite the error the binding still seems to work even though the “Last Voice Command” no longer shows up while e.g. TTS works flawless.

181

It might be this repository that has the iobroker binding, but I can’t find much pointing to something that has been fixed: https://github.com/Apollon77/ioBroker.alexa2

182

I think I found the culprit. Just doing some verification before I’ll provide a test jar.

Edit: please try link removed, use snapshot, changes are merged. Instructions for usage see above.

14 Likes
183

I think things got lost because of a regular restart. The broken system (OOM) in written into the json-db. I also lost my things, but there is an automatically backup of the json-db, see the backup folder.

:smiley:

2 Likes
184

It works, I am getting lastCommand back into OpenHAB! Thank you so much.

1 Like
185

LGTM

Thanks :slight_smile:

186

Seems to work also here. Thank you very much!

Br,
Stefan

187

You are probably right, that the database is corrupted because of the unclean shutdown after the OOM. This should be considered a bug. Could you file an issue in openhab-core repository for that?

188

this jar got lastVoice working for me too.
but… I did get this error in my log
I couldn’t find any negative consequences of the error, so I’m in no rush to fix it. But I’d be glad to help if anyone wants to.

17:56:22.791 [WARN ] [ntrol.internal.handler.AccountHandler] - handling of websockets fails
org.openhab.binding.amazonechocontrol.internal.HttpException: GET url 'https://alexa.amazon.com/api/activities?startTime=1592258184045&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$AmazonEchoControlWebSocket.onWebSocketBinary(WebSocketConnection.java:417) [bundleFile:?]
        at sun.reflect.GeneratedMethodAccessor403.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_192]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_192]
        at org.eclipse.jetty.websocket.common.events.annotated.CallableMethod.call(CallableMethod.java:70) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.websocket.common.events.annotated.OptionalSessionCallableMethod.call(OptionalSessionCallableMethod.java:72) [bundleFile:9.4.20.v20190813]
        at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onBinaryMessage(JettyAnnotatedEventDriver.java:133) [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.JettyAnnotatedEventDriver.onBinaryFrame(JettyAnnotatedEventDriver.java:125) [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_192]
189

I‘m sorry. I already spent much more time in this than I originally planned. I wanted to fix the OOM exception because it affects the whole system. Now I spend around 10 more hours in fixing the websocket connection. I have no idea where to start with your error, so this will need someone else for fixing it.

190

Good job! To unterstand, it was not a missing part, it was a redundant part?!? I am really interested how this came to your mind OO

191

Setting jetty to DEBUG shows the requests. It’s a bit hard to see, because jetty is very chatty at DEBUG.

After I found that, I originally thought that amazon is blocking jetty as user-agent and tried to set the user-agent header to a more common Mozilla. To my surprise this resulted in two user-agent headers which is obviously wrong. I then had a closer look at the other headers and found the the binding adds headers that are later added by jetty. After I removed that, the connection succeeded.

I‘m not entirely sure if this should be considered a bug in jetty. If I pass a request to the client, IMO it should not add already existing headers.

3 Likes
192

Very impressive that you find it this way. I never thought headers could exist multiple times. The big question: If the jetty version did not change and amazon did not change anything. How could it be the headers are added twice from one day to another? This seems to be very strange.

193

I think amazon is validating more strictly now. This probably also explaining why it was not immediately there for all users, depending on the server update and re-connection.

194

Many thanks Jan. It seems to be working for me too.
Chris

195

This is great news! Even if it is not a perfect, permanent fix, it seems we are in much better shape. Thank you so very much for taking so much of your time to troubleshoot and help come up with this working solution @J-N-K!

I was going to say, even though “LastVoiceCommand” wasn’t working, the data still was there, in the API. If you follow the link (updated of course with your own, local IP address and account key) that was provided in the Preview and Beta version of the Add-In, under the section:
"Advanced Feature Technically Experienced Users" http://openhab:8080/amazonechocontrol/account1/PROXY/api/activities?startTime=&size=50&offset=1

…you will still see your “LastVoiceCommand” data is present there in the API. I am not very proficient with coding, especially this type of coding, but I was thinking maybe Amazon had renamed a variable or changed a header or there was a cookie problem or something and maybe if you look at the API through this link that we could figure out what changed. But now it seems we are in good shape!.

196

That makes sense. I also checked the user agent but i was not able to see the real outgooing request on the lower level (jetty). Big thanks for the explanation, it helps me to understand. Tomorrow i will do the git pull and try to do the PR. If this webSocket issue didnt burn off your energy, maybe i can ask some more questions :wink: