[dpdk-dev] [RFC PATCH] log: track log level changes

[dpdk-dev] [RFC PATCH] log: track log level changes

[David Marchand]

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

Re: [dpdk-dev] [RFC PATCH] log: track log level changes

[Andrew Rybchenko]

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>

Re: [dpdk-dev] [RFC PATCH] log: track log level changes

[Lukasz Wojciechowski]

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

Re: [dpdk-dev] [RFC PATCH] log: track log level changes

[David Marchand]

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

[dpdk-dev] [PATCH 0/3] Track log level changes

[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

[dpdk-dev] [PATCH 1/3] test/log: check levels

[David Marchand]

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

[dpdk-dev] [PATCH 2/3] log: track log level changes

[David Marchand]

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

[dpdk-dev] [PATCH 3/3] eal: fix evaluation of log level option

[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>
---
 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

Re: [dpdk-dev] [dpdk-stable] [PATCH 3/3] eal: fix evaluation of log level option

[Thomas Monjalon]

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>

Re: [dpdk-dev] [dpdk-stable] [PATCH 3/3] eal: fix evaluation of log level option

[Lukasz Wojciechowski]

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

[dpdk-dev] [PATCH v2 0/3] Track log level changes

[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 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

[dpdk-dev] [PATCH v2 1/3] test/log: check levels

[David Marchand]

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

[dpdk-dev] [PATCH v2 2/3] log: track log level changes

[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
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

Re: [dpdk-dev] [PATCH v2 2/3] log: track log level changes

[Thomas Monjalon]

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 ""?

Re: [dpdk-dev] [PATCH v2 2/3] log: track log level changes

[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.


-- 
David Marchand

Re: [dpdk-dev] [PATCH v2 2/3] log: track log level changes

[Thomas Monjalon]

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.

[dpdk-dev] [PATCH v2 3/3] eal: fix evaluation of log level option

[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>
---
 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

[dpdk-dev] [PATCH v3 0/3] Track log level changes

[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 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

[dpdk-dev] [PATCH v3 1/3] test/log: check levels

[David Marchand]

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

[dpdk-dev] [PATCH v3 2/3] log: track log level changes

[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
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

Re: [dpdk-dev] [PATCH v3 2/3] log: track log level changes

[Thomas Monjalon]

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>

Re: [dpdk-dev] [PATCH v3 2/3] log: track log level changes

[David Marchand]

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

[dpdk-dev] [PATCH v3 3/3] eal: fix evaluation of log level option

[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>
---
 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

Re: [dpdk-dev] [PATCH v3 0/3] Track log level changes

[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