Refine STATUS/NOTE/INFO logging for consistent UX and accurate terminology

- doc/logging.md: Complete rewrite with clear INFO/NOTE/WARN guidance, table
  with sleep/blank-line columns, add measuring_trace.log to Quiet mode table
- initrd/bin/cbfs-init.sh: Add STATUS_OK for flash read, streamline messages
- initrd/bin/gpg-gui.sh: Change INFO to NOTE for GPG instructions
- initrd/bin/gui-init.sh: Remove noisy STATUS pairs, add enable_usb for GPG,
  add STATUS for HOTP verification
- initrd/bin/kexec-insert-key.sh: Improve DUK measuring message
- initrd/bin/kexec-seal-key.sh: Add STATUS_OK for key gen, slot update, PCR read
- initrd/bin/kexec-select-boot.sh: Fix "unsigned boot options" -> "boot options"
- initrd/bin/lock_chip.sh: Add STATUS_OK for chipset lock
- initrd/bin/network-init-recovery.sh: Add STATUS_OK for modules, clock, SSH
- initrd/bin/oem-factory-reset.sh: Many STATUS_OK additions, INFO->NOTE for guidance
- initrd/bin/qubes-measure-luks.sh, uefi-init.sh, usb-init.sh: Improve PCR messages
- initrd/bin/seal-hotpkey.sh: Add STATUS/STATUS_OK for HOTP secret write
- initrd/bin/seal-totp.sh: Change STATUS to NOTE for TOTP secret
- initrd/bin/tpmr.sh: Add STATUS/STATUS_OK, INFO->WARN for unseal, add PCR extend INFO
- initrd/bin/unseal-hotp.sh: Add STATUS/STATUS_OK for unseal
- initrd/etc/functions.sh: PCR5 regression fix (don't auto-load USB), VID wait
  loop fixes (sleep 0.1, iteration cap), pcrs() formatting fix
- initrd/etc/gui_functions.sh: Remove redundant STATUS_OK, add for signing key verification
- initrd/init: echo->STATUS_OK, add measuring_trace.log, fix grammar
- initrd/sbin/insmod.sh: Improve PCR extend message

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

Author: tlaurion

doc/logging.md

@@ -24,10 +24,12 @@ if [ -z "$CONFIG_PCR" ]; then
 fi
 
 if [ "$CONFIG_CBFS_VIA_FLASHPROG" = "y" ]; then
-	# Use flashrom directly, because we don't have /tmp/config with params for flash.sh yet
-	STATUS "Reading board keys and configuration from SPI flash"
+	# Workaround: cbfs cannot read CBFS directly on rom_hole boards
+	# See: https://github.com/osresearch/flashtools/issues/10
+	STATUS "Reading SPI flash with flashprog (rom_hole workaround)..."
 	if /bin/flashprog -p internal --fmap -i COREBOOT -i FMAP -r /tmp/cbfs-init.rom; then
 		CBFS_ARG=" -o /tmp/cbfs-init.rom"
+		STATUS_OK "ROM read"
 	else
 		WARN "Failed to read board keys and configuration from SPI flash - some features may not be available"
 	fi
@@ -47,7 +49,6 @@ for cbfsname in `echo $cbfsfiles`; do
 		|| DIE "$filename: cbfs file read failed"
 		if [ "$CONFIG_TPM" = "y" ]; then
 			TRACE_FUNC
-			INFO "Measuring $filename into TPM PCR[$CONFIG_PCR]"
 			# Measure both the filename and its content.  This
 			# ensures that renaming files or pivoting file content
 			# will still affect the resulting PCR measurement.
@@ -57,4 +58,4 @@ for cbfsname in `echo $cbfsfiles`; do
 		fi
 	fi
 done
-STATUS_OK "Board keys and configuration loaded from firmware"
+STATUS_OK "GPG keyring, trustdb, and board configuration extracted from firmware"

initrd/bin/cbfs-init.sh

@@ -57,8 +57,8 @@ while true; do
 	"g")
 		confirm_gpg_card
 		STATUS "INSTRUCTIONS:"
-		INFO "Type 'admin' then 'generate' and follow the prompts to generate a GPG key"
-		INFO "Type 'quit' once the key is generated to exit GPG"
+		NOTE "Type 'admin' then 'generate' and follow the prompts to generate a GPG key"
+		NOTE "Type 'quit' once the key is generated to exit GPG"
 		gpg --card-edit >/tmp/gpg_card_edit_output
 		if [ $? -eq 0 ]; then
 			gpg_post_gen_mgmt

initrd/bin/gpg-gui.sh

