testlib: Prevent Apple test logger from stomping on other loggers

We were potentially adding the Apple test logger multiple times, and we
didn't consider whether the existing loggers were logging to file or not
when circumventing them.

We now don't use the Apple logger if it would touch stderr and some other
logger is using stdout. In the case of no explicit logger being specified
on the command line, we allow the Apple logger to take priority over the
default plain test logger.

Change-Id: I31bbec4f4b3ab84ba9a2be35e8e5db08fee071a7
Reviewed-by: Edward Welbourne <edward.welbourne@qt.io>

src/corelib/kernel/qcore_mac.cpp

@@ -65,6 +65,19 @@ QCFString::operator CFStringRef() const
 
 #if defined(QT_USE_APPLE_UNIFIED_LOGGING)
 
+bool AppleUnifiedLogger::willMirrorToStderr()
+{
+    // When running under Xcode or LLDB, one or more of these variables will
+    // be set, which triggers libsystem_trace.dyld to log messages to stderr
+    // as well, via_os_log_impl_mirror_to_stderr. Un-setting these variables
+    // is not an option, as that would silence normal NSLog or os_log calls,
+    // so instead we skip our own stderr output. See rdar://36919139.
+    static bool willMirror = qEnvironmentVariableIsSet("OS_ACTIVITY_DT_MODE")
+                                 || qEnvironmentVariableIsSet("ACTIVITY_LOG_STDERR")
+                                 || qEnvironmentVariableIsSet("CFLOG_FORCE_STDERR");
+    return willMirror;
+}
+
 QT_MAC_WEAK_IMPORT(_os_log_default);
 bool AppleUnifiedLogger::messageHandler(QtMsgType msgType, const QMessageLogContext &context,
                                         const QString &message, const QString &optionalSubsystem)
@@ -103,15 +116,7 @@ bool AppleUnifiedLogger::messageHandler(QtMsgType msgType, const QMessageLogCont
     // system from redacting our log message.
     os_log_with_type(log, logType, "%{public}s", qPrintable(message));
 
-    // When running under Xcode or LLDB, one or more of these variables will
+    return willMirrorToStderr();
-    // be set, which triggers libsystem_trace.dyld to log messages to stderr
-    // as well, via_os_log_impl_mirror_to_stderr. Un-setting these variables
-    // is not an option, as that would silence normal NSLog or os_log calls,
-    // so instead we skip our own stderr output. See rdar://36919139.
-    static bool mirroredToStderr = qEnvironmentVariableIsSet("OS_ACTIVITY_DT_MODE")
-                                 || qEnvironmentVariableIsSet("ACTIVITY_LOG_STDERR")
-                                 || qEnvironmentVariableIsSet("CFLOG_FORCE_STDERR");
-    return mirroredToStderr;
 }
 
 os_log_type_t AppleUnifiedLogger::logTypeForMessageType(QtMsgType msgType)

src/corelib/kernel/qcore_mac_p.h

@@ -202,6 +202,7 @@ class Q_CORE_EXPORT AppleUnifiedLogger
 public:
     static bool messageHandler(QtMsgType msgType, const QMessageLogContext &context, const QString &message,
         const QString &subsystem = QString());
+    static bool willMirrorToStderr();
 private:
     static os_log_type_t logTypeForMessageType(QtMsgType msgType);
     static os_log_t cachedLog(const QString &subsystem, const QString &category);

src/testlib/qappletestlogger.cpp

@@ -55,9 +55,8 @@ bool QAppleTestLogger::debugLoggingEnabled()
     return os_log_type_enabled(OS_LOG_DEFAULT, OS_LOG_TYPE_DEBUG);
 }
 
-QAppleTestLogger::QAppleTestLogger(QAbstractTestLogger *logger)
+QAppleTestLogger::QAppleTestLogger()
     : QAbstractTestLogger(nullptr)
-    , m_logger(logger)
 {
 }
 
