Skip to content

Conversation

@tlaurion
Copy link
Collaborator

@tlaurion tlaurion commented Mar 17, 2025

Fixes #1562
Supeseeds #1934 + reviewed changes


@marmarek/ @JonathonHall-Purism : good enough for merge?
EDIT: Thanks @JonathonHall-Purism for your review. All comments addressed.


Changes:

  • No more multi-console 3 attempts of TPMTOTP unsealing for race condition management when simultaneous TPM usage (introduced on Talos-2 port since dual console output on BMC and display consoles) : now if TPM unseal fails, we die
    • Now die() asks to press Enter key, which is clearer for UX to understand what fails
  • Add of DEBUG + TRACE_FUNC calls and call stack traces (this is 280cb1f which is PR DEBUG+TRACE mode: provide a complete call stack trace on console / debug.log #1934)
  • Bumps hotp-verification to 1.7+ unreleased fixes under 1.71/1.8 so that hotp_verification output is on multi-lines even if hiccups on physical presence detection
  • Clarifies TPM counter creation + increment (I had bad time understanding why things were not working. Easier to understand and debug if needed in the future, easy to understand if board is in DEBUG+TRACE mode)
    • Added TRACE_FUNC (which now outputs call hierarchy) along the way so that when in DEBUG+TRACE mode, call trace is now easy to follow for the future.
  • ident to tabs on all code reviewed.
  • When going to recovery shell: guide user into how to provide logs (enable debug, and then when in debug, recovery shell shows how to mount usb dongle and put logs there).

@tlaurion
Copy link
Collaborator Author

tlaurion commented Mar 18, 2025

@marmarek

This is ./docker_repro.sh make BOARD=qemu-coreboot-fbwhiptail-tpm2-hotp-prod_quiet USB_TOKEN=Nitrokey3NFC PUBKEY_ASC=pubkey.asc inject_gpg run with nk3 passed to testing qube.

Simulating OS reinstallation (wiping /boot/kexec*)

So same firmware, meaning:

  • Same firmware, with public key fused in rom and measured. So TPMTOTP good. Should warn that HOTP counter doesn't exist and prompt for HOTP reseal.
  • Let's wipe /boot/kexec* files:
    2025-03-17-200019
  • Reboot. And Then:
    2025-03-17-200115
    2025-03-17-200208
  • Then selection non-existing default boot should pick up and guide user into signing and selecting default:
    2025-03-17-200244
    2025-03-17-200319
    2025-03-17-200408
  • And then finally ask if TPM DUK must be created (optional):
    2025-03-17-195901

@JonathonHall-Purism

Other changes

  • Stubborn users not following on screen instructions still are reminded that they haven't followed instructions. die() now requires to "Press a any key:
    2025-03-17-201600
    2025-03-17-201614
    2025-03-17-201632
    2025-03-17-201655
    2025-03-17-201729
    2025-03-17-201755
  • rest as usual.

@tlaurion tlaurion marked this pull request as draft March 18, 2025 00:21
@tlaurion tlaurion changed the title WiP - HOTP asked to be resealed even if TOTP good (Picks up on a reinstalled OS even if firmware measurements haven't changed) HOTP asked to be resealed even if TOTP good (Picks up on a reinstalled OS even if firmware measurements haven't changed) Mar 18, 2025
@tlaurion tlaurion marked this pull request as ready for review March 18, 2025 00:21
@tlaurion
Copy link
Collaborator Author

@JonathonHall-Purism in debug.

This is ./docker_repro.sh make BOARD=qemu-coreboot-whiptail-tpm2-hotp USB_TOKEN=Nitrokey3NFC PUBKEY_ASC=pubkey.asc inject_gpg run

To show 280cb1f

  • User does reseal TPMTOTP/HOTP instead of reset TPM:
    2025-03-17-202616
    2025-03-17-202819

So now user is locked in into following steps:

  • Reset TPM, which reseals TPM/HOTP + updates checksums and sign /boot
  • Be happy (user guided to do the right thing

Full debug log of the combined steps (user doing Reset TPM as asked up to setting TPM DUK) with way more interesting call stack for everyone to understand:
full_debug_trace-from_tpm_reset-to_TPM_DUK.txt

Note:
For those who doesn't own a NK3/Librem Key : use non-hotp variants. qemu boards enforce canokey for GPG OpenPGP smartcard operations, follow targets/qemu.md, starting with ./docker_repro.sh make BOARD=qemu-coreboot-fbwhiptail-tpm2. You can learn Heads, or develop/contribute by running non prod_quiet versions, which will output in TRACE+DEBUG mode.

@marmarek
Copy link
Contributor

To be clear - previously after OS reinstall (including removal of /boot/kexec* files) the recommendation was to do full TPM reset, and now just resealing the HOTP secret should work, right?


counter_value=$(cat $HOTP_COUNTER)
#if HOTP_COUNTER is not present, bail out
if [ ! -f $HOTP_COUNTER ]; then
Copy link
Collaborator Author

@tlaurion tlaurion Mar 18, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@marmarek the issue was that previously, if TOTPM previously sealed/unsealed (measured boot from coreboot+heads), Heads was not looking to see if HOTP counter under /boot/kexec_hotp_counter was still present.

fi

if [[ "$CONFIG_TPM" = n && "$HOTP" = "Invalid code" ]]; then
if [[ "$HOTP" = "Invalid code" ]]; then
Copy link
Collaborator Author

@tlaurion tlaurion Mar 18, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This check only verified if HOTP was invalid if no TPM was in use.

So now, if there is no /boot/kexec_hotp_counter and TPMTOTP can unseal, user is promoted to reseal HOTP alone (OS reinstall use case without firmware upgrade)

This comment was marked as outdated.

Copy link
Collaborator Author

@tlaurion tlaurion left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@marmarek added comments in code: with this PR, HOTP counter not being present will guide user to only reseal HOTP and generate hashes and /boot detached signed digest files, as well as selecting default boot and propose to set TPM DUK.

So TPM reset is not needed anymore in case of OS re-installation for TPM1.
For TPM2, TPM primary handle still needs to be created+hashed, which is TPM Reset is advised for creation and hash creation advised for in output as well.

This is workaround for you issue.

  • #1480 is still the real solution to get rid of TPM2 primary handle (discussion at #1655)
  • Getting rid of HOTP counter issue tracking is #1651

@tlaurion tlaurion force-pushed the hotp_fixup_without_firmware_upgrade_boot_wiped branch from 6159012 to 75e766a Compare March 18, 2025 15:42
Copy link
Collaborator

@JonathonHall-Purism JonathonHall-Purism left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks @tlaurion, strategy looks good to me and I left comments on some of the details 💯

tee /tmp/counter-$1 >/dev/null 2>&1 ||
die "TPM counter increment failed for rollback prevention. Please reset the TPM"
die "TPM counter increment failed for rollback prevention. Please reset the TPM. Press Enter to continue"
#TODO: why the die here needs to say to Press Enter to continue? Should be part of die call?
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe because oem-factory-reset has its own die()? It's not equivalent to this one though so you can't just delete it (kills some TOP_PID it captured rather than exiting) 🤔

@tlaurion tlaurion marked this pull request as draft March 25, 2025 16:28
@tlaurion tlaurion force-pushed the hotp_fixup_without_firmware_upgrade_boot_wiped branch 4 times, most recently from 5cfcc73 to 47c696f Compare March 25, 2025 22:25
DO_WITH_DEBUG tpm forceclear &>/dev/null
DO_WITH_DEBUG tpm physicalenable &>/dev/null
DO_WITH_DEBUG tpm takeown -pwdo "$tpm_owner_password" &>/dev/null
DO_WITH_DEBUG --mask-position 3 tpm takeown -pwdo "$tpm_owner_password" &>/dev/null
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

DEBUG was exposing TPM owner passphrase on log + debug.log

@tlaurion tlaurion force-pushed the hotp_fixup_without_firmware_upgrade_boot_wiped branch 2 times, most recently from c38c13b to dae9e85 Compare March 25, 2025 22:33
mount /dev/sda1 /boot && mount -o remount,rw /boot && rm /boot/kexec* && mount -o remount,ro /boot
#Generate keys on OpenPGP smartcard:
mount-usb && gpg --home=/.gnupg/ --card-edit
mount-usb --mode rw && gpg --home=/.gnupg/ --card-edit
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

bash history now promotes mount-usb --mode rw. nitpick

…ives call hierarchy, fix HOTP resealing only on OS reinstall, clarify TPM increment workflow

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
@tlaurion tlaurion force-pushed the hotp_fixup_without_firmware_upgrade_boot_wiped branch from dae9e85 to 1f6a975 Compare March 26, 2025 03:12
@tlaurion tlaurion marked this pull request as ready for review March 26, 2025 03:17
TOTP="NO TPM"
else
TOTP=$(unseal-totp)
# On platforms using CONFIG_BOOT_EXTRA_TTYS multiple processes may try to
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

No more 3 attempts on boot to unseal TPMTOTP: if multiple consoles (Eg Talos-2 with display console + BMC, at worst we could intruduce small delay if race condition still happening, while die asks user to press Enter now, guiding to reseal TPMTOTP or reset TPM if unable to access TPM NVRAM.

@tlaurion
Copy link
Collaborator Author

tlaurion commented Mar 26, 2025

  • Using it on nv41, wiped /boot/kexec* : simulating OS reinstall: ok
  • Tested under qemu tpm2:
    • Wiped build///vtpm : reseal TPMTOTP/HOTP dies telling user reset tpm needed TPM not owned) : ok
    • Wiped /boot/kexechotp : Reseal HOTP picks up when TPMTOTP is good: tests your reinstall case: ok

@tlaurion
Copy link
Collaborator Author

tlaurion commented Jun 23, 2025

#1935 (comment) testing showed:

TODO, fix

@marmarek if you could restest with 1a8d685 I think this is good to merge after testing + @JonathonHall-Purism final code review is needed (die now wait for input; warn waits 1 second; both of which don't require docs changes after reading.
This will most probably require automated testing changes if those exists @macpijan (as can be seen under screenshots at #1935 (comment) and ERROR: messages followed by Press Enter to continue..., if you want to open an issue pointing to testing changes introduced here.

I could clean commit logs once testing is reported fixing everything reported here, (and making console output clear and code clearer and having warnings that can actually be seen, errors that ask user acknowledgement etc, which are all input for now merged first steps of #1888 but I have not much more time to put here after that.

@tlaurion tlaurion requested review from JonathonHall-Purism and removed request for JonathonHall-Purism June 23, 2025 20:13
@marmarek
Copy link
Contributor

Thanks, I'll test it soon, but it will take me some time. That test system got hit with #1882 again :(

@marmarek
Copy link
Contributor

HOTP part seems to be okay now, but signing boot files fails with can't stat '/tmp/kexec/kexec_tree.txt.user': No such file or directory and then prompts for the TPM Owner Password. Or maybe the message is about something else (rollback counter)? It's not clear from the message, but normally I'd expect GPG card pin at this stage...
See here: https://openqa.qubes-os.org/tests/145106#step/firstboot/12 (and the next step)

@tlaurion
Copy link
Collaborator Author

HOTP part seems to be okay now, but signing boot files fails with can't stat '/tmp/kexec/kexec_tree.txt.user': No such file or directory and then prompts for the TPM Owner Password. Or maybe the message is about something else (rollback counter)? It's not clear from the message, but normally I'd expect GPG card pin at this stage... See here: https://openqa.qubes-os.org/tests/145106#step/firstboot/12 (and the next step)

Recontextualization of your use case:
1- reinstall QubesOS on a previously owned laptop (TPM owner password is set)

  • There is no kexec_*.txt files under /boot left by Heads since /boot got wiped per reinstall
    • This also means there is no kexec_tree.txt/kexec_tree.txt.user to compare since no default boot nor saved /boot hashes have been saved before (I could silence this, but aht would still require TPM owner passphrase to set TPM counter, yes.

@marmarek what would you like to see here? I agree the diff/file non existience is not helpful here. But what would be?

@marmarek
Copy link
Contributor

Ok, so it seems the issue is about the message - normally the "Missing file" error is about signing /boot content with gpg, and the next step is about signing them (see https://openqa.qubes-os.org/tests/145090#step/firstboot/4 for example). TPM owner password is unexpected/surprising prompt. So, maybe just add one line before that prompt explaining why it's asking for it? Alternatively, change the "Missing file" error to include that info?

tlaurion added 6 commits June 30, 2025 15:48
Tested under QEMU
- wipe of /boot/kexec_*
- TPM reset + boot default + define default + TPM DUK
- remove qemu *.rom files (so keyring injected is unique and triggers TPM unseal error on boot)
- Reseal TPMTOTP+HOTP succeeds giving debug output of TPM counter increment succeeding
- comparing hashes under /boot/kexec_rollback.txt validates TPM increment works and is validated (rollback is to prevent copying old kexec*.txt + kexec.sig under /boot)

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
…o when no previous file exists

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
…rning to user that he will be prompted for TPM Owner Password to set new TPM counter for /boot content rollback prevention

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
…for input

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
…answers are escaped prior of being put in variable (remove TODO)

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
Signed-off-by: Thierry Laurion <insurgo@riseup.net>
@tlaurion tlaurion force-pushed the hotp_fixup_without_firmware_upgrade_boot_wiped branch from 1e60236 to 21adb0d Compare July 10, 2025 18:02
@tlaurion
Copy link
Collaborator Author

In last rounds of testing (w530), updating firmware required TPM reset for some reason, where resealing TOTP was not enough.
This cause issue since GPG prompt to sign digests actually hid TPM ownership PIN being required and Heads seemed frozen without asking GPG prompt.

I'll try to repro, but I remember this issue vanished with this PR. (which was abandonned a long time ago...... because it involved way too much work).

@marmarek
Copy link
Contributor

I remember I hit similar issue before, it was about one too many >/dev/null somewhere. I can't find notes about this issue (I think I posted it somewhere? some comment in one of issues here?), but AFAIR it was something about check_tpm_counter output being hidden, but it prompting for TPM password

Signed-off-by: Thierry Laurion <insurgo@riseup.net>
if [ -r "$1" ]; then
TPM_COUNTER=$(grep counter- "$1" | cut -d- -f2)
# Robustly extract the first hex string after 'counter-' on any line
TPM_COUNTER=$(grep -Eo 'counter-[0-9a-fA-F]+' "$1" | sed -n 's/counter-//p' | head -n1 | tr -d '\n')
Copy link
Collaborator Author

@tlaurion tlaurion Nov 20, 2025

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is where check_tpm_counter failed and where TPM passphtase was asked in silenced output @marmarek

DEBUG "Detach-signing boot files under kexec.sig: ${param_files}"

if sha256sum $param_files 2>/dev/null | gpg \
if sha256sum $param_files 2>/dev/null | gpg --detach-sign \
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cosmetic; just so its easier to search codebase for gpg --detach-sign operations.

@@ -0,0 +1,10 @@
Welcome to the Recovery Shell!
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@JonathonHall-Purism pushing this forward unless you push veto.


# Traverse the call stack from the earliest caller to the direct caller of TRACE_FUNC
for ((i = ${#FUNCNAME[@]} - 1; i > 1; i--)); do
stack_trace+="${FUNCNAME[i]}(${BASH_SOURCE[i]}:${BASH_LINENO[i - 1]}) -> "
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Precious: permits to see how we arrived here; important for newcomers, audits of code and debugging.

@tlaurion
Copy link
Collaborator Author

tlaurion commented Nov 20, 2025

repro

./docker_repro.sh make BOARD=qemu-coreboot-fbwhiptail-tpm2
#hardlink disk image to where its stored on same disk when Heads complains about no OS installed. Have to install once, of course, and move it out to reuse.... copy into directory where qemu roms are built
sudo cp -alf ~/qemu-disks/debian-12-2_luks.qcow2 /home/user/heads/build/x86/qemu-coreboot-fbwhiptail-tpm2/root.qcow2
#cp public key of testing linked USB Security dongle once to be reused in make calls with inject_gpg and PUBJEY_ASC=
cp ~/Insurgo_2024_no_expiration_date.asc pubkey.asc

./docker_repro.sh make BOARD=qemu-coreboot-fbwhiptail-tpm2-hotp-prod_quiet USB_TOKEN=Nitrokey3NFC PUBKEY_ASC=pubkey.asc inject_gpg run

Normal update

2025-11-20-174307 2025-11-20-174307

OS reinstallation simulation (TPM measurements good, only heads related kexec* files wiped)

2025-11-20-175234 2025-11-20-175746 2025-11-20-175821

Others

./docker_repro.sh make BOARD=qemu-coreboot-fbwhiptail-tpm2 USB_TOKEN=Nitrokey3NFC PUBKEY_ASC=pubkey.asc inject_gpg run
!!! Hit enter to proceed to recovery shell !!!
[   10.006841] DEBUG: Loading linux kernel shipped keyboard layout keymap: share/keymaps/defkeymap.map
[   10.071749] DEBUG: loadkeys --default
[   10.211091] DEBUG: Loading keyboard keymap: /usr/lib/kbd/keymaps/i386/qwerty/us.map
[   10.279207] DEBUG: loadkeys /usr/lib/kbd/keymaps/i386/qwerty/us.map
[   10.731699] TRACE: main(/bin/setconsolefont.sh:6)
[   10.817012] DEBUG: Keep default console font size due to framebuffer height 768
[   10.980115] TRACE: main(/bin/gui-init:639)
[   11.001208] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1247)
[   11.413451] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1203)
[   11.477417] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1215) -> is_gpt_bios_grub(/etc/functions:1163)
[   11.567315] TRACE: /dev/vda1 is partition 1 of vda
[   11.670591] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1216) -> find_lvm_vg_name(/etc/functions:1140)
[   11.891298] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1230)
[   11.965622] DEBUG: Try mounting /dev/vda1 as /boot
[   12.051817] EXT4-fs (vda1): mounted filesystem with ordered data mode. Quota mode: disabled.
[   12.133608] TRACE: main(/bin/gui-init:654) -> clean_boot_check(/bin/gui-init:307)
[   12.245017] TRACE: main(/bin/gui-init:662) -> check_gpg_key(/bin/gui-init:335)
[   12.395039] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:183)
[   12.550313] TRACE: main(/bin/unseal-totp:8)
[   12.625103] DEBUG: tpmr unseal 4d47 0,1,2,3,4,7 312 <hidden>
[   12.819505] TRACE: main(/bin/tpmr:870) -> tpm2_unseal(/bin/tpmr:572)
[   12.915663] DEBUG: tpm2_unseal: handle=0x81004d47 pcrl=0,1,2,3,4,7 file=/tmp/secret/totp.key pass=<empty>
[   13.484474] TRACE: main(/bin/tpmr:870) -> tpm2_unseal(/bin/tpmr:617) -> INFO(/etc/functions:80)
[   13.515055] Unable to unseal secret from TPM NVRAM
[   13.569522] DEBUG: Running at_exit handlers
[   13.601117] TRACE: main(/bin/tpmr:870) -> tpm2_unseal(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_session(/bin/tpmr:378)
[   13.665396] DEBUG: Clean up session: /tmp/secret/unsealfile_policy.session
[   13.823607] DEBUG: tpmr: exited with status 1
[   13.851601] TRACE: main(/bin/unseal-totp:13) -> die(/etc/functions:6)
[   13.883793]  !!! ERROR: Unable to unseal TOTP secret from TPM !!!
[  348.317198] DEBUG: CONFIG_TPM: y
[  348.380434] DEBUG: CONFIG_TPM2_TOOLS: y
[  348.453330] DEBUG: Show PCRs
[  348.590525] DEBUG:   sha256:
[  348.603104] 0 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.666458] 1 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.723882] 2 : 0x57B7F0ECC5F3E556247361BFDC6EAB19320B2AA900DE87AE25FBA9673DE1CED4
[  348.740777] 3 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.764715] 4 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.784009] 5 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.826048] 6 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.849276] 7 : 0x407927B4884B014901A6E13ED21B8AEBA4FAB8A36FFEE8A2FF688DD4EC7445BA
[  348.894635] 8 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.940115] 9 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  348.958379] 10: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.015560] 11: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.033137] 12: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.101827] 13: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.158497] 14: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.196001] 15: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.218484] 16: 0x0000000000000000000000000000000000000000000000000000000000000000
[  349.278633] 17: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  349.322988] 18: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  349.365859] 19: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  349.396746] 20: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  349.411730] 21: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  349.484489] 22: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  349.538341] 23: 0x0000000000000000000000000000000000000000000000000000000000000000
[  354.704779] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> generate_totp_hotp(/bin/gui-init:150)
[  354.803744] TRACE: main(/bin/seal-totp:10)
[  354.883328] DEBUG: Sealing TOTP with actual state of PCR0-3
[  354.975932] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  355.055151] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:0
[  355.314136] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  355.387614] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:1
[  355.641010] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  355.743173] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:2
[  356.017468] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  356.068205] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:3
[  356.271621] DEBUG: Sealing TOTP with boot state of PCR4 (Going to recovery shell extends PCR4)
[  356.363480] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:197)
[  356.473937] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[  356.497983] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[  356.601691] DEBUG: Replayed cbmem -L clean boot state of PCR=4 ALG=sha256 : 0000000000000000000000000000000000000000000000000000000000000000
[  356.699847] DEBUG: Sealing TOTP neglecting PCR5 involvement (Dynamically loaded kernel modules are not firmware integrity attestation related)
[  356.763177] DEBUG: Sealing TOTP without PCR6 involvement (LUKS header consistency is not firmware integrity attestation related)
[  356.826136] DEBUG: Sealing TOTP with actual state of PCR7 (User injected stuff in cbfs)
[  356.916095] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  356.979531] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:7
[  357.244411] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:432)
[  357.362676] DEBUG: tpm2_seal: file=/tmp/secret/totp.key handle=0x81004d47 pcrl=0,1,2,3,4,7 pcrf=/tmp/secret/pcrf.bin pass=<empty>
[  358.017586] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:491) -> prompt_tpm_owner_password(/etc/functions:780)
[  361.037715] DEBUG: Caching TPM Owner Password to /tmp/secret/tpm_owner_password
[  361.094539] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:493) -> tpm2_password_hex(/bin/tpmr:45)
[  361.290286] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:495) -> tpm2_password_hex(/bin/tpmr:45)
[  361.384190] DEBUG: tpm2 evictcontrol -Q -C o -P <hidden> -c /tmp/secret/totp.key.seal.ctx 0x81004d47
[  361.644310] DEBUG: Running at_exit handlers
[  361.666461] TRACE: main(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_session(/bin/tpmr:378)
[  361.779191] DEBUG: Clean up session: /tmp/secret/sealfile_trial.session
[  361.903233] DEBUG: TOTP secret output on screen (both URL and QR code)
[  365.336722] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:183)
[  365.569747] TRACE: main(/bin/unseal-totp:8)
[  365.704843] DEBUG: tpmr unseal 4d47 0,1,2,3,4,7 312 <hidden>
[  366.126793] TRACE: main(/bin/tpmr:870) -> tpm2_unseal(/bin/tpmr:572)
[  366.243587] DEBUG: tpm2_unseal: handle=0x81004d47 pcrl=0,1,2,3,4,7 file=/tmp/secret/totp.key pass=<empty>
[  366.790988] DEBUG: Running at_exit handlers
[  366.805447] TRACE: main(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_session(/bin/tpmr:378)
[  366.875109] DEBUG: Clean up session: /tmp/secret/unsealfile_policy.session
[  367.024588] DEBUG: totp -q
[  367.178200] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> reseal_tpm_disk_decryption_key(/etc/functions:649)
[  367.233576] DEBUG: LUKS TPM Disk Unlock Key is allowed in board configs. Continuing
[  368.431097] TRACE: main(/bin/kexec-seal-key:35)
[  368.542282] DEBUG: Devices defined for disk encryption: /dev/vda3 /dev/vda5
[  368.603834] DEBUG: No LVM volume group defined for activation
[  368.755645] DEBUG:   sha256:
[  368.784849] 0 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  368.808727] 1 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  368.831961] 2 : 0x57B7F0ECC5F3E556247361BFDC6EAB19320B2AA900DE87AE25FBA9673DE1CED4
[  368.847997] 3 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  368.863208] 4 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  368.886108] 5 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  368.912091] 6 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  368.947648] 7 : 0x407927B4884B014901A6E13ED21B8AEBA4FAB8A36FFEE8A2FF688DD4EC7445BA
[  368.973717] 8 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.002980] 9 : 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.038162] 10: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.053021] 11: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.071934] 12: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.103617] 13: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.144116] 14: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.161368] 15: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.176812] 16: 0x0000000000000000000000000000000000000000000000000000000000000000
[  369.192975] 17: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  369.211163] 18: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  369.238183] 19: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  369.265045] 20: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  369.285849] 21: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  369.301846] 22: 0xFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFFF
[  369.334552] 23: 0x0000000000000000000000000000000000000000000000000000000000000000
[  379.305925] DEBUG: Testing /tmp/secret/recovery.key keyfile against /dev/vda3
[  383.801177] DEBUG: Testing /tmp/secret/recovery.key keyfile against /dev/vda5
[  393.534779] TRACE: main(/bin/kexec-seal-key:118) -> warn(/etc/functions:24)
[  393.582196]  *** WARNING: Disk Unlock Key (DUK) passphrases do not match. Please try again. ***
[  401.097951] DEBUG: /dev/vda3: LUKSv2 device detected
[  401.235651] DEBUG: /dev/vda3 LUKS key slots: 0 31
[  401.285527] DEBUG: Testing LUKS key slot 0 against /tmp/secret/recovery.key for Disk Recovery Key slot...
[  401.339051] DEBUG: cryptsetup open --test-passphrase --key-slot 0 --key-file /tmp/secret/recovery.key /dev/vda3
[  403.541788] DEBUG: Disk Recovery key slot is 0
[  403.594143] DEBUG: LUKS key slot 31 is the expected DUK key slot. Will wipe this DUK key slot silently
[  403.664522] DEBUG: cryptsetup luksKillSlot --key-file /tmp/secret/recovery.key /dev/vda3 31
[  406.557726] DEBUG: cryptsetup luksAddKey --key-file /tmp/secret/recovery.key --new-key-slot 31 /dev/vda3 /tmp/secret/secret.key
[  418.694169] DEBUG: /dev/vda5: LUKSv2 device detected
[  418.864424] DEBUG: /dev/vda5 LUKS key slots: 0 31
[  418.931855] DEBUG: Testing LUKS key slot 0 against /tmp/secret/recovery.key for Disk Recovery Key slot...
[  418.993347] DEBUG: cryptsetup open --test-passphrase --key-slot 0 --key-file /tmp/secret/recovery.key /dev/vda5
[  421.781738] DEBUG: Disk Recovery key slot is 0
[  421.849826] DEBUG: LUKS key slot 31 is the expected DUK key slot. Will wipe this DUK key slot silently
[  421.922348] DEBUG: cryptsetup luksKillSlot --key-file /tmp/secret/recovery.key /dev/vda5 31
[  424.848607] DEBUG: cryptsetup luksAddKey --key-file /tmp/secret/recovery.key --new-key-slot 31 /dev/vda5 /tmp/secret/secret.key
[  443.251588] TRACE: main(/bin/qubes-measure-luks:6)
[  443.310924] DEBUG: Arguments passed to qubes-measure-luks: /dev/vda3 /dev/vda5
[  443.397184] DEBUG: Storing LUKS header for /dev/vda3 into /tmp/lukshdr-_dev_vda3
[  443.783960] DEBUG: Storing LUKS header for /dev/vda5 into /tmp/lukshdr-_dev_vda5
[  443.985275] DEBUG: Hashing LUKS headers into /tmp/luksDump.txt
[  444.462702] DEBUG: Removing /tmp/lukshdr-*
[  444.510482] TRACE: main(/bin/qubes-measure-luks:22)
[  444.535203] TRACE: main(/bin/qubes-measure-luks:23) -> INFO(/etc/functions:80)
[  444.559727] TPM: Extending PCR[6] with hash of LUKS headers from /tmp/luksDump.txt
[  444.673340] TRACE: main(/bin/tpmr:847)
[  444.715953] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  444.762802] TPM: Extending PCR[6] with /tmp/luksDump.txt
[  444.801832] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  444.839797] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  444.905163] DEBUG: TPM: Will extend PCR[6] with hash of file content /tmp/luksDump.txt
[  445.094039] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  445.130890] sha256: 6 : 0xF450E2F4F1851F6A6A3D3CAA9614164CB92B63EF5750646D4FAB9CFC5EBCBF29
[  445.171032] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  445.237474] DEBUG: TPM: Extended PCR[6] with hash db9ad2084912330006fa64d2495f0a12e5d568e657f99daa1187bb0271acf75f
[  445.339431] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  445.386647] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:0
[  445.878565] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  445.956571] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:1
[  446.228694] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  446.311577] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:2
[  446.485660] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  446.534425] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:3
[  446.713448] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:197)
[  446.793313] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[  446.820974] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[  446.894432] DEBUG: Replayed cbmem -L clean boot state of PCR=4 ALG=sha256 : 0000000000000000000000000000000000000000000000000000000000000000
[  446.937354] DEBUG: Sealing LUKS TPM Disk Unlock Key with PCR5=0 (NO additional kernel modules are loaded per board config)...
[  447.011858] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:197)
[  447.122953] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[  447.167743] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[  447.273071] DEBUG: Replayed cbmem -L clean boot state of PCR=5 ALG=sha256 : 0000000000000000000000000000000000000000000000000000000000000000
[  447.346882] DEBUG: Precomputing TPM future value for PCR6 sealing/unsealing of LUKS TPM Disk Unlock Key...
[  447.426874] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:197)
[  447.501534] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[  447.605663] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:122) -> hex2bin(/bin/tpmr:35)
[  447.672954] TRACE: main(/bin/tpmr:844) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[  447.749765] DEBUG: Replayed cbmem -L clean boot state of PCR=6 ALG=sha256 : f450e2f4f1851f6a6a3d3caa9614164cb92b63ef5750646d4fab9cfc5ebcbf29
[  447.827694] TRACE: main(/bin/tpmr:838) -> tpm2_pcrread(/bin/tpmr:53)
[  447.902623] DEBUG: tpm2 pcrread -Q -o /dev/fd/63 sha256:7
[  448.108923] DEBUG: tpmr seal /tmp/secret/secret.key 3 0,1,2,3,4,5,6,7 /tmp/secret/pcrf.bin 312 <hidden>
[  448.293675] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:432)
[  448.559593] DEBUG: tpm2_seal: file=/tmp/secret/secret.key handle=0x81000003 pcrl=0,1,2,3,4,5,6,7 pcrf=/tmp/secret/pcrf.bin pass=<hidden>
[  448.985258] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:470) -> tpm2_password_hex(/bin/tpmr:45)
[  449.577206] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:491) -> prompt_tpm_owner_password(/etc/functions:780)
[  449.639242] DEBUG: /tmp/secret/tpm_owner_password already cached in file. Reusing
[  449.715545] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:493) -> tpm2_password_hex(/bin/tpmr:45)
[  450.066729] TRACE: main(/bin/tpmr:864) -> tpm2_seal(/bin/tpmr:495) -> tpm2_password_hex(/bin/tpmr:45)
[  450.175139] DEBUG: tpm2 evictcontrol -Q -C o -P <hidden> -c /tmp/secret/secret.key.seal.ctx 0x81000003
[  450.534907] DEBUG: Running at_exit handlers
[  450.569063] TRACE: main(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_session(/bin/tpmr:378)
[  450.635304] DEBUG: Clean up session: /tmp/secret/sealfile_trial.session
[  450.808633] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[  450.902073] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[  452.027729] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> reseal_tpm_disk_decryption_key(/etc/functions:672) -> update_checksums(/etc/functions:982)
[  452.098705] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[  452.161989] DEBUG: add -r to kexec-sign-config since CONFIG_IGNORE_ROLLBACK is not set
[  452.235302] DEBUG: kexec-sign-config -p /boot -u -r
[  452.404534] TRACE: main(/bin/kexec-sign-config:7)
[  452.459025] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1082)
[  452.501891] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1247)
[  452.540980] EXT4-fs (vda1): unmounting filesystem.
[  452.890072] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1203)
[  452.941804] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1215) -> is_gpt_bios_grub(/etc/functions:1163)
[  453.012738] TRACE: /dev/vda1 is partition 1 of vda
[  453.094107] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1216) -> find_lvm_vg_name(/etc/functions:1140)
[  453.202868] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1230)
[  453.243909] DEBUG: Try mounting /dev/vda1 as /boot
[  453.287025] EXT4-fs (vda1): mounted filesystem with ordered data mode. Quota mode: disabled.
[  453.426092] TRACE: main(/bin/kexec-sign-config:30)
[  453.458511] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[  453.546613] DEBUG: Signing kexec parameters in /boot, rollback=y, update=y, counter=
[  453.600520] TRACE: main(/bin/kexec-sign-config:40)
[  453.665170] DEBUG: update=y: Updating kexec hashes in /boot
[  457.852561] DEBUG: /boot/kexec_default_hashes.txt exists, updating /boot/kexec_default_hashes.txt
[  459.404421] TRACE: main(/bin/kexec-sign-config:51) -> print_tree(/etc/functions:1014)
[  459.577921] TRACE: main(/bin/kexec-sign-config:52)
[  459.756893] DEBUG: rollback=y, counter=, paramsdir=/boot, rollback_file=/boot/kexec_rollback.txt
[  459.820328] TRACE: main(/bin/kexec-sign-config:65)
[  459.871766] DEBUG: rollback=y: counter was not provided: checking for existing TPM counter from TPM rollback_file=/boot/kexec_rollback.txt
[  459.939349] TRACE: main(/bin/kexec-sign-config:76)
[  460.030129] DEBUG: rollback=y: Found TPM counter 1418cee in rollback file /boot/kexec_rollback.txt
[  460.050174] TRACE: main(/bin/kexec-sign-config:93)
[  460.107203] DEBUG: rollback=y: Incrementing counter 1418cee.
[  460.169952] DEBUG: increment_tpm_counter 1418cee
[  460.278949] TRACE: main(/bin/kexec-sign-config:97) -> DO_WITH_DEBUG(/etc/functions:540) -> increment_tpm_counter(/etc/functions:870)
[  460.365448] DEBUG: tpmr counter_read -ix 1418cee
[  460.552580] TRACE: main(/bin/tpmr:852) -> tpm2_counter_read(/bin/tpmr:267)
[  460.912003] DEBUG: TPM counter 1418cee exists and was read successfully
[  460.992655] DEBUG: tpmr counter_increment -ix 1418cee -pwdc
[  461.171041] TRACE: main(/bin/tpmr:855) -> tpm2_counter_inc(/bin/tpmr:283)
[  461.734521] DEBUG: TPM counter incremented successfully for index 1418cee
[  461.821670] DEBUG: TPM counter file '/tmp/counter-1418cee' found.
[  461.880802] TRACE: main(/bin/kexec-sign-config:115)
[  461.935425] TRACE: main(/bin/kexec-sign-config:122) -> confirm_gpg_card(/etc/functions:129)
[  534.823396] TRACE: main(/bin/kexec-sign-config:122) -> confirm_gpg_card(/etc/functions:197) -> enable_usb(/etc/functions:410)
[  534.933030] TRACE: main(/sbin/insmod:9)
[  535.150882] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  535.204850] TPM: Extending PCR[5] with /lib/modules/ehci-hcd.ko and parameters '' before loading
[  535.250870] TRACE: main(/sbin/insmod:53)
[  535.293115] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  535.308466] No module parameters, extending only with the module's content
[  535.389300] TRACE: main(/bin/tpmr:847)
[  535.404376] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  535.442811] TPM: Extending PCR[5] with /lib/modules/ehci-hcd.ko
[  535.487068] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  535.527086] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  535.598553] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/ehci-hcd.ko
[  535.798840] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  535.845545] sha256: 5 : 0x909690BD6F97E04B50958166F992B414D81A0D36B732B6A7DA951763541D1CF5
[  535.906762] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  536.048208] DEBUG: TPM: Extended PCR[5] with hash 24eae3f2a147c715bd7e0c0ca362f2fe4d6def6925cfea8a06f3a243bd07bf58
[  536.126313] DEBUG: Loading /lib/modules/ehci-hcd.ko with busybox insmod
[  536.252068] TRACE: main(/sbin/insmod:9)
[  536.365227] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  536.391826] TPM: Extending PCR[5] with /lib/modules/uhci-hcd.ko and parameters '' before loading
[  536.416357] TRACE: main(/sbin/insmod:53)
[  536.436560] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  536.511943] No module parameters, extending only with the module's content
[  536.647013] TRACE: main(/bin/tpmr:847)
[  536.681818] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  536.715918] TPM: Extending PCR[5] with /lib/modules/uhci-hcd.ko
[  536.753279] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  536.784159] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  536.826118] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/uhci-hcd.ko
[  537.215130] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  537.254205] sha256: 5 : 0x8EC9D2802F8413D4F6C607B73A5103E568ED77E62FB9EEA6EDFDD5EF2693DFDF
[  537.289662] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  537.349550] DEBUG: TPM: Extended PCR[5] with hash 351589f2423438d7e7bcfab17d1065da794185fd105a2eaa70938f84635aa1f4
[  537.398778] DEBUG: Loading /lib/modules/uhci-hcd.ko with busybox insmod
[  537.619232] TRACE: main(/sbin/insmod:9)
[  538.138745] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  538.170947] TPM: Extending PCR[5] with /lib/modules/ohci-hcd.ko and parameters '' before loading
[  538.201980] TRACE: main(/sbin/insmod:53)
[  538.239824] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  538.272103] No module parameters, extending only with the module's content
[  538.492931] TRACE: main(/bin/tpmr:847)
[  538.562792] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  538.602922] TPM: Extending PCR[5] with /lib/modules/ohci-hcd.ko
[  538.658151] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  538.698411] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  538.770157] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/ohci-hcd.ko
[  538.963301] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  539.028685] sha256: 5 : 0x5A5A2C556E0204C43F40A8B45CA0FC19CFDFA97F6CFEBBD0D37AF8C342916F4A
[  539.122741] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  539.252065] DEBUG: TPM: Extended PCR[5] with hash 355261b550b90c17b3d7de6306b63d4ac81b3901eb3e698718feb8f9e455beac
[  539.323670] DEBUG: Loading /lib/modules/ohci-hcd.ko with busybox insmod
[  539.417147] TRACE: main(/sbin/insmod:9)
[  539.517349] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  539.538536] TPM: Extending PCR[5] with /lib/modules/ohci-pci.ko and parameters '' before loading
[  539.597163] TRACE: main(/sbin/insmod:53)
[  539.683885] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  539.721768] No module parameters, extending only with the module's content
[  539.891276] TRACE: main(/bin/tpmr:847)
[  539.915235] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  540.001328] TPM: Extending PCR[5] with /lib/modules/ohci-pci.ko
[  540.023588] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  540.052884] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  540.125741] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/ohci-pci.ko
[  540.273788] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  540.287108] sha256: 5 : 0x8BA29C95378766C29BEEFB929839549069585709C32EA253F4E11234766039C1
[  540.308111] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  540.344889] DEBUG: TPM: Extended PCR[5] with hash fc9a0bcce7dbf1e2c47f138f8f4fb30b26973686d3e3fe671f82848af7fd28c3
[  540.405955] DEBUG: Loading /lib/modules/ohci-pci.ko with busybox insmod
[  540.666842] TRACE: main(/sbin/insmod:9)
[  540.824598] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  540.893243] TPM: Extending PCR[5] with /lib/modules/ehci-pci.ko and parameters '' before loading
[  540.923754] TRACE: main(/sbin/insmod:53)
[  540.983301] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  541.016008] No module parameters, extending only with the module's content
[  541.263525] TRACE: main(/bin/tpmr:847)
[  541.311203] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  541.346106] TPM: Extending PCR[5] with /lib/modules/ehci-pci.ko
[  541.399359] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  541.434229] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  541.550110] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/ehci-pci.ko
[  542.038445] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  542.103333] sha256: 5 : 0x3479F0982F2000A4052ADA1FA5485239FCD86C0EAD6F624FC300DA8A29C6157A
[  542.183541] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  542.338278] DEBUG: TPM: Extended PCR[5] with hash 70c868f3f436e7ae7daaa0b070ecc024309e634cb3cd6387394249e69a8e7f58
[  542.410339] DEBUG: Loading /lib/modules/ehci-pci.ko with busybox insmod
[  542.554255] TRACE: main(/sbin/insmod:9)
[  542.713714] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  542.745048] TPM: Extending PCR[5] with /lib/modules/xhci-hcd.ko and parameters '' before loading
[  542.774978] TRACE: main(/sbin/insmod:53)
[  542.838796] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  542.873676] No module parameters, extending only with the module's content
[  543.008530] TRACE: main(/bin/tpmr:847)
[  543.040042] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  543.083887] TPM: Extending PCR[5] with /lib/modules/xhci-hcd.ko
[  543.132445] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  543.167286] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  543.227520] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/xhci-hcd.ko
[  543.437558] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  543.468541] sha256: 5 : 0x76B689397B52935FCC087204CBFCAD42442577A38025DACC0C6481BFDC8609B4
[  543.506334] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  543.543857] DEBUG: TPM: Extended PCR[5] with hash 5777b543e7a375a39ce486d83a5ff02dcaf5ec2d26356818d8ed0619224f31b3
[  543.596925] DEBUG: Loading /lib/modules/xhci-hcd.ko with busybox insmod
[  543.676300] TRACE: main(/sbin/insmod:9)
[  543.780631] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[  543.802179] TPM: Extending PCR[5] with /lib/modules/xhci-pci.ko and parameters '' before loading
[  543.885318] TRACE: main(/sbin/insmod:53)
[  543.928922] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[  543.985058] No module parameters, extending only with the module's content
[  544.111020] TRACE: main(/bin/tpmr:847)
[  544.146452] TRACE: main(/bin/tpmr:848) -> INFO(/etc/functions:80)
[  544.191175] TPM: Extending PCR[5] with /lib/modules/xhci-pci.ko
[  544.229314] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:233)
[  544.264072] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:249)
[  544.303767] DEBUG: TPM: Will extend PCR[5] with hash of file content /lib/modules/xhci-pci.ko
[  544.489250] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:260) -> INFO(/etc/functions:80)
[  544.520734] sha256: 5 : 0x4BB1E1405AD1FA13B66FE9BB465B0DB0F18CA317B9802CE40D42589ACE26BF0E
[  544.557353] TRACE: main(/bin/tpmr:849) -> tpm2_extend(/bin/tpmr:262)
[  544.606240] DEBUG: TPM: Extended PCR[5] with hash 7a3d34fe568abab53b827ff77d4c51f21a7057111c8afcc4c91e775f92ed3488
[  544.666113] DEBUG: Loading /lib/modules/xhci-pci.ko with busybox insmod
[  544.695973] xhci_hcd 0000:00:04.0: xHCI Host Controller
[  544.700923] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 1
[  544.710235] xhci_hcd 0000:00:04.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010
[  544.722323] xhci_hcd 0000:00:04.0: xHCI Host Controller
[  544.727169] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 2
[  544.737434] xhci_hcd 0000:00:04.0: Host supports USB 3.0 SuperSpeed
[  544.762666] hub 1-0:1.0: USB hub found
[  544.770567] hub 1-0:1.0: 4 ports detected
[  544.786289] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[  544.799246] hub 2-0:1.0: USB hub found
[  544.816461] hub 2-0:1.0: 4 ports detected
[  545.056751] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[  545.340581] usb 2-2: new SuperSpeed USB device number 2 using xhci_hcd
[  545.488503] usb 1-3: new full-speed USB device number 3 using xhci_hcd
[  550.322688] TRACE: main(/bin/kexec-sign-config:123)
[  550.419083] DEBUG: sha256sum /boot/kexec_default.1.txt /boot/kexec_default_hashes.txt /boot/kexec_hashes.txt /boot/kexec_initrd_crypttab_overrides.txt /boot/kexec_key_devices.txt /boot/kexec_lukshdr_hash.txt /boot/kexec_primhdl_hash.txt /boot/kexec_rollback.txt /boot/kexec_tree.txt
[  560.965223] TRACE: main(/bin/kexec-sign-config:127) -> check_config(/etc/functions:902)
[  561.093927] DEBUG: second param:  != force
[  561.235105] TRACE: main(/bin/gpgv:5)
[  561.409875] TRACE: main(/bin/kexec-sign-config:127) -> check_config(/etc/functions:929) -> INFO(/etc/functions:80)
[  561.472967] +++ Found verified kexec boot params
[  561.578119] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[  561.643290] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[  565.798665] TRACE: main(/bin/reboot:4)
[  565.881892] TRACE: main(/bin/tpmr:879) -> tpm2_shutdown(/bin/tpmr:752)
[  565.940688] sysrq: Emergency Sync
[  565.942445] sysrq: HELP : loglevel(0-9) reboot(b) crash(c) terminate-all-tasks(e) memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k) show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n) poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s) show-task-states(t) unmount(u) show-blocked-tasks(w) 
[  565.947787] Emergency Sync complete
[  565.949586] sysrq: Emergency Remount R/O
[  565.950955] sysrq: HELP : loglevel(0-9) reboot(b) crash(c) terminate-all-tasks(e) memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k) show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n) poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s) show-task-states(t) unmount(u) show-blocked-tasks(w) 
[  565.956930] Emergency Remount complete
./docker_repro.sh make BOARD=qemu-coreboot-fbwhiptail-tpm1 USB_TOKEN=Nitrokey3NFC PUBKEY_ASC=pubkey.asc inject_gpg run ```

!!! Hit enter to proceed to recovery shell !!!
[ 7.460125] DEBUG: Loading linux kernel shipped keyboard layout keymap: share/keymaps/defkeymap.map
[ 7.521477] DEBUG: loadkeys --default
[ 7.724220] DEBUG: Loading keyboard keymap: /usr/lib/kbd/keymaps/i386/qwerty/us.map
[ 7.757255] DEBUG: loadkeys /usr/lib/kbd/keymaps/i386/qwerty/us.map
[ 8.071524] TRACE: main(/bin/setconsolefont.sh:6)
[ 8.139598] DEBUG: Keep default console font size due to framebuffer height 768
[ 8.314079] TRACE: main(/bin/gui-init:639)
[ 8.344471] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1247)
[ 8.676767] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1203)
[ 8.710384] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1215) -> is_gpt_bios_grub(/etc/functions:1163)
[ 8.817125] TRACE: /dev/vda1 is partition 1 of vda
[ 8.954919] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1216) -> find_lvm_vg_name(/etc/functions:1140)
[ 9.113350] TRACE: main(/bin/gui-init:652) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1230)
[ 9.155205] DEBUG: Try mounting /dev/vda1 as /boot
[ 9.192561] EXT4-fs (vda1): mounted filesystem with ordered data mode. Quota mode: disabled.
[ 9.240450] TRACE: main(/bin/gui-init:654) -> clean_boot_check(/bin/gui-init:307)
[ 9.312241] TRACE: main(/bin/gui-init:662) -> check_gpg_key(/bin/gui-init:335)
[ 9.413420] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:183)
[ 9.529324] TRACE: main(/bin/unseal-totp:8)
[ 9.591780] DEBUG: tpmr unseal 4d47 0,1,2,3,4,7 312
[ 9.789720] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:626)
[ 9.871365] DEBUG: tpm nv_readvalue -in 4d47 -sz 312 -of /tmp/secret/tpm1_unseal_sealed.bin
[ 10.051670] DEBUG: tpm: exited with status 2
[ 10.075116] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:646) -> die(/etc/functions:6)
[ 10.114900] !!! ERROR: Unable to read sealed file from TPM NVRAM !!!
[ 100.576570] DEBUG: Running at_exit handlers
[ 100.619219] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:646) -> die(/etc/functions:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_shred(/bin/tpmr:394)
[ 100.859986] DEBUG: tpmr: exited with status 1
[ 100.897170] TRACE: main(/bin/unseal-totp:13) -> die(/etc/functions:6)
[ 100.914516] !!! ERROR: Unable to unseal TOTP secret from TPM !!!
[ 103.224786] DEBUG: CONFIG_TPM: y
[ 103.317045] DEBUG: CONFIG_TPM2_TOOLS:
[ 103.389253] DEBUG: Show PCRs
[ 103.588385] DEBUG: PCR-00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 103.645226] PCR-01: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 103.680380] PCR-02: EA 0C A8 07 AB 2D 9C EC 41 0D 38 16 AF ED 73 C0 E3 B3 92 25
[ 103.715374] PCR-03: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 103.731545] PCR-04: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 103.766097] PCR-05: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 103.812577] PCR-06: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 103.828545] PCR-07: 14 BA 09 9D BF 1B 99 63 21 39 0A AF AB 1B 52 EF 5C 9A FF 80
[ 117.843274] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> generate_totp_hotp(/bin/gui-init:150)
[ 117.961393] TRACE: main(/bin/seal-totp:10)
[ 118.086148] DEBUG: Sealing TOTP with actual state of PCR0-3
[ 118.319133] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 118.385661] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 118.432163] DEBUG: tpm pcrread -ix 0
[ 118.599695] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 118.669552] DEBUG: tpm pcrread -ix 1
[ 118.673640] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 118.910311] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 118.960941] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 118.965143] DEBUG: tpm pcrread -ix 2
[ 119.127326] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 119.175095] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 119.193501] DEBUG: tpm pcrread -ix 3
[ 119.330915] DEBUG: Sealing TOTP with boot state of PCR4 (Going to recovery shell extends PCR4)
[ 119.436841] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:197)
[ 119.548280] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[ 119.590954] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[ 119.667142] DEBUG: Replayed cbmem -L clean boot state of PCR=4 ALG=sha1 : 0000000000000000000000000000000000000000
[ 119.706154] DEBUG: Sealing TOTP neglecting PCR5 involvement (Dynamically loaded kernel modules are not firmware integrity attestation related)
[ 119.753356] DEBUG: Sealing TOTP without PCR6 involvement (LUKS header consistency is not firmware integrity attestation related)
[ 119.795741] DEBUG: Sealing TOTP with actual state of PCR7 (User injected stuff in cbfs)
[ 119.869577] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 119.946558] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 120.009149] DEBUG: tpm pcrread -ix 7
[ 120.255882] TRACE: main(/bin/tpmr:811) -> tpm1_seal(/bin/tpmr:505)
[ 120.317264] DEBUG: tpm1_seal arguments: file=/tmp/secret/totp.key index=4d47 pcrl=0,1,2,3,4,7 pcrf=/tmp/secret/pcrf.bin sealed_size=312 pass= tpm_password=
[ 120.591642] DEBUG: Running at_exit handlers
[ 120.606226] TRACE: main(/bin/tpmr:811) -> tpm1_seal(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_shred(/bin/tpmr:394)
[ 120.663755] TRACE: main(/bin/seal-totp:53) -> die(/etc/functions:6)
[ 120.716424] !!! ERROR: Unable to write sealed secret to NVRAM from seal-totp !!!
[ 124.022465] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> generate_totp_hotp(/bin/gui-init:177) -> warn(/etc/functions:24)
[ 124.082501] *** WARNING: Unsealing TOTP/HOTP secret from previous sealed measurements failed ***
[ 125.144459] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> generate_totp_hotp(/bin/gui-init:178) -> warn(/etc/functions:24)
[ 125.162908] *** WARNING: Try "Generate new HOTP/TOTP secret" option if you updated firmware content ***
[ 126.203111] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:183)
[ 126.318860] TRACE: main(/bin/unseal-totp:8)
[ 126.377387] DEBUG: tpmr unseal 4d47 0,1,2,3,4,7 312
[ 126.516390] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:626)
[ 126.569291] DEBUG: tpm nv_readvalue -in 4d47 -sz 312 -of /tmp/secret/tpm1_unseal_sealed.bin
[ 126.677088] DEBUG: tpm: exited with status 2
[ 126.708503] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:646) -> die(/etc/functions:6)
[ 126.734584] !!! ERROR: Unable to read sealed file from TPM NVRAM !!!
[ 136.537415] DEBUG: Running at_exit handlers
[ 136.574536] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:646) -> die(/etc/functions:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_shred(/bin/tpmr:394)
[ 136.676785] DEBUG: tpmr: exited with status 1
[ 136.710219] TRACE: main(/bin/unseal-totp:13) -> die(/etc/functions:6)
[ 136.745289] !!! ERROR: Unable to unseal TOTP secret from TPM !!!
[ 139.327121] DEBUG: CONFIG_TPM: y
[ 139.385373] DEBUG: CONFIG_TPM2_TOOLS:
[ 139.458215] DEBUG: Show PCRs
[ 139.624388] DEBUG: PCR-00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 139.636242] PCR-01: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 139.655415] PCR-02: EA 0C A8 07 AB 2D 9C EC 41 0D 38 16 AF ED 73 C0 E3 B3 92 25
[ 139.691632] PCR-03: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 139.736901] PCR-04: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 139.770829] PCR-05: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 139.802073] PCR-06: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 139.844867] PCR-07: 14 BA 09 9D BF 1B 99 63 21 39 0A AF AB 1B 52 EF 5C 9A FF 80
[ 142.561461] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:534)
[ 144.052397] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:539) -> prompt_new_owner_password(/etc/functions:802)
[ 150.141291] DEBUG: Caching TPM Owner Password to /tmp/secret/tpm_owner_password
[ 150.269246] TRACE: main(/bin/tpmr:820) -> tpm1_reset(/bin/tpmr:710)
[ 150.354224] DEBUG: Caching TPM Owner Password to /tmp/secret/tpm_owner_password
[ 150.403345] DEBUG: tpm physicalpresence -s
[ 150.567359] DEBUG: tpm physicalenable
[ 150.730800] DEBUG: tpm physicalsetdeactivated -c
[ 150.907101] DEBUG: tpm forceclear
[ 151.085382] DEBUG: tpm physicalenable
[ 151.261554] DEBUG: tpm takeown -pwdo
[ 151.981943] DEBUG: tpm physicalpresence -s
[ 152.153240] DEBUG: tpm physicalenable
[ 152.436282] DEBUG: tpm physicalsetdeactivated -c
[ 152.598545] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:549) -> mount_boot(/bin/gui-init:20)
[ 152.670158] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 152.711608] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:553) -> INFO(/etc/functions:80)
[ 152.749009] Removing rollback and primary handle hashes under /boot
[ 152.803172] DEBUG: Removing /boot/kexec_rollback.txt and /boot/kexec_primhdl_hash.txt
[ 152.871916] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:560) -> check_tpm_counter(/etc/functions:825)
[ 152.911593] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:560) -> check_tpm_counter(/etc/functions:836) -> INFO(/etc/functions:80)
[ 152.944405] /boot/kexec_rollback.txt does not exist; creating new TPM counter
[ 153.036478] TRACE: main(/bin/tpmr:785) -> tpm1_counter_create(/bin/tpmr:304)
[ 153.064952] TRACE: main(/bin/tpmr:785) -> tpm1_counter_create(/bin/tpmr:308) -> prompt_tpm_owner_password(/etc/functions:780)
[ 153.113270] DEBUG: /tmp/secret/tpm_owner_password already cached in file. Reusing
[ 153.298210] DEBUG: Created new TPM_COUNTER: '0'
[ 153.334169] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:563)
[ 153.437221] DEBUG: TPM_COUNTER: 0
[ 153.500975] DEBUG: increment_tpm_counter 0
[ 153.654127] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:569) -> DO_WITH_DEBUG(/etc/functions:540) -> increment_tpm_counter(/etc/functions:870)
[ 153.740038] DEBUG: tpmr counter_read -ix 0
[ 153.933030] DEBUG: Direct translation from tpmr to tpm1 call
[ 154.028529] DEBUG: exec tpm counter_read -ix 0
[ 154.231972] DEBUG: TPM counter 0 exists and was read successfully
[ 154.320028] DEBUG: tpmr counter_increment -ix 0 -pwdc
[ 154.552195] DEBUG: Direct translation from tpmr to tpm1 call
[ 154.591630] DEBUG: exec tpm counter_increment -ix 0 -pwdc
[ 154.762875] DEBUG: TPM counter incremented successfully for index 0
[ 154.818605] DEBUG: sha256sum /tmp/counter-0
[ 154.919755] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:575)
[ 158.041365] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:579) -> update_checksums(/etc/functions:982)
[ 158.098409] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 158.148940] DEBUG: add -r to kexec-sign-config since CONFIG_IGNORE_ROLLBACK is not set
[ 158.200886] DEBUG: kexec-sign-config -p /boot -u -r
[ 158.381426] TRACE: main(/bin/kexec-sign-config:7)
[ 158.459585] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1082)
[ 158.500149] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1247)
[ 158.561099] EXT4-fs (vda1): unmounting filesystem.
[ 159.075235] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1203)
[ 159.130048] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1215) -> is_gpt_bios_grub(/etc/functions:1163)
[ 159.241217] TRACE: /dev/vda1 is partition 1 of vda
[ 159.331772] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1216) -> find_lvm_vg_name(/etc/functions:1140)
[ 159.610174] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1230)
[ 159.688190] DEBUG: Try mounting /dev/vda1 as /boot
[ 159.727034] EXT4-fs (vda1): mounted filesystem with ordered data mode. Quota mode: disabled.
[ 159.870777] TRACE: main(/bin/kexec-sign-config:30)
[ 159.919201] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 159.989635] DEBUG: Signing kexec parameters in /boot, rollback=y, update=y, counter=
[ 160.025693] TRACE: main(/bin/kexec-sign-config:40)
[ 160.089545] DEBUG: update=y: Updating kexec hashes in /boot
[ 164.183035] DEBUG: /boot/kexec_default_hashes.txt exists, updating /boot/kexec_default_hashes.txt
[ 165.588942] TRACE: main(/bin/kexec-sign-config:51) -> print_tree(/etc/functions:1014)
[ 165.770519] TRACE: main(/bin/kexec-sign-config:52)
[ 165.852304] DEBUG: rollback=y, counter=, paramsdir=/boot, rollback_file=/boot/kexec_rollback.txt
[ 165.874144] TRACE: main(/bin/kexec-sign-config:65)
[ 165.923732] DEBUG: rollback=y: counter was not provided: checking for existing TPM counter from TPM rollback_file=/boot/kexec_rollback.txt
[ 165.961274] TRACE: main(/bin/kexec-sign-config:76)
[ 166.065449] DEBUG: rollback=y: Found TPM counter 0 in rollback file /boot/kexec_rollback.txt
[ 166.097852] TRACE: main(/bin/kexec-sign-config:93)
[ 166.173707] DEBUG: rollback=y: Incrementing counter 0.
[ 166.222415] DEBUG: increment_tpm_counter 0
[ 166.315375] TRACE: main(/bin/kexec-sign-config:97) -> DO_WITH_DEBUG(/etc/functions:540) -> increment_tpm_counter(/etc/functions:870)
[ 166.493209] DEBUG: tpmr counter_read -ix 0
[ 166.706449] DEBUG: Direct translation from tpmr to tpm1 call
[ 166.770485] DEBUG: exec tpm counter_read -ix 0
[ 166.897255] DEBUG: TPM counter 0 exists and was read successfully
[ 166.958634] DEBUG: tpmr counter_increment -ix 0 -pwdc
[ 167.138984] DEBUG: Direct translation from tpmr to tpm1 call
[ 167.213150] DEBUG: exec tpm counter_increment -ix 0 -pwdc
[ 167.343782] DEBUG: TPM counter incremented successfully for index 0
[ 167.421772] DEBUG: TPM counter file '/tmp/counter-0' found.
[ 167.466588] TRACE: main(/bin/kexec-sign-config:115)
[ 167.505717] TRACE: main(/bin/kexec-sign-config:122) -> confirm_gpg_card(/etc/functions:129)
[ 169.488331] TRACE: main(/bin/kexec-sign-config:122) -> confirm_gpg_card(/etc/functions:197) -> enable_usb(/etc/functions:410)
[ 169.601407] TRACE: main(/sbin/insmod:9)
[ 169.710517] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 169.723069] TPM: Extending PCR[5] with /lib/modules/ehci-hcd.ko and parameters '' before loading
[ 169.753751] TRACE: main(/sbin/insmod:53)
[ 169.770483] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 169.799454] No module parameters, extending only with the module's content
[ 169.884212] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ehci-hcd.ko
[ 169.952664] TRACE: main(/bin/tpmr:802)
[ 169.983749] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 170.028549] TPM: Extending PCR[5] with hash a4bac2eb1d4ceecbd95f500cf0e31dd3aafea560
[ 170.129783] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ehci-hcd.ko
[ 170.566442] DEBUG: Loading /lib/modules/ehci-hcd.ko with busybox insmod
[ 170.672909] TRACE: main(/sbin/insmod:9)
[ 170.800954] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 170.833124] TPM: Extending PCR[5] with /lib/modules/uhci-hcd.ko and parameters '' before loading
[ 170.865916] TRACE: main(/sbin/insmod:53)
[ 170.897234] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 170.921667] No module parameters, extending only with the module's content
[ 171.045174] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/uhci-hcd.ko
[ 171.168109] TRACE: main(/bin/tpmr:802)
[ 171.240892] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 171.277175] TPM: Extending PCR[5] with hash cfd84d5de268371d6977d81eee1e53c0ab2c5f39
[ 171.354302] DEBUG: exec tpm extend -ix 5 -if /lib/modules/uhci-hcd.ko
[ 171.542288] DEBUG: Loading /lib/modules/uhci-hcd.ko with busybox insmod
[ 171.763175] TRACE: main(/sbin/insmod:9)
[ 171.916955] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 171.964050] TPM: Extending PCR[5] with /lib/modules/ohci-hcd.ko and parameters '' before loading
[ 172.000384] TRACE: main(/sbin/insmod:53)
[ 172.044914] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 172.061975] No module parameters, extending only with the module's content
[ 172.209117] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ohci-hcd.ko
[ 172.294008] TRACE: main(/bin/tpmr:802)
[ 172.332972] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 172.368583] TPM: Extending PCR[5] with hash 3da371fb66cdb653706651604ff9d0e364403893
[ 172.444209] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ohci-hcd.ko
[ 172.614022] DEBUG: Loading /lib/modules/ohci-hcd.ko with busybox insmod
[ 172.738309] TRACE: main(/sbin/insmod:9)
[ 172.891390] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 172.922034] TPM: Extending PCR[5] with /lib/modules/ohci-pci.ko and parameters '' before loading
[ 172.969920] TRACE: main(/sbin/insmod:53)
[ 173.001698] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 173.047961] No module parameters, extending only with the module's content
[ 173.154114] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ohci-pci.ko
[ 173.202554] TRACE: main(/bin/tpmr:802)
[ 173.226249] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 173.249445] TPM: Extending PCR[5] with hash 9a584a69fdf5f3fac43bfb4526c41b688bf18541
[ 173.293551] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ohci-pci.ko
[ 173.482219] DEBUG: Loading /lib/modules/ohci-pci.ko with busybox insmod
[ 173.614765] TRACE: main(/sbin/insmod:9)
[ 173.770407] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 173.802207] TPM: Extending PCR[5] with /lib/modules/ehci-pci.ko and parameters '' before loading
[ 173.839063] TRACE: main(/sbin/insmod:53)
[ 173.867203] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 173.897585] No module parameters, extending only with the module's content
[ 173.996066] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ehci-pci.ko
[ 174.044414] TRACE: main(/bin/tpmr:802)
[ 174.067471] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 174.094334] TPM: Extending PCR[5] with hash 38f9a96aa8774f5198753248e164367a9eaaf102
[ 174.167953] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ehci-pci.ko
[ 174.600704] DEBUG: Loading /lib/modules/ehci-pci.ko with busybox insmod
[ 174.769773] TRACE: main(/sbin/insmod:9)
[ 174.929488] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 174.956059] TPM: Extending PCR[5] with /lib/modules/xhci-hcd.ko and parameters '' before loading
[ 174.982499] TRACE: main(/sbin/insmod:53)
[ 175.004848] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 175.024234] No module parameters, extending only with the module's content
[ 175.115997] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/xhci-hcd.ko
[ 175.175886] TRACE: main(/bin/tpmr:802)
[ 175.196191] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 175.220419] TPM: Extending PCR[5] with hash fa097f1129a9d80f3bfbab5c45f0965c2e4e1c8d
[ 175.277794] DEBUG: exec tpm extend -ix 5 -if /lib/modules/xhci-hcd.ko
[ 175.422452] DEBUG: Loading /lib/modules/xhci-hcd.ko with busybox insmod
[ 175.504041] TRACE: main(/sbin/insmod:9)
[ 175.610343] TRACE: main(/sbin/insmod:42) -> INFO(/etc/functions:80)
[ 175.623499] TPM: Extending PCR[5] with /lib/modules/xhci-pci.ko and parameters '' before loading
[ 175.643008] TRACE: main(/sbin/insmod:53)
[ 175.663327] TRACE: main(/sbin/insmod:54) -> INFO(/etc/functions:80)
[ 175.693633] No module parameters, extending only with the module's content
[ 175.782238] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/xhci-pci.ko
[ 175.948262] TRACE: main(/bin/tpmr:802)
[ 176.027173] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 176.083099] TPM: Extending PCR[5] with hash fea887117bb26df62ede05afdb5fdd8230cd9732
[ 176.216497] DEBUG: exec tpm extend -ix 5 -if /lib/modules/xhci-pci.ko
[ 176.406852] DEBUG: Loading /lib/modules/xhci-pci.ko with busybox insmod
[ 176.437252] xhci_hcd 0000:00:04.0: xHCI Host Controller
[ 176.441785] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 1
[ 176.450468] xhci_hcd 0000:00:04.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010
[ 176.461042] xhci_hcd 0000:00:04.0: xHCI Host Controller
[ 176.464307] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 2
[ 176.467456] xhci_hcd 0000:00:04.0: Host supports USB 3.0 SuperSpeed
[ 176.477834] hub 1-0:1.0: USB hub found
[ 176.490228] hub 1-0:1.0: 4 ports detected
[ 176.494847] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[ 176.497307] hub 2-0:1.0: USB hub found
[ 176.499044] hub 2-0:1.0: 4 ports detected
[ 176.751019] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[ 177.027604] usb 2-2: new SuperSpeed USB device number 2 using xhci_hcd
[ 177.183116] usb 1-3: new full-speed USB device number 3 using xhci_hcd
[ 180.895423] TRACE: main(/bin/kexec-sign-config:123)
[ 180.961492] DEBUG: sha256sum /boot/kexec_default.1.txt /boot/kexec_default_hashes.txt /boot/kexec_hashes.txt /boot/kexec_initrd_crypttab_overrides.txt /boot/kexec_key_devices.txt /boot/kexec_lukshdr_hash.txt /boot/kexec_rollback.txt /boot/kexec_tree.txt
[ 191.202987] TRACE: main(/bin/kexec-sign-config:127) -> check_config(/etc/functions:902)
[ 191.305890] DEBUG: second param: != force
[ 191.450920] TRACE: main(/bin/gpgv:5)
[ 191.652349] TRACE: main(/bin/kexec-sign-config:127) -> check_config(/etc/functions:929) -> INFO(/etc/functions:80)
[ 191.716447] +++ Found verified kexec boot params
[ 191.806625] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 191.856526] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 191.877331] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 191.903615] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reset_tpm(/bin/gui-init:589) -> generate_totp_hotp(/bin/gui-init:150)
[ 192.107956] TRACE: main(/bin/seal-totp:10)
[ 192.302028] DEBUG: Sealing TOTP with actual state of PCR0-3
[ 192.413476] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 192.478419] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 192.505103] DEBUG: tpm pcrread -ix 0
[ 192.692090] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 192.742426] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 192.750536] DEBUG: tpm pcrread -ix 1
[ 193.104111] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 193.192418] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 193.260083] DEBUG: tpm pcrread -ix 2
[ 193.488883] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 193.557702] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 193.631852] DEBUG: tpm pcrread -ix 3
[ 193.838258] DEBUG: Sealing TOTP with boot state of PCR4 (Going to recovery shell extends PCR4)
[ 193.968224] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:197)
[ 194.189408] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[ 194.248940] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[ 194.317101] DEBUG: Replayed cbmem -L clean boot state of PCR=4 ALG=sha1 : 0000000000000000000000000000000000000000
[ 194.369110] DEBUG: Sealing TOTP neglecting PCR5 involvement (Dynamically loaded kernel modules are not firmware integrity attestation related)
[ 194.432691] DEBUG: Sealing TOTP without PCR6 involvement (LUKS header consistency is not firmware integrity attestation related)
[ 194.483319] DEBUG: Sealing TOTP with actual state of PCR7 (User injected stuff in cbfs)
[ 194.622269] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 194.709511] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 194.742094] DEBUG: tpm pcrread -ix 7
[ 194.923450] TRACE: main(/bin/tpmr:811) -> tpm1_seal(/bin/tpmr:505)
[ 194.985560] DEBUG: tpm1_seal arguments: file=/tmp/secret/totp.key index=4d47 pcrl=0,1,2,3,4,7 pcrf=/tmp/secret/pcrf.bin sealed_size=312 pass= tpm_password=
[ 195.679849] TRACE: main(/bin/tpmr:811) -> tpm1_seal(/bin/tpmr:553) -> prompt_tpm_owner_password(/etc/functions:780)
[ 195.754594] DEBUG: /tmp/secret/tpm_owner_password already cached in file. Reusing
[ 195.874908] DEBUG: Running at_exit handlers
[ 195.889221] TRACE: main(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_shred(/bin/tpmr:394)
[ 195.965232] DEBUG: TOTP secret output on screen (both URL and QR code)
[ 197.694104] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> update_totp(/bin/gui-init:183)
[ 197.817916] TRACE: main(/bin/unseal-totp:8)
[ 197.898393] DEBUG: tpmr unseal 4d47 0,1,2,3,4,7 312
[ 198.102892] TRACE: main(/bin/tpmr:816) -> tpm1_unseal(/bin/tpmr:626)
[ 198.167675] DEBUG: tpm nv_readvalue -in 4d47 -sz 312 -of /tmp/secret/tpm1_unseal_sealed.bin
[ 198.392841] DEBUG: Running at_exit handlers
[ 198.416273] TRACE: main(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_shred(/bin/tpmr:394)
[ 198.498466] DEBUG: totp -q
[ 198.600035] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reseal_tpm_disk_decryption_key(/etc/functions:649)
[ 198.627785] DEBUG: LUKS TPM Disk Unlock Key is allowed in board configs. Continuing
[ 199.774956] TRACE: main(/bin/kexec-seal-key:35)
[ 199.869659] DEBUG: Devices defined for disk encryption: /dev/vda3 /dev/vda5
[ 199.927428] DEBUG: No LVM volume group defined for activation
[ 200.102082] DEBUG: PCR-00: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 200.127221] PCR-01: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 200.154513] PCR-02: EA 0C A8 07 AB 2D 9C EC 41 0D 38 16 AF ED 73 C0 E3 B3 92 25
[ 200.181648] PCR-03: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 200.214148] PCR-04: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 200.249790] PCR-05: 7E 12 05 8D 57 4F 26 C5 02 76 43 5A C5 88 50 70 77 7D BF 74
[ 200.263870] PCR-06: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
[ 200.281134] PCR-07: 14 BA 09 9D BF 1B 99 63 21 39 0A AF AB 1B 52 EF 5C 9A FF 80
[ 204.532830] DEBUG: Testing /tmp/secret/recovery.key keyfile against /dev/vda3
[ 206.985679] DEBUG: Testing /tmp/secret/recovery.key keyfile against /dev/vda5
[ 224.230473] DEBUG: /dev/vda3: LUKSv2 device detected
[ 224.411904] DEBUG: /dev/vda3 LUKS key slots: 0 31
[ 224.467796] DEBUG: Testing LUKS key slot 0 against /tmp/secret/recovery.key for Disk Recovery Key slot...
[ 224.523502] DEBUG: cryptsetup open --test-passphrase --key-slot 0 --key-file /tmp/secret/recovery.key /dev/vda3
[ 227.188545] DEBUG: Disk Recovery key slot is 0
[ 227.251127] DEBUG: LUKS key slot 31 is the expected DUK key slot. Will wipe this DUK key slot silently
[ 227.316395] DEBUG: cryptsetup luksKillSlot --key-file /tmp/secret/recovery.key /dev/vda3 31
[ 230.110469] DEBUG: cryptsetup luksAddKey --key-file /tmp/secret/recovery.key --new-key-slot 31 /dev/vda3 /tmp/secret/secret.key
[ 246.752612] DEBUG: /dev/vda5: LUKSv2 device detected
[ 246.875211] DEBUG: /dev/vda5 LUKS key slots: 0 31
[ 246.941457] DEBUG: Testing LUKS key slot 0 against /tmp/secret/recovery.key for Disk Recovery Key slot...
[ 247.055116] DEBUG: cryptsetup open --test-passphrase --key-slot 0 --key-file /tmp/secret/recovery.key /dev/vda5
[ 250.231404] DEBUG: Disk Recovery key slot is 0
[ 250.315910] DEBUG: LUKS key slot 31 is the expected DUK key slot. Will wipe this DUK key slot silently
[ 250.385051] DEBUG: cryptsetup luksKillSlot --key-file /tmp/secret/recovery.key /dev/vda5 31
[ 253.932129] DEBUG: cryptsetup luksAddKey --key-file /tmp/secret/recovery.key --new-key-slot 31 /dev/vda5 /tmp/secret/secret.key
[ 268.493563] TRACE: main(/bin/qubes-measure-luks:6)
[ 268.565782] DEBUG: Arguments passed to qubes-measure-luks: /dev/vda3 /dev/vda5
[ 268.658433] DEBUG: Storing LUKS header for /dev/vda3 into /tmp/lukshdr-_dev_vda3
[ 268.929471] DEBUG: Storing LUKS header for /dev/vda5 into /tmp/lukshdr-_dev_vda5
[ 269.362538] DEBUG: Hashing LUKS headers into /tmp/luksDump.txt
[ 269.892843] DEBUG: Removing /tmp/lukshdr-*
[ 269.953087] TRACE: main(/bin/qubes-measure-luks:22)
[ 270.026197] TRACE: main(/bin/qubes-measure-luks:23) -> INFO(/etc/functions:80)
[ 270.075597] TPM: Extending PCR[6] with hash of LUKS headers from /tmp/luksDump.txt
[ 270.217279] DEBUG: TPM: Will extend PCR[6] hash content of file /tmp/luksDump.txt
[ 270.300665] TRACE: main(/bin/tpmr:802)
[ 270.352840] TRACE: main(/bin/tpmr:803) -> INFO(/etc/functions:80)
[ 270.388427] TPM: Extending PCR[6] with hash d4c71afa8757b38dc1dcfc2ec427f7711d82f0c9
[ 270.424239] DEBUG: exec tpm extend -ix 6 -if /tmp/luksDump.txt
[ 270.588549] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 270.667606] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 270.703482] DEBUG: tpm pcrread -ix 0
[ 270.992972] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 271.075326] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 271.147033] DEBUG: tpm pcrread -ix 1
[ 271.592012] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 271.752006] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 271.835469] DEBUG: tpm pcrread -ix 2
[ 272.246518] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 272.409675] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 272.474072] DEBUG: tpm pcrread -ix 3
[ 272.995557] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:197)
[ 273.282060] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[ 273.394072] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[ 273.593058] DEBUG: Replayed cbmem -L clean boot state of PCR=4 ALG=sha1 : 0000000000000000000000000000000000000000
[ 273.726693] DEBUG: Sealing LUKS TPM Disk Unlock Key with PCR5=0 (NO additional kernel modules are loaded per board config)...
[ 273.873865] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:197)
[ 274.115404] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[ 274.233620] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[ 274.326508] DEBUG: Replayed cbmem -L clean boot state of PCR=5 ALG=sha1 : 0000000000000000000000000000000000000000
[ 274.370273] DEBUG: Precomputing TPM future value for PCR6 sealing/unsealing of LUKS TPM Disk Unlock Key...
[ 274.444504] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:197)
[ 274.550144] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:108)
[ 274.860614] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:216) -> extend_pcr_state(/bin/tpmr:122) -> hex2bin(/bin/tpmr:35)
[ 275.134218] TRACE: main(/bin/tpmr:781) -> replay_pcr(/bin/tpmr:217) -> hex2bin(/bin/tpmr:35)
[ 275.237024] DEBUG: Replayed cbmem -L clean boot state of PCR=6 ALG=sha1 : d3992793ed34f51530cd34111f0ac1392a18b7b3
[ 275.345831] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:71)
[ 275.419480] TRACE: main(/bin/tpmr:774) -> tpm1_pcrread(/bin/tpmr:86) -> hex2bin(/bin/tpmr:35)
[ 275.479161] DEBUG: tpm pcrread -ix 7
[ 275.694857] DEBUG: tpmr seal /tmp/secret/secret.key 3 0,1,2,3,4,5,6,7 /tmp/secret/pcrf.bin 312
[ 275.892707] TRACE: main(/bin/tpmr:811) -> tpm1_seal(/bin/tpmr:505)
[ 275.965885] DEBUG: tpm1_seal arguments: file=/tmp/secret/secret.key index=3 pcrl=0,1,2,3,4,5,6,7 pcrf=/tmp/secret/pcrf.bin sealed_size=312 pass= tpm_password=
[ 276.533845] TRACE: main(/bin/tpmr:811) -> tpm1_seal(/bin/tpmr:553) -> prompt_tpm_owner_password(/etc/functions:780)
[ 276.585169] DEBUG: /tmp/secret/tpm_owner_password already cached in file. Reusing
[ 276.683234] DEBUG: Running at_exit handlers
[ 276.701692] TRACE: main(/bin/tpmr:1) -> run_at_exit_handlers(/etc/functions:1408) -> cleanup_shred(/bin/tpmr:394)
[ 276.812874] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 276.909043] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 278.024058] TRACE: main(/bin/gui-init:665) -> update_totp(/bin/gui-init:221) -> update_totp(/bin/gui-init:229) -> reseal_tpm_disk_decryption_key(/etc/functions:672) -> update_checksums(/etc/functions:982)
[ 278.100498] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 278.188578] DEBUG: add -r to kexec-sign-config since CONFIG_IGNORE_ROLLBACK is not set
[ 278.264482] DEBUG: kexec-sign-config -p /boot -u -r
[ 278.451115] TRACE: main(/bin/kexec-sign-config:7)
[ 278.484056] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1082)
[ 278.522057] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1247)
[ 278.604327] EXT4-fs (vda1): unmounting filesystem.
[ 279.159642] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1203)
[ 279.203324] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1215) -> is_gpt_bios_grub(/etc/functions:1163)
[ 279.300548] TRACE: /dev/vda1 is partition 1 of vda
[ 279.427838] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1216) -> find_lvm_vg_name(/etc/functions:1140)
[ 279.559844] TRACE: main(/bin/kexec-sign-config:29) -> assert_signable(/etc/functions:1084) -> detect_boot_device(/etc/functions:1277) -> mount_possible_boot_device(/etc/functions:1230)
[ 279.614379] DEBUG: Try mounting /dev/vda1 as /boot
[ 279.672704] EXT4-fs (vda1): mounted filesystem with ordered data mode. Quota mode: disabled.
[ 279.824886] TRACE: main(/bin/kexec-sign-config:30)
[ 279.868030] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 279.913353] DEBUG: Signing kexec parameters in /boot, rollback=y, update=y, counter=
[ 279.962111] TRACE: main(/bin/kexec-sign-config:40)
[ 280.024524] DEBUG: update=y: Updating kexec hashes in /boot
[ 284.175113] DEBUG: /boot/kexec_default_hashes.txt exists, updating /boot/kexec_default_hashes.txt
[ 285.806218] TRACE: main(/bin/kexec-sign-config:51) -> print_tree(/etc/functions:1014)
[ 285.900264] TRACE: main(/bin/kexec-sign-config:52)
[ 285.983701] DEBUG: rollback=y, counter=, paramsdir=/boot, rollback_file=/boot/kexec_rollback.txt
[ 286.047613] TRACE: main(/bin/kexec-sign-config:65)
[ 286.110120] DEBUG: rollback=y: counter was not provided: checking for existing TPM counter from TPM rollback_file=/boot/kexec_rollback.txt
[ 286.147794] TRACE: main(/bin/kexec-sign-config:76)
[ 286.257746] DEBUG: rollback=y: Found TPM counter 0 in rollback file /boot/kexec_rollback.txt
[ 286.294572] TRACE: main(/bin/kexec-sign-config:93)
[ 286.362416] DEBUG: rollback=y: Incrementing counter 0.
[ 286.425445] DEBUG: increment_tpm_counter 0
[ 286.558396] TRACE: main(/bin/kexec-sign-config:97) -> DO_WITH_DEBUG(/etc/functions:540) -> increment_tpm_counter(/etc/functions:870)
[ 286.676582] DEBUG: tpmr counter_read -ix 0
[ 286.891674] DEBUG: Direct translation from tpmr to tpm1 call
[ 286.948017] DEBUG: exec tpm counter_read -ix 0
[ 287.154144] DEBUG: TPM counter 0 exists and was read successfully
[ 287.245364] DEBUG: tpmr counter_increment -ix 0 -pwdc
[ 287.518446] DEBUG: Direct translation from tpmr to tpm1 call
[ 287.592506] DEBUG: exec tpm counter_increment -ix 0 -pwdc
[ 287.822315] DEBUG: TPM counter incremented successfully for index 0
[ 287.925049] DEBUG: TPM counter file '/tmp/counter-0' found.
[ 288.033877] TRACE: main(/bin/kexec-sign-config:115)
[ 288.125424] TRACE: main(/bin/kexec-sign-config:122) -> confirm_gpg_card(/etc/functions:129)
[ 304.231399] TRACE: main(/bin/kexec-sign-config:122) -> confirm_gpg_card(/etc/functions:197) -> enable_usb(/etc/functions:410)
[ 304.336122] TRACE: main(/sbin/insmod:9)
[ 304.459634] DEBUG: /lib/modules/ehci-hcd.ko: already loaded, skipping
[ 304.523029] TRACE: main(/sbin/insmod:9)
[ 304.647400] DEBUG: /lib/modules/uhci-hcd.ko: already loaded, skipping
[ 304.743963] TRACE: main(/sbin/insmod:9)
[ 304.869670] DEBUG: /lib/modules/ohci-hcd.ko: already loaded, skipping
[ 304.969549] TRACE: main(/sbin/insmod:9)
[ 305.089455] DEBUG: /lib/modules/ohci-pci.ko: already loaded, skipping
[ 305.192634] TRACE: main(/sbin/insmod:9)
[ 305.405633] DEBUG: /lib/modules/ehci-pci.ko: already loaded, skipping
[ 305.584723] TRACE: main(/sbin/insmod:9)
[ 305.725626] DEBUG: /lib/modules/xhci-hcd.ko: already loaded, skipping
[ 305.823742] TRACE: main(/sbin/insmod:9)
[ 306.015734] DEBUG: /lib/modules/xhci-pci.ko: already loaded, skipping
[ 307.695331] TRACE: main(/bin/kexec-sign-config:123)
[ 307.808745] DEBUG: sha256sum /boot/kexec_default.1.txt /boot/kexec_default_hashes.txt /boot/kexec_hashes.txt /boot/kexec_initrd_crypttab_overrides.txt /boot/kexec_key_devices.txt /boot/kexec_lukshdr_hash.txt /boot/kexec_rollback.txt /boot/kexec_tree.txt
[ 313.705430] TRACE: main(/bin/kexec-sign-config:127) -> check_config(/etc/functions:902)
[ 313.801730] DEBUG: second param: != force
[ 313.924022] TRACE: main(/bin/gpgv:5)
[ 314.088917] TRACE: main(/bin/kexec-sign-config:127) -> check_config(/etc/functions:929) -> INFO(/etc/functions:80)
[ 314.127657] +++ Found verified kexec boot params
[ 314.213838] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 314.278442] EXT4-fs (vda1): re-mounted. Quota mode: disabled.
[ 318.467281] TRACE: main(/bin/reboot:4)
[ 318.629508] sysrq: Emergency Sync
[ 318.631330] sysrq: HELP : loglevel(0-9) reboot(b) crash(c) terminate-all-tasks(e) memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k) show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n) poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s) show-task-states(t) unmount(u) show-blocked-tasks(w)
[ 318.636126] Emergency Sync complete
[ 318.638244] sysrq: Emergency Remount R/O
[ 318.639951] sysrq: HELP : loglevel(0-9) reboot(b) crash(c) terminate-all-tasks(e) memory-full-oom-kill(f) kill-all-tasks(i) thaw-filesystems(j) sak(k) show-backtrace-all-active-cpus(l) show-memory-usage(m) nice-all-RT-tasks(n) poweroff(o) show-registers(p) show-all-timers(q) unraw(r) sync(s) show-task-states(t) unmount(u) show-blocked-tasks(w)
[ 318.645099] Emergency Remount complete

</details>




@tlaurion tlaurion marked this pull request as ready for review November 20, 2025 23:01
@tlaurion tlaurion assigned marmarek and unassigned tlaurion Nov 20, 2025
@tlaurion
Copy link
Collaborator Author

Also note that when in Quiet mode, accessing to recovery shell will

!!! Hit enter to proceed to recovery shell !!!

NOTE: If you want to file a bug, please enable Debug mode through 'Options --> Change configuration settings > Configure Heads informational'

!!!!! Starting recovery shell

I remember I hit similar issue before, it was about one too many >/dev/null somewhere. I can't find notes about this issue (I think I posted it somewhere? some comment in one of issues here?), but AFAIR it was something about check_tpm_counter output being hidden, but it prompting for TPM password

@marmarek the issue was under /etc/functions for counter operations. see #1935 (comment)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

Projects

None yet

Development

Successfully merging this pull request may close these issues.

Unable to create rollback file after OS reinstall (Regenerate TOTP/HOTP)

3 participants