Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

240.0: Can't boot with bcache mountpoint in fstab. Can't mount bcache FS. #11368

Closed
rcpoison opened this issue Jan 9, 2019 · 16 comments · Fixed by #11891
Closed

240.0: Can't boot with bcache mountpoint in fstab. Can't mount bcache FS. #11368

rcpoison opened this issue Jan 9, 2019 · 16 comments · Fixed by #11891
Labels
regression ⚠️ A bug in something that used to work correctly and broke through some recent commit udev
Milestone

Comments

@rcpoison
Copy link

rcpoison commented Jan 9, 2019

systemd version the issue has been seen with

240.0

Used distribution

archlinux

Expected behaviour you didn't see

Can boot.
Can mount bcache partitions.

Unexpected behaviour you saw

Can't boot with bcache partitions in fstab if nofail isn't added. Otherwise just blank screen, doesn't reach network target. Can't boot to rescue target.
boot-fail.log
boot-240-bcache-nofail.log

Can't mount bcache partitions after boot.

Errors:

Jan 09 10:02:34 draco systemd-udevd[402]: Process 'bcache-register /dev/sda1' failed with exit code 1.
Jan 09 10:02:34 draco systemd-udevd[402]: Failed to wait spawned command 'bcache-register /dev/sda1': Input/output error
Jan 09 10:02:34 draco systemd-udevd[378]: Process 'bcache-register /dev/sda2' failed with exit code 1.
Jan 09 10:02:34 draco systemd-udevd[378]: Failed to wait spawned command 'bcache-register /dev/sda2': Input/output error
Jan 09 10:02:34 draco systemd-udevd[377]: Process 'bcache-register /dev/sdc1' failed with exit code 1.
Jan 09 10:02:34 draco systemd-udevd[377]: Failed to wait spawned command 'bcache-register /dev/sdc1': Input/output error

Steps to reproduce the problem

Upgrade to 240.0, reboot.

Reverting to earlier systemd (239.370) fixes the problem:
boot-success-239.log

Archlinux bug report:
https://bugs.archlinux.org/task/61317

@yuwata
Copy link
Member

yuwata commented Jan 9, 2019

Already fixed by #11270. Sorry, that may not related.

@yuwata yuwata closed this as completed Jan 9, 2019
@yuwata yuwata reopened this Jan 9, 2019
@yuwata
Copy link
Member

yuwata commented Jan 9, 2019

Could you try the current git snapshot?

@yuwata yuwata added udev needs-reporter-feedback ❓ There's an unanswered question, the reporter needs to answer labels Jan 10, 2019
@endomandi
Copy link

I'm using Debian, with relevant packages: dracut, dracut-core (048+80-1); udev, libudev1 (240-4), and am experiencing the same apparent failure to register a volume with bcache, with identical error messages as above.

However, the same failure is reported with the PROGRAM invocation from line 14–15 in /usr/lib/dracut/modules.d/90lvm/64-lvm.rules, a dracut specific udev rule:

PROGRAM=="/bin/sh -c 'for i in $sys/$devpath/holders/dm-[0-9]*; do [ -e $$i ] && exit 0; done; exit 1;' ", \
    GOTO="lvm_end"

The referenced sysfs paths all exist on later inspection (while the initramfs is running), leaving little room for actual failure within this command.

Similarly, bcache-register is a very thin wrapper around writing to sysfs, which works later from within the initramfs. Therefore, I think it's fairly likely that this is an issue in udev itself, or in using sysfs.

@endomandi
Copy link

With systemd 241, the issue is still recurring here, but now with only the message:

[    2.221610] valravn systemd-udevd[261]: Process 'bcache-register /dev/sdb' failed with exit code 1.

Running bcache-register for a different block device /dev/sda2 completes without any message.

@poettering
Copy link
Member

hmm, this looks like a problem in bcache-register now, i.e. you might want to check under which conditions bcache_register returns exit code 1

@endomandi
Copy link

Per my comment above, bcache-register is a very thin wrapper around writing to sysfs. It exits with code 1 if there is more than one argument, if it fails to open() /sys/fs/bcache/register write only, or if it then fails to dprintf() to the opened fd. udev does not appear to be logging any of the associated messages to stderr to distinguish the cases.

The referenced command is successful if later run manually from within dracut, consistent with the sysfs paths existing on later examination per my comment, above.

@yuwata
Copy link
Member

yuwata commented Mar 4, 2019

Could you show the source of the wrapper?

@yuwata
Copy link
Member

yuwata commented Mar 4, 2019

@poettering BTW, currently, spawned external programs by udevd cannot log to journal. I do not know why. Could you give me some hints?

@zdzichu
Copy link
Contributor

zdzichu commented Mar 4, 2019

https://github.com/koverstreet/bcache-tools/blob/master/bcache-register.c

@yuwata
Copy link
Member

yuwata commented Mar 4, 2019

Thanks. Hmm... so simple.

@yuwata
Copy link
Member

yuwata commented Mar 4, 2019

Are there any relevant logs when booting with udev.log_priority=debug?

From the rule, kmod udev-builtin seems to be invoked before running bcache-register. Is it possible to confirm that in journal?

