Date: Wed, 23 Sep 2015 16:47:22 +0200 From: Julien Charbon <jch@freebsd.org> To: Palle Girgensohn <girgen@FreeBSD.org>, John Baldwin <jhb@FreeBSD.org> Cc: Konstantin Belousov <kostikbel@gmail.com>, freebsd-net@freebsd.org, Robert Watson <rwatson@FreeBSD.org>, Warner Losh <imp@bsdimp.com> Subject: Can tcp_close() be called in INP_TIMEWAIT case [was: Re: Kernel panics in tcp_twclose] Message-ID: <5602BB7A.9010504@freebsd.org> In-Reply-To: <5601CF2D.9030307@freebsd.org> 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> <F9D29C16-502B-43A1-BE2C-D2AD30F0B9EF@FreeBSD.org> <5601CF2D.9030307@freebsd.org>
next in thread | previous in thread | raw e-mail | index | archive | help
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 <jch@freebsd.org>:
>>> On 22/09/15 18:49, Palle Girgensohn wrote:
>>>>> 22 sep 2015 kl. 18:46 skrev Palle Girgensohn=20
>>>>> <girgen@FreeBSD.org>:
>>>>>> 21 sep 2015 kl. 15:53 skrev Palle Girgensohn=20
>>>>>> <girgen@FreeBSD.org>:
>>>>>>> 21 sep 2015 kl. 10:21 skrev Julien Charbon=20
>>>>>>> <jch@FreeBSD.org>: 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<value optimized out>,
>>>> ap=3D<value optimized out>) at
>>>> /usr/src/sys/kern/kern_shutdown.c:758 #3 0xffffffff8094b6d9 in
>>>> kassert_panic (fmt=3D<value optimized out>) at=20
>>>> /usr/src/sys/kern/kern_shutdown.c:646 #4 0xffffffff80b1ee59 in=20
>>>> tcp_usr_detach (so=3D<value optimized out>) 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<value optimized out>) 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<value optimized out>, fp=3D0xfffff802a593db40,
>>>> td=3D0xfffff80eebc894a0, holdleaders=3D<value optimized out>) 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--
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?5602BB7A.9010504>