Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1775157 - lvm fails after glibc upgrade on armhfp
Summary: lvm fails after glibc upgrade on armhfp
Keywords:
Status: CLOSED NOTABUG
Alias: None
Product: Fedora
Classification: Fedora
Component: glibc
Version: rawhide
Hardware: armhfp
OS: Unspecified
unspecified
unspecified
Target Milestone: ---
Assignee: Carlos O'Donell
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
Depends On:
Blocks: ARMTracker
TreeView+ depends on / blocked
 
Reported: 2019-11-21 13:53 UTC by Paul Whalen
Modified: 2019-11-26 17:35 UTC (History)
11 users (show)

Fixed In Version:
Doc Type: If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed: 2019-11-26 17:35:02 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)
lvs verbose output (231.31 KB, text/plain)
2019-11-21 14:46 UTC, Paul Whalen 		no flags Details
lvs verbose output (148.54 KB, text/plain)
2019-11-21 15:05 UTC, Paul Whalen 		no flags Details
Fedora-Rawhide-20191108.n.0 boot log (34.87 KB, text/plain)
2019-11-21 18:37 UTC, Paul Whalen 		no flags Details
Show Obsolete (1) View All

Description Paul Whalen 2019-11-21 13:53:25 UTC 
Description of problem:
Armhfp systems that use lvm fail to boot after upgrading to glibc-2.30.9000-17.fc32, waiting indefinitely:


Version-Release number of selected component (if applicable):
glibc-2.30.9000-17.fc32
lvm2-2.03.06-1.fc32.armv7hl
systemd-udev-243-4.gitef67743.fc32.armv7hl

How reproducible:
Everytime

Steps to Reproduce:
1. Boot disk image from Fedora-Rawhide-20191106.n.0 compose on armhfp device
2. upgrade glibc to glibc-2.30.9000-17.fc32+
3. Use lvm commands 

Actual results:
System hangs when booting with lvm, lvm commands fail


Additional info:
Using lvm commands manually on another system with glibc-2.30.9000-17.fc32+

# fdisk -l /dev/sdb
Disk /dev/sdb: 7.47 GiB, 8004829184 bytes, 15634432 sectors
Disk model: USB DISK 2.0    
Units: sectors of 1 * 512 = 512 bytes
Sector size (logical/physical): 512 bytes / 512 bytes
I/O size (minimum/optimal): 512 bytes / 512 bytes
Disklabel type: dos
Disk identifier: 0x730bc46f

Device     Boot   Start      End  Sectors  Size Id Type
/dev/sdb1  *       2048  2099199  2097152    1G 83 Linux
/dev/sdb2       2099200 15634431 13535232  6.5G 8e Linux LVM
[root@localhost ~]# lvs
  WARNING: Device /dev/sda not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/mmcblk0 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda3 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda5 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sdb2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/mmcblk0 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda1 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda2 not initialized in udev database even after waiting 10000000 microseconds.
  WARNING: Device /dev/sda3 not initialized in udev database even after waiting 10000000 microseconds.

systemctl status systemd-udevd
● systemd-udevd.service - udev Kernel Device Manager
   Loaded: loaded (/usr/lib/systemd/system/systemd-udevd.service; static; vendor preset: disabled)
   Active: active (running) since Thu 2019-10-10 08:56:18 EDT; 1 months 11 days ago
     Docs: man:systemd-udevd.service(8)
           man:udev(7)
 Main PID: 421 (systemd-udevd)
   Status: "Processing with 10 children at max"
    Tasks: 1
   Memory: 14.8M
      CPU: 9.597s
   CGroup: /system.slice/systemd-udevd.service
           └─421 /usr/lib/systemd/systemd-udevd

Oct 10 09:16:42 localhost.localdomain systemd-udevd[666]: sdb: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:42 localhost.localdomain systemd-udevd[668]: sdb2: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:42 localhost.localdomain systemd-udevd[666]: sdb1: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:42 localhost.localdomain systemd-udevd[421]: Failed to touch /run/udev/queue: Operation not permitted
Oct 10 09:16:42 localhost.localdomain systemd-udevd[668]: dm-0: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:42 localhost.localdomain systemd-udevd[669]: dm-1: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:43 localhost.localdomain systemd-udevd[668]: dm-0: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:43 localhost.localdomain systemd-udevd[666]: dm-1: Failed to process device, ignoring: Operation not permitted
Oct 10 09:16:52 localhost.localdomain systemd-udevd[421]: Failed to touch /run/udev/queue: Operation not permitted
Oct 10 09:16:52 localhost.localdomain systemd-udevd[687]: card0: Failed to process device, ignoring: Operation not permitted
Comment 1 Florian Weimer 2019-11-21 14:00:14 UTC 
Is this real hardware, or QEMU? If the latter, which kind?

Is there anything in the audit log?
Comment 2 Paul Whalen 2019-11-21 14:45:34 UTC 
On the real hardware (Raspberry Pi 3 and Banana Pi). 

Not seeing anything in audit.log:

cat /var/log/audit/audit.log | grep lvm2
type=SERVICE_START msg=audit(1574307737.071:121): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-monitor comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
type=SERVICE_START msg=audit(1574309167.423:136): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:34 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'UID="root" AUID="unset"
type=SERVICE_START msg=audit(1574309208.745:145): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:18 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=failed'UID="root" AUID="unset"
type=SERVICE_START msg=audit(1574309386.982:121): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:18 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
type=SERVICE_STOP msg=audit(1574309388.820:133): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:18 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
type=SERVICE_START msg=audit(1574309673.247:122): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:18 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
type=SERVICE_STOP msg=audit(1574309977.200:205): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=lvm2-pvscan@8:18 comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"