yuwata added a commit to yuwata/systemd that referenced this issue Mar 4, 2019
This fixes bugs introduced by 2944849
and d838e14.

Previously, RUN and SECLABEL keys are stored in udev_list with its unique
flag is false. If the flag is false, then udev_list is just a linked
list and new entries are always added in the last.
So, we should use OrderedHashmap instead of Hashmap.

Fixes systemd#11368.
@yuwata yuwata added has-pr ✨ and removed needs-reporter-feedback ❓ There's an unanswered question, the reporter needs to answer labels Mar 4, 2019
@yuwata
Copy link
Member

yuwata commented Mar 4, 2019

Maybe I found the root of this issue. If possible, please test #11891.

@yuwata yuwata added this to the v242 milestone Mar 4, 2019
@yuwata yuwata added the regression ⚠️ A bug in something that used to work correctly and broke through some recent commit label Mar 4, 2019
yuwata added a commit to yuwata/systemd that referenced this issue Mar 5, 2019
This fixes bugs introduced by 2944849
and d838e14.

Previously, RUN and SECLABEL keys are stored in udev_list with its unique
flag is false. If the flag is false, then udev_list is just a linked
list and new entries are always added in the last.
So, we should use OrderedHashmap instead of Hashmap.

Fixes systemd#11368.
poettering pushed a commit that referenced this issue Mar 5, 2019
This fixes bugs introduced by 2944849
and d838e14.

Previously, RUN and SECLABEL keys are stored in udev_list with its unique
flag is false. If the flag is false, then udev_list is just a linked
list and new entries are always added in the last.
So, we should use OrderedHashmap instead of Hashmap.

Fixes #11368.
yuwata added a commit to yuwata/systemd that referenced this issue Mar 5, 2019
This fixes bugs introduced by 2944849
and d838e14.

Previously, RUN and SECLABEL keys are stored in udev_list with its unique
flag is false. If the flag is false, then udev_list is just a linked
list and new entries are always added in the last.
So, we should use OrderedHashmap instead of Hashmap.

Fixes systemd#11368.

(cherry picked from commit 39a15c8)
@yuwata
Copy link
Member

yuwata commented Mar 5, 2019

#11891 is merged, and backporting this to v241 is waiting in systemd/systemd-stable#47, though I am not sure archlinux uses the repository or not.

@endomandi
Copy link

Here is the output from udev in the initramfs (dracut) with udev debug log_priority, clipped to the relevant process when it is processing the bcache device. As you have surmised to be the problem, the RUN lines are occurring in a different order than as specified in the rules file.

