ubuntu-kernel-tests

fanotify07 in LTP syscall test generates kernel trace with T/X kernel

Bug #1775165 reported by Po-Hsu Lin
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
ubuntu-kernel-tests
Confirmed
Undecided
Unassigned
linux (Ubuntu)
Fix Released
Medium
Unassigned
Trusty
Won't Fix
Medium
Unassigned
Xenial
Won't Fix
Medium
Matthew Ruffell

Bug Description

BugLink: https://bugs.launchpad.net/bugs/1775165

[Impact]

When userspace tasks which are processing fanotify permission events act
incorrectly, the fsnotify_mark_srcu SRCU is held indefinitely which causes
the whole notification subsystem to hang.

This has been seen in production, and it can also be seen when running the
Linux Test Project testsuite, specifically fanotify07.

[Fix]

Instead of holding the SRCU lock while waiting for userspace to respond,
which may never happen, or not in the order we are expecting, we drop the
fsnotify_mark_srcu SRCU lock before waiting for userspace response, and then
reacquire the lock again when userspace responds.

The fixes are from a series of upstream commits:

05f0e38724e8449184acd8fbf0473ee5a07adc6c (cherry-pick)
9385a84d7e1f658bb2d96ab798393e4b16268aaa (backport)
abc77577a669f424c5d0c185b9994f2621c52aa4 (backport)

The following are upstream commits necessary for the fixes to function:

35e481761cdc688dbee0ef552a13f49af8eba6cc (backport)
0918f1c309b86301605650c836ddd2021d311ae2 (cherry-pick)

[Testcase]

You can reproduce the problem pretty quickly with the Linux Test Project:

Steps (with root):
  1. sudo apt-get install git xfsprogs -y
  2. git clone --depth=1 https://github.com/linux-test-project/ltp.git
  3. cd ltp
  4. make autotools
  5. ./configure
  6. make; make install
  7. cd /opt/ltp
  8. echo -e "fanotify07 fanotify07 \nfanotify08 fanotify08" > /tmp/jobs
  9. ./runltp -f /tmp/jobs

On a stock Xenial kernel, the system will hang, and the testcase will look like:

<<<test_start>>>
tag=fanotify07 stime=1554326200
cmdline="fanotify07 "
contacts=""
analysis=exit
<<<test_output>>>
tst_test.c:1096: INFO: Timeout per run is 0h 05m 00s
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Test timeouted, sending SIGKILL!
Cannot kill test processes!
Congratulation, likely test hit a kernel bug.
Exitting uncleanly...
<<<execution_status>>>
initiation_status="ok"
duration=350 termination_type=exited termination_id=1 corefile=no
cutime=0 cstime=0
<<<test_end>>>

Looking at dmesg, we see the following call stack

[ 790.772792] LTP: starting fanotify07 (fanotify07 )
[ 960.140455] INFO: task fsnotify_mark:36 blocked for more than 120 seconds.
[ 960.140867] Not tainted 4.4.0-142-generic #168-Ubuntu
[ 960.141185] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 960.141498] fsnotify_mark D ffff8800b6703c98 0 36 2 0x00000000
[ 960.141516] ffff8800b6703c98 ffff88013a558a00 ffff8800b7797000 ffff8800b66f8000
[ 960.141524] ffff8800b6704000 7fffffffffffffff ffff8800b6703de0 ffff8800b66f8000
[ 960.141528] 0000000000000000 ffff8800b6703cb0 ffffffff8185cb45 ffff8800b6703de8
[ 960.141532] Call Trace:
[ 960.141580] [<ffffffff8185cb45>] schedule+0x35/0x80
[ 960.141588] [<ffffffff818600f4>] schedule_timeout+0x1b4/0x270
[ 960.141617] [<ffffffff810f57ac>] ? mod_timer+0x10c/0x240
[ 960.141621] [<ffffffff8185c60d>] ? __schedule+0x30d/0x810
[ 960.141625] [<ffffffff8185d652>] wait_for_completion+0xb2/0x190
[ 960.141636] [<ffffffff810b1f10>] ? wake_up_q+0x70/0x70
[ 960.141641] [<ffffffff810eb140>] __synchronize_srcu+0x100/0x1a0
[ 960.141645] [<ffffffff810ea400>] ? trace_raw_output_rcu_utilization+0x60/0x60
[ 960.141664] [<ffffffff81260870>] ? fsnotify_put_mark+0x40/0x40
[ 960.141669] [<ffffffff810eb204>] synchronize_srcu+0x24/0x30
[ 960.141672] [<ffffffff812608f4>] fsnotify_mark_destroy+0x84/0x130
[ 960.141680] [<ffffffff810ca000>] ? wake_atomic_t_function+0x60/0x60
[ 960.141691] [<ffffffff810a6227>] kthread+0xe7/0x100
[ 960.141694] [<ffffffff8185c601>] ? __schedule+0x301/0x810
[ 960.141699] [<ffffffff810a6140>] ? kthread_create_on_node+0x1e0/0x1e0
[ 960.141703] [<ffffffff818618e5>] ret_from_fork+0x55/0x80
[ 960.141706] [<ffffffff810a6140>] ? kthread_create_on_node+0x1e0/0x1e0

