[Ubuntu][Bionic] systemd caused kernel to hang on fsnotify wait-on-completion

Bug #1872021 reported by Laurent Sesquès
20
This bug affects 2 people
Affects Status Importance Assigned to Milestone
MAAS
Invalid
Undecided
Unassigned
linux (Ubuntu)
Expired
Undecided
Unassigned
Bionic
Expired
Medium
Unassigned
Eoan
Won't Fix
Undecided
Unassigned
Focal
Expired
Undecided
Unassigned

Bug Description

This is with MAAS 2.7.0, commissioning an HP DL385 G7 with Bionic.
During the first boot, the machine performs an apt-get upgrade, which includes an update of ipmitool (1.8.18-5ubuntu0.1) and freeipmi-tools (1.4.11-1.1ubuntu4.1).
This triggers hung tasks:
[ 66.457048] cloud-init[1534]: Setting up ipmitool (1.8.18-5ubuntu0.1) ...
         Starting IPMI event daemon...
[ OK ] Started IPMI event daemon.
[ 67.240857] cloud-init[1534]: Setting up freeipmi-tools (1.4.11-1.1ubuntu4.1) ...
[ 67.254241] cloud-init[1534]: Processing triggers for systemd (237-3ubuntu10.39) ...
[ 242.642684] INFO: task systemd:1 blocked for more than 120 seconds.
[ 242.725654] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 242.799835] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 242.906319] INFO: task kworker/u49:0:6 blocked for more than 120 seconds.
[ 242.997214] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 243.072024] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 247.381896] cloud-init[1534]: Failed to reload daemon: Connection timed out
[ 247.385109] cloud-init[1534]: Processing triggers for man-db (2.8.3-2ubuntu0.1) ...
[ 249.828279] cloud-init[1534]: Processing triggers for ureadahead (0.100.0-21) ...
[ 249.874840] cloud-init[1534]: Processing triggers for install-info (6.5.0.dfsg.1-2) ...
[ 250.160889] cloud-init[1534]: Processing triggers for libc-bin (2.27-3ubuntu1) ...
[ 363.465849] INFO: task systemd:1 blocked for more than 120 seconds.
[ 363.550072] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 363.623823] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 363.728949] INFO: task kworker/u49:0:6 blocked for more than 120 seconds.
[ 363.820481] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 363.894774] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 484.291609] INFO: task systemd:1 blocked for more than 120 seconds.
[ 484.381026] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 484.458451] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 484.568130] INFO: task kworker/u49:0:6 blocked for more than 120 seconds.
[ 484.661642] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 484.740371] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 484.850615] INFO: task udevadm:2665 blocked for more than 120 seconds.
[ 484.942379] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 485.018318] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 607.165768] INFO: task systemd:1 blocked for more than 120 seconds.
[ 607.250976] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 607.325651] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 607.432497] INFO: task kworker/u49:0:6 blocked for more than 120 seconds.
[ 607.525757] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 607.599770] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 607.707273] INFO: task udevadm:2665 blocked for more than 120 seconds.
[ 607.795467] Not tainted 4.15.0-96-generic #97-Ubuntu
[ 607.869751] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

I can perform more tests on this system if needed.

Tags: bionic
Revision history for this message
Lee Trager (ltrager) wrote :

Can you try using the hwe-18.04-edge kernel?

https://maas.io/docs/ubuntu-kernels

Changed in maas:
status: New → Incomplete
Revision history for this message
Laurent Sesquès (sajoupa) wrote :

Hi,

It still gives the same behavior.
I ssh'd into the machine and syslog shows the following:

