[PATCH 0/4] Add severity to library logs

[PATCH 0/4] Add severity to library logs

[Tzvetomir Stoyanov (VMware)]

Defined library log levels and add a new API to set the desired log level.

Tzvetomir Stoyanov (VMware) (4):
  libtraceevent: Add log levels
  libtraceevent: Add logs with severity info
  libtraceevent: Rename tep_vwarning() to tep_vprint()
  libtraceevent: Document new log functionality

 Documentation/libtraceevent-log.txt | 90 +++++++++++++++++++++++++++++
 Documentation/libtraceevent.txt     |  3 +
 src/event-parse.c                   | 14 ++---
 src/event-parse.h                   | 12 ++++
 src/event-plugin.c                  |  2 +-
 src/event-utils.h                   | 11 +---
 src/parse-utils.c                   | 48 +++++++--------
 7 files changed, 140 insertions(+), 40 deletions(-)
 create mode 100644 Documentation/libtraceevent-log.txt

-- 
2.30.2

[PATCH 1/4] libtraceevent: Add log levels

[Tzvetomir Stoyanov (VMware)]

Defined levels of the library logs and new API to set the desired log
level. By default, only critical logs are enabled.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 src/event-parse.h | 12 ++++++++++++
 src/parse-utils.c | 16 ++++++++++++++++
 2 files changed, 28 insertions(+)