The vanilla 4.4 kernel also shows the same call stack.

On a patched kernel, the test will pass successfully, and there will be no
messages in dmesg.

[Regression Potential]

This makes modifications to how locking is performed in fsnotify / fanotify and
there may be some cause for regression. Running all fanotify Linux Test Project
tests shows that there are no extra failures caused by the patches, and instead
fewer failures are seen due to the bugfix.

Running the entire Linux Test Project testsuite actually works and runs to
completion, somewhich doesn't happen in a unpatched kernel since it will hang
on the fanotify07 test.

The patches are taken from upstream, and all necessary commits have been taken
into account, so I am happy with the potential risks and that testing has been
completed.

See original description
Revision history for this message
Po-Hsu Lin (cypressyew) wrote :
summary: - fanotify07 in LTP syscall test cause kernel oops with T kernel
+ fanotify07 in LTP syscall test generates kernel trace with T kernel
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote : Status changed to Confirmed

This change was made by a bot.

Changed in linux (Ubuntu):
status: New → Confirmed
Joseph Salisbury (jsalisbury)
Changed in linux (Ubuntu):
importance: Undecided → Medium
Changed in linux (Ubuntu Trusty):
status: New → Triaged
Changed in linux (Ubuntu):
status: Confirmed → Triaged
Changed in linux (Ubuntu Trusty):
importance: Undecided → Medium
Po-Hsu Lin (cypressyew)
summary: - fanotify07 in LTP syscall test generates kernel trace with T kernel
+ fanotify07/fanotify08 in LTP syscall test generates kernel trace with T
+ kernel
description: updated
tags: added: ppc64le
Revision history for this message
Po-Hsu Lin (cypressyew) wrote : Re: fanotify07/fanotify08 in LTP syscall test generates kernel trace with T kernel

From the comment in the test case:

 * Kernel crashes should be fixed by:
 * 96d41019e3ac "fanotify: fix list corruption in fanotify_get_response()"
 *
 * Kernel hangs should be fixed by:
 * 05f0e38724e8 "fanotify: Release SRCU lock when waiting for userspace response"

In this case, it's kernel hung, so 05f0e38724e8 should do the trick.

However, from a discussion thread [1] for debian it looks like this is difficult to backport.

[1] https://lists.debian.org/debian-kernel/2017/06/msg00170.html

Revision history for this message
Po-Hsu Lin (cypressyew) wrote :

This timeout issue could be found on X-generic / X-AWS as well.

