Date:   Wed, 15 Aug 2018 09:26:07 -0400
From:   Adam Mitchell <adamhmitchell@...il.com>
To:     netdev@...r.kernel.org
Subject: net/ipv4/tcp.c:2278 WARN_ON(sock_owned_by_user(sk))

After moving a busy mysql database to AWS (and changing distro,
kernel, etc), we see the following kernel warning every few days (on
several hosts):

     WARNING: CPU: 33 PID: 75361 at net/ipv4/tcp.c:2278 tcp_close+0x40f/0x430

This is coming from the following section of tcp_close():

     /* Now socket is owned by kernel and we acquire BH lock
     *  to finish close. No need to check for user refs.
     */
     local_bh_disable();
     bh_lock_sock(sk);
     WARN_ON(sock_owned_by_user(sk));

TL;DR -> Any ideas what could lead to this warning?  I'm thinking that
the ____fput() (and related) code above this in the stack trace should
have left this socket in a state that could be closed without
warnings.  Could some other kernel thread be setting sk->sk_lock.owned
to 1 during this tcp_close()?

It appears that the socket is NOT owned by kernel, causing the
warning.  This warning does not appear to break anything - however we
will eventually receive this next error (can take over a week to
happen):

     IPv4: Attempt to release TCP socket in state 10 0000000039ed388a

Once this happens, mysqld will no longer accept() new clients.
Existing open sockets work fine.  We assume the above warning about
"state 10" (TCP_LISTEN) is related, but we don't know why/how that
LISTEN socket is being released or how/if it's related to the above
warnings from tcp_close().

This error comes from net/ipv4/af_inet.c:144:

     if (sk->sk_type == SOCK_STREAM && sk->sk_state != TCP_CLOSE) {
     pr_err("Attempt to release TCP socket in state %d %p\n",
            sk->sk_state, sk);
     return;
     }


For what it's worth, mysqld seems completely unaware that it cannot
take new clients.  GDB attached to the user-mode process (pstack)
shows that it's still listening for new connections (but they will
never come up the stack).  For this reason, I don't think mysqld was
part of the attempt to close that LISTEN socket.

     Thread 1 (Thread 0x7fd82b8bd8c0 (LWP 5633)):
     #0  0x00007fd82942ff0d in poll () from /lib64/libc.so.6
     #1  0x0000000000d9c5fe in
Mysqld_socket_listener::listen_for_connection_event() ()
     #2  0x0000000000798461 in mysqld_main(int, char**) ()
     #3  0x00007fd82935e445 in __libc_start_main () from /lib64/libc.so.6
     #4  0x000000000078c875 in _start ()


Extra details below:

Kernel is 4.16.13-1.el7.elrepo.x86_64 #1 running in AWS.

https://elixir.bootlin.com/linux/v4.16.13/source/net/ipv4/tcp.c#L2278
https://elixir.bootlin.com/linux/v4.16.13/source/net/ipv4/af_inet.c#L144



[726780.788201] WARNING: CPU: 15 PID: 52245 at net/ipv4/tcp.c:2278
tcp_close+0x40f/0x430
[726780.794947] Modules linked in: binfmt_misc nf_conntrack_netlink
nfnetlink_queue tcp_diag inet_diag isofs ip6table_mangle ip6table_raw
ip6table_nat nf_nat_ipv6 iptable_security xt_CT iptable_raw
iptable_nat nf_nat_ipv4 nf_nat iptable_mangle xt_pkttype xt_NFLOG
nfnetlink_log xt_u32 xt_multiport xt_set xt_conntrack
ip_set_hash_netport ip_set_hash_ipport ip_set_hash_net ip_set_hash_ip
ip_set nfnetlink nf_conntrack_proto_gre nf_conntrack_ipv6
nf_defrag_ipv6 ip6table_filter ip6_tables xt_LOG nf_conntrack_tftp
nf_conntrack_ftp nf_conntrack_ipv4 nf_defrag_ipv4 nf_conntrack
iptable_filter zfs(PO) zunicode(PO) zavl(PO) icp(PO) sb_edac
intel_powerclamp crct10dif_pclmul crc32_pclmul ghash_clmulni_intel
pcbc aesni_intel crypto_simd glue_helper cryptd cirrus snd_seq
zcommon(PO) ttm intel_rapl_perf snd_seq_device
[726780.848696]  drm_kms_helper znvpair(PO) snd_pcm snd_timer spl(O)
drm snd soundcore syscopyarea sysfillrect pcspkr sysimgblt input_leds
fb_sys_fops i2c_piix4 ip_tables xfs libcrc32c ata_generic pata_acpi
ata_piix xen_blkfront crc32c_intel libata ena(O) serio_raw floppy
sunrpc
[726780.863916] CPU: 15 PID: 52245 Comm: mysqld Tainted: P        W  O
    4.16.13-1.el7.elrepo.x86_64 #1
