update-grub (grub-probe) during package installation on Cisco UCS B260 servers - Precise deployment fails with hwe-t kernel

[Larry Michel]

In bug 1437475, deploying Precise with maas was failing with curtin error with generic ephemeral image.

With hwe-t kernel it gets passed the curtin error.. However, grub looks to be stuck. Looking at the diff for install log minutes apart right before deployment gets marked as failed by maas, it looks to be retrying the last step:

Last lines of curtin install log:
===========================================================================
Unpacking linux-generic-lts-trusty (from .../linux-generic-lts-trusty_3.13.0.52.45_amd64.deb) ...
Setting up linux-image-3.13.0-52-generic (3.13.0-52.86~precise1) ...
Running depmod.
update-initramfs: deferring update (hook will be called later)
Examining /etc/kernel/postinst.d.
run-parts: executing /etc/kernel/postinst.d/apt-auto-removal 3.13.0-52-generic /boot/vmlinuz-3.13.0-52-generic
run-parts: executing /etc/kernel/postinst.d/initramfs-tools 3.13.0-52-generic /boot/vmlinuz-3.13.0-52-generic
update-initramfs: Generating /boot/initrd.img-3.13.0-52-generic
df: Warning: cannot read table of mounted file systems: No such file or directory
run-parts: executing /etc/kernel/postinst.d/update-notifier 3.13.0-52-generic /boot/vmlinuz-3.13.0-52-generic
run-parts: executing /etc/kernel/postinst.d/x-grub-legacy-ec2 3.13.0-52-generic /boot/vmlinuz-3.13.0-52-generic
Searching for GRUB installation directory ... found: /boot/grub
Searching for default file ... found: /boot/grub/default
Testing for an existing GRUB menu.lst file ... found: /boot/grub/menu.lst
Searching for splash image ... none found, skipping ...
Ignoring non-Xen Kernel on Xen domU host: vmlinuz-3.2.0-80-generic
Found kernel: /boot/vmlinuz-3.13.0-52-generic
Found kernel: /boot/memtest86+.bin
Updating /boot/grub/menu.lst ... done

run-parts: executing /etc/kernel/postinst.d/zz-update-grub 3.13.0-52-generic /boot/vmlinuz-3.13.0-52-generic
Generating grub.cfg ...
Found linux image: /boot/vmlinuz-3.13.0-52-generic
Found initrd image: /boot/initrd.img-3.13.0-52-generic
Found linux image: /boot/vmlinuz-3.2.0-80-generic
Found initrd image: /boot/initrd.img-3.2.0-80-generic
Found memtest86+ image: /boot/memtest86+.bin
done
Setting up linux-image-generic-lts-trusty (3.13.0.52.45) ...
Setting up linux-headers-3.13.0-52 (3.13.0-52.86~precise1) ...
Setting up linux-headers-3.13.0-52-generic (3.13.0-52.86~precise1) ...
Setting up linux-headers-generic-lts-trusty (3.13.0.52.45) ...
Setting up linux-generic-lts-trusty (3.13.0.52.45) ...
Leaving 'diversion of /etc/init/ureadahead.conf to /etc/init/ureadahead.conf.disabled by cloud-init'
8192+0 records in
8192+0 records out
8589934592 bytes (8.6 GB) copied, 6.10194 s, 1.4 GB/s
Setting up swapspace version 1, size = 8388604 KiB
no label, UUID=56f58ad7-bd54-4c17-be2f-893d3c70cd7e
Generating grub.cfg ...
Found linux image: /boot/vmlinuz-3.13.0-52-generic
Found initrd image: /boot/initrd.img-3.13.0-52-generic
Found linux image: /boot/vmlinuz-3.2.0-80-generic
Found initrd image: /boot/initrd.img-3.2.0-80-generic
Found memtest86+ image: /boot/memtest86+.bin
done
Generating grub.cfg ...
Found linux image: /boot/vmlinuz-3.13.0-52-generic
Found initrd image: /boot/initrd.img-3.13.0-52-generic
===========================================================================