Jun 22 06:41:26 rumford kernel: [69360.848524] INFO: task fsnotify_mark:105 blocked for more than 120 seconds.
Jun 22 06:41:26 rumford kernel: [69360.848930] Not tainted 4.4.0-130-generic #156-Ubuntu
Jun 22 06:41:26 rumford kernel: [69360.849258] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 22 06:41:26 rumford kernel: [69360.849727] fsnotify_mark D ffff8808542ebc98 0 105 2 0x00000000
Jun 22 06:41:26 rumford kernel: [69360.849734] ffff8808542ebc98 ffff88085f3972c0 ffff88085b4b5400 ffff8808542e0000
Jun 22 06:41:26 rumford kernel: [69360.849739] ffff8808542ec000 ffff8808542ebde8 ffff8808542ebde0 ffff8808542e0000
Jun 22 06:41:26 rumford kernel: [69360.849744] 0000000000000000 ffff8808542ebcb0 ffffffff8184f0e5 7fffffffffffffff
Jun 22 06:41:26 rumford kernel: [69360.849749] Call Trace:
Jun 22 06:41:26 rumford kernel: [69360.849763] [<ffffffff8184f0e5>] schedule+0x35/0x80
Jun 22 06:41:26 rumford kernel: [69360.849768] [<ffffffff81852276>] schedule_timeout+0x1b6/0x270
Jun 22 06:41:26 rumford kernel: [69360.849776] [<ffffffff810bafeb>] ? dequeue_entity+0x41b/0xa80
Jun 22 06:41:26 rumford kernel: [69360.849783] [<ffffffff81416cf5>] ? find_next_bit+0x15/0x20
Jun 22 06:41:26 rumford kernel: [69360.849791] [<ffffffff810e8812>] ? srcu_readers_seq_idx.isra.7+0x52/0x70
Jun 22 06:41:26 rumford kernel: [69360.849797] [<ffffffff8184fb43>] wait_for_completion+0xb3/0x140
Jun 22 06:41:26 rumford kernel: [69360.849805] [<ffffffff810b0140>] ? wake_up_q+0x70/0x70
Jun 22 06:41:26 rumford kernel: [69360.849810] [<ffffffff810e8cb4>] __synchronize_srcu+0xf4/0x130
Jun 22 06:41:26 rumford kernel: [69360.849815] [<ffffffff810e8070>] ? trace_raw_output_rcu_utilization+0x60/0x60
Jun 22 06:41:26 rumford kernel: [69360.849820] [<ffffffff810e8d14>] synchronize_srcu+0x24/0x30
Jun 22 06:41:26 rumford kernel: [69360.849827] [<ffffffff8125a24b>] fsnotify_mark_destroy+0x8b/0x140
Jun 22 06:41:26 rumford kernel: [69360.849835] [<ffffffff810c80b0>] ? wake_atomic_t_function+0x60/0x60
Jun 22 06:41:26 rumford kernel: [69360.849840] [<ffffffff8125a1c0>] ? fsnotify_put_mark+0x40/0x40
Jun 22 06:41:26 rumford kernel: [69360.849845] [<ffffffff810a45b7>] kthread+0xe7/0x100
Jun 22 06:41:26 rumford kernel: [69360.849850] [<ffffffff810a44d0>] ? kthread_create_on_node+0x1e0/0x1e0
Jun 22 06:41:26 rumford kernel: [69360.849855] [<ffffffff818536f5>] ret_from_fork+0x55/0x80
Jun 22 06:41:26 rumford kernel: [69360.849859] [<ffffffff810a44d0>] ? kthread_create_on_node+0x1e0/0x1e0

summary: - fanotify07/fanotify08 in LTP syscall test generates kernel trace with T
- kernel
+ fanotify07/fanotify08 in LTP syscall test generates kernel trace with
+ T/X/X-AWs kernel
summary: fanotify07/fanotify08 in LTP syscall test generates kernel trace with
- T/X/X-AWs kernel
+ T/X/X-AWS kernel
Matthew Ruffell (mruffell)
Changed in linux (Ubuntu Xenial):
importance: Undecided → Medium
status: New → In Progress
assignee: nobody → Matthew Ruffell (mruffell)
tags: added: sts
description: updated
Revision history for this message
Matthew Ruffell (mruffell) wrote : Re: fanotify07/fanotify08 in LTP syscall test generates kernel trace with T/X/X-AWS kernel

I have gone ahead and backported the fixes for xenial's 4.4 kernel.

This patch series is for ubuntu-xenial 4.4: https://paste.ubuntu.com/p/Kj43J6H3Hm/

