[libcamera-devel] [PATCH] libcamera: Print backtrace on fatal errors

[Laurent Pinchart]

Hi Kieran,

On Mon, Nov 25, 2019 at 10:57:53AM +0000, Kieran Bingham wrote:
> On 23/11/2019 12:43, Laurent Pinchart wrote:
> > When a fatal error occurs the program aborts, and all the logger
> > provides is the location of the line that caused the error. Extend this
> > with a full backtrace to help debugging.
> > 
> > The backtrace is generated using the backtrace() call, a GNU extension
> > to the C library. It is available in glibc and uClibc but not in musl.
> > Test for availability of the function to condition compilation of the
> > backtrace printing. Implementing backtrace support with musl is an
> > exercise left to the reader if desired.
> 
> Nice, I like features like this. I had this as a TODO note in one of my
> branches, so I'm glad you've got to it first!.
> 
> Have you looked at libSegFault as well perhaps by any chance?

I wasn't aware of it, thanks for the pointer.

> I'm wondering if something like the following might be a useful addition
> in this topic:
> 
> +if cc.find_library('SegFault', required: false).found()
> +    message('Found libSegFault')
> +    common_arguments += [ '-lSegFault', ]
> +endif
> +
> 
> Although - also possibly conditioned on being a debug build.

In this particular case it wouldn't have helped, as I could only
reproduce the issue with release builds. I thus wonder if we shouldn't
LD_PRELOAD libSegFault.so instead when running tests, like we use
valgrind on tests from time to time. Or would libasan be a better option
in that case ?

What I'm trying to figure out is how much overlap there is between this
patch and libSegFault or libasan.

> This works nicely for me so far, so:
> 
>   Tested-by: Kieran Bingham <kieran.bingham at ideasonboard.com>
> 
> It might be argued that the LogOutput changes required here could be
> split to clarify them, as it took a bit of parsing to understand what
> had to be moved and why. I don't see much requirement to split it, but
> it might be nice to add a description to the changelog to help
> understanding.
> 
> From my parsing - something like:
> 
> The LogOutput class is extended to support writing string messages
> directly to the output. Strings written directly will be considered as
> LogDebug messages when written to the Syslog.
> 
> (Adapting that for correctness if you do decide to add it of course)

Text added, thank you.