Diff output:
===========================================================================
ubuntu@pullman-01:~$ diff install.log var/log/curtin/install.log
219,221d218
< Generating grub.cfg ...
< Found linux image: /boot/vmlinuz-3.13.0-52-generic
< Found initrd image: /boot/initrd.img-3.13.0-52-generic
ubuntu@pullman-01:~$
===========================================================================

I am attaching some logs I collected including content of /var/log

[Larry Michel (lmic)]

Using the same cisco system, I deployed trusty. I then installed a package and installation of the package around the same location. I then found that it was hanging in grub-probe. I kill that process a couple of times and the installation proceeded and completed afterwards. The Killed message showed that it was the right grub-probe process that I killed.

================================================================================
ubuntu@pullman-01:~$ ps -ef|grep grub
root 48137 48120 0 20:09 pts/2 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 48436 48137 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48447 48436 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48448 48447 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48455 48448 30 20:22 pts/2 00:00:13 /usr/sbin/grub-probe --device /dev/sda1 --target=partmap
ubuntu 48742 48643 0 20:23 pts/4 00:00:00 grep --color=auto grub
ubuntu@pullman-01:~$ sudo kill -9 48455
kill: No such process
ubuntu@pullman-01:~$ ps -ef|grep grub
root 48137 48120 0 20:09 pts/2 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 48436 48137 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48447 48436 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48448 48447 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48747 48448 22 20:24 pts/2 00:00:04 /usr/sbin/grub-probe --device /dev/sda1 --target=drive
ubuntu 48751 48643 0 20:24 pts/4 00:00:00 grep --color=auto grub
ubuntu@pullman-01:~$ ps -ef|grep grub
root 48137 48120 0 20:09 pts/2 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 48436 48137 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48447 48436 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48448 48447 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48747 48448 29 20:24 pts/2 00:00:06 /usr/sbin/grub-probe --device /dev/sda1 --target=drive
ubuntu 48753 48643 0 20:24 pts/4 00:00:00 grep --color=auto grub
ubuntu@pullman-01:~$ ps -ef|grep grub
root 48137 48120 0 20:09 pts/2 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 48436 48137 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48447 48436 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48448 48447 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48747 48448 32 20:24 pts/2 00:00:10 /usr/sbin/grub-probe --device /dev/sda1 --target=drive
ubuntu 48756 48643 0 20:24 pts/4 00:00:00 grep --color=auto grub
ubuntu@pullman-01:~$ sudo kill -9 48747
ubuntu@pullman-01:~$ ps -ef|grep grub
root 48137 48120 0 20:09 pts/2 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 48436 48137 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48447 48436 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48448 48447 0 20:21 pts/2 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 48759 48448 18 2...

[Larry Michel (lmic)]

correction: installation of the package around the same location --> installation of the package stalled at around the same location

[Steve Langasek (vorlon)]

A couple of things that you might want to check on the affected system:

 - can you edit /etc/grub.d/20_memtest86+ to include 'set -x' as the second line, and capture the output of running 'sudo /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg'?
 - can you test whether this problem exists when installing the current wily?

[Larry Michel (lmic)]

I am trying the set -x step. We don't have 15.10 images on our maas servers, but I will look to see whether we can get it on there.

[Larry Michel (lmic)]

This is the output and looks to be stuck for some time on the last line:

update-initramfs: deferring update (hook will be called later)
Examining /etc/kernel/postinst.d.
run-parts: executing /etc/kernel/postinst.d/apt-auto-removal 3.13.0-55-generic /boot/vmlinuz-3.13.0-55-generic
run-parts: executing /etc/kernel/postinst.d/initramfs-tools 3.13.0-55-generic /boot/vmlinuz-3.13.0-55-generic
update-initramfs: Generating /boot/initrd.img-3.13.0-55-generic
df: Warning: cannot read table of mounted file systems: No such file or directory
run-parts: executing /etc/kernel/postinst.d/update-notifier 3.13.0-55-generic /boot/vmlinuz-3.13.0-55-generic
run-parts: executing /etc/kernel/postinst.d/x-grub-legacy-ec2 3.13.0-55-generic /boot/vmlinuz-3.13.0-55-generic
Searching for GRUB installation directory ... found: /boot/grub
Searching for default file ... found: /boot/grub/default
Testing for an existing GRUB menu.lst file ... found: /boot/grub/menu.lst
Searching for splash image ... none found, skipping ...
Ignoring non-Xen Kernel on Xen domU host: vmlinuz-3.2.0-80-generic
Found kernel: /boot/vmlinuz-3.13.0-55-generic
Found kernel: /boot/memtest86+.bin
Updating /boot/grub/menu.lst ... done

