Add a log message when changing log levels to be sure of which logtype is enabled. Suggested-by: Ilya Maximets <i.maximets@ovn.org> Signed-off-by: David Marchand <david.marchand@redhat.com> --- Sending this as a RFC, this makes it easier to notice the problem we have lived with so far: shared library loading do not honor log levels set on cmdline unless it uses rte_log_register_type_and_pick_level. --- lib/librte_eal/common/eal_common_log.c | 56 ++++++++++++++++---------- 1 file changed, 35 insertions(+), 21 deletions(-) diff --git a/lib/librte_eal/common/eal_common_log.c b/lib/librte_eal/common/eal_common_log.c index 8835c8fff8..24d53ed9c7 100644 --- a/lib/librte_eal/common/eal_common_log.c +++ b/lib/librte_eal/common/eal_common_log.c @@ -130,6 +130,37 @@ rte_log_can_log(uint32_t logtype, uint32_t level) return true; } +static const char * +loglevel_to_string(uint32_t level) +{ + switch (level) { + case 0: return "disabled"; + case RTE_LOG_EMERG: return "emerg"; + case RTE_LOG_ALERT: return "alert"; + case RTE_LOG_CRIT: return "critical"; + case RTE_LOG_ERR: return "error"; + case RTE_LOG_WARNING: return "warning"; + case RTE_LOG_NOTICE: return "notice"; + case RTE_LOG_INFO: return "info"; + case RTE_LOG_DEBUG: return "debug"; + default: return "unknown"; + } +} + +static void +logtype_set_level(uint32_t type, uint32_t level) +{ + uint32_t current = rte_logs.dynamic_types[type].loglevel; + + if (current != level) { + rte_logs.dynamic_types[type].loglevel = level; + RTE_LOG(DEBUG, EAL, "%s logtype level changed from %s to %s\n", + rte_logs.dynamic_types[type].name, + loglevel_to_string(current), + loglevel_to_string(level)); + } +} + int rte_log_set_level(uint32_t type, uint32_t level) { @@ -138,7 +169,7 @@ rte_log_set_level(uint32_t type, uint32_t level) if (level > RTE_LOG_DEBUG) return -1; - rte_logs.dynamic_types[type].loglevel = level; + logtype_set_level(type, level); return 0; } @@ -161,7 +192,7 @@ rte_log_set_level_regexp(const char *regex, uint32_t level) continue; if (regexec(&r, rte_logs.dynamic_types[i].name, 0, NULL, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } regfree(&r); @@ -221,7 +252,7 @@ rte_log_set_level_pattern(const char *pattern, uint32_t level) continue; if (fnmatch(pattern, rte_logs.dynamic_types[i].name, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } return 0; @@ -328,7 +359,7 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) } } - rte_logs.dynamic_types[type].loglevel = level; + logtype_set_level(type, level); return type; } @@ -390,23 +421,6 @@ RTE_INIT_PRIO(rte_log_init, LOG) rte_logs.dynamic_types_len = RTE_LOGTYPE_FIRST_EXT_ID; } -static const char * -loglevel_to_string(uint32_t level) -{ - switch (level) { - case 0: return "disabled"; - case RTE_LOG_EMERG: return "emerg"; - case RTE_LOG_ALERT: return "alert"; - case RTE_LOG_CRIT: return "critical"; - case RTE_LOG_ERR: return "error"; - case RTE_LOG_WARNING: return "warning"; - case RTE_LOG_NOTICE: return "notice"; - case RTE_LOG_INFO: return "info"; - case RTE_LOG_DEBUG: return "debug"; - default: return "unknown"; - } -} - /* dump global level and registered log types */ void rte_log_dump(FILE *f) -- 2.23.0
On 6/26/20 2:47 PM, David Marchand wrote:
> Add a log message when changing log levels to be sure of which logtype
> is enabled.
>
> Suggested-by: Ilya Maximets <i.maximets@ovn.org>
> Signed-off-by: David Marchand <david.marchand@redhat.com>
Acked-by: Andrew Rybchenko <arybchenko@solarflare.com>
W dniu 26.06.2020 o 16:46, Andrew Rybchenko pisze:
> On 6/26/20 2:47 PM, David Marchand wrote:
>> Add a log message when changing log levels to be sure of which logtype
>> is enabled.
>>
>> Suggested-by: Ilya Maximets <i.maximets@ovn.org>
>> Signed-off-by: David Marchand <david.marchand@redhat.com>
> Acked-by: Andrew Rybchenko <arybchenko@solarflare.com>
>
I also like the idea so:
Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com>
although I think there is one place that can be smoothed a bit. Every
newly registered type's loglevel is set to RTE_LOG_INFO in
__rte_log_register(), so:
* if new type is registered with rte_log_register_type_and_pick_level()
and level is set to INFO, nothing will be printed (as current is equal
to new level);
* any registration made with rte_log_register() won't be seen either as
there is no call to newly introduced function logtype_set_level().
How about additionally changing behavior so any registration will print
change from "disabled" (level=0) to new level:
* in case of rte_log_register_type_and_pick_level() to chosen level
* in case of rte_log_register() to default level which is "info"
Best regards
--
Lukasz Wojciechowski
Principal Software Engineer
Samsung R&D Institute Poland
Samsung Electronics
Office +48 22 377 88 25
l.wojciechow@partner.samsung.com
Hello Lukasz,
On Thu, Jul 9, 2020 at 2:16 AM Lukasz Wojciechowski
<l.wojciechow@partner.samsung.com> wrote:
>
>
> W dniu 26.06.2020 o 16:46, Andrew Rybchenko pisze:
> > On 6/26/20 2:47 PM, David Marchand wrote:
> >> Add a log message when changing log levels to be sure of which logtype
> >> is enabled.
> >>
>
> although I think there is one place that can be smoothed a bit. Every
> newly registered type's loglevel is set to RTE_LOG_INFO in
> __rte_log_register(), so:
> * if new type is registered with rte_log_register_type_and_pick_level()
> and level is set to INFO, nothing will be printed (as current is equal
> to new level);
> * any registration made with rte_log_register() won't be seen either as
> there is no call to newly introduced function logtype_set_level().
>
> How about additionally changing behavior so any registration will print
> change from "disabled" (level=0) to new level:
> * in case of rte_log_register_type_and_pick_level() to chosen level
> * in case of rte_log_register() to default level which is "info"
Sorry, I had forgotten about this rfc... reviving it as I am reviewing
some log patch.
Good idea, I will post a v1 with this.
--
David Marchand
Here is a little series, following RFC [1]. No change in behavior expected, but reviews welcome ! :-) 1: https://patchwork.dpdk.org/project/dpdk/list/?series=10632 Changes since RFC: - added unit test, - logged level changes in rte_log_register, - fixed double evaluation of --log-level options, -- David Marchand David Marchand (3): test/log: check levels log: track log level changes eal: fix evaluation of log level option app/test/test_logs.c | 53 +++++++++++- lib/librte_eal/common/eal_common_log.c | 113 +++++++++++++------------ lib/librte_eal/freebsd/eal.c | 4 + lib/librte_eal/linux/eal.c | 4 + lib/librte_eal/windows/eal.c | 4 + 5 files changed, 120 insertions(+), 58 deletions(-) -- 2.23.0
Add checks on log levels: - default values for rte_log_register and RTE_LOG_REGISTER, - level changes with rte_log_set_level and consorts Signed-off-by: David Marchand <david.marchand@redhat.com> --- app/test/test_logs.c | 53 +++++++++++++++++++++++++++++++++++++++++--- 1 file changed, 50 insertions(+), 3 deletions(-) diff --git a/app/test/test_logs.c b/app/test/test_logs.c index 425ae03cb9..db754465c0 100644 --- a/app/test/test_logs.c +++ b/app/test/test_logs.c @@ -20,6 +20,10 @@ #define RTE_LOGTYPE_TESTAPP1 RTE_LOGTYPE_USER1 #define RTE_LOGTYPE_TESTAPP2 RTE_LOGTYPE_USER2 +static int logtype1; +static int logtype2; +RTE_LOG_REGISTER(logtype3, logtype3, ERR) + /* * Logs * ==== @@ -61,9 +65,24 @@ test_legacy_logs(void) static int test_logs(void) { - int logtype1, logtype2; int ret; +#define CHECK_LEVELS(exp_logtype1, exp_logtype2, exp_logtype3) do \ +{ \ + ret = rte_log_get_level(logtype1); \ + TEST_ASSERT_EQUAL(ret, exp_logtype1, \ + "%s:%d, invalid level for logtype1 %d, expecting %d\n", \ + __FILE__, __LINE__, ret, exp_logtype1); \ + ret = rte_log_get_level(logtype2); \ + TEST_ASSERT_EQUAL(ret, exp_logtype2, \ + "%s:%d, invalid level for logtype2 %d, expecting %d\n", \ + __FILE__, __LINE__, ret, exp_logtype2); \ + ret = rte_log_get_level(logtype3); \ + TEST_ASSERT_EQUAL(ret, exp_logtype3, \ + "%s:%d, invalid level for logtype3 %d, expecting %d\n", \ + __FILE__, __LINE__, ret, exp_logtype3); \ +} while (0) + printf("== dynamic log types\n"); logtype1 = rte_log_register("logtype1"); @@ -71,15 +90,41 @@ test_logs(void) printf("Cannot register logtype1\n"); return -1; } + ret = rte_log_get_level(logtype1); + TEST_ASSERT_EQUAL(ret, RTE_LOG_INFO, + "invalid default level for logtype1 %d, expecting %d\n", + ret, RTE_LOG_INFO); + logtype2 = rte_log_register("logtype2"); if (logtype2 < 0) { printf("Cannot register logtype2\n"); return -1; } + ret = rte_log_get_level(logtype2); + TEST_ASSERT_EQUAL(ret, RTE_LOG_INFO, + "invalid default level for logtype2 %d, expecting %d\n", + ret, RTE_LOG_INFO); + + ret = rte_log_get_level(logtype3); + TEST_ASSERT_EQUAL(ret, RTE_LOG_ERR, + "invalid default level for logtype3 %d, expecting %d\n", + ret, RTE_LOG_ERR); + + rte_log_set_level(logtype1, RTE_LOG_ERR); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_INFO, RTE_LOG_ERR); + + rte_log_set_level_regexp("type$", RTE_LOG_EMERG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_INFO, RTE_LOG_ERR); + + rte_log_set_level_regexp("type[23]", RTE_LOG_EMERG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_EMERG, RTE_LOG_EMERG); + + rte_log_set_level_pattern("logtype", RTE_LOG_DEBUG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_EMERG, RTE_LOG_EMERG); /* set logtype level low to so we can test global level */ - rte_log_set_level(logtype1, RTE_LOG_DEBUG); - rte_log_set_level(logtype2, RTE_LOG_DEBUG); + rte_log_set_level_pattern("logtype*", RTE_LOG_DEBUG); + CHECK_LEVELS(RTE_LOG_DEBUG, RTE_LOG_DEBUG, RTE_LOG_DEBUG); /* log in error level */ rte_log_set_global_level(RTE_LOG_ERR); @@ -103,6 +148,8 @@ test_logs(void) if (ret < 0) return ret; +#undef CHECK_LEVELS + return 0; } -- 2.23.0
Add a log message when changing log levels. Example: $ DPDK_TEST=logs_autotest ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug ... RTE>>logs_autotest == dynamic log types EAL: logtype1 logtype level changed from disabled to info EAL: logtype2 logtype level changed from disabled to info EAL: logtype1 logtype level changed from info to error EAL: logtype3 logtype level changed from error to emerg EAL: logtype2 logtype level changed from info to emerg EAL: logtype3 logtype level changed from emerg to debug EAL: logtype1 logtype level changed from error to debug EAL: logtype2 logtype level changed from emerg to debug error message critical message critical message error message == static log types TESTAPP1: error message TESTAPP1: critical message TESTAPP2: critical message TESTAPP1: error message Test OK Suggested-by: Ilya Maximets <i.maximets@ovn.org> Signed-off-by: David Marchand <david.marchand@redhat.com> Acked-by: Andrew Rybchenko <arybchenko@solarflare.com> Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> --- lib/librte_eal/common/eal_common_log.c | 113 +++++++++++++------------ 1 file changed, 58 insertions(+), 55 deletions(-) diff --git a/lib/librte_eal/common/eal_common_log.c b/lib/librte_eal/common/eal_common_log.c index c5554badb2..b64a1b9381 100644 --- a/lib/librte_eal/common/eal_common_log.c +++ b/lib/librte_eal/common/eal_common_log.c @@ -135,6 +135,38 @@ rte_log_can_log(uint32_t logtype, uint32_t level) return true; } +static const char * +loglevel_to_string(uint32_t level) +{ + switch (level) { + case 0: return "disabled"; + case RTE_LOG_EMERG: return "emerg"; + case RTE_LOG_ALERT: return "alert"; + case RTE_LOG_CRIT: return "critical"; + case RTE_LOG_ERR: return "error"; + case RTE_LOG_WARNING: return "warning"; + case RTE_LOG_NOTICE: return "notice"; + case RTE_LOG_INFO: return "info"; + case RTE_LOG_DEBUG: return "debug"; + default: return "unknown"; + } +} + +static void +logtype_set_level(uint32_t type, uint32_t level) +{ + uint32_t current = rte_logs.dynamic_types[type].loglevel; + + if (current != level) { + rte_logs.dynamic_types[type].loglevel = level; + RTE_LOG(DEBUG, EAL, "%s logtype level changed from %s to %s\n", + rte_logs.dynamic_types[type].name == NULL ? + "" : rte_logs.dynamic_types[type].name, + loglevel_to_string(current), + loglevel_to_string(level)); + } +} + int rte_log_set_level(uint32_t type, uint32_t level) { @@ -143,7 +175,7 @@ rte_log_set_level(uint32_t type, uint32_t level) if (level > RTE_LOG_DEBUG) return -1; - rte_logs.dynamic_types[type].loglevel = level; + logtype_set_level(type, level); return 0; } @@ -166,7 +198,7 @@ rte_log_set_level_regexp(const char *regex, uint32_t level) continue; if (regexec(&r, rte_logs.dynamic_types[i].name, 0, NULL, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } regfree(&r); @@ -226,7 +258,7 @@ rte_log_set_level_pattern(const char *pattern, uint32_t level) continue; if (fnmatch(pattern, rte_logs.dynamic_types[i].name, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } return 0; @@ -264,29 +296,11 @@ rte_log_lookup(const char *name) return -1; } -/* register an extended log type, assuming table is large enough, and id - * is not yet registered. - */ static int -__rte_log_register(const char *name, int id) -{ - char *dup_name = strdup(name); - - if (dup_name == NULL) - return -ENOMEM; - - rte_logs.dynamic_types[id].name = dup_name; - rte_logs.dynamic_types[id].loglevel = RTE_LOG_INFO; - - return id; -} - -/* register an extended log type */ -int -rte_log_register(const char *name) +__rte_log_register(const char *name, uint32_t level) { struct rte_log_dynamic_type *new_dynamic_types; - int id, ret; + int id; id = rte_log_lookup(name); if (id >= 0) @@ -299,13 +313,24 @@ rte_log_register(const char *name) return -ENOMEM; rte_logs.dynamic_types = new_dynamic_types; - ret = __rte_log_register(name, rte_logs.dynamic_types_len); - if (ret < 0) - return ret; + id = rte_logs.dynamic_types_len; + memset(&rte_logs.dynamic_types[id], 0, + sizeof(rte_logs.dynamic_types[id])); + rte_logs.dynamic_types[id].name = strdup(name); + if (rte_logs.dynamic_types[id].name == NULL) + return -ENOMEM; + logtype_set_level(id, level); rte_logs.dynamic_types_len++; - return ret; + return id; +} + +/* register an extended log type */ +int +rte_log_register(const char *name) +{ + return __rte_log_register(name, RTE_LOG_INFO); } /* Register an extended log type and try to pick its level from EAL options */ @@ -314,11 +339,6 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) { struct rte_eal_opt_loglevel *opt_ll; uint32_t level = level_def; - int type; - - type = rte_log_register(name); - if (type < 0) - return type; TAILQ_FOREACH(opt_ll, &opt_loglevel_list, next) { if (opt_ll->level > RTE_LOG_DEBUG) @@ -333,9 +353,7 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) } } - rte_logs.dynamic_types[type].loglevel = level; - - return type; + return __rte_log_register(name, level); } struct logtype { @@ -388,30 +406,15 @@ RTE_INIT_PRIO(rte_log_init, LOG) return; /* register legacy log types */ - for (i = 0; i < RTE_DIM(logtype_strings); i++) - __rte_log_register(logtype_strings[i].logtype, - logtype_strings[i].log_id); + for (i = 0; i < RTE_DIM(logtype_strings); i++) { + rte_logs.dynamic_types[logtype_strings[i].log_id].name = + strdup(logtype_strings[i].logtype); + logtype_set_level(logtype_strings[i].log_id, RTE_LOG_INFO); + } rte_logs.dynamic_types_len = RTE_LOGTYPE_FIRST_EXT_ID; } -static const char * -loglevel_to_string(uint32_t level) -{ - switch (level) { - case 0: return "disabled"; - case RTE_LOG_EMERG: return "emerg"; - case RTE_LOG_ALERT: return "alert"; - case RTE_LOG_CRIT: return "critical"; - case RTE_LOG_ERR: return "error"; - case RTE_LOG_WARNING: return "warning"; - case RTE_LOG_NOTICE: return "notice"; - case RTE_LOG_INFO: return "info"; - case RTE_LOG_DEBUG: return "debug"; - default: return "unknown"; - } -} - /* dump global level and registered log types */ void rte_log_dump(FILE *f) -- 2.23.0
--log-level option is handled early, no need to reevaluate it later in EAL init. Before: $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug \ --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \ |& grep -i logtype.level EAL: lib.eal logtype level changed from info to debug EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info After: $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug \ --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \ |& grep -i logtype.level EAL: lib.eal logtype level changed from info to debug EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info Fixes: 6c7216eefd63 ("eal: fix log level of early messages") Fixes: 1c806ae5c3ac ("eal/windows: support command line options parsing") Cc: stable@dpdk.org Signed-off-by: David Marchand <david.marchand@redhat.com> --- lib/librte_eal/freebsd/eal.c | 4 ++++ lib/librte_eal/linux/eal.c | 4 ++++ lib/librte_eal/windows/eal.c | 4 ++++ 3 files changed, 12 insertions(+) diff --git a/lib/librte_eal/freebsd/eal.c b/lib/librte_eal/freebsd/eal.c index 62320d610f..817961d8d6 100644 --- a/lib/librte_eal/freebsd/eal.c +++ b/lib/librte_eal/freebsd/eal.c @@ -521,6 +521,10 @@ eal_parse_args(int argc, char **argv) goto out; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { diff --git a/lib/librte_eal/linux/eal.c b/lib/librte_eal/linux/eal.c index 9ffb4b3314..8070e0f632 100644 --- a/lib/librte_eal/linux/eal.c +++ b/lib/librte_eal/linux/eal.c @@ -704,6 +704,10 @@ eal_parse_args(int argc, char **argv) goto out; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { diff --git a/lib/librte_eal/windows/eal.c b/lib/librte_eal/windows/eal.c index 2fc3d6141c..e3b6a6ea61 100644 --- a/lib/librte_eal/windows/eal.c +++ b/lib/librte_eal/windows/eal.c @@ -149,6 +149,10 @@ eal_parse_args(int argc, char **argv) return -1; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { -- 2.23.0
23/03/2021 11:19, David Marchand:
> --log-level option is handled early, no need to reevaluate it later in
> EAL init.
>
> Before:
> $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \
> --log-level=lib.eal:debug \
> --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \
> |& grep -i logtype.level
>
> EAL: lib.eal logtype level changed from info to debug
> EAL: lib.ethdev logtype level changed from info to debug
> EAL: lib.ethdev logtype level changed from debug to info
> EAL: lib.ethdev logtype level changed from info to debug
> EAL: lib.ethdev logtype level changed from debug to info
>
> After:
> $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \
> --log-level=lib.eal:debug \
> --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \
> |& grep -i logtype.level
>
> EAL: lib.eal logtype level changed from info to debug
> EAL: lib.ethdev logtype level changed from info to debug
> EAL: lib.ethdev logtype level changed from debug to info
>
> Fixes: 6c7216eefd63 ("eal: fix log level of early messages")
> Fixes: 1c806ae5c3ac ("eal/windows: support command line options parsing")
> Cc: stable@dpdk.org
>
> Signed-off-by: David Marchand <david.marchand@redhat.com>
Acked-by: Thomas Monjalon <thomas@monjalon.net>
W dniu 23.03.2021 o 16:54, Thomas Monjalon pisze:
> 23/03/2021 11:19, David Marchand:
>> --log-level option is handled early, no need to reevaluate it later in
>> EAL init.
>>
>> Before:
>> $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \
>> --log-level=lib.eal:debug \
>> --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \
>> |& grep -i logtype.level
>>
>> EAL: lib.eal logtype level changed from info to debug
>> EAL: lib.ethdev logtype level changed from info to debug
>> EAL: lib.ethdev logtype level changed from debug to info
>> EAL: lib.ethdev logtype level changed from info to debug
>> EAL: lib.ethdev logtype level changed from debug to info
>>
>> After:
>> $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \
>> --log-level=lib.eal:debug \
>> --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \
>> |& grep -i logtype.level
>>
>> EAL: lib.eal logtype level changed from info to debug
>> EAL: lib.ethdev logtype level changed from info to debug
>> EAL: lib.ethdev logtype level changed from debug to info
>>
>> Fixes: 6c7216eefd63 ("eal: fix log level of early messages")
>> Fixes: 1c806ae5c3ac ("eal/windows: support command line options parsing")
>> Cc: stable@dpdk.org
>>
>> Signed-off-by: David Marchand <david.marchand@redhat.com>
> Acked-by: Thomas Monjalon <thomas@monjalon.net>
>
>
Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com>
Tested-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com>
--
Lukasz Wojciechowski
Principal Software Engineer
Samsung R&D Institute Poland
Samsung Electronics
Office +48 22 377 88 25
l.wojciechow@partner.samsung.com
Here is a little series, following RFC [1]. No change in behavior expected, but reviews welcome ! :-) 1: https://patchwork.dpdk.org/project/dpdk/list/?series=10632 Changes since v1: - some cleanup in patch 1, - some precision in description of patch 2, Changes since RFC: - added unit test, - logged level changes in rte_log_register, - fixed double evaluation of --log-level options, -- David Marchand David Marchand (3): test/log: check levels log: track log level changes eal: fix evaluation of log level option app/test/test_logs.c | 51 ++++++++++- lib/librte_eal/common/eal_common_log.c | 113 +++++++++++++------------ lib/librte_eal/freebsd/eal.c | 4 + lib/librte_eal/linux/eal.c | 4 + lib/librte_eal/windows/eal.c | 4 + 5 files changed, 119 insertions(+), 57 deletions(-) -- 2.23.0
Add checks on log levels: - default values for rte_log_register and RTE_LOG_REGISTER, - level changes with rte_log_set_level and consorts Signed-off-by: David Marchand <david.marchand@redhat.com> --- Changes since v1: - dropped unrelated change moving logtype1 and logtype2 as global static variables, - dropped __FILE__ + __LINE__ from assert logs, since the macro already logs the line, --- app/test/test_logs.c | 51 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 49 insertions(+), 2 deletions(-) diff --git a/app/test/test_logs.c b/app/test/test_logs.c index 425ae03cb9..7abb6eeca2 100644 --- a/app/test/test_logs.c +++ b/app/test/test_logs.c @@ -20,6 +20,8 @@ #define RTE_LOGTYPE_TESTAPP1 RTE_LOGTYPE_USER1 #define RTE_LOGTYPE_TESTAPP2 RTE_LOGTYPE_USER2 +RTE_LOG_REGISTER(logtype3, logtype3, ERR) + /* * Logs * ==== @@ -64,6 +66,22 @@ test_logs(void) int logtype1, logtype2; int ret; +#define CHECK_LEVELS(exp1, exp2, exp3) do \ +{ \ + ret = rte_log_get_level(logtype1); \ + TEST_ASSERT_EQUAL(ret, exp1, \ + "invalid level for logtype1 got %d, expecting %d\n", \ + ret, exp1); \ + ret = rte_log_get_level(logtype2); \ + TEST_ASSERT_EQUAL(ret, exp2, \ + "invalid level for logtype2 got %d, expecting %d\n", \ + ret, exp2); \ + ret = rte_log_get_level(logtype3); \ + TEST_ASSERT_EQUAL(ret, exp3, \ + "invalid level for logtype3 got %d, expecting %d\n", \ + ret, exp3); \ +} while (0) + printf("== dynamic log types\n"); logtype1 = rte_log_register("logtype1"); @@ -77,9 +95,36 @@ test_logs(void) return -1; } + ret = rte_log_get_level(logtype1); + TEST_ASSERT_EQUAL(ret, RTE_LOG_INFO, + "invalid default level for logtype1 got %d, expecting %d\n", + ret, RTE_LOG_INFO); + + ret = rte_log_get_level(logtype2); + TEST_ASSERT_EQUAL(ret, RTE_LOG_INFO, + "invalid default level for logtype2 got %d, expecting %d\n", + ret, RTE_LOG_INFO); + + ret = rte_log_get_level(logtype3); + TEST_ASSERT_EQUAL(ret, RTE_LOG_ERR, + "invalid default level for logtype3 got %d, expecting %d\n", + ret, RTE_LOG_ERR); + + rte_log_set_level(logtype1, RTE_LOG_ERR); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_INFO, RTE_LOG_ERR); + + rte_log_set_level_regexp("type$", RTE_LOG_EMERG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_INFO, RTE_LOG_ERR); + + rte_log_set_level_regexp("type[23]", RTE_LOG_EMERG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_EMERG, RTE_LOG_EMERG); + + rte_log_set_level_pattern("logtype", RTE_LOG_DEBUG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_EMERG, RTE_LOG_EMERG); + /* set logtype level low to so we can test global level */ - rte_log_set_level(logtype1, RTE_LOG_DEBUG); - rte_log_set_level(logtype2, RTE_LOG_DEBUG); + rte_log_set_level_pattern("logtype*", RTE_LOG_DEBUG); + CHECK_LEVELS(RTE_LOG_DEBUG, RTE_LOG_DEBUG, RTE_LOG_DEBUG); /* log in error level */ rte_log_set_global_level(RTE_LOG_ERR); @@ -103,6 +148,8 @@ test_logs(void) if (ret < 0) return ret; +#undef CHECK_LEVELS + return 0; } -- 2.23.0
Add a log message when registering log types and changing log levels. __rte_log_register previous handled both legacy and dynamic logtypes. To simplify the code, __rte_log_register is reworked to only handle dynamic logtypes and takes a log level. Example: $ DPDK_TEST=logs_autotest ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug ... RTE>>logs_autotest == dynamic log types EAL: logtype1 logtype level changed from disabled to info EAL: logtype2 logtype level changed from disabled to info EAL: logtype1 logtype level changed from info to error EAL: logtype3 logtype level changed from error to emerg EAL: logtype2 logtype level changed from info to emerg EAL: logtype3 logtype level changed from emerg to debug EAL: logtype1 logtype level changed from error to debug EAL: logtype2 logtype level changed from emerg to debug error message critical message critical message error message == static log types TESTAPP1: error message TESTAPP1: critical message TESTAPP2: critical message TESTAPP1: error message Test OK Suggested-by: Ilya Maximets <i.maximets@ovn.org> Signed-off-by: David Marchand <david.marchand@redhat.com> Acked-by: Andrew Rybchenko <arybchenko@solarflare.com> Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> --- Changes since v1: - updated commitlog, --- lib/librte_eal/common/eal_common_log.c | 113 +++++++++++++------------ 1 file changed, 58 insertions(+), 55 deletions(-) diff --git a/lib/librte_eal/common/eal_common_log.c b/lib/librte_eal/common/eal_common_log.c index c5554badb2..b64a1b9381 100644 --- a/lib/librte_eal/common/eal_common_log.c +++ b/lib/librte_eal/common/eal_common_log.c @@ -135,6 +135,38 @@ rte_log_can_log(uint32_t logtype, uint32_t level) return true; } +static const char * +loglevel_to_string(uint32_t level) +{ + switch (level) { + case 0: return "disabled"; + case RTE_LOG_EMERG: return "emerg"; + case RTE_LOG_ALERT: return "alert"; + case RTE_LOG_CRIT: return "critical"; + case RTE_LOG_ERR: return "error"; + case RTE_LOG_WARNING: return "warning"; + case RTE_LOG_NOTICE: return "notice"; + case RTE_LOG_INFO: return "info"; + case RTE_LOG_DEBUG: return "debug"; + default: return "unknown"; + } +} + +static void +logtype_set_level(uint32_t type, uint32_t level) +{ + uint32_t current = rte_logs.dynamic_types[type].loglevel; + + if (current != level) { + rte_logs.dynamic_types[type].loglevel = level; + RTE_LOG(DEBUG, EAL, "%s logtype level changed from %s to %s\n", + rte_logs.dynamic_types[type].name == NULL ? + "" : rte_logs.dynamic_types[type].name, + loglevel_to_string(current), + loglevel_to_string(level)); + } +} + int rte_log_set_level(uint32_t type, uint32_t level) { @@ -143,7 +175,7 @@ rte_log_set_level(uint32_t type, uint32_t level) if (level > RTE_LOG_DEBUG) return -1; - rte_logs.dynamic_types[type].loglevel = level; + logtype_set_level(type, level); return 0; } @@ -166,7 +198,7 @@ rte_log_set_level_regexp(const char *regex, uint32_t level) continue; if (regexec(&r, rte_logs.dynamic_types[i].name, 0, NULL, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } regfree(&r); @@ -226,7 +258,7 @@ rte_log_set_level_pattern(const char *pattern, uint32_t level) continue; if (fnmatch(pattern, rte_logs.dynamic_types[i].name, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } return 0; @@ -264,29 +296,11 @@ rte_log_lookup(const char *name) return -1; } -/* register an extended log type, assuming table is large enough, and id - * is not yet registered. - */ static int -__rte_log_register(const char *name, int id) -{ - char *dup_name = strdup(name); - - if (dup_name == NULL) - return -ENOMEM; - - rte_logs.dynamic_types[id].name = dup_name; - rte_logs.dynamic_types[id].loglevel = RTE_LOG_INFO; - - return id; -} - -/* register an extended log type */ -int -rte_log_register(const char *name) +__rte_log_register(const char *name, uint32_t level) { struct rte_log_dynamic_type *new_dynamic_types; - int id, ret; + int id; id = rte_log_lookup(name); if (id >= 0) @@ -299,13 +313,24 @@ rte_log_register(const char *name) return -ENOMEM; rte_logs.dynamic_types = new_dynamic_types; - ret = __rte_log_register(name, rte_logs.dynamic_types_len); - if (ret < 0) - return ret; + id = rte_logs.dynamic_types_len; + memset(&rte_logs.dynamic_types[id], 0, + sizeof(rte_logs.dynamic_types[id])); + rte_logs.dynamic_types[id].name = strdup(name); + if (rte_logs.dynamic_types[id].name == NULL) + return -ENOMEM; + logtype_set_level(id, level); rte_logs.dynamic_types_len++; - return ret; + return id; +} + +/* register an extended log type */ +int +rte_log_register(const char *name) +{ + return __rte_log_register(name, RTE_LOG_INFO); } /* Register an extended log type and try to pick its level from EAL options */ @@ -314,11 +339,6 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) { struct rte_eal_opt_loglevel *opt_ll; uint32_t level = level_def; - int type; - - type = rte_log_register(name); - if (type < 0) - return type; TAILQ_FOREACH(opt_ll, &opt_loglevel_list, next) { if (opt_ll->level > RTE_LOG_DEBUG) @@ -333,9 +353,7 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) } } - rte_logs.dynamic_types[type].loglevel = level; - - return type; + return __rte_log_register(name, level); } struct logtype { @@ -388,30 +406,15 @@ RTE_INIT_PRIO(rte_log_init, LOG) return; /* register legacy log types */ - for (i = 0; i < RTE_DIM(logtype_strings); i++) - __rte_log_register(logtype_strings[i].logtype, - logtype_strings[i].log_id); + for (i = 0; i < RTE_DIM(logtype_strings); i++) { + rte_logs.dynamic_types[logtype_strings[i].log_id].name = + strdup(logtype_strings[i].logtype); + logtype_set_level(logtype_strings[i].log_id, RTE_LOG_INFO); + } rte_logs.dynamic_types_len = RTE_LOGTYPE_FIRST_EXT_ID; } -static const char * -loglevel_to_string(uint32_t level) -{ - switch (level) { - case 0: return "disabled"; - case RTE_LOG_EMERG: return "emerg"; - case RTE_LOG_ALERT: return "alert"; - case RTE_LOG_CRIT: return "critical"; - case RTE_LOG_ERR: return "error"; - case RTE_LOG_WARNING: return "warning"; - case RTE_LOG_NOTICE: return "notice"; - case RTE_LOG_INFO: return "info"; - case RTE_LOG_DEBUG: return "debug"; - default: return "unknown"; - } -} - /* dump global level and registered log types */ void rte_log_dump(FILE *f) -- 2.23.0
--log-level option is handled early, no need to reevaluate it later in EAL init. Before: $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug \ --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \ |& grep -i logtype.level EAL: lib.eal logtype level changed from info to debug EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info After: $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug \ --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \ |& grep -i logtype.level EAL: lib.eal logtype level changed from info to debug EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info Fixes: 6c7216eefd63 ("eal: fix log level of early messages") Fixes: 1c806ae5c3ac ("eal/windows: support command line options parsing") Cc: stable@dpdk.org Signed-off-by: David Marchand <david.marchand@redhat.com> Acked-by: Thomas Monjalon <thomas@monjalon.net> Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> Tested-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> --- lib/librte_eal/freebsd/eal.c | 4 ++++ lib/librte_eal/linux/eal.c | 4 ++++ lib/librte_eal/windows/eal.c | 4 ++++ 3 files changed, 12 insertions(+) diff --git a/lib/librte_eal/freebsd/eal.c b/lib/librte_eal/freebsd/eal.c index 62320d610f..817961d8d6 100644 --- a/lib/librte_eal/freebsd/eal.c +++ b/lib/librte_eal/freebsd/eal.c @@ -521,6 +521,10 @@ eal_parse_args(int argc, char **argv) goto out; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { diff --git a/lib/librte_eal/linux/eal.c b/lib/librte_eal/linux/eal.c index 9ffb4b3314..8070e0f632 100644 --- a/lib/librte_eal/linux/eal.c +++ b/lib/librte_eal/linux/eal.c @@ -704,6 +704,10 @@ eal_parse_args(int argc, char **argv) goto out; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { diff --git a/lib/librte_eal/windows/eal.c b/lib/librte_eal/windows/eal.c index 2fc3d6141c..e3b6a6ea61 100644 --- a/lib/librte_eal/windows/eal.c +++ b/lib/librte_eal/windows/eal.c @@ -149,6 +149,10 @@ eal_parse_args(int argc, char **argv) return -1; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { -- 2.23.0
24/03/2021 11:32, David Marchand: > Add a log message when registering log types and changing log levels. [...] > + RTE_LOG(DEBUG, EAL, "%s logtype level changed from %s to %s\n", I would prefer "foo log level changed" instead of "foo logtype level changed". Opinions? > + rte_logs.dynamic_types[type].name == NULL ? > + "" : rte_logs.dynamic_types[type].name, In which case the logtype name is undefined? If it is unexexpected, should we have "unknown" instead of ""?
On Thu, Apr 8, 2021 at 5:55 PM Thomas Monjalon <thomas@monjalon.net> wrote: > > 24/03/2021 11:32, David Marchand: > > Add a log message when registering log types and changing log levels. > [...] > > + RTE_LOG(DEBUG, EAL, "%s logtype level changed from %s to %s\n", > > I would prefer "foo log level changed" > instead of "foo logtype level changed". > Opinions? No objection for me. > > > + rte_logs.dynamic_types[type].name == NULL ? > > + "" : rte_logs.dynamic_types[type].name, > > In which case the logtype name is undefined? The logtype name is strdup(). When registering static logtypes, this could fail, and we log the level change at this point. The other path would be to call rte_log_set_level() on those static logtypes (there is also the case of the holes in the static logtypes, but if users are using them, it sounds like a hack). > If it is unexexpected, should we have "unknown" instead of ""? We could still register a "unknown" logtype, and then it would be odd :-). Empty is clear to me. -- David Marchand
09/04/2021 11:08, David Marchand:
> On Thu, Apr 8, 2021 at 5:55 PM Thomas Monjalon <thomas@monjalon.net> wrote:
> >
> > 24/03/2021 11:32, David Marchand:
> > > Add a log message when registering log types and changing log levels.
> > [...]
> > > + RTE_LOG(DEBUG, EAL, "%s logtype level changed from %s to %s\n",
> >
> > I would prefer "foo log level changed"
> > instead of "foo logtype level changed".
> > Opinions?
>
> No objection for me.
>
>
> >
> > > + rte_logs.dynamic_types[type].name == NULL ?
> > > + "" : rte_logs.dynamic_types[type].name,
> >
> > In which case the logtype name is undefined?
>
> The logtype name is strdup().
> When registering static logtypes, this could fail, and we log the
> level change at this point.
>
> The other path would be to call rte_log_set_level() on those static
> logtypes (there is also the case of the holes in the static logtypes,
> but if users are using them, it sounds like a hack).
>
> > If it is unexexpected, should we have "unknown" instead of ""?
>
> We could still register a "unknown" logtype, and then it would be odd :-).
> Empty is clear to me.
OK
Anyway it is unlikely.
Here is a little series, following RFC [1]. No change in behavior expected, but reviews welcome ! :-) 1: https://patchwork.dpdk.org/project/dpdk/list/?series=10632 Changes since v2: - rebased on main, - updated log message in patch 2, Changes since v1: - some cleanup in patch 1, - some precision in description of patch 2, Changes since RFC: - added unit test, - logged level changes in rte_log_register, - fixed double evaluation of --log-level options, -- David Marchand David Marchand (3): test/log: check levels log: track log level changes eal: fix evaluation of log level option app/test/test_logs.c | 51 ++++++++++++++++- lib/librte_eal/common/eal_common_log.c | 79 +++++++++++++------------- lib/librte_eal/freebsd/eal.c | 4 ++ lib/librte_eal/linux/eal.c | 4 ++ lib/librte_eal/windows/eal.c | 4 ++ 5 files changed, 102 insertions(+), 40 deletions(-) -- 2.23.0
Add checks on log levels: - default values for rte_log_register and RTE_LOG_REGISTER, - level changes with rte_log_set_level and consorts Signed-off-by: David Marchand <david.marchand@redhat.com> --- Changes since v1: - dropped unrelated change moving logtype1 and logtype2 as global static variables, - dropped __FILE__ + __LINE__ from assert logs, since the macro already logs the line, --- app/test/test_logs.c | 51 ++++++++++++++++++++++++++++++++++++++++++-- 1 file changed, 49 insertions(+), 2 deletions(-) diff --git a/app/test/test_logs.c b/app/test/test_logs.c index 425ae03cb9..7abb6eeca2 100644 --- a/app/test/test_logs.c +++ b/app/test/test_logs.c @@ -20,6 +20,8 @@ #define RTE_LOGTYPE_TESTAPP1 RTE_LOGTYPE_USER1 #define RTE_LOGTYPE_TESTAPP2 RTE_LOGTYPE_USER2 +RTE_LOG_REGISTER(logtype3, logtype3, ERR) + /* * Logs * ==== @@ -64,6 +66,22 @@ test_logs(void) int logtype1, logtype2; int ret; +#define CHECK_LEVELS(exp1, exp2, exp3) do \ +{ \ + ret = rte_log_get_level(logtype1); \ + TEST_ASSERT_EQUAL(ret, exp1, \ + "invalid level for logtype1 got %d, expecting %d\n", \ + ret, exp1); \ + ret = rte_log_get_level(logtype2); \ + TEST_ASSERT_EQUAL(ret, exp2, \ + "invalid level for logtype2 got %d, expecting %d\n", \ + ret, exp2); \ + ret = rte_log_get_level(logtype3); \ + TEST_ASSERT_EQUAL(ret, exp3, \ + "invalid level for logtype3 got %d, expecting %d\n", \ + ret, exp3); \ +} while (0) + printf("== dynamic log types\n"); logtype1 = rte_log_register("logtype1"); @@ -77,9 +95,36 @@ test_logs(void) return -1; } + ret = rte_log_get_level(logtype1); + TEST_ASSERT_EQUAL(ret, RTE_LOG_INFO, + "invalid default level for logtype1 got %d, expecting %d\n", + ret, RTE_LOG_INFO); + + ret = rte_log_get_level(logtype2); + TEST_ASSERT_EQUAL(ret, RTE_LOG_INFO, + "invalid default level for logtype2 got %d, expecting %d\n", + ret, RTE_LOG_INFO); + + ret = rte_log_get_level(logtype3); + TEST_ASSERT_EQUAL(ret, RTE_LOG_ERR, + "invalid default level for logtype3 got %d, expecting %d\n", + ret, RTE_LOG_ERR); + + rte_log_set_level(logtype1, RTE_LOG_ERR); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_INFO, RTE_LOG_ERR); + + rte_log_set_level_regexp("type$", RTE_LOG_EMERG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_INFO, RTE_LOG_ERR); + + rte_log_set_level_regexp("type[23]", RTE_LOG_EMERG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_EMERG, RTE_LOG_EMERG); + + rte_log_set_level_pattern("logtype", RTE_LOG_DEBUG); + CHECK_LEVELS(RTE_LOG_ERR, RTE_LOG_EMERG, RTE_LOG_EMERG); + /* set logtype level low to so we can test global level */ - rte_log_set_level(logtype1, RTE_LOG_DEBUG); - rte_log_set_level(logtype2, RTE_LOG_DEBUG); + rte_log_set_level_pattern("logtype*", RTE_LOG_DEBUG); + CHECK_LEVELS(RTE_LOG_DEBUG, RTE_LOG_DEBUG, RTE_LOG_DEBUG); /* log in error level */ rte_log_set_global_level(RTE_LOG_ERR); @@ -103,6 +148,8 @@ test_logs(void) if (ret < 0) return ret; +#undef CHECK_LEVELS + return 0; } -- 2.23.0
Add a log message when registering log types and changing log levels. __rte_log_register previous handled both legacy and dynamic logtypes. To simplify the code, __rte_log_register is reworked to only handle dynamic logtypes and takes a log level. Example: $ DPDK_TEST=logs_autotest ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug ... RTE>>logs_autotest == dynamic log types EAL: logtype1 logtype level changed from disabled to info EAL: logtype2 logtype level changed from disabled to info EAL: logtype1 logtype level changed from info to error EAL: logtype3 logtype level changed from error to emerg EAL: logtype2 logtype level changed from info to emerg EAL: logtype3 logtype level changed from emerg to debug EAL: logtype1 logtype level changed from error to debug EAL: logtype2 logtype level changed from emerg to debug error message critical message critical message error message == static log types TESTAPP1: error message TESTAPP1: critical message TESTAPP2: critical message TESTAPP1: error message Test OK Suggested-by: Ilya Maximets <i.maximets@ovn.org> Signed-off-by: David Marchand <david.marchand@redhat.com> Acked-by: Andrew Rybchenko <arybchenko@solarflare.com> Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> --- Changes since v2: - rebased on Thomas changes, - updated log level change message, Changes since v1: - updated commitlog, --- lib/librte_eal/common/eal_common_log.c | 79 +++++++++++++------------- 1 file changed, 41 insertions(+), 38 deletions(-) diff --git a/lib/librte_eal/common/eal_common_log.c b/lib/librte_eal/common/eal_common_log.c index 4c1d514770..bed83a402a 100644 --- a/lib/librte_eal/common/eal_common_log.c +++ b/lib/librte_eal/common/eal_common_log.c @@ -135,6 +135,21 @@ rte_log_can_log(uint32_t logtype, uint32_t level) return true; } +static void +logtype_set_level(uint32_t type, uint32_t level) +{ + uint32_t current = rte_logs.dynamic_types[type].loglevel; + + if (current != level) { + rte_logs.dynamic_types[type].loglevel = level; + RTE_LOG(DEBUG, EAL, "%s log level changed from %s to %s\n", + rte_logs.dynamic_types[type].name == NULL ? + "" : rte_logs.dynamic_types[type].name, + eal_log_level2str(current), + eal_log_level2str(level)); + } +} + int rte_log_set_level(uint32_t type, uint32_t level) { @@ -143,7 +158,7 @@ rte_log_set_level(uint32_t type, uint32_t level) if (level > RTE_LOG_MAX) return -1; - rte_logs.dynamic_types[type].loglevel = level; + logtype_set_level(type, level); return 0; } @@ -166,7 +181,7 @@ rte_log_set_level_regexp(const char *regex, uint32_t level) continue; if (regexec(&r, rte_logs.dynamic_types[i].name, 0, NULL, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } regfree(&r); @@ -227,7 +242,7 @@ rte_log_set_level_pattern(const char *pattern, uint32_t level) continue; if (fnmatch(pattern, rte_logs.dynamic_types[i].name, 0) == 0) - rte_logs.dynamic_types[i].loglevel = level; + logtype_set_level(i, level); } return 0; @@ -266,29 +281,11 @@ log_lookup(const char *name) return -1; } -/* register an extended log type, assuming table is large enough, and id - * is not yet registered. - */ static int -log_register(const char *name, int id) -{ - char *dup_name = strdup(name); - - if (dup_name == NULL) - return -ENOMEM; - - rte_logs.dynamic_types[id].name = dup_name; - rte_logs.dynamic_types[id].loglevel = RTE_LOG_INFO; - - return id; -} - -/* register an extended log type */ -int -rte_log_register(const char *name) +log_register(const char *name, uint32_t level) { struct rte_log_dynamic_type *new_dynamic_types; - int id, ret; + int id; id = log_lookup(name); if (id >= 0) @@ -301,13 +298,24 @@ rte_log_register(const char *name) return -ENOMEM; rte_logs.dynamic_types = new_dynamic_types; - ret = log_register(name, rte_logs.dynamic_types_len); - if (ret < 0) - return ret; + id = rte_logs.dynamic_types_len; + memset(&rte_logs.dynamic_types[id], 0, + sizeof(rte_logs.dynamic_types[id])); + rte_logs.dynamic_types[id].name = strdup(name); + if (rte_logs.dynamic_types[id].name == NULL) + return -ENOMEM; + logtype_set_level(id, level); rte_logs.dynamic_types_len++; - return ret; + return id; +} + +/* register an extended log type */ +int +rte_log_register(const char *name) +{ + return log_register(name, RTE_LOG_INFO); } /* Register an extended log type and try to pick its level from EAL options */ @@ -316,11 +324,6 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) { struct rte_eal_opt_loglevel *opt_ll; uint32_t level = level_def; - int type; - - type = rte_log_register(name); - if (type < 0) - return type; TAILQ_FOREACH(opt_ll, &opt_loglevel_list, next) { if (opt_ll->level > RTE_LOG_MAX) @@ -335,9 +338,7 @@ rte_log_register_type_and_pick_level(const char *name, uint32_t level_def) } } - rte_logs.dynamic_types[type].loglevel = level; - - return type; + return log_register(name, level); } struct logtype { @@ -390,9 +391,11 @@ RTE_INIT_PRIO(log_init, LOG) return; /* register legacy log types */ - for (i = 0; i < RTE_DIM(logtype_strings); i++) - log_register(logtype_strings[i].logtype, - logtype_strings[i].log_id); + for (i = 0; i < RTE_DIM(logtype_strings); i++) { + rte_logs.dynamic_types[logtype_strings[i].log_id].name = + strdup(logtype_strings[i].logtype); + logtype_set_level(logtype_strings[i].log_id, RTE_LOG_INFO); + } rte_logs.dynamic_types_len = RTE_LOGTYPE_FIRST_EXT_ID; } -- 2.23.0
--log-level option is handled early, no need to reevaluate it later in EAL init. Before: $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug \ --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \ |& grep -i logtype.level EAL: lib.eal logtype level changed from info to debug EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info After: $ echo quit | ./build/app/test/dpdk-test --no-huge -m 512 \ --log-level=lib.eal:debug \ --log-level=lib.ethdev:debug --log-level=lib.ethdev:info \ |& grep -i logtype.level EAL: lib.eal logtype level changed from info to debug EAL: lib.ethdev logtype level changed from info to debug EAL: lib.ethdev logtype level changed from debug to info Fixes: 6c7216eefd63 ("eal: fix log level of early messages") Fixes: 1c806ae5c3ac ("eal/windows: support command line options parsing") Cc: stable@dpdk.org Signed-off-by: David Marchand <david.marchand@redhat.com> Acked-by: Thomas Monjalon <thomas@monjalon.net> Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> Tested-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> --- lib/librte_eal/freebsd/eal.c | 4 ++++ lib/librte_eal/linux/eal.c | 4 ++++ lib/librte_eal/windows/eal.c | 4 ++++ 3 files changed, 12 insertions(+) diff --git a/lib/librte_eal/freebsd/eal.c b/lib/librte_eal/freebsd/eal.c index 5544701f20..f4d1676754 100644 --- a/lib/librte_eal/freebsd/eal.c +++ b/lib/librte_eal/freebsd/eal.c @@ -521,6 +521,10 @@ eal_parse_args(int argc, char **argv) goto out; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { diff --git a/lib/librte_eal/linux/eal.c b/lib/librte_eal/linux/eal.c index baeead3301..ba19fc6347 100644 --- a/lib/librte_eal/linux/eal.c +++ b/lib/librte_eal/linux/eal.c @@ -705,6 +705,10 @@ eal_parse_args(int argc, char **argv) goto out; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { diff --git a/lib/librte_eal/windows/eal.c b/lib/librte_eal/windows/eal.c index 68a1fd1d21..41be20d89f 100644 --- a/lib/librte_eal/windows/eal.c +++ b/lib/librte_eal/windows/eal.c @@ -150,6 +150,10 @@ eal_parse_args(int argc, char **argv) return -1; } + /* eal_log_level_parse() already handled this option */ + if (opt == OPT_LOG_LEVEL_NUM) + continue; + ret = eal_parse_common_option(opt, optarg, internal_conf); /* common parser is not happy */ if (ret < 0) { -- 2.23.0
09/04/2021 13:04, David Marchand: > Add a log message when registering log types and changing log levels. > > __rte_log_register previous handled both legacy and dynamic logtypes. > To simplify the code, __rte_log_register is reworked to only handle > dynamic logtypes and takes a log level. > > Example: > $ DPDK_TEST=logs_autotest ./build/app/test/dpdk-test --no-huge -m 512 \ > --log-level=lib.eal:debug > ... > RTE>>logs_autotest > == dynamic log types > EAL: logtype1 logtype level changed from disabled to info > EAL: logtype2 logtype level changed from disabled to info > EAL: logtype1 logtype level changed from info to error > EAL: logtype3 logtype level changed from error to emerg > EAL: logtype2 logtype level changed from info to emerg > EAL: logtype3 logtype level changed from emerg to debug > EAL: logtype1 logtype level changed from error to debug > EAL: logtype2 logtype level changed from emerg to debug This needs to be updated: logtype -> log > error message > critical message > critical message > error message > == static log types > TESTAPP1: error message > TESTAPP1: critical message > TESTAPP2: critical message > TESTAPP1: error message > Test OK > > Suggested-by: Ilya Maximets <i.maximets@ovn.org> > Signed-off-by: David Marchand <david.marchand@redhat.com> > Acked-by: Andrew Rybchenko <arybchenko@solarflare.com> > Acked-by: Lukasz Wojciechowski <l.wojciechow@partner.samsung.com> Acked-by: Thomas Monjalon <thomas@monjalon.net>
On Fri, Apr 9, 2021 at 1:59 PM Thomas Monjalon <thomas@monjalon.net> wrote:
>
> 09/04/2021 13:04, David Marchand:
> > Add a log message when registering log types and changing log levels.
> >
> > __rte_log_register previous handled both legacy and dynamic logtypes.
> > To simplify the code, __rte_log_register is reworked to only handle
> > dynamic logtypes and takes a log level.
> >
> > Example:
> > $ DPDK_TEST=logs_autotest ./build/app/test/dpdk-test --no-huge -m 512 \
> > --log-level=lib.eal:debug
> > ...
> > RTE>>logs_autotest
> > == dynamic log types
> > EAL: logtype1 logtype level changed from disabled to info
> > EAL: logtype2 logtype level changed from disabled to info
> > EAL: logtype1 logtype level changed from info to error
> > EAL: logtype3 logtype level changed from error to emerg
> > EAL: logtype2 logtype level changed from info to emerg
> > EAL: logtype3 logtype level changed from emerg to debug
> > EAL: logtype1 logtype level changed from error to debug
> > EAL: logtype2 logtype level changed from emerg to debug
>
> This needs to be updated: logtype -> log
I refreshed patch 3 commitlog too.
Thanks.
--
David Marchand
On Fri, Apr 9, 2021 at 1:05 PM David Marchand <david.marchand@redhat.com> wrote:
>
> Here is a little series, following RFC [1].
> No change in behavior expected, but reviews welcome ! :-)
>
> 1: https://patchwork.dpdk.org/project/dpdk/list/?series=10632
>
> Changes since v2:
> - rebased on main,
> - updated log message in patch 2,
Refreshed commitlogs for patch 2 and 3 following Thomas comment.
Series applied, thanks.
--
David Marchand