Invalid Handshake over WS

[giuseppe.corti]

Hi Ike,

With the server log settings suggested in a previous post you should find these logs pertaining to a client session successfully bound to a websocket transport

26-Oct-23 09:32:33,112|INFO |L.connections |ACCEPT POOLED THREAD 8 |Accepted HTTP connection on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52916
26-Oct-23 09:32:33,800|INFO |L.requests |SERVER POOLED THREAD 10 |Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=jqWtj1twChtfDxikwp1ltvc B4CJCJi kOj2CKDk&LS_adapter_set=WELCOME& on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52916
26-Oct-23 09:32:33,997|INFO |L.requests |SERVER POOLED THREAD 10 |Starting new session: S132b0001a335379aM2ccT3233994 (dotnet_standard_client 5.1.8 build 109) on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52916
26-Oct-23 09:32:34,046|INFO |L.pump |SERVER POOLED THREAD 10 |Session S132b0001a335379aM2ccT3233994 started.
26-Oct-23 09:32:34,077|INFO |L.connections |PUMP POOLED THREAD 8 |Reused HTTP connection on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52916
26-Oct-23 09:32:34,151|INFO |L.connections |SERVER POOLED THREAD 10 |Closed HTTP connection with internal cause code: 5 (Interrupted by client) on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52916
26-Oct-23 09:32:34,248|INFO |L.connections |ACCEPT POOLED THREAD 8 |Accepted HTTP connection on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52917
26-Oct-23 09:32:36,478|INFO |L.connections |ACCEPT POOLED THREAD 8 |Upgraded HTTP connection on subprotocol TLCP-2.1.0 on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52917
26-Oct-23 09:32:36,555|INFO |L.requests |SERVER POOLED THREAD 10 |Serving request: bind_session -> LS_cause=loop1&LS_session=S132b0001a335379aM2ccT32 33994& on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52917
26-Oct-23 09:32:36,559|INFO |L.requests |SERVER POOLED THREAD 10 |Attaching session: S132b0001a335379aM2ccT3233994 on "Lightstreamer HTTP Server" from 0:0:0:0:0:0:0:1:52917

In particular the two lines bolded are the upgrade to websocket of the http channel.
In case the Lightstreamer server responds with a 404 to the upgrade request, instead of the message 'Upgraded HTTP connection on subprotocol TLCP-2.1.0...,' a DEBUG-level message from the 'LightstreamerLogger.webServer' logger should appear with error details.

[Ike]

Hi Giuseppe,

We set the logs on the server side and here is the log. The log starts from the bottom.

