From 613334074f2c8d2e7c356b3c63ad4a4322afa1e6 Mon Sep 17 00:00:00 2001 From: Stephen Birarda Date: Mon, 9 Sep 2013 15:11:11 -0700 Subject: [PATCH] leverage qDebug and custom message handler for verbose logging --- assignment-client/src/main.cpp | 19 +++++++----- interface/src/Application.cpp | 4 +-- libraries/shared/src/Assignment.cpp | 6 +--- libraries/shared/src/Assignment.h | 2 -- libraries/shared/src/Logging.cpp | 46 +++++++++++++---------------- libraries/shared/src/Logging.h | 10 +------ libraries/shared/src/Node.cpp | 12 ++++---- libraries/shared/src/Node.h | 2 -- libraries/shared/src/NodeList.cpp | 14 ++++----- libraries/shared/src/UDPSocket.cpp | 2 +- 10 files changed, 49 insertions(+), 68 deletions(-) diff --git a/assignment-client/src/main.cpp b/assignment-client/src/main.cpp index 896b69b274..0579b8bb56 100644 --- a/assignment-client/src/main.cpp +++ b/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(); diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index ea61179057..7f055abe88 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -48,7 +48,7 @@ #include #include #include -#include +#include #include #include #include @@ -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 diff --git a/libraries/shared/src/Assignment.cpp b/libraries/shared/src/Assignment.cpp index 867854030a..850922396f 100644 --- a/libraries/shared/src/Assignment.cpp +++ b/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(); } \ No newline at end of file diff --git a/libraries/shared/src/Assignment.h b/libraries/shared/src/Assignment.h index 34cf065ce5..693cc42577 100644 --- a/libraries/shared/src/Assignment.h +++ b/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 diff --git a/libraries/shared/src/Logging.cpp b/libraries/shared/src/Logging.cpp index 9da64ec271..bfdc3523f1 100644 --- a/libraries/shared/src/Logging.cpp +++ b/libraries/shared/src/Logging.cpp @@ -8,6 +8,7 @@ #include #include +#include #include #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()); } \ No newline at end of file diff --git a/libraries/shared/src/Logging.h b/libraries/shared/src/Logging.h index 705bad86b3..0bd6197b9a 100644 --- a/libraries/shared/src/Logging.h +++ b/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; diff --git a/libraries/shared/src/Node.cpp b/libraries/shared/src/Node.cpp index 09d8801068..c91626d99d 100644 --- a/libraries/shared/src/Node.cpp +++ b/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(); } diff --git a/libraries/shared/src/Node.h b/libraries/shared/src/Node.h index d22d4e0076..2de75bcec1 100644 --- a/libraries/shared/src/Node.h +++ b/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); diff --git a/libraries/shared/src/NodeList.cpp b/libraries/shared/src/NodeList.cpp index 7b0bef7002..3b16150a00 100644 --- a/libraries/shared/src/NodeList.cpp +++ b/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); diff --git a/libraries/shared/src/UDPSocket.cpp b/libraries/shared/src/UDPSocket.cpp index f2f5129181..d89265b471 100644 --- a/libraries/shared/src/UDPSocket.cpp +++ b/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() {