From 8077963bb1d2641b04bf8eeddc9f2a44f18aefc4 Mon Sep 17 00:00:00 2001 From: Stephen Birarda Date: Mon, 9 Sep 2013 14:21:33 -0700 Subject: [PATCH] add standardized logging and leverage forked assignment clients --- assignment-client/src/main.cpp | 20 ++-- domain-server/src/main.cpp | 6 +- libraries/audio/src/AudioMixer.cpp | 14 +-- libraries/shared/src/Assignment.cpp | 6 +- libraries/shared/src/Assignment.h | 2 + libraries/shared/src/Logging.cpp | 106 ++++++++++++++++++ .../shared/src/{Logstash.h => Logging.h} | 18 ++- libraries/shared/src/Logstash.cpp | 60 ---------- 8 files changed, 150 insertions(+), 82 deletions(-) create mode 100644 libraries/shared/src/Logging.cpp rename libraries/shared/src/{Logstash.h => Logging.h} (66%) delete mode 100644 libraries/shared/src/Logstash.cpp diff --git a/assignment-client/src/main.cpp b/assignment-client/src/main.cpp index 130cca9135..9259e503e3 100644 --- a/assignment-client/src/main.cpp +++ b/assignment-client/src/main.cpp @@ -15,11 +15,14 @@ #include #include #include +#include #include #include #include const long long ASSIGNMENT_REQUEST_INTERVAL_USECS = 1 * 1000 * 1000; +const char PARENT_TARGET_NAME[] = "assignment-client-monitor"; +const char CHILD_TARGET_NAME[] = "assignment-client"; pid_t* childForks = NULL; sockaddr_in customAssignmentSocket = {}; @@ -61,14 +64,15 @@ void childClient() { // construct the deployed assignment from the packet data Assignment deployedAssignment(packetData, receivedBytes); - qDebug() << "Received an assignment - " << deployedAssignment << "\n"; + Logging::standardizedLog(QString("Received an assignment - %1").arg(deployedAssignment.toString()), + CHILD_TARGET_NAME); // 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)); - qDebug() << "Changed domain IP to " << inet_ntoa(domainSocketAddr); + Logging::standardizedLog(QString("Changed Domain IP to %1").arg(inet_ntoa(domainSocketAddr)), CHILD_TARGET_NAME); } if (deployedAssignment.getType() == Assignment::AudioMixer) { @@ -77,7 +81,8 @@ void childClient() { AvatarMixer::run(); } - qDebug() << "Assignment finished or never started - waiting for new assignment"; + Logging::standardizedLog(QString("Assignment finished or never started - waiting for new assignment"), + CHILD_TARGET_NAME); // reset our NodeList by switching back to unassigned and clearing the list nodeList->setOwnerType(NODE_TYPE_UNASSIGNED); @@ -96,14 +101,11 @@ void sigchldHandler(int sig) { break; } - qDebug() << "Handling death of" << processID; - int newForkProcessID = 0; // find the dead process in the array of child forks for (int i = 0; i < ::numForks; i++) { if (::childForks[i] == processID) { - qDebug() << "Matched" << ::childForks[i] << "with" << processID; newForkProcessID = fork(); if (newForkProcessID == 0) { @@ -115,6 +117,10 @@ void sigchldHandler(int sig) { } else { // this is the parent, replace the dead process with the new one ::childForks[i] = newForkProcessID; + + Logging::standardizedLog(QString("Repleaced dead %1 with new fork %2").arg(processID).arg(newForkProcessID), + PARENT_TARGET_NAME); + break; } } @@ -165,7 +171,7 @@ int main(int argc, const char* argv[]) { if (numForksString) { ::numForks = atoi(numForksString); - qDebug() << "Starting" << numForks << "assignment clients."; + Logging::standardizedLog(QString("Starting %1 assignment clients").arg(numForks), PARENT_TARGET_NAME); ::childForks = new pid_t[numForks]; diff --git a/domain-server/src/main.cpp b/domain-server/src/main.cpp index 0d51671e0c..5739639f95 100644 --- a/domain-server/src/main.cpp +++ b/domain-server/src/main.cpp @@ -28,7 +28,7 @@ #include "Assignment.h" #include "NodeList.h" #include "NodeTypes.h" -#include "Logstash.h" +#include "Logging.h" #include "PacketHeaders.h" #include "SharedUtil.h" @@ -234,12 +234,12 @@ int main(int argc, const char* argv[]) { } } - if (Logstash::shouldSendStats()) { + if (Logging::shouldSendStats()) { if (usecTimestampNow() - usecTimestamp(&lastStatSendTime) >= (NODE_COUNT_STAT_INTERVAL_MSECS * 1000)) { // time to send our count of nodes and servers to logstash const char NODE_COUNT_LOGSTASH_KEY[] = "ds-node-count"; - Logstash::stashValue(STAT_TYPE_TIMER, NODE_COUNT_LOGSTASH_KEY, nodeList->getNumAliveNodes()); + Logging::stashValue(STAT_TYPE_TIMER, NODE_COUNT_LOGSTASH_KEY, nodeList->getNumAliveNodes()); gettimeofday(&lastStatSendTime, NULL); } diff --git a/libraries/audio/src/AudioMixer.cpp b/libraries/audio/src/AudioMixer.cpp index c6387ce02a..b11aa9c14b 100644 --- a/libraries/audio/src/AudioMixer.cpp +++ b/libraries/audio/src/AudioMixer.cpp @@ -32,7 +32,7 @@ #include #include -#include +#include #include #include #include @@ -105,8 +105,8 @@ void AudioMixer::run() { stk::StkFrames stkFrameBuffer(BUFFER_LENGTH_SAMPLES_PER_CHANNEL, 1); // if we'll be sending stats, call the Logstash::socket() method to make it load the logstash IP outside the loop - if (Logstash::shouldSendStats()) { - Logstash::socket(); + if (Logging::shouldSendStats()) { + Logging::socket(); } while (true) { @@ -114,7 +114,7 @@ void AudioMixer::run() { break; } - if (Logstash::shouldSendStats()) { + if (Logging::shouldSendStats()) { gettimeofday(&beginSendTime, NULL); } @@ -123,12 +123,12 @@ void AudioMixer::run() { gettimeofday(&lastDomainServerCheckIn, NULL); NodeList::getInstance()->sendDomainServerCheckIn(); - if (Logstash::shouldSendStats() && numStatCollections > 0) { + if (Logging::shouldSendStats() && numStatCollections > 0) { // if we should be sending stats to Logstash send the appropriate average now const char MIXER_LOGSTASH_METRIC_NAME[] = "audio-mixer-frame-time-usage"; float averageFrameTimePercentage = sumFrameTimePercentages / numStatCollections; - Logstash::stashValue(STAT_TYPE_TIMER, MIXER_LOGSTASH_METRIC_NAME, averageFrameTimePercentage); + Logging::stashValue(STAT_TYPE_TIMER, MIXER_LOGSTASH_METRIC_NAME, averageFrameTimePercentage); sumFrameTimePercentages = 0.0f; numStatCollections = 0; @@ -398,7 +398,7 @@ void AudioMixer::run() { } } - if (Logstash::shouldSendStats()) { + if (Logging::shouldSendStats()) { // send a packet to our logstash instance // calculate the percentage value for time elapsed for this send (of the max allowable time) diff --git a/libraries/shared/src/Assignment.cpp b/libraries/shared/src/Assignment.cpp index 850922396f..867854030a 100644 --- a/libraries/shared/src/Assignment.cpp +++ b/libraries/shared/src/Assignment.cpp @@ -130,7 +130,11 @@ 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 << "T:" << assignment.getType() << "P:" << assignment.getPool(); + debug << assignment.toString().toStdString().c_str(); return debug.nospace(); } \ No newline at end of file diff --git a/libraries/shared/src/Assignment.h b/libraries/shared/src/Assignment.h index 693cc42577..34cf065ce5 100644 --- a/libraries/shared/src/Assignment.h +++ b/libraries/shared/src/Assignment.h @@ -54,6 +54,8 @@ 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 new file mode 100644 index 0000000000..cb4c249620 --- /dev/null +++ b/libraries/shared/src/Logging.cpp @@ -0,0 +1,106 @@ +// +// Logging.cpp +// hifi +// +// Created by Stephen Birarda on 6/11/13. +// Copyright (c) 2013 HighFidelity, Inc. All rights reserved. +// + +#include +#include +#include + +#include "SharedUtil.h" +#include "NodeList.h" + +#include "Logging.h" + +sockaddr_in Logging::logstashSocket = {}; + +sockaddr* Logging::socket() { + + if (logstashSocket.sin_addr.s_addr == 0) { + // we need to construct the socket object + + // assume IPv4 + logstashSocket.sin_family = AF_INET; + + // use the constant port + logstashSocket.sin_port = htons(LOGSTASH_UDP_PORT); + + // lookup the IP address for the constant hostname + struct hostent* logstashHostInfo; + if ((logstashHostInfo = gethostbyname(LOGSTASH_HOSTNAME))) { + memcpy(&logstashSocket.sin_addr, logstashHostInfo->h_addr_list[0], logstashHostInfo->h_length); + } else { + printf("Failed to lookup logstash IP - will try again on next log attempt.\n"); + } + } + + return (sockaddr*) &logstashSocket; +} + +bool Logging::shouldSendStats() { + static bool shouldSendStats = isInEnvironment("production"); + return shouldSendStats; +} + +void Logging::stashValue(char statType, const char* key, float value) { + static char logstashPacket[MAX_PACKET_SIZE]; + + // load up the logstash packet with the key and the passed float value + // send it to 4 decimal places + int numPacketBytes = sprintf(logstashPacket, "%c %s %.4f", statType, key, value); + + NodeList *nodeList = NodeList::getInstance(); + + if (nodeList) { + nodeList->getNodeSocket()->send(socket(), logstashPacket, numPacketBytes); + } +} + +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; + } +} + +// 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 QString &output, const char* targetName, Logging::Type logType) { + time_t rawTime; + time(&rawTime); + struct tm* localTime = localtime(&rawTime); + + // log prefix is in the following format + // [DEBUG] [TIMESTAMP] [PID:PARENT_PID] [TARGET] logged string + + QString prefixString = QString("[%1] ").arg(stringForLogType(logType)); + + char dateString[100]; + strftime(dateString, sizeof(dateString), DATE_STRING_FORMAT, localTime); + + prefixString.append(QString("[%1] ").arg(dateString)); + + prefixString.append(QString("[%1").arg(getpid())); + + pid_t parentProcessID = getppid(); + if (parentProcessID != 0) { + prefixString.append(QString(":%1] ").arg(parentProcessID)); + } else { + prefixString.append("]"); + } + + prefixString.append(QString("[%1]").arg(targetName)); + + qDebug("%s %s", prefixString.toStdString().c_str(), output.toStdString().c_str()); +} \ No newline at end of file diff --git a/libraries/shared/src/Logstash.h b/libraries/shared/src/Logging.h similarity index 66% rename from libraries/shared/src/Logstash.h rename to libraries/shared/src/Logging.h index 7c805ddb23..c8f12ac8b6 100644 --- a/libraries/shared/src/Logstash.h +++ b/libraries/shared/src/Logging.h @@ -1,16 +1,18 @@ // -// Logstash.h +// Logging.h // hifi // // Created by Stephen Birarda on 6/11/13. // Copyright (c) 2013 HighFidelity, Inc. All rights reserved. // -#ifndef __hifi__Logstash__ -#define __hifi__Logstash__ +#ifndef __hifi__Logging__ +#define __hifi__Logging__ #include +#include + const int LOGSTASH_UDP_PORT = 9500; const char LOGSTASH_HOSTNAME[] = "graphite.highfidelity.io"; @@ -18,11 +20,19 @@ const char STAT_TYPE_TIMER = 't'; const char STAT_TYPE_COUNTER = 'c'; const char STAT_TYPE_GAUGE = 'g'; -class Logstash { +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 standardizedLog(const QString& output, const char* targetName, Logging::Type logType = Logging::Debug); private: static sockaddr_in logstashSocket; }; diff --git a/libraries/shared/src/Logstash.cpp b/libraries/shared/src/Logstash.cpp deleted file mode 100644 index 63d3da56d9..0000000000 --- a/libraries/shared/src/Logstash.cpp +++ /dev/null @@ -1,60 +0,0 @@ -// -// Logstash.cpp -// hifi -// -// Created by Stephen Birarda on 6/11/13. -// Copyright (c) 2013 HighFidelity, Inc. All rights reserved. -// - -#include -#include -#include - -#include "SharedUtil.h" -#include "NodeList.h" - -#include "Logstash.h" - -sockaddr_in Logstash::logstashSocket = {}; - -sockaddr* Logstash::socket() { - - if (logstashSocket.sin_addr.s_addr == 0) { - // we need to construct the socket object - - // assume IPv4 - logstashSocket.sin_family = AF_INET; - - // use the constant port - logstashSocket.sin_port = htons(LOGSTASH_UDP_PORT); - - // lookup the IP address for the constant hostname - struct hostent* logstashHostInfo; - if ((logstashHostInfo = gethostbyname(LOGSTASH_HOSTNAME))) { - memcpy(&logstashSocket.sin_addr, logstashHostInfo->h_addr_list[0], logstashHostInfo->h_length); - } else { - printf("Failed to lookup logstash IP - will try again on next log attempt.\n"); - } - } - - return (sockaddr*) &logstashSocket; -} - -bool Logstash::shouldSendStats() { - static bool shouldSendStats = isInEnvironment("production"); - return shouldSendStats; -} - -void Logstash::stashValue(char statType, const char* key, float value) { - static char logstashPacket[MAX_PACKET_SIZE]; - - // load up the logstash packet with the key and the passed float value - // send it to 4 decimal places - int numPacketBytes = sprintf(logstashPacket, "%c %s %.4f", statType, key, value); - - NodeList *nodeList = NodeList::getInstance(); - - if (nodeList) { - nodeList->getNodeSocket()->send(socket(), logstashPacket, numPacketBytes); - } -} \ No newline at end of file