knurling-rs / defmt

Efficient, deferred formatting for logging on embedded systems
https://defmt.ferrous-systems.com/
Apache License 2.0
750 stars 69 forks source link

Sort IDs of log msgs by severity to allow runtime filtering #843

Closed t-moe closed 3 weeks ago

t-moe commented 1 month ago

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: https://github.com/knurling-rs/defmt/issues/793 -> Filtering by module

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

jonathanpallant commented 1 month ago

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 commented 1 month ago

... 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 commented 3 weeks ago

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 commented 3 weeks ago

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

t-moe commented 3 weeks ago

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 commented 3 weeks ago

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.