zap_pid_ns_processes() might suggest that it has something to do with processes within the ARC++ container. I'm not sure exactly what a Chrome thread would do with those, but it looks like this is some cleanup happening at thread exit.

Other than that, I'd risk saying that the other warnings are just red herrings:

<6>[10806.433793] tpm_i2c_infineon 1-0020: command 0x65 (size 20) returned code 0x0

Is code 0x0 really an error? Maybe just overly verbose logging.

<3>[10822.946821] rk3288-dmc ff610000.dmc: pause cpu 1 timeout
<3>[10822.946865] rk3288-dmc ff610000.dmc: failed to change dmc freq

AFAIK the ddr freq driver needs to stop the CPUs for the time of changing the frequency and it does so waiting opportunistically until some conditions are met, otherwise times out. Some ddr freq expert should verify this, but I remember seeing these messages all around since long, long time.

<4>[ 104.089447] ------------[ cut here ]------------
<4>[ 104.089478] WARNING: CPU: 3 PID: 10806 at /mnt/host/source/src/third_party/kernel/v3.14/drivers/media/v4l2-core/videobuf2-core.c:1185 __fill_vb2_buffer+0x80/0x34c()

The V4L2 warning is:

	if (V4L2_TYPE_IS_OUTPUT(b->type)) {
		if (WARN_ON_ONCE(b->bytesused == 0)) {
			pr_warn_once("use of bytesused == 0 is deprecated and will be removed in the future,\n");
			if (vb->vb2_queue->allow_zero_bytesused)
				pr_warn_once("use VIDIOC_DECODER_CMD(V4L2_DEC_CMD_STOP) instead.\n");
			else
				pr_warn_once("use the actual size instead.\n");
		}
	}

It is just a warning about using some deprecated API feature, since Chrome didn't stop using it yet.

<1>[ 6843.300927] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x40a31c40
<1>[ 6843.300961] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x40a31c40

There is a lot of those and I remember seeing them all the time. Although I don't really know what they are caused by. Looks like a userspace process exception, though.

> <6>[10806.433793] tpm_i2c_infineon 1-0020: command 0x65 (size 20) returned code 0x0

Overly verbose logging.  One of these days I need to test better and land <https://chromium-review.googlesource.com/#/c/305044/>


> <3>[10822.946821] rk3288-dmc ff610000.dmc: pause cpu 1 timeout
> <3>[10822.946865] rk3288-dmc ff610000.dmc: failed to change dmc freq

Normal and expected.  Sometimes we don't pause CPUs in time.  If you get spammed by them it means performance will be suffering.  A lot.  ...but just seeing one or two isn't a problem.  We could possibly add the words "non fatal" to the error?


> <1>[ 6843.300927] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x40a31c40
> <1>[ 6843.300961] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x40a31c40

These have been there for years and don't seem to be a problem.  I recall digging once but I looked recently and couldn't find.  It would be nice to clean those up since it confuses people a lot.

I think

<1>[ 6843.300927] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x40a31c40
<1>[ 6843.300961] Unhandled prefetch abort: breakpoint debug exception (0x002) at 0x40a31c40

are triggered intentionally by NaCl upon process start-up and are harmless:

https://chromium.googlesource.com/native_client/src/native_client/+/master/src/trusted/platform_qualify/arch/arm/nacl_qualify_sandbox_instrs.c#65

> zap_pid_ns_processes() might suggest that it has something to do with processes within the ARC++ container

When djkurtz and I looked at this last week, that was my initial guess too.  But container teardown usually coincides with logout, and djkurtz pointed out that the breadcrumbs in the audit entries didn't seem to back up the theory that the user was logging out when these hangs were seen.

So, I added a zap_ns bucket to crcrash, since these are only warnings and we need to separate them from generic hung_tasks errors.

Per https://goto.google.com/ijmfc we can see these hangs on lots of older platforms that do not run ARC++.  The ones I looked at were all in the chrome browser process.  According to the security docs, Chrome has used PID namespaces since M44:

https://chromium.googlesource.com/chromium/src/+/master/docs/linux_sandboxing.md

Looking at a disassembly on wolf (report a9313c5700000000) we're stuck in this loop:

	for (;;) {
		set_current_state(TASK_UNINTERRUPTIBLE);
		if (pid_ns->nr_hashed == init_pids)
			break;
		schedule();
	}

Casually browsing through the crash reports I see a bunch of these hangs on 3.8/3.10, a few on 3.18, and almost none on 3.14.  This surprises me, but maybe it has more to do with the relative popularity of each platform.

