ably-java icon indicating copy to clipboard operation
ably-java copied to clipboard
verified publisher icon ably

Devices do not reconnect after handshake failure

Open QuintinWillison opened this issue 5 years ago • 5 comments

We've had a report from a customer, via Intercom. Conversation detail, with redactions:

CUSTOMER: hello. I get handshake failure:

[Ably internal] setState(): setting suspended; reason [ErrorInfo message=Received fatal alert: handshake_failure (See https://help.ably.io/error/80000) code=80000 statusCode=503 href=https://help.ably.io/error/80000] on all my devices being restarted

CUSTOMER: they run java 11 under ARMv7

Jo from Ably: Hi, sorry to hear you're having issues, could you give me a little more information on how you're using ably?

CUSTOMER: we use the java client

CUSTOMER: version 1.1.10

Jo from Ably: 80000 is a network connectivity error, do your clients all have network access?

CUSTOMER: yeah I tried using curl on https, and that went fine

CUSTOMER: java client works on windows as well through java here

Jo from Ably: and the connection does not retry after 15 seconds?

CUSTOMER: so it must be some kind of an SSL handshake failure happening only on ARM but I am not sure if you changed the certificate for your web services

CUSTOMER:

[Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
[Ably internal] X-Ably-Lib: java-1.1.10
[Ably internal] Accept: application/json
[Ably internal] X-Ably-Version: 1.0
[Ably internal] HTTP response:
[Ably internal] CF-RAY: REDACTED
[Ably internal] Server: cloudflare
[Ably internal] Connection: keep-alive
[Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
[Ably internal] x-amz-version-id: null
[Ably internal] Date: Thu, 27 Aug 2020 15:03:41 GMT
[Ably internal] Accept-Ranges: bytes
[Ably internal] CF-Cache-Status: DYNAMIC
[Ably internal] ETag: "REDACTED"
[Ably internal] Set-Cookie: REDACTED; expires=Sat, 26-Sep-20 15:03:40 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
[Ably internal] x-amz-request-id: REDACTED
[Ably internal] x-amz-id-2: REDACTED
[Ably internal] Content-Length: 4
[Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
[Ably internal] cf-request-id: REDACTED
[Ably internal] Content-Type: text/plain
[Ably internal] 
yes

CUSTOMER: so ably does a test and that goes fine, it's only when it tries to connect to web sockets it fails on port 443

CUSTOMER: I have a full log of the retries if you want that I can put in a txt

CUSTOMER: I have 2 different locations doing the same thing. and it started happening very recently. the 2nd one is my personal device at home where I know everything is open. so it can't be any firewall stuff

Jo from Ably: That might be helpful

CUSTOMER: I run my java program with -Dhttps.protocols=TLSv1,TLSv1.1,TLSv1.2

Jo from Ably: If you can send logs then hopefully we can get to the bottom of this

CUSTOMER: thanks

27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,662Z [WebSocketConnectReadThread-646] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to A.ably-realtime.com
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,662Z [WebSocketConnectReadThread-646] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,666Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] Wait ended by action: io.ably.lib.transport.ConnectionManager$AsynchronousStateChangeAction@99d720
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,667Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,667Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,668Z [WebSocketWriteThread-647] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,671Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,672Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,672Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://A.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,773Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,773Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,773Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,773Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:52 (+0200) <controller> 2020-08-27T15:33:52,773Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:52 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,997Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,998Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:52 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,998Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,998Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,998Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,998Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,998Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,999Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,999Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:53 (+0200) <controller> yes
27.08.20 17:33:53 (+0200) <controller> 
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:52,999Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to D.ably-realtime.com
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,000Z [WebSocketConnectReadThread-651] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,001Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] Wait ended by action: io.ably.lib.transport.ConnectionManager$AsynchronousStateChangeAction@184f98e
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,005Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,006Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,006Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,006Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,223Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,225Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,226Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,229Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,230Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,232Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,233Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:53 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,235Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,236Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,237Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,239Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:53 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,240Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,241Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,243Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,244Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,245Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,246Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,247Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:53 (+0200) <controller> yes
27.08.20 17:33:53 (+0200) <controller> 
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,249Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to D.ably-realtime.com
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,250Z [WebSocketWriteThread-652] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,251Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,251Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,252Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,253Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,253Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://D.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,258Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,258Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,258Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,258Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,258Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://D.ably-realtime.com:443/?accessToken=REDACTEDw&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,325Z [WebSocketConnectReadThread-654] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,325Z [WebSocketWriteThread-657] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,328Z [WebSocketWriteThread-657] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,329Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,331Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,331Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,331Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,331Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,456Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,457Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,458Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,458Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,459Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,459Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,459Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:53 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,459Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,459Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:53 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,460Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:53 (+0200) <controller> yes
27.08.20 17:33:53 (+0200) <controller> 
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,461Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to C.ably-realtime.com
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,461Z [WebSocketConnectReadThread-656] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,462Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,463Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,463Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,464Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,708Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,708Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,709Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,709Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,709Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,710Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,710Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:53 GMT
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,710Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,711Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,711Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,711Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:53 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,712Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,713Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,713Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,713Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,714Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,714Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,723Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:53 (+0200) <controller> yes
27.08.20 17:33:53 (+0200) <controller> 
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,724Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to C.ably-realtime.com
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,724Z [WebSocketWriteThread-658] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,725Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] Wait ended by action: io.ably.lib.transport.ConnectionManager$AsynchronousStateChangeAction@1f83e55
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,725Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,725Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,725Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,725Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,726Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://C.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,733Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,736Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,737Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,737Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,738Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://C.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,842Z [WebSocketConnectReadThread-660] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,842Z [WebSocketWriteThread-664] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,843Z [WebSocketWriteThread-664] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,846Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,846Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,846Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,846Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:53 (+0200) <controller> 2020-08-27T15:33:53,846Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,084Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,085Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,085Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,085Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,085Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:54 GMT
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:53 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,086Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,087Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,087Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:54 (+0200) <controller> yes
27.08.20 17:33:54 (+0200) <controller> 
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,087Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to B.ably-realtime.com
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,088Z [WebSocketConnectReadThread-662] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,088Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] Wait ended by action: io.ably.lib.transport.ConnectionManager$AsynchronousStateChangeAction@1337344
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,089Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,090Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,091Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,091Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,091Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,317Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,318Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,318Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,318Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,318Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,319Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,319Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:54 GMT
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,319Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,320Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,320Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,320Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:54 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,320Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,321Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,321Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,321Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,321Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,322Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,322Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:54 (+0200) <controller> yes
27.08.20 17:33:54 (+0200) <controller> 
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,323Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] checkFallback: fallback to E.ably-realtime.com
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,323Z [WebSocketWriteThread-663] DEBUG com.customer.app.AblyTransport - [Ably internal] requestState(): requesting connecting; id = null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,323Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,324Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,324Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,324Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://B.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,329Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting connecting; reason null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,330Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] close()
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,331Z [Thread-17] INFO  com.customer.app.AblyTransport - [Ably internal] using cached token; expires = 1598544147111
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,331Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] getConnectParams: params = [accessToken:REDACTED, v:1.0, format:msgpack, heartbeats:false, lib:java-1.1.10]
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,332Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] connect(); wsUri = wss://E.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.1.10
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,409Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP request: https://internet-up.ably-realtime.com/is-the-internet-up.txt GET
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,409Z [WebSocketWriteThread-669] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,410Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Lib: java-1.1.10
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,410Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal]   Accept: application/json
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,410Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal]   X-Ably-Version: 1.0
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,417Z [WebSocketWriteThread-670] DEBUG com.customer.app.AblyTransport - [Ably internal] onClose(): wsCode = -1; wsReason = ; remote = true
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,629Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] HTTP response:
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,629Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-RAY: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,630Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Server: cloudflare
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,630Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Connection: keep-alive
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,630Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Last-Modified: Wed, 14 Jan 2015 16:12:25 GMT
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-version-id: null
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Date: Thu, 27 Aug 2020 15:33:54 GMT
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Accept-Ranges: bytes
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] CF-Cache-Status: DYNAMIC
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] ETag: "REDACTED"
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Set-Cookie: __cfduid=REDACTED; expires=Sat, 26-Sep-20 15:33:54 GMT; path=/; domain=.ably-realtime.com; HttpOnly; SameSite=Lax
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,631Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-request-id: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,632Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] x-amz-id-2: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,632Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Length: 4
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,632Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Expect-CT: max-age=604800, report-uri="https://report-uri.cloudflare.com/cdn-cgi/beacon/expect-ct"
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,632Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] cf-request-id: REDACTED
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,632Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] Content-Type: text/plain
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,633Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] 
27.08.20 17:33:54 (+0200) <controller> yes
27.08.20 17:33:54 (+0200) <controller> 
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,634Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] checkSuspended: timeToSuspend = -1829475ms; suspendMode = true
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,635Z [WebSocketConnectReadThread-668] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): setting suspended; reason [ErrorInfo message=Received fatal alert: handshake_failure (See https://help.ably.io/error/80000) code=80000 statusCode=503 href=https://help.ably.io/error/80000]
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,647Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] Wait ended by action: io.ably.lib.transport.ConnectionManager$SynchronousStateChangeAction@1f38015
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,647Z [Thread-17] INFO  com.customer.app.AblyTransport - Connection state changed to 'suspended' from 'connecting'. Reason: '[ErrorInfo message=Received fatal alert: handshake_failure (See https://help.ably.io/error/80000) code=80000 statusCode=503 href=https://help.ably.io/error/80000]'.
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,653Z [WebSocketWriteThread-670] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,654Z [WebSocketConnectReadThread-666] DEBUG com.customer.app.AblyTransport - [Ably internal] onTransportUnavailable: ignoring disconnection event from superseded transport
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,654Z [WebSocketWriteThread-669] DEBUG com.customer.app.AblyTransport - [Ably internal] checkSuspended: timeToSuspend = -1829495ms; suspendMode = true
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,661Z [WebSocketWriteThread-669] DEBUG com.customer.app.AblyTransport - [Ably internal] setState(): not transitioning; not a valid transition suspended
27.08.20 17:33:54 (+0200) <controller> 2020-08-27T15:33:54,664Z [Thread-17] DEBUG com.customer.app.AblyTransport - [Ably internal] Wait ended by action: io.ably.lib.transport.ConnectionManager$SynchronousStateChangeAction@12559ac

CUSTOMER: this is an excerpt from the last part, but it looks the same

Jo from Ably: ok, let me take a look

CUSTOMER: treid to upgrade to 1.2.1 and deployed to my device, getting

[Ably internal] connect(); wsUri = wss://E.ably-realtime.com:443/?accessToken=REDACTED&v=1.0&format=msgpack&heartbeats=false&lib=java-1.2.1

CUSTOMER: then it fails with code -1

CUSTOMER: so has something happened with the certs on wss://ably-realtime.com

Jo from Ably: let me double check with our engineering team, but I do not think so.

CUSTOMER: strange that is has started to happen recently without any deployment

CUSTOMER: can this error occur if the token is invalid from options.authUrl ?

CUSTOMER: that's the only thing I can think of

CUSTOMER: it can't be that either since it works on windows but not on balenaOS / arm

Jo from Ably: We have recently had clients who were getting requests blocked by cloudflare, are you getting any errors from them?

Jo from Ably: our engineering team are going to take a look at your logs and will get back to you asap

CUSTOMER: thanks!

CUSTOMER: here it's fine but my device is at home. I should try more there but then I have to drive home

CUSTOMER: the server giving tokens is behind cloudflar

CUSTOMER: but I do get a token so I dunno why that could be the issue

CUSTOMER: I think I solved it

CUSTOMER: for some reason it now requires jdk.crypto.ec

CUSTOMER: but this will require a deployment across the whole fleet

CUSTOMER: https://stackoverflow.com/questions/55439599/sslhandshakeexception-with-jlink-created-runtime#comment105948918_55517159

CUSTOMER: so has something switched from SSL to TLS?

CUSTOMER: or something in that manner

Jo from Ably: Just checking with our SDK team. Apologies for the slow response.

CUSTOMER: no problem

CUSTOMER: I think something has changed on the server side and not the client library

Jo from Ably: I have not received a response from the SDK team whether there have been any changes, but usually such a thing would be communicated, so I do not belive there would have been. It sounds like you might have gotten to the bottom of the issue, but I'll get an update to you as soon as I can tomorrow as our support hours are now closing.

CUSTOMER: thanks!

CUSTOMER: yeah it would be interesting to know if your realtime server changed from SSL to TLS

CUSTOMER: hello again! seems like some of the older ones managed to connect again after handshake failure, so something must be going on in the server end of things

Jo from Ably: hello, ah, I'm glad it managed to connect again!

Jo from Ably: Would you like me to open a ticket for this support request so that the SDK team takes a look at it or are we ok to close?

CUSTOMER: hello :) the problem is still there on some devices, I would like to know what happened and why it suddenly started to happen after months of operation

