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

[Kieran Bingham]

Hi Laurent,

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'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.

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)

  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.



> +	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
--
Kieran