[SOLVED] Connection to my own openHAB Cloud instance always times out after upgrading to the 2.5.0 snapshot

Hi,

after upgrading my openhab instance to the latest 2.5.0 snapshot docker image (it also happened with earlier snapshots) the connection to my self-hosted openHAB Cloud instance no longer works. The connection is actually established but is reset after 10s due to some timeout event, repeatedly and reproducably.

Connections to myopenhab.org are fine, though, so I wonder what’s wrong with my instance which is running the latest code and which works fine with 2.4. Any hints on how to debug this would be much appreciated.

The log on the client side looks like this:

2019-06-03 21:08:54.714 [DEBUG] [io.openhabcloud.internal.CloudClient] - Socket.IO connected                                                                                                                                                                                  
2019-06-03 21:08:54.714 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = b74c886c-7c89-407d-b594-3207ede5bfab, base URL = http://localhost:8080)                                                                               
2019-06-03 21:09:04.718 [DEBUG] [io.openhabcloud.internal.CloudClient] - Socket.IO error: {}                                                                                                                                                                                  
io.socket.engineio.client.EngineIOException: xhr poll error                                                                                                                                                                                                                   
        at io.socket.engineio.client.Transport.onError(Transport.java:63) [219:io.socket.engine.io-client:1.0.0]                                                                                                                                                              
        at io.socket.engineio.client.transports.PollingXHR.access$100(PollingXHR.java:26) [219:io.socket.engine.io-client:1.0.0]                                                                                                                                              
        at io.socket.engineio.client.transports.PollingXHR$6$1.run(PollingXHR.java:140) [219:io.socket.engine.io-client:1.0.0]                                                                                                                                                
        at io.socket.thread.EventThread$2.run(EventThread.java:80) [219:io.socket.engine.io-client:1.0.0]                                                                                                                                                                     
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
        at java.lang.Thread.run(Thread.java:748) [?:?]
Caused by: java.net.SocketTimeoutException: timeout
        at okio.Okio$4.newTimeoutException(Okio.java:232) ~[?:?]
        at okio.AsyncTimeout.exit(AsyncTimeout.java:285) ~[?:?]
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:241) ~[?:?]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:354) ~[?:?]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:226) ~[?:?]
        at okhttp3.internal.http1.Http1Codec.readHeaderLine(Http1Codec.java:215) ~[?:?]
        at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189) ~[?:?]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:254) ~[?:?]
        at okhttp3.RealCall$AsyncCall.execute(RealCall.java:200) ~[?:?]
        at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
        ... 3 more
Caused by: java.net.SocketException: Socket closed
        at java.net.SocketInputStream.read(SocketInputStream.java:204) ~[?:?]
        at java.net.SocketInputStream.read(SocketInputStream.java:141) ~[?:?]
        at sun.security.ssl.InputRecord.readFully(InputRecord.java:465) ~[?:?]
        at sun.security.ssl.InputRecord.read(InputRecord.java:503) ~[?:?]
        at sun.security.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:975) ~[?:?]
        at sun.security.ssl.SSLSocketImpl.readDataRecord(SSLSocketImpl.java:933) ~[?:?]
        at sun.security.ssl.AppInputStream.read(AppInputStream.java:105) ~[?:?]
        at okio.Okio$2.read(Okio.java:140) ~[?:?]
        at okio.AsyncTimeout$2.read(AsyncTimeout.java:237) ~[?:?]
        at okio.RealBufferedSource.indexOf(RealBufferedSource.java:354) ~[?:?]
        at okio.RealBufferedSource.readUtf8LineStrict(RealBufferedSource.java:226) ~[?:?]
        at okhttp3.internal.http1.Http1Codec.readHeaderLine(Http1Codec.java:215) ~[?:?]
        at okhttp3.internal.http1.Http1Codec.readResponseHeaders(Http1Codec.java:189) ~[?:?]
        at okhttp3.internal.http.CallServerInterceptor.intercept(CallServerInterceptor.java:88) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.connection.ConnectInterceptor.intercept(ConnectInterceptor.java:45) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.internal.cache.CacheInterceptor.intercept(CacheInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.internal.http.BridgeInterceptor.intercept(BridgeInterceptor.java:93) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RetryAndFollowUpInterceptor.intercept(RetryAndFollowUpInterceptor.java:126) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:147) ~[?:?]
        at okhttp3.internal.http.RealInterceptorChain.proceed(RealInterceptorChain.java:121) ~[?:?]
        at okhttp3.RealCall.getResponseWithInterceptorChain(RealCall.java:254) ~[?:?]
        at okhttp3.RealCall$AsyncCall.execute(RealCall.java:200) ~[?:?]
        at okhttp3.internal.NamedRunnable.run(NamedRunnable.java:32) ~[?:?]
        ... 3 more
