Skip to content

DEBUG+TRACE mode: provide a complete call stack trace on console / debug.log #1934

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Closed
wants to merge 1 commit into from

Conversation

tlaurion
Copy link
Collaborator

When board/runtime configuration settings have DEBUG+TRACE turned on, to ease understanding where things are happening/producing output, its not always easy to understand the call trace. This Pull requests addresses that.

DEBUG+TRACE mode is default for qemu boards variants that are not "production" variants.
End users/devels can turn this on through Configuration Settings, since the default is quiet mode.

Before:

[    4.306902] Run /init as init process
[    4.309896]   with arguments:
[    4.313204]     /init
[    4.316184]   with environment:
[    4.319522]     HOME=/
[    4.323056]     TERM=linux
[    4.467595] [U] hello world
[    4.884642] TRACE: /bin/cbfs-init(12): main
[    5.124552] TRACE: /etc/functions(308): combine_configs
[    5.176783] TRACE: /init(102): main
[    5.256951] DEBUG: Full debug output enabled from this point: output both in dmesg and on console (equivalent of passing debug to kernel cmdline)
[    5.321704] DEBUG: NOTE: DO_WITH_DEBUG std_err and std_out will be redirected to /tmp/debug.log
[    5.385998] TRACE: /init(129): main
[    5.469463] DEBUG: Applying panic_on_oom setting to sysctl
[    5.699167] TRACE: /bin/key-init(6): main
[    8.232087]  *** WARNING: Adding user's keys to distro keys failed ***
[    9.305520] TRACE: /etc/functions(302): pause_recovery
!!! Hit enter to proceed to recovery shell !!!
[    9.625526] TRACE: /bin/setconsolefont.sh(6): main
[    9.688778] DEBUG: Board does not ship setfont, not checking console font
[    9.953825] TRACE: /bin/gui-init(631): main
[    9.987605] TRACE: /etc/functions(364): enable_usb
[   10.098270] TRACE: /sbin/insmod(9): main
[   10.245902] TPM: Extending PCR[5] with /lib/modules/ehci-hcd.ko and parameters '' before loading
[   10.278587] TRACE: /sbin/insmod(53): main
[   10.309936] No module parameters, extending only with the module's content
[   10.460897] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ehci-hcd.ko
[   10.582720] TRACE: /bin/tpmr(802): main
[   10.628715] TPM: Extending PCR[5] with hash a4bac2eb1d4ceecbd95f500cf0e31dd3aafea560
[   10.711091] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ehci-hcd.ko
[   10.947208] DEBUG: Loading /lib/modules/ehci-hcd.ko with busybox insmod
[   11.107759] TRACE: /sbin/insmod(9): main
[   11.262344] TPM: Extending PCR[5] with /lib/modules/uhci-hcd.ko and parameters '' before loading
[   11.291277] TRACE: /sbin/insmod(53): main
[   11.325092] No module parameters, extending only with the module's content
[   11.479691] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/uhci-hcd.ko
[   11.573443] TRACE: /bin/tpmr(802): main
[   11.602725] TPM: Extending PCR[5] with hash cfd84d5de268371d6977d81eee1e53c0ab2c5f39
[   11.665743] DEBUG: exec tpm extend -ix 5 -if /lib/modules/uhci-hcd.ko
[   11.838017] DEBUG: Loading /lib/modules/uhci-hcd.ko with busybox insmod
[   11.970697] TRACE: /sbin/insmod(9): main
[   12.123714] TPM: Extending PCR[5] with /lib/modules/ohci-hcd.ko and parameters '' before loading
[   12.139995] TRACE: /sbin/insmod(53): main
[   12.181554] No module parameters, extending only with the module's content
[   12.307836] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ohci-hcd.ko
[   12.372850] TRACE: /bin/tpmr(802): main
[   12.393608] TPM: Extending PCR[5] with hash 3da371fb66cdb653706651604ff9d0e364403893
[   12.462225] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ohci-hcd.ko
[   12.641877] DEBUG: Loading /lib/modules/ohci-hcd.ko with busybox insmod
[   12.758674] TRACE: /sbin/insmod(9): main
[   12.915371] TPM: Extending PCR[5] with /lib/modules/ohci-pci.ko and parameters '' before loading
[   12.950989] TRACE: /sbin/insmod(53): main
[   12.981798] No module parameters, extending only with the module's content
[   13.138811] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ohci-pci.ko
[   13.219983] TRACE: /bin/tpmr(802): main
[   13.253136] TPM: Extending PCR[5] with hash 9a584a69fdf5f3fac43bfb4526c41b688bf18541
[   13.323110] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ohci-pci.ko
[   13.529972] DEBUG: Loading /lib/modules/ohci-pci.ko with busybox insmod
[   13.649589] TRACE: /sbin/insmod(9): main
[   13.802208] TPM: Extending PCR[5] with /lib/modules/ehci-pci.ko and parameters '' before loading
[   13.834917] TRACE: /sbin/insmod(53): main
[   13.870674] No module parameters, extending only with the module's content
[   14.066878] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ehci-pci.ko
[   14.150974] TRACE: /bin/tpmr(802): main
[   14.180830] TPM: Extending PCR[5] with hash 38f9a96aa8774f5198753248e164367a9eaaf102
[   14.247225] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ehci-pci.ko
[   14.449537] DEBUG: Loading /lib/modules/ehci-pci.ko with busybox insmod
[   14.572380] TRACE: /sbin/insmod(9): main
[   14.724192] TPM: Extending PCR[5] with /lib/modules/xhci-hcd.ko and parameters '' before loading
[   14.753744] TRACE: /sbin/insmod(53): main
[   14.786047] No module parameters, extending only with the module's content
[   14.949749] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/xhci-hcd.ko
[   15.056455] TRACE: /bin/tpmr(802): main
[   15.091812] TPM: Extending PCR[5] with hash fa097f1129a9d80f3bfbab5c45f0965c2e4e1c8d
[   15.155918] DEBUG: exec tpm extend -ix 5 -if /lib/modules/xhci-hcd.ko
[   15.360811] DEBUG: Loading /lib/modules/xhci-hcd.ko with busybox insmod
[   15.506479] TRACE: /sbin/insmod(9): main
[   15.664849] TPM: Extending PCR[5] with /lib/modules/xhci-pci.ko and parameters '' before loading
[   15.693488] TRACE: /sbin/insmod(53): main
[   15.734548] No module parameters, extending only with the module's content
[   15.897806] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/xhci-pci.ko
[   15.977377] TRACE: /bin/tpmr(802): main
[   16.023220] TPM: Extending PCR[5] with hash fea887117bb26df62ede05afdb5fdd8230cd9732
[   16.103508] DEBUG: exec tpm extend -ix 5 -if /lib/modules/xhci-pci.ko
[   16.291089] DEBUG: Loading /lib/modules/xhci-pci.ko with busybox insmod
[   16.323884] xhci_hcd 0000:00:04.0: xHCI Host Controller
[   16.328391] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 1
[   16.343726] xhci_hcd 0000:00:04.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010
[   16.356131] xhci_hcd 0000:00:04.0: xHCI Host Controller
[   16.367136] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 2
[   16.371637] xhci_hcd 0000:00:04.0: Host supports USB 3.0 SuperSpeed
[   16.391205] hub 1-0:1.0: USB hub found
[   16.396395] hub 1-0:1.0: 4 ports detected
[   16.417067] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[   16.451639] hub 2-0:1.0: USB hub found
[   16.457319] hub 2-0:1.0: 4 ports detected
[   16.702956] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[   17.002743] usb 2-2: new SuperSpeed USB device number 2 using xhci_hcd
[   18.541770] TRACE: /etc/functions(1130): detect_boot_device
[   18.931225] TRACE: /etc/functions(1086): mount_possible_boot_device
[   18.988700] TRACE: /etc/functions(1046): is_gpt_bios_grub
[   19.097298] TRACE: /dev/vda is not a mountable partition for /boot
[   19.195130] TRACE: /etc/functions(1086): mount_possible_boot_device
[   19.247477] TRACE: /etc/functions(1046): is_gpt_bios_grub
[   19.332709] TRACE: /dev/vda is not a mountable partition for /boot
[   19.376969] TRACE: /bin/gui-init(20): mount_boot

