diff --git a/assignment-client/src/main.cpp b/assignment-client/src/main.cpp index 130cca9135..0579b8bb56 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 = {}; @@ -29,6 +32,9 @@ int numForks = 0; void childClient() { // this is one of the child forks or there is a single assignment client, continue assignment-client execution + // set the logging target to the the CHILD_TARGET_NAME + Logging::setTargetName(CHILD_TARGET_NAME); + // create a NodeList as an unassigned client NodeList* nodeList = NodeList::createInstance(NODE_TYPE_UNASSIGNED); @@ -58,17 +64,19 @@ void childClient() { if (nodeList->getNodeSocket()->receive(packetData, &receivedBytes) && packetData[0] == PACKET_TYPE_DEPLOY_ASSIGNMENT && packetVersionMatch(packetData)) { + + // construct the deployed assignment from the packet data Assignment deployedAssignment(packetData, receivedBytes); - qDebug() << "Received an assignment - " << deployedAssignment << "\n"; + 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)); - qDebug() << "Changed domain IP to " << inet_ntoa(domainSocketAddr); + qDebug("Changed Domain IP to %s\n", inet_ntoa(domainSocketAddr)); } if (deployedAssignment.getType() == Assignment::AudioMixer) { @@ -77,11 +85,14 @@ void childClient() { AvatarMixer::run(); } - qDebug() << "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); nodeList->clear(); + + // reset the logging target to the the CHILD_TARGET_NAME + Logging::setTargetName(CHILD_TARGET_NAME); } } } @@ -96,14 +107,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 +123,9 @@ void sigchldHandler(int sig) { } else { // this is the parent, replace the dead process with the new one ::childForks[i] = newForkProcessID; + + qDebug("Replaced dead %d with new fork %d\n", processID, newForkProcessID); + break; } } @@ -148,6 +159,12 @@ 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); + // grab the overriden assignment-server hostname from argv, if it exists const char* customAssignmentServer = getCmdOption(argc, argv, "-a"); if (customAssignmentServer) { @@ -165,12 +182,12 @@ int main(int argc, const char* argv[]) { if (numForksString) { ::numForks = atoi(numForksString); - qDebug() << "Starting" << numForks << "assignment clients."; + 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) { @@ -183,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/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/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/audio/src/AudioMixer.cpp b/libraries/audio/src/AudioMixer.cpp index c6387ce02a..d4b6097134 100644 --- a/libraries/audio/src/AudioMixer.cpp +++ b/libraries/audio/src/AudioMixer.cpp @@ -32,7 +32,7 @@ #include #include -#include +#include #include #include #include @@ -57,6 +57,8 @@ const unsigned int BUFFER_SEND_INTERVAL_USECS = floorf((BUFFER_LENGTH_SAMPLES_PE const int MAX_SAMPLE_VALUE = std::numeric_limits::max(); const int MIN_SAMPLE_VALUE = std::numeric_limits::min(); +const char AUDIO_MIXER_LOGGING_TARGET_NAME[] = "audio-mixer"; + void attachNewBufferToNode(Node *newNode) { if (!newNode->getLinkedData()) { if (newNode->getType() == NODE_TYPE_AGENT) { @@ -68,6 +70,8 @@ void attachNewBufferToNode(Node *newNode) { } void AudioMixer::run() { + // change the logging target name while this is running + Logging::setTargetName(AUDIO_MIXER_LOGGING_TARGET_NAME); NodeList *nodeList = NodeList::getInstance(); nodeList->setOwnerType(NODE_TYPE_AUDIO_MIXER); @@ -105,8 +109,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 +118,7 @@ void AudioMixer::run() { break; } - if (Logstash::shouldSendStats()) { + if (Logging::shouldSendStats()) { gettimeofday(&beginSendTime, NULL); } @@ -123,12 +127,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 +402,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/avatars/src/AvatarMixer.cpp b/libraries/avatars/src/AvatarMixer.cpp index 92e27a64af..acf77be8da 100644 --- a/libraries/avatars/src/AvatarMixer.cpp +++ b/libraries/avatars/src/AvatarMixer.cpp @@ -10,6 +10,7 @@ // The avatar mixer receives head, hand and positional data from all connected // nodes, and broadcasts that data back to them, every BROADCAST_INTERVAL ms. +#include #include #include #include @@ -18,6 +19,8 @@ #include "AvatarMixer.h" +const char AVATAR_MIXER_LOGGING_NAME[] = "avatar-mixer"; + unsigned char* addNodeToBroadcastPacket(unsigned char *currentPosition, Node *nodeToAdd) { currentPosition += packNodeId(currentPosition, nodeToAdd->getNodeID()); @@ -81,6 +84,9 @@ void broadcastAvatarData(NodeList* nodeList, sockaddr* nodeAddress) { } void AvatarMixer::run() { + // change the logging target name while AvatarMixer is running + Logging::setTargetName(AVATAR_MIXER_LOGGING_NAME); + NodeList* nodeList = NodeList::getInstance(); nodeList->setOwnerType(NODE_TYPE_AVATAR_MIXER); diff --git a/libraries/shared/src/Logging.cpp b/libraries/shared/src/Logging.cpp new file mode 100644 index 0000000000..bfdc3523f1 --- /dev/null +++ b/libraries/shared/src/Logging.cpp @@ -0,0 +1,118 @@ +// +// Logging.cpp +// hifi +// +// Created by Stephen Birarda on 6/11/13. +// Copyright (c) 2013 HighFidelity, Inc. All rights reserved. +// + +#include +#include +#include +#include + +#include "SharedUtil.h" +#include "NodeList.h" + +#include "Logging.h" + +sockaddr_in Logging::logstashSocket = {}; +char* Logging::targetName = NULL; + +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); + } +} + +void Logging::setTargetName(const char* targetName) { + // remove the old target name, if it exists + delete Logging::targetName; + + // copy over the new target name + Logging::targetName = new char[strlen(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::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(type)); + + time_t rawTime; + time(&rawTime); + struct tm* localTime = localtime(&rawTime); + + 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("]"); + } + + if (Logging::targetName) { + prefixString.append(QString(" [%1]").arg(Logging::targetName)); + } + + 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 new file mode 100644 index 0000000000..c4f921070a --- /dev/null +++ b/libraries/shared/src/Logging.h @@ -0,0 +1,51 @@ +// +// Logging.h +// hifi +// +// Created by Stephen Birarda on 6/11/13. +// Copyright (c) 2013 HighFidelity, Inc. All rights reserved. +// + +#ifndef __hifi__Logging__ +#define __hifi__Logging__ + +#include + +#include + +const int LOGSTASH_UDP_PORT = 9500; +const char LOGSTASH_HOSTNAME[] = "graphite.highfidelity.io"; + +const char STAT_TYPE_TIMER = 't'; +const char STAT_TYPE_COUNTER = 'c'; +const char STAT_TYPE_GAUGE = 'g'; + +/// Handles custom message handling and sending of stats/logs to Logstash instance +class Logging { +public: + /// \return the socket used to send stats to logstash + static sockaddr* socket(); + + /// checks if this target should send stats to logstash, given its current environment + /// \return true if the caller should send stats to logstash + static bool shouldSendStats(); + + /// stashes a float value to Logstash instance + /// \param statType a stat type from the constants in this file + /// \param key the key at which to store the stat + /// \param value the value to store + static void stashValue(char statType, const char* key, float value); + + /// sets the target name to output via the verboseMessageHandler, called once before logging begins + /// \param targetName the desired target name to output in logs + static void setTargetName(const char* targetName); + + /// 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); +private: + static sockaddr_in logstashSocket; + static char* targetName; +}; + +#endif /* defined(__hifi__Logstash__) */ 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 diff --git a/libraries/shared/src/Logstash.h b/libraries/shared/src/Logstash.h deleted file mode 100644 index 7c805ddb23..0000000000 --- a/libraries/shared/src/Logstash.h +++ /dev/null @@ -1,30 +0,0 @@ -// -// Logstash.h -// hifi -// -// Created by Stephen Birarda on 6/11/13. -// Copyright (c) 2013 HighFidelity, Inc. All rights reserved. -// - -#ifndef __hifi__Logstash__ -#define __hifi__Logstash__ - -#include - -const int LOGSTASH_UDP_PORT = 9500; -const char LOGSTASH_HOSTNAME[] = "graphite.highfidelity.io"; - -const char STAT_TYPE_TIMER = 't'; -const char STAT_TYPE_COUNTER = 'c'; -const char STAT_TYPE_GAUGE = 'g'; - -class Logstash { -public: - static sockaddr* socket(); - static bool shouldSendStats(); - static void stashValue(char statType, const char* key, float value); -private: - static sockaddr_in logstashSocket; -}; - -#endif /* defined(__hifi__Logstash__) */ diff --git a/libraries/shared/src/NodeList.cpp b/libraries/shared/src/NodeList.cpp index 4d042b0f63..a982e22242 100644 --- a/libraries/shared/src/NodeList.cpp +++ b/libraries/shared/src/NodeList.cpp @@ -14,6 +14,7 @@ #include #include "Assignment.h" +#include "Logging.h" #include "NodeList.h" #include "NodeTypes.h" #include "PacketHeaders.h" @@ -43,7 +44,7 @@ NodeList* NodeList::createInstance(char ownerType, unsigned short int socketList if (!_sharedInstance) { _sharedInstance = new NodeList(ownerType, socketListenPort); } else { - qDebug("NodeList createInstance called with existing instance.\n"); + qDebug("NodeList createInstance called with existing instance."); } return _sharedInstance; @@ -51,7 +52,7 @@ NodeList* NodeList::createInstance(char ownerType, unsigned short int socketList NodeList* NodeList::getInstance() { if (!_sharedInstance) { - qDebug("NodeList getInstance called before call to createInstance. Returning NULL pointer.\n"); + qDebug("NodeList getInstance called before call to createInstance. Returning NULL pointer."); } return _sharedInstance; @@ -278,7 +279,6 @@ 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)); - qDebug("Domain Server: %s\n", _domainHostname); } else { qDebug("Failed domain server lookup\n"); @@ -516,7 +516,7 @@ void* removeSilentNodes(void *args) { if ((checkTimeUSecs - node->getLastHeardMicrostamp()) > NODE_SILENCE_THRESHOLD_USECS) { - qDebug() << "Killed" << *node << "\n"; + qDebug() << "Killed " << *node << "\n"; nodeList->notifyHooksOfKilledNode(&*node); diff --git a/libraries/shared/src/UDPSocket.cpp b/libraries/shared/src/UDPSocket.cpp index ab2460dd7f..d89265b471 100644 --- a/libraries/shared/src/UDPSocket.cpp +++ b/libraries/shared/src/UDPSocket.cpp @@ -23,6 +23,7 @@ #include +#include "Logging.h" #include "UDPSocket.h" sockaddr_in destSockaddr, senderAddress; @@ -170,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); - qDebug("Created UDP socket listening on port %hu.\n", _listeningPort); + qDebug("Created UDP Socket listening on %hd\n", _listeningPort); } UDPSocket::~UDPSocket() {