2019-06-03 21:09:04.749 [DEBUG] [io.openhabcloud.internal.CloudClient] - Socket.IO disconnected
2019-06-03 21:09:04.749 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = b74c886c-7c89-407d-b594-3207ede5bfab, base URL = http://localhost:8080)
2019-06-03 21:09:06.203 [DEBUG] [io.openhabcloud.internal.CloudClient] - Socket.IO connected
2019-06-03 21:09:06.204 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = b74c886c-7c89-407d-b594-3207ede5bfab, base URL = http://localhost:8080)

The according log on the server side:

2019-06-03 21:08:54:5454 info: openHAB-cloud: Authorizing incoming openHAB connection
2019-06-03 21:08:54:5454 info: openHAB-cloud: Incoming openHAB connection for uuid b74c886c-7c89-407d-b594-3207ede5bfab
2019-06-03 21:08:54:5454 info: openHAB-cloud: Connected openHAB with b74c886c-7c89-407d-b594-3207ede5bfab successfully
2019-06-03 21:08:54:5454 info: openHAB-cloud: uuid b74c886c-7c89-407d-b594-3207ede5bfab server address undefined:undefined my address undefined:undefined
2019-06-03 21:09:04:044 info: openHAB-cloud: Disconnected b74c886c-7c89-407d-b594-3207ede5bfab
2019-06-03 21:09:06:066 info: openHAB-cloud: Authorizing incoming openHAB connection

Cheers!

Hi André,

Welcome back :wink: .

I recently have done some changes to openHAB Cloud Connector. These could be related. Can you specify your OH 2.5 snapshot version? Which one do you use exactly?

On the other hand after OH 2.4 we changed the complete build system and the way how to include dependencies. Which resulted in some version updates of them too.

Hey Christoph :slight_smile:

I’m currently using the latest snapshot docker image that’s available from dockerhub, it’s 6 days old. I’m not sure where to find the exact snapshot number tbh.

I don’t think that your changes from May are related. I’m pretty sure that I already saw this exact behavior with the M1 build.

One way to find out your version is to login into the console. It is shown on the start screen. IIRC latest snapshot is S1603 (built on 29th of May).

Yes, I’m using #1603.

Ok, I figured it out. It was related to some misconfiguration in the reverse proxy setup I’m using. For whatever reason that didn’t cause any issues with 2.4 but only with 2.5. Anyway, everything’s working great now.

Thanks!

Good to hear. Please mark this thread as “solved”.

Hi Andre,

I am having the same issue, and I was just wondering what was wrong with your reverse proxy config. I am running my OpenHAB Cloud server behind a Sophos UTM 9 firewall, and that’s where my “reverse proxy” is set up (it’s a “Virtual Webserver”). Perhaps that “server address undefined:undefined my address undefined:undefined” is something to be fixed?

I hope I used the right terms, and it is not a complete rubbish I am saying, please feel free to correct me.

Thanks,
Miki.

Hi @aduffeck,

I’ve got the same issue and was wondering what the changes to your reverse proxy were that lead to the problem going away for you, as I can’t figure this out, even though I’ve been at it for some time now. Thank you very much!

Cheers,
Gregory

Can you share what reverse proxy setting that is causing this errror? I am facing the same problem as well on nginx at server end.

I had to change the keepalive_timeout value for nginx reverse proxy: https://community.openhab.org/t/switches-occasionally-do-not-react-are-not-updated/

After upgrade to latest opencloud repo, everything is resolved.