This patch series is for vanilla upstream 4.4: https://paste.ubuntu.com/p/MzdjcHCqbz/

Both patch and compile and fix the problem.

Po-Hsu Lin (cypressyew)
tags: added: xenial
Po-Hsu Lin (cypressyew)
tags: added: ppc64el
removed: ppc64le
Revision history for this message
Po-Hsu Lin (cypressyew) wrote :

It turns out the culprit is fanotify07.

On Xenial, if you run fanotify08 after a clean reboot it will be fine.

@Matthew
Thanks for the work, do you mind submit your patches to the mailing list "<email address hidden>"? (The title of your cover-letter needs some fix)

Revision history for this message
Matthew Ruffell (mruffell) wrote :

Hi Po-Hsu Lin,

Sorry for not updating this bug earlier.

Upstream 4.4 and 4.9 are also effected by this bug, so I went and posted the
patches to be considered for upstream -stable.

Upstream 4.4 thread: [1]
Upstream 4.9 thread: [2]

Now, I got some feedback from the original author of the upstream commits that
the scenario is more complicated than I thought, and I ended up missing a lot
of commits required to fix the problem completely.

It turns out that the fixes prevent the system from crashing, but that some
data structures silently get corrupted over time, meaning the system will
eventually require a reboot anyway.

If you are interested, you can read all about it here: [3] [4] [5]

For now, it seems the list of commits required to actually fix the problem [6]
is a little too large to include in -stable, since it changes a lot of that
subsystem dramatically, and it might introduce regressions, which I want to
avoid.

In the end Greg K-H agreed with me [7], the patches were dropped, and this
won't be getting fixed upstream.

That is the status of this bug, and it likely won't be fixed. I did try, but
there is just too much code to backport and support, its easier to tell people
to use HWE kernels if they are hitting the problem.

[1] https://www.spinics.net/lists/stable/msg296857.html
[2] https://www.spinics.net/lists/stable/msg296895.html
[3] https://www.spinics.net/lists/stable/msg296992.html
[4] https://www.spinics.net/lists/stable/msg297024.html
[5] https://www.spinics.net/lists/stable/msg297027.html
[6] https://www.spinics.net/lists/stable/msg297476.html
[7] https://www.spinics.net/lists/stable/msg297485.html

Revision history for this message
Po-Hsu Lin (cypressyew) wrote :

Hi Matthew,

I think that's a valid point to mark this bug as a Won't Fix for X (which applies to T as well).

Thanks for working on this one.
I will bring this to the LTP, to see if we can skip this one with older kernels.

Changed in linux (Ubuntu Trusty):
status: Triaged → Won't Fix
Changed in linux (Ubuntu):
status: Triaged → Fix Released
Changed in linux (Ubuntu Xenial):
status: In Progress → Won't Fix
Brad Figg (brad-figg)
tags: added: cscc
Sean Feole (sfeole)
tags: added: linux-oracle oracle sru-20190722
Po-Hsu Lin (cypressyew)
summary: - fanotify07/fanotify08 in LTP syscall test generates kernel trace with
- T/X/X-AWS kernel
+ fanotify07 in LTP syscall test generates kernel trace with T/X/X-AWS
+ kernel
summary: - fanotify07 in LTP syscall test generates kernel trace with T/X/X-AWS
- kernel
+ fanotify07 in LTP syscall test generates kernel trace with T/X kernel
Revision history for this message
Po-Hsu Lin (cypressyew) wrote :

Test blacklisted for older kernels
https://kernel.ubuntu.com/git/ubuntu/autotest-client-tests.git/commit/?id=1e99a9a95ba6e99440b46b9f0911fbd63d4dc95f

Changed in ubuntu-kernel-tests:
status: New → Fix Released
assignee: nobody → Po-Hsu Lin (cypressyew)
Revision history for this message
Po-Hsu Lin (cypressyew) wrote :

As we have the ubuntu_ltp_syscalls test changed, we're no longer blacklisting this test, I will put this bug back to confirmed.

Changed in ubuntu-kernel-tests:
status: Fix Released → Confirmed
assignee: Po-Hsu Lin (cypressyew) → nobody
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.
Subscribing...

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.