| Message ID | 20191123124302.25863-1-laurent.pinchart@ideasonboard.com |
|---|---|
| State | Accepted |
| Commit | 442f516c6215aa0bbdeec4c7f2d6c406521a92fd |
| Headers | show |
| Series |
|
| Related | show |
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@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@ideasonboard.com> > Signed-off-by: Laurent Pinchart <laurent.pinchart@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(); > + } > } > > /** >
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@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@ideasonboard.com> > > > Signed-off-by: Laurent Pinchart <laurent.pinchart@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(); > > + } > > } > > > > /**
Hi Laurent, On 26/11/2019 02:01, Laurent Pinchart wrote: > 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. 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. 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. 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@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@ideasonboard.com> >> >>> Signed-off-by: Laurent Pinchart <laurent.pinchart@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). -- Kieran >>> + 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(); >>> + } >>> } >>> >>> /** >
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@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@ideasonboard.com> > >> > >>> Signed-off-by: Laurent Pinchart <laurent.pinchart@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(); > >>> + } > >>> } > >>> > >>> /**
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@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@ideasonboard.com> >>>> >>>>> Signed-off-by: Laurent Pinchart <laurent.pinchart@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(); >>>>> + } >>>>> } >>>>> >>>>> /** >
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 + 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(); + } } /**
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. Signed-off-by: Laurent Pinchart <laurent.pinchart@ideasonboard.com> --- meson.build | 4 ++ src/libcamera/log.cpp | 93 ++++++++++++++++++++++++++++++++++--------- 2 files changed, 79 insertions(+), 18 deletions(-)