[libcamera-devel] [PATCH 2/3] libcamera: Add initial logger

[Laurent Pinchart]

Hi Jacopo,

On Thursday, 6 December 2018 19:11:06 EET jacopo mondi wrote:
> Hi Laurent,
>    thanks for the patches
> 
> On Wed, Dec 05, 2018 at 12:11:22AM +0200, Laurent Pinchart wrote:
> > The logger is based on the ostream API, allowing code to log messages in
> > a native way. It automatically logs the time stamp, severity level, file
> > name and line number.
> > 
> > Many important features are missing, such as logging to file, logging
> > classes, and log filtering based on the severity level, file name and
> > class.
> 
> How do you expect to control filtering? Should we use a library-wide
> tag list to match on, which could be controlled through environment
> variables? (such as GST_DEBUG is?)

I'm thinking about an environment variable indeed, likely with an API for 
application to control logging manually.

> In such a case, I wonder if it wouldn't be worth subclassing
> osstringstream and provide an overriden str() method that does the
> filtering before calling the base class str() ?

I was thinking about implementing the filtering in the LogMessage destructor.

> > Signed-off-by: Laurent Pinchart <laurent.pinchart at ideasonboard.com>
> > ---
> > 
> >  src/libcamera/include/.keep_empty |  0
> 
> ?

The file is deleted as the directory isn't empty anymore.

> >  src/libcamera/include/log.h       | 38 +++++++++++++++
> >  src/libcamera/include/utils.h     | 12 +++++
> >  src/libcamera/log.cpp             | 81 +++++++++++++++++++++++++++++++
> >  src/libcamera/meson.build         |  5 +-
> >  5 files changed, 135 insertions(+), 1 deletion(-)
> >  delete mode 100644 src/libcamera/include/.keep_empty
> >  create mode 100644 src/libcamera/include/log.h
> >  create mode 100644 src/libcamera/include/utils.h
> >  create mode 100644 src/libcamera/log.cpp
> > 
> > diff --git a/src/libcamera/include/.keep_empty
> > b/src/libcamera/include/.keep_empty deleted file mode 100644
> > index e69de29bb2d1..000000000000
> > diff --git a/src/libcamera/include/log.h b/src/libcamera/include/log.h
> > new file mode 100644
> > index 000000000000..76acd1520868
> > --- /dev/null
> > +++ b/src/libcamera/include/log.h
> > @@ -0,0 +1,38 @@
> > +/* SPDX-License-Identifier: LGPL-2.1-or-later */
> > +/*
> > + * Copyright (C) 2018, Google Inc.
> > + *
> > + * log.h - Logging infrastructure
> > + */
> > +#ifndef __LIBCAMERA_LOG_H__
> > +#define __LIBCAMERA_LOG_H__
> > +
> > +#include <sstream>
> > +
> > +namespace libcamera {
> > +
> > +enum LogSeverity {
> > +	LogInfo,
> > +	LogWarning,
> > +	LogError,
> > +};
> > +
> > +class LogMessage
> > +{
> > +public:
> > +	LogMessage(const char *fileName, unsigned int line,
> > +		  LogSeverity severity);
> > +	LogMessage(const LogMessage&) = delete;
> > +	~LogMessage();
> > +
> > +	std::ostream& stream() { return msgStream; }
> > +
> > +private:
> > +	std::ostringstream msgStream;
> > +};
> > +
> > +#define LOG(severity) LogMessage(__FILE__, __LINE__,
> > Log##severity).stream()
> > +
> 
> So, each call to LOG will instantiate a new 'LogMessage' instance, I
> wonder if it wouldn't be better to have a log object global to the library
> instead... I'm sure you have considerate that though..

I have :-) I actually have started with such an object, and then modified the 
design as it didn't really fit.

The core idea of this API is to define macros that will provide an ostream, to 
allow logging using the C++ stream API. The stream must be used on the stop, 
and the message must be flushed to the log backend automatically. Starting 
with a Logger class that would contain an ostream, there was no easy way to 
implement automatic flushing easily. That's why I decided to create a 
LogMessage class that would be instantiated for every LOG() call. The instance 
is temporary only, and serves as a wrapper around the ostream it contains. As 
the instance is destroyed immediately after being used, the destructor serves 
as a convenient way to flush the log message.

> > +};
> > +
> > +#endif /* __LIBCAMERA_LOG_H__ */
> > diff --git a/src/libcamera/include/utils.h b/src/libcamera/include/utils.h
> > new file mode 100644
> > index 000000000000..3ffa6f4ea591
> > --- /dev/null
> > +++ b/src/libcamera/include/utils.h
> > @@ -0,0 +1,12 @@
> > +/* SPDX-License-Identifier: LGPL-2.1-or-later */
> > +/*
> > + * Copyright (C) 2018, Google Inc.
> > + *
> > + * utils.h - Miscellaneous utility functions
> > + */
> > +#ifndef __LIBCAMERA_UTILS_H__
> > +#define __LIBCAMERA_UTILS_H__
> > +
> > +#define ARRAY_SIZE(a)	(sizeof(a) / sizeof(a[0]))
> > +
> > +#endif /* __LIBCAMERA_UTILS_H__ */
> > diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> > new file mode 100644
> > index 000000000000..18ccfa32d8b4
> > --- /dev/null
> > +++ b/src/libcamera/log.cpp
> > @@ -0,0 +1,81 @@
> > +/* SPDX-License-Identifier: LGPL-2.1-or-later */
> > +/*
> > + * Copyright (C) 2018, Google Inc.
> > + *
> > + * log.h - Logging infrastructure
> 
> That's log.ccp :)

Or even log.cpp. I'll fix that.

> 
> > + */
> > +
> 
> nit: in other files you don't have an empty line here

