From 9f598d5ee9819971613c27705bce39e505705903 Mon Sep 17 00:00:00 2001 From: Olivier Goffart Date: Sun, 13 Jul 2014 13:07:40 +0200 Subject: Logging: support %{backtrace} in QT_MESSAGE_PATTERN On supported platform, allow to show a backtrace by using %{backtrace} or %{backtrace depth=N separator="|"} [ChangeLog][QtCore][Logging] QT_MESSAGE_PATTERN can include a backtrace using %{backtrace} Change-Id: Ib00418c070d3bd6fe846dc04bf69fa91ba64f9cd Reviewed-by: Kai Koehne --- src/corelib/global/qlogging.cpp | 105 +++++++++++++++++++++ tests/auto/corelib/global/qlogging/app/app.pro | 3 + tests/auto/corelib/global/qlogging/app/main.cpp | 31 ++++++ .../auto/corelib/global/qlogging/tst_qlogging.cpp | 37 ++++++-- 4 files changed, 169 insertions(+), 7 deletions(-) diff --git a/src/corelib/global/qlogging.cpp b/src/corelib/global/qlogging.cpp index 8174d125a3..847b7cb4c0 100644 --- a/src/corelib/global/qlogging.cpp +++ b/src/corelib/global/qlogging.cpp @@ -1,6 +1,7 @@ /**************************************************************************** ** ** Copyright (C) 2013 Digia Plc and/or its subsidiary(-ies). +** Copyright (C) 2014 Olivier Goffart ** Contact: http://www.qt-project.org/legal ** ** This file is part of the QtCore module of the Qt Toolkit. @@ -72,6 +73,22 @@ # include #endif +#if !defined QT_NO_REGULAREXPRESSION && !defined(QT_BOOTSTRAPPED) +#ifdef __has_include +#if __has_include() && __has_include() +#define QLOGGING_HAVE_BACKTRACE +#endif +#elif defined(__GLIBCXX__) && defined(__GLIBC__) // (because older version of gcc don't have __has_include) +#define QLOGGING_HAVE_BACKTRACE +#endif + +#ifdef QLOGGING_HAVE_BACKTRACE +#include +#include +#include +#endif +#endif + #include QT_BEGIN_NAMESPACE @@ -763,6 +780,7 @@ static const char pidTokenC[] = "%{pid}"; static const char appnameTokenC[] = "%{appname}"; static const char threadidTokenC[] = "%{threadid}"; static const char timeTokenC[] = "%{time"; //not a typo: this command has arguments +static const char backtraceTokenC[] = "%{backtrace"; //ditto static const char ifCategoryTokenC[] = "%{if-category}"; static const char ifDebugTokenC[] = "%{if-debug}"; static const char ifWarningTokenC[] = "%{if-warning}"; @@ -784,6 +802,10 @@ struct QMessagePattern { const char **literals; const char **tokens; QString timeFormat; +#ifdef QLOGGING_HAVE_BACKTRACE + int backtraceDepth; + QString backtraceSeparator; +#endif bool fromEnvironment; static QBasicMutex mutex; @@ -798,6 +820,10 @@ QBasicMutex QMessagePattern::mutex; QMessagePattern::QMessagePattern() : literals(0) , tokens(0) +#ifdef QLOGGING_HAVE_BACKTRACE + , backtraceDepth(5) + , backtraceSeparator(QLatin1Char('|')) +#endif , fromEnvironment(false) #ifndef QT_BOOTSTRAPPED , startTime(QDateTime::currentDateTime()) @@ -898,6 +924,25 @@ void QMessagePattern::setPattern(const QString &pattern) int spaceIdx = lexeme.indexOf(QChar::fromLatin1(' ')); if (spaceIdx > 0) timeFormat = lexeme.mid(spaceIdx + 1, lexeme.length() - spaceIdx - 2); + } else if (lexeme.startsWith(QLatin1String(backtraceTokenC))) { +#ifdef QLOGGING_HAVE_BACKTRACE + tokens[i] = backtraceTokenC; + QRegularExpression depthRx(QStringLiteral(" depth=(?|\"([^\"]*)\"|([^ }]*))")); + QRegularExpression separatorRx(QStringLiteral(" separator=(?|\"([^\"]*)\"|([^ }]*))")); + QRegularExpressionMatch m = depthRx.match(lexeme); + if (m.hasMatch()) { + int depth = m.capturedRef(1).toInt(); + if (depth <= 0) + error += QStringLiteral("QT_MESSAGE_PATTERN: %{backtrace} depth must be a number greater than 0\n"); + else + backtraceDepth = depth; + } + m = separatorRx.match(lexeme); + if (m.hasMatch()) + backtraceSeparator = m.captured(1); +#else + error += QStringLiteral("QT_MESSAGE_PATTERN: %{backtrace} is not supported by this Qt build\n"); +#endif } #define IF_TOKEN(LEVEL) \ @@ -1068,6 +1113,58 @@ Q_CORE_EXPORT QString qMessageFormatString(QtMsgType type, const QMessageLogCont } else if (token == threadidTokenC) { message.append(QLatin1String("0x")); message.append(QString::number(qlonglong(QThread::currentThread()->currentThread()), 16)); +#ifdef QLOGGING_HAVE_BACKTRACE + } else if (token == backtraceTokenC) { + QVarLengthArray buffer(15 + pattern->backtraceDepth); + int n = backtrace(buffer.data(), buffer.size()); + if (n > 0) { + QScopedPointer strings(backtrace_symbols(buffer.data(), n)); + int numberPrinted = 0; + for (int i = 0; i < n && numberPrinted < pattern->backtraceDepth; ++i) { + QString trace = QString::fromLatin1(strings.data()[i]); + // The results of backtrace_symbols looks like this: + // /lib/libc.so.6(__libc_start_main+0xf3) [0x4a937413] + // The offset and function name are optional. + // This regexp tries to extract the librry name (without the path) and the function name. + // This code is protected by QMessagePattern::mutex so it is thread safe on all compilers + static QRegularExpression rx(QStringLiteral("^(?:[^(]*/)?([^(/]+)\\(([^+]*)(?:[\\+[a-f0-9x]*)?\\) \\[[a-f0-9x]*\\]$"), + QRegularExpression::OptimizeOnFirstUsageOption); + + QRegularExpressionMatch m = rx.match(trace); + if (m.hasMatch()) { + // skip the trace from QtCore that are because of the qDebug itself + QString library = m.captured(1); + QString function = m.captured(2); + if (!numberPrinted && library.contains(QLatin1String("Qt5Core")) + && (function.isEmpty() || function.contains(QLatin1String("Message"), Qt::CaseInsensitive) + || function.contains(QLatin1String("QDebug")))) { + continue; + } + + if (function.startsWith(QLatin1String("_Z"))) { + QScopedPointer demangled( + abi::__cxa_demangle(function.toUtf8(), 0, 0, 0)); + if (demangled) + function = QString::fromUtf8(qCleanupFuncinfo(demangled.data())); + } + + if (numberPrinted > 0) + message.append(pattern->backtraceSeparator); + + if (function.isEmpty()) + message += QLatin1Char('?') + library + QLatin1Char('?'); + else + message += function; + + } else { + if (numberPrinted == 0) + continue; + message += pattern->backtraceSeparator + QLatin1String("???"); + } + numberPrinted++; + } + } +#endif } else if (token == timeTokenC) { quint64 ms = pattern->timer.elapsed(); if (pattern->timeFormat.isEmpty()) @@ -1458,6 +1555,14 @@ void qErrnoWarning(int code, const char *msg, ...) \row \li \c %{time} \li time of the message, in seconds since the process started \row \li \c %{time format} \li system time when the message occurred, formatted by passing the \c format to \l QDateTime::toString() + \row \li \c{%{backtrace [depth=N] [separator="..."]}} \li A backtrace with the number of frames + specified by the optional \c depth parameter (defaults to 5), and separated by the optional + \c separator parameter (defaults to "|"). + This expansion is available only on some platforms (currently only platfoms using glibc). + Names are only known for exported functions. If you want to see the name of every function + in your application, use \c{QMAKE_LFLAGS += -rdynamic}. + When reading backtraces, take into account that frames might be missing due to inlining or + tail call optimization. \endtable You can also use conditionals on the type of the message using \c %{if-debug}, diff --git a/tests/auto/corelib/global/qlogging/app/app.pro b/tests/auto/corelib/global/qlogging/app/app.pro index 24ac571bac..b11e792a4c 100644 --- a/tests/auto/corelib/global/qlogging/app/app.pro +++ b/tests/auto/corelib/global/qlogging/app/app.pro @@ -10,3 +10,6 @@ CONFIG += console SOURCES += main.cpp DEFINES += QT_DISABLE_DEPRECATED_BEFORE=0 + +gcc:!mingw: QMAKE_LFLAGS += -rdynamic + diff --git a/tests/auto/corelib/global/qlogging/app/main.cpp b/tests/auto/corelib/global/qlogging/app/main.cpp index 621059caad..e190a48873 100644 --- a/tests/auto/corelib/global/qlogging/app/main.cpp +++ b/tests/auto/corelib/global/qlogging/app/main.cpp @@ -42,11 +42,37 @@ #include #include +#ifdef Q_CC_GNU +#define NEVER_INLINE __attribute__((__noinline__)) +#else +#define NEVER_INLINE +#endif + struct T { T() { qDebug("static constructor"); } ~T() { qDebug("static destructor"); } } t; +class MyClass : public QObject +{ + Q_OBJECT +public slots: + virtual NEVER_INLINE QString mySlot1(); +private: + virtual NEVER_INLINE void myFunction(int a); +}; + +QString MyClass::mySlot1() +{ + myFunction(34); + return QString(); +} + +void MyClass::myFunction(int a) +{ + qDebug() << "from_a_function" << a; +} + int main(int argc, char **argv) { QCoreApplication app(argc, argv); @@ -65,5 +91,10 @@ int main(int argc, char **argv) qDebug("qDebug2"); + MyClass cl; + QMetaObject::invokeMethod(&cl, "mySlot1"); + return 0; } + +#include "main.moc" diff --git a/tests/auto/corelib/global/qlogging/tst_qlogging.cpp b/tests/auto/corelib/global/qlogging/tst_qlogging.cpp index 3c1a26c629..a8027a4157 100644 --- a/tests/auto/corelib/global/qlogging/tst_qlogging.cpp +++ b/tests/auto/corelib/global/qlogging/tst_qlogging.cpp @@ -1,6 +1,7 @@ /**************************************************************************** ** ** Copyright (C) 2013 Digia Plc and/or its subsidiary(-ies). +** Copyright (C) 2014 Olivier Goffart ** Contact: http://www.qt-project.org/legal ** ** This file is part of the test suite of the Qt Toolkit. @@ -650,14 +651,15 @@ void tst_qmessagehandler::qMessagePattern_data() // %{file} is tricky because of shadow builds QTest::newRow("basic") << "%{type} %{appname} %{line} %{function} %{message}" << true << (QList() - << "debug 46 T::T static constructor" + << "debug 52 T::T static constructor" // we can't be sure whether the QT_MESSAGE_PATTERN is already destructed << "static destructor" - << "debug tst_qlogging 57 main qDebug" - << "warning tst_qlogging 58 main qWarning" - << "critical tst_qlogging 59 main qCritical" - << "warning tst_qlogging 62 main qDebug with category" - << "debug tst_qlogging 66 main qDebug2"); + << "debug tst_qlogging 73 MyClass::myFunction from_a_function 34" + << "debug tst_qlogging 83 main qDebug" + << "warning tst_qlogging 84 main qWarning" + << "critical tst_qlogging 85 main qCritical" + << "warning tst_qlogging 88 main qDebug with category" + << "debug tst_qlogging 92 main qDebug2"); QTest::newRow("invalid") << "PREFIX: %{unknown} %{message}" << false << (QList() @@ -701,6 +703,23 @@ void tst_qmessagehandler::qMessagePattern_data() QTest::newRow("time") << "<%{time}>%{message}" << true << (QList() << "< "); +#ifdef __GLIBC__ +#ifdef QT_NAMESPACE +#define QT_NAMESPACE_STR QT_STRINGIFY(QT_NAMESPACE::) +#else +#define QT_NAMESPACE_STR "" +#endif + +#ifndef QT_NO_DEBUG + QTest::newRow("backtrace") << "[%{backtrace}] %{message}" << true << (QList() + // MyClass::qt_static_metacall is explicitly marked as hidden in the Q_OBJECT macro + << "[MyClass::myFunction|MyClass::mySlot1|?app?|" QT_NAMESPACE_STR "QMetaMethod::invoke|" QT_NAMESPACE_STR "QMetaObject::invokeMethod] from_a_function 34"); +#endif + + QTest::newRow("backtrace depth,separator") << "[%{backtrace depth=2 separator=\"\n\"}] %{message}" << true << (QList() + << "[MyClass::myFunction\nMyClass::mySlot1] from_a_function 34"); +#endif + } @@ -734,7 +753,11 @@ void tst_qmessagehandler::qMessagePattern() QCOMPARE(!output.contains("QT_MESSAGE_PATTERN"), valid); foreach (const QByteArray &e, expected) { - QVERIFY(output.contains(e)); + if (!output.contains(e)) { + qDebug() << output; + qDebug() << "expected: " << e; + QVERIFY(output.contains(e)); + } } #endif } -- cgit v1.2.3