[v2,2/3] log: track log level changes

Message ID 20210324103213.29922-3-david.marchand@redhat.com (mailing list archive)
State Superseded, archived
Delegated to: David Marchand
Headers
Series Track log level changes |

Checks

Context Check Description
ci/checkpatch success coding style OK

Commit Message

David Marchand March 24, 2021, 10:32 a.m. UTC
  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(-)
  

Comments

Thomas Monjalon April 8, 2021, 3:54 p.m. UTC | #1
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 ""?
  
David Marchand April 9, 2021, 9:08 a.m. UTC | #2
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.
  
Thomas Monjalon April 9, 2021, 9:12 a.m. UTC | #3
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.
  

Patch

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)