Seems to work also here. Thank you very much!
Br,
Stefan
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?
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]
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.
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
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
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.
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.
Many thanks Jan. It seems to be working for me too.
Chris
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!.
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 
A big thank you for taking the time and for delivering a binding without the OOM problem. And using your last version, i’m not receiving the INFO every 65 seconds any more. 
Warnings like mentioned eusblh are still there. But looking in older logs, i see them since month.
I just started to make use of the amazonecho binding some days ago. So i cannot say much about features not working.
I had the OOM error too.
After updating the binding on 2.4.0 OH2, I get this error every 60seconds still
] [internal.WebSocketConnection$Listener] - Web Socket error
org.eclipse.jetty.websocket.api.UpgradeException: 0 null
at org.eclipse.jetty.websocket.client.WebSocketUpgradeRequest.onComplete(WebSocketUpgradeRequest.java:522) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:216) ~[?:?]
at org.eclipse.jetty.client.ResponseNotifier.notifyComplete(ResponseNotifier.java:208) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.terminateResponse(HttpReceiver.java:470) ~[?:?]
at org.eclipse.jetty.client.HttpReceiver.abort(HttpReceiver.java:552) ~[?:?]
at org.eclipse.jetty.client.HttpChannel.abortResponse(HttpChannel.java:156) ~[?:?]
at org.eclipse.jetty.client.HttpChannel.abort(HttpChannel.java:149) ~[?:?]
at org.eclipse.jetty.client.HttpExchange.abort(HttpExchange.java:257) ~[?:?]
at org.eclipse.jetty.client.HttpConversation.abort(HttpConversation.java:141) ~[?:?]
at org.eclipse.jetty.client.HttpRequest.abort(HttpRequest.java:767) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.abort(HttpConnectionOverHTTP.java:204) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:190) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.close(HttpConnectionOverHTTP.java:182) ~[?:?]
at java.util.ArrayList.forEach(ArrayList.java:1257) [?:?]
at org.eclipse.jetty.client.AbstractConnectionPool.close(AbstractConnectionPool.java:209) [71:org.eclipse.jetty.client:9.4.11.v20180605]
at org.eclipse.jetty.client.DuplexConnectionPool.close(DuplexConnectionPool.java:236) [71:org.eclipse.jetty.client:9.4.11.v20180605]
at org.eclipse.jetty.client.HttpDestination.close(HttpDestination.java:386) [71:org.eclipse.jetty.client:9.4.11.v20180605]
at org.eclipse.jetty.client.HttpClient.doStop(HttpClient.java:256) [71:org.eclipse.jetty.client:9.4.11.v20180605]
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:89) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.component.ContainerLifeCycle.stop(ContainerLifeCycle.java:149) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.util.component.ContainerLifeCycle.doStop(ContainerLifeCycle.java:170) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.eclipse.jetty.websocket.client.WebSocketClient.doStop(WebSocketClient.java:423) [91:org.eclipse.jetty.websocket.client:9.4.11.v20180605]
at org.eclipse.jetty.util.component.AbstractLifeCycle.stop(AbstractLifeCycle.java:89) [87:org.eclipse.jetty.util:9.4.11.v20180605]
at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection.close(WebSocketConnection.java:171) [288:org.openhab.binding.amazonechocontrol:2.5.6.202006141340]
at org.openhab.binding.amazonechocontrol.internal.WebSocketConnection$2.run(WebSocketConnection.java:200) [288:org.openhab.binding.amazonechocontrol:2.5.6.202006141340]
at java.util.TimerThread.mainLoop(Timer.java:555) [?:?]
at java.util.TimerThread.run(Timer.java:505) [?:?]
I have loaded the 2.5.6-fix-leaks-fix-connection.jar file and I seem to be in much better shape! LastVoiceCommand is working again! However, none of my Alexa/Echo “Smart Home Devices” are working any longer - I’m assuming this is because this updated .jar was for the regular Add-On and is not for the Preview and Beta version of the add-on, right? Is there any way we can fix the connectivity issue in the Beta version as well? I can try to review the above posts describing what the issue was and how the add-on was fixed and see if I can copy these changes into the Beta version as well.
I’m getting the following error over and over, but I think I always get that anyway/I’m just going to ignore it for now:
20│2020-06-15 17:59:50.262 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.handleCommand()' on 'org.openhab.binding.amazonechocontrol.internal.handler.EchoHandler@57c87c': POST url │
20│'https://alexa.amazon.com/api/behaviors/preview' failed: Too Many Requests │
20│org.openhab.binding.amazonechocontrol.internal.HttpException: POST url 'https://alexa.amazon.com/api/behaviors/preview' failed: Too Many Requests │
20│ at org.openhab.binding.amazonechocontrol.internal.Connection.makeRequest(Connection.java:644) ~[?:?] │
20│ at org.openhab.binding.amazonechocontrol.internal.Connection.executeSequenceNode(Connection.java:1186) ~[?:?] │
20│ at org.openhab.binding.amazonechocontrol.internal.Connection.executeSequenceCommand(Connection.java:1171) ~[?:?] │
20│ at org.openhab.binding.amazonechocontrol.internal.Connection.executeSequenceCommandWithVolume(Connection.java:1162) ~[?:?] │
20│ at org.openhab.binding.amazonechocontrol.internal.Connection.sendAnnouncement(Connection.java:1133) ~[?:?] │
20│ at org.openhab.binding.amazonechocontrol.internal.handler.EchoHandler.startTextToSpeech(EchoHandler.java:722) ~[?:?] │
20│ at org.openhab.binding.amazonechocontrol.internal.handler.EchoHandler.handleCommand(EchoHandler.java:577) ~[?:?] │
20│ at sun.reflect.GeneratedMethodAccessor114.invoke(Unknown Source) ~[?:?] │
20│ at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252] │
20│ at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252] │
20│ at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?] │
20│ at org.eclipse.smarthome.core.internal.common.InvocationHandlerSync.invoke(InvocationHandlerSync.java:59) [bundleFile:?] │
20│ at com.sun.proxy.$Proxy521.handleCommand(Unknown Source) [?:?] │
20│ at org.eclipse.smarthome.core.thing.internal.profiles.ProfileCallbackImpl.handleCommand(ProfileCallbackImpl.java:74) [bundleFile:?] │
20│ at org.eclipse.smarthome.core.thing.internal.profiles.SystemDefaultProfile.onCommandFromItem(SystemDefaultProfile.java:48) [bundleFile:?] │
20│ at sun.reflect.GeneratedMethodAccessor113.invoke(Unknown Source) ~[?:?] │
20│ at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252] │
20│ at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252] │
20│ at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:152) [bundleFile:?] │
20│ at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:52) [bundleFile:?] │
20│ at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_252] │
20│ at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_252] │
20│ at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_252] │
20│ at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]My log is filled with this too. Can someone link to the solution so I don’t have to read 200 posts?
2020-06-15 19:17:33.013 [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_222]
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_222]
at java.util.TimerThread.run(Timer.java:505) [?:1.8.0_222]try the connection fixed jar, stop openhab, clean cache and tmp folder and put in this fixed jar seems to have stopped websocket error for amazon echo. Uninstalled the binding in paper ui first if you have installed before doing all this.
Thank you for the fix J-N-K
Uninstalled the old binding, put the new fix binding in, cleared cache and rebooted. Same issue
mine has been up 42 minutes and no more websocket error which i had every minute in the log.
cleaned tmp folder also?
Certainly did!
sudo /etc/init.d/openhab2 stop
sudo rm -rf /var/lib/openhab2/cache/*
sudo rm -rf /var/lib/openhab2/tmp/*
sudo /etc/init.d/openhab2 start