Issue with TWebSocketAsyncServer

maro · 2023-11-02 09:59:10

My situation is as follows:
- Delphi 7 is used as compiler
- Operating system Windows Server 2019 Datacenter
- mORMot2 source code referenced on commit 8c357e18e4627a3de1cdb62c09e013d092086cfd

The service had the same problems with the TWebSocketAsyncServer as mentioned in the post (https://synopse.info/forum/viewtopic.php?id=6682).
After a few hours, the CPU load was high. So, we updated mORMot2 to the commit "8c357e18e4627a3de1cdb62c09e013d092086cfd". Since then we have the problem that after a certain time the websocket server rejects incoming connections. I have the appropriate logging for such an incident as well as a layer 3 trace. Since TLS is in use, I don't see anything from the websocket protocol, but I can see that the websocket server sends a TCP FIN packet.
I would like to attach the TSynLog generated file, but I don't see a function here in the forum.

/edit

20231031 07112644 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) ConnectionNew {"TWebSocketAsyncConnection(0f0f9e00)":{Handle:91,RemoteIP:"212.76.196.6",RemoteIPWithPort:"212.76.196.6:60223",RemotePort:60223}} sock=0ad0 count=1 gc=0
20231031 07112644 trace mormot.net.async.TPollConnectionSockets(0a651570) GetOnePending(R1:##PROTOCOL##)=0f0f9e00 1 #1/1
20231031 07112645 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9cd0) Write len=2 $89$00
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) IdleEverySecond TWebSocketAsyncConnection idle=1 notif=1 gc=0B 46us
20231031 07112646 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) ProcessRead recv(0ad0)=Retry len=32768 in 10us {"TPollConnectionSockets(0a651570)":{Count:1}}
20231031 07112646 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) Subscribe(0ad0)=true read handle=91 pseRead cnt=1
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents=1 in fPoll[0] (subscribed=1) pending=1 182334us
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) GetOnePending(R1:##PROTOCOL##)=0f0f9cd0 1 #1/1
20231031 07112646 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) ProcessRead recv(0a7c)=Ok len=6 in 32us {"TPollConnectionSockets(0a651570)":{Count:1,SubscribeCount:1}}
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents sub=1 unsub=0
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents Subscribe(0ad0) count=1
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents=1 in fPoll[0] (subscribed=2) pending=1 3178us
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) GetOnePending(R1:##PROTOCOL##)=0f0f9e00 1 #1/1
20231031 07112646 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) ProcessRead recv(0ad0)=Ok len=200 in 378us {"TPollConnectionSockets(0a651570)":{Count:2}}
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) OnRead hrsGetCommand len=200 GET /endpoint HTTP/1.1$0d$0aUser-Agent: websocket-sharp/1.0$0d$0aHost: ##SERVER_IP_ADDRESS##:8998$0d$0aUpgrade: websocket$0d$0aConnection: Upgrade$0d$0aSec-WebSocket-Key: AQk5bd0m4WdzW9UcXfNDNQ==$0d$0aSec-WebSocket-Version: 13$0d$0a$0d$0a
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=162 HTTP/1.1 101 Switching Protocols$0d$0aUpgrade: websocket$0d$0aConnection: Upgrade$0d$0aSec-WebSocket-Connection-ID: 91$0d$0aSec-WebSocket-Accept: PDImcTaMgOJa1tWZau+RcPd0Dj8=$0d$0a$0d$0a
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents=1 in fPoll[0] (subscribed=2) pending=1 14051us
20231031 07112646 trace mormot.net.async.TPollConnectionSockets(0a651570) GetOnePending(R1:##PROTOCOL##)=0f0f9e00 1 #1/1
20231031 07112646 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) ProcessRead recv(0ad0)=Ok len=6 in 35us {"TPollConnectionSockets(0a651570)":{Count:2}}
20231031 07112646 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=2 $8a$00
20231031 07112648 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112649 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112649 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents=1 in fPoll[0] (subscribed=2) pending=1 19727us
20231031 07112649 trace mormot.net.async.TPollConnectionSockets(0a651570) GetOnePending(R1:##PROTOCOL##)=0f0f9e00 1 #1/1
20231031 07112649 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) ProcessRead recv(0ad0)=Ok len=114 in 38us {"TPollConnectionSockets(0a651570)":{Count:2}}
20231031 07112650 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112651 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112652 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112653 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112654 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112655 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112656 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112657 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112658 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112659 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112660 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112661 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112662 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112700 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112701 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112702 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112703 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=1 #2=0 free=0
20231031 07112704 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112705 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112706 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112707 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112708 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112709 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112710 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112711 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112712 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112713 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112714 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112715 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112716 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112717 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112718 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112719 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112720 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112721 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112722 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112723 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112723 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=92 $81Z["##OWN_PROTOCOL##"]
20231031 07112723 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=30 $81$1c["##OWN_PROTOCOL##"]
20231031 07112724 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112725 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112725 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112727 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112728 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112729 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112729 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112730 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112731 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112732 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112733 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112734 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112735 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112736 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112737 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112739 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112740 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112741 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112742 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112743 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112743 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=76 $81J["##OWN_PROTOCOL##"]
20231031 07112744 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112745 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112746 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112747 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112748 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112748 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=231 $81~$00$e3["##OWN_PROTOCOL##"]
20231031 07112749 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112750 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112751 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112752 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112753 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112754 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112755 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112755 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=99 $81a["##OWN_PROTOCOL##"]
20231031 07112756 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112757 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112758 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112759 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112760 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112761 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112762 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112800 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112801 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112802 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112803 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112804 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112804 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112806 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112807 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) DoGC #1=0 #2=1 free=0
20231031 07112807 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents=1 in fPoll[0] (subscribed=2) pending=1 321049us
20231031 07112807 trace mormot.net.async.TPollConnectionSockets(0a651570) GetOnePending(R1:##PROTOCOL##)=0f0f9e00 1 #1/1
20231031 07112807 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) ProcessRead recv(0ad0)=Ok len=6 in 34us {"TPollConnectionSockets(0a651570)":{Count:2}}
20231031 07112807 trace mormot.net.ws.async.TWebSocketAsyncConnection(0f0f9e00) Write len=2 $88$00
20231031 07112807 trace mormot.net.async.TAsyncConnectionsSockets(0c6713e8) Stop sock=0ad0 handle=91 r=1+ w=0-
20231031 07112807 trace mormot.net.ws.async.TWebSocketAsyncConnections(0ef36dd0) ConnectionDelete {"TWebSocketAsyncConnection(0f0f9e00)":{Handle:91,RemoteIP:"212.76.196.6",RemoteIPWithPort:"212.76.196.6:60223",RemotePort:60223}} ndx=1 count=1 1us
20231031 07112807 trace mormot.net.async.TPollConnectionSockets(0a651570) PollForPendingEvents sub=0 unsub=1