2023-10-26 12:33:40.222
26.Oct.23 17:33:40,222 < INFO> Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=jqWtj1twChtfDxikwp1ltvc B4CJCJi kOj2CKDk&LS_adapter_set=xxxxx&LS_user=xxxx&LS_pass word=[...]& on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.222
/lightstreamer/create_session.txt
2023-10-26 12:33:40.222
26.Oct.23 17:33:40,222 <DEBUG> Processing push request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.222
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=jqWtj1twChtfDxikwp1ltvc B4CJCJi kOj2CKDk&LS_adapter_set=xxxxx&LS_user=xxxx&LS_pass word=xxxxx&
2023-10-26 12:33:40.222
content-type: text/plain; charset=UTF-8
2023-10-26 12:33:40.222
user-agent: Lightstreamer.DotNetStandard.Client 5.1.8
2023-10-26 12:33:40.222
Content-Length: 272
2023-10-26 12:33:40.222
X-Scheme: https
2023-10-26 12:33:40.222
X-Forwarded-Proto: https
2023-10-26 12:33:40.222
X-Forwarded-Port: 443
2023-10-26 12:33:40.222
X-Forwarded-Host: xxxx
2023-10-26 12:33:40.222
X-Forwarded-For: xxxxxx
2023-10-26 12:33:40.222
X-Real-IP: xxxx
2023-10-26 12:33:40.222
X-Request-ID: 3b8bbd185b5540610fa9b045e52c924f
2023-10-26 12:33:40.222
Host: xxxx
2023-10-26 12:33:40.222
POST /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 HTTP/1.1
2023-10-26 12:33:40.222
26.Oct.23 17:33:40,221 <DEBUG> Parsing request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.222
26.Oct.23 17:33:40,221 <DEBUG> Got body of size 272 on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.222
26.Oct.23 17:33:40,221 < INFO> Accepted HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.222
26.Oct.23 17:33:40,221 <DEBUG> Socket accept on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:38.573
26.Oct.23 17:33:38,572 < INFO> Closed HTTP connection with internal cause code: 10 (Read timed out) on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:18.185
2023-10-26 17:33:18,184 DEBUG c.l.u.m.j.JMXMetricsCollector [pool-7-thread-5] Collected metrics
2023-10-26 12:33:18.184
2023-10-26 17:33:18,184 DEBUG c.l.u.m.j.JMXMetricsCollector [pool-7-thread-5] Collecting metrics from JMX...
2023-10-26 12:33:11.483
26.Oct.23 17:33:11,483 < INFO> Reused HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:11.483
OK
2023-10-26 12:33:11.483
x-accel-buffering: no
2023-10-26 12:33:11.483
Content-Length: 4
2023-10-26 12:33:11.483
Date: Thu, 26 Oct 2023 17:33:11 GMT
2023-10-26 12:33:11.483
Content-Type: text/plain; charset=iso-8859-1
2023-10-26 12:33:11.483
Server: Lightstreamer-Server/7.2.2 build 2341 (Lightstreamer Server - www.lightstreamer.com) ENTERPRISE edition
2023-10-26 12:33:11.483
HTTP/1.1 200 OK
2023-10-26 12:33:11.483
26.Oct.23 17:33:11,483 <DEBUG> Writing response on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:11.483
/lightstreamer/healthcheck
2023-10-26 12:33:11.483
26.Oct.23 17:33:11,482 <DEBUG> Processing push request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:11.483
Accept-Encoding: gzip,deflate,identity
2023-10-26 12:33:11.483
User-Agent: Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)
2023-10-26 12:33:11.483
X-Scheme: https
2023-10-26 12:33:11.483
X-Forwarded-Proto: https
2023-10-26 12:33:11.483
X-Forwarded-Port: 443
2023-10-26 12:33:11.483
X-Forwarded-Host: xxxx
2023-10-26 12:33:11.483
X-Forwarded-For: xxxxx
2023-10-26 12:33:11.483
X-Real-IP: xxxxx
2023-10-26 12:33:11.483
X-Request-ID: 4a7ac8ee1e9a2f34c5340e2ca6e44483
2023-10-26 12:33:11.483
Host: xxxx
2023-10-26 12:33:11.483
GET /lightstreamer/healthcheck HTTP/1.1
2023-10-26 12:33:11.483
26.Oct.23 17:33:11,482 <DEBUG> Parsing request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:11.483
26.Oct.23 17:33:11,482 < INFO> Accepted HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:11.483
2023-10-26 12:32:38.573
26.Oct.23 17:32:38,573 < INFO> Closed HTTP connection with internal cause code: 10 (Read timed out) on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:32:18.185
2023-10-26 17:32:18,184 DEBUG c.l.u.m.j.JMXMetricsCollector [pool-7-thread-4] Collected metrics
2023-10-26 12:32:18.184
2023-10-26 17:32:18,183 DEBUG c.l.u.m.j.JMXMetricsCollector [pool-7-thread-4] Collecting metrics from JMX...
2023-10-26 12:32:11.403
26.Oct.23 17:32:11,402 < INFO> Reused HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:32:11.403
OK
2023-10-26 12:32:11.403
x-accel-buffering: no
2023-10-26 12:32:11.403
Content-Length: 4
2023-10-26 12:32:11.403
Date: Thu, 26 Oct 2023 17:32:11 GMT
2023-10-26 12:32:11.403
Content-Type: text/plain; charset=iso-8859-1
2023-10-26 12:32:11.403
Server: Lightstreamer-Server/7.2.2 build 2341 (Lightstreamer Server - www.lightstreamer.com) ENTERPRISE edition
2023-10-26 12:32:11.403
HTTP/1.1 200 OK
2023-10-26 12:32:11.403
26.Oct.23 17:32:11,402 <DEBUG> Writing response on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:32:11.403
/lightstreamer/healthcheck
2023-10-26 12:32:11.403
26.Oct.23 17:32:11,402 <DEBUG> Processing push request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:32:11.403
Accept-Encoding: gzip,deflate,identity
2023-10-26 12:32:11.403
User-Agent: Pingdom.com_bot_version_1.4_(http://www.pingdom.com/)
2023-10-26 12:32:11.403
X-Scheme: https
2023-10-26 12:32:11.403
X-Forwarded-Proto: https
2023-10-26 12:32:11.403
X-Forwarded-Port: 443
2023-10-26 12:32:11.403
X-Forwarded-Host: xxxx
2023-10-26 12:32:11.403
X-Forwarded-For: xxxxxxx
2023-10-26 12:32:11.403
X-Real-IP: xxxxxxx
2023-10-26 12:32:11.403
X-Request-ID: 56526eda9f70d85b7e0831483e09a5f9
2023-10-26 12:32:11.403
Host: xxxx
2023-10-26 12:32:11.403
GET /lightstreamer/healthcheck HTTP/1.1
2023-10-26 12:32:11.403
26.Oct.23 17:32:11,402 <DEBUG> Parsing request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:32:11.402
26.Oct.23 17:32:11,402 < INFO> Accepted HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:32:11.402
26.Oct.23 17:32:11,402 <DEBUG> Socket accept on "Lightstreamer HTTP Server" from xxxxx

[Ike]

here's the rest of it. again it starts from the bottom.

2023-10-26 12:33:51.027
26.Oct.23 17:33:51,026 <DEBUG> Parsing request on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:51.027
26.Oct.23 17:33:51,026 <DEBUG> Got body of size 146 on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:51.027
26.Oct.23 17:33:51,026 < INFO> Accepted HTTP connection on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:51.027
26.Oct.23 17:33:51,026 <DEBUG> Socket accept on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.807
26.Oct.23 17:33:50,807 < INFO> Reused HTTP connection on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.807
26.Oct.23 17:33:50,806 < INFO> Session S4227a9bb98d54f89M8b3T3350806 started.
2023-10-26 12:33:50.807
26.Oct.23 17:33:50,806 < INFO> Starting new session: S4227a9bb98d54f89M8b3T3350806 (dotnet_standard_client 5.1.8 build 109) on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.800
26.Oct.23 17:33:50,800 < INFO> Serving request: /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 --> LS_polling=true&LS_cause=new.switch.timeout.timeou t.FIRST_BINDING.1&LS_polling_millis=0&LS_idle_mill is=0&LS_cid=jqWtj1twChtfDxikwp1ltvcB4CJCJi kOj2CKDk&LS_adapter_set=xxxxx&LS_user=xxxx&LS_pass word=[...]&LS_old_session=Sf35cb3885663aa23M8b3T3340342& on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.800
/lightstreamer/create_session.txt
2023-10-26 12:33:50.800
26.Oct.23 17:33:50,799 <DEBUG> Processing push request on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.800
LS_polling=true&LS_cause=new.switch.timeout.timeou t.FIRST_BINDING.1&LS_polling_millis=0&LS_idle_mill is=0&LS_cid=jqWtj1twChtfDxikwp1ltvcB4CJCJi kOj2CKDk&LS_adapter_set=xxxxx&LS_user=xxxx&LS_pass word=xxxxx&LS_old_session=Sf35cb3885663aa23M8b3T33 40342&
2023-10-26 12:33:50.800
content-type: text/plain; charset=UTF-8
2023-10-26 12:33:50.800
user-agent: Lightstreamer.DotNetStandard.Client 5.1.8
2023-10-26 12:33:50.800
cookie: xxxxx-futureslightstreamer=1698341621.221.22712.173367
2023-10-26 12:33:50.800
Content-Length: 352
2023-10-26 12:33:50.800
X-Scheme: https
2023-10-26 12:33:50.800
X-Forwarded-Proto: https
2023-10-26 12:33:50.800
X-Forwarded-Port: 443
2023-10-26 12:33:50.800
X-Forwarded-Host: xxxx
2023-10-26 12:33:50.800
X-Forwarded-For: 192.111.84.36
2023-10-26 12:33:50.800
X-Real-IP: 192.111.84.36
2023-10-26 12:33:50.800
X-Request-ID: a2bd4f36c384cf443f4ab87e66e89dba
2023-10-26 12:33:50.800
Host: xxxx
2023-10-26 12:33:50.800
POST /lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0 HTTP/1.1
2023-10-26 12:33:50.800
26.Oct.23 17:33:50,799 <DEBUG> Parsing request on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.800
26.Oct.23 17:33:50,799 <DEBUG> Got body of size 352 on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.800
26.Oct.23 17:33:50,799 < INFO> Accepted HTTP connection on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.800
26.Oct.23 17:33:50,799 <DEBUG> Socket accept on "Lightstreamer HTTP Server" from xxxxxxx
2023-10-26 12:33:50.344
26.Oct.23 17:33:50,343 < INFO> Session Sf35cb3885663aa23M8b3T3340342 closed after 10001 ms, initiated on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:50.344
26.Oct.23 17:33:50,343 < INFO> Closed session Sf35cb3885663aa23M8b3T3340342 with internal cause code: 39/1 (Timeout waiting for client rebind after creation).
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,800 < INFO> Reused HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.800
REQOK,2
2023-10-26 12:33:46.800
x-accel-buffering: no
2023-10-26 12:33:46.800
Content-Length: 9
2023-10-26 12:33:46.800
Date: Thu, 26 Oct 2023 17:33:46 GMT
2023-10-26 12:33:46.800
Expires: Thu, 1 Jan 1970 00:00:00 GMT
2023-10-26 12:33:46.800
Pragma: no-cache
2023-10-26 12:33:46.800
Cache-Control: no-cache
2023-10-26 12:33:46.800
Cache-Control: no-transform
2023-10-26 12:33:46.800
Cache-Control: no-store
2023-10-26 12:33:46.800
Content-Type: text/enriched; charset=ISO-8859-1
2023-10-26 12:33:46.800
Server: Lightstreamer-Server/7.2.2 build 2341 (Lightstreamer Server - www.lightstreamer.com) ENTERPRISE edition
2023-10-26 12:33:46.800
HTTP/1.1 200 OK
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,800 <DEBUG> Writing response on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,799 < INFO> Forcing rebind on session: Sf35cb3885663aa23M8b3T3340342 on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,799 < INFO> Serving request: /lightstreamer/control.txt?LS_protocol=TLCP-2.1.0 --> LS_reqId=2&LS_op=force_rebind&LS_session=Sf35cb388 5663aa23M8b3T3340342&LS_cause=timeout.FIRST_BINDIN G.1& on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.800
/lightstreamer/control.txt
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,799 <DEBUG> Processing push request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.800
LS_reqId=2&LS_op=force_rebind&LS_session=Sf35cb388 5663aa23M8b3T3340342&LS_cause=timeout.FIRST_BINDIN G.1&
2023-10-26 12:33:46.800
content-type: text/plain; charset=UTF-8
2023-10-26 12:33:46.800
user-agent: Lightstreamer.DotNetStandard.Client 5.1.8
2023-10-26 12:33:46.800
cookie: xxxx-futureslightstreamer=1698341621.221.22712.173367
2023-10-26 12:33:46.800
Content-Length: 106
2023-10-26 12:33:46.800
X-Scheme: https
2023-10-26 12:33:46.800
X-Forwarded-Proto: https
2023-10-26 12:33:46.800
X-Forwarded-Port: 443
2023-10-26 12:33:46.800
X-Forwarded-Host: xxxx
2023-10-26 12:33:46.800
X-Forwarded-For: xxxxx
2023-10-26 12:33:46.800
X-Real-IP: xxxxx
2023-10-26 12:33:46.800
X-Request-ID: c4b6b90c953cf976133bea881ea4474e
2023-10-26 12:33:46.800
Host: xxxx
2023-10-26 12:33:46.800
POST /lightstreamer/control.txt?LS_protocol=TLCP-2.1.0 HTTP/1.1
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,799 <DEBUG> Parsing request on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.800
26.Oct.23 17:33:46,799 <DEBUG> Got body of size 106 on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.799
26.Oct.23 17:33:46,799 < INFO> Accepted HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:46.799
26.Oct.23 17:33:46,799 <DEBUG> Socket accept on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.344
26.Oct.23 17:33:40,343 < INFO> Reused HTTP connection on "Lightstreamer HTTP Server" from xxxxx
2023-10-26 12:33:40.343
26.Oct.23 17:33:40,343 < INFO> Session Sf35cb3885663aa23M8b3T3340342 started.
2023-10-26 12:33:40.343
26.Oct.23 17:33:40,342 < INFO> Starting new session: Sf35cb3885663aa23M8b3T3340342 (dotnet_standard_client 5.1.8 build 109) on "Lightstreamer HTTP Server" from xxxxx

[giuseppe.corti]

Hi Ike,

In the log, there is no trace of the WebSocket protocol upgrade requests, neither successful nor any errors.
It's possible that there is an intermediary between your client and the server that intercepts WebSocket requests?
In fact, if, for any reason, WebSocket transport is blocked in your environment, it would be better to force the use of HTTP streaming with this client setting:

client.connectionOptions.ForcedTransport = "HTTP";

https://sdk.lightstreamer.com/ls-dot...orcedTransport

[Ike]

Hi Giuseppe, we already have JavaScript and Java client that are working fine (streaming WS) against the same server set up, so not sure why it's not working with the.NET client. Anyway, thanks for looking into this.

[Ike]

Also, we did some testing on the LS dotnet client locally. We were able to get it to upgrade to WS.
Problem occurs when we test with the servers in K8s. Locally we're hitting the local LS server using HTTP. The Azure K8s LS instance is HTTPS. Also there is an Nginx ingress controller in AZ K8s. Those are the only differences we can think of, besides one set of clients are JS/WebBrowsers and the other is C#.

[giuseppe.corti]

Hi Ike,

This is strange, from the log you collected so far, it seems that the client send the we upgrade request bur receive a 404 error.
On the server side, it seems that the WebSocket upgrade request was never received.
To try to determine if the problem lies on the client or server side, would you be able to conduct a test by pointing your client to our demo server?
You should set "https://push.lightstreamer.com" as the URL and "WELCOME" as the adapter set.

[Ike]

Hi Giuseppe,

I got 502 error when I pointed to your demo server.

2023-10-30 09:01:46,581 DEBUG lightstreamer.stream - HTTP transport connection establishing (oid=1): https://push.lightstreamer.com:443
/lightstreamer/create_session.txt?LS_protocol=TLCP-2.1.0
LS_polling=true&LS_cause=new.api&LS_polling_millis =0&LS_idle_millis=0&LS_cid=jqWtj1twChtfDxikwp1ltvc B4CJCJi kOj2CKDk&LS_adapter_set=WELCOME&
2023-10-30 09:01:46,582 DEBUG lightstreamer.stream - - target: 34.217.249.182:443 - True(com.lightstreamer.client.transport.providers. netty.NettyFullAddress).
2023-10-30 09:01:46,667 DEBUG lightstreamer.netty.pool - New HTTP channel pool created. Remote address: 34.217.249.182:443
2023-10-30 09:01:46,873 DEBUG lightstreamer.session - sessionStatusChanged 1, 1
2023-10-30 09:01:46,874 DEBUG lightstreamer.session - Session state change (1): OFF -> CREATING
2023-10-30 09:01:46,877 DEBUG lightstreamer.session - phasing : 1 - 1
2023-10-30 09:01:46,881 DEBUG lightstreamer.session - Status timeout in 4000 [currentConnectTimeout] due to
2023-10-30 09:01:46,896 DEBUG lightstreamer.netty.pool - HTTP channel created [2687cef5, com.lightstreamer.client.transport.providers.netty .NettyFullAddress]: False
2023-10-30 09:01:46,975 DEBUG lightstreamer.netty.pool - HTTP channel active [2687cef5]
2023-10-30 09:01:47,006 DEBUG lightstreamer.stream - - acquired! 2687cef5
2023-10-30 09:01:47,013 DEBUG lightstreamer.stream - Go with the request True
2023-10-30 09:01:47,094 DEBUG lightstreamer.stream - Send Request Task status = RanToCompletion
2023-10-30 09:01:47,413 DEBUG lightstreamer.stream - HTTP transport receiving [2687cef5]:
CONOK,S4fb5a355a280f791M90bT0146909,50000,0,*
SERVNAME,Lightstreamer HTTPS Server
CLIENTIP,163.116.133.115
LOOP,0
2023-10-30 09:01:47,415 DEBUG lightstreamer.stream - Readeable bytes: 118
2023-10-30 09:01:47,415 DEBUG lightstreamer.stream - Start: 0
2023-10-30 09:01:47,416 DEBUG lightstreamer.stream - findEol: 0 <> 118
2023-10-30 09:01:47,417 DEBUG lightstreamer.stream - findEol - cr: 45 eol:46
2023-10-30 09:01:47,417 DEBUG lightstreamer.stream - never ending story of a message com.lightstreamer.client.transport.Http+MyHttpList ener - CONOK,S4fb5a355a280f791M90bT0146909,50000,0,*
2023-10-30 09:01:47,418 DEBUG lightstreamer.stream - .:. com.lightstreamer.client.transport.providers.netty .NettyRequestListener - CONOK,S4fb5a355a280f791M90bT0146909,50000,0,*
2023-10-30 09:01:47,418 DEBUG lightstreamer.stream - findEol: 47 <> 118
2023-10-30 09:01:47,419 DEBUG lightstreamer.stream - findEol - cr: 82 eol:83
2023-10-30 09:01:47,419 DEBUG lightstreamer.stream - never ending story of a message com.lightstreamer.client.transport.Http+MyHttpList ener - SERVNAME,Lightstreamer HTTPS Server
2023-10-30 09:01:47,419 DEBUG lightstreamer.stream - .:. com.lightstreamer.client.transport.providers.netty .NettyRequestListener - SERVNAME,Lightstreamer HTTPS Server
2023-10-30 09:01:47,419 DEBUG lightstreamer.stream - findEol: 84 <> 118
2023-10-30 09:01:47,419 DEBUG lightstreamer.stream - findEol - cr: 108 eol:109
2023-10-30 09:01:47,420 DEBUG lightstreamer.stream - never ending story of a message com.lightstreamer.client.transport.Http+MyHttpList ener - CLIENTIP,163.116.133.115
2023-10-30 09:01:47,420 DEBUG lightstreamer.stream - .:. com.lightstreamer.client.transport.providers.netty .NettyRequestListener - CLIENTIP,163.116.133.115
2023-10-30 09:01:47,420 DEBUG lightstreamer.stream - findEol: 110 <> 118
2023-10-30 09:01:47,420 DEBUG lightstreamer.stream - findEol - cr: 116 eol:117
2023-10-30 09:01:47,421 DEBUG lightstreamer.stream - never ending story of a message com.lightstreamer.client.transport.Http+MyHttpList ener - LOOP,0
2023-10-30 09:01:47,421 DEBUG lightstreamer.stream - .:. com.lightstreamer.client.transport.providers.netty .NettyRequestListener - LOOP,0
2023-10-30 09:01:47,421 DEBUG lightstreamer.stream - findEol: 118 <> 118
2023-10-30 09:01:47,421 DEBUG lightstreamer.stream - .:.: False(0)
2023-10-30 09:01:47,421 DEBUG lightstreamer.stream - linePart: 0
2023-10-30 09:01:47,422 DEBUG lightstreamer.stream - Reuse failed for 2687cef5
2023-10-30 09:01:47,437 DEBUG lightstreamer.netty.pool - HTTP channel inactive [2687cef5]
2023-10-30 09:01:47,437 DEBUG lightstreamer.netty.pool - ... False - False
2023-10-30 09:01:47,437 DEBUG lightstreamer.netty.pool - Socket Closed.
2023-10-30 09:01:47,441 DEBUG lightstreamer.protocol - New message (1 - OPENING_STREAM): CONOK,S4fb5a355a280f791M90bT0146909,50000,0,*
2023-10-30 09:01:47,444 DEBUG lightstreamer.session - OK event while CREATING
2023-10-30 09:01:47,444 DEBUG lightstreamer.session - Address to use after create: https://push.lightstreamer.com/
2023-10-30 09:01:47,444 DEBUG lightstreamer.session - Data event while CREATING
2023-10-30 09:01:47,444 DEBUG lightstreamer.session - sessionStatusChanged 1, 1
2023-10-30 09:01:47,444 DEBUG lightstreamer.session - Session state change (1): CREATING -> CREATED
2023-10-30 09:01:47,445 DEBUG lightstreamer.session - phasing : 2 - 2
2023-10-30 09:01:47,445 DEBUG lightstreamer.session - Status timeout in 2000 [executionTimeout] due to
2023-10-30 09:01:47,445 DEBUG lightstreamer.session - Check Point 1a120ak.
2023-10-30 09:01:47,445 DEBUG lightstreamer.subscribe - SubscriptionManager sessionAlive set to true.
2023-10-30 09:01:47,446 DEBUG lightstreamer.subscribe - sendAllSubscriptions: 0
2023-10-30 09:01:47,447 DEBUG lightstreamer.subscribe - sendAllSubscriptions done!
2023-10-30 09:01:47,448 INFO lightstreamer.subscribe - Start message handler
2023-10-30 09:01:47,448 DEBUG lightstreamer.subscribe - Sending queued messages
2023-10-30 09:01:47,450 INFO lightstreamer.actions - Session ID value changed to S4fb5a355a280f791M90bT0146909
2023-10-30 09:01:47,450 INFO lightstreamer.actions - Server Instance Address value changed to https://push.lightstreamer.com/
2023-10-30 09:01:47,450 DEBUG lightstreamer.protocol - New message (1 - READING_STREAM): SERVNAME,Lightstreamer HTTPS Server
2023-10-30 09:01:47,451 INFO lightstreamer.actions - Server Socket Name value changed to Lightstreamer HTTPS Server
2023-10-30 09:01:47,451 DEBUG lightstreamer.protocol - New message (1 - READING_STREAM): CLIENTIP,163.116.133.115
2023-10-30 09:01:47,451 INFO lightstreamer.actions - Client IP value changed to 163.116.133.115
2023-10-30 09:01:47,451 DEBUG lightstreamer.protocol - New message (1 - READING_STREAM): LOOP,0
2023-10-30 09:01:47,453 DEBUG lightstreamer.session - sessionStatusChanged 1, 1
2023-10-30 09:01:47,453 DEBUG lightstreamer.session - Session state change (1): CREATED -> FIRST_PAUSE
2023-10-30 09:01:47,453 DEBUG lightstreamer.session - phasing : 3 - 3
2023-10-30 09:01:47,454 DEBUG lightstreamer.session - Timeout event [noPause] while FIRST_PAUSE cause=
2023-10-30 09:01:47,455 DEBUG lightstreamer.session - SessionWS state change (1) (sendBind): WS_NOT_CONNECTED -> WS_CONNECTING
2023-10-30 09:01:47,457 INFO lightstreamer.stream - Requested cookies for uri https://push.lightstreamer.com/lightstreamer:
2023-10-30 09:01:47,460 DEBUG lightstreamer.netty.pool - New WS channel pool created. Remote address: 34.217.249.182:4432023-10-30 09:01:47,462 DEBUG lightstreamer.netty.pool - ... try get parent pool channel ... com.lightstreamer.client.transport.providers.netty .HttpPoolManager+HttpChannelPool
2023-10-30 09:01:47,464 DEBUG lightstreamer.netty.pool - HTTP channel created [63a8f9c9, com.lightstreamer.client.transport.providers.netty .NettyFullAddress]: False
2023-10-30 09:01:47,467 DEBUG lightstreamer.stream - WebSocket transport - : CONNECTING
2023-10-30 09:01:47,467 DEBUG lightstreamer.requests - Status timeout in 4000 [currentConnectTimeoutWS]
2023-10-30 09:01:47,467 DEBUG lightstreamer.session - SessionWS state change (1) (sendBind): WS_CONNECTING
2023-10-30 09:01:47,536 DEBUG lightstreamer.netty.pool - HTTP channel active [63a8f9c9]
2023-10-30 09:01:47,539 DEBUG lightstreamer.netty.pool - ... Channel [id: 0x63a8f9c9, [::ffff:192.168.86.150]:53426 => [::ffff:34.217.249.182]:443]
2023-10-30 09:01:47,540 DEBUG lightstreamer.netty.pool - Wait WS upgrade completition.
2023-10-30 09:01:47,541 DEBUG lightstreamer.netty.pool - [id: 0x63a8f9c9, [::ffff:192.168.86.150]:53426 => [::ffff:34.217.249.182]:443] is active -> upgrade ...
2023-10-30 09:01:47,542 DEBUG lightstreamer.netty.pool - [id: 0x63a8f9c9, [::ffff:192.168.86.150]:53426 => [::ffff:34.217.249.182]:443] ... wait upgrade ... False
CONNECTED:STREAM-SENSING
2023-10-30 09:01:49,554 DEBUG lightstreamer.netty.pool - ... wsHandshakeHandler ...
2023-10-30 09:01:49,557 DEBUG lightstreamer.netty.pool - ... add ws pipeline ...
2023-10-30 09:01:49,576 DEBUG lightstreamer.netty.pool - ... ws handshake task: 212 - False - False - False
2023-10-30 09:01:49,577 DEBUG lightstreamer.netty.pool - [id: 0x63a8f9c9, [::ffff:192.168.86.150]:53426 => [::ffff:34.217.249.182]:443] ... wait upgrade 2 ... False
2023-10-30 09:01:49,581 DEBUG lightstreamer.netty.pool - [id: 0x63a8f9c9, [::ffff:192.168.86.150]:53426 => [::ffff:34.217.249.182]:443] ... done False - True
2023-10-30 09:01:50,448 DEBUG lightstreamer.netty.pool - WS Read0 - False - Msg:AggregatedFullHttpResponse(decodeResult: success, version: HTTP/1.1, content: CompositeByteBuffer(ridx: 0, widx: 1326, cap: 1326, components=2))
HTTP/1.1 502 Bad Gateway
Connection:close
Content-Length:1326
2023-10-30 09:01:50,449 DEBUG lightstreamer.netty.pool - WS Read0 -- 502 Bad Gateway
2023-10-30 09:01:50,452 INFO lightstreamer.netty.pool - WS upgrade error: Invalid handshake response getStatus: 502 Bad Gateway
2023-10-30 09:01:50,452 DEBUG lightstreamer.netty.pool - WS Read0 ----- 502 Bad Gateway

[giuseppe.corti]

It seems that in your client's environment, there is something interfering with the WebSocket upgrade requests.