#windows network programming

[loobeny]

Playing with Multi-threading bug (2)

  When QA was doing test for the previous bug, a new problem was found.

On startup, when PC is under load, our customer premise system shows no interface (the link to server) available and it can not process any request.

  Our customer premise system is a multi process architecture (simplified):

  An process accepts and handles requests (these requests come from another process developed by business partner, but let's ignore it here), implement most of the business logics, let's call it App process;

Another process is responsible establishing connections to server, forwards the messages from App process to server and vice versa, let's call it Network process.

  App process <---TCP--> Network process <---TCP--> Server

     1)

To solve the issue, first we need to narrow down the problem. The first part that I looked at was the connection between the Network process and server.

I examined the logs generated by the Network process. The connection setup between the Network process and server is fine, because the log shows that the links are closed as idle after connected (I mentioned in previous blog that some third party server does not allow persistent connections):

     Line 103: 02:58:22.234375 W ...> ** - IDLE CLOSE (**)    Line 108: 02:58:22.234375 W ...> ** - IDLE CLOSE (*)    Line 115: 02:58:22.234375 W ...> ** - IDLE CLOSE (*)

So the problem resides on App process, or the interaction between App process and Network process.

   2) 

Dived into the code of App process to do a quick investigation of the status update mechanism of server interface.

The status is initialized as false(0). So when App process connected to Network process, the status is 0. But after connected, App process will send a status query message to Network process to get link status every 2 seconds . And calls a setting method update the status (only if the status is OK) when response message returns.

 3) 

Added debug log to that status setting method in App process, and QA reproduced it. But the added log could not be seen, so the server status in App process was never updated actually. 

However, from the point of view of App process, the TCP connection with Network process should have been connected successfully, otherwise it would attempt to reconnect.

The log of Network process showed that no accept event  occurred, which meant from Network process’s point of view there is no TCP connection between App process and Network process at all. 

Contradictory, so we need to look at it at a lower level to see what really happens.

 4)

 Used RawCap (right, Wireshark can not sniff the loopback traffic) to capture the loopback traffic between App process and Network process. Analyse the captured packets with Wireshark, filtered with expression “tcp.dstport == xx or tcp.srcport == xx” (Network process listen on port xx):

  155 02:12:58.077133 127.0.0.1 127.0.0.1 TCP 52 61169 > xx [SYN] Seq=0 Win=8192 Len=0 MSS=65495 WS=256 SACK_PERM=1

156 02:12:58.077133 127.0.0.1 127.0.0.1 TCP 52 xx > 61169 [SYN, ACK] Seq=0 Ack=1 Win=8192 Len=0 MSS=65495 WS=256 SACK_PERM=1

157 02:12:58.077133 127.0.0.1 127.0.0.1 TCP 40 61169 > xx [ACK] Seq=1 Ack=1 Win=8192 Len=0

158 02:12:58.088133 127.0.0.1 127.0.0.1 TCP 84 61169 > xx [PSH, ACK] Seq=1 Ack=1 Win=8192 Len=44

159 02:12:58.088133 127.0.0.1 127.0.0.1 TCP 40 xx > 61169 [ACK] Seq=1 Ack=45 Win=7936 Len=0

173 02:12:59.436133 127.0.0.1 127.0.0.1 TCP 178 61169 > xx [PSH, ACK] Seq=45 Ack=1 Win=8192 Len=138

174 02:12:59.436133 127.0.0.1 127.0.0.1 TCP 40 xx > 61169 [ACK] Seq=1 Ack=183 Win=7936 Len=0

175 02:12:59.463133 127.0.0.1 127.0.0.1 TCP 219 61169 > xx [PSH, ACK] Seq=183 Ack=1 Win=8192 Len=179

176 02:12:59.463133 127.0.0.1 127.0.0.1 TCP 40 xx > 61169 [ACK] Seq=1 Ack=362 Win=7680 Len=0

188 02:13:00.188133 127.0.0.1 127.0.0.1 TCP 84 61169 > xx [PSH, ACK] Seq=362 Ack=1 Win=8192 Len=44

189 02:13:00.188133 127.0.0.1 127.0.0.1 TCP 40 xx > 61169 [ACK] Seq=1 Ack=406 Win=7680 Len=0

227 02:13:02.291133 127.0.0.1 127.0.0.1 TCP 84 61169 > xx [PSH, ACK] Seq=406 Ack=1 Win=8192 Len=44

228 02:13:02.291133 127.0.0.1 127.0.0.1 TCP 40 xx > 61169 [ACK] Seq=1 Ack=450 Win=7680 Len=0