Do you have any idea what I can do?

Last edited by maro (2023-11-02 10:11:29)

ab · 2023-11-03 14:48:14

Please follow the forum rules and don't post huge content like those log lines within the message.

Does the blocking happen also without TLS?

maro · 2023-11-03 15:14:08

My intention was not to break any rules. That's why I only attached the excerpt from the complete log of a logical connection attempt.
Regarding the question of whether the same thing happens without TLS, unfortunately I can't answer that.
The service runs at the customer with the security layer, which we cannot switch off.
I have been able to investigate this twice within the development environment, but unfortunately I cannot reproduce it.
I also had it running with TLS in the development environment. I was able to debug the source code up to "THttpAsyncConnection.DoHeaders", after which the connection timed out.
I would have to assume that the same thing should happen without TLS, as the close already occurred at websocket protocol level.

maro · 2023-11-09 10:30:21

I can narrow it down enough to say that it only happens within an encrypted communication. Is there a way to debug the TLS layer or determine why the layer breaks down?

ec · 2023-11-09 10:51:05

Good morning !

The following situation was also observed: Quickly connecting and disconnecting a single websocket client, everything works well, it is possible to connect and disconnect quickly and efficiently. From the second websocket client onwards, the behavior of new connections changes. Thereafter, there is an unusual delay in all new connections, until, finally, the new connections are rejected. In the test carried out there is no data traffic, only websocket connection and disconnection.

** This does not happen without TLS !!!

I hope I contributed in some way

Last edited by ec (2023-11-09 18:34:27)

maro · 2023-11-15 08:36:33

