stuck localhost TCP connections, v2.6.26-rc3+

(Oy, resending. Freakin' gmail; sorry for the base64 encoded noise.)

Okay, but in some sense you've already bisected this somewhat. I'm assuming that your testing uses the latest tip and is refreshed daily.

If that's the case, then I would (possibly naively) expect the culprit
to show up in a:
git log -p v2.6.26-rc1..78b58e549a3098 net/{compat.c,core,ipv4,netfilter,packet,sched,socket.c}

There are only a few commits in there that appear to touch network behavior:

79d44516b4b178ffb6e2159c75584cfcfc097914
a1c1f281b84a751fdb5ff919da3b09df7297619f
62ab22278308a40bcb7f4079e9719ab8b7fe11b5

Reverting just those three and running overnight might provide a clue. OTOH, I'm in no way a net/ expert, so if you are already working a debugging strategy then feel free to ignore this. I'm only piping up as it appears that the troubleshooting has stalled.

Hi Ray,

...I reorganized it a bit.

I think you miss here a lot of clues. First I suspected my FRTO changes as well but later discoveries pointed elsewhere... Those fixes are for sender behavior, which is not the problem here. It's just that once you have flow control, the sending TCP obviously gets stuck once all "buffering" capacity downstream is used up, and that's _correct_ sender behavior rather than a bug in itself. Therefore both FRTO and Ingo's theory about Cubic (though his test with 2.6.25 will definately seems currently a useful result with or without Cubic :-)) completely fails to explain why receiver didn't read the portion that was sitting there waiting (see below).

Also, I think you missed one (though it's commit message seems to say that it isn't relevant here but who knows):

1ac06e0306d0192a7a4d9ea1c9e06d355ce7e7d3

...but still that hardly would explains why the receiver queue was not consumed.

Of course Ingo could easily test without FRTO by playing with the sysctl, all those three patches are not in use if tcp_frto is set to zero (he probably didn't because I "cancelled" that request...?), but I find it very unlikely to help any.

Me neither, I just know some about TCP, so I probably have as much problems as you do in understanding this :-).

...Thanks, I definately don't mind any help here. Though it probably partially seems completely "stalled" because figuring this out leads me more and more to a territory which is previously unknown to me (plus the time constraints I have), not that it's a bad thing to learn & read a lot of other code too but it just takes more time and I cannot do anything while off-line like I could with a code that I'm familiar with.

Would you perhaps have any clue about two clearly strange things I listed here:
http://marc.info/?l=linux-kernel&m=121207001329497&w=2

...

...i.e., one connection, two endpoints:

             ^^^^^

Can you perhaps find/guess/think some explanation for this _receiver queue_...? This was a trick question :-), as we already know that the receiving process is no longer there and therefore obviously won't be reading anything anymore. But that opened another question, why TCP is then still in ESTABLISHED as orphaned TCP shouldn't be in establised state anymore, tcp_close should have changed the state (either at close or at process exit). I guess once it becomes known why tcp_close either wasn't called at all or it didn't change the state of the flow (it's quite simple, see for yourself), the cause of the bug is found (it might even be that the process went away when it shouldn't have, either a bookkeeping bug somewhere or real death, or something along those lines).

I was thinking of storing some info about old owner while orphaning to struct sock and collecting that once one of the flows gets stuck but this requires me to figure a lot unknowns out before I can just code it.

 i.

In that case pid Ingo straced was still valid and existed (ans stuck probably in tcp_sendpage() - sysrq-t dump was messy), so process still exist, but sock somewhat lost its reference to socket. AFICS all (three) calls for sk_orphan() can not happen without state change to something closing (like fin wait or close), except some linger things and listening socket, which frees its connection requests.

	Evgeniy Polyakov

...No, I think it was the sender, not the receiver that Ingo straced! A _correctly_ behaving TCP sender will just get "stuck" once the window is exhausted. It as was proven that advertized window is zero (tcpdump). So I find that hardly a bug.

...this is something that seems possible explanation.

Yes, this what I figured out as well (distcc didn't seem to play with linger, I checked, nor would it have any reason to)... The LISTENING socket was still there in /proc/net/tcp, so closing that won't explain it.

In addition, it seems that tcp_close would notify the other end as well, either with RST or with FIN, which would cause the other end to leave ESTABLISHED (unless tcp_transmit_skb would fail but I guess that would end up into some MIB in either of the cases). Here RST is the way to go because there's unread data (though in theory having yet another bug could allow building up the receiver queue afterwards).

Which then boils down to two alternatives:
1) The receiving process lost its reference though the process still exists and therefore cannot read
2) tcp_close wasn't called when it should have, e.g., process exited but the tcp_close wasn't called because the reference wasn't there