After:

[    3.695136] Run /init as init process
[    3.697294]   with arguments:
[    3.699434]     /init
[    3.703019]   with environment:
[    3.706338]     HOME=/
[    3.708011]     TERM=linux
[    3.814388] [U] hello world
[    4.180235] TRACE: main(/bin/cbfs-init:12)
[    4.369723] TRACE: main(/init:92) -> combine_configs(/etc/functions:308)
[    4.428664] TRACE: main(/init:102)
[    4.514235] DEBUG: Full debug output enabled from this point: output both in dmesg and on console (equivalent of passing debug to kernel cmdline)
[    4.582312] DEBUG: NOTE: DO_WITH_DEBUG std_err and std_out will be redirected to /tmp/debug.log
[    4.618649] TRACE: main(/init:129)
[    4.660898] DEBUG: Applying panic_on_oom setting to sysctl
[    4.854483] TRACE: main(/bin/key-init:6)
[    7.097158]  *** WARNING: Adding user's keys to distro keys failed ***
[    8.169724] TRACE: main(/init:184) -> pause_recovery(/etc/functions:302)
!!! Hit enter to proceed to recovery shell !!!
[    8.459168] TRACE: main(/bin/setconsolefont.sh:6)
[    8.541743] DEBUG: Board does not ship setfont, not checking console font
[    8.790340] TRACE: main(/bin/gui-init:631)
[    8.824333] TRACE: main(/bin/gui-init:641) -> enable_usb(/etc/functions:364)
[    8.937608] TRACE: main(/sbin/insmod:9)
[    9.117674] TPM: Extending PCR[5] with /lib/modules/ehci-hcd.ko and parameters '' before loading
[    9.148579] TRACE: main(/sbin/insmod:53)
[    9.181364] No module parameters, extending only with the module's content
[    9.330947] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ehci-hcd.ko
[    9.415643] TRACE: main(/bin/tpmr:802)
[    9.462588] TPM: Extending PCR[5] with hash a4bac2eb1d4ceecbd95f500cf0e31dd3aafea560
[    9.534084] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ehci-hcd.ko
[    9.729698] DEBUG: Loading /lib/modules/ehci-hcd.ko with busybox insmod
[    9.855062] TRACE: main(/sbin/insmod:9)
[   10.044589] TPM: Extending PCR[5] with /lib/modules/uhci-hcd.ko and parameters '' before loading
[   10.080619] TRACE: main(/sbin/insmod:53)
[   10.114875] No module parameters, extending only with the module's content
[   10.255691] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/uhci-hcd.ko
[   10.341724] TRACE: main(/bin/tpmr:802)
[   10.369509] TPM: Extending PCR[5] with hash cfd84d5de268371d6977d81eee1e53c0ab2c5f39
[   10.441941] DEBUG: exec tpm extend -ix 5 -if /lib/modules/uhci-hcd.ko
[   10.651250] DEBUG: Loading /lib/modules/uhci-hcd.ko with busybox insmod
[   10.773059] TRACE: main(/sbin/insmod:9)
[   10.931800] TPM: Extending PCR[5] with /lib/modules/ohci-hcd.ko and parameters '' before loading
[   10.969017] TRACE: main(/sbin/insmod:53)
[   11.004900] No module parameters, extending only with the module's content
[   11.166461] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ohci-hcd.ko
[   11.245659] TRACE: main(/bin/tpmr:802)
[   11.279167] TPM: Extending PCR[5] with hash 3da371fb66cdb653706651604ff9d0e364403893
[   11.343464] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ohci-hcd.ko
[   11.552797] DEBUG: Loading /lib/modules/ohci-hcd.ko with busybox insmod
[   11.668448] TRACE: main(/sbin/insmod:9)
[   11.820264] TPM: Extending PCR[5] with /lib/modules/ohci-pci.ko and parameters '' before loading
[   11.850608] TRACE: main(/sbin/insmod:53)
[   11.888349] No module parameters, extending only with the module's content
[   12.069884] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ohci-pci.ko
[   12.157966] TRACE: main(/bin/tpmr:802)
[   12.188691] TPM: Extending PCR[5] with hash 9a584a69fdf5f3fac43bfb4526c41b688bf18541
[   12.257048] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ohci-pci.ko
[   12.450499] DEBUG: Loading /lib/modules/ohci-pci.ko with busybox insmod
[   12.578463] TRACE: main(/sbin/insmod:9)
[   12.731850] TPM: Extending PCR[5] with /lib/modules/ehci-pci.ko and parameters '' before loading
[   12.762571] TRACE: main(/sbin/insmod:53)
[   12.799871] No module parameters, extending only with the module's content
[   12.962378] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/ehci-pci.ko
[   13.057046] TRACE: main(/bin/tpmr:802)
[   13.088693] TPM: Extending PCR[5] with hash 38f9a96aa8774f5198753248e164367a9eaaf102
[   13.156952] DEBUG: exec tpm extend -ix 5 -if /lib/modules/ehci-pci.ko
[   13.334691] DEBUG: Loading /lib/modules/ehci-pci.ko with busybox insmod
[   13.473618] TRACE: main(/sbin/insmod:9)
[   13.637968] TPM: Extending PCR[5] with /lib/modules/xhci-hcd.ko and parameters '' before loading
[   13.670188] TRACE: main(/sbin/insmod:53)
[   13.703716] No module parameters, extending only with the module's content
[   13.849469] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/xhci-hcd.ko
[   13.950473] TRACE: main(/bin/tpmr:802)
[   13.980471] TPM: Extending PCR[5] with hash fa097f1129a9d80f3bfbab5c45f0965c2e4e1c8d
[   14.060847] DEBUG: exec tpm extend -ix 5 -if /lib/modules/xhci-hcd.ko
[   14.273667] DEBUG: Loading /lib/modules/xhci-hcd.ko with busybox insmod
[   14.398645] TRACE: main(/sbin/insmod:9)
[   14.584733] TPM: Extending PCR[5] with /lib/modules/xhci-pci.ko and parameters '' before loading
[   14.616519] TRACE: main(/sbin/insmod:53)
[   14.656415] No module parameters, extending only with the module's content
[   14.802791] DEBUG: TPM: Will extend PCR[5] hash content of file /lib/modules/xhci-pci.ko
[   14.880300] TRACE: main(/bin/tpmr:802)
[   14.907501] TPM: Extending PCR[5] with hash fea887117bb26df62ede05afdb5fdd8230cd9732
[   14.986463] DEBUG: exec tpm extend -ix 5 -if /lib/modules/xhci-pci.ko
[   15.180198] DEBUG: Loading /lib/modules/xhci-pci.ko with busybox insmod
[   15.208981] xhci_hcd 0000:00:04.0: xHCI Host Controller
[   15.212776] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 1
[   15.226603] xhci_hcd 0000:00:04.0: hcc params 0x00087001 hci version 0x100 quirks 0x0000000000000010
[   15.234529] xhci_hcd 0000:00:04.0: xHCI Host Controller
[   15.238430] xhci_hcd 0000:00:04.0: new USB bus registered, assigned bus number 2
[   15.243596] xhci_hcd 0000:00:04.0: Host supports USB 3.0 SuperSpeed
[   15.258512] hub 1-0:1.0: USB hub found
[   15.266773] hub 1-0:1.0: 4 ports detected
[   15.275684] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[   15.281193] hub 2-0:1.0: USB hub found
[   15.285723] hub 2-0:1.0: 4 ports detected
[   15.541648] usb 1-1: new high-speed USB device number 2 using xhci_hcd
[   15.841733] usb 2-2: new SuperSpeed USB device number 2 using xhci_hcd
[   17.347451] TRACE: main(/bin/gui-init:644) -> detect_boot_device(/etc/functions:1158)
[   17.758260] TRACE: main(/bin/gui-init:644) -> detect_boot_device(/etc/functions:1188) -> mount_possible_boot_device(/etc/functions:1114)
[   17.817842] TRACE: main(/bin/gui-init:644) -> detect_boot_device(/etc/functions:1188) -> mount_possible_boot_device(/etc/functions:1126) -> is_gpt_bios_grub(/etc/functions:1074)
[   17.908715] TRACE: /dev/vda is not a mountable partition for /boot
[   18.031541] TRACE: main(/bin/gui-init:644) -> detect_boot_device(/etc/functions:1188) -> mount_possible_boot_device(/etc/functions:1114)
[   18.100893] TRACE: main(/bin/gui-init:644) -> detect_boot_device(/etc/functions:1188) -> mount_possible_boot_device(/etc/functions:1126) -> is_gpt_bios_grub(/etc/functions:1074)
[   18.196908] TRACE: /dev/vda is not a mountable partition for /boot
[   18.238089] TRACE: main(/bin/gui-init:650) -> mount_boot(/bin/gui-init:20)

