Improve DEBUG and DO_WITH_DEBUG output handling to also keep output of DO_WITH_DEBUG commands

[tlaurion]

Outcome of this PR:

• We can now ask users to toggle debug+tracing at runtime (or flash back config to have early boot debugging as well) to produce logs under /tmp/debug.log and dmesg
• bonus : debug also includes board name and commit id.
• make qemu-coreboot boards references for anyone wanting to understand what board configs are about. Until those are splitter into Mk files per functions, which board configs will include. This is Create seperate targets/*.mk files: Add TPM1/TPM2/HOTP/Common/whiptail/fbwhiptail/tethering others. #1643

TODO:

• modify issue template with instructions on how to get those logs. Basically
  • Config settings - enable debug and trace
  • do whatever doesn't work
  • Go to recovery shell if not landing there already by bug
    • mount-usb --mode rw
    • cp /tmp/debug.log /media
    • umount /media
  • attach said log to issue.

---

SRC #1642 (comment):

From out of band discussion:

• We tweaked the labeling of stdout/stderr in the logs to be clearer ("$1 err:" looked like an error, "$1 stderr:" is better)
• stdout/stderr no longer go to kmsg since we never really want these on the console, log file only (added LOG for verbose tracing like this), silenced kexec stderr from the console too with 2>/dev/null
• restored eval in front of $kexeccmd, DO_WITH_DEBUG should be the same as regular command invocation so just add DO_WITH_DEBUG to the existing eval
• board and version are debug-logged when entering recovery shell

And then

• make qemu-coreboot-* board configs clear enough to be used for references for tpm1/tpm2 /HOTP/non-HOTP and properly documented.

---

Old

Goal here was to have kexec -l output to kmesg so also to console when BOARD is in DEBUG+TRACE mode (configuration settings menu + flash)

@JonathonHall-Purism please review

A variation of this commit is under #1640 to troubleshoot #1641 more easily and permit users to provide /tmp/debug.log

[tlaurion]

Without debug on qemu-coreboot-whiptail-tpm2-hotp

~ # kexec-select-boot -b /boot -f
 *** WARNING: Hash of TPM2 primary key handle does not exist ***
 *** WARNING: Please rebuild the boot hash tree ***
+++ Found verified kexec boot params
+++ Scanning for unsigned boot options
+++ Select your boot option:
1. Ubuntu [kernel /vmlinuz-6.5.0-14-generic]
2. Ubuntu, with Linux 6.5.0-14-generic [kernel /vmlinuz-6.5.0-14-generic]
3. Ubuntu, with Linux 6.5.0-14-generic (recovery mode) [kernel /vmlinuz-6.5.0-14-generic]
4. Ubuntu, with Linux 5.15.0-48-generic [kernel /vmlinuz-5.15.0-48-generic]
5. Ubuntu, with Linux 5.15.0-48-generic (recovery mode) [kernel /vmlinuz-5.15.0-48-generic]
6. Memory test (memtest86+.bin, serial console) [kernel /memtest86+.bin]
Choose the boot option [1-6, a to abort]: 1
Enter LUKS TPM Disk Unlock Key passphrase (blank to abort): 
!!! ERROR: Aborting unseal disk encryption key !!!

!!! Failed to unseal the TPM LUKS disk key
Do you wish to boot and use the LUKS Disk Recovery Key? [Y/n] y

+++ Building initrd
232902+1 records in
232903+0 records out
119246336 bytes (113.7MB) copied, 3.421565 seconds, 33.2MB/s
Loading the new kernel:
kexec -l /boot/vmlinuz-6.5.0-14-generic --initrd=/tmp/secret/initrd.cpio --append="root=/dev/mapper/vgubuntu-root ro console=ttyS0 console=tty systemd.zram=0 console=ttyS0 console=tty systemd.zram=0  vt.default_red=0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff,0xff"
Locking TPM2 platform hierarchy...
Starting the new kernel
qemu: terminating on signal 2

No observed regression and really big step forward to have useful user generated bug reports. :)

[JonathonHall-Purism]

Thanks for splitting this up, taking a look 👀

[JonathonHall-Purism]

@tlaurion Suggestion here: JonathonHall-Purism@015af7e

TL;DR - DO_WITH_DEBUG can be inserted anywhere with no impact to the script (exit status / stdout / stderr all stay the same from the script's perspective) and with minimal spam (trace exit status only when nonzero, trace PATH only for exit status 127, trace output only when non-empty, etc.)

This way you can add/remove a DO_WITH_DEBUG just about anywhere without risking subtle breakage due to stdout/stderr being consumed, splitting or not splitting a single argument, etc.

I improved the documentation and examples in the comment too, so have a look over there 🙂

Specifically:

• It looks to me like kexec-unseal-key would have had failed:
  • --mask-position was breaking the password (it executed the masked command)
  • I think set -e would have caused it to terminate
• Do not split a single argument, I think that's a bad idea as I said in https://github.com/linuxboot/heads/pull/1640/files#r1571385205 (and it violates the "just add/remove DO_WITH_DEBUG with no impact" design)
• Exit status is only trace if unsuccessful to reduce spam
• Command output is only traced if not empty to reduce spam
• Out/err are clearly marked in the debug log ($1 out / $1 err)
• PATH is only traced if the command was (probably) not found to reduce spam (exit status 127)
• Out/err still go to the caller as they would without DO_WITH_DEBUG so you can use it anywhere

---

I didn't test Heads logic extensively yet (help appreciated!) but I did test DO_WITH_DEBUG itself.

Silent success - traces command, nothing else:

~ # bash -c '. /etc/functions; DO_WITH_DEBUG true; echo $?'
[   32.377401] DEBUG: true
0

Silent failure - traces command and exit status, caller still sees status:

~ # bash -c '. /etc/functions; DO_WITH_DEBUG false; echo $?'
[   28.408719] DEBUG: false
[   28.415424] DEBUG: false: exited with status 1
1

stdout - caller still observes output, traced with label:

~ # bash -c '. /etc/functions; DO_WITH_DEBUG ls /; echo $?'
[   22.737953] DEBUG: ls /
bin
boot
dev
etc
init
lib
media
mount-boot
proc
run
sbin
sys
tmp
0
~ # [   22.749170] DEBUG: ls out: bin
[   22.752434] DEBUG: ls out: boot
[   22.758151] DEBUG: ls out: dev
[   22.761524] DEBUG: ls out: etc
[   22.764724] DEBUG: ls out: init
[   22.767905] DEBUG: ls out: lib
[   22.772845] DEBUG: ls out: media
[   22.776752] DEBUG: ls out: mount-boot
[   22.779941] DEBUG: ls out: proc
[   22.783067] DEBUG: ls out: run
[   22.786146] DEBUG: ls out: sbin
[   22.790383] DEBUG: ls out: sys
[   22.793391] DEBUG: ls out: tmp

stderr - still printed normally, caller observes exit status

~ # bash -c '. /etc/functions; DO_WITH_DEBUG ls /dummy; echo $?'
[   40.044565] DEBUG: ls /dummy
ls: /dummy: No such file or directory
[   40.051851] DEBUG: ls err: ls: /dummy: No such file or directory
[   40.055193] DEBUG: ls: exited with status 1
1

command does not exist - stderr still printed, PATH shown, caller observes status

~ # bash -c '. /etc/functions; DO_WITH_DEBUG dummy; echo $?'
[   54.542449] DEBUG: dummy
/etc/functions: line 97: dummy: command not found
[   54.546724] DEBUG: dummy err: /etc/functions: line 97: dummy: command not found
[   54.548941] DEBUG: dummy: exited with status 127
[   54.550579] DEBUG: dummy: PATH=/sbin:/bin:/usr/sbin:/usr/bin:/usr/local/bin
127

Also ran all of the above with set -eo pipefail, output is essentially the same (other than set -e preventing the echo $? for failures)

[JonathonHall-Purism]

Oh and one more I just remembered - masking a parameter (showing it still executes with the unmasked value) and output that doesn't end in a line break:

~ # bash -c '. /etc/functions; DO_WITH_DEBUG --mask-position 2 echo -n foo " "; 
echo $?'
[  234.772789] DEBUG: echo -n <hidden>
foo  0
~ # [  234.781664] DEBUG: echo out: foo

[JonathonHall-Purism]

From out of band discussion:

• We tweaked the labeling of stdout/stderr in the logs to be clearer ("$1 err:" looked like an error, "$1 stderr:" is better)
• stdout/stderr no longer go to kmsg since we never really want these on the console, log file only (added LOG for verbose tracing like this), silenced kexec stderr from the console too with 2>/dev/null
• restored eval in front of $kexeccmd, DO_WITH_DEBUG should be the same as regular command invocation so just add DO_WITH_DEBUG to the existing eval
• board and version are debug-logged when entering recovery shell

[tlaurion]

Testing first prior of merging.

[tlaurion]

Ci builds, if failing, would be CI related. Merging.