[libcamera-devel] libcamera: log: add colors to log levels

12198 diff mbox series

Add colored logs if the output belongs to a terminal. This makes it easier
to identitify warnings and/or errors.

Signed-off-by: Marco Felsch <m.felsch@pengutronix.de>
---
Hi all,

this is an reworked version of [1]. I used by sob and auther since I did
more changes than I kept from [1].

[1] 20210203181746.22028-1-m.cichy@pengutronix.de

 src/libcamera/log.cpp | 28 ++++++++++++++++++++++++++++
 1 file changed, 28 insertions(+)

Hi Marco,

Thank you for the patch.

On Wed, May 05, 2021 at 05:33:18PM +0200, Marco Felsch wrote:
> Add colored logs if the output belongs to a terminal. This makes it easier
> to identitify warnings and/or errors.
> 
> Signed-off-by: Marco Felsch <m.felsch@pengutronix.de>
> ---
> Hi all,
> 
> this is an reworked version of [1]. I used by sob and auther since I did
> more changes than I kept from [1].
> 
> [1] 20210203181746.22028-1-m.cichy@pengutronix.de
> 
>  src/libcamera/log.cpp | 28 ++++++++++++++++++++++++++++
>  1 file changed, 28 insertions(+)
> 
> diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> index 94175ab3..3dffd004 100644
> --- a/src/libcamera/log.cpp
> +++ b/src/libcamera/log.cpp
> @@ -19,6 +19,7 @@
>  #include <string.h>
>  #include <syslog.h>
>  #include <time.h>
> +#include <unistd.h>
>  #include <unordered_set>
>  
>  #include <libcamera/logging.h>
> @@ -98,6 +99,26 @@ static const char *log_severity_name(LogSeverity severity)
>  		return "UNKWN";
>  }
>  
> +static const char *log_severity_color_name(LogSeverity severity)
> +{
> +	static const char *const names[] = {
> +		"\033[1m\033[37mDEBUG\033[0m",
> +		"\033[1m\033[32m INFO\033[0m",
> +		"\033[1m\033[33m WARN\033[0m",
> +		"\033[1m\033[31mERROR\033[0m",
> +		"\033[1m\033[35mFATAL\033[0m",
> +	};
> +
> +	/* Only print colored output if output really belongs to a terminal */
> +	if (!isatty(fileno(stderr)))

What is the stream that the logger logs to isn't stderr ?

> +		return log_severity_name(severity);
> +
> +	if (static_cast<unsigned int>(severity) < std::size(names))
> +		return names[severity];
> +	else
> +		return "\033[1m\033[32mUNKWN\033[0m";
> +}
> +
>  /**
>   * \brief Log output
>   *
> @@ -197,6 +218,13 @@ void LogOutput::write(const LogMessage &msg)
>  		writeSyslog(msg.severity(), str);
>  		break;
>  	case LoggingTargetStream:
> +		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> +		    + std::to_string(Thread::currentId()) + "] "
> +		    + log_severity_color_name(msg.severity()) + " "
> +		    + msg.category().name() + " " + msg.fileInfo() + " "
> +		    + msg.msg();
> +		writeStream(str);
> +		break;
>  	case LoggingTargetFile:
>  		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
>  		    + std::to_string(Thread::currentId()) + "] "

On 21-05-05 18:37, Laurent Pinchart wrote:
> Hi Marco,
> 
> Thank you for the patch.
> 
> On Wed, May 05, 2021 at 05:33:18PM +0200, Marco Felsch wrote:
> > Add colored logs if the output belongs to a terminal. This makes it easier
> > to identitify warnings and/or errors.
> > 
> > Signed-off-by: Marco Felsch <m.felsch@pengutronix.de>
> > ---
> > Hi all,
> > 
> > this is an reworked version of [1]. I used by sob and auther since I did
> > more changes than I kept from [1].
> > 
> > [1] 20210203181746.22028-1-m.cichy@pengutronix.de
> > 
> >  src/libcamera/log.cpp | 28 ++++++++++++++++++++++++++++
> >  1 file changed, 28 insertions(+)
> > 
> > diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> > index 94175ab3..3dffd004 100644
> > --- a/src/libcamera/log.cpp
> > +++ b/src/libcamera/log.cpp
> > @@ -19,6 +19,7 @@
> >  #include <string.h>
> >  #include <syslog.h>
> >  #include <time.h>
> > +#include <unistd.h>
> >  #include <unordered_set>
> >  
> >  #include <libcamera/logging.h>
> > @@ -98,6 +99,26 @@ static const char *log_severity_name(LogSeverity severity)
> >  		return "UNKWN";
> >  }
> >  
> > +static const char *log_severity_color_name(LogSeverity severity)
> > +{
> > +	static const char *const names[] = {
> > +		"\033[1m\033[37mDEBUG\033[0m",
> > +		"\033[1m\033[32m INFO\033[0m",
> > +		"\033[1m\033[33m WARN\033[0m",
> > +		"\033[1m\033[31mERROR\033[0m",
> > +		"\033[1m\033[35mFATAL\033[0m",
> > +	};
> > +
> > +	/* Only print colored output if output really belongs to a terminal */
> > +	if (!isatty(fileno(stderr)))
> 
> What is the stream that the logger logs to isn't stderr ?

