Adds LOG_*_ONCE macros #41783

RafaelLaya · 2022-01-13T07:12:31Z

Sometimes it can be useful to execute a log statement only a fixed number of times. For instance, because logging it would produce a lot of spam and it's a fact that will stay constant during the whole runtime. This change adds macros to silence a single log statement after a given number of executions.

Signed-off-by: Rafael Laya rafaellaya@fb.com

nordic-krch

Please add test to tests/subsys/logging/log_api. If macro for limited number of executions is added to sys/util add also test there.

nordic-krch · 2022-01-13T07:53:07Z

include/logging/log.h

+ * @param ... A string optionally containing printk valid conversion specifier,
+ * followed by as many values as specifiers.
+ */
+#define LOG_ERR_ONCE(...)    Z_LOG_ONCE(LOG_LEVEL_ERR, __VA_ARGS__)


I guess that it can be helpful in certain debugging scenarios. What about making it more generic and converting to LOG_ERR_N(n, ...)? LOG_ERR_N(1, ...) would be LOG_ERR_ONCE equivalent.

I would do something like:

#define DO_N(n, code) \ static int _do_n_cnt_##__LINE__; \ if (_do_n_cnt_##__LINE__ < n) { \ _do_n_cnt_##__LINE__++; \ code; \ }

In fact macro like that is not logging specific. Belongs better to sys/util_macro.h

Great suggestion!

Hi again @nordic-krch, I've made some local changes and about to make tests. However, I might be missing how to run the tests properly. For instance:

I go to zephyr/tests/subsys/logging/log_api/src/test.inc

As an attempt to break test_log_various_messages(), I replace the LOG_DBG() in line 125 by some garbage like LOG_DBG("garbage");

Save

Then from zephyr root I run ./scripts/twister -T tests/subsys/logging/log_api

I see the tests passing even though I tried to break one

Did I miss something about running the tests?

$ ./scripts/twister -T tests/subsys/logging/log_api ZEPHYR_BASE unset, using "/home/rafael/zephyrproject/zephyr" Renaming output directory to /home/rafael/zephyrproject/zephyr/twister-out.49 INFO - Zephyr version: v2.7.99-3242-gecb9b1d3b757 INFO - JOBS: 8 INFO - Using 'zephyr' toolchain. INFO - Selecting default platforms per test case INFO - Building initial testcase list... INFO - 18 test scenarios (666 configurations) selected, 280 configurations discarded due to filters. INFO - Adding tasks to the queue... INFO - Added initial list of jobs to queue INFO - Total complete: 386/ 386 100% skipped: 388, failed: 0 INFO - 278 of 278 test configurations passed (100.00%), 0 failed, 388 skipped with 0 warnings in 2366.77 seconds INFO - In total 278 test cases were executed, 388 skipped on 22 out of total 418 platforms (5.26%) INFO - 278 test configurations executed on platforms, 0 test configurations were only built. INFO - Saving reports... INFO - Writing xunit report /home/rafael/zephyrproject/zephyr/twister-out/twister.xml... INFO - Writing xunit report /home/rafael/zephyrproject/zephyr/twister-out/twister_report.xml... INFO - Run completed

you're right. It got broken when new ztest got introduced. You can try with fix: #41872.

Thanks! that fix helped

nordic-krch · 2022-01-13T07:55:15Z

include/logging/log_core.h

@@ -357,9 +357,21 @@ static inline char z_log_minimal_level_to_char(int level)
 	} \
 } while (false)

