[SOLVED] PVE on encrypted NVME no longer booting

[dmpm]

I installed PVE on a hardware encrypted NVME in my Lenovo M720q, with mandos automatic decryption and dropbear as a fallback, mainly using these guides and some stuff I found elsewhere about cryptsetup and OPAL, and that was working fine. It would retrieve the key from the mandos server (on 10.10.55.20) and if that wasn't available, I could SSH in using dropbear and enter the password, or type it in locally.
https://forum.proxmox.com/threads/adding-full-disk-encryption-to-proxmox.137051/
https://blog.boyeau.com/booting-an-...server-ubuntu-server-16-04-setup-with-mandos/

However, when I just tried to boot, it's no longer working. I haven't done any updates recently, and I haven't had time to play with this server in the last couple of weeks so I don't know exactly when it stopped working. As you can see in the attached photo, it's running the process usr/lib/mandos/plugin-runner, the IP address is set to 10.10.55.198 manually in the grub config, and it starts dropbear, but then it gives some I/O errors about nvme0n1 (the only drive) and n1p3 (which is the encrypted root partition), and then it just prints a load of "Running /scripts/local-block...done" before failing and dropping to BusyBox, and it never prompts to enter the password.

The second photo shows the output from blkid after it's failed to boot. As per the guide, n1p1 is a small EFI partition, around 200MB, n1p2 is the boot partition, around 800MB, and n3 is the encrypted root partition.

I originally installed it on a Crucial self-encrypting SSD before replacing that with the NVME and reinstalling from scratch, so I'll try switching back to the SSD to see if that still works as I haven't wiped it yet, but I can't think of any reason why the NVME should stop working like this.

 

[fabian]

those errors point at the disk failing.. maybe boot a livecd and check the smart values?

 

[dmpm]

those errors point at the disk failing.. maybe boot a livecd and check the smart values?

I booted a Ubunutu livecd and ran smartctl and that doesn't seem to show any problems with the NVME.

root@ubuntu:~# smartctl /dev/nvme0n1 -a
smartctl 7.4 2023-08-01 r5530 [x86_64-linux-6.8.0-41-generic] (local build)
Copyright (C) 2002-23, Bruce Allen, Christian Franke, www.smartmontools.org

=== START OF INFORMATION SECTION ===
Model Number:                       Samsung SSD 990 EVO 1TB
Serial Number:                      S7GCNS0X222162T
Firmware Version:                   0B2QKXJ7
PCI Vendor/Subsystem ID:            0x144d
IEEE OUI Identifier:                0x002538
Total NVM Capacity:                 1,000,204,886,016 [1.00 TB]
Unallocated NVM Capacity:           0
Controller ID:                      1
NVMe Version:                       2.0
Number of Namespaces:               1
Namespace 1 Size/Capacity:          1,000,204,886,016 [1.00 TB]
Namespace 1 Utilization:            135,491,035,136 [135 GB]
Namespace 1 Formatted LBA Size:     512
Namespace 1 IEEE EUI-64:            002538 22414124f0
Local Time is:                      Tue Dec  3 16:24:34 2024 UTC
Firmware Updates (0x16):            3 Slots, no Reset required
Optional Admin Commands (0x0017):   Security Format Frmw_DL Self_Test
Optional NVM Commands (0x00df):     Comp Wr_Unc DS_Mngmt Wr_Zero Sav/Sel_Feat Timestmp Verify
Log Page Attributes (0x2f):         S/H_per_NS Cmd_Eff_Lg Ext_Get_Lg Telmtry_Lg Log0_FISE_MI
Maximum Data Transfer Size:         128 Pages
Warning  Comp. Temp. Threshold:     85 Celsius
Critical Comp. Temp. Threshold:     85 Celsius

Supported Power States
St Op     Max   Active     Idle   RL RT WL WT  Ent_Lat  Ex_Lat
 0 +     7.47W       -        -    0  0  0  0        0       0
 1 +     7.47W       -        -    1  1  1  1      500     500
 2 +     7.47W       -        -    2  2  2  2     1100    3600
 3 -   0.0800W       -        -    3  3  3  3     3700    2400
 4 -   0.0070W       -        -    4  4  4  4     3700   45000

Supported LBA Sizes (NSID 0x1)
Id Fmt  Data  Metadt  Rel_Perf
 0 +     512       0         0

=== START OF SMART DATA SECTION ===
SMART overall-health self-assessment test result: PASSED