@@ -65,6 +64,8 @@ static QAppleLogActivity testFunctionActivity;
 
 void QAppleTestLogger::enterTestFunction(const char *function)
 {
+    Q_UNUSED(function);
+
     // Re-create activity each time
     testFunctionActivity = QT_APPLE_LOG_ACTIVITY("Running test function").enter();
 
@@ -73,15 +74,12 @@ void QAppleTestLogger::enterTestFunction(const char *function)
     QString identifier = QString::fromLatin1(testIdentifier.data());
     QMessageLogContext context(nullptr, 0, nullptr, "qt.test.enter");
     QString message = identifier;
-    if (AppleUnifiedLogger::messageHandler(QtDebugMsg, context, message, identifier))
-        return; // AUL already printed to stderr
 
-    m_logger->enterTestFunction(function);
+    AppleUnifiedLogger::messageHandler(QtDebugMsg, context, message, identifier);
 }
 
 void QAppleTestLogger::leaveTestFunction()
 {
-    m_logger->leaveTestFunction();
     testFunctionActivity.leave();
 }
 
@@ -134,18 +132,12 @@ void QAppleTestLogger::addIncident(IncidentTypes type, const char *description,
     if (qstrlen(description))
         message += QLatin1Char('\n') % QString::fromLatin1(description);
 
-    if (AppleUnifiedLogger::messageHandler(incidentClassification.first, context, message, subsystem))
+    AppleUnifiedLogger::messageHandler(incidentClassification.first, context, message, subsystem);
-        return; // AUL already printed to stderr
-
-    m_logger->addIncident(type, description, file, line);
 }
 
 void QAppleTestLogger::addMessage(QtMsgType type, const QMessageLogContext &context, const QString &message)
 {
-    if (AppleUnifiedLogger::messageHandler(type, context, message))
+    AppleUnifiedLogger::messageHandler(type, context, message);
-        return; // AUL already printed to stderr
-
-    m_logger->addMessage(type, context, message);
 }
 
 #endif // QT_USE_APPLE_UNIFIED_LOGGING

src/testlib/qappletestlogger_p.h

@@ -63,12 +63,7 @@ class QAppleTestLogger : public QAbstractTestLogger
 public:
     static bool debugLoggingEnabled();
 
-    QAppleTestLogger(QAbstractTestLogger *logger);
+    QAppleTestLogger();
-
-    void startLogging() override
-    { m_logger->startLogging(); }
-    void stopLogging() override
-    { m_logger->stopLogging(); }
 
     void enterTestFunction(const char *function) override;
     void leaveTestFunction() override;
@@ -77,16 +72,12 @@ public:
                      const char *file = 0, int line = 0) override;
     void addMessage(QtMsgType, const QMessageLogContext &,
             const QString &) override;
-
-    void addBenchmarkResult(const QBenchmarkResult &result) override
-    { m_logger->addBenchmarkResult(result); }
-
     void addMessage(MessageTypes type, const QString &message,
                             const char *file = 0, int line = 0) override
-    { m_logger->addMessage(type, message, file, line); }
+    { Q_UNUSED(type); Q_UNUSED(message); Q_UNUSED(file); Q_UNUSED(line); Q_UNREACHABLE(); }
 
-private:
+    void addBenchmarkResult(const QBenchmarkResult &result) override
-    QScopedPointer<QAbstractTestLogger> m_logger;
+    { Q_UNUSED(result); }
 };
 #endif
 

src/testlib/qtestcase.cpp

@@ -77,6 +77,10 @@
 #include <QtTest/private/qtestutil_macos_p.h>
 #endif
 
+#if defined(Q_OS_DARWIN)
+#include <QtTest/private/qappletestlogger_p.h>
+#endif
+
 #include <cmath>
 #include <numeric>
 #include <algorithm>
@@ -509,7 +513,7 @@ static int qToInt(char *str)
 
 Q_TESTLIB_EXPORT void qtest_qParseArgs(int argc, char *argv[], bool qml)
 {
-    QTestLog::LogMode logFormat = QTestLog::Plain;
+    int logFormat = -1; // Not set
     const char *logFilename = 0;
 
     QTest::testFunctions.clear();
@@ -677,7 +681,7 @@ Q_TESTLIB_EXPORT void qtest_qParseArgs(int argc, char *argv[], bool qml)
                     fprintf(stderr, "only one logger can log to stdout\n");
                     exit(1);
                 }
