From owner-freebsd-net@freebsd.org Wed Sep 23 14:47:46 2015 Return-Path: Delivered-To: freebsd-net@mailman.ysv.freebsd.org Received: from mx1.freebsd.org (mx1.freebsd.org [IPv6:2001:1900:2254:206a::19:1]) by mailman.ysv.freebsd.org (Postfix) with ESMTP id 290A8A06C8B for ; Wed, 23 Sep 2015 14:47:46 +0000 (UTC) (envelope-from julien.charbon@gmail.com) Received: from mail-wi0-f177.google.com (mail-wi0-f177.google.com [209.85.212.177]) (using TLSv1.2 with cipher ECDHE-RSA-AES128-GCM-SHA256 (128/128 bits)) (Client CN "smtp.gmail.com", Issuer "Google Internet Authority G2" (verified OK)) by mx1.freebsd.org (Postfix) with ESMTPS id B45D51928; Wed, 23 Sep 2015 14:47:45 +0000 (UTC) (envelope-from julien.charbon@gmail.com) Received: by wiclk2 with SMTP id lk2so72968010wic.1; Wed, 23 Sep 2015 07:47:38 -0700 (PDT) X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20130820; h=subject:to:references:cc:from:message-id:date:user-agent :mime-version:in-reply-to:content-type; bh=diXdyRwqoawyzOFUN0UW5DlS8+ZLiHD9ewLjaJk92cM=; b=ShVfza2uybC9hKxkIMiTNSyFgOp7o3UhIPPcjHrq/yvygBJF6ZlPZSo+raxbL/YVk7 x94kFB66yiTUxmzZqaKelXfxn4WrQarJw2crGCIIK2yDXwI6rf1NaDHrbwNiA0yK5z7e ZSfZ3EKRmbSbwtifyR2Tl+8NS1IE2pB3xj1w7TrcBjYWRplBGOjb7gb+t6tnz4HOWbM2 45t8/MkNnySy7sxx+sxU9JZzzqahR/S0kfJEQ9TqDhNn5StZ706XVXjtaE8jaB7F6eDK MhWagkZjGGdzd5Zq/HEvQ/uWQ5YPl3/LH7AhsWEoHpvHOrkygpG+HlkMEKaIPOZ/6o9Q rJKA== X-Received: by 10.194.23.167 with SMTP id n7mr35129629wjf.112.1443019658576; Wed, 23 Sep 2015 07:47:38 -0700 (PDT) Received: from FRI2JCHARBON-M1.local ([217.30.88.7]) by smtp.googlemail.com with ESMTPSA id pl7sm757207wic.4.2015.09.23.07.47.36 (version=TLSv1.2 cipher=ECDHE-RSA-AES128-GCM-SHA256 bits=128/128); Wed, 23 Sep 2015 07:47:38 -0700 (PDT) Subject: Can tcp_close() be called in INP_TIMEWAIT case [was: Re: Kernel panics in tcp_twclose] To: Palle Girgensohn , John Baldwin References: <26B0FF93-8AE3-4514-BDA1-B966230AAB65@FreeBSD.org> <55FC1809.3070903@freebsd.org> <20150918160605.GN67105@kib.kiev.ua> <55FFBE01.6060706@freebsd.org> <3721F099-F45D-4DCD-8AB3-84D1ABC44145@FreeBSD.org> <73856F2B-3E70-483C-9988-C84E798CEB44@FreeBSD.org> <44EBAC98-4761-4E47-8E47-5032430A1C8A@FreeBSD.org> <56019AF8.8000705@freebsd.org> <5601CF2D.9030307@freebsd.org> Cc: Konstantin Belousov , freebsd-net@freebsd.org, Robert Watson , Warner Losh From: Julien Charbon X-Enigmail-Draft-Status: N1110 Message-ID: <5602BB7A.9010504@freebsd.org> Date: Wed, 23 Sep 2015 16:47:22 +0200 User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.10; rv:38.0) Gecko/20100101 Thunderbird/38.2.0 MIME-Version: 1.0 In-Reply-To: <5601CF2D.9030307@freebsd.org> Content-Type: multipart/signed; micalg=pgp-sha512; protocol="application/pgp-signature"; boundary="s9lbmCv2GbI7TneJF7f7xkPr5S7L6gbRV" X-BeenThere: freebsd-net@freebsd.org X-Mailman-Version: 2.1.20 Precedence: list List-Id: Networking and TCP/IP with FreeBSD List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Wed, 23 Sep 2015 14:47:46 -0000 This is an OpenPGP/MIME signed message (RFC 4880 and 3156) --s9lbmCv2GbI7TneJF7f7xkPr5S7L6gbRV Content-Type: text/plain; charset=windows-1252 Content-Transfer-Encoding: quoted-printable Hi -net, On 22/09/15 23:59, Julien Charbon wrote: > On 22/09/15 22:58, Palle Girgensohn wrote: >>> 22 sep 2015 kl. 20:16 skrev Julien Charbon : >>> On 22/09/15 18:49, Palle Girgensohn wrote: >>>>> 22 sep 2015 kl. 18:46 skrev Palle Girgensohn=20 >>>>> : >>>>>> 21 sep 2015 kl. 15:53 skrev Palle Girgensohn=20 >>>>>> : >>>>>>> 21 sep 2015 kl. 10:21 skrev Julien Charbon=20 >>>>>>> : On 18/09/15 18:06, Konstantin Belousov=20 >>>>>>> wrote: >>>>>>>> On Fri, Sep 18, 2015 at 03:56:25PM +0200, Julien Charbon=20 >>>>>>>> wrote: >>>>>>>>> [...] >>>>>>> - Second, if issue is still in stable/10, compile 10.2 >>>>>>> kernel with these options: >>>>>>> >>>>>>> options DDB options DEADLKRES options=20 >>>>>>> INVARIANTS options INVARIANT_SUPPORT options WITNESS >>>>>>> options WITNESS_SKIPSPIN >>>>>>> >>>>>>> To see where the original fault is coming from. >>>>>> [...] >>>>>> >>>>>> I'll try stable/10 now. Would you suggest a "clean" >>>>>> stable/10, or could 287621 and 287780 help? >>>>>> >>>>>> I'll add the debugging suggested options right away. >>>>>> >>>>>> Palle >>>>> >>>>> I have a new core dump from ^/stable/10 with: >>>>> >>>>> options DDB options DEADLKRES options INVARIANTS >>>>> options INVARIANT_SUPPORT options WITNESS options >>>>> WITNESS_SKIPSPIN >>>> >>>> # kgdb kernel /var/crash/vmcore.2 GNU gdb 6.1.1 [FreeBSD] >>>> Copyright 2004 Free Software Foundation, Inc. GDB is free >>>> software, covered by the GNU General Public License, and you are >>>> welcome to change it and/or distribute copies of it under certain >>>> conditions. Type "show copying" to see the conditions. There is >>>> absolutely no warranty for GDB. Type "show warranty" for >>>> details. This GDB was configured as "amd64-marcel-freebsd"... >>>> >>>> Unread portion of the kernel message buffer: panic: tcp_detach:=20 >>>> INP_TIMEWAIT && INP_DROPPED && tp !=3D NULL cpuid =3D 16 KDB: stack = >>>> backtrace: db_trace_self_wrapper() at=20 >>>> db_trace_self_wrapper+0x2b/frame 0xfffffe183d9e97e0 >>>> kdb_backtrace() at kdb_backtrace+0x39/frame 0xfffffe183d9e9890 >>>> vpanic() at vpanic+0x126/frame 0xfffffe183d9e98d0 kassert_panic() >>>> at kassert_panic+0x139/frame 0xfffffe183d9e9940 tcp_usr_detach() >>>> at tcp_usr_detach+0xf9/frame 0xfffffe183d9e9970 sofree() at=20 >>>> sofree+0x1f1/frame 0xfffffe183d9e99a0 soclose() at=20 >>>> soclose+0x3a0/frame 0xfffffe183d9e99f0 _fdrop() at=20 >>>> _fdrop+0x29/frame 0xfffffe183d9e9a10 closef() at >>>> closef+0x1e2/frame 0xfffffe183d9e9aa0 closefp() at >>>> closefp+0x9d/frame 0xfffffe183d9e9ae0 amd64_syscall() at >>>> amd64_syscall+0x25a/frame 0xfffffe183d9e9bf0 Xfast_syscall() at >>>> Xfast_syscall+0xfb/frame 0xfffffe183d9e9bf0 --- syscall (6, >>>> FreeBSD ELF64, sys_close), rip =3D 0x801c8d94a, rsp =3D >>>> 0x7ffff91c8668, rbp =3D 0x7ffff91c8680 --- KDB: enter: panic >>>> Uptime: 18h57m59s Dumping 23085 out of 98263=20 >>>> MB:..1%..11%..21%..31%..41%..51%..61%..71%..81%..91% >>>> >>>> Reading symbols from /boot/kernel/nullfs.ko.symbols...done. >>>> Loaded symbols for /boot/kernel/nullfs.ko.symbols Reading symbols >>>> from /boot/kernel/zfs.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/zfs.ko.symbols Reading symbols from=20 >>>> /boot/kernel/opensolaris.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/opensolaris.ko.symbols Reading symbols from=20 >>>> /boot/kernel/ng_bridge.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/ng_bridge.ko.symbols Reading symbols from=20 >>>> /boot/kernel/netgraph.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/netgraph.ko.symbols Reading symbols from=20 >>>> /boot/kernel/ng_eiface.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/ng_eiface.ko.symbols Reading symbols from=20 >>>> /boot/kernel/ng_ether.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/ng_ether.ko.symbols Reading symbols from=20 >>>> /boot/kernel/accf_data.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/accf_data.ko.symbols Reading symbols from=20 >>>> /boot/kernel/accf_http.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/accf_http.ko.symbols Reading symbols from=20 >>>> /boot/kernel/ums.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/ums.ko.symbols Reading symbols from=20 >>>> /boot/kernel/ng_socket.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/ng_socket.ko.symbols Reading symbols from=20 >>>> /boot/kernel/fdescfs.ko.symbols...done. Loaded symbols for=20 >>>> /boot/kernel/fdescfs.ko.symbols #0 doadump (textdump=3D1) at=20 >>>> pcpu.h:219 219 __asm("movq %%gs:%1,%0" : "=3Dr" (td) (kgdb) bt #0=20 >>>> doadump (textdump=3D1) at pcpu.h:219 #1 0xffffffff8094b337 in=20 >>>> kern_reboot (howto=3D260) at /usr/src/sys/kern/kern_shutdown.c:451 >>>> #2 0xffffffff8094b845 in vpanic (fmt=3D, >>>> ap=3D) at >>>> /usr/src/sys/kern/kern_shutdown.c:758 #3 0xffffffff8094b6d9 in >>>> kassert_panic (fmt=3D) at=20 >>>> /usr/src/sys/kern/kern_shutdown.c:646 #4 0xffffffff80b1ee59 in=20 >>>> tcp_usr_detach (so=3D) at=20 >>>> /usr/src/sys/netinet/tcp_usrreq.c:202 #5 0xffffffff809cd291 in=20 >>>> sofree (so=3D0xfffff801dd302000) at=20 >>>> /usr/src/sys/kern/uipc_socket.c:747 #6 0xffffffff809cdb00 in=20 >>>> soclose (so=3D) at=20 >>>> /usr/src/sys/kern/uipc_socket.c:849 #7 0xffffffff808fe659 in=20 >>>> _fdrop (fp=3D0xfffff802a593db40, td=3D0x0) at file.h:343 #8=20 >>>> 0xffffffff80901092 in closef (fp=3D0xfffff802a593db40,=20 >>>> td=3D0xfffff80eebc894a0) at /usr/src/sys/kern/kern_descrip.c:2338 >>>> #9 0xffffffff808feb5d in closefp (fdp=3D0xfffff80b20cce000, >>>> fd=3D, fp=3D0xfffff802a593db40, >>>> td=3D0xfffff80eebc894a0, holdleaders=3D) at=20 >>>> /usr/src/sys/kern/kern_descrip.c:1194 #10 0xffffffff80d7bc3a in=20 >>>> amd64_syscall (td=3D0xfffff80eebc894a0, traced=3D0) at=20 >>>> subr_syscall.c:134 #11 0xffffffff80d5f1db in Xfast_syscall () at=20 >>>> /usr/src/sys/amd64/amd64/exception.S:396 #12 0x0000000801c8d94a >>>> in ?? () Previous frame inner to this frame (corrupt stack?) >>>> Current language: auto; currently minimal >>> >>> Thanks for the information. As I suspected the initial error was=20 >>> elsewhere than tcp_twclose(), never got this assertion before: >>> >>> tcp_detach: INP_TIMEWAIT && INP_DROPPED && tp !=3D NULL >>> >>> from here: >>> >>> static void tcp_detach(struct socket *so, struct inpcb *inp) {=20 >>> struct tcpcb *tp; >>> >>> INP_INFO_WLOCK_ASSERT(&V_tcbinfo); INP_WLOCK_ASSERT(inp); >>> >>> KASSERT(so->so_pcb =3D=3D inp, ("tcp_detach: so_pcb !=3D inp"));=20 >>> KASSERT(inp->inp_socket =3D=3D so, ("tcp_detach: inp_socket !=3D so")= ); >>> >>> tp =3D intotcpcb(inp); >>> >>> if (inp->inp_flags & INP_TIMEWAIT) { if (inp->inp_flags & >>> INP_DROPPED) { KASSERT(tp =3D=3D NULL, ("tcp_detach: INP_TIMEWAIT && = "=20 >>> "INP_DROPPED && tp !=3D NULL")); >>> >>> Let me check if I could find a path that could lead to this=20 >>> unexpected case. Unexpected because: INP_DROPPED and >>> inp->inp_ppcb is set to NULL are set at same time here: >>> >>> void tcp_twclose(struct tcptw *tw, int reuse) { struct socket *so;=20 >>> struct inpcb *inp; >>> >>> inp =3D tw->tw_inpcb; KASSERT((inp->inp_flags & INP_TIMEWAIT), >>> ("tcp_twclose: !timewait")); KASSERT(intotw(inp) =3D=3D tw, >>> ("tcp_twclose: inp_ppcb !=3D tw"));=20 >>> INP_INFO_WLOCK_ASSERT(&V_tcbinfo); /* in_pcbfree() */=20 >>> INP_WLOCK_ASSERT(inp); >>> >>> tcp_tw_2msl_stop(tw, reuse); inp->inp_ppcb =3D NULL;=20 >>> in_pcbdrop(inp); ... Thanks to Palle, I got access to the kernel dump. And the results is more interesting than expected: Thus somehow the kernel reaches a state in tcp_detach() where: INP_TIMEWAIT && INP_DROPPED && tp !=3D NULL In details: - inp is in TIMEWAIT state - inp has been dropped by in_pcbdrop() - inp->inp_ppcb (a struct tcptw) is not NULL All the related structures looks good from the coredump: socket, inp, and tcptw, thus no sign of any memory corruption (so far). And for the kernel, this state it is _not_ ok. Hopefully, there are only two functions that set the INP_DROPPED flags: - tcp_twclose() and, - tcp_close() If tcp_twclose() is called inp->inp_ppcb is set to NULL and the struct tcptw is freed (all good, not assertion) If tcp_close() is called inp->inp_ppcb is left untouched (less ok, potential assertion) Almost all tcp_close() calls (or tcp_close() parents calls) use a pattern like: if (inp->inp_flags & INP_TIMEWAIT) { /* Don't call tcp_close() just return */ return; } /* Call tcp_close() */ tcp_close(); But not _all_ tcp_close() calls. Thus the most important point here is: Either this assertion is wrong, either tcp_close() in INP_TIMEWAIT state should not happen. This assert and tcp_close() current behavior is here since a long time, thus I would like old beards^W^W^W more experimented TCP stack developers to give an opinion/refresh theirs memories on this very specific case. Thanks. -- Julien --s9lbmCv2GbI7TneJF7f7xkPr5S7L6gbRV Content-Type: application/pgp-signature; name="signature.asc" Content-Description: OpenPGP digital signature Content-Disposition: attachment; filename="signature.asc" -----BEGIN PGP SIGNATURE----- Comment: GPGTools - https://gpgtools.org iQEcBAEBCgAGBQJWAruHAAoJEKVlQ5Je6dhxG18H/jDEaEnWvEPSUvo7xPkHcTeW eiyWDP99Lrfa2xe0CNdyLMhrv3/Ck5nga9bBfS1GFGyijy4+Ta6GEBC9xy+XP9uY Y7hh2PEZiGHaHsfZo+DwnOWhZzAWACZoXZwi4kgDU5cvzlona/6Oij9880EYISeJ oXUIX74e1RyUP0JcWLyAxjFx/V/Hf9c4UNpZOONDcGnbwjR9s5x4KggyVDGXaAaX rae+kbXyFrIG7Uaia5J2ipyck7wmrHV505qKrPQrZq0eig1rQtIn9jpjf9LRzHgR /EJ5IGfXBD8ajVazqLf3uHR+M+8DX49NS/iTUo0qzmLesNgFxf0oUlvwBR+RhM8= =m8Mc -----END PGP SIGNATURE----- --s9lbmCv2GbI7TneJF7f7xkPr5S7L6gbRV--