I found an empty line here in .cpp files easier to read, but that's not a big 
deal, we can remove it if you think that's better. Or add an empty line in .h 
files.

> > +#include <cstdio>
> > +#include <ctime>
> > +#include <iomanip>
> > +#include <string.h>
> > +
> > +#include "log.h"
> > +#include "utils.h"
> > +
> > +/**
> > + * \file log.h
> 
> ditto

Will fix too.

> > + * \brief Logging infrastructure
> > + */
> > +
> > +namespace libcamera {
> > +
> > +/**
> > + * \enum LogSeverity
> > + * Log message severity
> > + * \var Info
> > + * Informational message
> > + * \var Warning
> > + * Warning message, signals a potential issue
> > + * \var Error
> > + * Error message, signals an unrecoverable issue
> > + */
> 
> Should we document types, enums etc in the cpp file, even if the
> definition is in the header file ?

I think so. Documentation in the .h file makes the header harder to read if 
you want to get an overview of the API. Beside, I think we should be 
consistent and document everything in the .h file or the .cpp file, and as 
most of the documentation should relate (for most classes) to member functions 
that we decided to document in the .cpp file, let's document everything there.

> > +
> > +/**
> > + * \def LOG(severity)
> > + * \brief Log a message
> > + *
> > + * Return an std::ostream reference to which a message can be logged
> > using the
> 
> nit: ostringstream

        std::ostream& stream() { return msgStream; }

It's an std::ostream. The fact that the returned ostream is an ostringstream 
is an implementation detail.

> > + * iostream API. The \a severity controls whether the message is printed
> > or
> > + * dropped, depending on the global log level.
> > + */
> 
> Same question: the macro is defined in the .h file. Documentation is
> useful once it gets generated, for sure, but shall be useful when
> you're only looking at the source code.

Same answer :-)

> > +
> > +static const char *log_severity_name(LogSeverity severity)
> > +{
> > +	static const char * const names[] = {
> > +		"INFO",
> > +		"WARN",
> > +		" ERR",
> 
>                  ^ space
> 
> Or is this intentional to have "ERR" messages stand out ?

It's not to make them stand out, but to align all messages the same way. I 
could put the space after ERR if you prefer :-)

> > +	};
> > +
> > +	if ((unsigned int)severity < ARRAY_SIZE(names))
> 
> Plain old style C cast. I'm fine with that, this is very simple, but
> c++ style static_cast<> might be more appropriate

Good point. The cast might actually not be needed, as g++ converts severity to 
an integer type. I haven't been able to find a guarantee in the C++ 
specification that the integer would be unsigned though, so I'll use a 
static_cast<>.

> > +		return names[severity];
> > +	else
> > +		return "UNKN";
> > +}
> > +
> > +LogMessage::LogMessage(const char *fileName, unsigned int line,
> > +		       LogSeverity severity)
> > +{
> > +	/* Log the timestamp, severity and file information. */
> > +	struct timespec timestamp;
> 
> What about an empty line between variable declaration and code?

You won't like this, but in C++ the functions aren't split anymore between 
variables and code. Variables get declared along with the code that uses them. 
I don't want to push that rule too far though, as it sometimes hinder 
readability, but in this case I think it is fine.

> > +	clock_gettime(CLOCK_MONOTONIC, &timestamp);
> > +	msgStream << "[" << timestamp.tv_sec / (60 * 60) << ":"
> > +		  << std::setw(2) << (timestamp.tv_sec / 60) % 60 << ":"
> > +		  << std::setw(2) << timestamp.tv_sec % 60 << "."
> > +		  << std::setw(9) << timestamp.tv_nsec << "]";
> > +
> > +	msgStream << " " << log_severity_name(severity);
> > +	msgStream << " " << basename(fileName) << ":" << line << " ";
> > +}
> > +
> > +LogMessage::~LogMessage()
> > +{
> > +	msgStream << std::endl;
> > +
> > +	std::string msg(msgStream.str());
> > +	fwrite(msg.data(), msg.size(), 1, stderr);
> > +	fflush(stderr);
> > +}
> > +
> > +};
> 
> /* namespace libcamera */

Will fix (and in log.h too), and will remove the ; after the } as it's not 
required.

> > diff --git a/src/libcamera/meson.build b/src/libcamera/meson.build
> > index 07d9cd448342..fe38f8b2b5b4 100644
> > --- a/src/libcamera/meson.build
> > +++ b/src/libcamera/meson.build
> > @@ -1,4 +1,7 @@
> > -sources = ['main.cpp']
> > +sources = files([
> > +    'log.cpp',
> > +    'main.cpp',
> > +])
> > 
> >  includes = [
> >      libcamera_includes,

-- 
Regards,

Laurent Pinchart