-                QTestLog::addLogger(logFormat, filename);
+                QTestLog::addLogger(QTestLog::LogMode(logFormat), filename);
             }
             delete [] filename;
             delete [] format;
@@ -839,10 +843,25 @@ Q_TESTLIB_EXPORT void qtest_qParseArgs(int argc, char *argv[], bool qml)
     QTestLog::setInstalledTestCoverage(installedTestCoverage);
 
     // If no loggers were created by the long version of the -o command-line
-    // option, create a logger using whatever filename and format were
+    // option, but a logger was requested via the old-style option, add it.
-    // set using the old-style command-line options.
+    const bool explicitLoggerRequested = logFormat != -1;
-    if (QTestLog::loggerCount() == 0)
+    if (QTestLog::loggerCount() == 0 && explicitLoggerRequested)
-        QTestLog::addLogger(logFormat, logFilename);
+        QTestLog::addLogger(QTestLog::LogMode(logFormat), logFilename);
+
+    bool addFallbackLogger = !explicitLoggerRequested;
+
+#if defined(QT_USE_APPLE_UNIFIED_LOGGING)
+    // Any explicitly requested loggers will be added by now, so we can check if they use stdout
+    const bool safeToAddAppleLogger = !AppleUnifiedLogger::willMirrorToStderr() || !QTestLog::loggerUsingStdout();
+    if (safeToAddAppleLogger && QAppleTestLogger::debugLoggingEnabled()) {
+        QTestLog::addLogger(QTestLog::Apple, nullptr);
+        if (AppleUnifiedLogger::willMirrorToStderr() && !logFilename)
+            addFallbackLogger = false; // Prevent plain test logger fallback below
+    }
+#endif
+
+    if (addFallbackLogger)
+        QTestLog::addLogger(QTestLog::Plain, logFilename);
 }
 
 QBenchmarkResult qMedian(const QVector<QBenchmarkResult> &container)

src/testlib/qtestlog.cpp

@@ -460,6 +460,11 @@ void QTestLog::addLogger(LogMode mode, const char *filename)
     case QTestLog::TAP:
         logger = new QTapTestLogger(filename);
         break;
+#if defined(QT_USE_APPLE_UNIFIED_LOGGING)
+    case QTestLog::Apple:
+        logger = new QAppleTestLogger;
+        break;
+#endif
 #if defined(HAVE_XCTEST)
     case QTestLog::XCTest:
         logger = new QXcodeTestLogger;
@@ -467,14 +472,6 @@ void QTestLog::addLogger(LogMode mode, const char *filename)
 #endif
     }
 
-#if defined(QT_USE_APPLE_UNIFIED_LOGGING)
-    // Logger that also feeds messages to AUL. It needs to wrap the existing
-    // logger, as it needs to be able to short circuit the existing logger
-    // in case AUL prints to stderr.
-    if (QAppleTestLogger::debugLoggingEnabled())
-        logger = new QAppleTestLogger(logger);
-#endif
-
     QTEST_ASSERT(logger);
     QTest::loggers.append(logger);
 }

src/testlib/qtestlog_p.h

@@ -53,6 +53,10 @@
 
 #include <QtTest/qttestglobal.h>
 
+#if defined(Q_OS_DARWIN)
+#include <QtCore/private/qcore_mac_p.h>
+#endif
+
 QT_BEGIN_NAMESPACE
 
 class QBenchmarkResult;
@@ -63,9 +67,12 @@ class Q_TESTLIB_EXPORT QTestLog
 {
 public:
     enum LogMode {
-        Plain = 0, XML, LightXML, XunitXML, CSV, TeamCity, TAP,
+        Plain = 0, XML, LightXML, XunitXML, CSV, TeamCity, TAP
+#if defined(QT_USE_APPLE_UNIFIED_LOGGING)
+        , Apple
+#endif
 #if defined(HAVE_XCTEST)
-        XCTest
+        , XCTest
 #endif
     };