Web Socket Error on AmazonEchoControl binding every 65 seconds

Fixer · June 16, 2020, 3:37pm

Just to report: Updated the bundle with the new connection fix version and the connection error message is gone. My logs are clean and everything seems to be working ok.
Many thanks!

J-N-K · June 16, 2020, 3:54pm

This seems to be the wrong version. You need the other one. I’ll edit-out the wrong link

mvo · June 16, 2020, 3:58pm

Thanks for quick reploy, which link should I use as correct? thanks in advance

Karl2 · June 16, 2020, 4:14pm

If its any help, the following worked for me. It sorted out the mem leak and log errors. Bundle listing shows 2.5.6.202006152137

https://janessa.me/esh/org.openhab.binding.amazonechocontrol-2.5.6-fix-leaks-fix-connection.jar

Cheers

Mario_Spies · June 16, 2020, 4:30pm

Hi @Karl2
Thanks so much. This solved the issue for me

ThomasOH · June 16, 2020, 6:38pm

The web socket issue creeped into my system a couple days ago. I see the web socket errors every 70 seconds. I’m running openHAB 2.4.0~20181104134837-1 (Build #1412) with manually installed amazonechocontrol:2.5.0.Beta_07_Preview_1 jar file.

I don’t see a log message that specifically reports out of memory, but that must be happening since OpenHAB gets lost after running for a few hours. A reboot restores operation, but this temporary fix is at best a rinse and repeat situation.

I manually installed J-N-K’s special jar and found it does not work at all on my 2.4.0 installation. I see the expected log messages when I issue voice commands that show the rules have been triggered. But the rules’ action do not occur and the Text-to-Voice responses are not heard. Furthermore, the amazonechocontrol/account web page shows the page is not available. Reverting to the previous jar file restores echo control, but now I’m back to rebooting every few hours.

If any of you are running 2.4.0, and have success with the new jar that J-N-K kindly provided, I would greatly appreciate any tips you may have.

Thomas

charcharwon · June 16, 2020, 6:51pm

I noticed websocket error for amazon echo in my logs and broken functionality of amazon echo while running 2.4 about a month ago and thought I messed up my installation with experimenting and decided to rebuild everything with clean openhabian 2.5 and the websocket error was worst until this fix. At least my code has been cleaned up and almost everything is configured with Paper UI as much as possible.

TTS works since I use it to announce house alarm messages mainly.

michi · June 16, 2020, 6:58pm

The PR for this [amazonechocontrol] Add features to control smart devices connected to the Amazon Echo by lkn94 · Pull Request #6140 · openhab/openhab-addons · GitHub is open since several month.

michi · June 16, 2020, 7:01pm

Take a look here: [amazonechocontrol] Add features to control smart devices connected to the Amazon Echo by lkn94 · Pull Request #6140 · openhab/openhab-addons · GitHub

sujitrp · June 16, 2020, 7:10pm

no error for last one hour . Now log looks good . Also Ram usage is stabilized
Usage for last 7 days : my system is using swap space 512 with RPI3b+ and 8-10 IOT stack docker container

Last 24 Hrs

J-N-K · June 16, 2020, 8:32pm

Are you planning to address the comments from @cpmeister? After I finished http and did the a review I promised some time ago, I could have a look at that PR if you don‘t find time to do so. Depends a bit on how much needs to be done there.

David_Garvin · June 16, 2020, 8:49pm

Continuing the discussion from Web Socket Error on AmazonEchoControl binding every 65 seconds:

I too have been getting these errors with OH 2.4 and OH 2.5 running on two separate Synology servers. The OH 2.4 installation has been running continuously for several weeks with no problems. The log files showed an amazonechocontrol web socket error starting on the 13th June at 11:07 Dublin time and continuing every 65 or so seconds as described. I checked the log files this evening, expecting to see the error continuing, but the errors stopped appearing at 01:42 today (16th June).

I checked the logs for the OH 2.5 version and found that the last error occurred at 07:28 today.

I have made no changes, nor updates, to either installation the problem appears to have gone away by itself!

J-N-K · June 16, 2020, 9:07pm

Maybe Amazon reverted the strict header checking (or it was not activated intentionally in the first place). You‘ll suffer from the
memory leak, but during normal operation it‘ll probably not show up early (Remember: it‘s almost 60 connects per hour, and the error shows up after some hours, depending on available memory. If you only re-connect once or twice a day, you‘ll need several month to exhaust your memory.).

ThomasOH · June 16, 2020, 9:53pm

Were any of you using the Preview and Beta: Amazon Echo Control version of the binding (amazonechocontrol_2.5.0.-2019-10-23.jar)? The “amazonechocontrol-2.5.6-fixleaks.jar” version doesn’t seem to allow for any of my Amazon/Echo “Smart Home Devices” to function, as they normally do with the 2019-10-23 Preview and Beta .jar file.

I’m running amazonechocontrol:2.5.0.Beta_07_Preview_1 jar on OH 2.4 (Build #1412). Like you found, the new “fixleaks” jar does not work in my installation. If you’ve found a workaround then please share the details.

Thomas

richaardvark · June 16, 2020, 10:08pm

I unfortunately have not found a workaround yet but will definitely let you know if I do!

ThomasOH · June 17, 2020, 1:22am

The memory leak that occurs with this bug has a big appetite. I’m seeing about 34MB per hour is lost on my OH2.4 running amazonechocontrol:2.5.0.Beta_07_Preview_1.

It takes about half a day to consume all the available memory on my RPI. I’m tempted to run a cron initiated reboot three times a day to buy some time while this problem is sorted out. Easy to do, but this kind of workaround would never win any awards for elegance.

Thomas

chimera · June 17, 2020, 4:18am

After applying the latest amazon .jar workaround I have got this show up in the logs - different error message, maybe related, maybe helpful???

2020-06-16 22:43:43.450 [WARN ] [trol.internal.handler.AccountHandler] - handling of websockets fails
org.openhab.binding.amazonechocontrol.internal.HttpException: GET url 'https://alexa.amazon.com/api/activities?startTime=1592304223045&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) ~[bundleFi                                    le:?]
        at org.openhab.binding.amazonechocontrol.internal.handler.AccountHandler.webSocketCommandReceived(AccountHandler.java:706) [bundleF                                    ile:?]
        at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection$AmazonEchoControlWebSocket.onWebSocketBinary(WebSocketConnect                                    ion.java:417) [bundleFile:?]
        at sun.reflect.GeneratedMethodAccessor112.invoke(Unknown Source) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_201]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_201]
        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) [b                                    undleFile:9.4.20.v20190813]
        at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onBinaryMessage(JettyAnnotatedEventDriver.java:133) [bundleF                                    ile:9.4.20.v20190813]
        at org.eclipse.jetty.websocket.common.message.SimpleBinaryMessage.messageComplete(SimpleBinaryMessage.java:68) [bundleFile:9.4.20.v                                    20190813]
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.appendMessage(AbstractEventDriver.java:65) [bundleFile:9.4.20.v201                                    90813]
        at org.eclipse.jetty.websocket.common.events.JettyAnnotatedEventDriver.onBinaryFrame(JettyAnnotatedEventDriver.java:125) [bundleFil                                    e:9.4.20.v20190813]
        at org.eclipse.jetty.websocket.common.events.AbstractEventDriver.incomingFrame(AbstractEventDriver.java:145) [bundleFile:9.4.20.v20                                    190813]
        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.v201                                    90813]
        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_201]

Sudipta_Ghorui · June 17, 2020, 4:53am

Thanks!!! This worked for me.

Karl2 · June 17, 2020, 6:59am

Hi ThomasOH,

I have version 2.4.0-1

I have updated the echo control bundle to the version shown below ( using the link I posted earlier )

NOTE : When it originally installed it would not start because of a dependency issue. I had to run the following before it would actually start and become active. This might have been due to the fact that OH 2.4 didn’t have what was needed by the latest echo control Jar file ? I was running a very old version prior to loading this one.

bundle:install https://repo1.maven.org/maven2/com/google/code/gson/gson/2.8.5/gson-2.8.5.jar

From the image above It would appear that I now have 2 libs offering the same services. Not sure if that’s a problem but all appears to be ok and all of my automation is functioning as per normal. The fact that the new one is showing “resolved” and not “Active” as per the other version 2.7.0 might suggest that 2.7.0 could still be providing the necessary services while 2.8.5 is laying dormant just satisfying the requirement for the new echo control Jar file to be bought online ?

Hope some of this helps you. My system has now been stable with no obvious errors in the logs and no noticeable memory leaks.

Cheers,
Karl.

idkpmiller · June 17, 2020, 7:39am

I am NZT in Pacific.