259 02:13:04.394133 127.0.0.1 127.0.0.1 TCP 84 61169 > xx [PSH, ACK] Seq=450 Ack=1 Win=8192 Len=44

260 02:13:04.394133 127.0.0.1 127.0.0.1 TCP 40 xx > 61169 [ACK] Seq=1 Ack=494 Win=7680 Len=0

293 02:13:06.497133 127.0.0.1 127.0.0.1 TCP 84 61169 > xx [PSH, ACK] Seq=494 Ack=1 Win=8192 Len=44

294 02:13:06.497133 127.0.0.1 127.0.0.1 TCP 40xx  > 61169 [ACK] Seq=1 Ack=538 Win=7424 Len=0

  A TCP connection did exist between App process and someone’s port xx. Handshakes succeeded. And App process always sent 44 byte data to the opponent every 2 seconds, but the opponent did not reply any data, just ack with sequence number 1. At this point, I can only imagine several possibilities: a) App process connected with process other than Network process, that process of course did not know how to respond App process’ get status msg. b) The connection somehow terminated at the TCP level, instead of going thru the process. 

5)

 I did an experiment with the accept code blocked in Network process, to see what would happen if Network process does not accept the connect request from App process. Got the same TCP sequence:

69 05:58:57.548361 127.0.0.1 127.0.0.1 TCP 52 61533 > xx [SYN] Seq=0 Win=8192 Len=0 MSS=65495 WS=256 SACK_PERM=1

70 05:58:57.548361 127.0.0.1 127.0.0.1 TCP 40 xx > 61533 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0

75 05:58:58.042916 127.0.0.1 127.0.0.1 TCP 52 61533 > xx [SYN] Seq=0 Win=8192 Len=0 MSS=65495 WS=256 SACK_PERM=1

76 05:58:58.042916 127.0.0.1 127.0.0.1 TCP 40 xx > 61533 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0

85 05:58:58.542466 127.0.0.1 127.0.0.1 TCP 48 61533 > xx [SYN] Seq=0 Win=8192 Len=0 MSS=65495 SACK_PERM=1

86 05:58:58.542466 127.0.0.1 127.0.0.1 TCP 40 xx > 61533 [RST, ACK] Seq=1 Ack=1 Win=0 Len=0

189 05:59:08.648362 127.0.0.1 127.0.0.1 TCP 52 61550 > xx [SYN] Seq=0 Win=8192 Len=0 MSS=65495 WS=256 SACK_PERM=1

190 05:59:08.648362 127.0.0.1 127.0.0.1 TCP 52 xx > 61550 [SYN, ACK] Seq=0 Ack=1 Win=8192 Len=0 MSS=65495 WS=256 SACK_PERM=1

191 05:59:08.648362 127.0.0.1 127.0.0.1 TCP 40 61550 > xx [ACK] Seq=1 Ack=1 Win=8192 Len=0

198 05:59:09.549550 127.0.0.1 127.0.0.1 TCP 84 61550 > xx [PSH, ACK] Seq=1 Ack=1 Win=8192 Len=44

199 05:59:09.549550 127.0.0.1 127.0.0.1 TCP 40 xx > 61550 [ACK] Seq=1 Ack=45 Win=7936 Len=0

222 05:59:11.650658 127.0.0.1 127.0.0.1 TCP 84 61550 > xx [PSH, ACK] Seq=45 Ack=1 Win=8192 Len=44

223 05:59:11.650658 127.0.0.1 127.0.0.1 TCP 40 xx > 61550 [ACK] Seq=1 Ack=89 Win=7936 Len=0

244 05:59:13.751765 127.0.0.1 127.0.0.1 TCP 84 61550 > xx [PSH, ACK] Seq=89 Ack=1 Win=8192 Len=44

245 05:59:13.751765 127.0.0.1 127.0.0.1 TCP 40 xx > 61550 [ACK] Seq=1 Ack=133 Win=7936 Len=0

266 05:59:15.852872 127.0.0.1 127.0.0.1 TCP 84 61550 > xx [PSH, ACK] Seq=133 Ack=1 Win=8192 Len=44

267 05:59:15.852872 127.0.0.1 127.0.0.1 TCP 40 xx > 61550 [ACK] Seq=1 Ack=177 Win=7936 Len=0

So basically I can assume it’s Network process not accepting the connect request causing the problem at this point.

6) 