run-parts: executing /etc/kernel/postinst.d/zz-update-grub 3.13.0-55-generic /boot/vmlinuz-3.13.0-55-generic
Generating grub.cfg ...
Found linux image: /boot/vmlinuz-3.13.0-55-generic
Found initrd image: /boot/initrd.img-3.13.0-55-generic
Found linux image: /boot/vmlinuz-3.2.0-80-generic
Found initrd image: /boot/initrd.img-3.2.0-80-generic
+ [ -f /usr/lib/grub/grub-mkconfig_lib ]
+ . /usr/lib/grub/grub-mkconfig_lib
+ transform=s,x,x,
+ prefix=/usr
+ exec_prefix=/usr
+ datarootdir=/usr/share
+ datadir=/usr/share
+ bindir=/usr/bin
+ sbindir=/usr/sbin
+ echo grub
+ sed s,x,x,
+ pkgdatadir=/usr/share/grub
+ test x = x
+ echo grub-probe
+ sed s,x,x,
+ grub_probe=/usr/sbin/grub-probe
+ test x = x
+ echo grub-mkrelpath
+ sed s,x,x,
+ grub_mkrelpath=/usr/bin/grub-mkrelpath
+ which gettext
+
+ gettext=gettext
+ LX=linux16
+ prepare_grub_to_access_device /dev/sda1
+ device=/dev/sda1
+ loop_file=
+ sed -e s/^/\t/
+ grep -q crypt[[:space:]]$
+ dmsetup status /dev/sda1
+ /usr/sbin/grub-probe --device /dev/sda1 --target=abstraction
+ abstraction=
+ /usr/sbin/grub-probe --device /dev/sda1 --target=partmap
+ partmap=msdos
+ echo insmod part_msdos
+ /usr/sbin/grub-probe --device /dev/sda1 --target=fs
+ fs=ext2
+ echo insmod ext2
+ /usr/sbin/grub-probe --device /dev/sda1 --target=drive
+ echo set root='(hd0,msdos1)'
+ /usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid

[Larry Michel (lmic)]

After perhaps 20 minutes or so, it's able to go on and the memtest completes, but some processes still remains:

+ fs_uuid=d729740f-7516-4530-80fc-a7d77bfe2bde
+ echo search --no-floppy --fs-uuid --set=root d729740f-7516-4530-80fc-a7d77bfe2bde
+ [ x != x ]
+ prepare_boot_cache= insmod part_msdos
 insmod ext2
 set root='(hd0,msdos1)'
 search --no-floppy --fs-uuid --set=root d729740f-7516-4530-80fc-a7d77bfe2bde
+ test -e /boot/memtest86+.bin
+ make_system_path_relative_to_its_root /boot/memtest86+.bin
+ /usr/bin/grub-mkrelpath /boot/memtest86+.bin
+ MEMTESTPATH=/boot/memtest86+.bin
+ echo Found memtest86+ image: /boot/memtest86+.bin
Found memtest86+ image: /boot/memtest86+.bin
+ cat
+ printf %s\n insmod part_msdos
 insmod ext2
 set root='(hd0,msdos1)'
 search --no-floppy --fs-uuid --set=root d729740f-7516-4530-80fc-a7d77bfe2bde
+ cat
+ printf %s\n insmod part_msdos
 insmod ext2
 set root='(hd0,msdos1)'
 search --no-floppy --fs-uuid --set=root d729740f-7516-4530-80fc-a7d77bfe2bde
