verify-sof-firmware-load: fix test to actually check the FW is loaded

[marc-hb]

Searching the logs for the firmware version was stupid because old logs
were enough to make the test pass!

Check whether /sys/kernel/debug/sof/fw_version exists instead.

This also makes the test pass with IPC4 and fixes #842 and #845

Signed-off-by: Marc Herbert marc.herbert@intel.com

[plbossart]

[root@fedora ~]# SOF_VERSION_CHECK=none SOF_LOGGING=none TPLG=/lib/firmware/intel/avs-tplg/sof-hda-generic.tplg ~/sof-test/test-case/verify-sof-firmware-load.sh 
2022-02-10 00:33:03 UTC [INFO] Showing all SOF Firmware version(s) in kernel log (mind the timestamps!)
  ------ /sys/kernel/debug/sof/fw_version found  ----
2022-02-10 00:33:03 UTC [INFO] Test Result: PASS!
[root@fedora ~]# more /sys/kernel/debug/sof/fw_version

doesn't sound very good to me, what does this test in practice? an empty firmware version is a success?

[marc-hb]

an empty /sys/kernel/debug/sof/fw_version version is a success?

The test is named "verify-sof-firmware-load" so yes that looks like a success to me, why not?

Certainly more appropriate than passing based on old and irrelevant logs...

Any better alternative to suggest?

[plbossart]

an empty /sys/kernel/debug/sof/fw_version version is a success?

The test is named "verify-sof-firmware-load" so yes that looks like a success to me, why not?

Certainly more appropriate than passing based on old and irrelevant logs...

Any better alternative to suggest?

if you want to check that the firmware booted, then we should look for specific strings that tell us just that. Or indirectly find a valid version number. An empty version number if not a good sign.

This is what you want to check for:

[    3.279704] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: firmware boot complete
[    3.279705] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 5 -> 6

[marc-hb]

Checking the logs does not really work because it involves time. This test currently passes after unloading the drivers, this is ridiculous.

Is there really nothing equivalent in /sys/kernel/debug/sof ? I could look at several files, that would still be much easier.

[marc-hb]

An empty version number if not a good sign.

This may mean that the firmware is not a good state (which will be detected by further tests) but can this ever be a sign that the firmware is not loaded?

I've been using an sof-logger patch (thesofproject/sof/pull/5027) for a few months locally. This patch makes the sof-logger wait for /sys/kernel/debug/sof/fw_version before starting. I've experienced a number of FW boot failures and I've never seen sof-logger start in that case.

[marc-hb]

How about aplay -l or /proc/asounds/cards?

[libinyang]

How about aplay -l or /proc/asounds/cards?

aplay -l and /proc/asound/cards only tell whether audio is probed and pcm is created successfully or not. If aplay -l passed it means fw is loaded OK. But if it fails, it doesn't mean FW is loaded unsuccessfully. There are some other reasons to make the probe fail.

[libinyang]

an empty /sys/kernel/debug/sof/fw_version version is a success?

The test is named "verify-sof-firmware-load" so yes that looks like a success to me, why not?

Certainly more appropriate than passing based on old and irrelevant logs...

Any better alternative to suggest?

If we want to check the fw_version, it will meet the same issue as aplay. If driver loads unsuccessfully in the main thread, the fw_version entry will be removed. In this situation, you can't tell FW is loaded successfully or not.
You can try below patch to have a test:

diff --git a/sound/soc/sof/core.c b/sound/soc/sof/core.c
index 5c5d97df0d99..7572bea1b1ae 100644
--- a/sound/soc/sof/core.c
+++ b/sound/soc/sof/core.c
@@ -302,6 +302,8 @@ static int sof_probe_continue(struct snd_sof_dev *sdev)
                        "error: failed to register machine driver %d\n", ret);
                goto fw_trace_err;
        }
