[libcamera-devel] [PATCH] libcamera: Print backtrace on fatal errors
Kieran Bingham
kieran.bingham at ideasonboard.com
Wed Jan 22 16:17:27 CET 2020
Hi Laurent,
On 11/01/2020 03:07, Laurent Pinchart wrote:
> 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 expect it was because I hadn't cleaned my build at the time.
Much as we've recently seen how changes to these default options
(cpp_std=c++11) does not cause a reconfigure (and as they are 'default
options' nor would I in fact expect them to).
Ok, so I can confirm, the libasan will not be used unless
b_sanitize=address,undefined is added to the configure options.
Meson doesn't do anything to jsut "use it because it's there".
--
Kieran
>> 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
--
Kieran
More information about the libcamera-devel
mailing list