+ cat
done
Setting up linux-image-generic-lts-trusty (3.13.0.55.48) ...
Setting up linux-headers-3.13.0-55 (3.13.0-55.94~precise1) ...
Setting up linux-headers-3.13.0-55-generic (3.13.0-55.94~precise1) ...
Setting up linux-headers-generic-lts-trusty (3.13.0.55.48) ...
Setting up linux-generic-lts-trusty (3.13.0.55.48) ...
Leaving 'diversion of /etc/init/ureadahead.conf to /etc/init/ureadahead.conf.disabled by cloud-init'
8192+0 records in
8192+0 records out
8589934592 bytes (8.6 GB) copied, 6.31303 s, 1.4 GB/s

Before /usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid completes:

root@pullman-01:/tmp/tmpO24sZq/target/etc/grub.d# ps -ef|grep grub
root 12328 2588 0 19:01 ? 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 12703 12328 0 19:13 ? 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 12714 12703 0 19:13 ? 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 12715 12714 0 19:13 ? 00:00:00 /bin/sh /etc/grub.d/20_memtest86+
root 12748 12715 30 19:16 ? 00:00:09 /usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid
root 12759 12361 0 19:17 pts/0 00:00:00 grep --color=auto grub

After:

root@pullman-01:~# ps -ef|grep grub
root 12931 2425 0 19:18 ? 00:00:00 /bin/bash /curtin/helpers/install-grub /tmp/tmpO24sZq/target /dev/sda
root 12938 12931 0 19:18 ? 00:00:00 sh -ec ? pkg=$1; shift;? dpkg-reconfigure "$pkg"? update-grub? for d in "$@"; do grub-install "$d" || exit; done -- grub-pc /dev/sda
root 12939 12938 0 19:18 ? 00:00:00 /usr/bin/perl -w /usr/sbin/dpkg-reconfigure grub-pc
root 12950 12939 0 19:18 ? 00:00:00 /bin/bash /var/lib/dpkg/info/grub-pc.postinst configure 1.99-21ubuntu3.17
root 13312 12950 0 19:20 ? 00:00:00 /bin/sh /usr/sbin/grub-mkconfig -o /boot/grub/grub.cfg
root 13356 13312 27 19:23 ? 00:00:13 /usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid
root 13363 12361 0 19:24 pts/0 00:00:00 grep --color=auto grub

[Larry Michel (lmic)]

We tried recreated today with a similar Cisco UCS 260 server and it deployed Precise ok with hwe-t kernel; we did not observe any issue with grub.

[Steve Langasek (vorlon)]

If this bug is no longer reproducible, should it be set to 'invalid' rather than 'new'?

[Larry Michel (lmic)]

I meant to set it to new for the previous data in comment #7 to be analyzed.

The issue itself is still very reproducible. I was just noting that we failed to recreate on another system which were able to access today.

However, the 2 systems are not fully identical. For the system that fails, the disks are ST300MM0006 300GB drives. For the new system which deployed Precise, the disks are WD3001BKHG-33D1 drives.

[Larry Michel (lmic)]

attached lshw for the 2 systems.

[Steve Langasek (vorlon)]

On Tue, Jun 23, 2015 at 12:57:12AM -0000, Larry Michel wrote:
> The issue itself is still very reproducible. I was just noting that we
> failed to recreate on another system which were able to access today.

> However, the 2 systems are not fully identical. For the system that
> fails, the disks are ST300MM0006 300GB drives. For the new system which
> deployed Precise, the disks are WD3001BKHG-33D1 drives.

Ok. The fact that it's not reproducible on two systems of the same class
strongly points to a hardware problem. And if it's not a hardware problem,
it's probably a kernel problem since grub-probe itself doesn't do much
that's particularly interesting.

Can you please run the '/usr/sbin/grub-probe --device /dev/sda1
--target=fs_uuid' under strace, and attach the resulting debug output?

[Brad Figg (brad-figg)]

This bug is missing log files that will aid in diagnosing the problem. From a terminal window please run:

apport-collect 1455268

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.