Comment on lines 549 to 563
DEBUG_STACK() {
local FRAMES
FRAMES="${#FUNCNAME[@]}"
DEBUG "call stack: ($((FRAMES - 1)) frames)"
# Don't print DEBUG_STACK itself, start from 1
for i in $(seq 1 "$((FRAMES - 1))"); do
DEBUG "- $((i - 1)) - ${BASH_SOURCE[$i]}(${BASH_LINENO[$((i - 1))]}): ${FUNCNAME[$i]}"
local SKIP_FIRST=0

# If TRACE_FUNC called DEBUG_STACK, remove it from the stack to avoid redundancy.
[[ "${FUNCNAME[1]}" == "TRACE_FUNC" ]] && SKIP_FIRST=1

# Get the total number of stack frames
local FRAMES="${#FUNCNAME[@]}"
DEBUG "call stack: ($((FRAMES - 1 - SKIP_FIRST)) frames)"

# Iterate through the stack and print each function call with file and line number
for i in $(seq $((1 + SKIP_FIRST)) "$((FRAMES - 1))"); do
DEBUG "- $((i - 1 - SKIP_FIRST)) - ${BASH_SOURCE[$i]}(${BASH_LINENO[$((i - 1))]}): ${FUNCNAME[$i]}"
done
}
Copy link
Collaborator

Choose a reason for hiding this comment

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

This looks like an artifact from some earlier implementation - TRACE_FUNC doesn't call DEBUG_STACK in the final version, so I think you should revert this

@tlaurion
Copy link
Collaborator Author

Included and cleaned up under #1935

@tlaurion tlaurion closed this Mar 25, 2025
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
2 participants