Subject: Crash with task->parent->nsproxy==NULL
From: Grzegorz Nosek <grzegorz.nosek@gmail.com>
Date: Mon, 25 Jun 2012 12:42:14 +0200

Hi,

I encountered a crash with kernel 3.2.15, patched with
patch-3.2.11-vs2.3.2.8.diff and patch from [1] to route SIGCHLD
properly. Quite possibly the problem is caused (or exposed) by my code,
but still, all comments are very welcome.

During a time of more-or-less mayhem (high CPU usage, moderate random
I/O load plus a crappy disk detaching itself from the bus right in the
middle), but *no* VServer-related actions like starting/stopping a
container I got an oops in do_notify_parent:

[58974.254066] BUG: unable to handle kernel NULL pointer dereference at
0000000000000020
[58974.260279] IP: [<ffffffff8104a0c2>] do_notify_parent+0x7a/0x1c1
[58974.260279] PGD 0
[58974.260279] Oops: 0000 [#1] SMP
[58974.260279] CPU 3
[58974.260279] Modules linked in: ipt_account ipt_MASQUERADE xt_owner
xt_hashlimit xt_multiport ipt_REJECT xt_comment xt_state iptable_filter
iptable_mangle iptable_nat nf_nat nf_conntrack_ipv4 nf_
conntrack nf_defrag_ipv4 ip_tables tg3 libphy psmouse i5k_amb hwmon e1000e
[58974.260279]
[58974.260279] Pid: 8582, comm: cron Not tainted 3.2.15-00013-g9c7edc7
#12 Supermicro X7DBR-3/X7DBR-3
[58974.260279] RIP: 0010:[<ffffffff8104a0c2>]  [<ffffffff8104a0c2>]
do_notify_parent+0x7a/0x1c1
[58974.260279] RSP: 0018:ffff8802e7173be8  EFLAGS: 00010046
[58974.260279] RAX: 0000000000000000 RBX: ffff8804157e2670 RCX:
0000000000000f5a
[58974.260279] RDX: ffff8804157e2990 RSI: 0000000000000000 RDI:
ffff8804157e2670
[58974.260279] RBP: ffff8802e7173c98 R08: 00000001005986a8 R09:
0000358d72e81768
[58974.260279] R10: 0000000002625a00 R11: ffff880327d36be8 R12:
0000000000000011
[58974.260279] R13: ffff8804150acce0 R14: ffff8804157e2670 R15:
ffff8804157e2910
[58974.260279] FS:  0000000000000000(0000) GS:ffff88042fd80000(0000)
knlGS:0000000000000000
[58974.260279] CS:  0010 DS: 002b ES: 002b CR0: 000000008005003b
[58974.260279] CR2: 0000000000000020 CR3: 0000000001a05000 CR4:
00000000000006e0
[58974.260279] DR0: 0000000000000000 DR1: 0000000000000000 DR2:
0000000000000000
[58974.260279] DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7:
0000000000000400
[58974.260279] Process cron (pid: 8582, threadinfo ffff8802e7172000,
task ffff880327d36ba0)
[58974.260279] Stack:
[58974.260279]  0000000000000011 ffffffff8102c169 ffff880200000000
ffff880327d36ba0
[58974.260279]  ffff880327d36ba0 0000000000000296 ffff8802e7173c58
ffffffff8102c7cf
[58974.260279]  0000000000000008 0000000000000296 ffff880327d36ba0
ffff880327d36ba0
[58974.260279] Call Trace:
[58974.260279]  [<ffffffff8102c169>] ? enqueue_task+0x5d/0x64
[58974.260279]  [<ffffffff8102c7cf>] ? sched_move_task+0x132/0x168
[58974.260279]  [<ffffffff8103c9e2>] do_exit+0x5a0/0x8c2
[58974.260279]  [<ffffffff81055514>] ? finish_wait+0x66/0x6e
[58974.260279]  [<ffffffff810553b2>] ? wake_up_bit+0x2a/0x2a
[58974.260279]  [<ffffffff8103cd7a>] do_group_exit+0x76/0x9e
[58974.260279]  [<ffffffff8104addb>] get_signal_to_deliver+0x552/0x573
[58974.260279]  [<ffffffff810016b1>] do_signal+0x3e/0x618
[58974.260279]  [<ffffffff810de688>] ? do_mmap_pgoff+0x287/0x2ea
[58974.260279]  [<ffffffff81001cb7>] do_notify_resume+0x2c/0x64
[58974.260279]  [<ffffffff8150a088>] int_signal+0x12/0x17
[58974.260279] Code: 00 74 04 0f 0b eb fe 48 8b 83 88 02 00 00 44 89 a5
50 ff ff ff 31 f6 c7 85 54 ff ff ff 00 00 00 00 48 89 df 48 8b 80 10 05
00 00 <48> 8b 50 20 e8 8a 7c 00 00 89 85 60 ff ff ff
48 8b 83 08 04 00
[58974.260279] RIP  [<ffffffff8104a0c2>] do_notify_parent+0x7a/0x1c1
[58974.260279]  RSP <ffff8802e7173be8>
[58974.260279] CR2: 0000000000000020
[58974.260279] ---[ end trace c1148b603ffdb861 ]---

As far as the original cause goes, I have no idea. Maybe it was an I/O
error on a swap partition (even though all RAID arrays remained
operational and kernel logs don't support this hypothesis). Also, the
machine crashed the following night with similar symptoms but without
I/O errors. Sadly, I don't have any logs from that event.

Anyway, the direct cause is task->parent->nsproxy being NULL. The
process in question is (99%+ certain) a cron worker, not the main
daemon. I guess the 0x11 on the stack is SIGCHLD, which makes a lot of
sense (cron jobs were starting and finishing around that time).

Apparently in Debian the cron worker sets the SIGCHLD handler to
SIG_DFL, so the task exit()ing kills it. This is consistent with the
stack trace above. So we'd have the master cron daemon (worker's parent)
with ->nsproxy == NULL.

However, if that was simply the case, the machine would crash whenever a
cron job ended, which definitely isn't true. So it's either a race (but
I'm lost as to what would race with what), or some other subtle effect.
FWIW, right now the cron master has this in its nsproxy file:

vback:/# cat /proc/4845/nsproxy
Proxy:	ffff8804278c7000(-)
Count:	6
uts:	ffff880427df0400(-)
ipc:	ffff880427df0600(-)
mnt:	ffff88042789e9c0(-)
pid:	ffffffff8159eeb0(I)
user:	ffff88042a0fa000(-)
net:	ffffffff81705f90(I)

The Proxy value is the same among 6 processes, including the fake
container init. Some other processes, resulting from `vserver foo
enter`, have a different Proxy, but all the separate namespaces are the
same.

The old cron master was also started during vserver boot, not e.g. via
an initscript from `vserver foo enter`.

Any ideas what could have happened or how to debug it? For the time
being I downgraded that machine to 2.6.27, which apparently is the last
kernel that works sort of reliably.

Best regards,
 Grzegorz Nosek

1.
http://list.linux-vserver.org/archive?mss:5779:201203:embicihfaemdienlcapb