Invalid Handshake over WS

[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.