+#define Z_LOG_DO_ACTION_ONCE(code)	\
+({ \
+	static _bool done_once = false; \


why _bool?

Sorry that must be a typo

Might consider changing the name to something like log_done_once so it will be less confusing when someone is going through the symbol table.

Thanks! Indeed it was a confusing name. I moved to sys_utils (since it's not log-specific) and renamed as DO_FIRST_N so that it's more clear that it just silences a piece of code after a given n. Does that sound better?

RafaelLaya · 2022-01-19T04:35:28Z

Re-named Z_LOG_DO_ACTION_ONCE to DO_FIRST_N (DO_FIRST_N(1, ...)) is equivalent to Z_LOG_DO_ACTION_ONCE) and moved to sys/util_macro.h
Added DO_FIRST_N tests to tests/unit/util/test.inc
Re-named LOG_*_ONCE to LOG_*_N and added parameter n
Added tests to tests/subsys/logging/log_api/src/test.inc

RafaelLaya · 2022-01-19T06:13:53Z

Fixed tests with CONFIG_LOG_FUNC_NAME_PREFIX_DBG=y and CONFIG_SAMPLE_MODULE_LOG_LEVEL_DBG=y

RafaelLaya · 2022-01-19T06:38:32Z

Split original into two commits

nordic-krch

Codewise looks good. Please remove [] from commit messages. Also split commits into testing part and feature part.

nordic-krch · 2022-01-19T06:49:49Z

include/logging/log.h

@@ -39,6 +39,17 @@ extern "C" {
 */
 #define LOG_ERR(...)    Z_LOG(LOG_LEVEL_ERR, __VA_ARGS__)

+/**
+ * @brief Writes an ERROR level message to the log, but only the first @p n times


English is not my primary language but in zephyr we usual don't use third person verb.
Write an ERROR ...

I copied that portion of the docstring from the other macros and it was already in third person. However this reminds me to add the "@param n" documentation to the docstring. I'll do that + the split tomorrow

yeah, you're right. This header was one of my first contributions to zephyr and i did that mistake.

RafaelLaya · 2022-01-20T06:08:06Z

Split into: 5 commits

add macro for silencing code after N executions
add tests to macro that silences code after N executions
Fix verbs in log.h for consistency with the rest of the code-base
Implement macros for logs with limited execution
Add tests for logging macros that have limited execution

nordic-krch · 2022-01-20T07:36:36Z

Commits with test changes should start with tests: .

RafaelLaya · 2022-01-21T03:44:27Z

Re-named commits that add tests so that they start with tests:
Fixed missing parameters in doxygen documentation
Fixed white-space in DO_FIRST_N()
Added Signed-off-by in the body of the commits

Hopefully that fixes the CI failures!

RafaelLaya · 2022-01-21T06:13:12Z

Fixed the doxygen which was the single last CI test that was failing. Ran the Document Generation engine locally and it ran successfully so should be fine now.

RafaelLaya · 2022-01-22T03:01:59Z

Fixed the author of the commit so it matches the signed-off-by line

nordic-krch

Looks good, please fix the sign-off email address.

RafaelLaya · 2022-01-25T02:52:06Z

Should be fixed now! I learned about gitlint so I checked locally that there are no errors

nordic-krch · 2022-01-25T06:25:53Z

Still not fixed. You are pushing fromRafael Laya <rafaellaya@fb.com> and sign off with Rafael Laya Alfonzo <rafaellaya@fb.com>

RafaelLaya · 2022-01-26T02:53:18Z

I see, in that case I've removed the Alfonzo part from the signed-off-by line. Hopefully it works this time!

nordic-krch · 2022-01-26T06:36:56Z

CI is green but it won't be merged until v3.0.0 comes out as there is a feature freeze phase now.

RafaelLaya · 2022-01-26T17:09:05Z

Great! thanks for the patience during my first contribution to Zephyr :)

nordic-krch · 2022-01-27T06:38:39Z

Great! thanks for the patience during my first contribution to Zephyr :)

No problem, I hope there will be more :)

RafaelLaya · 2022-01-28T01:51:04Z

Resolved merge conflict

Sometimes you might want to execute a piece of code and then silence it. This macro allows you to do so. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

This add tests to the macro DO_FIRST_N() which is used to silence a piece of code after it has executed N times. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

…base Zephyr does not use 3rd person verb in docstrings. This fixes the verbs for log.h. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

Adds macros to silence a log after N executions, using the macro DO_FIRST_N() Signed-off-by: Rafael Laya <rafaellaya@fb.com>

This adds tests to the logging macros that silence after N executions. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

nordic-krch · 2022-02-24T06:49:50Z

@RafaelLaya please resolve conflict. We could merge it soon.

carlescufi · 2022-03-21T14:14:08Z

@RafaelLaya please rebase

github-actions · 2022-05-21T00:30:14Z

This pull request has been marked as stale because it has been open (more than) 60 days with no activity. Remove the stale label or add a comment saying that you would like to have the label removed otherwise this pull request will automatically be closed in 14 days. Note, that you can always re-open a closed pull request at any time.

bbilas · 2022-11-18T15:25:11Z

@RafaelLaya would you mind re-opening that MR and preparing it to be merged? That's a super helpful feature that I want to see in the upstream.

RafaelLaya requested a review from nordic-krch as a code owner January 13, 2022 07:12

github-actions bot added the area: API Changes to public APIs label Jan 13, 2022

nordic-krch requested changes Jan 13, 2022

View reviewed changes

zephyrbot added the area: Logging label Jan 13, 2022

zephyrbot requested a review from chen-png January 13, 2022 18:45

zephyrbot assigned nordic-krch Jan 13, 2022

nashif requested a review from dcpleung January 13, 2022 18:53

RafaelLaya force-pushed the add_log_once_macros branch from 666c07f to ddf33cb Compare January 19, 2022 04:30

RafaelLaya requested review from carlescufi, galak, MaureenHelm and nashif as code owners January 19, 2022 04:30

github-actions bot added the area: Tests Issues related to a particular existing or missing test label Jan 19, 2022

RafaelLaya requested a review from nordic-krch January 19, 2022 04:38

RafaelLaya force-pushed the add_log_once_macros branch from ddf33cb to 219d29a Compare January 19, 2022 06:11

RafaelLaya force-pushed the add_log_once_macros branch from 219d29a to 2707867 Compare January 19, 2022 06:37

nordic-krch reviewed Jan 19, 2022

View reviewed changes

RafaelLaya force-pushed the add_log_once_macros branch 3 times, most recently from 6b26563 to f9d6a73 Compare January 20, 2022 06:06

RafaelLaya force-pushed the add_log_once_macros branch from f9d6a73 to 623c5b5 Compare January 21, 2022 03:42

RafaelLaya force-pushed the add_log_once_macros branch 2 times, most recently from 3dab952 to a1c436e Compare January 21, 2022 05:51

RafaelLaya force-pushed the add_log_once_macros branch from a1c436e to 504d5a5 Compare January 22, 2022 03:01

RafaelLaya requested a review from nordic-krch January 23, 2022 01:13

nordic-krch previously approved these changes Jan 24, 2022

View reviewed changes

RafaelLaya force-pushed the add_log_once_macros branch from 504d5a5 to ca85023 Compare January 25, 2022 02:50

RafaelLaya force-pushed the add_log_once_macros branch from ca85023 to cfa9387 Compare January 26, 2022 02:52

dcpleung previously approved these changes Jan 26, 2022

View reviewed changes

RafaelLaya added 5 commits January 27, 2022 17:56

utils: add macro for silencing code after N executions

9bd6ed5

Sometimes you might want to execute a piece of code and then silence it. This macro allows you to do so. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

tests: add tests to util for macro that silences code after N executions

85a96d6

This add tests to the macro DO_FIRST_N() which is used to silence a piece of code after it has executed N times. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

logging: Fix verbs in log.h for consistency with the rest of the code…

eddf8ce

…base Zephyr does not use 3rd person verb in docstrings. This fixes the verbs for log.h. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

logging: Implement macros for logs with limited execution

d20af1b

Adds macros to silence a log after N executions, using the macro DO_FIRST_N() Signed-off-by: Rafael Laya <rafaellaya@fb.com>

tests: Add tests for logging macros that have limited execution

9600e42

This adds tests to the logging macros that silence after N executions. Signed-off-by: Rafael Laya <rafaellaya@fb.com>

RafaelLaya force-pushed the add_log_once_macros branch from f507d36 to 9600e42 Compare January 28, 2022 01:58

dleach02 dismissed stale reviews from dcpleung and nordic-krch via 9600e42 February 11, 2022 16:03

github-actions bot added the Stale label May 21, 2022

github-actions bot closed this Jun 4, 2022

nordic-krch mentioned this pull request Mar 18, 2024

logging: log: add LOG_WRN_ONCE #70282

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Adds LOG_*_ONCE macros #41783

Adds LOG_*_ONCE macros #41783

RafaelLaya commented Jan 13, 2022 •

edited

nordic-krch left a comment

nordic-krch Jan 13, 2022

RafaelLaya Jan 13, 2022

RafaelLaya Jan 15, 2022 •

edited

nordic-krch Jan 17, 2022

RafaelLaya Jan 17, 2022

nordic-krch Jan 13, 2022

RafaelLaya Jan 13, 2022

dcpleung Jan 18, 2022

RafaelLaya Jan 19, 2022

RafaelLaya commented Jan 19, 2022 •

edited

RafaelLaya commented Jan 19, 2022

RafaelLaya commented Jan 19, 2022

nordic-krch left a comment

nordic-krch Jan 19, 2022

RafaelLaya Jan 19, 2022 •

edited

nordic-krch Jan 19, 2022

RafaelLaya commented Jan 20, 2022 •

edited

nordic-krch commented Jan 20, 2022

RafaelLaya commented Jan 21, 2022

RafaelLaya commented Jan 21, 2022

RafaelLaya commented Jan 22, 2022

nordic-krch left a comment

RafaelLaya commented Jan 25, 2022

nordic-krch commented Jan 25, 2022

RafaelLaya commented Jan 26, 2022 •

edited

nordic-krch commented Jan 26, 2022

RafaelLaya commented Jan 26, 2022

nordic-krch commented Jan 27, 2022

RafaelLaya commented Jan 28, 2022

nordic-krch commented Feb 24, 2022

carlescufi commented Mar 21, 2022

github-actions bot commented May 21, 2022

bbilas commented Nov 18, 2022

Adds LOG_*_ONCE macros #41783

Adds LOG_*_ONCE macros #41783

Conversation

RafaelLaya commented Jan 13, 2022 • edited

nordic-krch left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RafaelLaya Jan 15, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RafaelLaya commented Jan 19, 2022 • edited

RafaelLaya commented Jan 19, 2022

RafaelLaya commented Jan 19, 2022

nordic-krch left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RafaelLaya Jan 19, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

RafaelLaya commented Jan 20, 2022 • edited

nordic-krch commented Jan 20, 2022

RafaelLaya commented Jan 21, 2022

RafaelLaya commented Jan 21, 2022

RafaelLaya commented Jan 22, 2022

nordic-krch left a comment

Choose a reason for hiding this comment

RafaelLaya commented Jan 25, 2022

nordic-krch commented Jan 25, 2022

RafaelLaya commented Jan 26, 2022 • edited

nordic-krch commented Jan 26, 2022

RafaelLaya commented Jan 26, 2022

nordic-krch commented Jan 27, 2022

RafaelLaya commented Jan 28, 2022

nordic-krch commented Feb 24, 2022

carlescufi commented Mar 21, 2022

github-actions bot commented May 21, 2022

bbilas commented Nov 18, 2022

RafaelLaya commented Jan 13, 2022 •

edited

RafaelLaya Jan 15, 2022 •

edited

RafaelLaya commented Jan 19, 2022 •

edited

RafaelLaya Jan 19, 2022 •

edited

RafaelLaya commented Jan 20, 2022 •

edited

RafaelLaya commented Jan 26, 2022 •

edited