I was able to reproduce a problem several times within the development environment, but I am not sure whether this has the same cause.
In any case, the communication in the protocol aborts. My guess is that the connection closes because the server does not answer the websocket PING.

I would need support on where to possibly start debugging this.

Time			Source			Info
13.11.23 12:21:01	Client -> Server	57420 → 8998 [SYN] Seq=0 Win=64240 Len=0 MSS=1460 SACK_PERM TSval=3260404215 TSecr=0 WS=128
13.11.23 12:21:01	Server -> Client	8998 → 57420 [SYN, ACK] Seq=0 Ack=1 Win=65535 Len=0 MSS=1460 WS=256 SACK_PERM
13.11.23 12:21:01	Client -> Server	57420 → 8998 [ACK] Seq=1 Ack=1 Win=64256 Len=0
13.11.23 12:21:01	Client -> Server	GET /endpoint HTTP/1.1
13.11.23 12:21:01	Server -> Client	HTTP/1.1 101 Switching Protocols
13.11.23 12:21:01	Client -> Server	57420 → 8998 [ACK] Seq=317 Ack=168 Win=64128 Len=0
13.11.23 12:21:03	Client -> Server	WebSocket Ping [FIN] [MASKED]
13.11.23 12:21:03	Server -> Client	8998 → 57420 [ACK] Seq=168 Ack=323 Win=2102272 Len=0
13.11.23 12:21:07	Server -> Client	WebSocket Ping [FIN]
13.11.23 12:21:07	Client -> Server	WebSocket Pong [FIN] [MASKED]
13.11.23 12:21:07	Server -> Client	8998 → 57420 [ACK] Seq=170 Ack=329 Win=2102272 Len=0
13.11.23 12:21:11	Server -> Client	WebSocket Connection Close [FIN]
13.11.23 12:21:11	Client -> Server	WebSocket Connection Close [FIN] [MASKED]
13.11.23 12:21:11	Client -> Server	57420 → 8998 [FIN, ACK] Seq=335 Ack=172 Win=64128 Len=0
13.11.23 12:21:11	Server -> Client	8998 → 57420 [ACK] Seq=172 Ack=336 Win=2102272 Len=0

ec · 2023-11-23 12:56:54

Good morning Arnaud !

What do you think could be happening ?

Thank you for your attention

ab · 2023-11-23 18:52:01

We need to circumvent the issue.
@maro are you using TLS too? I suspect not...
@ec are you sure this is the same problem as @maro ?

@ec
Which TLS layer are you using?
Default SSPI Windows API or OpenSSL?
You may try with OpenSSL.
On Server side, but also on client(s) side.

@maro
If TLS is not involved, could you try with a Linux server to see if it is a network problem on the server layer?

ec · 2023-11-23 20:17:20

Hi Arnaud !

I'm not sure if this is the same problem observed by @maro.

Tested only with Default SSPI Windows API (Windows 10 and 11). I'm sure this only occurs on the server side.

Reproducing what I observed is very simple.

1) I created a websocket listener:
FWsServer :=
TWebSocketAsyncServer.Create('0.0.0.0:7799', Nil, Nil, 'Acceptor', 32, 30000, [
hsoNoXPoweredHeader, hsoHeadersInterning, hsoThreadSmooting,
hsoNoStats, hsoBan40xIP, hsoEnableTls ]);
...

2) The reproduction of what I observed can be done as follows:
In Google Chrome, using two instances of the "Simple Websocket Client" extension,
pointing to: "wss://192.168.0.109:7799/Test", it is observed that the connection of the first instance occurs normally.
Connecting and disconnecting, with a single instance, occurs quickly.
With the first instance connected, the second instance's connection behaves differently, the time to connect increases,
and, after several repetitions, the server stops responding.

It only occurs when I'm using TLS.

I hope I have contributed in some way.

Thank you very much for your attention.

Last edited by ec (2023-11-23 21:47:12)

ab · 2023-11-27 08:39:45

Could you try with OpenSSL instead of SSPI ?

ec · 2023-11-27 15:15:12

Good morning Arnaud !

When I define USE_OPENSSL in the project it works normally.

ab · 2023-11-27 15:26:04

The SSPI support on the async server side is in beta state.
We did not debug it much, because we don't recommend using it on production.