[726780.869486] Hardware name: Xen HVM domU, BIOS 4.2.amazon 08/24/2006
[726780.873756] RIP: 0010:tcp_close+0x40f/0x430
[726780.877049] RSP: 0018:ffffc90063a87dd0 EFLAGS: 00010202
[726780.880913] RAX: 0000000000000001 RBX: ffff8839cbb4b300 RCX:
0000000000000001
[726780.885708] RDX: 0000000000400001 RSI: 0000000000023540 RDI:
000000000000002b
[726780.890412] RBP: ffffc90063a87df0 R08: 0000000000000000 R09:
0000000000000101
[726780.895192] R10: 00000000000003ff R11: 0000000000002057 R12:
ffff8839cbb4b388
[726780.900029] R13: 0000000000000009 R14: ffff8839cbb4b3c8 R15:
ffff883c5ed14900
[726780.904777] FS:  00007f6acd467700(0000) GS:ffff883c8b1c0000(0000)
knlGS:0000000000000000
[726780.909964] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[726780.914078] CR2: 00007f6cd5d430c8 CR3: 0000003c7e6b6005 CR4:
00000000001606e0
[726780.918837] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[726780.923433] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7:
0000000000000400
[726780.927882] Call Trace:
[726780.930410]  inet_release+0x42/0x70
[726780.933423]  inet6_release+0x30/0x40
[726780.936439]  sock_release+0x25/0x80
[726780.939421]  sock_close+0x12/0x20
[726780.942342]  __fput+0xea/0x220
[726780.945170]  ____fput+0xe/0x10
[726780.947963]  task_work_run+0x8c/0xb0
[726780.951052]  exit_to_usermode_loop+0x6b/0x95
[726780.954480]  do_syscall_64+0x182/0x1b0
[726780.957586]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[726780.961288] RIP: 0033:0x7fd82b27085d
[726780.964349] RSP: 002b:00007f6acd466b50 EFLAGS: 00000293 ORIG_RAX:
0000000000000003
[726780.969280] RAX: 0000000000000000 RBX: 00007f65b2418220 RCX:
00007fd82b27085d
[726780.973987] RDX: 0000000000000003 RSI: 00007f6d5e9990c0 RDI:
00000000000002d8
[726780.978689] RBP: 00007f6acd466c00 R08: 0000000001622848 R09:
00000000000001f8
[726780.983373] R10: 0000000000000000 R11: 0000000000000293 R12:
0000000000000000
[726780.988049] R13: 00007f6d5e9990c0 R14: 0000000001d87cc0 R15:
00000000000002d8
[726780.992700] Code: ff 48 8b 43 28 31 f6 48 89 df 48 8b 40 10 e8 49
2d 4e 00 48 8b 43 30 48 8b 80 98 01 00 00 65 48 ff 80 90 01 00 00 e9
49 ff ff ff <0f> 0b e9 ab fc ff ff 48 8b 43 28 31 f6 48 89 df 48 8b 40
10 e8
[726781.004156] ---[ end trace 8525f27644ac4631 ]---
[752066.800148] IPv4: Attempt to release TCP socket in state 10 0000000039ed388a

Powered by blists - more mailing lists