[    2.764816] systemd-udevd[241]: sdb: Processing device (SEQNUM=1704, ACTION=add)
[    2.764860] systemd-udevd[241]: sdb: GROUP 6 /lib/udev/rules.d/50-udev-default.rules:56
[    2.765044] systemd-udevd[241]: sdb: IMPORT 'ata_id --export /dev/sdb' /lib/udev/rules.d/60-persistent-storage.rules:40
[    2.765089] systemd-udevd[241]: Starting 'ata_id --export /dev/sdb'
[    2.765245] systemd-udevd[241]: Successfully forked off '(spawn)' as PID 309.
[    2.765292] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA=1'
[    2.765337] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_TYPE=disk'
[    2.765380] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_BUS=ata'
[    2.765423] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_MODEL=LITEON_CV8-8E128-11_SATA_128GB'
[    2.765467] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_MODEL_ENC=LITEON\x20CV8-8E128-11\x20SATA\x20128GB\x20\x20\x20\x20\x20\x20\x20\x20\x20\x20'
[    2.765514] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_REVISION=C27110B'
[    2.765559] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_SERIAL=LITEON_CV8-8E128-11_SATA_128GB_XXXXXXXXXXXXXXXXXXXX'
[    2.765602] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_SERIAL_SHORT=XXXXXXXXXXXXXXXXXXXX'
[    2.765655] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_WRITE_CACHE=1'
[    2.765700] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_WRITE_CACHE_ENABLED=1'
[    2.765743] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_HPA=1'
[    2.765796] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_HPA_ENABLED=1'
[    2.765840] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_PM=1'
[    2.765890] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_PM_ENABLED=1'
[    2.765935] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SECURITY=1'
[    2.765980] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SECURITY_ENABLED=0'
[    2.766030] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SECURITY_ERASE_UNIT_MIN=2'
[    2.766076] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SECURITY_ENHANCED_ERASE_UNIT_MIN=2'
[    2.766127] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SECURITY_FROZEN=1'
[    2.766183] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SMART=1'
[    2.766236] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_SMART_ENABLED=1'
[    2.766293] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_AAM=1'
[    2.766348] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_AAM_ENABLED=0'
[    2.766399] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_AAM_VENDOR_RECOMMENDED_VALUE=254'
[    2.766457] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_FEATURE_SET_AAM_CURRENT_VALUE=128'
[    2.766513] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_DOWNLOAD_MICROCODE=1'
[    2.766560] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_SATA=1'
[    2.766604] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_SATA_SIGNAL_RATE_GEN2=1'
[    2.766647] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_SATA_SIGNAL_RATE_GEN1=1'
[    2.766691] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_ATA_ROTATION_RATE_RPM=0'
[    2.766742] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_WWN=0xXXXXXXXXXXXXXXXX'
[    2.766786] systemd-udevd[241]: 'ata_id --export /dev/sdb'(out) 'ID_WWN_WITH_EXTENSION=0xXXXXXXXXXXXXXXXX'
[    2.766831] systemd-udevd[241]: Process 'ata_id --export /dev/sdb' succeeded.
[    2.766882] systemd-udevd[241]: sdb: LINK 'disk/by-id/ata-LITEON_CV8-8E128-11_SATA_128GB_XXXXXXXXXXXXXXXXXXXX' /lib/udev/rules.d/60-persistent-storage.rules:54
[    2.766937] systemd-udevd[241]: sdb: IMPORT builtin 'path_id' /lib/udev/rules.d/60-persistent-storage.rules:78
[    2.766981] systemd-udevd[241]: sdb: LINK 'disk/by-path/pci-0000:00:17.0-ata-3' /lib/udev/rules.d/60-persistent-storage.rules:80
[    2.767025] systemd-udevd[241]: sdb: IMPORT builtin 'blkid' /lib/udev/rules.d/60-persistent-storage.rules:95
[    2.767090] systemd-udevd[241]: sdb: Probe /dev/sdb with raid and offset=0
[    2.769999] systemd-udevd[241]: sdb: LINK 'disk/by-uuid/XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX' /lib/udev/rules.d/60-persistent-storage.rules:98
[    2.770062] systemd-udevd[241]: sdb: LINK 'disk/by-id/wwn-0xXXXXXXXXXXXXXXXX' /lib/udev/rules.d/60-persistent-storage.rules:102
[    2.770109] systemd-udevd[241]: sdb: RUN 'kmod load bcache' /lib/udev/rules.d/69-bcache.rules:21
[    2.770155] systemd-udevd[241]: sdb: RUN 'bcache-register $tempnode' /lib/udev/rules.d/69-bcache.rules:22
[    2.770198] systemd-udevd[241]: sdb: Handling device node '/dev/sdb', devnum=b8:16, mode=0660, uid=0, gid=6
[    2.770245] systemd-udevd[241]: sdb: Setting permissions /dev/sdb, 060660, uid=0, gid=6
[    2.770289] systemd-udevd[241]: sdb: Creating symlink '/dev/block/8:16' to '../sdb'
[    2.770333] systemd-udevd[241]: sdb: Creating symlink '/dev/disk/by-path/pci-0000:00:17.0-ata-3' to '../../sdb'
[    2.770376] systemd-udevd[241]: sdb: Creating symlink '/dev/disk/by-uuid/XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX' to '../../sdb'
[    2.770418] systemd-udevd[241]: sdb: Creating symlink '/dev/disk/by-id/ata-LITEON_CV8-8E128-11_SATA_128GB_XXXXXXXXXXXXXXXXXXXX' to '../../sdb'
[    2.770462] systemd-udevd[241]: sdb: Creating symlink '/dev/disk/by-id/wwn-0xXXXXXXXXXXXXXXXX' to '../../sdb'
[    2.770505] systemd-udevd[241]: sdb: sd-device: Created db file '/run/udev/data/b8:16' for '/devices/pci0000:00/0000:00:17.0/ata3/host2/target2:0:0/2:0:0:0/block/sdb'
[    2.770549] systemd-udevd[241]: Starting 'bcache-register /dev/sdb'
[    2.770594] systemd-udevd[241]: Successfully forked off '(spawn)' as PID 310.
[    2.771251] systemd-udevd[241]: 'bcache-register /dev/sdb'(err) 'Error opening /sys/fs/bcache/register: No such file or directory'
[    2.771314] systemd-udevd[241]: 'bcache-register /dev/sdb'(err) 'The bcache kernel module must be loaded'
[    2.771360] systemd-udevd[241]: Process 'bcache-register /dev/sdb' failed with exit code 1.
[    2.771404] systemd-udevd[241]: Loading module: bcache
[    2.778289] systemd-udevd[241]: Inserted module 'bcache'
[    2.778422] systemd-udevd[241]: sdb: Adding watch on '/dev/sdb'
[    2.778580] systemd-udevd[241]: sdb: sd-device: Created db file '/run/udev/data/b8:16' for '/devices/pci0000:00/0000:00:17.0/ata3/host2/target2:0:0/2:0:0:0/block/sdb'
[    2.778666] systemd-udevd[241]: sdb: Device (SEQNUM=1704, ACTION=add) processed
[    2.778796] systemd-udevd[241]: sdb: sd-device-monitor: Passed 1730 byte to netlink monitor

@zdzichu
Copy link
Contributor

zdzichu commented Mar 6, 2019

@endomandi this is with #11891 ?

@endomandi
Copy link

Apologies for not including the necessary information. That log was in response to this:

Are there any relevant logs when booting with udev.log_priority=debug?

So, that is without #11891.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
regression ⚠️ A bug in something that used to work correctly and broke through some recent commit udev
Development

Successfully merging a pull request may close this issue.

5 participants