[TCP bug, regression] stuck distcc connections in latest -git

[Ingo Molnar <mingo@elte.hu>]

* Ingo Molnar <mingo@elte.hu> wrote:

> Alas, the problem has not reoccured since then - more than a thousand 
> kernel builds down the line. [...]

the permanently hug distcc kernel build bug triggered again, twice. 
First time it happened yesterday, i left it running overnight and it 
never recovered after a 14+ hours of wait.

It shows a similar pattern, 'ESTABLISHED' state on both sides, but the 
client-side is stuck and the server (running latest kernel) is seemingly 
clueless about that fact:

 client:

  Proto Recv-Q Send-Q Local Address       Foreign Address     State
  tcp        0 375450 10.0.1.16:39201     10.0.1.19:3632      ESTABLISHED

 server:

  Proto Recv-Q Send-Q Local Address       Foreign Address     State
  tcp        0      0 10.0.1.19:3632      10.0.1.16:39201     ESTABLISHED

i waited ~30 minutes in this second case.

the client (running 2.6.24) does periodic 120 seconds retransmits:

07:40:48.255452 IP dione.39201 > phoenix.distcc: . 1608:2144(536) ack 1 win 584007:40:48.255547 IP phoenix.distcc > dione.39201: . ack 2144 win 65535
07:40:48.255564 IP dione.39201 > phoenix.distcc: . 67143:67679(536) ack 1 win 5840
07:40:48.255648 IP phoenix.distcc > dione.39201: . ack 2144 win 65535
07:42:48.255440 IP dione.39201 > phoenix.distcc: . 2144:2680(536) ack 1 win 5840
07:42:48.255559 IP phoenix.distcc > dione.39201: . ack 2680 win 65535
07:42:48.255570 IP dione.39201 > phoenix.distcc: . 67679:68215(536) ack 1 win 5840
07:42:48.255659 IP phoenix.distcc > dione.39201: . ack 2680 win 65535
07:44:48.255436 IP dione.39201 > phoenix.distcc: . 2680:3216(536) ack 1 win 584007:44:48.255570 IP phoenix.distcc > dione.39201: . ack 3216 win 65535
07:44:48.255585 IP dione.39201 > phoenix.distcc: . 68215:68751(536) ack 1 win 5840
07:44:48.255669 IP phoenix.distcc > dione.39201: . ack 3216 win 65535

the server (running the latest kernel) responds:

07:40:47.551098 IP dione.39201 > phoenix.distcc: . 1072:1608(536) ack 1 win 584007:40:47.551141 IP phoenix.distcc > dione.39201: . ack 1608 win 65535
07:40:47.551204 IP dione.39201 > phoenix.distcc: . 66607:67143(536) ack 1 win 5840
07:40:47.551213 IP phoenix.distcc > dione.39201: . ack 1608 win 65535
07:42:47.570994 IP dione.39201 > phoenix.distcc: . 1608:2144(536) ack 1 win 584007:42:47.571027 IP phoenix.distcc > dione.39201: . ack 2144 win 65535
07:42:47.571117 IP dione.39201 > phoenix.distcc: . 67143:67679(536) ack 1 win 5840
07:42:47.571127 IP phoenix.distcc > dione.39201: . ack 2144 win 65535
07:44:47.590901 IP dione.39201 > phoenix.distcc: . 2144:2680(536) ack 1 win 584007:44:47.590960 IP phoenix.distcc > dione.39201: . ack 2680 win 65535
07:44:47.591042 IP dione.39201 > phoenix.distcc: . 67679:68215(536) ack 1 win 5840
07:44:47.591054 IP phoenix.distcc > dione.39201: . ack 2680 win 65535

full client socket state:

 dione:~> grep $(printf "%X\n" 39201) /proc/net/tcp
   44: 1001000A:9921 1301000A:0E30 01 0005ABF2:00000000 01:00002B8A 
       00000000   500        0 63130083 2 ffff81000c762d00 120000 0 0 28 101

 [ a few minutes later ]

   44: 1001000A:9921 1301000A:0E30 01 0005A392:00000000 01:00002BF0 
       00000000   500        0 63130083 2 ffff81000c762d00 120000 0 0 32 101

 [ i.e. the tx queue did increase by 2144 bytes - 4x 536 bytes ]

full server socket state:

 phoenix:~> grep $(printf "%X\n" 39201) /proc/net/tcp
    6: 1301000A:0E30 1001000A:9921 01 00000000:00000000 00:00000000 
       00000000    99        0 728382 1 ffff88042d8db280 300 4 30 2 -1

 [ a few minutes later ]

    6: 1301000A:0E30 1001000A:9921 01 00000000:00000000 00:00000000 
       00000000    99        0 728382 1 ffff88042d8db280 300 4 30 2 -1

 [ i.e. no change - no pending packets ]

I've started a longer capture session as well - it seems the TCP stack 
is slowly cycling through retransmissions of 536-byte packets, with 
375450 bytes pending? At 120 seconds a pop that would be about 23 hours 
to make any progress on - but i'm not sure i interpreted that right. It 
all looks very weird.

The timestamps of the two boxes are synced up to within about 1 second:

  earth4:~> for N in dione phoenix; do ssh $N date; done
  Thu Jul 24 07:44:02 CEST 2008
  Thu Jul 24 07:44:02 CEST 2008

( but the two boxes are responding to each other fine, so ordering of 
  events is not a question here. )

Any other state you'd like to see before i continue with -tip testing? 

	Ingo