You are not logged in.
Pages: 1
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, 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.
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
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?
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.
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?
Pages: 1