SMART/Health Information (NVMe Log 0x02)
Critical Warning:                   0x00
Temperature:                        34 Celsius
Available Spare:                    100%
Available Spare Threshold:          10%
Percentage Used:                    0%
Data Units Read:                    1,161,697 [594 GB]
Data Units Written:                 900,469 [461 GB]
Host Read Commands:                 11,486,381
Host Write Commands:                40,261,603
Controller Busy Time:               343
Power Cycles:                       10
Power On Hours:                     712
Unsafe Shutdowns:                   7
Media and Data Integrity Errors:    0
Error Information Log Entries:      0
Warning  Comp. Temperature Time:    0
Critical Comp. Temperature Time:    0
Temperature Sensor 1:               32 Celsius
Temperature Sensor 2:               34 Celsius

Error Information (NVMe Log 0x01, 16 of 64 entries)
No Errors Logged

Read Self-test Log failed: Invalid Field in Command (0x002)

I can unlock the third partition with 'cryptsetup open /dev/nvme0n1p3 n1p3-crypt' and then access the lvs

root@ubuntu:~# lvs
  LV            VG  Attr       LSize   Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  PBS           pve -wi-a----- 100.00g
  data          pve twi-aotz-- 500.00g             8.26   12.92
  root          pve -wi-a-----  30.00g
  swap          pve -wi-a-----   8.00g
  vm-100-disk-0 pve Vwi-a-tz--   4.00m data        18.75
  vm-100-disk-1 pve Vwi-a-tz--  32.00g data        13.44
  vm-101-disk-0 pve Vwi-a-tz--   2.00g data        40.60
  vm-102-disk-0 pve Vwi-a-tz--   2.00g data        61.88
  vm-103-disk-1 pve Vwi-a-tz--   3.00g data        63.35
  vm-104-disk-0 pve Vwi-a-tz--   2.00g data        39.82
  vm-105-disk-0 pve Vwi-a-tz--   4.00g data        35.15
  vm-106-disk-0 pve Vwi-a-tz--   4.00g data        29.64
  vm-107-disk-0 pve Vwi-a-tz--   8.00g data        12.30
  vm-108-disk-0 pve Vwi-a-tz--   2.00g data        45.00
  vm-111-disk-0 pve Vwi-a-tz--   8.00g data        25.24
  vm-112-disk-0 pve Vwi-a-tz--   8.00g data        24.92
  vm-115-disk-0 pve Vwi-a-tz--   4.00g data        25.83
  vm-116-disk-0 pve Vwi-a-tz--   8.00g data        67.21
  vm-121-disk-0 pve Vwi-a-tz--  32.00g data        32.92
  vm-199-disk-0 pve Vwi-a-tz--   8.00g data        71.20
  vm-200-disk-0 pve Vwi-a-tz--   2.00g data        55.35

and then mount /dev/pve/PBS and /dev/pve/root, so the drive seems to be fine.

 

[dmpm]

I've chrooted into the Proxmox install and checked everything. The only potential issue I've found is that running 'update-initramfs -c -k all' I see this in the output "cryptsetup: WARNING: target 'n1p3-crypt' not found in /etc/crypttab"

When I run 'cryptsetup open /dev/nvme0n1p3 n1p3-crypt' in the LiveCD system, it creates /dev/mapper/n1p3-crypt, and there's also a /dev/mapper/n1p3-crypt in the Proxmox system that I'm chrooted into, which is probably left over from when I was setting it up, but in /etc/crypttab the entry I have for n1p3 is 'cryptlvm UUID=8d308592-933f-4927-b666-59494574ddf4 none luks'.

Presumably it will create /dev/mapper/cryptlvm when unlocking the partition, so I'm not sure what this warning about n1p3-crypt not being found in /etc/crypttab is about. Can I safely ignore it?

 

[fabian]

try reading the full disk and see if that throws an error.. e.g., "dd if=/dev/nvme0n1 of=/dev/null bs=1M status=progress" (this will read the full disk using 1M blocks and print progress while it is doing it). it should not throw any errors, if it does, the disk *is* broken. if that works, then we need to find out why it does not in the early stages of booting..

 

[dmpm]

try reading the full disk and see if that throws an error.. e.g., "dd if=/dev/nvme0n1 of=/dev/null bs=1M status=progress" (this will read the full disk using 1M blocks and print progress while it is doing it). it should not throw any errors, if it does, the disk *is* broken. if that works, then we need to find out why it does not in the early stages of booting..

I found that when it fails to boot and drops to BusyBox I can enter 'cryptsetup open /dev/nvme0n1p3 cryptlvm' and then 'exit' and then it boots fine. Then I ran that dd command and it doesn't show any errors, so there's something else that's causing it not to boot.