diff --git a/src/event-parse.h b/src/event-parse.h
index 05b156b..77be2b9 100644
--- a/src/event-parse.h
+++ b/src/event-parse.h
@@ -749,4 +749,16 @@ int tep_filter_copy(struct tep_event_filter *dest, struct tep_event_filter *sour
 
 int tep_filter_compare(struct tep_event_filter *filter1, struct tep_event_filter *filter2);
 
+/* Control library logs */
+enum tep_loglevel {
+	TEP_LOG_NONE = 0,
+	TEP_LOG_CRITICAL,
+	TEP_LOG_ERROR,
+	TEP_LOG_WARNING,
+	TEP_LOG_INFO,
+	TEP_LOG_DEBUG,
+	TEP_LOG_ALL
+};
+void tep_set_loglevel(enum tep_loglevel level);
+
 #endif /* _PARSE_EVENTS_H */
diff --git a/src/parse-utils.c b/src/parse-utils.c
index 6a4a2cd..bc89c44 100644
--- a/src/parse-utils.c
+++ b/src/parse-utils.c
@@ -9,8 +9,21 @@
 #include <stdarg.h>
 #include <errno.h>
 
+#include "event-parse.h"
+
 #define __weak __attribute__((weak))
 
+static int log_level = TEP_LOG_CRITICAL;
+
+/**
+ * tep_set_loglevel - set log level of the library
+ * @level: desired level of the library messages
+ */
+void tep_set_loglevel(enum tep_loglevel level)
+{
+	log_level = level;
+}
+
 int __weak tep_vwarning(const char *name, const char *fmt, va_list ap)
 {
 	int ret = errno;
@@ -29,6 +42,9 @@ void __weak tep_warning(const char *fmt, ...)
 {
 	va_list ap;
 
+	if (log_level < TEP_LOG_WARNING)
+		return;
+
 	va_start(ap, fmt);
 	tep_vwarning("libtraceevent", fmt, ap);
 	va_end(ap);
-- 
2.30.2

[PATCH 2/4] libtraceevent: Add logs with severity info

[Tzvetomir Stoyanov (VMware)]

Renamed existing pr_stat() internal function to tep_info() and limit it
to print only when the log level is TEP_LOG_INFO. Removed duplicated and
unused functions:
 vpr_stat()
 __pr_stat()
 __vpr_stat()

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 src/event-parse.c  | 14 +++++++-------
 src/event-plugin.c |  2 +-
 src/event-utils.h  |  7 +------
 src/parse-utils.c  | 24 ++++--------------------
 4 files changed, 13 insertions(+), 34 deletions(-)

diff --git a/src/event-parse.c b/src/event-parse.c
index 88ec909..97c1a97 100644
--- a/src/event-parse.c
+++ b/src/event-parse.c
@@ -6927,8 +6927,8 @@ static int find_event_handle(struct tep_handle *tep, struct tep_event *event)
 	if (!(*next))
 		return 0;
 
-	pr_stat("overriding event (%d) %s:%s with new print handler",
-		event->id, event->system, event->name);
+	tep_info("overriding event (%d) %s:%s with new print handler",
+		 event->id, event->system, event->name);
 
 	event->handler = handle->func;
 	event->context = handle->context;
@@ -7404,7 +7404,7 @@ int tep_register_print_function(struct tep_handle *tep,
 		 * plugins updating the function. This overrides the
 		 * system defaults.
 		 */
-		pr_stat("override of function helper '%s'", name);
+		tep_info("override of function helper '%s'", name);
 		remove_func_handler(tep, name);
 	}
 
@@ -7542,8 +7542,8 @@ int tep_register_event_handler(struct tep_handle *tep, int id,
 	if (event == NULL)
 		goto not_found;
 
-	pr_stat("overriding event (%d) %s:%s with new print handler",
-		event->id, event->system, event->name);
+	tep_info("overriding event (%d) %s:%s with new print handler",
+		 event->id, event->system, event->name);
 
 	event->handler = func;
 	event->context = context;
@@ -7628,8 +7628,8 @@ int tep_unregister_event_handler(struct tep_handle *tep, int id,
 		goto not_found;
 
 	if (event->handler == func && event->context == context) {
-		pr_stat("removing override handler for event (%d) %s:%s. Going back to default handler.",
-			event->id, event->system, event->name);
+		tep_info("removing override handler for event (%d) %s:%s. Going back to default handler.",
+			 event->id, event->system, event->name);
 
 		event->handler = NULL;
 		event->context = NULL;
diff --git a/src/event-plugin.c b/src/event-plugin.c
index df4a0a3..f42243f 100644
--- a/src/event-plugin.c
+++ b/src/event-plugin.c
@@ -497,7 +497,7 @@ load_plugin(struct tep_handle *tep, const char *path,
 	list->name = plugin;
 	*plugin_list = list;
 
-	pr_stat("registering plugin: %s", plugin);
+	tep_info("registering plugin: %s", plugin);
 	func(tep);
 	return;
 
diff --git a/src/event-utils.h b/src/event-utils.h
index ff4d6c4..1951557 100644
--- a/src/event-utils.h
+++ b/src/event-utils.h
@@ -9,15 +9,10 @@
 #include <ctype.h>
 #include <stdarg.h>
 
+void tep_info(const char *fmt, ...);
 /* Can be overridden */
 void tep_warning(const char *fmt, ...);
 int tep_vwarning(const char *name, const char *fmt, va_list ap);
-void pr_stat(const char *fmt, ...);
-void vpr_stat(const char *fmt, va_list ap);
-
-/* Always available */
-void __pr_stat(const char *fmt, ...);
-void __vpr_stat(const char *fmt, ...);
 
 #define min(x, y) ({				\
 	typeof(x) _min1 = (x);			\
diff --git a/src/parse-utils.c b/src/parse-utils.c
index bc89c44..b997823 100644
--- a/src/parse-utils.c
+++ b/src/parse-utils.c
@@ -50,31 +50,15 @@ void __weak tep_warning(const char *fmt, ...)
 	va_end(ap);
 }
 
-void __vpr_stat(const char *fmt, va_list ap)
-{
-	vprintf(fmt, ap);
-	printf("\n");
-}
 
-void __pr_stat(const char *fmt, ...)
+void tep_info(const char *fmt, ...)
 {
 	va_list ap;
 
-	va_start(ap, fmt);
-	__vpr_stat(fmt, ap);
-	va_end(ap);
-}
-
-void __weak vpr_stat(const char *fmt, va_list ap)
-{
-	__vpr_stat(fmt, ap);
-}
-
-void __weak pr_stat(const char *fmt, ...)
-{
-	va_list ap;
+	if (log_level < TEP_LOG_INFO)
+		return;
 
 	va_start(ap, fmt);
-	__vpr_stat(fmt, ap);
+	tep_vwarning("libtraceevent", fmt, ap);
 	va_end(ap);
 }
-- 
2.30.2

Re: [PATCH 2/4] libtraceevent: Add logs with severity info

[Steven Rostedt]

On Wed, 28 Apr 2021 10:29:59 +0300
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> Renamed existing pr_stat() internal function to tep_info() and limit it

Unfortunately they are also not internal functions :-(

> to print only when the log level is TEP_LOG_INFO. Removed duplicated and
> unused functions:
>  vpr_stat()
>  __pr_stat()
>  __vpr_stat()

trace-record.c: In function ‘expand_event_files’:
trace-record.c:2971:3: warning: implicit declaration of function ‘pr_stat’; did you mean ‘lstat’? [-Wimplicit-function-declaration]
 2971 |   pr_stat("%s\n", path);
      |   ^~~~~~~
      |   lstat


ctracecmd_wrap.c: In function ‘pr_stat’:
ctracecmd_wrap.c:2779:2: warning: implicit declaration of function ‘__vpr_stat’; did you mean ‘pr_stat’? [-Wimplicit-function-declaration]
 2779 |  __vpr_stat(fmt, ap);
      |  ^~~~~~~~~~
      |  pr_stat


-- Steve

Re: [PATCH 2/4] libtraceevent: Add logs with severity info

[Steven Rostedt]

On Tue, 4 May 2021 16:00:08 -0400
Steven Rostedt <rostedt@goodmis.org> wrote:

> > Renamed existing pr_stat() internal function to tep_info() and limit it  
> 
> Unfortunately they are also not internal functions :-(
> 
> > to print only when the log level is TEP_LOG_INFO. Removed duplicated and
> > unused functions:
> >  vpr_stat()
> >  __pr_stat()
> >  __vpr_stat()  
> 
> trace-record.c: In function ‘expand_event_files’:
> trace-record.c:2971:3: warning: implicit declaration of function ‘pr_stat’; did you mean ‘lstat’? [-Wimplicit-function-declaration]
>  2971 |   pr_stat("%s\n", path);
>       |   ^~~~~~~
>       |   lstat
> 
> 
> ctracecmd_wrap.c: In function ‘pr_stat’:
> ctracecmd_wrap.c:2779:2: warning: implicit declaration of function ‘__vpr_stat’; did you mean ‘pr_stat’? [-Wimplicit-function-declaration]
>  2779 |  __vpr_stat(fmt, ap);
>       |  ^~~~~~~~~~
>       |  pr_stat

So I added another patch to bring these back for backward compatibility.
Feel free to remove them in this series, and I'll just add that patch at
the end:

  https://lore.kernel.org/linux-trace-devel/20210504163156.2bfdd63d@gandalf.local.home/

But as I still have issues with this patch series and will wait for your
reply before applying anything.

Thanks,

-- Steve

Re: [PATCH 2/4] libtraceevent: Add logs with severity info

[Steven Rostedt]

On Wed, 28 Apr 2021 10:29:59 +0300
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

>  void tep_info(const char *fmt, ...)
>  {
>  	va_list ap;
>  
>	if (log_level < TEP_LOG_INFO)
>		return;
>  
>  	va_start(ap, fmt);
>	tep_vprint("libtraceevent", TEP_LOG_INFO fmt, ap);
>  	va_end(ap);
>  }

The above should just be:

void tep_info(const char *fmt, ...)
{
	va_list ap;

 	va_start(ap, fmt);
	tep_vprint("libtraceevent", TEP_LOG_INFO fmt, ap);
 	va_end(ap);
}

And let the tep_vprint() decide to print it or not.

-- Steve

Re: [PATCH 2/4] libtraceevent: Add logs with severity info

[Tzvetomir Stoyanov]

On Tue, May 4, 2021 at 11:24 PM Steven Rostedt <rostedt@goodmis.org> wrote:
>
> On Wed, 28 Apr 2021 10:29:59 +0300
> "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
>
> >  void tep_info(const char *fmt, ...)
> >  {
> >       va_list ap;
> >
> >       if (log_level < TEP_LOG_INFO)
> >               return;
> >
> >       va_start(ap, fmt);
> >       tep_vprint("libtraceevent", TEP_LOG_INFO fmt, ap);
> >       va_end(ap);
> >  }
>
> The above should just be:
>
> void tep_info(const char *fmt, ...)
> {
>         va_list ap;
>
>         va_start(ap, fmt);
>         tep_vprint("libtraceevent", TEP_LOG_INFO fmt, ap);
>         va_end(ap);
> }
>
> And let the tep_vprint() decide to print it or not.

The tep_vprint() is used also by libtacecmd and libtracefs for
printing logs. Each library has its own log_level local variable,
that's why I check the log level in the library specific log
functions.

>
> -- Steve



-- 
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center

Re: [PATCH 2/4] libtraceevent: Add logs with severity info

[Steven Rostedt]

On Wed, 5 May 2021 07:45:44 +0300
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:

> On Tue, May 4, 2021 at 11:24 PM Steven Rostedt <rostedt@goodmis.org> wrote:
> >
> > On Wed, 28 Apr 2021 10:29:59 +0300
> > "Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
> >
> > And let the tep_vprint() decide to print it or not.  
> 
> The tep_vprint() is used also by libtacecmd and libtracefs for
> printing logs. Each library has its own log_level local variable,
> that's why I check the log level in the library specific log
> functions.

But tep_vprint() looks like this:

int __weak tep_vprint(const char *name, enum tep_loglevel level, const char *fmt, va_list ap)
{
        int ret = errno;

        if (errno && level <= TEP_LOG_WARNING)
                perror(name);

        fprintf(stderr, "  ");
        vfprintf(stderr, fmt, ap);
        fprintf(stderr, "\n");

        return ret;
}

That check of the log level is confusing. Just remove it. In fact, we
should add a boolean on whether to print the errno message or not.

Like this:

int __weak tep_vprint(const char *name, bool print_errno, const char *fmt, va_list ap)
{
        int ret = errno;

        if (errno && print_errno)
                perror(name);

        fprintf(stderr, "  ");
        vfprintf(stderr, fmt, ap);
        fprintf(stderr, "\n");

        return ret;
}

That would make a lot more sense, and let the callers of it decide to
print it or not, and not have the internal level of libtraceevent
decide.

-- Steve

[PATCH 3/4] libtraceevent: Rename tep_vwarning() to tep_vprint()

[Tzvetomir Stoyanov (VMware)]

Renamed the existing weak function tep_vwarning() to tep_vprint(), to
match its purpose. This function is used to print library logs with any
log severity, not only warnings.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 src/event-utils.h |  4 ++--
 src/parse-utils.c | 10 +++++-----
 2 files changed, 7 insertions(+), 7 deletions(-)

diff --git a/src/event-utils.h b/src/event-utils.h
index 1951557..0e09838 100644
--- a/src/event-utils.h
+++ b/src/event-utils.h
@@ -9,10 +9,10 @@
 #include <ctype.h>
 #include <stdarg.h>
 
+void tep_warning(const char *fmt, ...);
 void tep_info(const char *fmt, ...);
 /* Can be overridden */
-void tep_warning(const char *fmt, ...);
-int tep_vwarning(const char *name, const char *fmt, va_list ap);
+int tep_vprint(const char *name, enum tep_loglevel level, const char *fmt, va_list ap);
 
 #define min(x, y) ({				\
 	typeof(x) _min1 = (x);			\
diff --git a/src/parse-utils.c b/src/parse-utils.c
index b997823..b4e95b7 100644
--- a/src/parse-utils.c
+++ b/src/parse-utils.c
@@ -24,11 +24,11 @@ void tep_set_loglevel(enum tep_loglevel level)
 	log_level = level;
 }
 
-int __weak tep_vwarning(const char *name, const char *fmt, va_list ap)
+int __weak tep_vprint(const char *name, enum tep_loglevel level, const char *fmt, va_list ap)
 {
 	int ret = errno;
 
-	if (errno)
+	if (errno && level <= TEP_LOG_WARNING)
 		perror(name);
 
 	fprintf(stderr, "  ");
@@ -38,7 +38,7 @@ int __weak tep_vwarning(const char *name, const char *fmt, va_list ap)
 	return ret;
 }
 
-void __weak tep_warning(const char *fmt, ...)
+void tep_warning(const char *fmt, ...)
 {
 	va_list ap;
 
@@ -46,7 +46,7 @@ void __weak tep_warning(const char *fmt, ...)
 		return;
 
 	va_start(ap, fmt);
-	tep_vwarning("libtraceevent", fmt, ap);
+	tep_vprint("libtraceevent", TEP_LOG_WARNING, fmt, ap);
 	va_end(ap);
 }
 
@@ -59,6 +59,6 @@ void tep_info(const char *fmt, ...)
 		return;
 
 	va_start(ap, fmt);
-	tep_vwarning("libtraceevent", fmt, ap);
+	tep_vprint("libtraceevent", TEP_LOG_INFO, fmt, ap);
 	va_end(ap);
 }
-- 
2.30.2

Re: [PATCH 3/4] libtraceevent: Rename tep_vwarning() to tep_vprint()

[Steven Rostedt]

On Wed, 28 Apr 2021 10:30:00 +0300
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:

> @@ -24,11 +24,11 @@ void tep_set_loglevel(enum tep_loglevel level)
>  	log_level = level;
>  }
>  
> -int __weak tep_vwarning(const char *name, const char *fmt, va_list ap)
> +int __weak tep_vprint(const char *name, enum tep_loglevel level, const char *fmt, va_list ap)
>  {
>  	int ret = errno;
>  
> -	if (errno)
> +	if (errno && level <= TEP_LOG_WARNING)
>  		perror(name);
>  
>  	fprintf(stderr, "  ");

If this is passing in a log level, why not just have:

	if (level < loglevel)
		return 0;

?

-- Steve

[PATCH 4/4] libtraceevent: Document new log functionality

[Tzvetomir Stoyanov (VMware)]

Updated man pages with the new log API and log levels.

Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
 Documentation/libtraceevent-log.txt | 90 +++++++++++++++++++++++++++++
 Documentation/libtraceevent.txt     |  3 +
 2 files changed, 93 insertions(+)
 create mode 100644 Documentation/libtraceevent-log.txt

diff --git a/Documentation/libtraceevent-log.txt b/Documentation/libtraceevent-log.txt
new file mode 100644
index 0000000..0aee21d
--- /dev/null
+++ b/Documentation/libtraceevent-log.txt
@@ -0,0 +1,90 @@
+libtraceevent(3)
+================
+
+NAME
+----
+tep_set_loglevel - Set log level of the library
+
+SYNOPSIS
+--------
+[verse]
+--
+*#include <event-parse.h>*
+
+enum *tep_loglevel* {
+	TEP_LOG_NONE = 0,
+	TEP_LOG_CRITICAL,
+	TEP_LOG_ERROR,
+	TEP_LOG_WARNING,
+	TEP_LOG_INFO,
+	TEP_LOG_DEBUG,
+	TEP_LOG_ALL
+};
+
+int *tep_set_loglevel*(enum tep_loglevel _level_);
+
+--
+DESCRIPTION
+-----------
+The _tep_set_loglevel()_ function sets the level of the library logs that will be printed
+on the console. Library log levels are:
+[verse]
+--
+	_TEP_LOG_NONE_ - Do not print any logs.
+	_TEP_LOG_CRITICAL_ - Print critical logs, problem that may case a crash.
+	_TEP_LOG_ERROR_ - Print error logs, problem that could break the main logic of an API.
+	_TEP_LOG_WARNING_ - Print warnings, problem that could limit the result of an API.
+	_TEP_LOG_INFO_ - Print information about normal execution of an API.
+	_TEP_LOG_DEBUG_ - Print debug information.
+	_TEP_LOG_ALL_ - Print logs from all levels.
+--
+Setting the log level to specific value means that logs from the previous levels will be printed
+too. For example _TEP_LOG_WARNING_ will print any logs with severity _TEP_LOG_WARNING_,
+_TEP_LOG_ERROR_ and _TEP_LOG_CRITICAL_. The default log level is _TEP_LOG_CRITICAL_.
+
+
+EXAMPLE
+-------
+[source,c]
+--
+#include <event-parse.h>
+
+tep_set_loglevel(TEP_LOG_ALL);
+...
+/* call libtraceevent APIs and observe any logs they produce */
+...
+tep_set_loglevel(TEP_LOG_CRITICAL);
+--
+
+FILES
+-----
+[verse]
+--
+*event-parse.h*
+	Header file to include in order to have access to the library APIs.
+*-ltraceevent*
+	Linker switch to add when building a program that uses the library.
+--
+
+SEE ALSO
+--------
+_libtraceevent(3)_, _trace-cmd(1)_
+
+AUTHOR
+------
+[verse]
+--
+*Steven Rostedt* <rostedt@goodmis.org>, author of *libtraceevent*.
+*Tzvetomir Stoyanov* <tz.stoyanov@gmail.com>, author of this man page.
+--
+REPORTING BUGS
+--------------
+Report bugs to  <linux-trace-devel@vger.kernel.org>
+
+LICENSE
+-------
+libtraceevent is Free Software licensed under the GNU LGPL 2.1
+
+RESOURCES
+---------
+https://git.kernel.org/pub/scm/libs/libtrace/libtraceevent.git/
diff --git a/Documentation/libtraceevent.txt b/Documentation/libtraceevent.txt
index 3365455..d42b5c9 100644
--- a/Documentation/libtraceevent.txt
+++ b/Documentation/libtraceevent.txt
@@ -127,6 +127,9 @@ Endian related APIs:
 	bool *tep_is_local_bigendian*(struct tep_handle pass:[*]_tep_);
 	void *tep_set_local_bigendian*(struct tep_handle pass:[*]_tep_, enum tep_endian _endian_);
 
+Control library logs:
+	int *tep_set_loglevel*(enum tep_loglevel _level_);
+
 Trace sequences:
 *#include <trace-seq.h>*
 	void *trace_seq_init*(struct trace_seq pass:[*]_s_);
-- 
2.30.2