{"action":"created","issue":{"url":"https://api.github.com/repos/moby/moby/issues/5618","repository_url":"https://api.github.com/repos/moby/moby","labels_url":"https://api.github.com/repos/moby/moby/issues/5618/labels{/name}","comments_url":"https://api.github.com/repos/moby/moby/issues/5618/comments","events_url":"https://api.github.com/repos/moby/moby/issues/5618/events","html_url":"https://github.com/moby/moby/issues/5618","id":32864464,"number":5618,"title":"kernel crash after \"unregister_netdevice: waiting for lo to become free. Usage count = 3\"","user":{"login":"tankywoo","id":1169499,"avatar_url":"https://avatars2.githubusercontent.com/u/1169499?v=4","gravatar_id":"","url":"https://api.github.com/users/tankywoo","html_url":"https://github.com/tankywoo","followers_url":"https://api.github.com/users/tankywoo/followers","following_url":"https://api.github.com/users/tankywoo/following{/other_user}","gists_url":"https://api.github.com/users/tankywoo/gists{/gist_id}","starred_url":"https://api.github.com/users/tankywoo/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/tankywoo/subscriptions","organizations_url":"https://api.github.com/users/tankywoo/orgs","repos_url":"https://api.github.com/users/tankywoo/repos","events_url":"https://api.github.com/users/tankywoo/events{/privacy}","received_events_url":"https://api.github.com/users/tankywoo/received_events","type":"User","site_admin":false},"labels":[{"id":102727640,"url":"https://api.github.com/repos/moby/moby/labels/area/kernel","name":"area/kernel","color":"fbca04","default":false},{"id":237472034,"url":"https://api.github.com/repos/moby/moby/labels/area/networking","name":"area/networking","color":"fbca04","default":false}],"state":"open","locked":false,"assignee":null,"assignees":[],"milestone":null,"comments":380,"created_at":"2014-05-06T03:48:01Z","updated_at":"2017-07-27T17:33:53Z","closed_at":null,"body":"This happens when I login the container, and can't quit by Ctrl-c.\n\nMy system is `Ubuntu 12.04`, kernel is `3.8.0-25-generic`.\n\ndocker version:\n\n```\nroot@wutq-docker:~# docker version\nClient version: 0.10.0\nClient API version: 1.10\nGo version (client): go1.2.1\nGit commit (client): dc9c28f\nServer version: 0.10.0\nServer API version: 1.10\nGit commit (server): dc9c28f\nGo version (server): go1.2.1\nLast stable version: 0.10.0\n```\n\nI have used the script https://raw.githubusercontent.com/dotcloud/docker/master/contrib/check-config.sh to check, and all right.\n\nI watch the syslog and found this message:\n\n```\nMay  6 11:30:33 wutq-docker kernel: [62365.889369] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:30:44 wutq-docker kernel: [62376.108277] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:30:54 wutq-docker kernel: [62386.327156] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:31:02 wutq-docker kernel: [62394.423920] INFO: task docker:1024 blocked for more than 120 seconds.\nMay  6 11:31:02 wutq-docker kernel: [62394.424175] \"echo 0 > /proc/sys/kernel/hung_task_timeout_secs\" disables this message.\nMay  6 11:31:02 wutq-docker kernel: [62394.424505] docker          D 0000000000000001     0  1024      1 0x00000004\nMay  6 11:31:02 wutq-docker kernel: [62394.424511]  ffff880077793cb0 0000000000000082 ffffffffffffff04 ffffffff816df509\nMay  6 11:31:02 wutq-docker kernel: [62394.424517]  ffff880077793fd8 ffff880077793fd8 ffff880077793fd8 0000000000013f40\nMay  6 11:31:02 wutq-docker kernel: [62394.424521]  ffff88007c461740 ffff880076b1dd00 000080d081f06880 ffffffff81cbbda0\nMay  6 11:31:02 wutq-docker kernel: [62394.424526] Call Trace:                                                         \nMay  6 11:31:02 wutq-docker kernel: [62394.424668]  [<ffffffff816df509>] ? __slab_alloc+0x28a/0x2b2\nMay  6 11:31:02 wutq-docker kernel: [62394.424700]  [<ffffffff816f1849>] schedule+0x29/0x70\nMay  6 11:31:02 wutq-docker kernel: [62394.424705]  [<ffffffff816f1afe>] schedule_preempt_disabled+0xe/0x10\nMay  6 11:31:02 wutq-docker kernel: [62394.424710]  [<ffffffff816f0777>] __mutex_lock_slowpath+0xd7/0x150\nMay  6 11:31:02 wutq-docker kernel: [62394.424715]  [<ffffffff815dc809>] ? copy_net_ns+0x69/0x130\nMay  6 11:31:02 wutq-docker kernel: [62394.424719]  [<ffffffff815dc0b1>] ? net_alloc_generic+0x21/0x30\nMay  6 11:31:02 wutq-docker kernel: [62394.424724]  [<ffffffff816f038a>] mutex_lock+0x2a/0x50\nMay  6 11:31:02 wutq-docker kernel: [62394.424727]  [<ffffffff815dc82c>] copy_net_ns+0x8c/0x130\nMay  6 11:31:02 wutq-docker kernel: [62394.424733]  [<ffffffff81084851>] create_new_namespaces+0x101/0x1b0\nMay  6 11:31:02 wutq-docker kernel: [62394.424737]  [<ffffffff81084a33>] copy_namespaces+0xa3/0xe0\nMay  6 11:31:02 wutq-docker kernel: [62394.424742]  [<ffffffff81057a60>] ? dup_mm+0x140/0x240\nMay  6 11:31:02 wutq-docker kernel: [62394.424746]  [<ffffffff81058294>] copy_process.part.22+0x6f4/0xe60\nMay  6 11:31:02 wutq-docker kernel: [62394.424752]  [<ffffffff812da406>] ? security_file_alloc+0x16/0x20\nMay  6 11:31:02 wutq-docker kernel: [62394.424758]  [<ffffffff8119d118>] ? get_empty_filp+0x88/0x180\nMay  6 11:31:02 wutq-docker kernel: [62394.424762]  [<ffffffff81058a80>] copy_process+0x80/0x90\nMay  6 11:31:02 wutq-docker kernel: [62394.424766]  [<ffffffff81058b7c>] do_fork+0x9c/0x230\nMay  6 11:31:02 wutq-docker kernel: [62394.424769]  [<ffffffff816f277e>] ? _raw_spin_lock+0xe/0x20\nMay  6 11:31:02 wutq-docker kernel: [62394.424774]  [<ffffffff811b9185>] ? __fd_install+0x55/0x70\nMay  6 11:31:02 wutq-docker kernel: [62394.424777]  [<ffffffff81058d96>] sys_clone+0x16/0x20\nMay  6 11:31:02 wutq-docker kernel: [62394.424782]  [<ffffffff816fb939>] stub_clone+0x69/0x90\nMay  6 11:31:02 wutq-docker kernel: [62394.424786]  [<ffffffff816fb5dd>] ? system_call_fastpath+0x1a/0x1f\nMay  6 11:31:04 wutq-docker kernel: [62396.466223] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:31:14 wutq-docker kernel: [62406.689132] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:31:25 wutq-docker kernel: [62416.908036] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:31:35 wutq-docker kernel: [62427.126927] unregister_netdevice: waiting for lo to become free. Usage count = 3\nMay  6 11:31:45 wutq-docker kernel: [62437.345860] unregister_netdevice: waiting for lo to become free. Usage count = 3\n```\n\nAfter happend this, I open another terminal and kill this process, and then restart docker, but this will be hanged.\n\nI reboot the host, and it still display that messages for some minutes when shutdown:\n![screen shot 2014-05-06 at 11 49 27](https://cloud.githubusercontent.com/assets/1169499/2885827/78dcd126-d4d0-11e3-8b0b-e1ccca449589.png)\n"},"comment":{"url":"https://api.github.com/repos/moby/moby/issues/comments/318432218","html_url":"https://github.com/moby/moby/issues/5618#issuecomment-318432218","issue_url":"https://api.github.com/repos/moby/moby/issues/5618","id":318432218,"user":{"login":"rn","id":3338098,"avatar_url":"https://avatars0.githubusercontent.com/u/3338098?v=4","gravatar_id":"","url":"https://api.github.com/users/rn","html_url":"https://github.com/rn","followers_url":"https://api.github.com/users/rn/followers","following_url":"https://api.github.com/users/rn/following{/other_user}","gists_url":"https://api.github.com/users/rn/gists{/gist_id}","starred_url":"https://api.github.com/users/rn/starred{/owner}{/repo}","subscriptions_url":"https://api.github.com/users/rn/subscriptions","organizations_url":"https://api.github.com/users/rn/orgs","repos_url":"https://api.github.com/users/rn/repos","events_url":"https://api.github.com/users/rn/events{/privacy}","received_events_url":"https://api.github.com/users/rn/received_events","type":"User","site_admin":false},"created_at":"2017-07-27T17:33:53Z","updated_at":"2017-07-27T17:33:53Z","body":"@piec, many thanks for the details. I have a few more questions for you at the end of this very long comment.\r\n\r\nUsing the SMB setup I was able to produce a number of things with different kernels. I've tried this with the NFS setup as well but no dice. \r\n\r\nAll tests are run with docker 17.06.1-ce on HyperKit with a VM configured with 2 vCPUs and 2GB of memory (via Docker for Mac, but that should not matter). I'm using LinuxKit kernels, because I can easily swap them out.\r\n\r\nI modified your `Dockerfile` in that I added a call to `date` as the first command executed and also added a call to `date` before andeafter the `docker run` for the client.\r\n\r\n### Experiment 1 (4.9.39 kernel)\r\n\r\nWith 4.9.39 (latest 4.9.x stable kernel) I get a kernel crash:\r\n```\r\n# while true; do  date;    docker run -it --rm --name client-smb --cap-add=SYS_ADMIN --cap-add DAC_READ_SEARCH --link samba:samba client-smb:1;  date;   sleep 1; done\r\nThu 27 Jul 2017 14:12:51 BST\r\n+ date\r\nThu Jul 27 13:12:52 UTC 2017\r\n+ mount.cifs //172.17.0.2/public /mnt/ -o vers=3.0,user=nobody,password=\r\n+ date\r\nThu Jul 27 13:12:52 UTC 2017\r\n+ ls -la /mnt\r\ntotal 1028\r\ndrwxr-xr-x    2 root     root             0 Jul 27 10:11 .\r\ndrwxr-xr-x    1 root     root          4096 Jul 27 13:12 ..\r\n-rwxr-xr-x    1 root     root             3 Jul 27 10:11 bla\r\n+ umount /mnt\r\n+ echo umount ok\r\numount ok\r\nThu 27 Jul 2017 14:12:52 BST\r\nThu 27 Jul 2017 14:12:53 BST\r\n\r\n---> First iteration suceeds and then hangs on the docker run\r\n```\r\nand in `dmesg`:\r\n```\r\n[  268.347598] BUG: unable to handle kernel paging request at 0000000100000015\r\n[  268.348072] IP: [<ffffffff8c64ea95>] sk_filter_uncharge+0x5/0x31\r\n[  268.348411] PGD 0 [  268.348517]\r\n[  268.348614] Oops: 0000 [#1] SMP\r\n[  268.348789] Modules linked in:\r\n[  268.348971] CPU: 1 PID: 2221 Comm: vsudd Not tainted 4.9.39-linuxkit #1\r\n[  268.349330] Hardware name:   BHYVE, BIOS 1.00 03/14/2014\r\n[  268.349620] task: ffff8b6ab8eb5100 task.stack: ffffa015c113c000\r\n[  268.349995] RIP: 0010:[<ffffffff8c64ea95>]  [<ffffffff8c64ea95>] sk_filter_uncharge+0x5/0x31\r\n[  268.350509] RSP: 0018:ffffa015c113fe10  EFLAGS: 00010202\r\n[  268.350818] RAX: 0000000000000000 RBX: ffff8b6ab7eee6a8 RCX: 0000000000000006\r\n[  268.351231] RDX: 00000000ffffffff RSI: 00000000fffffffd RDI: ffff8b6ab7eee400\r\n[  268.351636] RBP: ffff8b6ab7eee400 R08: 0000000000000000 R09: 0000000000000000\r\n[  268.352022] R10: ffffa015c101fcb0 R11: 0000000000000000 R12: 0000000000000000\r\n[  268.352409] R13: ffff8b6ab7eee4a8 R14: ffff8b6ab7f8e340 R15: 0000000000000000\r\n[  268.352796] FS:  00007f03f62e3eb0(0000) GS:ffff8b6abc700000(0000) knlGS:0000000000000000\r\n[  268.353234] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033\r\n[  268.353546] CR2: 0000000100000015 CR3: 00000000782d2000 CR4: 00000000000406a0\r\n[  268.353961] Stack:\r\n[  268.354106]  ffffffff8c625054 ffff8b6ab7eee400 ffffa015c113fe88 0000000000000000\r\n[  268.354526]  ffffffff8c74ed96 01000008bc718980 0000000000000000 0000000000000000\r\n[  268.354965]  de66927a28223151 ffff8b6ab4443a40 ffffa015c101fcb0 ffff8b6ab4443a70\r\n[  268.355384] Call Trace:\r\n[  268.355523]  [<ffffffff8c625054>] ? __sk_destruct+0x35/0x133\r\n[  268.355822]  [<ffffffff8c74ed96>] ? unix_release_sock+0x1df/0x212\r\n[  268.356164]  [<ffffffff8c74ede2>] ? unix_release+0x19/0x25\r\n[  268.356454]  [<ffffffff8c62034c>] ? sock_release+0x1a/0x6c\r\n[  268.356742]  [<ffffffff8c6203ac>] ? sock_close+0xe/0x11\r\n[  268.357019]  [<ffffffff8c1f8710>] ? __fput+0xdd/0x17b\r\n[  268.357288]  [<ffffffff8c0f604d>] ? task_work_run+0x64/0x7a\r\n[  268.357583]  [<ffffffff8c003285>] ? prepare_exit_to_usermode+0x7d/0xa4\r\n[  268.357925]  [<ffffffff8c7d2884>] ? entry_SYSCALL_64_fastpath+0xa7/0xa9\r\n[  268.358268] Code: 08 4c 89 e7 e8 fb f8 ff ff 48 3d 00 f0 ff ff 77 06 48 89 45 00 31 c0 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f 44 00 00 <48> 8b 46 18 8b 40 04 48 8d 04 c5 28 00 00 00 f0 29 87 24 01 00\r\n[  268.359776] RIP  [<ffffffff8c64ea95>] sk_filter_uncharge+0x5/0x31\r\n[  268.360118]  RSP <ffffa015c113fe10>\r\n[  268.360311] CR2: 0000000100000015\r\n[  268.360550] ---[ end trace 4a7830b42d5acfb3 ]---\r\n[  268.360861] Kernel panic - not syncing: Fatal exception\r\n[  268.361217] Kernel Offset: 0xb000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)\r\n[  268.361789] Rebooting in 120 seconds..\r\n```\r\nSome times I see several iteration of what the 4.11.12 kernel does, including the `unregister_netdevice` messages (see below) and then get the kernel crash above. Sometimes I see a slight variations for the crash, like:\r\n```\r\n[  715.926694] BUG: unable to handle kernel paging request at 00000000fffffdc9\r\n[  715.927380] IP: [<ffffffff8664ea95>] sk_filter_uncharge+0x5/0x31\r\n[  715.927868] PGD 0 [  715.928022]\r\n[  715.928174] Oops: 0000 [#1] SMP\r\n[  715.928424] Modules linked in:\r\n[  715.928703] CPU: 0 PID: 2665 Comm: runc:[0:PARENT] Not tainted 4.9.39-linuxkit #1\r\n[  715.929321] Hardware name:   BHYVE, BIOS 1.00 03/14/2014\r\n[  715.929765] task: ffff931538ef4140 task.stack: ffffbcbbc0214000\r\n[  715.930279] RIP: 0010:[<ffffffff8664ea95>]  [<ffffffff8664ea95>] sk_filter_uncharge+0x5/0x31\r\n[  715.931043] RSP: 0018:ffffbcbbc0217be0  EFLAGS: 00010206\r\n[  715.931487] RAX: 0000000000000000 RBX: ffff931532a662a8 RCX: 0000000000000006\r\n[  715.932043] RDX: 00000000ffffffff RSI: 00000000fffffdb1 RDI: ffff931532a66000\r\n[  715.932612] RBP: ffff931532a66000 R08: 0000000000000000 R09: 0000000000000000\r\n[  715.933181] R10: ffff9315394f2990 R11: 000000000001bb68 R12: ffff931532a66000\r\n[  715.933725] R13: ffff9315328060a8 R14: ffff931532a66340 R15: 0000000000000000\r\n[  715.934258] FS:  0000000000000000(0000) GS:ffff93153c600000(0000) knlGS:0000000000000000\r\n[  715.934857] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033\r\n[  715.935286] CR2: 00000000fffffdc9 CR3: 0000000052c09000 CR4: 00000000000406b0\r\n[  715.935822] Stack:\r\n[  715.935974]  ffffffff86625054 ffff931532806000 ffffbcbbc0217c58 ffff931532a66000\r\n[  715.936560]  ffffffff8674ed37 0100000800000282 0000000000000000 0000000000000000\r\n[  715.937173]  5de0b9a3a313c00b ffff9315346f5080 ffff9315394f2990 ffff9315346f50b0\r\n[  715.937751] Call Trace:\r\n[  715.937982]  [<ffffffff86625054>] ? __sk_destruct+0x35/0x133\r\n[  715.938608]  [<ffffffff8674ed37>] ? unix_release_sock+0x180/0x212\r\n[  715.939130]  [<ffffffff8674ede2>] ? unix_release+0x19/0x25\r\n[  715.939517]  [<ffffffff8662034c>] ? sock_release+0x1a/0x6c\r\n[  715.939907]  [<ffffffff866203ac>] ? sock_close+0xe/0x11\r\n[  715.940277]  [<ffffffff861f8710>] ? __fput+0xdd/0x17b\r\n[  715.940635]  [<ffffffff860f604d>] ? task_work_run+0x64/0x7a\r\n[  715.941072]  [<ffffffff860e148a>] ? do_exit+0x42a/0x8e0\r\n[  715.941472]  [<ffffffff8674edfa>] ? scm_destroy+0xc/0x25\r\n[  715.941880]  [<ffffffff867504e0>] ? unix_stream_sendmsg+0x2dd/0x30b\r\n[  715.942357]  [<ffffffff860e19aa>] ? do_group_exit+0x3c/0x9d\r\n[  715.942780]  [<ffffffff860eac41>] ? get_signal+0x45d/0x4e2\r\n[  715.943210]  [<ffffffff86621640>] ? sock_sendmsg+0x2d/0x3c\r\n[  715.943618]  [<ffffffff8602055a>] ? do_signal+0x36/0x4c9\r\n[  715.944017]  [<ffffffff861f64c7>] ? __vfs_write+0x8f/0xcc\r\n[  715.944416]  [<ffffffff861f7100>] ? vfs_write+0xbb/0xc7\r\n[  715.944809]  [<ffffffff8600326c>] ? prepare_exit_to_usermode+0x64/0xa4\r\n[  715.945295]  [<ffffffff867d2884>] ? entry_SYSCALL_64_fastpath+0xa7/0xa9\r\n[  715.945789] Code: 08 4c 89 e7 e8 fb f8 ff ff 48 3d 00 f0 ff ff 77 06 48 89 45 00 31 c0 48 83 c4 10 5b 5d 41 5c 41 5d 41 5e 41 5f c3 0f 1f 44 00 00 <48> 8b 46 18 8b 40 04 48 8d 04 c5 28 00 00 00 f0 29 87 24 01 00\r\n[  715.947701] RIP  [<ffffffff8664ea95>] sk_filter_uncharge+0x5/0x31\r\n[  715.948112]  RSP <ffffbcbbc0217be0>\r\n[  715.948292] CR2: 00000000fffffdc9\r\n[  715.948467] ---[ end trace 2d69bea56725fd5f ]---\r\n[  715.948722] Kernel panic - not syncing: Fatal exception\r\n[  715.949059] Kernel Offset: 0x5000000 from 0xffffffff81000000 (relocation range: 0xffffffff80000000-0xffffffffbfffffff)\r\n[  715.949595] Rebooting in 120 seconds..\r\n```\r\n\r\nThe crashes are in the unix domain socket code and similar/identical to what is\r\nreported [here](https://github.com/linuxkit/linuxkit/issues/2156), though with this new test case it is much easier to reproduce.\r\n\r\n\r\n### Experiment 2 (4.11.12 kernel)\r\n\r\nWith 4.11.12 (which is the latest stable in the 4.11 series) I see no crashes, *but* it is really slow (annotations inline with `--->`):\r\n```\r\n# while true; do  date;    docker run -it --rm --name client-smb --cap-add=SYS_ADMIN --cap-add DAC_READ_SEARCH --link samba:samba client-smb:1;  date;   sleep 1; done\r\nThu 27 Jul 2017 13:48:04 BST\r\n+ date\r\nThu Jul 27 12:48:05 UTC 2017\r\n+ mount.cifs //172.17.0.2/public /mnt/ -o vers=3.0,user=nobody,password=\r\n+ date\r\nThu Jul 27 12:48:05 UTC 2017\r\n+ ls -la /mnt\r\ntotal 1028\r\ndrwxr-xr-x    2 root     root             0 Jul 27 10:11 .\r\ndrwxr-xr-x    1 root     root          4096 Jul 27 12:48 ..\r\n-rwxr-xr-x    1 root     root             3 Jul 27 10:11 bla\r\n+ umount /mnt\r\n+ echo umount ok\r\numount ok\r\nThu 27 Jul 2017 13:48:05 BST\r\n\r\n---> First iteration takes one second\r\n\r\nThu 27 Jul 2017 13:48:06 BST\r\ndocker: Error response from daemon: containerd: container did not start before the specified timeout.\r\nThu 27 Jul 2017 13:50:07 BST\r\n\r\n---> Second iteration fails after 2 minutes with dockerd unable to start the container\r\n\r\nThu 27 Jul 2017 13:50:08 BST\r\n+ date\r\nThu Jul 27 12:51:52 UTC 2017\r\n+ mount.cifs //172.17.0.2/public /mnt/ -o vers=3.0,user=nobody,password=\r\n+ date\r\nThu Jul 27 12:51:53 UTC 2017\r\n+ ls -la /mnt\r\ntotal 1028\r\ndrwxr-xr-x    2 root     root             0 Jul 27 10:11 .\r\ndrwxr-xr-x    1 root     root          4096 Jul 27 12:50 ..\r\n-rwxr-xr-x    1 root     root             3 Jul 27 10:11 bla\r\n+ umount /mnt\r\n+ echo umount ok\r\numount ok\r\nThu 27 Jul 2017 13:51:53 BST\r\n\r\n---> Third iterations succeeds, BUT it takes almost 2 minutes between docker run and the container running\r\n\r\nThu 27 Jul 2017 13:51:54 BST\r\ndocker: Error response from daemon: containerd: container did not start before the specified timeout.\r\nThu 27 Jul 2017 13:53:55 BST\r\n\r\n---> Fourth iteration fails after two minutes\r\n\r\nThu 27 Jul 2017 13:53:56 BST\r\n+ date\r\nThu Jul 27 12:55:37 UTC 2017\r\n+ mount.cifs //172.17.0.2/public /mnt/ -o vers=3.0,user=nobody,password=\r\n+ date\r\nThu Jul 27 12:55:37 UTC 2017\r\n+ ls -la /mnt\r\ntotal 1028\r\ndrwxr-xr-x    2 root     root             0 Jul 27 10:11 .\r\ndrwxr-xr-x    1 root     root          4096 Jul 27 12:53 ..\r\n-rwxr-xr-x    1 root     root             3 Jul 27 10:11 bla\r\n+ umount /mnt\r\n+ echo umount ok\r\numount ok\r\nThu 27 Jul 2017 13:55:38 BST\r\n\r\n---> Fifth iteration succeeds, but almost 2 minutes between docker run and the container executing\r\n```\r\n\r\nI had this running for an hour or so with the same pattern repeating, *but* no kernel crash.\r\n\r\nI the kernel logs I see, lots of:\r\n```\r\n[   84.940380] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[   95.082151] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  105.253289] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  115.477095] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  125.627059] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  135.789298] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  145.969455] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  156.101126] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  166.303333] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  176.445791] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  186.675958] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  196.870265] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  206.998238] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[...]\r\n```\r\nThat is a message every ten seconds.\r\n\r\nSince this does not cause the hung task detection to kick in even after an hour, I suspect that with 4.11.12 the reference count *eventually* gets decremented and the device get's freed, but, judging by the intervals I can run containers, it might take up to 4mins!\r\n\r\n\r\n### Experiment 3 (4.11.12 kernel)\r\n\r\nThe kernel crash in the OP indicated that the kernel crashed because a hung task was detected. I haven not seen this crash in my testing, so I changed the `sysctl` setting related to hung task detection:\r\n```\r\n# sysctl -a | grep kernel.hung_task\r\nkernel.hung_task_check_count = 4194304\r\nkernel.hung_task_panic = 0\r\nkernel.hung_task_timeout_secs = 120\r\nkernel.hung_task_warnings = 10\r\n# sysctl -w kernel.hung_task_timeout_secs = 60\r\n# sysctl -w kernel.hung_task_panic=1\r\n```\r\nThis reduces the timeout to 60 seconds and panics the kernel if a hung task was detected. Since it takes around 2 minutes before `dockerd` complained that `containerd` did not start, reducing the hung task detection to 60s ought to trigger a kernel panics *if* a single task was hung. Alas there was no crash in the logs\r\n\r\n\r\n### Experiment 4 (4.11.12 kernel)\r\n\r\nNext, I increase the `sleep` after each `docker run` to 5 minutes to see if the messages are continuous. In this case all `docker run`s seem to work, which is kinda expected since from the previous experiments a `docker run` would work every 4 minutes or so\r\n\r\n```\r\n---> This is after the first run\r\n[  281.406660] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  291.455945] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  301.721340] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  311.988572] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  322.258805] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  332.527383] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  342.796511] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  353.059499] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  363.327472] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  373.365562] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  383.635923] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  393.684949] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  403.950186] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  414.221779] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  424.490110] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  434.754925] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  445.022243] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  455.292106] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  465.557462] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  475.826946] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  486.097833] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n\r\n---> 200+ seconds of messages and then nothing for almost 400 seconds\r\n\r\n[  883.924399] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  893.975810] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n...\r\n[ 1088.624065] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[ 1098.891297] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n\r\n---> 200+ seconds of messages and then a gap of 90 seconds\r\n\r\n[ 1185.119327] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[ 1195.387962] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n...\r\n[ 1390.040035] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[ 1400.307359] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n\r\n---> 200+ seconds of messages and then a gap of 80+ seconds\r\n\r\n[ 1486.325724] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[ 1496.591715] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n...\r\n[ 1680.987216] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[ 1691.255068] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n\r\n---> 200+ seconds of messages and then a gap of 90+ seconds\r\n\r\n[ 1787.547334] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[ 1797.819703] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n```\r\n\r\nIt looks like we are getting around 200 seconds worth of `unregister_netdevice` on almost every `docker run` (except for the second one). I suspect during that time we can't start new containers (as indicated by Experiment 2. It's curious that the hung task detection is not kicking in, presumably because no task is hung.\r\n\r\n\r\n### Experiment 5 (4.11.12/4.9.39 with a extra debugging enable in the kernel)\r\n\r\nThis is reverting back to 1s sleep in between `docker run`\r\n\r\nWe have another kernel which enabled a bunch of additional debug\r\noptions, such as `LOCKDEP`, `RCU_TRACE`, `LOCKUP_DETECTOR` and a few\r\nmore.\r\n\r\nRunning the repro 4.11.12 kernels with these debug options enabled did not trigger anything.\r\n\r\nDitto for the 4.9.39 kernel, where the normal kernel crashes. The debug options change the timing slightly, so this maybe an additional clue that the crash in the unix domain socket code shows about is due to a race.\r\n\r\n\r\n### Digging a bit deeper\r\n\r\n`strace` on the various `containerd` processes is not helpful (it\r\nusually isn't because it's written in Go). Lots of long stalls in\r\n`futex(...FUTEX_WAIT...)` with any information on where/why.\r\n\r\nSome poking around with `sysrq`:\r\n\r\nIncrease verbosity:\r\n```\r\necho 9 > /proc/sysrq-trigger\r\n```\r\n\r\nStack trace from all CPUs:\r\n```\r\necho l > /proc/sysrq-trigger\r\n[ 1034.298202] sysrq: SysRq : Show backtrace of all active CPUs\r\n[ 1034.298738] NMI backtrace for cpu 1\r\n[ 1034.299073] CPU: 1 PID: 2235 Comm: sh Tainted: G    B           4.11.12-linuxkit #1\r\n[ 1034.299818] Hardware name:   BHYVE, BIOS 1.00 03/14/2014\r\n[ 1034.300286] Call Trace:\r\n[ 1034.300517]  dump_stack+0x82/0xb8\r\n[ 1034.300827]  nmi_cpu_backtrace+0x75/0x87\r\n[ 1034.301200]  ? irq_force_complete_move+0xf1/0xf1\r\n[ 1034.301633]  nmi_trigger_cpumask_backtrace+0x6e/0xfd\r\n[ 1034.302097]  arch_trigger_cpumask_backtrace+0x19/0x1b\r\n[ 1034.302560]  ? arch_trigger_cpumask_backtrace+0x19/0x1b\r\n[ 1034.302989]  sysrq_handle_showallcpus+0x17/0x19\r\n[ 1034.303438]  __handle_sysrq+0xe4/0x172\r\n[ 1034.303826]  write_sysrq_trigger+0x47/0x4f\r\n[ 1034.304210]  proc_reg_write+0x5d/0x76\r\n[ 1034.304507]  __vfs_write+0x35/0xc8\r\n[ 1034.304773]  ? rcu_sync_lockdep_assert+0x12/0x52\r\n[ 1034.305132]  ? __sb_start_write+0x152/0x189\r\n[ 1034.305458]  ? file_start_write+0x27/0x29\r\n[ 1034.305770]  vfs_write+0xda/0x100\r\n[ 1034.306029]  SyS_write+0x5f/0xa3\r\n[ 1034.306283]  entry_SYSCALL_64_fastpath+0x1f/0xc2\r\n[ 1034.306638] RIP: 0033:0x7fa4810488a9\r\n[ 1034.306976] RSP: 002b:00007fffd3a29828 EFLAGS: 00000246 ORIG_RAX: 0000000000000001\r\n[ 1034.307567] RAX: ffffffffffffffda RBX: 000000c6b523a020 RCX: 00007fa4810488a9\r\n[ 1034.308101] RDX: 0000000000000002 RSI: 000000c6b5239d00 RDI: 0000000000000001\r\n[ 1034.308635] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000\r\n[ 1034.309169] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000\r\n[ 1034.309700] R13: 0000000000000000 R14: 00007fffd3a29988 R15: 00007fa481280ee0\r\n[ 1034.310334] Sending NMI from CPU 1 to CPUs 0:\r\n[ 1034.310710] NMI backtrace for cpu 0 skipped: idling at pc 0xffffffffa0922756\r\n```\r\nNothing here, CPU1 is idle, CPU0 is handling the sysrq.\r\n\r\n\r\nShow blocked tasks (twice)\r\n```\r\necho w > /proc/sysrq-trigger\r\n[  467.167062] sysrq: SysRq : Show Blocked State\r\n[  467.167731]   task                        PC stack   pid father\r\n[  467.168580] kworker/u4:6    D    0   293      2 0x00000000\r\n[  467.169096] Workqueue: netns cleanup_net\r\n[  467.169487] Call Trace:\r\n[  467.169732]  __schedule+0x582/0x701\r\n[  467.170073]  schedule+0x89/0x9a\r\n[  467.170338]  schedule_timeout+0xbf/0xff\r\n[  467.170666]  ? del_timer_sync+0xc1/0xc1\r\n[  467.171011]  schedule_timeout_uninterruptible+0x2a/0x2c\r\n[  467.171422]  ? schedule_timeout_uninterruptible+0x2a/0x2c\r\n[  467.171866]  msleep+0x1e/0x22\r\n[  467.172155]  netdev_run_todo+0x173/0x2c4\r\n[  467.172499]  rtnl_unlock+0xe/0x10\r\n[  467.172770]  default_device_exit_batch+0x13c/0x15f\r\n[  467.173226]  ? __wake_up_sync+0x12/0x12\r\n[  467.173550]  ops_exit_list+0x29/0x53\r\n[  467.173850]  cleanup_net+0x1a8/0x261\r\n[  467.174153]  process_one_work+0x276/0x4fb\r\n[  467.174487]  worker_thread+0x1eb/0x2ca\r\n[  467.174800]  ? rescuer_thread+0x2d9/0x2d9\r\n[  467.175136]  kthread+0x106/0x10e\r\n[  467.175406]  ? __list_del_entry+0x22/0x22\r\n[  467.175737]  ret_from_fork+0x2a/0x40\r\n[  467.176167] runc:[1:CHILD]  D    0  2609   2606 0x00000000\r\n[  467.176636] Call Trace:\r\n[  467.176849]  __schedule+0x582/0x701\r\n[  467.177152]  schedule+0x89/0x9a\r\n[  467.177451]  schedule_preempt_disabled+0x15/0x1e\r\n[  467.177827]  __mutex_lock+0x2a0/0x3ef\r\n[  467.178133]  ? copy_net_ns+0xbb/0x17c\r\n[  467.178456]  mutex_lock_killable_nested+0x1b/0x1d\r\n[  467.179068]  ? mutex_lock_killable_nested+0x1b/0x1d\r\n[  467.179489]  copy_net_ns+0xbb/0x17c\r\n[  467.179798]  create_new_namespaces+0x12b/0x19b\r\n[  467.180151]  unshare_nsproxy_namespaces+0x8f/0xaf\r\n[  467.180569]  SyS_unshare+0x17b/0x302\r\n[  467.180925]  entry_SYSCALL_64_fastpath+0x1f/0xc2\r\n[  467.181303] RIP: 0033:0x737b97\r\n[  467.181559] RSP: 002b:00007fff1965ab18 EFLAGS: 00000246 ORIG_RAX: 0000000000000110\r\n[  467.182182] RAX: ffffffffffffffda RBX: 0000000002277bd8 RCX: 0000000000737b97\r\n[  467.182805] RDX: 0000000000000000 RSI: 0000000000867a0f RDI: 000000006c020000\r\n[  467.183368] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000\r\n[  467.184014] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000\r\n[  467.184639] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000\r\n[  477.286653] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  487.457828] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  497.659654] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  507.831614] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  518.030241] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  528.232963] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  538.412263] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n[  548.583610] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\necho w > /proc/sysrq-trigger\r\n[  553.969592] sysrq: SysRq : Show Blocked State\r\n[  553.970411]   task                        PC stack   pid father\r\n[  553.971208] kworker/u4:6    D    0   293      2 0x00000000\r\n[  553.971686] Workqueue: netns cleanup_net\r\n[  553.972058] Call Trace:\r\n[  553.972305]  __schedule+0x582/0x701\r\n[  553.972690]  schedule+0x89/0x9a\r\n[  553.973039]  schedule_timeout+0xbf/0xff\r\n[  553.973462]  ? del_timer_sync+0xc1/0xc1\r\n[  553.973890]  schedule_timeout_uninterruptible+0x2a/0x2c\r\n[  553.974706]  ? schedule_timeout_uninterruptible+0x2a/0x2c\r\n[  553.975244]  msleep+0x1e/0x22\r\n[  553.975539]  netdev_run_todo+0x173/0x2c4\r\n[  553.975950]  rtnl_unlock+0xe/0x10\r\n[  553.976303]  default_device_exit_batch+0x13c/0x15f\r\n[  553.976725]  ? __wake_up_sync+0x12/0x12\r\n[  553.977121]  ops_exit_list+0x29/0x53\r\n[  553.977501]  cleanup_net+0x1a8/0x261\r\n[  553.977869]  process_one_work+0x276/0x4fb\r\n[  553.978245]  worker_thread+0x1eb/0x2ca\r\n[  553.978578]  ? rescuer_thread+0x2d9/0x2d9\r\n[  553.978933]  kthread+0x106/0x10e\r\n[  553.979283]  ? __list_del_entry+0x22/0x22\r\n[  553.979774]  ret_from_fork+0x2a/0x40\r\n[  553.980244] runc:[1:CHILD]  D    0  2609   2606 0x00000000\r\n[  553.980728] Call Trace:\r\n[  553.980949]  __schedule+0x582/0x701\r\n[  553.981254]  schedule+0x89/0x9a\r\n[  553.981533]  schedule_preempt_disabled+0x15/0x1e\r\n[  553.981917]  __mutex_lock+0x2a0/0x3ef\r\n[  553.982220]  ? copy_net_ns+0xbb/0x17c\r\n[  553.982524]  mutex_lock_killable_nested+0x1b/0x1d\r\n[  553.982909]  ? mutex_lock_killable_nested+0x1b/0x1d\r\n[  553.983311]  copy_net_ns+0xbb/0x17c\r\n[  553.983606]  create_new_namespaces+0x12b/0x19b\r\n[  553.983977]  unshare_nsproxy_namespaces+0x8f/0xaf\r\n[  553.984363]  SyS_unshare+0x17b/0x302\r\n[  553.984663]  entry_SYSCALL_64_fastpath+0x1f/0xc2\r\n[  553.985080] RIP: 0033:0x737b97\r\n[  553.985306] RSP: 002b:00007fff1965ab18 EFLAGS: 00000246 ORIG_RAX: 0000000000000110\r\n[  553.985861] RAX: ffffffffffffffda RBX: 0000000002277bd8 RCX: 0000000000737b97\r\n[  553.986383] RDX: 0000000000000000 RSI: 0000000000867a0f RDI: 000000006c020000\r\n[  553.986811] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000\r\n[  553.987182] R10: 0000000000000000 R11: 0000000000000246 R12: 0000000000000000\r\n[  553.987551] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000\r\n/ # [  558.844761] unregister_netdevice: waiting for lo to become free. Usage count = 1\r\n```\r\n\r\nThis shows that both the `netns` and `cleanup_net` work queues are busy. I found a somewhat related issue a quite a while back [here](http://marc.info/?l=linux-netdev&m=147870616302799&w=2), but this time the `cleanup_net` workqueue is in a different state.\r\n\r\n\r\n### Summary\r\n\r\n- I think the crash on 4.9.x kernels is unrelated but seems to be fixed in 4.11.x. This needs a bit more triage.\r\n- Unlike some previous reports, no hung tasks are reported, but it's hard to tell because there are very few stack traces on this issue.\r\n- Something is blocked for a very long time (2-4 minutes). It's likely related to the workqueue state\r\n- The dump of the workqueue needs more analysis, in particualr why the workqueue stay in that state that long.\r\n- The `unregister_netdev` messages seem unrelated to the recent fix (which is in both 4.9.39 and 4.11.12). This maybe because the  `cleanup_net` work queue is not progressing and thus the message is printed.\r\n  \r\nI will dig a bit more and then send a summary to `netdev`.\r\n\r\n\r\n@piec do you have console access and can see if there is anything in terms of crash dump or do you also just see huge delays as I see? If you have a crash dump, I'd be very interested in seeing it. Also, are you running on bare metal or in a VM? What's your configuration in terms of CPUs and memory?"}}
{"actor":{"display_login":"rn"}}