Fix for rare crash in LogHandler::flushRepeatedMessages()

This can happen when LogHandler::flushRepetedMessages is called on
the main thread, while the application is printing messages on
a separate thread.  The access to the _lastRepeatedMessage QHash was
not guarded.

I've added two mutexes to guard access to both the repeatedMessage
hashes/regexes and the onlyOnceMessages/regexes.  This will unfortunately
incur a performance hit for frequent debug logging, but that's better
then crashing.

Also, I've added the ability to print threadIDs as well as Process ids.
This is helpful when debugging multi-threaded access to shared variables.

assignment-client/src/AssignmentClient.cpp

@@ -74,7 +74,7 @@ AssignmentClient::AssignmentClient(Assignment::Type requestAssignmentType, QStri
     LogHandler::getInstance().setTargetName(ASSIGNMENT_CLIENT_TARGET_NAME);
 
     // make sure we output process IDs for a child AC otherwise it's insane to parse
-    LogHandler::getInstance().setShouldOutputPID(true);
+    LogHandler::getInstance().setShouldOutputProcessID(true);
 
     // setup our _requestAssignment member variable from the passed arguments
     _requestAssignment = Assignment(Assignment::RequestCommand, requestAssignmentType, assignmentPool);

assignment-client/src/AssignmentClientMonitor.cpp

@@ -44,7 +44,7 @@ AssignmentClientMonitor::AssignmentClientMonitor(const unsigned int numAssignmen
     LogHandler::getInstance().setTargetName(ASSIGNMENT_CLIENT_MONITOR_TARGET_NAME);
 
     // make sure we output process IDs for a monitor otherwise it's insane to parse
-    LogHandler::getInstance().setShouldOutputPID(true);
+    LogHandler::getInstance().setShouldOutputProcessID(true);
 
     // create a NodeList so we can receive stats from children
     DependencyManager::registerInheritance<LimitedNodeList, NodeList>();

libraries/shared/src/LogHandler.cpp

@@ -12,9 +12,10 @@
 
 #include <qcoreapplication.h>
 
-#include <qdatetime.h>
+#include <QDateTime>
-#include <qdebug.h>
+#include <QDebug>
-#include <qtimer.h>
+#include <QTimer>
+#include <QThread>
 
 #include "LogHandler.h"
 
@@ -24,13 +25,14 @@ LogHandler& LogHandler::getInstance() {
 }
 
 LogHandler::LogHandler() :
-    _shouldOutputPID(false)
+    _shouldOutputProcessID(false),
+    _shouldOutputThreadID(false)
 {
     // setup our timer to flush the verbose logs every 5 seconds
     QTimer* logFlushTimer = new QTimer(this);
     connect(logFlushTimer, &QTimer::timeout, this, &LogHandler::flushRepeatedMessages);
     logFlushTimer->start(VERBOSE_LOG_INTERVAL_SECONDS * 1000);
-    
+
     // when the log handler is first setup we should print our timezone
     QString timezoneString = "Time zone: " + QDateTime::currentDateTime().toString("t");
     printf("%s\n", qPrintable(timezoneString));
@@ -57,51 +59,55 @@ const char* stringForLogType(LogMsgType msgType) {
 const QString DATE_STRING_FORMAT = "MM/dd hh:mm:ss";
 
 void LogHandler::flushRepeatedMessages() {
+    QMutexLocker locker(&_repeatedMessageLock);
     QHash<QString, int>::iterator message = _repeatMessageCountHash.begin();
     while (message != _repeatMessageCountHash.end()) {
-        
+
         if (message.value() > 0) {
             QString repeatMessage = QString("%1 repeated log entries matching \"%2\" - Last entry: \"%3\"")
             .arg(message.value()).arg(message.key()).arg(_lastRepeatedMessage.value(message.key()));
-            
+
             QMessageLogContext emptyContext;
             printMessage(LogSuppressed, emptyContext, repeatMessage);
         }
-        
+
         _lastRepeatedMessage.remove(message.key());
         message = _repeatMessageCountHash.erase(message);
     }
 }
 
 QString LogHandler::printMessage(LogMsgType type, const QMessageLogContext& context, const QString& message) {
-    
+
     if (message.isEmpty()) {
         return QString();
     }
-    
+
     if (type == LogDebug) {
         // for debug messages, check if this matches any of our regexes for repeated log messages
+        QMutexLocker locker(&_repeatedMessageLock);
         foreach(const QString& regexString, getInstance()._repeatedMessageRegexes) {
             QRegExp repeatRegex(regexString);
             if (repeatRegex.indexIn(message) != -1) {
-                
+
                 if (!_repeatMessageCountHash.contains(regexString)) {
                     // we have a match but didn't have this yet - output the first one
                     _repeatMessageCountHash[regexString] = 0;
-                    
+
                     // break the foreach so we output the first match
                     break;
                 } else {
                     // we have a match - add 1 to the count of repeats for this message and set this as the last repeated message
                     _repeatMessageCountHash[regexString] += 1;
                     _lastRepeatedMessage[regexString] = message;
-                    
+
                     // return out, we're not printing this one
                     return QString();
                 }
             }
         }
-
+    }
+    if (type == LogDebug) {
+        QMutexLocker locker(&_onlyOnceMessageLock);
         // see if this message is one we should only print once
         foreach(const QString& regexString, getInstance()._onlyOnceMessageRegexes) {
             QRegExp onlyOnceRegex(regexString);
@@ -118,23 +124,27 @@ QString LogHandler::printMessage(LogMsgType type, const QMessageLogContext& cont
             }
         }
     }
-    
+
     // log prefix is in the following format
-    // [TIMESTAMP] [DEBUG] [PID] [TARGET] logged string
+    // [TIMESTAMP] [DEBUG] [PID] [TID] [TARGET] logged string
-    
+
     QString prefixString = QString("[%1]").arg(QDateTime::currentDateTime().toString(DATE_STRING_FORMAT));
-    
+
     prefixString.append(QString(" [%1]").arg(stringForLogType(type)));
-    
+
-    if (_shouldOutputPID) {
+    if (_shouldOutputProcessID) {
         prefixString.append(QString(" [%1]").arg(QCoreApplication::instance()->applicationPid()));
-        
     }
-    
+
+    if (_shouldOutputThreadID) {
+        size_t threadID = (size_t)QThread::currentThreadId();
+        prefixString.append(QString(" [%1]").arg(threadID));
+    }
+
     if (!_targetName.isEmpty()) {
         prefixString.append(QString(" [%1]").arg(_targetName));
     }
-    
+
     QString logMessage = QString("%1 %2").arg(prefixString, message.split("\n").join("\n" + prefixString + " "));
     fprintf(stdout, "%s\n", qPrintable(logMessage));
     return logMessage;
@@ -143,3 +153,13 @@ QString LogHandler::printMessage(LogMsgType type, const QMessageLogContext& cont
 void LogHandler::verboseMessageHandler(QtMsgType type, const QMessageLogContext& context, const QString& message) {
     getInstance().printMessage((LogMsgType) type, context, message);
 }
+
+const QString& LogHandler::addRepeatedMessageRegex(const QString& regexString) {
+    QMutexLocker locker(&_repeatedMessageLock);
+    return *_repeatedMessageRegexes.insert(regexString);
+}
+
+const QString& LogHandler::addOnlyOnceMessageRegex(const QString& regexString) {
+    QMutexLocker locker(&_onlyOnceMessageLock);
+    return *_onlyOnceMessageRegexes.insert(regexString);
+}

libraries/shared/src/LogHandler.h

@@ -34,34 +34,38 @@ class LogHandler : public QObject {
     Q_OBJECT
 public:
     static LogHandler& getInstance();
-    
+
     /// sets the target name to output via the verboseMessageHandler, called once before logging begins
     /// \param targetName the desired target name to output in logs
     void setTargetName(const QString& targetName) { _targetName = targetName; }
-    
+
-    void setShouldOutputPID(bool shouldOutputPID) { _shouldOutputPID = shouldOutputPID; }
+    void setShouldOutputProcessID(bool shouldOutputProcessID) { _shouldOutputProcessID = shouldOutputProcessID; }
-    
+    void setShouldOutputThreadID(bool shouldOutputThreadID) { _shouldOutputThreadID = shouldOutputThreadID; }
+
     QString printMessage(LogMsgType type, const QMessageLogContext& context, const QString &message);
-    
+
     /// a qtMessageHandler that can be hooked up to a target that links to Qt
     /// prints various process, message type, and time information
     static void verboseMessageHandler(QtMsgType type, const QMessageLogContext& context, const QString &message);
-    
+
-    const QString& addRepeatedMessageRegex(const QString& regexString) { return *_repeatedMessageRegexes.insert(regexString); }
+    const QString& addRepeatedMessageRegex(const QString& regexString);
-    const QString& addOnlyOnceMessageRegex(const QString& regexString) { return *_onlyOnceMessageRegexes.insert(regexString); }
+    const QString& addOnlyOnceMessageRegex(const QString& regexString);
 private:
     LogHandler();
-    
+
     void flushRepeatedMessages();
-    
+
     QString _targetName;
-    bool _shouldOutputPID;
+    bool _shouldOutputProcessID;
+    bool _shouldOutputThreadID;
     QSet<QString> _repeatedMessageRegexes;
     QHash<QString, int> _repeatMessageCountHash;
     QHash<QString, QString> _lastRepeatedMessage;
+    QMutex _repeatedMessageLock;
 
     QSet<QString> _onlyOnceMessageRegexes;
     QHash<QString, int> _onlyOnceMessageCountHash;
+    QMutex _onlyOnceMessageLock;
 };
 
 #endif // hifi_LogHandler_h