Btw, Ingo also got this warning later on which might be helpful in understanding all this:

I guess that sk_ack_backlog was already visible at the time when the TCP got stuck because listening socket already had 1 there in /proc/net/tcp (though this depends if there was some other connection attempts still going on).

...Some new info (at least to me). I tried with ./stress_accept 5000 2 (attached), I could easily produce a number of ESTABLISHED connections which won't yet have an owner in netstat (tested in 2.6.25.3) while connect.sh is running but it seems some kind of transitional state as once I do killall -TERM connect.sh (attached), they get the owning stress_accept. So third explanation would be some race during that transition that would allow process to never get the reference...

Before:
tcp 65436 0 lo:5000 lo:59980 ESTABLISHED -
After killall:
tcp 76444 0 lo:5000 lo:59980 ESTABLISHED 9013/stress_accept

 i.

#include <stdio.h>
#include <stdlib.h>
#include <string.h>

#include <unistd.h>
#include <sys/wait.h>

#include <sys/types.h>
#include <sys/socket.h>
#include <netinet/in.h>
#include <arpa/inet.h>

void error(const char *str)

{
	perror(str);
	exit(1);
}

void worker(int listenfd)

{
	int fd;
	struct sockaddr_in peeraddr;
	socklen_t len = sizeof(peeraddr);
	int pid;
	char buf[100];

	while(1) {
		memset(&peeraddr, 0, sizeof(peeraddr));
		fd = accept(listenfd, (struct sockaddr *)&peeraddr, &len);
		if (fd < 0)
			error("accept");

		pid = fork();
		if (pid < 0) {
			error("fork");
		} else if (pid != 0) {
			close(fd);
/*			while(1)
				sleep(1); */
		} else {
			read(fd, &buf, sizeof(buf));
			while(1)
				sleep(1);
			exit(0);
		}
	}

	exit(0);
}

int main(int argc, char **argv)

{
	int listenfd;
	struct sockaddr_in myaddr;
	int res;
	pid_t pid;
	int i;

	if (argc < 3) {
		fprintf(stderr, "%s serverport processes\n", argv[0]);
		exit(1);
	}
	
	listenfd = socket(PF_INET, SOCK_STREAM, 0);
	if (listenfd < 0)
		error("socket");
	
	memset(&myaddr, 0, sizeof(myaddr));
	myaddr.sin_family = PF_INET;
	myaddr.sin_addr.s_addr = inet_addr("127.0.0.1");
	myaddr.sin_port = htons(atoi(argv[1]));
    
	res = bind(listenfd, (struct sockaddr *)&myaddr, sizeof(myaddr));
	if (res < 0)
		error("bind");

	/* distccd uses 10 here */
	if (listen(listenfd, 10) < 0)
		error("listen");

	for (i = 0; i < atoi(argv[2]); i++) {
		pid = fork();
		if (pid < 0)
			error("fork");

		if (pid == 0) {
			worker(listenfd);
		}
	}

	while (1) {
		sleep(1);
	}

	return 0;
}

This is what happens before accept(2) is called. Ingo, please strace the process that owns the listening socket to make sure that it is actually calling accept(2). If it ever stops calling accept(2) then this is expected behaviour.

Cheers,

Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <[email protected]>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt

Shouldn't that be already visible in the ingo's sysrq-t dump, no? There:

http://marc.info/?l=linux-kernel&m=121182099131520&w=2

There are many sys_accepts at least (if I understand that dump at all). There were some ip_local_outs there as well, which made me wonder if the totally innocent looking commit 1ac06e0306d0192a7a4d9ea1c9e06d355ce7e7d3 (ipsec: Use the correct ip_local_out function) has something to do with this (I definately don't understand that part at all).

 i.

No, we need an actual strace rather than the static stack back-trace. So start with netstat -lntp to locate the process listening on that port, and then strace it to see if it's calling accept.

This patch only has an effect for IPsec.

Cheers,

Visit Openswan at http://www.openswan.org/
Email: Herbert Xu ~{PmV>HI~} <[email protected]>
Home Page: http://gondor.apana.org.au/~herbert/
PGP Key: http://gondor.apana.org.au/~herbert/pubkey.txt