Sort IDs of log msgs by severity to allow runtime filtering

[t-moe]

I want to be able to filter log messages at runtime by their log level. For this, the id's must be ordered by level and we need some markers to query the id ranges of the individual levels.

This PR implements a hacked-together version of what I need. AFAIK it is not a breaking change and defmt-print etc will continue to work. Would something like this be mergable?

Our usecase:
We develop an embedded iot product where we use defmt to store the logs into the flash of the device. When we have a defective device, the customer sends it back, and we can extract the logs from the flash. Now, it would be nice, to also be able to request the logs from the device over the air, but for that we need to be able to reduce the number of logs to transmit by filtering them. We can already filter the messages by timestamp today, but not by severity. In order to filter the logs by severity we need the changes implemented by this PR. I'll probably open-source the tooling we've built around this entire use-case, as soon as it is mature enough.

Related: #793 -> Filtering by module

(Note: This PR is not related to embedded-test in any way)

[jonathanpallant]

I can see what you're trying to do, but it looks like this broke the Windows builds? Also, are we sure that the IDs always fit in a u16? (Maybe this is assumed somewhere else already).

[t-moe]

... it looks like this broke the Windows builds?

Oops. Fixed, by ignoring the new code in the tests.

Also, are we sure that the IDs always fit in a u16? (Maybe this is assumed somewhere else already).