Hi Laurent,

According Logger::parseLogFile this can't be the case.

Regards,
  Marco

> 
> > +		return log_severity_name(severity);
> > +
> > +	if (static_cast<unsigned int>(severity) < std::size(names))
> > +		return names[severity];
> > +	else
> > +		return "\033[1m\033[32mUNKWN\033[0m";
> > +}
> > +
> >  /**
> >   * \brief Log output
> >   *
> > @@ -197,6 +218,13 @@ void LogOutput::write(const LogMessage &msg)
> >  		writeSyslog(msg.severity(), str);
> >  		break;
> >  	case LoggingTargetStream:
> > +		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> > +		    + std::to_string(Thread::currentId()) + "] "
> > +		    + log_severity_color_name(msg.severity()) + " "
> > +		    + msg.category().name() + " " + msg.fileInfo() + " "
> > +		    + msg.msg();
> > +		writeStream(str);
> > +		break;
> >  	case LoggingTargetFile:
> >  		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> >  		    + std::to_string(Thread::currentId()) + "] "
> 
> -- 
> Regards,
> 
> Laurent Pinchart
>

Hi Marco,

On 05/05/2021 16:33, Marco Felsch wrote:
> Add colored logs if the output belongs to a terminal. This makes it easier
> to identitify warnings and/or errors.
> 
> Signed-off-by: Marco Felsch <m.felsch@pengutronix.de>
> ---
> Hi all,
> 
> this is an reworked version of [1]. I used by sob and auther since I did
> more changes than I kept from [1].
> 
> [1] 20210203181746.22028-1-m.cichy@pengutronix.de

Personally, I'm very pleased to see this being worked on. It's a small
touch but it really does help ease the eyes when trying to follow the logs.

I've carried a cherry-pick of [1] on some of my branches for exactly
that reason.



> 
>  src/libcamera/log.cpp | 28 ++++++++++++++++++++++++++++
>  1 file changed, 28 insertions(+)
> 
> diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> index 94175ab3..3dffd004 100644
> --- a/src/libcamera/log.cpp
> +++ b/src/libcamera/log.cpp
> @@ -19,6 +19,7 @@
>  #include <string.h>
>  #include <syslog.h>
>  #include <time.h>
> +#include <unistd.h>
>  #include <unordered_set>
>  
>  #include <libcamera/logging.h>
> @@ -98,6 +99,26 @@ static const char *log_severity_name(LogSeverity severity)
>  		return "UNKWN";
>  }
>  
> +static const char *log_severity_color_name(LogSeverity severity)
> +{
> +	static const char *const names[] = {
> +		"\033[1m\033[37mDEBUG\033[0m",
> +		"\033[1m\033[32m INFO\033[0m",
> +		"\033[1m\033[33m WARN\033[0m",
> +		"\033[1m\033[31mERROR\033[0m",
> +		"\033[1m\033[35mFATAL\033[0m",
> +	};

I find this quite ... painful to read?

We're duplicating the names from log_severity_name, and we're hardcoding
the ansi tty colours inline which are ... well quite unreadable (to an
untrained eye).

At the very least those escape codes should be defined out to named
types in my opinion

#define TTY_CLEAR "\033[0m"
or
COLOUR(BLUE).

A helper function might be useful, as then it could always return ""
instead of the colour in a single place if the colour was disabled, but
that's not helpful for the const chars :-(

At least a simple macro could potentially make this:

+	static const char *const names[] = {
+		COLOUR(GREEN)  "DEBUG" TTY_CLEAR(),
+		COLOUR(BLACK)  " INFO" TTY_CLEAR(),
+		COLOUR(YELLOW) " WARN" TTY_CLEAR(),
+		COLOUR(BLUE)   "ERROR" TTY_CLEAR(),
+		COLOUR(RED)    "FATAL" TTY_CLEAR(),
+	};

if the helper function isn't possible.


> +
> +	/* Only print colored output if output really belongs to a terminal */
> +	if (!isatty(fileno(stderr)))
> +		return log_severity_name(severity);
> +
> +	if (static_cast<unsigned int>(severity) < std::size(names))
> +		return names[severity];
> +	else
> +		return "\033[1m\033[32mUNKWN\033[0m";
> +}
> +
>  /**
>   * \brief Log output
>   *
> @@ -197,6 +218,13 @@ void LogOutput::write(const LogMessage &msg)
>  		writeSyslog(msg.severity(), str);
>  		break;
>  	case LoggingTargetStream:
> +		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> +		    + std::to_string(Thread::currentId()) + "] "
> +		    + log_severity_color_name(msg.severity()) + " "
> +		    + msg.category().name() + " " + msg.fileInfo() + " "
> +		    + msg.msg();
> +		writeStream(str);
> +		break;
>  	case LoggingTargetFile:
>  		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
>  		    + std::to_string(Thread::currentId()) + "] "
>

Hi Marco,

On Wed, May 05, 2021 at 05:44:44PM +0200, Marco Felsch wrote:
> On 21-05-05 18:37, Laurent Pinchart wrote:
> > On Wed, May 05, 2021 at 05:33:18PM +0200, Marco Felsch wrote:
> > > Add colored logs if the output belongs to a terminal. This makes it easier
> > > to identitify warnings and/or errors.
> > > 
> > > Signed-off-by: Marco Felsch <m.felsch@pengutronix.de>
> > > ---
> > > Hi all,
> > > 
> > > this is an reworked version of [1]. I used by sob and auther since I did
> > > more changes than I kept from [1].
> > > 
> > > [1] 20210203181746.22028-1-m.cichy@pengutronix.de
> > > 
> > >  src/libcamera/log.cpp | 28 ++++++++++++++++++++++++++++
> > >  1 file changed, 28 insertions(+)
> > > 
> > > diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> > > index 94175ab3..3dffd004 100644
> > > --- a/src/libcamera/log.cpp
> > > +++ b/src/libcamera/log.cpp
> > > @@ -19,6 +19,7 @@
> > >  #include <string.h>
> > >  #include <syslog.h>
> > >  #include <time.h>
> > > +#include <unistd.h>
> > >  #include <unordered_set>
> > >  
> > >  #include <libcamera/logging.h>
> > > @@ -98,6 +99,26 @@ static const char *log_severity_name(LogSeverity severity)
> > >  		return "UNKWN";
> > >  }
> > >  
> > > +static const char *log_severity_color_name(LogSeverity severity)
> > > +{
> > > +	static const char *const names[] = {
> > > +		"\033[1m\033[37mDEBUG\033[0m",
> > > +		"\033[1m\033[32m INFO\033[0m",
> > > +		"\033[1m\033[33m WARN\033[0m",
> > > +		"\033[1m\033[31mERROR\033[0m",
> > > +		"\033[1m\033[35mFATAL\033[0m",
> > > +	};
> > > +
> > > +	/* Only print colored output if output really belongs to a terminal */
> > > +	if (!isatty(fileno(stderr)))
> > 
> > What is the stream that the logger logs to isn't stderr ?
> 
> Hi Laurent,
> 
> According Logger::parseLogFile this can't be the case.

But we also have Logger::logSetStream(), which can be used by
applications to redirect the log output to a custom stream. It gets
called by the global logSetStream() function (declared in the public
include/libcamera/logging.h header).

> > > +		return log_severity_name(severity);
> > > +
> > > +	if (static_cast<unsigned int>(severity) < std::size(names))
> > > +		return names[severity];
> > > +	else
> > > +		return "\033[1m\033[32mUNKWN\033[0m";
> > > +}
> > > +
> > >  /**
> > >   * \brief Log output
> > >   *
> > > @@ -197,6 +218,13 @@ void LogOutput::write(const LogMessage &msg)
> > >  		writeSyslog(msg.severity(), str);
> > >  		break;
> > >  	case LoggingTargetStream:
> > > +		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> > > +		    + std::to_string(Thread::currentId()) + "] "
> > > +		    + log_severity_color_name(msg.severity()) + " "
> > > +		    + msg.category().name() + " " + msg.fileInfo() + " "
> > > +		    + msg.msg();
> > > +		writeStream(str);
> > > +		break;
> > >  	case LoggingTargetFile:
> > >  		str = "[" + utils::time_point_to_string(msg.timestamp()) + "] ["
> > >  		    + std::to_string(Thread::currentId()) + "] "