+       dev_err(sdev->dev, "in %s %d fake fail\n", __func__, __LINE__);
+       goto sof_machine_err;

        ret = sof_register_clients(sdev);
        if (ret < 0) {

You can find "firmware boot complete" is showed in dmesg, which means fw is loaded successfully. But cat fw_version will fail.
So I think @plbossart 's suggestion is the only correct solution.

[plbossart]

Checking the logs does not really work because it involves time. This test currently passes after unloading the drivers, this is ridiculous.

Is there really nothing equivalent in /sys/kernel/debug/sof ? I could look at several files, that would still be much easier.

@marc-hb not able to understand why a log isn't good. that's what we use to report errors, don't we? if you want to double check that a driver is bound, you can add an additional check. I think it's feasible with sysfs or lspci, but that's different to checking if the firmware booted.

[marc-hb]

@marc-hb not able to understand why a log isn't good.

Because the test to check whether the firmware is loaded passes after unloading the firmware. Especially ridiculous in the unload-reload test!!

that's what we use to report errors, don't we?

Yes but only thanks an elaborate timestamp scheme (a.k.a. "kernel checkpoint") that could be used in the load-unload test but can simply not be used in any "spot check" like this one.

So how about this: because nothing in /sys tells us whether the firmware is loaded right now (hard to believe but it is what it is) let's delete this standalone "spot check", it's just not possible and never seemed very useful anyway. Then I fix the unload-reload to look for your firmware boot complete line at the right time thanks to our "kernel checkpoints".

[marc-hb]

A. let's delete this standalone "spot check", it's just not possible and never seemed very useful anyway. B. Then I fix the unload-reload to look for your firmware boot complete line at the right time thanks to our "kernel checkpoints".

Actually: first B and then A. Obviously.

[plbossart]

@marc-hb not able to understand why a log isn't good.

Because the test to check whether the firmware is loaded passes after unloading the firmware. Especially ridiculous in the unload-reload test!!

that's what we use to report errors, don't we?

Yes but only thanks an elaborate timestamp scheme (a.k.a. "kernel checkpoint") that could be used in the load-unload test but can simply not be used in any "spot check" like this one.

So how about this: because nothing in /sys tells us whether the firmware is loaded right now (hard to believe but it is what it is) let's delete this standalone "spot check", it's just not possible and never seemed very useful anyway. Then I fix the unload-reload to look for your firmware boot complete line at the right time thanks to our "kernel checkpoints".

Why can't we also do this on the initial test? It's useful to check if the firmware booted correctly the FIRST time. doing it only when cycling load/unload is weird.

Put differently, the 'load' sequence is exactly the same for the first boot, or after doing the remove. I don't see why we should special-case stress tests.

[marc-hb]

Why can't we also do this on the initial test?

We can but it's a different test.

So, new proposal:

• Rename verify-sof-firmware-load to verify-fw-loaded-at-least-once. So this test stops lying about what it does.
• Fix the unload-reload test so it does NOT use verify-fw-loaded-at-least-once. Thanks to the new and correct name the bug is now very obvious. Make the unload-reload test use log kernel checkpoints instead (like other tests)
• In all cases look for firmware boot complete instead of firmware versions to support IPC4.
• Internally, move common code to case-lib/ to avoid duplication.

[plbossart]

Why can't we also do this on the initial test?

We can but it's a different test.

So, new proposal:

• Rename verify-sof-firmware-load to verify-fw-loaded-at-least-once. So this test stops lying about what it does.
• Fix the unload-reload test so it does NOT use verify-fw-loaded-at-least-once. Thanks to the new and correct name the bug is now very obvious. Make the unload-reload test use log kernel checkpoints instead (like other tests)
• In all cases look for firmware boot complete instead of firmware versions to support IPC4.
• Internally, move common code to case-lib/ to avoid duplication.

sounds good to me @marc-hb.

I am not sure if 'at least once' is the right name, you can't load the same firmware twice but that's fine. Maybe 'first boot' or something.

[marc-hb]

So, new proposal:

Submitted in #860 which superseded this. I'm keeping this open for now as reminder because there may still be some stuff to salvage from this PR.

I am not sure if 'at least once' is the right name, you can't load the same firmware twice but that's fine. Maybe 'first boot' or something.

I haven't included any rename in #860 so it can be reviewed and merged faster. Will do later.

[marc-hb]

This is what you want to check for:
[ 3.279704] kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: firmware boot complete

I just noticed by chance that even when running verify-sof-firmware-load as the very first test this line can appear multiple times. Because of D3.

Should not be a problem.

[marc-hb]

Submitted in #860 which superseded this. I'm keeping this open for now as reminder because there may still be some stuff to salvage from this PR.

The rest (and a bit more) submitted in

• verify-sof-firmware-load: fix dmesg.txt collection + better logs + fix -help #873