@@ -249,11 +249,11 @@ gate_reseal_with_integrity_report() {
 			# starting the NK3 CCID teardown.  This safety call covers the
 			# case where scdaemon was restarted between then and now.
 			release_scdaemon
-			STATUS "Checking $DONGLE_BRAND presence before sealing"
 			DEBUG "gate_reseal_with_integrity_report: checking HOTP token presence"
+			STATUS "Checking $DONGLE_BRAND presence before sealing"
 			if hotp_verification info >/dev/null 2>&1; then
-				token_ok="y"
 				STATUS_OK "$DONGLE_BRAND present and accessible"
+				token_ok="y"
 				break
 			fi
 			DEBUG "gate_reseal_with_integrity_report: HOTP token not accessible"
@@ -285,10 +285,9 @@ generate_totp_hotp() {
 	if [ "$CONFIG_TPM" != "y" ] && [ -x /bin/hotp_verification ]; then
 		# If we don't have a TPM, but we have a HOTP USB Security dongle
 		TRACE_FUNC
-		STATUS "Generating new HOTP secret"
 		/bin/seal-hotpkey.sh ||
 			DIE "Failed to generate HOTP secret"
-	elif STATUS "Generating new TOTP secret" && /bin/seal-totp.sh "$BOARD_NAME" "$tpm_owner_passphrase"; then
+	elif /bin/seal-totp.sh "$BOARD_NAME" "$tpm_owner_passphrase"; then
 		if [ -x /bin/hotp_verification ]; then
 			# If we have a TPM and a HOTP USB Security dongle
 			if [ "$CONFIG_TOTP_SKIP_QRCODE" != y ]; then
@@ -362,6 +361,7 @@ update_totp() {
 				return 1 # Already asked to skip to menu from a prior error
 			fi
 
+			DEBUG "TPM state at TOTP failure:"
 			DEBUG "$(pcrs)"
 
 			totp_menu_text=$(
@@ -437,6 +437,7 @@ update_hotp() {
 	local hotp_token_info hotp_exit attempt
 
 	# Ensure dongle is present; capture info for PIN counter display
+	STATUS "Checking $DONGLE_BRAND presence"
 	if ! hotp_token_info="$(hotp_verification info)"; then
 		if [ "$skip_to_menu" = "true" ]; then
 			return 1 # Already asked to skip to menu from a prior error
@@ -474,12 +475,14 @@ update_hotp() {
 	# PIN retry count is shown only before a retry so normal boots stay silent.
 	for attempt in 1 2 3; do
 		# Don't output HOTP codes to screen, so as to make replay attacks harder
+		STATUS "Verifying HOTP code"
 		hotp_verification check "$HOTP"
 		hotp_exit=$?
 		case "$hotp_exit" in
 		0)
 			HOTP="Success"
 			BG_COLOR_MAIN_MENU="normal"
+			STATUS_OK "HOTP code verified"
 			return
 			;;
 		4 | 7) # 4: code incorrect, 7: not a valid HOTP code — no point retrying same code
@@ -654,7 +657,6 @@ check_gpg_key() {
 
 prompt_auto_default_boot() {
 	TRACE_FUNC
-	STATUS_OK "HOTP verification success"
 	if pause_automatic_boot; then
 		STATUS "Attempting default boot"
 		attempt_default_boot
@@ -867,16 +869,17 @@ reset_tpm() {
 				DIE "Unable to create rollback file"
 
 			TRACE_FUNC
-			# As a countermeasure for existing primary handle hash, we will now force sign /boot without it
-			# USB is already initialized at startup; run gpg --card-status to populate key stub.
+			# As a countermeasure for existing primary handle hash, we will now force sign /boot without it.
+			# NOTE: At seal time, PCR5 is IGNORED (not measured) - only used on HOTP board variants. So USB
+			# modules loading here don't affect DUK seal. GPG card needs USB to be enabled first.
+			enable_usb
 			wait_for_gpg_card || true
 			while true; do
 				GPG_KEY_COUNT=$(gpg -K 2>/dev/null | wc -l)
 				if [ "$GPG_KEY_COUNT" -eq 0 ]; then
 					prompt_missing_gpg_key_action || return 1
 					wait_for_gpg_card || true
 				else
-					STATUS_OK "TPM reset successful - updating /boot checksums and signatures"
 					if ! update_checksums; then
 						whiptail_error --title 'ERROR' \
 							--msgbox "Failed to update checksums / sign default config" 0 80
@@ -896,14 +899,9 @@ reset_tpm() {
 			fi
 
 			if [ -s /boot/kexec_key_devices.txt ] || [ -s /boot/kexec_key_lvm.txt ]; then
-				STATUS_OK "TPM reset successful - resealing TPM Disk Unlock Key (DUK)"
 				reseal_tpm_disk_decryption_key || prompt_missing_gpg_key_action
 			fi
-		else
-			INFO "Returning to the main menu"
 		fi
-	else
-		whiptail_error --title 'ERROR: No TPM Detected' --msgbox "This device does not have a TPM.\n\nPress OK to return to the Main Menu" 0 80
 	fi
 }
 

initrd/bin/gui-init.sh

@@ -29,7 +29,7 @@ if [ -r "$TMP_KEY_LVM" ]; then
 fi
 
 # Measure the LUKS headers before we unseal the LUKS Disk Unlock Key from TPM
-STATUS "Measuring LUKS headers"
+STATUS "Measuring TPM Disk Unlock Key (DUK) into PCR[6])"
 cat "$TMP_KEY_DEVICES" | cut -d\  -f1 | xargs /bin/qubes-measure-luks.sh ||
 	DIE "LUKS measure failed"
 
@@ -65,7 +65,7 @@ fi
 
 # Override PCR 4 so that user can't read the key
 TRACE_FUNC
-INFO "TPM: Extending PCR[4] to prevent any future secret unsealing"
+INFO "TPM: Extending PCR[4] with content of string 'generic' to prevent secret unsealing"
 tpmr.sh extend -ix 4 -ic generic ||
 	DIE 'Unable to scramble PCR'
 

initrd/bin/kexec-insert-key.sh

@@ -174,6 +174,7 @@ dd \
 	count=128 \
 	2>/dev/null ||
 	DIE "Unable to generate random key of 128 characters"
+STATUS_OK "LUKS TPM Disk Unlock Key generated"
 
 previous_luks_header_version=0
 for dev in $key_devices; do
@@ -261,15 +262,17 @@ for dev in $key_devices; do
 		--new-key-slot "$duk_keyslot" \
 		"$dev" "$DUK_KEY_FILE" ||
 		DIE "$dev: Unable to add LUKS TPM Disk Unlock Key to LUKS key slot $duk_keyslot"
+	STATUS_OK "$dev: LUKS TPM Disk Unlock Key added to slot $duk_keyslot"
 done
 
 # Now that we have setup the new keys, measure the PCRs
 # We don't care what ends up in PCR 6; we just want
 # to get the /tmp/luksDump.txt file.  We use PCR16
 # since it should still be zero
-STATUS "Measuring LUKS headers for TPM sealing policy"
+STATUS "Measuring TPM Disk Unlock Key (DUK) for sealing policy (PCR[6])"
 echo "$key_devices" | xargs /bin/qubes-measure-luks.sh ||
 	DIE "Unable to measure the LUKS headers"
+STATUS_OK "TPM Disk Unlock Key (DUK) measured for sealing policy (PCR[6])"
 
 STATUS "Reading current PCR values for TPM sealing policy"
 pcrf="/tmp/secret/pcrf.bin"
@@ -293,6 +296,7 @@ DEBUG "Precomputing TPM future value for PCR6 sealing/unsealing of LUKS TPM Disk
 tpmr.sh calcfuturepcr 6 "/tmp/luksDump.txt" >>"$pcrf"
 # We take into consideration user files in cbfs
 tpmr.sh pcrread -a 7 "$pcrf"
+STATUS_OK "PCR values read for TPM sealing policy"
 
 # tpmr.sh seal may prompt for TPM owner password; avoid DO_WITH_DEBUG here so the
 # prompt remains visible on console. tpmr.sh logs command details internally.

initrd/bin/kexec-seal-key.sh

@@ -204,7 +204,7 @@ parse_option() {
 }
 
 scan_options() {
-	STATUS "Scanning for unsigned boot options"
+	STATUS "Scanning for boot options"
 	option_file="/tmp/kexec_options.txt"
 	scan_boot_options "$bootdir" "$config" "$option_file"
 	if [ ! -s $option_file ]; then
@@ -373,7 +373,7 @@ while true; do
 		if [ ! -r "$TMP_KEY_DEVICES" ]; then
 			# Extend PCR4 as soon as possible
 			TRACE_FUNC
-			INFO "TPM: Extending PCR[4] to prevent further secret unsealing"
+			INFO "TPM: Extending PCR[4] with content of string 'generic' to prevent secret unsealing"
 			tpmr.sh extend -ix 4 -ic generic ||
 				DIE "Failed to extend TPM PCR[4]"
 		fi

initrd/bin/kexec-select-boot.sh

@@ -21,6 +21,7 @@ if [ -n "$APM_CNT" -a -n "$FIN_CODE" ]; then
 	# until the next system reset.
 	STATUS "Finalizing chipset write protection via SMI PR0 lockdown"
 	io386 -o b -b x $APM_CNT $FIN_CODE
+	STATUS_OK "Chipset write protection locked"
 else
 	NOTE "NOT finalizing chipset - lock_chip.sh called without valid APM_CNT and FIN_CODE"
 fi

initrd/bin/lock_chip.sh

@@ -60,6 +60,7 @@ ethernet_activation()
 			insmod.sh /lib/modules/$module.ko
 		fi
 	done
+	STATUS_OK "Ethernet network modules loaded"
 }
 
 # bring up the ethernet interface
@@ -113,10 +114,10 @@ if [ -n "$dev" ]; then
 						STATUS_OK "NTP time sync successful"
 					fi
 				fi
-				STATUS "Syncing hardware clock with system time (UTC)"
-				hwclock -w
-				date=$(date "+%Y-%m-%d %H:%M:%S %Z")
-				STATUS "Time: $date"
+			STATUS "Syncing hardware clock with system time (UTC)"
+			hwclock -w
+			date=$(date "+%Y-%m-%d %H:%M:%S %Z")
+			STATUS_OK "Hardware clock synced: $date"
 			fi
 		fi
 	fi
@@ -133,6 +134,7 @@ if [ -n "$dev" ]; then
 		# -B background
 		# -R create host keys
 		dropbear -B -R
+		STATUS_OK "Dropbear SSH server started"
 	fi
 	STATUS_OK "Network setup complete"
 	ifconfig $dev