openhcl/firmware_uefi: EfiDiagnostics filter known error messages

[maheeraeron]

Certain messages like the following are flooding kmsg with OpenHCL and Hyper-V today:

[2.273523] firmware_uefi::service::diagnostics: INFO  EFI log entry debug_level=PAGE+ERROR ticks=0x18843b2 phase=DXE log_message="ConvertPages: failed to find range 180000000 - 180008FFF"

and this:

[2.273074] firmware_uefi::service::diagnostics: WARN  EFI log entry debug_level=WARNING ticks=0x187fb03 phase=DXE log_message="WARNING: There is mismatch of supported HashMask (0x2 - 0x7) between modules"
[2.273309] firmware_uefi::service::diagnostics: WARN  EFI log entry debug_level=WARNING ticks=0x187fb15 phase=DXE log_message="that are linking different HashInstanceLib instances!"

We should add code in diagnostics.rs such that known message patterns get dropped, with a TODO item to address their fixes from the UEFI side later

[jstarks]

You need to switch these to use tracelimit::info_ratelimited! as well, so that the guest cannot flood the log and thereby hide other things that are going on.

[maheeraeron]

You need to switch these to use tracelimit::info_ratelimited! as well, so that the guest cannot flood the log and thereby hide other things that are going on.

In general yes, I think this is the right thing to do.

We might want to leave messages at ERROR+LOAD level from UEFI persist to tracing::info!() though?

For example:

0.192257038s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xdb650 phase=PEI_CORE log_message="ResetSystemPei.efi"
   0.192308284s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xdb82b phase=PEI_CORE log_message="RngPei.efi"
   0.192328100s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xdba03 phase=PEI_CORE log_message="PlatformPei.efi"
   0.192365419s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe2299 phase=PEI_CORE log_message="PeiCore.efi"
   0.192405919s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe341a phase=PEI_CORE log_message="PcdPeim.efi"
   0.192449493s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe3d41 phase=PEI_CORE log_message="DxeIpl.efi"
   0.192490207s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe5900 phase=PEI_CORE log_message="MsUiThemePpi.efi"
   0.192506718s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe6e00 phase=PEI_CORE log_message="DebugConfigPei.efi"
   0.192543819s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe7d1f phase=PEI_CORE log_message="CryptoPei.efi"
   0.192698286s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xe857f phase=PEI_CORE log_message="Tcg2Pei.efi"
   0.192765598s  INFO firmware_uefi::service::diagnostics:  EFI log entry debug_level=LOAD+ERROR ticks=0xee4dd phase=PEI_CORE log_message="DxeCore.efi"

These are all the driver load messages from UEFI, which I think we want at all times to get an idea of where UEFI was.

If these messages go through tracelimit::info_ratelimited!(), only a few show up and the rest get quickly dropped.

Are we okay with leaving these at tracing::info!()? I'm less worried about other informational level logs

[jstarks]

I am not OK with leaving anything guest-initiated without rate limits. We either need to generate additional trace points (so that the redundant stuff has a different limit counter from the important stuff), or we need to fix UEFI to not log pointless stuff at all.

[jstarks]

In your example, there seem to be two bugs:

1. If the debug level includes ERROR, then presumably we should be logging at error level. The current implementation only does this if the level is just ERROR, which seems wrong.
2. Why the heck is UEFI logging load messages at error level?

[maheeraeron]

1. If the debug level includes ERROR, then presumably we should be logging at error level. The current implementation only does this if the level is just ERROR, which seems wrong.

Initially I did this because I don't want DRIs to confuse ERROR+LOAD as real errors. But once this is fixed, I will make it so that if it includes ERROR, then it should go to tracelimit::error_ratelimited()

2. Why the heck is UEFI logging load messages at error level?

That code existed in DXE core since the beginning of time-- core UEFI team's original intent was to ensure that these logs would always be present since they assumed everyone would at least have ERROR logging on. We have upstream changes on the way to fix this now, so this should be an easy fix.

[maheeraeron]

@tjones60 just checked in a PR that suppresses known error messages for now. I will still leave this issue open as I'm still awaiting UEFI changes to change those LOAD+ERROR messages to LOAD so that all ERROR goes to tracelimit::error_ratelimited().

This was the PR: https://github.com/microsoft/openvmm/pull/1551/files

We probably want to backport this to 1.6

[maheeraeron]

@jstarks This PR should now address the tracelimit feedback, now that I added support for custom period/limit: #1706