leverage qDebug and custom message handler for verbose logging

assignment-client/src/main.cpp

@@ -69,14 +69,14 @@ void childClient() {
             // construct the deployed assignment from the packet data
             Assignment deployedAssignment(packetData, receivedBytes);
             
-            Logging::standardizedLog(QString("Received an assignment - %1").arg(deployedAssignment.toString()));
+            qDebug() << "Received an assignment -" << deployedAssignment << "\n";
             
             // switch our nodelist DOMAIN_IP to the ip receieved in the assignment
             if (deployedAssignment.getDomainSocket()->sa_family == AF_INET) {
                 in_addr domainSocketAddr = ((sockaddr_in*) deployedAssignment.getDomainSocket())->sin_addr;
                 nodeList->setDomainIP(inet_ntoa(domainSocketAddr));
                 
-                Logging::standardizedLog(QString("Changed Domain IP to %1").arg(inet_ntoa(domainSocketAddr)));
+                qDebug("Changed Domain IP to %s\n", inet_ntoa(domainSocketAddr));
             }
             
             if (deployedAssignment.getType() == Assignment::AudioMixer) {
@@ -85,7 +85,7 @@ void childClient() {
                 AvatarMixer::run();
             }
             
-            Logging::standardizedLog(QString("Assignment finished or never started - waiting for new assignment"));
+            qDebug("Assignment finished or never started - waiting for new assignment\n");
             
             // reset our NodeList by switching back to unassigned and clearing the list
             nodeList->setOwnerType(NODE_TYPE_UNASSIGNED);
@@ -124,7 +124,7 @@ void sigchldHandler(int sig) {
                     // this is the parent, replace the dead process with the new one
                     ::childForks[i] = newForkProcessID;
                    
-                    Logging::standardizedLog(QString("Replaced dead %1 with new fork %2").arg(processID).arg(newForkProcessID));
+                    qDebug("Replaced dead %d with new fork %d\n", processID, newForkProcessID);
                     
                     break;
                 }
@@ -159,6 +159,9 @@ int main(int argc, const char* argv[]) {
     
     setvbuf(stdout, NULL, _IOLBF, 0);
     
+    // use the verbose message handler in Logging
+    qInstallMessageHandler(Logging::verboseMessageHandler);
+    
     // start the Logging class with the parent's target name
     Logging::setTargetName(PARENT_TARGET_NAME);
     
@@ -179,12 +182,12 @@ int main(int argc, const char* argv[]) {
     
     if (numForksString) {
         ::numForks = atoi(numForksString);
-        Logging::standardizedLog(QString("Starting %1 assignment clients").arg(numForks));
+        qDebug("Starting %d assignment clients\n", ::numForks);
         
-        ::childForks = new pid_t[numForks];
+        ::childForks = new pid_t[::numForks];
         
         // fire off as many children as we need (this is one less than the parent since the parent will run as well)
-        for (int i = 0; i < numForks; i++) {
+        for (int i = 0; i < ::numForks; i++) {
             processID = fork();
             
             if (processID == 0) {
@@ -197,7 +200,7 @@ int main(int argc, const char* argv[]) {
         }
     }
     
-    if (processID == 0 || numForks == 0) {
+    if (processID == 0 || ::numForks == 0) {
         childClient();
     } else {
         parentMonitor();

interface/src/Application.cpp

@@ -48,7 +48,7 @@
 #include <NodeTypes.h>
 #include <AudioInjectionManager.h>
 #include <AudioInjector.h>
-#include <Logstash.h>
+#include <Logging.h>
 #include <OctalCode.h>
 #include <PacketHeaders.h>
 #include <PairingHandler.h>
@@ -318,7 +318,7 @@ void Application::initializeGL() {
         const char LOGSTASH_INTERFACE_START_TIME_KEY[] = "interface-start-time";
         
         // ask the Logstash class to record the startup time
-        Logstash::stashValue(STAT_TYPE_TIMER, LOGSTASH_INTERFACE_START_TIME_KEY, startupTime);
+        Logging::stashValue(STAT_TYPE_TIMER, LOGSTASH_INTERFACE_START_TIME_KEY, startupTime);
     }
     
     // update before the first render

libraries/shared/src/Assignment.cpp

@@ -130,11 +130,7 @@ int Assignment::packToBuffer(unsigned char* buffer) {
     return numPackedBytes;
 }
 
-QString Assignment::toString() const {
-    return QString("T:%1 P:%2").arg(_type).arg(_pool);
-}
-
 QDebug operator<<(QDebug debug, const Assignment &assignment) {
-    debug << assignment.toString().toStdString().c_str();
+    debug << "T:" << assignment.getType() << "P:" << assignment.getPool();
     return debug.nospace();
 }

libraries/shared/src/Assignment.h

@@ -54,8 +54,6 @@ public:
     /// Sets _time to the current time given by gettimeofday
     void setCreateTimeToNow() { gettimeofday(&_time, NULL); }
     
-    QString toString() const;
-    
 private:
     Assignment::Direction _direction; /// the direction of the assignment (Create, Deploy, Request)
     Assignment::Type _type; /// the type of the assignment, defines what the assignee will do

libraries/shared/src/Logging.cpp

@@ -8,6 +8,7 @@
 
 #include <cstring>
 #include <cstdio>
+#include <iostream>
 #include <netdb.h>
 
 #include "SharedUtil.h"
@@ -60,20 +61,6 @@ void Logging::stashValue(char statType, const char* key, float value) {
     }
 }
 
-const QString DEBUG_STRING = "DEBUG";
-const QString WARN_STRING = "WARN";
-const QString ERROR_STRING = "ERROR";
-
-const QString& stringForLogType(Logging::Type logType) {
-    if (logType == Logging::Debug) {
-        return DEBUG_STRING;
-    } else if (logType == Logging::Warn) {
-        return WARN_STRING;
-    } else {
-        return ERROR_STRING;
-    }
-}
-
 void Logging::setTargetName(const char* targetName) {
     // remove the old target name, if it exists
     delete Logging::targetName;
@@ -83,22 +70,31 @@ void Logging::setTargetName(const char* targetName) {
     strcpy(Logging::targetName, targetName);
 }
 
+const char* stringForLogType(QtMsgType msgType) {
+    switch (msgType) {
+        case QtDebugMsg:
+            return "DEBUG";
+        case QtCriticalMsg:
+            return "CRITICAL";
+        case QtFatalMsg:
+            return "FATAL";
+        case QtWarningMsg:
+            return "WARNING";
+    }
+}
+
 // the following will produce 2000-10-02 13:55:36 -0700
 const char DATE_STRING_FORMAT[] = "%F %H:%M:%S %z";
 
-void Logging::standardizedLog(const char *output, Logging::Type logType) {
-    standardizedLog(QString(output), logType);
-}
-
-void Logging::standardizedLog(const QString &output, Logging::Type logType) {
-    time_t rawTime;
-    time(&rawTime);
-    struct tm* localTime = localtime(&rawTime);
-    
+void Logging::verboseMessageHandler(QtMsgType type, const QMessageLogContext& context, const QString& message) {
     // log prefix is in the following format
     // [DEBUG] [TIMESTAMP] [PID:PARENT_PID] [TARGET] logged string
     
-    QString prefixString = QString("[%1]").arg(stringForLogType(logType));
+    QString prefixString = QString("[%1]").arg(stringForLogType(type));
+    
+    time_t rawTime;
+    time(&rawTime);
+    struct tm* localTime = localtime(&rawTime);
     
     char dateString[100];
     strftime(dateString, sizeof(dateString), DATE_STRING_FORMAT, localTime);
@@ -118,5 +114,5 @@ void Logging::standardizedLog(const QString &output, Logging::Type logType) {
         prefixString.append(QString(" [%1]").arg(Logging::targetName));
     }
     
-    qDebug("%s %s", prefixString.toStdString().c_str(), output.toStdString().c_str());
+    fprintf(stdout, "%s %s", prefixString.toLocal8Bit().constData(), message.toLocal8Bit().constData());
 }

libraries/shared/src/Logging.h

@@ -22,19 +22,11 @@ const char STAT_TYPE_GAUGE = 'g';
 
 class Logging {
 public:
-    
-    enum Type {
-        Error,
-        Warn,
-        Debug
-    };
-    
     static sockaddr* socket();
     static bool shouldSendStats();
     static void stashValue(char statType, const char* key, float value);
     static void setTargetName(const char* targetName);
-    static void standardizedLog(const char* output, Logging::Type logType = Logging::Debug);
-    static void standardizedLog(const QString& output, Logging::Type logType = Logging::Debug);
+    static void verboseMessageHandler(QtMsgType type, const QMessageLogContext& context, const QString &message);
 private:
     static sockaddr_in logstashSocket;
     static char* targetName;

libraries/shared/src/Node.cpp

@@ -144,16 +144,14 @@ float Node::getAverageKilobitsPerSecond() {
     }
 }
 
-QString Node::toString() const {
+QDebug operator<<(QDebug debug, const Node &node) {
     char publicAddressBuffer[16] = {'\0'};
-    unsigned short publicAddressPort = loadBufferWithSocketInfo(publicAddressBuffer, _publicSocket);
+    unsigned short publicAddressPort = loadBufferWithSocketInfo(publicAddressBuffer, node.getPublicSocket());
     
     //char localAddressBuffer[16] = {'\0'};
     //unsigned short localAddressPort = loadBufferWithSocketInfo(localAddressBuffer, node.localSocket);
     
-    return QString("# %1 %2 %3 %4:%5").arg(_nodeID).arg(getTypeName()).arg(_type).arg(publicAddressBuffer).arg(publicAddressPort);
-}
-
-QDebug operator<<(QDebug debug, const Node &node) {
-    return debug << node.toString();
+    debug << "#" << node.getNodeID() << node.getTypeName() << node.getType();
+    debug.nospace() << publicAddressBuffer << ":" << publicAddressPort;
+    return debug.nospace();
 }

libraries/shared/src/Node.h

@@ -72,8 +72,6 @@ public:
     void unlock() { pthread_mutex_unlock(&_mutex); }
 
     static void printLog(Node const&);
-    
-    QString toString() const;
 private:
     // privatize copy and assignment operator to disallow Node copying
     Node(const Node &otherNode);

libraries/shared/src/NodeList.cpp

@@ -44,7 +44,7 @@ NodeList* NodeList::createInstance(char ownerType, unsigned short int socketList
     if (!_sharedInstance) {
         _sharedInstance = new NodeList(ownerType, socketListenPort);
     } else {
-        Logging::standardizedLog("NodeList createInstance called with existing instance.");
+        qDebug("NodeList createInstance called with existing instance.");
     }
     
     return _sharedInstance;
@@ -52,7 +52,7 @@ NodeList* NodeList::createInstance(char ownerType, unsigned short int socketList
 
 NodeList* NodeList::getInstance() {
     if (!_sharedInstance) {
-        Logging::standardizedLog("NodeList getInstance called before call to createInstance. Returning NULL pointer.");
+        qDebug("NodeList getInstance called before call to createInstance. Returning NULL pointer.");
     }
     
     return _sharedInstance;
@@ -279,12 +279,12 @@ void NodeList::sendDomainServerCheckIn() {
             sockaddr_in tempAddress;
             memcpy(&tempAddress.sin_addr, pHostInfo->h_addr_list[0], pHostInfo->h_length);
             strcpy(_domainIP, inet_ntoa(tempAddress.sin_addr));
-            Logging::standardizedLog(QString("Domain Server: %1").arg(_domainHostname));
+            qDebug("Domain Server: %s", _domainHostname);
         } else {
-            Logging::standardizedLog("Failed domain server lookup", Logging::Warn);
+            qDebug("Failed domain server lookup");
         }
     } else if (!printedDomainServerIP) {
-        Logging::standardizedLog(QString("Domain Server IP: %1").arg(_domainIP));
+        qDebug("Domain Server IP: %s", _domainIP);
         printedDomainServerIP = true;
     }
     
@@ -460,7 +460,7 @@ void NodeList::addNodeToList(Node* newNode) {
     
     ++_numNodes;
     
-    Logging::standardizedLog(QString("Added %1").arg(newNode->toString()));
+    qDebug() << "Added" << *newNode << "\n";
     
     notifyHooksOfAddedNode(newNode);
 }
@@ -516,7 +516,7 @@ void* removeSilentNodes(void *args) {
             
             if ((checkTimeUSecs - node->getLastHeardMicrostamp()) > NODE_SILENCE_THRESHOLD_USECS) {
             
-                Logging::standardizedLog(QString("Killed %1").arg(node->toString()));
+                qDebug() << "Killed " << *node << "\n";
                 
                 nodeList->notifyHooksOfKilledNode(&*node);
                 

libraries/shared/src/UDPSocket.cpp

@@ -171,7 +171,7 @@ UDPSocket::UDPSocket(unsigned short int listeningPort) :
     const int DEFAULT_BLOCKING_SOCKET_TIMEOUT_USECS = 0.5 * 1000000;
     setBlockingReceiveTimeoutInUsecs(DEFAULT_BLOCKING_SOCKET_TIMEOUT_USECS);
     
-    Logging::standardizedLog(QString("Created UDP Socket listening on %1").arg(_listeningPort));
+    qDebug("Created UDP Socket listening on %hd\n", _listeningPort);
 }
 
 UDPSocket::~UDPSocket() {