Apr 10 09:00:34 machine-name kernel: [ 78.597093] x86/PAT: ipmi-locate:2583 map pfn expected mapping type uncached-minus for [mem 0xbde1d000-0xbde1dfff], got write-back
Apr 10 09:00:34 machine-name kernel: [ 78.758144] x86/PAT: ipmi-locate:2583 map pfn expected mapping type uncached-minus for [mem 0xbde1c000-0xbde1cfff], got write-back
Apr 10 09:01:08 machine-name systemd[1]: Starting Stop ureadahead data collection...
Apr 10 09:01:08 machine-name systemd[1]: Stopping Read required files in advance...
Apr 10 09:01:08 machine-name systemd[1]: Started Stop ureadahead data collection.
Apr 10 09:01:25 machine-name kernel: [ 129.353796] INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 10 09:01:25 machine-name kernel: [ 129.429260] 0-...!: (0 ticks this GP) idle=c18/0/0 softirq=2098/2098 fqs=0
Apr 10 09:01:25 machine-name kernel: [ 129.524289] (detected by 6, t=15044 jiffies, g=1622, c=1621, q=11120)
Apr 10 09:01:25 machine-name kernel: [ 129.613039] Sending NMI from CPU 6 to CPUs 0:
Apr 10 09:01:25 machine-name kernel: [ 129.613089] NMI backtrace for cpu 0 skipped: idling at native_safe_halt+0x12/0x20
Apr 10 09:01:25 machine-name kernel: [ 129.614057] rcu_sched kthread starved for 15067 jiffies! g1622 c1621 f0x0 RCU_GP_WAIT_FQS(3) ->state=0x402 ->cpu=0
Apr 10 09:01:25 machine-name kernel: [ 129.755325] rcu_sched I 0 9 2 0x80000000
Apr 10 09:01:25 machine-name kernel: [ 129.755332] Call Trace:
Apr 10 09:01:25 machine-name kernel: [ 129.755350] __schedule+0x24e/0x880
Apr 10 09:01:25 machine-name kernel: [ 129.755357] ? __switch_to_asm+0x41/0x70
Apr 10 09:01:25 machine-name kernel: [ 129.755363] schedule+0x2c/0x80
Apr 10 09:01:25 machine-name kernel: [ 129.755368] schedule_timeout+0x15d/0x350
Apr 10 09:01:25 machine-name kernel: [ 129.755375] ? __next_timer_interrupt+0xe0/0xe0
Apr 10 09:01:25 machine-name kernel: [ 129.755382] rcu_gp_kthread+0x53a/0x980
Apr 10 09:01:25 machine-name kernel: [ 129.755390] kthread+0x121/0x140
Apr 10 09:01:25 machine-name kernel: [ 129.755394] ? rcu_note_context_switch+0x150/0x150
Apr 10 09:01:25 machine-name kernel: [ 129.755399] ? kthread_create_worker_on_cpu+0x70/0x70
Apr 10 09:01:25 machine-name kernel: [ 129.755404] ret_from_fork+0x22/0x40

Changed in maas:
status: Incomplete → New
Revision history for this message
Christian Ehrhardt  (paelzer) wrote :

@maas team can the hang in impitool be isolated somehow for debugging?

Changed in ipmitool (Ubuntu):
status: New → Incomplete
Revision history for this message
Lee Trager (ltrager) wrote :

MAAS instructs cloud-init to install ipmitool during commissioning. If you select "Skip configuring supported BMC controllers with a MAAS generated username and password" and "Allow SSH access and prevent machine powering off" ipmitool won't be installed and the machine will be left on after commissioning/testing to allow for debug. You can also boot into rescue mode on a failed host.

Changed in ipmitool (Ubuntu):
status: Incomplete → New
Alberto Donato (ack)
Changed in maas:
milestone: none → 2.8.0b2
milestone: 2.8.0b2 → none
Revision history for this message
Laurent Sesquès (sajoupa) wrote :

Thanks, I could commission and deploy the machine after disabling the BMC configuration step.
After the machine booted, I manually installed impitool and ran 'ipmitool lan print' successfully.

After that, I released the machine, and commissioned again with the options "Skip configuring supported BMC controllers with a MAAS generated username and password" and "Allow SSH access and prevent machine powering off".
I ssh'ed into the machine, and ran 'apt-get install ipmitools'.
The command hanged for 2 minutes, and then finally finished: https://pastebin.canonical.com/p/n2YFPFt5nY/
I opened another SSH session, which took ~30s to open, and took the output from dmesg:
https://pastebin.canonical.com/p/PkQXCy4gP4/

This was using the following config:
$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 18.04.4 LTS
Release: 18.04
Codename: bionic
$ uname -r
4.15.0-96-generic

The machine is still in this state and I can perform more tests.

Revision history for this message
Laurent Sesquès (sajoupa) wrote :

Just re-deployed the machine to check that it worked with the same kernel, and it does:
$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description: Ubuntu 18.04.4 LTS
Release: 18.04
Codename: bionic
$ uname -r
4.15.0-96-generic

Revision history for this message
Rafael David Tinoco (rafaeldtinoco) wrote :

Summary...

For Ubuntu Bionic, dpkg triggers for systemd (237-3ubuntu10.39) might have caused systemd to hang:

[ 363.776878] wait_for_completion+0xba/0x140
[ 363.776890] __flush_work+0x15b/0x210
[ 363.776901] flush_delayed_work+0x41/0x50
[ 363.776908] fsnotify_wait_marks_destroyed+0x15/0x20
[ 363.776912] fsnotify_destroy_group+0x48/0xd0
[ 363.776917] inotify_release+0x1e/0x50
[ 363.776923] __fput+0xea/0x220
[ 363.776929] ____fput+0xe/0x10
[ 363.776935] task_work_run+0x9d/0xc0
[ 363.776942] exit_to_usermode_loop+0xc0/0xd0
[ 363.776947] do_syscall_64+0x121/0x130
[ 363.776954] entry_SYSCALL_64_after_hwframe+0x3d/0xa2