> 
>   Reviewed-by: Kieran Bingham <kieran.bingham at ideasonboard.com>
> 
> > Signed-off-by: Laurent Pinchart <laurent.pinchart at ideasonboard.com>
> > ---
> >  meson.build           |  4 ++
> >  src/libcamera/log.cpp | 93 ++++++++++++++++++++++++++++++++++---------
> >  2 files changed, 79 insertions(+), 18 deletions(-)
> > 
> > diff --git a/meson.build b/meson.build
> > index 0a222ba96dcb..634488589a46 100644
> > --- a/meson.build
> > +++ b/meson.build
> > @@ -26,6 +26,10 @@ libcamera_version = libcamera_git_version.split('+')[0]
> >  cc = meson.get_compiler('c')
> >  config_h = configuration_data()
> >  
> > +if cc.has_header_symbol('execinfo.h', 'backtrace')
> > +    config_h.set('HAVE_BACKTRACE', 1)
> > +endif
> > +
> >  if cc.has_header_symbol('stdlib.h', 'secure_getenv', prefix : '#define _GNU_SOURCE')
> >      config_h.set('HAVE_SECURE_GETENV', 1)
> >  endif
> > diff --git a/src/libcamera/log.cpp b/src/libcamera/log.cpp
> > index 50f345b98c74..f4eb8c11adc3 100644
> > --- a/src/libcamera/log.cpp
> > +++ b/src/libcamera/log.cpp
> > @@ -7,6 +7,9 @@
> >  
> >  #include "log.h"
> >  
> > +#if HAVE_BACKTRACE
> > +#include <execinfo.h>
> > +#endif
> >  #include <fstream>
> >  #include <iostream>
> >  #include <list>
> > @@ -108,10 +111,11 @@ public:
> >  
> >  	bool isValid() const;
> >  	void write(const LogMessage &msg);
> > +	void write(const std::string &msg);
> >  
> >  private:
> > -	void writeSyslog(const LogMessage &msg);
> > -	void writeStream(const LogMessage &msg);
> > +	void writeSyslog(LogSeverity severity, const std::string &msg);
> > +	void writeStream(const std::string &msg);
> >  
> >  	std::ostream *stream_;
> >  	LoggingTarget target_;
> > @@ -180,34 +184,55 @@ bool LogOutput::isValid() const
> >   * \param[in] msg Message to write
> >   */
> >  void LogOutput::write(const LogMessage &msg)
> > +{
> > +	std::string str;
> > +
> > +	switch (target_) {
> > +	case LoggingTargetSyslog:
> > +		str = std::string(log_severity_name(msg.severity())) + " "
> > +		    + msg.category().name() + " " + msg.fileInfo() + " "
> > +		    + msg.msg();
> > +		writeSyslog(msg.severity(), str);
> > +		break;
> > +	case LoggingTargetStream:
> > +	case LoggingTargetFile:
> > +		str = "[" + utils::time_point_to_string(msg.timestamp()) + "]"
> > +		    + log_severity_name(msg.severity()) + " "
> > +		    + msg.category().name() + " " + msg.fileInfo() + " "
> > +		    + msg.msg();
> > +		writeStream(str);
> > +		break;
> > +	default:
> > +		break;
> > +	}
> > +}
> > +
> > +/**
> > + * \brief Write string to log output
> > + * \param[in] str String to write
> > + */
> > +void LogOutput::write(const std::string &str)
> >  {
> >  	switch (target_) {
> >  	case LoggingTargetSyslog:
> > -		writeSyslog(msg);
> > +		writeSyslog(LogDebug, str);
> >  		break;
> >  	case LoggingTargetStream:
> >  	case LoggingTargetFile:
> > -		writeStream(msg);
> > +		writeStream(str);
> >  		break;
> >  	default:
> >  		break;
> >  	}
> >  }
> >  
> > -void LogOutput::writeSyslog(const LogMessage &msg)
> > +void LogOutput::writeSyslog(LogSeverity severity, const std::string &str)
> >  {
> > -	std::string str = std::string(log_severity_name(msg.severity())) + " " +
> > -	      		  msg.category().name() + " " + msg.fileInfo() + " " +
> > -			  msg.msg();
> > -	syslog(log_severity_to_syslog(msg.severity()), "%s", str.c_str());
> > +	syslog(log_severity_to_syslog(severity), "%s", str.c_str());
> >  }
> >  
> > -void LogOutput::writeStream(const LogMessage &msg)
> > +void LogOutput::writeStream(const std::string &str)
> >  {
> > -	std::string str = "[" + utils::time_point_to_string(msg.timestamp()) +
> > -			  "]" + log_severity_name(msg.severity()) + " " +
> > -			  msg.category().name() + " " + msg.fileInfo() + " " +
> > -			  msg.msg();
> >  	stream_->write(str.c_str(), str.size());
> >  	stream_->flush();
> >  }
> > @@ -223,6 +248,7 @@ public:
> >  	static Logger *instance();
> >  
> >  	void write(const LogMessage &msg);
> > +	void backtrace();
> >  
> >  	int logSetFile(const char *path);
> >  	int logSetStream(std::ostream *stream);
> > @@ -240,9 +266,6 @@ private:
> >  	void registerCategory(LogCategory *category);
> >  	void unregisterCategory(LogCategory *category);
> >  
> > -	void writeSyslog(const LogMessage &msg);
> > -	void writeStream(const LogMessage &msg);
> > -
> >  	std::unordered_set<LogCategory *> categories_;
> >  	std::list<std::pair<std::string, LogSeverity>> levels_;
> >  
> > @@ -370,6 +393,38 @@ void Logger::write(const LogMessage &msg)
> >  	output->write(msg);
> >  }
> >  
> > +/**
> > + * \brief Write a backtrace to the log
> > + */
> > +void Logger::backtrace()
> > +{
> > +#if HAVE_BACKTRACE
> 
> Will this still be usable/desirable on release builds when
> function/symbol names are possibly unavailable?
> 
> If not - then we might want to make this:
> 
> 	#if HAVE_BACKTRACE && !defined(NDEBUG)
> 
> But I'm not entirely averse to having the backtrace in regardless in
> fact, as it will likely backtrace all the way into the calling
> application (which should have symbols if it's being developed) and
> could add value in that scenario regardless.

I think it's still desirable, as I'm using it with release builds :-)

> > +	std::shared_ptr<LogOutput> output = std::atomic_load(&output_);
> > +	if (!output)
> > +		return;
> > +
> > +	void *buffer[32];
> > +	int num_entries = ::backtrace(buffer, ARRAY_SIZE(buffer));
> > +	char **strings = backtrace_symbols(buffer, num_entries);
> > +	if (!strings)
> > +		return;
> > +
> > +	std::ostringstream msg;
> > +	msg << "Backtrace:" << std::endl;
> > +
> > +	/*
> > +	 * Skip the first two entries that correspond to this method and
> > +	 * ~LogMessage().
> > +	 */
> > +	for (int i = 2; i < num_entries; ++i)
> > +		msg << strings[i] << std::endl;
> > +
> > +	output->write(msg.str());
> > +
> > +	free(strings);
> > +#endif
> > +}
> > +
> >  /**
> >   * \brief Set the log file
> >   * \param[in] path Full path to the log file
> > @@ -783,8 +838,10 @@ LogMessage::~LogMessage()
> >  	if (severity_ >= category_.severity())
> >  		Logger::instance()->write(*this);
> >  
> > -	if (severity_ == LogSeverity::LogFatal)
> > +	if (severity_ == LogSeverity::LogFatal) {
> > +		Logger::instance()->backtrace();
> >  		std::abort();
> > +	}
> >  }
> >  
> >  /**

-- 
Regards,

Laurent Pinchart