More debug log added (and QA reproduced that, cause I could not reproduce it on my machine), and found that Network process could receive the readable event of the listen socket, but the event was somehow ignored.

    Line 90: 03:22:08.906250 W 00161788> Socket 932 created

    Line 96: 03:22:09.031250 W 00161788> Listening on Socket 932

    Line 250: 03:22:17.671875 W 00168450> readable socket list:932,

7) 

More debug log added, found some readable socket did not have corresponding Socket entry in the internal socket table:

21:34:01.181500 W 00176268> Socket 972 not matched ...

The internal socket table was in a mess, some slot was mistakenly erased, and this is highly possible with multiple threads writing to it.

8) 

With more debug log added, this round of reproduce finally reveal the root cause:

01:47:01.796875  Socket 968 created

01:47:01.796875  Attach: i=0.

01:47:01.796875  Socket 952 created

01:47:01.796875  Attach:  i=0.

01:47:01.796875  Socket 964 created

01:47:01.796875  Attach: i=0.

01:47:01.796875  Socket 960 created

01:47:01.796875  Attach:  i=0.

01:47:01.796875  Socket 956 created

01:47:01.796875  Attach:  i=0.

Multiple sockets stored to the same slot (i=0)of the internal table, So only the last one got stored, all previous ones were leaked.

Each connection create/setup was execute in distinct thread, but the code to find the available slot has no protection, so multiple threads see the same slot (i=0) as empty.. 

9) 

Reverse the investigation process, the ins and outs are very clear:

a) The main thread that create the listen socket (on port xx), stored the socket pointer in internal socket table’s slot 0 Socket[0]. 

b) Some IO thread  that create socket to connect server saw slot 0 was still available, so overwritten that slot.

c) App process attempted to setup connection with Network process port xx, 

d) OS’s TCP layer finished  the handshake of  the TCP connection.

e) Network process polled the listen socket’s FD and get the readable event.

f) Looked it up in the socket table but cannot find a match entry. So Network process did not accept the connection.

g) Removed the listen socket’s FD from the read FD set, and so the listen socket would not be polled (by calling select()) again. 

h) So, although App process sent get status request every 2s, but the msg was just terminated in TCP layer, Network process never knows that, so App process got no real reply.

i) Without any update, App process’ link status is kept as “link failure”.

  (note. for confidential purpose, some of the details are hidden. I tried to explain the technical aspect in a general approach )

[loobeny]

Playing with Multi-threading bug (1)

In some customer site, after machine reboot, the connections to third party partner's server did not come up, while to connections to our own server was OK.

If the links are failed for network or any kind of reason, it must be retested/reattempted after some kind of timeout.

QA team did the initial investigation first and they managed to reproduce it in local environment intermittently (yeah, threading race condition always happens intermittently, sometimes more frequently on some heavy load condition). Then I was in.

I analyzed the existing logs, could not get any conclusion based on it. So I added more debug logs in the code, and QA re-run it... Finally see the root cause.

These two types of links are managed differently although they share some basic socket representations. 

The interface of this third party server has no application level keep alive (heartbeat) protocol, it all relies on the TCP level status to manage the connections. It also inhabit persistent connection, connections can only establish on demand when request is to be sent. When it's idle (no request to send), we need to close the connection. So there is status called something like "Idle Closed" for it, which means it's already closed  because of idle but it's believe to be healthy.

The original design favors  asynchronous. For the link to our own server, a connection is setup as follows: One thread invokes connect() on a non-blocking socket (and mark the link status as Connecting), then another thread calls select() against all sockets in Connecting status to poll writable event. If writable event is got, the link is marked Connected.

Maybe partly because of the non-persistent nature of the partner links, or for the ease of programming (yeah, the code flow looks much simpler that after one single method call the connection either established or failed), links to the partner server are connected synchronously. One method named ****ConnectSync() is called to connect synchronously in one thread. However,  the system call it used is not synchronous, rather, it invoke connect() on a non-blocking socket (and mark the link as Connecting), but then block on a select() call. ****ConnectSync() returns after select() gets writable event or timeout. This makes ****ConnectSync() looks like synchronous.

 If Status is set as Connecting in ****ConnectSync(), another thread  may call select() against the same socket to poll writable event. 

 With two threads call select() against the same socket, only one of them will get the writable event, which indicates  the connection is established successfully . (on Windows platform)

 So one thread marks the link as connected and idle closed it, while the other thread considers the connect failed  so mark the link not Available.

If the link is idle closed and not Available, then it will neither be tested again (idle closed means the link is good) nor selected/checked when request arrives (it's not Available so it would not be selected). So the links to third party partner's server failed forever because it will never be retried again. 

The fix is obvious...