and

[ 364.050206] wait_for_completion+0xba/0x140
[ 364.050238] __synchronize_srcu.part.13+0x85/0xb0
[ 364.050248] synchronize_srcu+0x66/0xe0
[ 364.050256] fsnotify_mark_destroy_workfn+0x7b/0xe0
[ 364.050262] process_one_work+0x1de/0x420
[ 364.050267] worker_thread+0x228/0x410
[ 364.050272] kthread+0x121/0x140

and

[ 364.326985] wait_for_completion+0xba/0x140
[ 364.326988] __synchronize_srcu.part.13+0x85/0xb0
[ 364.326993] synchronize_srcu+0x66/0xe0
[ 364.326995] ? synchronize_srcu+0x66/0xe0
[ 364.326996] fsnotify_connector_destroy_workfn+0x4a/0x80
[ 364.326998] process_one_work+0x1de/0x420
[ 364.326999] worker_thread+0x253/0x410
[ 364.327001] kthread+0x121/0x140

All stack traces seem to come from "fsnotify" subsystem and waiting on delayed work (completion) for fsnotify marks destruction after a inotify_release() was called. Completion did not happen for the past 2 minutes. Without a kernel dump it is hard to tell if completion was still ok - due to kthread being overloaded doing scheduled work and/or the marks group destruction - or there was a dead lock for the completion due to a kernel bug.

If this is reproducible, I think that having a kernel dump would help identifying the issue. I'm letting the kernel team to handle this and marking all other issues as dealt per previous comments.

no longer affects: ipmitool (Ubuntu)
Changed in maas:
status: New → Invalid
summary: - commissioning fails due to hung tasks setting up ipmitool
+ [Ubuntu][Bionic] systemd caused kernel to hang on fsnotify wait-on-
+ completion
no longer affects: linux (Ubuntu)
affects: linux → linux (Ubuntu)
Changed in linux (Ubuntu Bionic):
status: New → Triaged
importance: Undecided → Medium
Revision history for this message
Ubuntu Kernel Bot (ubuntu-kernel-bot) wrote : Missing required logs.

This bug is missing log files that will aid in diagnosing the problem. While running an Ubuntu kernel (not a mainline or third-party kernel) please enter the following command in a terminal window:

apport-collect 1872021

and then change the status of the bug to 'Confirmed'.

If, due to the nature of the issue you have encountered, you are unable to run this command, please add a comment stating that fact and change the bug status to 'Confirmed'.

This change has been made by an automated script, maintained by the Ubuntu Kernel Team.

Changed in linux (Ubuntu):
status: New → Incomplete
Changed in linux (Ubuntu Eoan):
status: New → Incomplete
tags: added: bionic
Revision history for this message
Brian Murray (brian-murray) wrote :

The Eoan Ermine has reached end of life, so this bug will not be fixed for that release

Changed in linux (Ubuntu Eoan):
status: Incomplete → Won't Fix
Revision history for this message
Mauricio Faria de Oliveira (mfo) wrote :

For documentation purposes,
(after working on items related to bug 1802021 / 1872021 / this bug)

The stack traces in this issue would suggest a duplicate of bug 1802021, fixed in kernel 4.15.0-47.50, but this happens in 4.15.0-96, which has that fix.

So, looking at comments #5 and #6, the issue seems particular to the MAAS deploy boot/environment, as it doesn't happen on the deployed system with the same kernel (i.e., same system and kernel, different boot/environment), even when running similar commands.

As such, this issue doesn't seem to be that kernel bug, but a manifestation with similar symptoms at the kernel level, due to what seems to be an underlying system/platform issue.

Supporting 'evidence' seems to be the lack of additional comments on those bugs after Fix Released, and later on this bug, perhaps due to some system/firmware upgrade, for example.

Changed in linux (Ubuntu Bionic):
status: Triaged → Incomplete
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for linux (Ubuntu Bionic) because there has been no activity for 60 days.]

Changed in linux (Ubuntu Bionic):
status: Incomplete → Expired
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for linux (Ubuntu Focal) because there has been no activity for 60 days.]

Changed in linux (Ubuntu Focal):
status: Incomplete → Expired
Revision history for this message
Launchpad Janitor (janitor) wrote :

[Expired for linux (Ubuntu) because there has been no activity for 60 days.]

Changed in linux (Ubuntu):
status: Incomplete → Expired
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

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