For the client, SSPI may be fine.
For the server, we recommend to use OpenSSL. You will have better performance, better algorithms (e.g. TLS 1.3 support), and consistent work if hosted on Linux.

Note that we plan to develop a native TLS 1.3 layer in the next months, mostly for clients (and perhaps also for server).
We prefer focusing on this task and not trying to debug the SSPI limitations. Better time spent IMHO.

Of course, if anyone is able to debug the SSPI server layer, and propose a pull request, we will be pleased to include it.

ec · 2023-11-27 17:26:45

Hi Arnaud !

I understood.

Anyway, I noticed that with a small increase in the number of test connections, the increase in connection time is also happening with openssl, only on the server side! But, despite the increase in connection time, the server continues to work, and new connections are established normally.

Thank you very much for your attention

ab · 2023-11-27 18:35:10

With only a few connections, the async server may have some delays (a few dozen ms) when accepting new connections, by design.
Then with a consistent amount of concurrent connections (a few hunderths) then it should respond immediately.

If you need only a few connections, don't use the async version, but the regular websockets server, with one thread per connection.

ec · 2023-11-27 19:24:08

I understood. Perfect ! The implementation, as it stands, already meets the needs. In the production environment, we will have thousands of concurrent connections, and, in addition to Linux, with several clients using the Windows server. This is why the synchronous version does not suit us.

Once again, thank you very much for your attention

maro · 2023-12-13 11:31:36

@ab, sorry for the delayed answers. We have still the issue.

The application is windows-only, so unfortunately I cannot test it under Linux.
And regarding TLS, yes, we continue to use TLS. Initially SSPI, the built-in one, now a reverse proxy upstream.
This means that communication on the WebSocket server is unencrypted and can be analysed.

ab · 2023-12-13 14:43:06

@maro
So you should either for TLS:
- use a reverse proxy .
- try to switch to OpenSSL instead of SSPI

IMHO a reverse proxy is a good practice on Windows servers, to reduce the security exposure of your application servers.
I usually put nginx in a small Linux or OpenBSD VM somewhere in the local network, and only exposes this VM over the Internet.

maro · 2023-12-19 08:20:51

In fact, we now use this approach with the customer as well.
After the switchover, we have noticed the missing pong twice so far.
However, it did not lead to a disconnect.
The firewall with SI may have been a problem the previous time. I can't exclude that.

Overall, the solution is stable. We are currently not investigating this issue any further.

ab · 2023-12-19 15:33:52

Thanks for the feedback!

mORMot Open Source

#1 2023-11-02 09:59:10

Issue with TWebSocketAsyncServer

#2 2023-11-03 14:48:14

Re: Issue with TWebSocketAsyncServer

#3 2023-11-03 15:14:08

Re: Issue with TWebSocketAsyncServer

#4 2023-11-09 10:30:21

Re: Issue with TWebSocketAsyncServer

#5 2023-11-09 10:51:05

Re: Issue with TWebSocketAsyncServer

#6 2023-11-15 08:36:33

Re: Issue with TWebSocketAsyncServer

#7 2023-11-23 12:56:54

Re: Issue with TWebSocketAsyncServer

#8 2023-11-23 18:52:01

Re: Issue with TWebSocketAsyncServer

#9 2023-11-23 20:17:20

Re: Issue with TWebSocketAsyncServer

#10 2023-11-27 08:39:45

Re: Issue with TWebSocketAsyncServer

#11 2023-11-27 15:15:12

Re: Issue with TWebSocketAsyncServer

#12 2023-11-27 15:26:04

Re: Issue with TWebSocketAsyncServer

#13 2023-11-27 17:26:45

Re: Issue with TWebSocketAsyncServer

#14 2023-11-27 18:35:10

Re: Issue with TWebSocketAsyncServer

#15 2023-11-27 19:24:08

Re: Issue with TWebSocketAsyncServer

#16 2023-12-13 11:31:36

Re: Issue with TWebSocketAsyncServer

#17 2023-12-13 14:43:06

Re: Issue with TWebSocketAsyncServer

#18 2023-12-19 08:20:51

Re: Issue with TWebSocketAsyncServer

#19 2023-12-19 15:33:52

Re: Issue with TWebSocketAsyncServer

Board footer