[root@rpi3-5 ~]# cat /var/log/audit/audit.log | grep udev
type=SERVICE_START msg=audit(1570712185.621:61): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0 msg='unit=systemd-udevd comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'UID="root" AUID="unset"
Comment 3 Paul Whalen 2019-11-21 14:46:51 UTC 
Created attachment 1638488 [details]
lvs verbose output
Comment 4 Florian Weimer 2019-11-21 14:49:43 UTC 
Comment on attachment 1638488 [details]
lvs verbose output

Has the command been executed correctly?

09:23:44.236905 lvs[692] cache/lvmcache.c:276  lvmcache has no info for vgname "lvs.txt".

Why lvs.txt?
Comment 5 Paul Whalen 2019-11-21 15:05:22 UTC 
Created attachment 1638499 [details]
lvs verbose output

Fixed, sorry about that.
Comment 6 Florian Weimer 2019-11-21 15:41:57 UTC 
Thanks. I would have expected denied system calls in the audit. In the log output, the time stamps align with the waiting, so that is good. I was worried that we broke something in the time-related system call wrappers, considering all the Y2038 work that is currently happening.

Sorry, I do not have a way to debug this further.
Comment 7 Paul Whalen 2019-11-21 18:37:23 UTC 
Created attachment 1638552 [details]
Fedora-Rawhide-20191108.n.0 boot log

This also affects installations when glibc-2.30.9000-17.fc32 was added, booting with "debug systemd.log_level=debug udev.log_priority=debug rd.udev.log_priority=debug" doesn't seem to give any useful output and ends with (full logs attached):

[   90.046073] systemd-udevd (784) used greatest stack depth: 4992 bytes left
[   90.132279] systemd-udevd (783) used greatest stack depth: 4972 bytes left
[   90.141240] systemd-udevd (782) used greatest stack depth: 4644 bytes left
[  OK  ] Started Create Volatile Files and Directories.[   90.728507] audit: type=1130 audit(1570712207.728:11): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=systemd-tmpfiles-setup comm="systemd" exe="/usr/lib/systemd'

[  OK  ] Reached target System Initialization.
[  OK  ] Listening on Open-iSCSI iscsid Socket.
[  OK  ] Listening on Open-iSCSI iscsiuio Socket.
[  OK  ] Reached target Sockets.
[  OK  ] Reached target Basic System.
         Starting iSCSI UserSpace I/O driver...
[   90.862804] systemd-journald[288]: Successfully sent stream file descriptor to service manager.
[  OK  ] Started iSCSI UserSpace I/O driver.[   90.951496] audit: type=1130 audit(1570712207.951:12): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=iscsiuio comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr'

         Starting Open-iSCSI...
[  OK  ] Started Open-iSCSI.
[   91.360853] audit: type=1130 audit(1570712208.360:13): pid=1 uid=0 auid=4294967295 ses=4294967295 subj=kernel msg='unit=iscsid comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=? res=success'
[  169.942795] systemd-journald[288]: Sent WATCHDOG=1 notification.
[  229.941127] systemd-journald[288]: Sent WATCHDOG=1 notification.
[  339.940934] systemd-journald[288]: Sent WATCHDOG=1 notification.
[  409.942431] systemd-journald[288]: Sent WATCHDOG=1 notification.
Comment 8 Carlos O'Donell 2019-11-22 04:21:31 UTC 
Does downgrading to 2.30.9000-16 fix the issue? That would at least allow us to track down which *week* the change occurred on and what impact it had (we sync Rawhide weekly).
Comment 9 Paul Whalen 2019-11-22 13:45:33 UTC 
Yes, glibc-2.30.9000-16.fc32 works as expected. Downgrading allows lvm commands to work.
Comment 10 Florian Weimer 2019-11-22 17:05:12 UTC 
To simplify bisection, I have started a scratch build with broken-out patches: https://koji.fedoraproject.org/koji/taskinfo?taskID=39202209

(Some patches for Hurd and locale-only chanhes I dropped, so it's best to verify the .38 build first.)

SRPM is also available here: https://people.redhat.com/~fweimer/glibc-2.30.9000-16.bz1775157.38.fc32.src.rpm
Comment 11 Carlos O'Donell 2019-11-26 14:14:45 UTC 
Paul, Do you know if anyone else is running into this? We're trying to determine if this is some kind of common-mode failure across the systems you are using e.g. corrupted NFS disk etc.
Comment 12 Paul Whalen 2019-11-26 17:33:47 UTC 
This is working again in 'Fedora-Rawhide-20191122.n.0' and onward. The version of glibc did not change (glibc-2.30.9000-19.fc32).

Last broken compose was Fedora-Rawhide-20191119.n.2. Limiting updates this appears to be fixed by libseccomp-2.4.2-1.fc32.armv7hl . Once installed lvm commands work as expected.

I also confirmed once libseccomp-2.4.2-1.fc32 was included in Rawhide installs worked as expected. Apologies for the noise (and thanks for your help).
Comment 13 Florian Weimer 2019-11-26 17:35:02 UTC 
Thanks for the feedback!
Note You need to log in before you can comment on or make changes to this bug.