[libcamera-devel] [PATCH] libcamera: Print backtrace on fatal errors
Laurent Pinchart
laurent.pinchart at ideasonboard.com
Sat Jan 11 04:07:24 CET 2020
Hi Kieran,
On Tue, Nov 26, 2019 at 09:55:12AM +0000, Kieran Bingham wrote:
> On 26/11/2019 02:01, Laurent Pinchart wrote:
> > 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.
>
> When I tried to test out libsegfault with the above snippet, I found
> libasan (which I have manually installed on my system) caught the traps
> first. I think libasan probably has more checks rather than just
> trapping on SIGSEGV so has more value, but the key difference is
> libsegfault is part that being part of the std gnu library, libsegfault
> probably has more potential users.
>
> I'm still a bit bemused that I didn't have libasan explicitly enabled
> for my build, so I suspect meson has enabled it 'because it was there'
> but I need to get that confirmed rather than just being a theory.
Have you had a chance to investigate this ?
> I think the difference is libSegFault will help reporting /where/ a
> failure occured when it happens, whereas libasan is more likely to help
> catch bugs earlier in the development cycle. (Note that we can
> explicitly enable libasan functionality with meson with something like
> the following snippets:
>
>
> ... meson.build
> index b2d52363ccae..aecace8ac556 100644
> @@ -3,10 +3,13 @@ project('libcamera', 'c', 'cpp',
> version : '0.0.0',
> default_options : [
> 'werror=true',
> 'warning_level=2',
> 'cpp_std=c++11',
> + 'b_sanitize=address,undefined',
> + #'b_sanitize=thread',
> + #'b_sanitize=memory',
> ],
> license : 'LGPL 2.1+')
>
> The thread and memory sanitizers are mutually exclusive against the
> address,undefined-behaviour sanitiser - so it might be useful to use
> this in some automated test setup with three separate builds with each
> of them enabled.
Agreed.
> Anyway, all of the above is slightly unrelated to this patch, so is only
> discussion - as this patch reports more information on our own internal
> Fatal log-level which is a great addition IMO...
>
> >> 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 :-)
>
>
> Excellent - I thought a release build would have stripped out the
> required symbol names.
>
> I certainly see some benefit to having this anyway.
>
> It will be even more beneficial if we later make Fatal 'non-fatal' in
> release builds, as there we really will want as much debug information
> to be reportable as possible, and Fatal will then give us a route to say
>
> "This is reallllly bad, we're trying to continue - but please report
> this issue"
>
> (And in debug builds, I very much prefer the fail-fast abort on a fatal).
>
> >>> + 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
More information about the libcamera-devel
mailing list