Platform information:
- openHAB Hardware: Raspi 3 B+ (Raspian OS 10)
- openHAB Software: 3.1.0 Release Build, running on Docker / Portainer 2.9.2
- openHAB Bindings: Homematic Binding (logging the heating, controlling lights and blinds), Gardena Binding for Gardena Gateway / smart irrigation control (logging soil humidity), Alexa Binding (controlling the Homematic lights)
- Homematic IP Hardware: CCU2 (2.59.7), multiple Homematic IP devices
- Other Hardware: Amber Wireless AMB8465 stick to read out Wireless M-Bus from water & heat meter
I’m having one annoying problem around a two odd log entries. Not sure if they’re connected, so here we go:
Annoying problem: Alexa loses connection from time to time
- The Alexa binding appears to lose connection from time to time (“Device unresponsive” in the Alexa App)…
- … with no related entries in the log…
- … but, even though Alexa cannot reach the devices, I can e.g. still make Alexa speak (e.g. via a simple command events.sendCommand(“Echo_Dot_Speak”, “Test”);), so the connection is somehow still there? Alexa just can’t control devices.
- This problem can also be solved via a reboot of openHAB (either in Portainer or the entire Raspi).
- Whenever Alexa has lost connection, https://myopenhab.org/ also correctly reports “Your openHAB is offline.”
So far so good.
Here’s what I also have in the logs. As said, I have these entries independent from “everything working normal” (e.g. after a reboot) as well as “when Alexa has lost connection”, so they show up anyway, even if everything works normal
1) Web Socket close 1005. Reason: null
2021-11-16 20:53:11.160 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 20:54:27.596 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 20:55:39.428 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 20:56:44.938 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 20:58:01.821 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 20:59:11.622 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:00:21.772 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:01:31.646 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:02:41.468 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:03:54.010 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:05:03.882 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:06:20.383 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
2021-11-16 21:07:36.630 [INFO ] [control.internal.WebSocketConnection] - Web Socket close 1005. Reason: null
This is what I understood is also being reported here, so I assume this can be ignored?!? Or is there a connection to the problem described above?
2) Web Socket error - javax.net.ssl.SSLHandshakeException: Abruptly closed by peer
Every now and then this is in my log:
20:51:54.601 [INFO ] [ocontrol.internal.WebSocketConnection] - Web Socket error
javax.net.ssl.SSLHandshakeException: Abruptly closed by peer
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:752) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:164) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:79) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:169) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882) [bundleFile:9.4.40.v20210413]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036) [bundleFile:9.4.40.v20210413]
at java.lang.Thread.run(Thread.java:829) [?:?]
Suppressed: javax.net.ssl.SSLException: closing inbound before receiving peer's close_notify
at sun.security.ssl.Alert.createSSLException(Alert.java:133) ~[?:?]
at sun.security.ssl.Alert.createSSLException(Alert.java:117) ~[?:?]
at sun.security.ssl.TransportContext.fatal(TransportContext.java:336) ~[?:?]
at sun.security.ssl.TransportContext.fatal(TransportContext.java:292) ~[?:?]
at sun.security.ssl.TransportContext.fatal(TransportContext.java:283) ~[?:?]
at sun.security.ssl.SSLEngineImpl.closeInbound(SSLEngineImpl.java:733) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.closeInbound(SslConnection.java:965) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:749) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:164) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:79) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:169) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882) [bundleFile:9.4.40.v20210413]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036) [bundleFile:9.4.40.v20210413]
at java.lang.Thread.run(Thread.java:829) [?:?]
Suppressed: org.eclipse.jetty.io.EofException
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:279) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.networkFlush(SslConnection.java:474) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.flush(SslConnection.java:1080) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doShutdownOutput(SslConnection.java:1292) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.doClose(SslConnection.java:1374) ~[?:?]
at org.eclipse.jetty.io.AbstractEndPoint.doOnClose(AbstractEndPoint.java:220) ~[?:?]
at org.eclipse.jetty.io.AbstractEndPoint.close(AbstractEndPoint.java:192) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.fill(SslConnection.java:828) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:164) ~[?:?]
at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:79) ~[?:?]
at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:131) ~[?:?]
at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:169) ~[?:?]
at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$DecryptedEndPoint.onFillable(SslConnection.java:540) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection.onFillable(SslConnection.java:395) ~[?:?]
at org.eclipse.jetty.io.ssl.SslConnection$2.succeeded(SslConnection.java:161) ~[?:?]
at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104) ~[?:?]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882) [bundleFile:9.4.40.v20210413]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036) [bundleFile:9.4.40.v20210413]
at java.lang.Thread.run(Thread.java:829) [?:?]
Caused by: java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.writev0(Native Method) ~[?:?]
at sun.nio.ch.SocketDispatcher.writev(SocketDispatcher.java:51) ~[?:?]
at sun.nio.ch.IOUtil.write(IOUtil.java:182) ~[?:?]
at sun.nio.ch.IOUtil.write(IOUtil.java:130) ~[?:?]
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:493) ~[?:?]
at java.nio.channels.SocketChannel.write(SocketChannel.java:507) ~[?:?]
at org.eclipse.jetty.io.ChannelEndPoint.flush(ChannelEndPoint.java:273) ~[?:?]
... 21 more
3) Raspi OS Log full of odd messages:
Nov 16 20:50:01 hab kernel: [ 24.879570] eth0: renamed from vethb9fc507
Nov 16 20:50:01 hab kernel: [ 24.927144] docker0: port 1(vetha7baf56) entered blocking state
Nov 16 20:50:01 hab kernel: [ 24.927168] docker0: port 1(vetha7baf56) entered forwarding state
Nov 16 20:50:01 hab kernel: [ 25.348713] eth0: renamed from veth25cd52f
Nov 16 20:50:01 hab kernel: [ 25.401024] app-openhab3: port 1(veth7855514) entered blocking state
Nov 16 20:50:01 hab kernel: [ 25.401049] app-openhab3: port 1(veth7855514) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 25.676261] eth0: renamed from vethd995a4a
Nov 16 20:50:02 hab kernel: [ 25.714777] eth0: renamed from vethe3376ad
Nov 16 20:50:02 hab kernel: [ 25.757971] br-90c87d73d85f: port 1(veth08729ea) entered blocking state
Nov 16 20:50:02 hab kernel: [ 25.757993] br-90c87d73d85f: port 1(veth08729ea) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 25.759338] br-0e8cc1951b33: port 1(vethdb1a6a5) entered blocking state
Nov 16 20:50:02 hab kernel: [ 25.759378] br-0e8cc1951b33: port 1(vethdb1a6a5) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 26.045400] eth0: renamed from veth5ca4745
Nov 16 20:50:02 hab kernel: [ 26.104900] eth0: renamed from vethf4218cc
Nov 16 20:50:02 hab kernel: [ 26.236912] eth0: renamed from veth8197d1f
Nov 16 20:50:02 hab kernel: [ 26.285393] be-openhab3: port 1(veth932fc1c) entered blocking state
Nov 16 20:50:02 hab kernel: [ 26.285409] be-openhab3: port 1(veth932fc1c) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 26.285636] eth0: renamed from vethed4f765
Nov 16 20:50:02 hab kernel: [ 26.355894] app-openhab3: port 2(veth9a50b47) entered blocking state
Nov 16 20:50:02 hab kernel: [ 26.355909] app-openhab3: port 2(veth9a50b47) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 26.356383] app-openhab3: port 3(veth7244a50) entered blocking state
Nov 16 20:50:02 hab kernel: [ 26.356394] app-openhab3: port 3(veth7244a50) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 26.358079] app-openhab3: port 4(veth97ad3d1) entered blocking state
Nov 16 20:50:02 hab kernel: [ 26.358109] app-openhab3: port 4(veth97ad3d1) entered forwarding state
Nov 16 20:50:02 hab kernel: [ 26.545142] eth1: renamed from veth3c8d90d
Nov 16 20:50:02 hab kernel: [ 26.595610] eth1: renamed from veth14171cf
Nov 16 20:50:03 hab kernel: [ 26.726980] be-openhab3: port 3(veth5aee02b) entered blocking state
Nov 16 20:50:03 hab kernel: [ 26.726997] be-openhab3: port 3(veth5aee02b) entered forwarding state
Anyone having an idea?