Yes, I think this is currently assumed in a lot of places. (e.g. https://github.com/knurling-rs/defmt/blob/main/defmt/defmt.x.in#L33 )

[jonathanpallant]

This looks OK to me:

00000001 g     O .defmt	00000001 {"package":"defmt","tag":"defmt_prim","data":"{=__internal_Display}","disambiguator":"5759480083669011735","crate_name":"defmt"}
00000002 g       .defmt	00000000 __DEFMT_MARKER_TRACE_START
00000002 g       .defmt	00000000 __DEFMT_MARKER_TRACE_END
00000002 g       .defmt	00000000 __DEFMT_MARKER_DEBUG_START
00000002 g     O .defmt	00000001 {"package":"project","tag":"defmt_debug","data":"debug message was here","disambiguator":"7100800799909264921","crate_name":"levels"}
00000003 g     O .defmt	00000001 {"package":"test-lib","tag":"defmt_debug","data":"debug from the lib","disambiguator":"2981217442466685779","crate_name":"test_lib"}
00000004 g       .defmt	00000000 __DEFMT_MARKER_DEBUG_END
00000004 g       .defmt	00000000 __DEFMT_MARKER_INFO_START
00000004 g     O .defmt	00000001 {"package":"project","tag":"defmt_info","data":"info message was here","disambiguator":"16176734987436242066","crate_name":"levels"}
00000004 g     O .vector_table	00000004 __RESET_VECTOR
00000005 g     O .defmt	00000001 {"package":"test-lib","tag":"defmt_info","data":"info from the lib","disambiguator":"12424770924108077945","crate_name":"test_lib"}
00000006 g       .defmt	00000000 __DEFMT_MARKER_INFO_END
00000006 g       .defmt	00000000 __DEFMT_MARKER_WARN_START
00000006 g     O .defmt	00000001 {"package":"project","tag":"defmt_warn","data":"warn message was here","disambiguator":"16355542634233735977","crate_name":"levels"}
00000007 g     O .defmt	00000001 {"package":"test-lib","tag":"defmt_warn","data":"warn from the lib","disambiguator":"18371419059053659539","crate_name":"test_lib"}
00000008 g       .defmt	00000000 __DEFMT_MARKER_WARN_END
00000008 g       .defmt	00000000 __DEFMT_MARKER_ERROR_START
00000008 g       .vector_table	00000000 __reset_vector
00000008 g     O .defmt	00000001 {"package":"project","tag":"defmt_error","data":"error message was here","disambiguator":"10809738337017493910","crate_name":"levels"}
00000008 g     O .vector_table	00000038 __EXCEPTIONS
00000009 g     O .defmt	00000001 {"package":"test-lib","tag":"defmt_error","data":"error from the lib","disambiguator":"10207188330997857878","crate_name":"test_lib"}
0000000a g     O .defmt	00000001 {"package":"panic-probe","tag":"defmt_error","data":"{}","disambiguator":"3281125884690968605","crate_name":"panic_probe"}
0000000b g       .defmt	00000000 __DEFMT_MARKER_ERROR_END
0000000b g     O .defmt	00000001 {"package":"project","tag":"defmt_timestamp","data":"{=usize}.{=usize:08}","disambiguator":"8731791122849759601","crate_name":"levels"}
0000000c g     O .defmt	00000004 __DEFMT_MARKER_TIMESTAMP_WAS_DEFINED
00000010 g     O .defmt	00000001 {"package":"project","tag":"defmt_println","data":"println message was here","disambiguator":"8803947213229515245","crate_name":"levels"}
00000011 g     O .defmt	00000001 {"package":"test-lib","tag":"defmt_println","data":"println from the lib","disambiguator":"13245979344436344527","crate_name":"test_lib"}
00000012 g     O .defmt	00000001 _defmt_version_ = 4
00000013 g     O .defmt	00000001 _defmt_encoding_ = rzcobs
00000014 g       .defmt	00000000 __DEFMT_MARKER_END

[jonathanpallant]

Please could you add an entry to the CHANGELOG that references this PR?

[t-moe]

Please could you add an entry to the CHANGELOG that references this PR?

Sure, done.

I was not expecting this to get approved this fast... Are we sure the changes in the linker file do not break any of the existing tooling? I haven't checked the source code of them, I only checked that defmt-print still works so far...

[jonathanpallant]

It only involves adding some additional symbols (which I don't expect to clash with anything because they start __DEFMT, which means they are private). The files end up in the same output section and so when looking at the ELF file, very little should change.

So I'm relatively relaxed about this change.

[t-moe]

How could one use this PR to implement runtime filtering? This PR laid the ground work for it, but it is not covered by semver yet.

you would have to set DEFMT_LOG=trace during build of your firmware (Note: flash overhead!!), and then implement your own defmt global_logger which filters the messages based on their message id. You can use the info introduced in this PR to get the id ranges for each severity level.

Note: you'll have to undo the rzcobs encoding first in order to get the msg-id. You can probably analyze the payload before it reaches the encoder though.

[Urhengulas]

but it is not covered by semver yet.

Do you mean it is not released yet, or something else?

Note: you'll have to undo the rzcobs encoding first in order to get the msg-id. You can probably analyze the payload before it reaches the encoder though.

You can disable rzcobs encoding like this:

[dependencies]
defmt = { version = "0.3", features = "encoding-raw" }

Read more here

defmt/defmt/Cargo.toml

Lines 25 to 40 in 29f1472

	# Encoding feature flags. These should only be set by end-user crates, not by library crates.
	#
	# If no encoding is selected, `defmt` will assume the encoding is "don't care" and
	# will pick a default one. The current default is `encoding-rzcobs`. The default may change
	# in minor releases, changing it is not considered a breaking change since all encodings
	# are guaranteed to be supported by the corresponding `defmt-decoder` version.
	# Raw encoding: All log frames are concatenated and sent over the wire with no framing or compression.
	# This is the fastest CPU-wise, but may end up being slower if the limiting factor is wire speed.
	encoding-raw = []
	# rzCOBS encoding: Performs framing on the log frames using reverse-COBS, additionally applying a
	# light compression for data known to contain many zero bytes, like defmt streams.
	# The framing allows the decoder to recover from missing or corrupted data, and start decoding
	# in the middle of a stream, for example when attaching to an already-running device.
	encoding-rzcobs = []

[t-moe]

Thanks for replying here @Urhengulas .

I'm the author of this PR and I was trying to answer what people were asking regarding this PR in the matrix chat yesterday, so that I can link to my comment here. So, no question here from my side. Sorry, for not being clear about that.

By "not covered by semver" I mean that since we published IdRanges as #[doc(hidden)] we'll probably also take the liberty of doinig semver-breaking changes to it.