Date: Fri, 28 May 2010 00:25:42 +0300 From: Mikolaj Golub <to.my.trociny@gmail.com> To: bug-followup@FreeBSD.org Cc: Robert Watson <rwatson@FreeBSD.org>, Anton Lavrentiev <lavr@ncbi.nlm.nih.gov>, freebsd-net@FreeBSD.org Subject: Re: kern/146845: [libc] close(2) returns error 54 (connection reset by peer) wrongly Message-ID: <86vda982ax.fsf@kopusha.home.net> In-Reply-To: <201005231404.o4NE4xJd006658@freefall.freebsd.org> (gavin@freebsd.org's message of "Sun, 23 May 2010 14:04:59 GMT") References: <201005231404.o4NE4xJd006658@freefall.freebsd.org>
index | next in thread | previous in thread | raw e-mail
[-- Attachment #1 --]
Hi,
We observed the same issue on our FreeBSD6 and 7 servers. I tried to reproduce
the problem writing a simple test case but failed -- I didn't come to the idea
of shutdown()/close() sequence (as Anton did). Although looking now at the
code we had the issue with I see that shutdown()/close() sequence was used
there too.
It looks like SO_LINGER is not important to reproduce ECONNRESET.
shutdown()/close() on one end and close() on the other is enough. Also,
slowdown of one the processes (done by Anton using select()) is not important
too. Taking this into consideration I have wrote a simplified version of a test
to reproduce the bug (may be it worth of including to tools/regression/sockets?).
I can easily reproduce the error with this test on FreeBSD7.1 and
8-STABLE. Adding some prints to the kernel code I localized the place where
the error appears and added panic() to get a backtrace.
So, the backtrace:
(kgdb) bt
#0 doadump () at pcpu.h:246
#1 0xc04ec829 in db_fncall (dummy1=-1064461270, dummy2=0, dummy3=-1, dummy4=0xe85e58b0 "ÄX^è")
at /usr/src/sys/ddb/db_command.c:548
#2 0xc04ecc5f in db_command (last_cmdp=0xc0e0af9c, cmd_table=0x0, dopager=0)
at /usr/src/sys/ddb/db_command.c:445
#3 0xc04ecd14 in db_command_script (command=0xc0e0bec4 "call doadump")
at /usr/src/sys/ddb/db_command.c:516
#4 0xc04f0e50 in db_script_exec (scriptname=0xe85e59bc "kdb.enter.panic", warnifnotfound=Variable "warnifnotfound" is not available.
)
at /usr/src/sys/ddb/db_script.c:302
#5 0xc04f0f37 in db_script_kdbenter (eventname=0xc0cc78ea "panic")
at /usr/src/sys/ddb/db_script.c:324
#6 0xc04eec18 in db_trap (type=3, code=0) at /usr/src/sys/ddb/db_main.c:228
#7 0xc08d9aa6 in kdb_trap (type=3, code=0, tf=0xe85e5af8) at /usr/src/sys/kern/subr_kdb.c:535
#8 0xc0befecb in trap (frame=0xe85e5af8) at /usr/src/sys/i386/i386/trap.c:690
#9 0xc0bd15eb in calltrap () at /usr/src/sys/i386/i386/exception.s:165
#10 0xc08d9c2a in kdb_enter (why=0xc0cc78ea "panic", msg=0xc0cc78ea "panic") at cpufunc.h:71
#11 0xc08a95b6 in panic (fmt=0xc0ce6585 "ECONNRESET") at /usr/src/sys/kern/kern_shutdown.c:562
#12 0xc0a3d805 in tcp_usr_disconnect (so=0xc715c670) at /usr/src/sys/netinet/tcp_usrreq.c:552
#13 0xc09111bd in sodisconnect (so=0xc715c670) at /usr/src/sys/kern/uipc_socket.c:810
#14 0xc0914144 in soclose (so=0xc715c670) at /usr/src/sys/kern/uipc_socket.c:658
#15 0xc08f6459 in soo_close (fp=0xc743e230, td=0xc7023000)
at /usr/src/sys/kern/sys_socket.c:291
#16 0xc086efc3 in _fdrop (fp=0xc743e230, td=0xc7023000) at file.h:293
#17 0xc0870cf0 in closef (fp=0xc743e230, td=0xc7023000)
at /usr/src/sys/kern/kern_descrip.c:2117
#18 0xc0871097 in kern_close (td=0xc7023000, fd=4) at /usr/src/sys/kern/kern_descrip.c:1162
#19 0xc087123a in close (td=0xc7023000, uap=0xe85e5cf8)
at /usr/src/sys/kern/kern_descrip.c:1114
#20 0xc0bef600 in syscall (frame=0xe85e5d38) at /usr/src/sys/i386/i386/trap.c:1111
#21 0xc0bd1680 in Xint0x80_syscall () at /usr/src/sys/i386/i386/exception.s:261
#22 0x00000033 in ?? ()
Previous frame inner to this frame (corrupt stack?)
(kgdb) fr 12
#12 0xc0a3d805 in tcp_usr_disconnect (so=0xc715c670) at /usr/src/sys/netinet/tcp_usrreq.c:552
552 panic("ECONNRESET");
(kgdb) list
547 inp = sotoinpcb(so);
548 KASSERT(inp != NULL, ("tcp_usr_disconnect: inp == NULL"));
549 INP_WLOCK(inp);
550 if (inp->inp_flags & (INP_TIMEWAIT | INP_DROPPED)) {
551 error = ECONNRESET;
552 panic("ECONNRESET");
553 /* log(LOG_INFO, "ECONNRESET 3: file %s; line %d\n", __FILE__, __LINE__); */
554 goto out;
555 }
556 tp = intotcpcb(inp);
(kgdb) p/x inp->inp_flags
$1 = 0x4800000
#define INP_DROPPED 0x04000000 /* protocol drop flag */
(kgdb) fr 14
#14 0xc0914144 in soclose (so=0xc715c670) at /usr/src/sys/kern/uipc_socket.c:658
658 error = sodisconnect(so);
(kgdb) list
653
654 CURVNET_SET(so->so_vnet);
655 funsetown(&so->so_sigio);
656 if (so->so_state & SS_ISCONNECTED) {
657 if ((so->so_state & SS_ISDISCONNECTING) == 0) {
658 error = sodisconnect(so);
659 if (error) {
660 if (error == ENOTCONN)
661 error = 0;
662 goto drop;
(kgdb) p/x so->so_state
$2 = 0x2000
#define SS_ISDISCONNECTED 0x2000 /* socket disconnected from peer */
(the code differs a bit here from original 8-STABLE version as it includes
patch from kern/144061 to deal with ENOTCONN errors but this does not
influence).
Actually, I think that the issue here is similar to kern/144061. In the code
above so_state is checked for SS_ISCONNECTED and SS_ISDISCONNECTING without
locking and then sodisconnect() is called. It looks like the following may
happen:
1) after shutdown() our output is closed;
2) then we call close(), soclose() checks that we are still in SS_ISCONNECTED
and calls sodisconnect();
3) at this time FIN arrives from the other end, which has called close() too,
and the kernel disconnects the socket (INP_DROPPED is set);
4) sodisconnect()/tcp_usr_disconnect() checks for INP_DROPPED and returns
ECONNRESET.
I am attaching the patch, which may not be a solution but rather for
illustration to described above. Running the test with this patch I am
observing the following messages in error logs
May 27 23:55:41 zhuzha kernel: ECONNRESET: so->state: 0x2000; file /usr/src/sys/kern/uipc_socket.c; line 664
and test does not fail.
--
Mikolaj Golub
[-- Attachment #2 --]
#include <sys/types.h>
#include <sys/socket.h>
#include <sys/sysctl.h>
#include <netinet/in.h>
#include <signal.h>
#include <stdio.h>
#include <string.h>
#include <stdlib.h>
#include <unistd.h>
#include <err.h>
#define LOOPS 100000
#define USLEEP 100
int
main(int argc, char **argv)
{
struct sockaddr_in sin;
int listenfd, connfd, pid;
u_int counter, ncpus;
size_t len;
socklen_t solen;
len = sizeof(ncpus);
if (sysctlbyname("kern.smp.cpus", &ncpus, &len, NULL, 0) < 0)
err(1, "kern.smp.cpus");
if (len != sizeof(ncpus))
errx(1, "kern.smp.cpus: invalid length");
if (ncpus < 2)
warnx("SMP not present, test may be unable to trigger race");
/*
* Create a tcp socket that the child will repeatedly accept()
* from, and that the parent will repeatedly connect() to.
* Choose the listen port dynamically and get its value using
* getsockname().
*/
if ((listenfd = socket(AF_INET, SOCK_STREAM, 0)) < 0)
err(1, "parent: socket error");
memset(&sin, 0, sizeof(sin));
sin.sin_len = sizeof(sin);
sin.sin_family = AF_INET;
if (bind(listenfd, (struct sockaddr *) &sin,
sizeof(sin)) < 0)
err(1, "parent: bind error");
if (getsockname(listenfd, (struct sockaddr *) &sin,
&solen) < 0)
err(1, "parent: getsockname error");
if (listen(listenfd, 1024) < 0)
err(1, "parent: listen error");
pid = fork();
if (pid == -1)
err(1, "fork()");
if (pid != 0) {
/*
* In the parent, repeatedly connect and disconnect
* from the socket, attempting to induce the race.
*/
close(listenfd);
sleep(1);
for (counter = 0; counter < LOOPS; counter++) {
if ((connfd = socket(AF_INET, SOCK_STREAM, 0)) < 0) {
(void)kill(pid, SIGTERM);
err(1, "parent: socket error");
}
if (connect(connfd, (struct sockaddr *)&sin,
sizeof(sin)) < 0) {
err(1, "parent: connect error (after %d iterations)",
counter);
}
if (close(connfd) < 0) {
(void)kill(pid, SIGTERM);
err(1, "parent: close error");
}
usleep(USLEEP);
}
(void)kill(pid, SIGTERM);
} else {
/*
* In the child, loop accepting, shutdown and closing.
* We may pick up the race here so report errors from
* close().
*/
for ( ; ; ) {
if ((connfd = accept(listenfd,
(struct sockaddr *)NULL, NULL)) < 0)
err(1, "child: accept error");
if (shutdown(connfd, SHUT_WR) < 0)
err(1, "child: shutdown error");
if (close(connfd) < 0)
err(1, "child: close error");
}
}
printf("OK\n");
exit(0);
}
[-- Attachment #3 --]
--- sys/kern/uipc_socket.c.orig 2010-04-02 13:36:19.000000000 +0300
+++ sys/kern/uipc_socket.c 2010-05-27 22:09:06.000000000 +0300
@@ -129,6 +129,7 @@ __FBSDID("$FreeBSD: src/sys/kern/uipc_so
#include <sys/sysctl.h>
#include <sys/uio.h>
#include <sys/jail.h>
+#include <sys/syslog.h>
#include <net/vnet.h>
@@ -656,8 +657,15 @@ soclose(struct socket *so)
if (so->so_state & SS_ISCONNECTED) {
if ((so->so_state & SS_ISDISCONNECTING) == 0) {
error = sodisconnect(so);
- if (error)
+ if (error) {
+ if (error == ECONNRESET) {
+ log(LOG_INFO,
+ "ECONNRESET: so->state: 0x%x; file %s; line %d\n",
+ so->so_state, __FILE__, __LINE__);
+ error = 0;
+ }
goto drop;
+ }
}
if (so->so_options & SO_LINGER) {
if ((so->so_state & SS_ISDISCONNECTING) &&
help
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?86vda982ax.fsf>