[Mathieu Trudel-Lapierre (cyphermox)]

For grub2 we're still waiting to see the result of running '/usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid' under strace, so setting the status to Incomplete..

[Larry Michel (lmic)]

Attached is the strace output for running:

root@pullman-01:~/fs# strace -o process_dump -ff /usr/sbin/grub-probe --device /dev/sda1 --target=fs
ext2
root@pullman-01:~/fs_uuid# strace -o process_dump -ff /usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid
61e97f71-41bd-432d-97b7-e86826f8a81d
root@pullman-01:~/fs_uuid#

Both command seemed to take as long to complete (as when I monitored through ps -ef).. I timed one of these commands to take as long as 50 seconds.

[Steve Langasek (vorlon)]

Larry, thanks for these traces. I realized it would have been a good idea to ask you for traces with timestamps, so we can confirm where the stall is actually happening. Could you rerun these with strace -t?

[Larry Michel (lmic)]

Steve, here is the output with the -t flags:

ubuntu@pullman-01:~$ sudo strace -t -o process_dump -ff /usr/sbin/grub-probe --device /dev/sda1 --target=fs
sudo: unable to resolve host pullman-01
ext2
ubuntu@pullman-01:~$ sudo strace -t -o process_dump -ff /usr/sbin/grub-probe --device /dev/sda1 --target=fs_uuid
sudo: unable to resolve host pullman-01
d1617fb9-47e7-4a90-a65f-a5cb5d20b72a

[Steve Langasek (vorlon)]

Thanks. From the fs log (fs/process_dump.12751):

16:17:43 open("/dev/sdb", O_RDONLY|O_SYNC) = 4
16:17:43 lseek(4, 0, SEEK_SET) = 0
16:17:43 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
16:17:43 read(4, "LABELONE\1\0\0\0\0\0\0\0]V\332\353 \0\0\0LVM2 001"..., 32256) = 32256
16:17:43 brk(0x20d2000) = 0x20d2000
16:17:43 mmap(NULL, 8589926400, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7f3f857c0000
16:17:43 lseek(4, 32768, SEEK_SET) = 32768
16:17:43 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4294901760) = 2147479552
16:17:54 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2147422208) = 2147422208
16:18:05 brk(0x20fa000) = 0x20fa000

[...]

grub-probe spends 22 seconds reading 4GB from the disk. Then this pattern repeats:

16:18:08 open("/dev/sdb", O_RDONLY|O_SYNC) = 4
16:18:08 lseek(4, 32768, SEEK_SET) = 32768
16:18:08 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4294901760) = 2147479552
16:18:19 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2147422208) = 2147422208
16:18:30 brk(0x2153000) = 0x2153000

And the same thing happens in the fs_uuid calls.

16:19:35 open("/dev/sdb", O_RDONLY|O_SYNC) = 4
16:19:35 lseek(4, 0, SEEK_SET) = 0
16:19:35 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
16:19:35 read(4, "LABELONE\1\0\0\0\0\0\0\0]V\332\353 \0\0\0LVM2 001"..., 32256) = 32256
16:19:35 brk(0x1707000) = 0x1707000
16:19:35 mmap(NULL, 8589926400, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7faca2289000
16:19:35 lseek(4, 32768, SEEK_SET) = 32768
16:19:35 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 4294901760) = 2147479552
16:19:46 read(4, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2147422208) = 2147422208
16:19:56 brk(0x172f000) = 0x172f000

I have no idea why grub-probe thinks it needs to read 4GB of disk, but that does explain why it's slow, and does point to a grub problem rather than a kernel problem.

[Mathieu Trudel-Lapierre (cyphermox)]

Could you please share the partition layout for that system? Which partitioning method you picked or if you specified some manual partitioning. Also, please include how many disks are included, of what size. I will try to reproduce this bug in a virtual machine for further debugging.

[Mate Kukri (mkukri)]

This bug has been marked Incomplete since 2015, I'll be closing this as 'Won't fix'. If anyone is still experiencing this issue on a modern Ubuntu release, please comment and/or report a new bug.