Bug 2177580

Summary: System fails to unlock from tang server
Product: [Fedora] Fedora Reporter: Dennis Gilmore <dennis>
Component: dracutAssignee: dracut-maint-list
Status: NEW --- QA Contact: Fedora Extras Quality Assurance <extras-qa>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 38CC: amulhern, dracut-maint-list, fmartine, jamacku, lnykryn, mzeleny, pvalena, rsroka, sarroutb, scorreia
Target Milestone: ---   
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:

Description Dennis Gilmore 2023-03-13 02:50:40 UTC
Description of problem:

Mar 12 19:57:48 ryac.ausil.us NetworkManager[1159]: <info>  [1678669068.3047] device (br0): carrier: link connected
Mar 12 19:57:57 ryac.ausil.us systemd[1]: dev-disk-by\x2duuid-afb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.device: Job dev-disk-by\x2duuid-afb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.device/start timed out.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: Timed out waiting for device dev-disk-by\x2duuid-afb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.device - /dev/disk/by-uuid/afb69124-101c-45fa-b39a-c744112e7251.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: Dependency failed for systemd-cryptsetup@luks\x2dafb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.service - Cryptography Setup for luks-afb69124-101c-45fa-b39a-c744112e7251.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: Dependency failed for cryptsetup.target - Local Encrypted Volumes.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: cryptsetup.target: Job cryptsetup.target/start failed with result 'dependency'.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: systemd-cryptsetup@luks\x2dafb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.service: Job systemd-cryptsetup@luks\x2dafb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.service/start failed with resu>
Mar 12 19:57:57 ryac.ausil.us systemd[1]: dev-disk-by\x2duuid-afb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.device: Job dev-disk-by\x2duuid-afb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.device/start failed with result 'timeout'.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: Reached target sysinit.target - System Initialization.
Mar 12 19:57:57 ryac.ausil.us systemd[1]: Reached target basic.target - Basic System.
Mar 12 19:58:16 ryac.ausil.us NetworkManager[1159]: <warn>  [1678669096.5391] settings: startup-complete: profile "enP13p1s0f0" (aff4dcb9-4f21-436d-acfd-3de9fa2e1bd2) was waiting for non-existing device (with timeout "connection.wait-dev>
Mar 12 19:58:16 ryac.ausil.us NetworkManager[1159]: <warn>  [1678669096.5392] settings: startup-complete: profile "enP12p1s0f0" (aff4dcb9-4f21-436d-acfd-3de9fa2e1bd5) was waiting for non-existing device (with timeout "connection.wait-dev>
Mar 12 19:58:16 ryac.ausil.us NetworkManager[1159]: <info>  [1678669096.5392] manager: startup complete
Mar 12 19:58:16 ryac.ausil.us systemd[1]: Finished nm-wait-online-initrd.service.
Mar 12 19:58:16 ryac.ausil.us systemd[1]: Starting dracut-initqueue.service - dracut initqueue hook...
Mar 12 19:58:16 ryac.ausil.us systemd[1]: Reloading requested from client PID 1388 (unit dracut-initqueue.service)...
Mar 12 19:58:16 ryac.ausil.us systemd[1]: Reloading.
Mar 12 19:58:17 ryac.ausil.us dracut-initqueue[1505]: Scanning devices md127  for LVM logical volumes fedora_ryac/root
Mar 12 19:58:17 ryac.ausil.us dracut-initqueue[1505]:   fedora_ryac/root linear
Mar 12 19:58:18 ryac.ausil.us systemd[1]: Starting systemd-cryptsetup@luks\x2dafb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.service - Cryptography Setup for luks-afb69124-101c-45fa-b39a-c744112e7251...
Mar 12 19:58:18 ryac.ausil.us systemd[1]: Started clevis-luks-askpass.service - Forward Password Requests to Clevis.
Mar 12 19:58:18 ryac.ausil.us systemd[1]: Started systemd-ask-password-plymouth.service - Forward Password Requests to Plymouth.
Mar 12 19:58:18 ryac.ausil.us clevis-luks-askpass[1561]: Unlocked /dev/disk/by-uuid/afb69124-101c-45fa-b39a-c744112e7251 (UUID=afb69124-101c-45fa-b39a-c744112e7251) successfully
Mar 12 19:58:18 ryac.ausil.us systemd[1]: clevis-luks-askpass.service: Deactivated successfully.
Mar 12 19:58:18 ryac.ausil.us systemd-cryptsetup[1560]: Set cipher aes, mode xts-plain64, key size 512 bits for device /dev/disk/by-uuid/afb69124-101c-45fa-b39a-c744112e7251.
Mar 12 19:58:23 ryac.ausil.us systemd[1]: Found device dev-disk-by\x2duuid-b548e00c\x2d7adf\x2d41bf\x2d92e7\x2d0dd66b8e0ca8.device - /dev/disk/by-uuid/b548e00c-7adf-41bf-92e7-0dd66b8e0ca8.
Mar 12 19:58:23 ryac.ausil.us systemd[1]: Reached target initrd-root-device.target - Initrd Root Device.
Mar 12 19:58:23 ryac.ausil.us systemd[1]: Finished systemd-cryptsetup@luks\x2dafb69124\x2d101c\x2d45fa\x2db39a\x2dc744112e7251.service - Cryptography Setup for luks-afb69124-101c-45fa-b39a-c744112e7251.


```
[  313.983060] dracut-initqueue[1375]: Warning: dracut-initqueue: timeout, still waiting for following initqueue hooks:
[  313.984497] dracut-initqueue[1375]: Warning: /lib/dracut/hooks/initqueue/finished/90-crypt.sh: "[ -e /dev/disk/by-id/dm-uuid-CRYPT-LUKS?-*afb69124101c45fab39ac744112e7251*-* ] || exit 1"
[  313.986152] dracut-initqueue[1375]: Warning: /lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2fdisk\x2fby-id\x2fmd-uuid-a19d3026:::.sh: "[ -e "/dev/disk/by-id/md-uuid-a19d3026:::" ]"
[  313.987912] dracut-initqueue[1375]: Warning: /lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2fdisk\x2fby-id\x2fmd-uuid-c4c50f04:10f750e1:af3b426e:ba5eef73.sh: "[ -e "/dev/disk/by-id/md-uuid-c4c50f04:10f750e1:af3b426e:ba5eef73" ]"
[  313.989573] dracut-initqueue[1375]: Warning: /lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2fdisk\x2fby-id\x2fmd-uuid-e27ee86d:2370f9ad:f5444acf:1a6165b4.sh: "[ -e "/dev/disk/by-id/md-uuid-e27ee86d:2370f9ad:f5444acf:1a6165b4" ]"
[  313.991331] dracut-initqueue[1375]: Warning: /lib/dracut/hooks/initqueue/finished/devexists-\x2fdev\x2ffedora_ryac\x2froot.sh: "[ -e "/dev/fedora_ryac/root" ]"
[  313.992957] dracut-initqueue[1375]: Warning: /lib/dracut/hooks/initqueue/finished/nm.sh: "[ -f /tmp/nm.done ]"
[  313.995314] dracut-initqueue[1375]: Warning: dracut-initqueue: starting timeout scripts
[  313.995514] dracut-initqueue[1375]: Warning: Could not boot.
         Starting dracut-emergency.…ce - Dracut Emergency Shell...
Warning: /dev/disk/by-id/md-uuid-a19d3026::: does not existPress Enter for maintenance
(or press Control-D to continue): 
```

When booting a system configured to use tang to decrypt the root disk the system reports a timeout for the luks setup, eventually dracut times out at which point I can hit ctrl-d and the system completes booting.


Dropping back to clevis-18-16.fc38.aarch64 allows my system to boot without the need of intervention 

Version-Release number of selected component (if applicable):
clevis-19-2.fc38.aarch64

How reproducible:


Steps to Reproduce:
1.
2.
3.

Actual results:


Expected results:


Additional info:

Comment 1 Sergio Correia 2023-03-14 11:49:43 UTC
Hi,

interestingly, it seems that the device is still unlocked, from the logs:

Mar 12 19:58:18 ryac.ausil.us clevis-luks-askpass[1561]: Unlocked /dev/disk/by-uuid/afb69124-101c-45fa-b39a-c744112e7251 (UUID=afb69124-101c-45fa-b39a-c744112e7251) successfully

Are you trying to unlock a single device?


Also, do you see any output when you run 'systemd-analyze verify default.target'? If you can check this also with clevis-19-2.fc38.aarch64, it might be helpful.

Comment 2 Dennis Gilmore 2023-03-14 14:38:10 UTC
NAME                                              MAJ:MIN RM   SIZE RO TYPE  MOUNTPOINTS
zram0                                             252:0    0     8G  0 disk  [SWAP]
nvme0n1                                           259:0    0 931.5G  0 disk  
├─nvme0n1p1                                       259:2    0     1G  0 part  
│ └─md127                                           9:127  0  1023M  0 raid1 /boot
├─nvme0n1p2                                       259:4    0     1G  0 part  
│ └─md125                                           9:125  0     1G  0 raid1 /boot/efi
└─nvme0n1p3                                       259:6    0 929.5G  0 part  
  └─md126                                           9:126  0 929.4G  0 raid1 
    └─fedora_ryac-root                            253:0    0 929.4G  0 lvm   
      └─luks-afb69124-101c-45fa-b39a-c744112e7251 253:1    0 929.4G  0 crypt /
nvme1n1                                           259:1    0 931.5G  0 disk  
├─nvme1n1p1                                       259:3    0     1G  0 part  
│ └─md127                                           9:127  0  1023M  0 raid1 /boot
├─nvme1n1p2                                       259:5    0     1G  0 part  
│ └─md125                                           9:125  0     1G  0 raid1 /boot/efi
└─nvme1n1p3                                       259:7    0 929.5G  0 part  
  └─md126                                           9:126  0 929.4G  0 raid1 
    └─fedora_ryac-root                            253:0    0 929.4G  0 lvm   
      └─luks-afb69124-101c-45fa-b39a-c744112e7251 253:1    0 929.4G  0 crypt /


That is my storage info. It is unlocking a single partition. clevis-19-2.fc38.aarch64 is what I was reporting as failing. 

[root@ryac ~]# systemd-analyze verify default.target
[root@ryac ~]#

Comment 3 Dennis Gilmore 2023-03-25 21:53:38 UTC
To be clear the systemd-analyse run is with clevis-19-2.fc38 installed and in use

Comment 4 Dennis Gilmore 2023-06-14 19:09:27 UTC
Reassigning to dracut, I removed clevis from use and ended up with the same broken behaviour

Comment 5 Dennis Gilmore 2023-06-14 20:03:32 UTC
dracut-059-3.fc38.aarch64
dracut-config-generic-059-3.fc38.aarch64
dracut-config-rescue-059-3.fc38.aarch64
dracut-network-059-3.fc38.aarch64
dracut-squash-059-3.fc38.aarch64