I don't see anything particularly interesting in -stable for kernel/pid_namespace.c.

I think what this loop is doing is waiting until all of the other processes in the pid namespace have exited.  If this process is the thread group leader, that means waiting until its other threads have terminated.  If not, it means waiting until everything else except the current process and the thread group leader have terminated.

Some possibilities include:

1) zap_pid_ns_processes() sent SIGKILL to the other processes in the pidns, but one or more of them is stuck and refuses to terminate.

2) Maybe some sort of race or corner case involving multiple threads owned by the "init" process for the namespace.  Ricky, do you know if this is possible, or is Chrome's per-pidns PID 1 always single-threaded?

3) Other accounting mishaps, maybe pid_ns->nr_hashed not getting properly decremented somewhere.

4) Other races caused by e.g. somebody outside the namespace calling setns() to move a process into the namespace at an inopportune time, or killing PID 1 at an inopportune time.  Ricky, do you know if either is possible?

Absent a repro case, one option is to push out some instrumentation to dev channel.  e.g. if that loop gets stuck for >10 seconds, print out more details for each process in that namespace. (It shouldn't be a long list because nearly everything should have terminated by this point.)


> triggered intentionally by NaCl upon process start-up and are harmless

It would be nice to know if the hang problem always correlates with NaCl usage, as nacl_helper_linux.cc is one of two calls to ForkInNewPidNamespace() and it might implement its own reaper.

I guess those messages will only show up on ARM systems, though.

Adding a message would make a lot of sense. Also, there are a number of related upstream patches. No idea if any of those may be relevant.

d23082257d83 pid_namespace: pidns_get() should check task_active_pid_ns() != NULL
dfccbb5e49a6 wait: fix reparent_leader() vs EXIT_DEAD->EXIT_ZOMBIE race
24c037ebf572 exit: pidns: alloc_pid() leaks pid_namespace if child_reaper is exiting
819077398514 kernel/fork.c:copy_process(): don't add the uninitialized child to thread/task/pid lists
314a8ad0f18a pidns: fix free_pid() to handle the first fork failure
1adfcb03e31b pid_namespace: make freeing struct pid_namespace rcu-delayed

All but the last of those are in v3.10.104.

Adding to #4:

If a thread is waiting on a kernel mutex, and that mutex is blocked (for example due to a bad error handling in another thread which doesn't release the mutex on return), is it possible that this thread can not exit ?

Found a crash report from kevin (chromeos-4.4). Report ID is 7fbbf13f00000000. Crash log is attached. Given that, we have to assume that the problem still exists in the 4.4 kernel.

Partial crash log:

<3>[ 7680.142449] INFO: task init:3524 blocked for more than 120 seconds.
<3>[ 7680.142484]       Not tainted 4.4.21-06176-ga3a774a #1
<3>[ 7680.142503] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[ 7680.142522] init            D ffffffc000204fd8     0  3524   1385 0x00400004
<0>[ 7680.142559] Call trace:
<4>[ 7680.142592] [<ffffffc000204fd8>] __switch_to+0x9c/0xa8
<4>[ 7680.142620] [<ffffffc00090ff94>] __schedule+0x440/0x6d8
<4>[ 7680.142643] [<ffffffc0009102c0>] schedule+0x94/0xb4
<4>[ 7680.142670] [<ffffffc0002b2354>] zap_pid_ns_processes+0x140/0x1a8
<4>[ 7680.142697] [<ffffffc000222468>] do_exit+0x514/0x8f0
<4>[ 7680.142723] [<ffffffc000223978>] do_group_exit+0x50/0xb0
<4>[ 7680.142749] [<ffffffc0002239f8>] __wake_up_parent+0x0/0x3c
<4>[ 7680.142774] [<ffffffc000203e34>] el0_svc_naked+0x24/0x28
<6>[ 7680.142790]   task                        PC stack   pid father
<6>[ 7680.143245] init            D ffffffc000204fd8     0  3524   1385 0x00400004
<0>[ 7680.143282] Call trace:
<4>[ 7680.143308] [<ffffffc000204fd8>] __switch_to+0x9c/0xa8
<4>[ 7680.143332] [<ffffffc00090ff94>] __schedule+0x440/0x6d8
<4>[ 7680.143354] [<ffffffc0009102c0>] schedule+0x94/0xb4
<4>[ 7680.143379] [<ffffffc0002b2354>] zap_pid_ns_processes+0x140/0x1a8
<4>[ 7680.143404] [<ffffffc000222468>] do_exit+0x514/0x8f0
<4>[ 7680.143430] [<ffffffc000223978>] do_group_exit+0x50/0xb0
<4>[ 7680.143456] [<ffffffc0002239f8>] __wake_up_parent+0x0/0x3c
<4>[ 7680.143479] [<ffffffc000203e34>] el0_svc_naked+0x24/0x28
<0>[ 7680.143600] Kernel panic - not syncing: hung_task: blocked tasks
<4>[ 7680.143656] CPU: 3 PID: 40 Comm: khungtaskd Not tainted 4.4.21-06176-ga3a774a #1
<4>[ 7680.143674] Hardware name: Google Kevin (DT)
<0>[ 7680.143688] Call trace:
<4>[ 7680.143713] [<ffffffc0002087dc>] dump_backtrace+0x0/0x160
<4>[ 7680.143737] [<ffffffc00020895c>] show_stack+0x20/0x28
<4>[ 7680.143762] [<ffffffc0004b0ea8>] dump_stack+0x90/0xb0
<4>[ 7680.143789] [<ffffffc0002f7368>] panic+0x100/0x248
<4>[ 7680.143846] [<ffffffc0002bebb0>] watchdog+0x344/0x370
<4>[ 7680.143870] [<ffffffc00023ef3c>] kthread+0x10c/0x114
<4>[ 7680.143894] [<ffffffc000203dd0>] ret_from_fork+0x10/0x40

Deleted: upload_file_kcrash-7fbbf13f00000000.kcrash 234 KB

upload_file_kcrash-7fbbf13f00000000.kcrash 234 KB Download

There are similar issue on caroline (9523.0.0 (Official Build) dev-channel caroline test, chromeos-3.18)
https://feedback.corp.google.com/#/Report/59423512539

the repro step is simple:
1. on caroline 9523.0.0, running telemetry perf benchmark, memory stress test
  ~/chromium/src/tools/perf$ ./run_benchmark --browser=cros-chrome --remote=DUT_IP tab_switching.typical_25 --also-run-disabled-tests --tabset-repeat=5
2. about 20% chance caused a hung task timeout

partial crash log:

<3>[  480.133578] INFO: task TaskSchedulerRe:4997 blocked for more than 120 seconds.
<3>[  480.133591]       Tainted: G        W      3.18.0 #5
<3>[  480.133596] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
<6>[  480.133605] TaskSchedulerRe D ffff880173456998     0  4997   4766 0x00000102
<4>[  480.133617]  ffff880126c9bc78 0000000000000046 0000000000000000 ffff880065f31240
<4>[  480.133628]  ffff880126c9bfd8 ffff880173456460 0000000000013500 ffff880173456460
<4>[  480.133640]  ffff8800fffffff6 0000000000000002 ffff880075cf19e0 ffff880173456460
<4>[  480.133653] Call Trace:
<4>[  480.133668]  [<ffffffff8a49b572>] schedule+0x69/0x6b
<4>[  480.133677]  [<ffffffff89ed38eb>] zap_pid_ns_processes+0x133/0x16f
<4>[  480.133688]  [<ffffffff89e64faa>] do_exit+0x51f/0x964
<4>[  480.133697]  [<ffffffff89e662b5>] do_group_exit+0x43/0xb1
<4>[  480.133706]  [<ffffffff89e7056d>] get_signal+0x573/0x5a5
<4>[  480.133715]  [<ffffffff89e02005>] do_signal+0x37/0x5f8
<4>[  480.133723]  [<ffffffff89ebfd21>] ? do_futex+0xc6/0x7de
<4>[  480.133732]  [<ffffffff89edf567>] ? __seccomp_phase1_filter+0x2f/0x1bc
<4>[  480.133742]  [<ffffffff89e025f2>] do_notify_resume+0x2c/0x61
<4>[  480.133750]  [<ffffffff8a49eb13>] int_signal+0x12/0x17

The report references in #10 has a number of threads (6 if I count correctly) trying to open files and waiting on IO, plus a pending page fault, also waiting for IO to complete. All of those seem to be stuck waiting for the mmc, which in turn seems to be stuck waiting for power. As such, the behavior is a bit different than originally observed, and appears to be related to an IO failure.

#10 may be different issue. I will create a new bug for #10

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/b2761fab16c8da01de42f0d34f46ee6ed4eeca91

commit b2761fab16c8da01de42f0d34f46ee6ed4eeca91
Author: Guenter Roeck <groeck@chromium.org>
Date: Thu May 11 08:58:54 2017

CHROMIUM: pid_namespace: Really print hung tasks after 10 seconds

schedule() doesn't return unless there is an event waking up an affected
task. If there is no event, nothing will happen. This is especially true
if the children we are waiting for to die are stuck.

Solve the problem by using schedule_timeout() and waking up every 10
seconds.

BUG= chromium:660628 
TEST=Build and run; ensure that no messages are seen during normal operation

Change-Id: I4603143775d76cadae112f3356ff151f4e86042c
Signed-off-by: Guenter Roeck <groeck@chromium.org>
Reviewed-on: https://chromium-review.googlesource.com/502073
Reviewed-by: Douglas Anderson <dianders@chromium.org>

[modify] https://crrev.com/b2761fab16c8da01de42f0d34f46ee6ed4eeca91/kernel/pid_namespace.c

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/8d3c47f143459e41cb73ce3b5dbb73f622e8e099

commit 8d3c47f143459e41cb73ce3b5dbb73f622e8e099
Author: Eric W. Biederman <ebiederm@xmission.com>
Date: Sat May 13 01:46:17 2017

FROMLIST: pid_ns: Sleep in TASK_INTERRUPTIBLE in zap_pid_ns_processes

The code can potentially sleep for an indefinite amount of time in
zap_pid_ns_processes triggering the hung task timeout, and increasing
the system average.  This is undesirable.  Sleep with a task state of
TASK_INTERRUPTIBLE instead of TASK_UNINTERRUPTIBLE to remove these
undesirable side effects.

Apparently under heavy load this has been allowing Chrome to trigger
the hung time task timeout error and cause ChromeOS to reboot.

BUG= chromium:721298   chromium:660628 
TEST=Run test application attached to chromium:721298

Change-Id: I80547dfae36ff1db3a4a508838e50a85efa981ca
Reported-by: Vovo Yang <vovoy@google.com>
Reported-by: Guenter Roeck <linux@roeck-us.net>
Fixes: 6347e9009104 ("pidns: guarantee that the pidns init will be the last pidns process reaped")
Cc: stable@vger.kernel.org
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Guenter Roeck <groeck@chromium.org>
(am from https://patchwork.kernel.org/patch/9724743/)
Reviewed-on: https://chromium-review.googlesource.com/505193

[modify] https://crrev.com/8d3c47f143459e41cb73ce3b5dbb73f622e8e099/kernel/pid_namespace.c

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/0af594bde2f90bbe6a738643c84af07aee190937

commit 0af594bde2f90bbe6a738643c84af07aee190937
Author: Eric W. Biederman <ebiederm@xmission.com>
Date: Sat May 13 01:46:16 2017

FROMLIST: pid_ns: Sleep in TASK_INTERRUPTIBLE in zap_pid_ns_processes

The code can potentially sleep for an indefinite amount of time in
zap_pid_ns_processes triggering the hung task timeout, and increasing
the system average.  This is undesirable.  Sleep with a task state of
TASK_INTERRUPTIBLE instead of TASK_UNINTERRUPTIBLE to remove these
undesirable side effects.

Apparently under heavy load this has been allowing Chrome to trigger
the hung time task timeout error and cause ChromeOS to reboot.

BUG= chromium:721298   chromium:660628 
TEST=Run test application attached to chromium:721298

Change-Id: I80547dfae36ff1db3a4a508838e50a85efa981ca
Reported-by: Vovo Yang <vovoy@google.com>
Reported-by: Guenter Roeck <linux@roeck-us.net>
Fixes: 6347e9009104 ("pidns: guarantee that the pidns init will be the last pidns process reaped")
Cc: stable@vger.kernel.org
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Guenter Roeck <groeck@chromium.org>
(am from https://patchwork.kernel.org/patch/9724743/)
Reviewed-on: https://chromium-review.googlesource.com/505194

[modify] https://crrev.com/0af594bde2f90bbe6a738643c84af07aee190937/kernel/pid_namespace.c

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/ff5ffb70d281fa7addd2ee2de6d6fa8c7c4f6747

commit ff5ffb70d281fa7addd2ee2de6d6fa8c7c4f6747
Author: Eric W. Biederman <ebiederm@xmission.com>
Date: Sat May 13 05:49:03 2017

FROMLIST: pid_ns: Sleep in TASK_INTERRUPTIBLE in zap_pid_ns_processes

The code can potentially sleep for an indefinite amount of time in
zap_pid_ns_processes triggering the hung task timeout, and increasing
the system average.  This is undesirable.  Sleep with a task state of
TASK_INTERRUPTIBLE instead of TASK_UNINTERRUPTIBLE to remove these
undesirable side effects.

Apparently under heavy load this has been allowing Chrome to trigger
the hung time task timeout error and cause ChromeOS to reboot.

BUG= chromium:721298   chromium:660628 
TEST=Run test application attached to chromium:721298

Change-Id: I80547dfae36ff1db3a4a508838e50a85efa981ca
Reported-by: Vovo Yang <vovoy@google.com>
Reported-by: Guenter Roeck <linux@roeck-us.net>
Fixes: 6347e9009104 ("pidns: guarantee that the pidns init will be the last pidns process reaped")
Cc: stable@vger.kernel.org
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Guenter Roeck <groeck@chromium.org>
(am from https://patchwork.kernel.org/patch/9724743/)
Reviewed-on: https://chromium-review.googlesource.com/505149
Reviewed-by: Douglas Anderson <dianders@chromium.org>

[modify] https://crrev.com/ff5ffb70d281fa7addd2ee2de6d6fa8c7c4f6747/kernel/pid_namespace.c

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/9497031b53a70b69526a4c276a3974f901e1cce1

commit 9497031b53a70b69526a4c276a3974f901e1cce1
Author: Eric W. Biederman <ebiederm@xmission.com>
Date: Sat May 13 08:04:44 2017

FROMLIST: pid_ns: Sleep in TASK_INTERRUPTIBLE in zap_pid_ns_processes

The code can potentially sleep for an indefinite amount of time in
zap_pid_ns_processes triggering the hung task timeout, and increasing
the system average.  This is undesirable.  Sleep with a task state of
TASK_INTERRUPTIBLE instead of TASK_UNINTERRUPTIBLE to remove these
undesirable side effects.

Apparently under heavy load this has been allowing Chrome to trigger
the hung time task timeout error and cause ChromeOS to reboot.

BUG= chromium:721298   chromium:660628 
TEST=Run test application attached to chromium:721298

Change-Id: I80547dfae36ff1db3a4a508838e50a85efa981ca
Reported-by: Vovo Yang <vovoy@google.com>
Reported-by: Guenter Roeck <linux@roeck-us.net>
Fixes: 6347e9009104 ("pidns: guarantee that the pidns init will be the last pidns process reaped")
Cc: stable@vger.kernel.org
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Guenter Roeck <groeck@chromium.org>
(am from https://patchwork.kernel.org/patch/9724743/)
Reviewed-on: https://chromium-review.googlesource.com/505706

[modify] https://crrev.com/9497031b53a70b69526a4c276a3974f901e1cce1/kernel/pid_namespace.c

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/kernel/+/10f175e80cdb29c2c7549fb9dbef4bd06c9db517

commit 10f175e80cdb29c2c7549fb9dbef4bd06c9db517
Author: Eric W. Biederman <ebiederm@xmission.com>
Date: Sat May 13 08:04:45 2017

FROMLIST: pid_ns: Sleep in TASK_INTERRUPTIBLE in zap_pid_ns_processes

The code can potentially sleep for an indefinite amount of time in
zap_pid_ns_processes triggering the hung task timeout, and increasing
the system average.  This is undesirable.  Sleep with a task state of
TASK_INTERRUPTIBLE instead of TASK_UNINTERRUPTIBLE to remove these
undesirable side effects.

Apparently under heavy load this has been allowing Chrome to trigger
the hung time task timeout error and cause ChromeOS to reboot.

BUG= chromium:721298   chromium:660628 
TEST=Run test application attached to chromium:721298

Change-Id: I80547dfae36ff1db3a4a508838e50a85efa981ca
Reported-by: Vovo Yang <vovoy@google.com>
Reported-by: Guenter Roeck <linux@roeck-us.net>
Fixes: 6347e9009104 ("pidns: guarantee that the pidns init will be the last pidns process reaped")
Cc: stable@vger.kernel.org
Signed-off-by: "Eric W. Biederman" <ebiederm@xmission.com>
Signed-off-by: Guenter Roeck <groeck@chromium.org>
(am from https://patchwork.kernel.org/patch/9724743/)
Reviewed-on: https://chromium-review.googlesource.com/505727

[modify] https://crrev.com/10f175e80cdb29c2c7549fb9dbef4bd06c9db517/kernel/pid_namespace.c

The applied patch ensures that processes are no longer stuck in "D" state. Instead, they will be reported to be in "S" state, and not result in hung task reports.
Underlying problem is that the affected processes are not reaped by the parent process. Without PID namespace, the processes will end up as zombies. There is ongoing upstream discussion if there is a remedy in the kernel, but that will only result in processes in Zombie instead of Sleep state. Underlying problem appears to be that userspace does not reap all its children.

Verified in Chrome OS 9756.0.0, 61.0.3159.0.