blocked tasks delay cloud-init for 240 seconds

[Scott Moser]

Binary package hint: cloud-init

Running tests for lucid rc, I came across one system that was not accessible via ssh.

The console collected after waiting ended like:
| [ 1.036270] Freeing unused kernel memory: 216k freed
| [ 1.037531] Write protecting the kernel text: 4288k
| [ 1.037892] Write protecting the kernel read-only data: 1324k
| init: console-setup main process (62) terminated with status 1
| %G

Because this was an ebs root instance, a shutdown was run, and console collected after that. I will attach that full console log. The interesting subsequent output was:

| %G[ 240.805451] INFO: task apparmor_parser:182 blocked for more than 120 seconds.
| [ 240.805466] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
| [ 240.805581] INFO: task mount:209 blocked for more than 120 seconds.
| [ 240.805587] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
| [ 240.805683] INFO: task flush-8:1:232 blocked for more than 120 seconds.
| [ 240.805689] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
| init: plymouth main process (44) killed by SEGV signal^M^M
| init: plymouth-splash main process (215) terminated with status 2^M^M
| Generating locales...^M
| en_GB.UTF-8... done^M
| Generation complete.^M

It appears that something apparmor related blocked for 240 seconds, which ran past my time alloted for boot and ssh connection. The system *did* come up, but in a much longer time frame than normal.

instance info:
 region: eu-west-1
 ami: ami-8f705afb
 instance-type: m1.small
 arch: i386
 build: 20100420
 root-store: ebs

[Scott Moser (smoser)]

Just realized that apparmor was only the first of 3 tasks to block for more than 120 seconds . Note also: mount, flush-8 also did. this likely not apparmor related.

[Scott Moser (smoser)]

I saw this again during lucid release testing (ami-594d672d - x86_64 - eu-west-1 20100427.1). In this failed log I also saw:

udevd[87]: worker [98] unexpectedly returned with status 0x0100^M
^M^M
udevd[87]: worker [98] failed while handling '/devices/xen/vbd-2064/block/sdb'

[s.fussenegger (stf+ubuntu-launchpad)]

I came across a similar boot problem on EC2. The only difference being that my instance didn't come up at all. All I did was starting a fresh 32-bit Lucid instance from Alestic (ami-cf4d67bb, eu-west-1). I've installed mysql and configured it to put its data and logs on a EBS volume. I've included these paths in /etc/apparmor.d/usr.sbin.mysqld

[Gerry Reno (greno-verizon)]

Had this happen on a regular lucid S3 instance today:

[ 0.944176] NET: Registered protocol family 17
[ 0.944293] registered taskstats version 1
[ 1.046692] /build/buildd/linux-ec2-2.6.32/drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
[ 1.149594] kjournald starting. Commit interval 5 seconds
[ 1.149592] EXT3-fs: mounted filesystem with writeback data mode.
[ 1.149603] VFS: Mounted root (ext3 filesystem) readonly on device 8:1.
[ 1.207051] devtmpfs: mounted
[ 1.207160] Freeing unused kernel memory: 228k freed
[ 1.207281] Write protecting the kernel read-only data: 6416k
init: console-setup main process (79) terminated with status 1
%Gmountall: Disconnected from Plymouth
init: plymouth main process (61) killed by SEGV signal
init: plymouth-splash main process (256) terminated with status 2

[Scott Moser (smoser)]

This is not related to cloud-init.

[Po-Hsu Lin (cypressyew)]

Closing this bug with Won't fix as this kernel / release is no longer supported.
Please feel free to open a new bug report if you're still experiencing this on a newer release (Bionic 18.04.3 / Disco 19.04)
Thanks!