CUSTOMER: I need to get to the bottom of it because I have to decide whether to deploy or if the problem will magically fix itself

Jo from Ably: Ok great, I'll open a ticket then and make sure you are notified, is the correct email address REDACTED ?

CUSTOMER: yes thanks

CUSTOMER: any idea when I might expect a response? the weekend is coming and if there's something in the APIs that have changed certificate / secure transport wise, I'd like to know if it affects java 11 w/o jdk.crypto.ec in jlink

Jo from Ably: Our engineering team are looking into this as we speak, I have created a ticket for it in our support desk: https://support.ably.com/a/tickets/114197 which will be updated when they have more information.

CUSTOMER: thanks! :)

Internal ticket: SDK-97

┆Issue is synchronized with this Jira Bug by Unito

QuintinWillison avatar Sep 29 '20 06:09 QuintinWillison

It seems, the connection is being closed by remote, so it's showing wscode=-1 (NEVER_CONNECTED - The connection had never been established)

sacOO7 avatar Oct 11 '20 18:10 sacOO7

Adding a reference to code causing the issue - https://github.com/TooTallNate/Java-WebSocket/blob/a76e0524ece10062ca98ffa74e20a9f9d8bbd51d/src/main/java/org/java_websocket/WebSocketImpl.java#L605

sacOO7 avatar Oct 11 '20 18:10 sacOO7

As the customer stated, It's definitely SSL handshake issue. Reference to code - https://github.com/TooTallNate/Java-WebSocket/blob/a76e0524ece10062ca98ffa74e20a9f9d8bbd51d/src/main/java/org/java_websocket/client/WebSocketClient.java#L966. Right after calling the SSL handshake error, it's sending ws code as -1. i.e. NEVER_CONNECTED

sacOO7 avatar Oct 11 '20 19:10 sacOO7

The library describes a fix for SSL/TLS related problems here : https://github.com/TooTallNate/Java-WebSocket/wiki/FAQ:-Secure-WebSockets#debugging-ssltls-connections

sacOO7 avatar Oct 11 '20 19:10 sacOO7

Currently can't really give a particular solution, since the problem is not clear. We will need more context-rich error logs related to SSL handshake.

sacOO7 avatar Oct 11 '20 19:10 sacOO7