999437631488 bytes (999 GB, 931 GiB) copied, 502 s, 2.0 GB/s
953869+1 records in
953869+1 records out
1000204886016 bytes (1.0 TB, 932 GiB) copied, 502.294 s, 2.0 GB/s

 

[fabian]

maybe it was just a single cell and the NVME detected it in the meantime and marked it as bad? but usually that would show up in smartctl/nvme-cli output..

I suggest moving the "why doesn't automatic unlock work" part to mandos support channels?

 

[dmpm]

maybe it was just a single cell and the NVME detected it in the meantime and marked it as bad? but usually that would show up in smartctl/nvme-cli output..

I suggest moving the "why doesn't automatic unlock work" part to mandos support channels?

It's not just the automatic unlock that's not working though. It's not even prompting me to enter the password, which it should do even without dropbear or mandos installed.

 

[fabian]

could you maybe try to get a full dmesg log from such a failed boot?

 

[dmpm]

could you maybe try to get a full dmesg log from such a failed boot?

I've attached the output from 'journalctl -o short-precise -k ' which is for the current boot. The nvme I/O errors start at 18:16:01.564522 but I can't see where it dropped to busybox and I manually ran cryptsetup and exited before it resumed booting. I see it mounted the root partition (UUID starting 0a9bb) as r/o and then remounted it as r/w at 18:16:01.569089 but that's too soon to be after I manually unlocked it.

Just checking for errors, 'dmesg -T --color=always --level=err,warn | more' returns:

[Wed Dec 4 18:14:25 2024] x86/cpu: SGX disabled by BIOS.
[Wed Dec 4 18:14:25 2024] hpet_acpi_add: no address or irqs in _CRS
[Wed Dec 4 18:14:25 2024] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log.
[Wed Dec 4 18:14:25 2024] platform eisa.0: EISA: Cannot allocate resource for mainboard
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 1
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 2
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 3
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 4
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 5
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 6
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 7
[Wed Dec 4 18:14:25 2024] platform eisa.0: Cannot allocate resource for EISA slot 8
[Wed Dec 4 18:14:26 2024] ENERGY_PERF_BIAS: Set to 'normal', was 'performance'
[Wed Dec 4 18:14:27 2024] nvme0n1: I/O Cmd(0x2) @ LBA 1757161344, 8 blocks, I/O Error (sct 0x2 / sc 0x86) DNR
[Wed Dec 4 18:14:27 2024] critical medium error, dev nvme0n1, sector 1757161344 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[Wed Dec 4 18:14:27 2024] nvme0n1: I/O Cmd(0x2) @ LBA 1757161344, 8 blocks, I/O Error (sct 0x2 / sc 0x86) DNR
[Wed Dec 4 18:14:27 2024] critical medium error, dev nvme0n1, sector 1757161344 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[Wed Dec 4 18:14:27 2024] Buffer I/O error on dev nvme0n1p3, logical block 219414512, async page read
[Wed Dec 4 18:14:27 2024] process 'usr/lib/mandos/plugin-runner' started with executable stack
[Wed Dec 4 18:14:27 2024] nvme0n1: I/O Cmd(0x2) @ LBA 1757161344, 8 blocks, I/O Error (sct 0x2 / sc 0x86) DNR
[Wed Dec 4 18:14:27 2024] critical medium error, dev nvme0n1, sector 1757161344 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[Wed Dec 4 18:14:27 2024] nvme0n1: I/O Cmd(0x2) @ LBA 1757161344, 8 blocks, I/O Error (sct 0x2 / sc 0x86) DNR
[Wed Dec 4 18:14:27 2024] critical medium error, dev nvme0n1, sector 1757161344 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[Wed Dec 4 18:14:27 2024] Buffer I/O error on dev nvme0n1p3, logical block 219414512, async page read
[Wed Dec 4 18:15:24 2024] nvme0n1: I/O Cmd(0x2) @ LBA 1757161344, 8 blocks, I/O Error (sct 0x2 / sc 0x86) DNR
[Wed Dec 4 18:15:24 2024] critical medium error, dev nvme0n1, sector 1757161344 op 0x0:(READ) flags 0x80700 phys_seg 1 prio class 0
[Wed Dec 4 18:15:24 2024] nvme0n1: I/O Cmd(0x2) @ LBA 1757161344, 8 blocks, I/O Error (sct 0x2 / sc 0x86) DNR
[Wed Dec 4 18:15:24 2024] critical medium error, dev nvme0n1, sector 1757161344 op 0x0:(READ) flags 0x0 phys_seg 1 prio class 0
[Wed Dec 4 18:15:24 2024] Buffer I/O error on dev nvme0n1p3, logical block 219414512, async page read
[Wed Dec 4 18:15:59 2024] systemd-sysv-generator[834]: SysV service '/etc/init.d/rrdcached' lacks a native systemd unit file. ~ Automatically generating a unit file
for compatibility. Please update package to include a native systemd unit file, in order to make it safe, robust and future-proof. ! This compatibility logic is deprecated, expect rem
oval soon. !
[Wed Dec 4 18:15:59 2024] systemd-sysv-generator[834]: SysV service '/etc/init.d/rng-tools-debian' lacks a native systemd unit file. ~ Automatically generating a uni
t file for compatibility. Please update package to include a native systemd unit file, in order to make it safe, robust and future-proof. ! This compatibility logic is deprecated, exp
ect removal soon. !
[Wed Dec 4 18:16:00 2024] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
[Wed Dec 4 18:16:00 2024] Bluetooth: hci0: Reading supported features failed (-16)
[Wed Dec 4 18:16:00 2024] Bluetooth: hci0: HCI LE Coded PHY feature bit is set, but its usage is not supported.
[Wed Dec 4 18:16:00 2024] thermal thermal_zone2: failed to read out thermal zone (-61)
[Wed Dec 4 18:16:01 2024] i915 0000:00:02.0: Direct firmware load for i915/gvt/vid_0x8086_did_0x3e92_rid_0x00.golden_hw_state failed with error -2
[Wed Dec 4 18:16:01 2024] spl: loading out-of-tree module taints kernel.
[Wed Dec 4 18:16:01 2024] zfs: module license 'CDDL' taints kernel.
[Wed Dec 4 18:16:01 2024] Disabling lock debugging due to kernel taint
[Wed Dec 4 18:16:01 2024] zfs: module license taints kernel.
[Wed Dec 4 18:17:44 2024] kauditd_printk_skb: 16 callbacks suppressed
[Wed Dec 4 18:37:44 2024] systemd-sysv-generator[20527]: SysV service '/etc/init.d/rrdcached' lacks a native systemd unit file. ~ Automatically generating a unit fil
e for compatibility. Please update package to include a native systemd unit file, in order to make it safe, robust and future-proof. ! This compatibility logic is deprecated, expect r
emoval soon. !
[Wed Dec 4 18:37:44 2024] systemd-sysv-generator[20527]: SysV service '/etc/init.d/rng-tools-debian' lacks a native systemd unit file. ~ Automatically generating a u
nit file for compatibility. Please update package to include a native systemd unit file, in order to make it safe, robust and future-proof. ! This compatibility logic is deprecated, e
xpect removal soon. !
[Thu Dec 5 16:01:26 2024] kauditd_printk_skb: 13 callbacks suppressed
[Fri Dec 6 01:30:52 2024] EXT4-fs (dm-25): write access unavailable, skipping orphan cleanup
[Fri Dec 6 01:31:17 2024] EXT4-fs (dm-25): write access unavailable, skipping orphan cleanup
[Sat Dec 7 01:30:31 2024] EXT4-fs (dm-25): write access unavailable, skipping orphan cleanup
[Sat Dec 7 01:30:56 2024] EXT4-fs (dm-25): write access unavailable, skipping orphan cleanup
[Sun Dec 8 01:30:28 2024] EXT4-fs (dm-25): write access unavailable, skipping orphan cleanup
[Sun Dec 8 01:30:53 2024] EXT4-fs (dm-25): write access unavailable, skipping orphan cleanup

 

[fabian]

that dm-1 device is very likely your rootfs, since it got mounted right before systemd starts executing (which is the first thing that happens after pivoting to the root file system).. I have to agree that that log doesn't really look like a manual unlock from initrd to me either, are you sure you didn't mix up the boots?

in any case, those errors still point at a hardware issue.. a disk shouldn't report I/O errors when reading

 

[dmpm]

that dm-1 device is very likely your rootfs, since it got mounted right before systemd starts executing (which is the first thing that happens after pivoting to the root file system).. I have to agree that that log doesn't really look like a manual unlock from initrd to me either, are you sure you didn't mix up the boots?

in any case, those errors still point at a hardware issue.. a disk shouldn't report I/O errors when reading

My understanding is that 'journalctl -o short-precise -k' provides the log for the current boot, so unless that's incorrect that must be the right log.

I agree that a disk shouldn't report I/O errors when reading, but the fact that the smartctl and dd tests don't show any problem seems to rule out a hardware issue, so maybe some software in the boot process is corrupted and that is causing the system not to prompt for the decrypt password and to report false I/O errors.

 

[dmpm]

I just updated PVE to the latest version, and everything's working again now, with no I/O errors, so I guess it must have been some borked software causing the problems.