Logger abi check #3195

ktrzcinx · 2020-07-15T09:52:30Z

Compatibility between fw and ldc file is checked in logger tool before logs convertion.
This mechanism was comparing sof_ipc_fw_version->abi_version saved in ldc file and
in fw_ready message, but in ldc this field is filled with DBG_ABI and in fw_ready with ABI,
so it wasn't working at all. Moreover FW and LDC file must mach exactly, so comparing ABI
version is too generous approach, it's much better to calculate fw hash for comparison.

The best would be to calculate executable binary hash and save it back to binary file and to ldc file,
then for example changing unlinked code, or comment in source code won't break ldc and firmware compatibility.
But this approach needs quite complex edition of output executable file or double compilation.

Much simpler approach is to hash source code before compilation and save this value in separate file,
then each whitespace has impact on FW hash, but it's shouldn't be real problem. In this approach
git tools can be used to calculate this value, so there no need for any new external tool.

See: #3243

Extracted from discussion:

we have two approaches:

First, hashing whole tracked source code :

Profits:

+Possibility to catch any local change (FW incompatibility with git source code pointed by hash commit)
+Straight forward build process, without additional hooks / build steps - easy to maintain
Drawbacks:

-Every time fw is updated, ldc should be updated too. (ATM compatibility check is optional, but in version where it will be checked by default, there should be flag to force 'no check' for situations like this - just like git hooks works).
Second, hashing only dictionary, and post build fw_ready section edit :

Profits:

+Dictionary compatibility kept after small FW changes (even one line add/delete breaks ldc compatibility because line number related with log message is saved in ldc file)
Drawbacks:

-Post build elf edition - one more obligatory post build step / making SMEX run obligatory and adding to them hashing library or double obligatory SMEX run (first to produce ldc file, then hash it in CMake, and second one SMEX, to fill value in fw_ready section). SMEX may be chosen because atm. SMEX is the only 'external' user of fw_ready section in elf file.

Maybe I missed something?
I choose 1. version because I prefer as simple and clear build-system architecture as it is possible.

paulstelian97

I guess this still needs to go through the ABI change procedure but the change itself is good.

lgirdwood

@mmaka1 any comments

scripts/cmake/version.cmake

lgirdwood · 2020-07-16T12:02:49Z

src/include/ipc/info.h

how is this different from git version hash ?

SOF_TAG refer git commit hash, changed after each commit, so I can edit file without commit, what wouldn't change SOF_TAG but will break ldc file compatibility. fw_hash will change value after each edit of any file tracked in git (answer for following question).

ok, so this need to be made clear in the comments alongside it's reproducability.

lgirdwood · 2020-07-16T12:07:56Z

src/init/ext_manifest.c

Is this reproducible - i.e are you hashing any generated files that could differ for different users.

lyakh

'SOF_TAG' refer git commit hash, changed after each commit, so I can edit file without commit, what wouldn't change 'SOF_TAG' but will break ldc file compatibility. 'fw_hash' will change value after each edit of any file tracked in git (answer for following question).

@ktrzcinx if you want to track uncommitted changes, then this isn't sufficient either. You can add (without committing) a new `#include' to a .c or .h file and then change that new header and since it isn't known to git, it won't be hashed. Maybe you need to get a file list from the compiler? This will then include any system headers used, but that shouldn't be harmful either.

lyakh · 2020-07-20T06:29:51Z

scripts/cmake/version.cmake

is this any different from just git ls-files stc?

I didn't notice any difference in results, I used src/* to indicate that I want files from some directory. Updated to version with src.

tools/logger/convert.c

ktrzcinx · 2020-07-20T14:58:14Z

@ktrzcinx if you want to track uncommitted changes, then this isn't sufficient either. You can add (without committing) a new `#include' to a .c or .h file and then change that new header and since it isn't known to git, it won't be hashed. Maybe you need to get a file list from the compiler? This will then include any system headers used, but that shouldn't be harmful either.

I'm little afraid that hashing system headers may impact hash reproducability - user with different toolchain version perhaps calculate different hash version, what's not an issue with my approach (because only hashing sof-git-tracked files).

