Fedora Account System
Red Hat Associate
Red Hat Customer
Description of problem: Recently my machine started to have strange issue. All works fine on cold boot. (EDIT: Not anymore, see below) But on reboot, I get this issue: A start job is running for dev-disk-by ... A stop job is running for LVM2 PV scan on device .... See the pictures: https://ibb.co/huh386 https://ibb.co/cYyX1R Those two messages are alternating and after timeout (I have set it to 30 sec. instead of default 1:30) I get this screen: https://ibb.co/fNxQMR Again, if I log in and do "reboot" I will get back to this situation again. If I do "poweroff" and then start PC again, no issue at all, boots perfectly fine (needs to "sit" for a few seconds, if I start immediately it might go to this error again). I was searching for the messages, but others seem to have this case consistent disregarding whether it is cold start or reboot. Looking for kernel version, which started this problem I got to these conclusions: I have reproduced this issue also in: 4.8.0 4.9.0 4.10.0 4.12.0 However, it seems that the older the kernel, the harder to reproduce - it takes more reboots for the issue to manifest itself. 4.8.0 - about 4-5 successful reboots before getting this error again 4.9.0 - about 4-5 successful reboots before getting this error again 4.10.0 - about 2-4 successful reboots before getting this error again 4.12.0 - about 1-3 successful reboots before getting this error again 4.13.x - about 0-1 successful reboots before getting this error again 4.14.3 - about 0-1 successful reboots before getting this error again Interestingly, I was not able to reproduce it in 4.9.66 LTS kernel, gave up after 10 successful reboots. EDIT: It seems that the issue is getting worse. I can not cold boot anymore with default kernel 4.13.something. Fails also on cold boot. But with 4.9.66 works without issue. This would suggest possible failing HW to me, but something in the new kernels seems to be triggering it that is not in LTS kernel. Version-Release number of selected component (if applicable): lvm2 2.02.176-1 multiple kernel versions How reproducible: No idea, easy to do on my HW, not sure about other HW. Needs just reboot. Steps to Reproduce: 1. Reboot Actual results: Fails to boot Expected results: Boot Additional info:
Created attachment 1362836 [details] new-kernel-dmesg
Created attachment 1362837 [details] fstab
Created attachment 1362838 [details] lts kernel dmesg
Log in and check `systemctl`: - which units are failing? - print `systemctl status` for the failed services What's `lvm lvs -a` saying, if anything? And `lsblk`?
Created attachment 1363922 [details] fdisk
Created attachment 1363923 [details] lsblk
Created attachment 1363924 [details] lvm lvs -a
Created attachment 1363925 [details] systemctl failed unit
Created attachment 1363926 [details] systemctl status of failed unit
I have added the requested info as attachments
Is the /dev/sdb USB attached storage ? Is the attachment of disk should be also auto-activating 'data' LV present on this LVM disk ? What 'pvscan -vvvvv' shows ? It's unclear why the systemd service gets blocked ? So attach also: pvscan -vvvv --cache --activate ay 8:18 Isn't there any suspicious USB blocking possible ? (No misbehaving cable connected ? eventually 'sleeping drive' which cannot be woken up ? (so only cold-boot makes it spinning and service read requests ?)
Created attachment 1363940 [details] pvscan -vvvvv
Created attachment 1363941 [details] pvscan -vvvv --cache --activate ay 8:18
"Is the /dev/sdb USB attached storage ?" -> No, it is internal 3.5" disk. Is the attachment of disk should be also auto-activating 'data' LV present on this LVM disk ? -> Sorry, I am not sure I do understand the question. Volgroup data should be mounted on boot: /dev/mapper/volgroup-data on /mnt/data type ext4 (rw,noatime,data=ordered) What 'pvscan -vvvvv' shows ? -> attached file It's unclear why the systemd service gets blocked ? So attach also: pvscan -vvvv --cache --activate ay 8:18 -> attached file Isn't there any suspicious USB blocking possible ? (No misbehaving cable connected ? eventually 'sleeping drive' which cannot be woken up ? (so only cold-boot makes it spinning and service read requests ?) -> There is no USB drive attached, only few unused cables. There is also not disk sleeping configured. It is desktop PC. I tried to check, but haven't found a command to check hdparm setting. But the drive is for all I know not spinning down.
Trace looks ok. You need to try capture these trace in the moment it doesn't work. As in your 'comment 13' there is clearly nothing being 'blocked' and process normally exits. While in 'comment 9' is clearly blocked 'forever'. So please repeat trace in the case your system doesn't work. You may possibly need to temporary disable mounted fs from your /dev/sdb device so your boot might finish without waiting for those to appear in system. Also actually make sure UUID mentioned in your 'fstab' are matching those present fs UUID you have. If you manage to non-cold 'boot' - repeat pvscan -vvvv so you can see if your /dev/sdb device works well. I'd also highly recommend newer kernel (4.14)
I have tried kernel 4.14 but result was the same, so I returned to 4.13 as this is default in my distro atm. I expect to get the new one soon, but it seems to make no difference in this case. "You need to try capture these trace in the moment it doesn't work." I am not sure what the process should be. Here is what I did - I rebooted system and waited until it timed out. Then I run those commands to get output. I have run them multiple times, because I did not nail the redirection to file at first attempt. Is that the issue, that I provided log on second or third run after failed boot instead of the first one, possibly already activated? "Also actually make sure UUID mentioned in your 'fstab' are matching those present fs UUID you have." Have you found any that do not match? There might be different root as I have multi boot and use one installation as default and other (cloned) for experiment testing, I did some reports from the experimental install and now I am on my main install, but they both mount the same "data", so that should be ok. "If you manage to non-cold 'boot'" -> by that you mean to boot without this error by not attempting to mount ? Not sure, sorry.
From provided traces there is no sign of anything going wrong on lvm2 software side. So until we get a trace where it's visible lvm2 is doing something bad there is low chance we can fix/improve it. As you say - if cold-boot does work while plain reboot does not - I'm expecting some HW issue on your setup. You can possibly increase verbosity of systemd: https://fedoraproject.org/wiki/How_to_debug_Systemd_problems systemd.log_level=debug What is recommendable (by me :)) is also enabling systemd debug shell: https://fedoraproject.org/wiki/Systemd_early_debug_shell Then you can with press CTRL+ALT+F9 and run individual command EVEN when your system is otherwise blocked on some timeout.
I have increased the log level of systemd, but haven't found anything useful in the failed unit status. I have run again command: pvscan -vvvv --cache --activate ay 8:18 right after the failed boot to make sure that subsequent runs before did not alter the result. I also have run it in early debug shell during the blocked period, before it timed out. I am attaching both files. I can not tell from them if they are of any use. Please you tell me. Note - I also got the upgraded kernel in my distro, so I am on 4.14 now.
Created attachment 1365444 [details] pvscan -vvvv --cache --activate ay 8:18 -> after failed boot timeout
Created attachment 1365445 [details] pvscan -vvvv --cache --activate ay 8:18 -> Early systemd debug shell, before timeout
(In reply to raqua from comment #19) > Created attachment 1365444 [details] > pvscan -vvvv --cache --activate ay 8:18 -> after failed boot timeout This trace suggest there is some 'dm-0' device in DM table and that you are using possibly 'too wide' accept filter (accept all). While the trace itself is not showing anything wrong - all seems to be working - there are 2 possible things to try: 1st. Setup 'global_filter' in lvm.conf to accept only your /dev/sdXXX devices = [ "a|^/dev/sd|", "r|.*/|" ] (eventually expand filter with more acceptable device and don't forget to update your init ramdisk - since lvm.conf is usually copied there too) -- 2nd. chance which tries to looks for core trouble: While the pvscan is stuck (systemd is waiting) - check with 'system debug console) state of 'dm tables' and attach 'dmsetup table' 'dmsetup info -c' and 'dmsetup status --noflush'
Created attachment 1366352 [details] dmsetup table
Created attachment 1366353 [details] dmsetup info -c
Created attachment 1366354 [details] dmsetup status --noflush
I have added the requested files. I have compared the output to the result of successful boot with lts kernel and the only difference is that "dmsetup info -c" has 1 in column "open".
Adding the global_filter you suggested did not help.
Your attached 'dmsetup' output are from the moment your LV volgroup/data is already active. You need to capture all traces of 'pvscan -vvvv' & 'dmsetup...' from the moment your system is blocked/waiting on pvscan. So far there is no sign we can see in traces that something goes wrong. Please follow URL in comment 17 and enable debug tracing of your systemd setup. As of now - there is no visible problem on lvm2 side we can help with.
Ok, so here is what I did: - set up systemd loglevel to debug (see attached config) - enabled systemd debug shell - booted with kernel parameter systemd.log_level=debug - during the blockage I switched to debug shell (CTRL+ALT+F9) and run script which produced log files that I am attaching. So ALL logs provided are collected when system is BLOCKED. There is one EXCEPTION and that is file pvscan-vvvv, which was run after that failed boot, because during the boot it would just hang until the boot completed. There is, however, one interesting observation. Yesterday, when I was preparing this (but could not finish), running "pvscan -vvvv --cache --activate ay 8:18" had somehow broken the blocking and made my system boot successfully. I was able to reproduce that multiple times. I can not reproduce this behavior today. There are some suspicious looking messages "Failed to send unit change signal for dev-sdb.device: Transport endpoint is not connected" in journalctl -b file.
Created attachment 1367608 [details] Complete logs from BLOCKED state
Ohh - your log suggests you are running 'arch' linux - you should have started with this. Well your bug surely isn't lvm2 related - I'd expect some configuration issue with systemd (or possibly using some old version of systemd). There are observable number of failing rules for systemd in your journalctl. You kernel is possibly missing certain mandatory features for proper usage of systemd. I'm closing bug for lvm2 - your problem is not lvm2 related. Noticeable thing from journal log - suggests you USB bus is disconnecting... Dec 13 22:39:25 archlinux systemd[1]: lvm2-pvscan@8:18.service: Enqueued job lvm2-pvscan@8:18.service/start as 85 Dec 13 22:39:25 archlinux systemd[1]: dev-sdb2.device: Failed to send unit change signal for dev-sdb2.device: Connection reset by peer Dec 13 22:39:25 archlinux systemd[1]: dev-disk-by\x2did-ata\x2dWDC_WD30EFRX\x2d68EUZN0_WD\x2dWMC4N2314012\x2dpart2.device: Failed to send unit change signal for dev-disk-by\x2did-ata\x2 dWDC_WD30EFRX\x2d68EUZN0_WD\x2dWMC4N2314012\x2dpart2.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: dev-disk-by\x2did-lvm\x2dpv\x2duuid\x2djhgD15\x2d6EwZ\x2dwJMd\x2dWpCb\x2dJ0oi\x2dgbpd\x2d4HAIOo.device: Failed to send unit change signal for dev-d isk-by\x2did-lvm\x2dpv\x2duuid\x2djhgD15\x2d6EwZ\x2dwJMd\x2dWpCb\x2dJ0oi\x2dgbpd\x2d4HAIOo.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: dev-disk-by\x2did-wwn\x2d0x50014ee003c725e9\x2dpart2.device: Failed to send unit change signal for dev-disk-by\x2did-wwn\x2d0x50014ee003c725e9\x2dp art2.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: dev-disk-by\x2dpartuuid-4e0d6eff\x2d6436\x2d4662\x2d8c70\x2dee849b076107.device: Failed to send unit change signal for dev-disk-by\x2dpartuuid-4e0d 6eff\x2d6436\x2d4662\x2d8c70\x2dee849b076107.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: dev-disk-by\x2dpath-pci\x2d0000:00:11.0\x2data\x2d3\x2dpart2.device: Failed to send unit change signal for dev-disk-by\x2dpath-pci\x2d0000:00:11.0\ x2data\x2d3\x2dpart2.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: sys-devices-pci0000:00-0000:00:11.0-ata5-host4-target4:0:0-4:0:0:0-block-sdb-sdb2.device: Failed to send unit change signal for sys-devices-pci0000 :00-0000:00:11.0-ata5-host4-target4:0:0-4:0:0:0-block-sdb-sdb2.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: dev-block-8:18.device: Failed to send unit change signal for dev-block-8:18.device: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: system-lvm2\x2dpvscan.slice: Failed to send unit change signal for system-lvm2\x2dpvscan.slice: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: lvm2-pvscan@8:18.service: Failed to send unit change signal for lvm2-pvscan@8:18.service: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: Failed to send job change signal for 85: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: Failed to send job change signal for 86: Transport endpoint is not connected Dec 13 22:39:25 archlinux systemd[1]: Failed to send job change signal for 90: Transport endpoint is not connected Dec 13 22:39:25 archlinux kernel: usb 7-2: new high-speed USB device number 3 using ehci-pci Dec 13 22:39:25 archlinux systemd[1]: Received SIGCHLD from PID 210 (systemctl). If your USB controler suffers with this problem only on reboot - you can turn off lvmetad (lvm.conf use_lvmetad=0) and your runtime command will possibly work in time. But you need to ensure yourself LVs are being activated...