Bug 1520659

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...