Described scenario with `#include' to a .c or .h file actually can be made, but it's quite rare scenario. Please remember, it's not security check, it's rather to warn about outdated / incapatible ldc file usage.

mmaka1 · 2020-07-28T18:46:38Z

tools/logger/convert.c

Should the verification be mandatory now, as it is more reliable (-e assumed when reading live trace and -v assumed when reading from a file)?

It sounds good for me, maybe then some flag, e.g. -E should be added to force running without compatibility check. It sound like something for separate PR

marc-hb · 2020-07-31T21:57:21Z

@ktrzcinx posted an interesting example but github seems to have lost it. Here it is again:

- tr_info(dev, "Some value %d", a);
+ tr_info(dev, "Some value %d", b);

Here ldc hash will be the same for both examples, source code hash will differ.

If this is a "quick and dirty fix" in a local developer workspace or "between two friends" then in an ideal world and for convenience it should not require a new dictionary. This is exactly what concerns me here, thanks for the interesting example.
If this is real change in a commit in the shared main branch then the message (and of course the dictionary) must absolutely be changed too otherwise you'd have two different values logged the exact same way: incredibly confusing!

tr_info(dev, "Some _different_ value B %d", b);

No, it doesn't [break tracing in tarball build anymore].

Nice fallback on the git hash, smart.

(even one line add/delete breaks ldc compatibility because line number related with log message is saved in ldc file)

Very good point, I didn't know this.

there should be flag to force 'no check' for situations like this

Great, I think this would make a big difference.

Post build elf edition

You're really making this look much more complicated than it would be.

making SMEX run obligatory

SMEX is already the tool that creates the dictionary in the first place!?!

adding to them hashing library or double obligatory SMEX run (first to produce ldc file, then hash it in CMake, and second one SMEX to fill value in fw_ready section).

None of that. CMake can hash the dictionary with one-line. objcopy can insert the hash with another line, done?

lgirdwood · 2020-08-04T19:26:20Z

SOFCI TEST

lgirdwood · 2020-08-04T19:27:40Z

CI appears to have got stuck - rerun. @marc-hb @ktrzcinx any more comments or updates pending ?

slawblauciak · 2020-08-10T11:31:38Z

SOFCI TEST

lgirdwood · 2020-08-14T12:01:42Z

@slawblauciak CI seems to have stalled - I'll rerun it again.

lgirdwood · 2020-08-14T12:01:50Z

SOFCI TEST

ktrzcinx · 2020-08-17T09:32:27Z

SOFCI TEST

slawblauciak · 2020-08-18T07:16:19Z

@lgirdwood looks like we passed all the required checks, good to merge now?

lgirdwood · 2020-08-18T09:26:39Z

@slawblauciak I'm seeing SCHEDULER CI failure. Can you confirm with @zrombel we are good.

slawblauciak · 2020-08-18T09:27:30Z

@lgirdwood already have, it's not relevant

marc-hb · 2020-08-27T03:57:31Z

A number of comments at #3195 (comment) had no answer.

This broke the build, fixed in PR #3322

Now running "make" prints this obscure warning every time:

CMake Warning at sof/scripts/cmake/version.cmake:87 (message):
  Source content hash can't be calculated, use GIT_LOG_HASH

Looking at the source code points a possible reason which... doesn't seem to apply to me.

marc-hb · 2020-07-31T19:10:20Z

scripts/cmake/version.cmake

Easy to change later but you could move all the temp files to some new build_dir/source_hash/ subdirectory instead.

I don't think CMake builds should ever delete any temporary file because:

Temporary files are useful to understand and debug the build. I very often browse or grep -r the build directory for that purpose. Then I can git grep the filenames and find the corresponding CMakeLists.txt source very quickly.

With out-of-source builds there's no "pollution" concern anymore.

marc-hb · 2020-07-31T19:12:57Z

scripts/cmake/version.cmake

+	message(STATUS "Source content hash: ${SOF_SRC_HASH}")
+else()
+	set(SOF_SRC_HASH ${GIT_LOG_HASH})
+	message(WARNING "Source content hash can't be calculated, use GIT_LOG_HASH")


message(WARNING "Source content hash not computed without git, _using_ GIT_LOG_HASH" instead)

"Use" is imperative mood.

ktrzcinx · 2020-08-27T10:11:30Z

@marc-hb I applied your suggestions in #3356

marc-hb · 2021-03-03T19:56:48Z

I just filed #3890

While comparing various build outputs I realized "by chance" why using a source content hash for the logger ABI check (#3195) is flawed. It's quite obvious with hindsight: that's simply because the "source" that git knows about is not the source code that gets compiled. git misses at least: pre-processing, generated config.h, compiler flags and version and maybe others...

marc-hb · 2021-04-14T01:19:20Z

With (even more) hindsight, the most obvious failure of this design is CONFIG_TRACEV. See #3890

Fixes commit 6c14e76 ("trace: Log FW ABI and hash numbers"). In June 2020, PR thesofproject#3195 added a tr_info() "banner" immediately after to make sure tracing works. That commit included a likely misunderstood trace_flush() call immediately after the tr_info(). The very poorly named trace_flush() function sounds like earlier scheduling of something that would the same later anyway but that's absolutely not what it does. Instead it copies pending DMA traces to the shared mailbox. This was most likely why the FW ABI banner is randomly duplicated in the etrace from time to time, see for instance: https://sof-ci.01.org/linuxpr/PR2954/build5823/devicetest/?model=BYT_MB_NOCODEC&testcase=test-speaker https://sof-ci.01.org/softestpr/PR666/build721/devicetest/?model=TGLH_RVP_HDA&testcase=check-sof-logger Note this test failure is unrelated. For now this CI does not read etrace unless there's a failure. In August 2020, commit 67a0a69 ("trace: Trace initial message as error logs") upgraded this banner from tr_info() to tr_err(). That made sure it gets to both the mailbox and the DMA trace but it didn't remove the trace_flush(). Remove it now. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Pure rename, zero functional change. The very poorly named trace_flush() function sounds like earlier scheduling of something that would the same later anyway but that's absolutely not what it does. Instead it copies pending DMA traces to the shared mailbox. As an example, in June 2020, PR thesofproject#3195 commit 6c14e76 ("trace: Log FW ABI and hash numbers") added a tr_info() "banner" immediately after to make sure tracing works. That included a likely misunderstood trace_flush() call immediately after the tr_info(). Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Fixes commit 6c14e76 ("trace: Log FW ABI and hash numbers"). In June 2020, PR #3195 added a tr_info() "banner" immediately after to make sure tracing works. That commit included a likely misunderstood trace_flush() call immediately after the tr_info(). The very poorly named trace_flush() function sounds like earlier scheduling of something that would the same later anyway but that's absolutely not what it does. Instead it copies pending DMA traces to the shared mailbox. This was most likely why the FW ABI banner is randomly duplicated in the etrace from time to time, see for instance: https://sof-ci.01.org/linuxpr/PR2954/build5823/devicetest/?model=BYT_MB_NOCODEC&testcase=test-speaker https://sof-ci.01.org/softestpr/PR666/build721/devicetest/?model=TGLH_RVP_HDA&testcase=check-sof-logger Note this test failure is unrelated. For now this CI does not read etrace unless there's a failure. In August 2020, commit 67a0a69 ("trace: Trace initial message as error logs") upgraded this banner from tr_info() to tr_err(). That made sure it gets to both the mailbox and the DMA trace but it didn't remove the trace_flush(). Remove it now. Signed-off-by: Marc Herbert <marc.herbert@intel.com>

Pure rename, zero functional change. The very poorly named trace_flush() function sounds like earlier scheduling of something that would the same later anyway but that's absolutely not what it does. Instead it copies pending DMA traces to the shared mailbox. As an example, in June 2020, PR #3195 commit 6c14e76 ("trace: Log FW ABI and hash numbers") added a tr_info() "banner" immediately after to make sure tracing works. That included a likely misunderstood trace_flush() call immediately after the tr_info(). Signed-off-by: Marc Herbert <marc.herbert@intel.com>

marc-hb · 2021-12-16T02:27:37Z

src/trace/dma-trace.c


+	/* it should be the very first sent log for easily identification */
+	tr_info(&dt_tr, "FW ABI 0x%x DBG ABI 0x%x tag " SOF_GIT_TAG " src hash 0x%x (ldc hash " META_QUOTE(SOF_SRC_HASH) ")",
+		SOF_ABI_VERSION, SOF_ABI_DBG_VERSION, SOF_SRC_HASH);


@ktrzcinx do you remember why you put both META_QUOTE(SOF_SRC_HASH) and %x SOF_SRC_HASH here? Do they ever look different from each other?

They differ in case of using incompatible .ldc file, it's because META_QUOTE(SOF_SRC_HASH) comes from used .ldc file and SOF_SRC_HASH is .ri buildin variable.

Thanks @ktrzcinx !

Do they ever look different from each other?

Answering that part of my own question: they do but only when forcing sof-logger to use an incompatible .ldc file with the -n option. META_QUOTE(SOF_SRC_HASH) is in the format string which is in the .ldc file and not in the firmware binary

marc-hb · 2023-01-11T01:16:42Z

This git hash-object technique is also creating autocrlf issues:

src/arch/xtensa: normalize two odd files from CRLF to LF #6920

ktrzcinx added the ABI ABI change involved label Jul 15, 2020

ktrzcinx requested review from a team, RanderWang, akloniex, bkokoszx, dbaluta, jajanusz, lbetlej, lgirdwood, mmaka1, plbossart, tlauda and xiulipan as code owners July 15, 2020 09:52

ktrzcinx force-pushed the logger-abi-check branch from 6f1940f to c26188e Compare July 15, 2020 09:55

paulstelian97 approved these changes Jul 15, 2020

View reviewed changes

paulstelian97 reviewed Jul 15, 2020

View reviewed changes

lgirdwood reviewed Jul 16, 2020

View reviewed changes

ktrzcinx force-pushed the logger-abi-check branch 3 times, most recently from 3fc12c6 to 01a61d0 Compare July 17, 2020 10:39

ktrzcinx mentioned this pull request Jul 17, 2020

ASoC:SOF: Add src_hash to sof_ipc_fw_version structure thesofproject/linux#2292

Merged

lyakh reviewed Jul 20, 2020

View reviewed changes

lyakh requested changes Jul 20, 2020

View reviewed changes

tools/logger/convert.c Outdated Show resolved Hide resolved

ktrzcinx force-pushed the logger-abi-check branch 2 times, most recently from 43a7391 to 1e210cf Compare July 20, 2020 14:54

ktrzcinx force-pushed the logger-abi-check branch from 1e210cf to dcc2db0 Compare July 21, 2020 06:56

ktrzcinx requested a review from lyakh July 21, 2020 12:30

ktrzcinx mentioned this pull request Jul 28, 2020

[BUG] sof-logger -e option is broken: firmware/debug ABI confusion #3243

Closed

mmaka1 reviewed Jul 28, 2020

View reviewed changes

lgirdwood approved these changes Aug 18, 2020

View reviewed changes

lgirdwood merged commit 6c14e76 into thesofproject:master Aug 18, 2020

ktrzcinx mentioned this pull request Aug 19, 2020

logger: Enable LDC and FW compatibility check by default #3326

Merged

marc-hb reviewed Aug 27, 2020

View reviewed changes

ktrzcinx mentioned this pull request Aug 27, 2020

cmake: Improve source hash calculation #3356

Merged

marc-hb mentioned this pull request Nov 10, 2020

Failure to start logger does not fail immediately, only at the end of the test thesofproject/sof-test#506

Closed

marc-hb mentioned this pull request Jan 6, 2021

How do we use tags on master branch? #3730

Closed

marc-hb mentioned this pull request Mar 3, 2021

[BUG] logger "ABI" dictionary check ignores configuration and other changes #3890

Closed

marc-hb reviewed Dec 16, 2021

View reviewed changes

Logger abi check #3195

Logger abi check #3195

Uh oh!

Conversation

ktrzcinx commented Jul 15, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Extracted from discussion:

Uh oh!

paulstelian97 left a comment

Choose a reason for hiding this comment

Uh oh!

lgirdwood left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ktrzcinx Jul 16, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

lyakh left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

ktrzcinx commented Jul 20, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ktrzcinx Jul 28, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

marc-hb commented Jul 31, 2020

Uh oh!

lgirdwood commented Aug 4, 2020

Uh oh!

lgirdwood commented Aug 4, 2020

Uh oh!

slawblauciak commented Aug 10, 2020

Uh oh!

lgirdwood commented Aug 14, 2020

Uh oh!

lgirdwood commented Aug 14, 2020

Uh oh!

ktrzcinx commented Aug 17, 2020

Uh oh!

slawblauciak commented Aug 18, 2020

Uh oh!

lgirdwood commented Aug 18, 2020

Uh oh!

slawblauciak commented Aug 18, 2020

Uh oh!

marc-hb commented Aug 27, 2020

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ktrzcinx commented Aug 27, 2020

Uh oh!

marc-hb commented Mar 3, 2021

Uh oh!

marc-hb commented Apr 14, 2021 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

ktrzcinx commented Jul 15, 2020 •

edited

Loading

ktrzcinx Jul 16, 2020 •

edited

Loading

ktrzcinx Jul 28, 2020 •

edited

Loading

marc-hb commented Apr 14, 2021 •

edited

Loading

marc-hb Dec 17, 2021 •

edited

Loading