Mirrors/overte
3
0
Fork 0
mirror of https://github.com/overte-org/overte.git synced 2025-04-20 12:04:18 +02:00
Code Issues Projects Releases Packages Wiki Activity Actions

Merge pull request #3681 from birarda/verbose-log-silencer

Browse source 
logging tweaks to reduce spam from repeated log messages
This commit is contained in:
Brad Hefta-Gaub 2014-10-28 17:58:17 -07:00
commit be65a798db
16 changed files with 238 additions and 211 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
assignment-client/src/AssignmentClient.cpp
View file

@ -16,7 +16,7 @@
#include <AccountManager.h>
#include <Assignment.h>
#include <HifiConfigVariantMap.h>
#include <Logging.h>
#include <LogHandler.h>
#include <LogUtils.h>
#include <NodeList.h>
#include <PacketHeaders.h>
@ -51,7 +51,7 @@ AssignmentClient::AssignmentClient(int &argc, char **argv) :
connect(&_shutdownEventListener, SIGNAL(receivedCloseEvent()), SLOT(quit()));
// set the logging target to the the CHILD_TARGET_NAME
Logging::setTargetName(ASSIGNMENT_CLIENT_TARGET_NAME);
LogHandler::getInstance().setTargetName(ASSIGNMENT_CLIENT_TARGET_NAME);
const QVariantMap argumentVariantMap = HifiConfigVariantMap::mergeCLParametersWithJSONConfig(arguments());
@ -218,7 +218,7 @@ void AssignmentClient::handleAuthenticationRequest() {
void AssignmentClient::assignmentCompleted() {
// reset the logging target to the the CHILD_TARGET_NAME
Logging::setTargetName(ASSIGNMENT_CLIENT_TARGET_NAME);
LogHandler::getInstance().setTargetName(ASSIGNMENT_CLIENT_TARGET_NAME);
qDebug("Assignment finished or never started - waiting for new assignment.");

4
assignment-client/src/AssignmentClientMonitor.cpp
View file

@ -9,7 +9,7 @@
// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
//
#include <Logging.h>
#include <LogHandler.h>
#include "AssignmentClientMonitor.h"
@ -21,7 +21,7 @@ AssignmentClientMonitor::AssignmentClientMonitor(int &argc, char **argv, int num
QCoreApplication(argc, argv)
{
// start the Logging class with the parent's target name
Logging::setTargetName(ASSIGNMENT_CLIENT_MONITOR_TARGET_NAME);
LogHandler::getInstance().setTargetName(ASSIGNMENT_CLIENT_MONITOR_TARGET_NAME);
_childArguments = arguments();

2
assignment-client/src/audio/AudioMixer.cpp
View file

@ -41,7 +41,7 @@
#include <QtNetwork/QNetworkRequest>
#include <QtNetwork/QNetworkReply>
#include <Logging.h>
#include <LogHandler.h>
#include <NetworkAccessManager.h>
#include <NodeList.h>
#include <Node.h>

2
assignment-client/src/avatars/AvatarMixer.cpp
View file

@ -15,7 +15,7 @@
#include <QtCore/QTimer>
#include <QtCore/QThread>
#include <Logging.h>
#include <LogHandler.h>
#include <NodeList.h>
#include <PacketHeaders.h>
#include <SharedUtil.h>

4
assignment-client/src/main.cpp
View file

@ -9,7 +9,7 @@
// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
//
#include <Logging.h>
#include <LogHandler.h>
#include <SharedUtil.h>
#include "Assignment.h"
@ -22,7 +22,7 @@ int main(int argc, char* argv[]) {
#endif
// use the verbose message handler in Logging
qInstallMessageHandler(Logging::verboseMessageHandler);
qInstallMessageHandler(LogHandler::verboseMessageHandler);
const char* numForksString = getCmdOption(argc, (const char**)argv, NUM_FORKS_PARAMETER);

4
assignment-client/src/octree/OctreeServer.cpp
View file

@ -18,7 +18,7 @@
#include <AccountManager.h>
#include <HTTPConnection.h>
#include <Logging.h>
#include <LogHandler.h>
#include <UUID.h>
#include "../AssignmentClient.h"
@ -923,7 +923,7 @@ void OctreeServer::run() {
beforeRun(); // after payload has been processed
qInstallMessageHandler(Logging::verboseMessageHandler);
qInstallMessageHandler(LogHandler::verboseMessageHandler);
const char* STATUS_PORT = "--statusPort";
const char* statusPort = getCmdOption(_argc, _argv, STATUS_PORT);

4
domain-server/src/main.cpp
View file

@ -17,7 +17,7 @@
#include <QtCore/QCoreApplication>
#include <Logging.h>
#include <LogHandler.h>
#include <SharedUtil.h>
#include "DomainServer.h"
@ -27,7 +27,7 @@ int main(int argc, char* argv[]) {
setvbuf(stdout, NULL, _IOLBF, 0);
#endif
qInstallMessageHandler(Logging::verboseMessageHandler);
qInstallMessageHandler(LogHandler::verboseMessageHandler);
int currentExitCode = 0;

4
ice-server/src/main.cpp
View file

@ -11,7 +11,7 @@
#include <QtCore/QCoreApplication>
#include <Logging.h>
#include <LogHandler.h>
#include "IceServer.h"
@ -20,7 +20,7 @@ int main(int argc, char* argv[]) {
setvbuf(stdout, NULL, _IOLBF, 0);
#endif
qInstallMessageHandler(Logging::verboseMessageHandler);
qInstallMessageHandler(LogHandler::verboseMessageHandler);
IceServer iceServer(argc, argv);
return iceServer.exec();

16
interface/src/Application.cpp
View file

@ -58,7 +58,7 @@
#include <HFActionEvent.h>
#include <HFBackEvent.h>
#include <LocalVoxelsList.h>
#include <Logging.h>
#include <LogHandler.h>
#include <NetworkAccessManager.h>
#include <OctalCode.h>
#include <OctreeSceneStats.h>
@ -116,12 +116,10 @@ const QString SKIP_FILENAME = QStandardPaths::writableLocation(QStandardPaths::D
const QString DEFAULT_SCRIPTS_JS_URL = "http://public.highfidelity.io/scripts/defaultScripts.js";
void messageHandler(QtMsgType type, const QMessageLogContext& context, const QString& message) {
if (message.size() > 0) {
QString dateString = QDateTime::currentDateTime().toTimeSpec(Qt::LocalTime).toString(Qt::ISODate);
QString formattedMessage = QString("[%1] %2\n").arg(dateString).arg(message);
fprintf(stdout, "%s", qPrintable(formattedMessage));
Application::getInstance()->getLogger()->addMessage(qPrintable(formattedMessage));
QString logMessage = LogHandler::getInstance().printMessage((LogMsgType) type, context, message);
if (!logMessage.isEmpty()) {
Application::getInstance()->getLogger()->addMessage(qPrintable(logMessage));
}
}
@ -581,10 +579,6 @@ void Application::initializeGL() {
float startupTime = (float)_applicationStartupTime.elapsed() / 1000.0;
_justStarted = false;
qDebug("Startup time: %4.2f seconds.", startupTime);
const char LOGSTASH_INTERFACE_START_TIME_KEY[] = "interface-start-time";
// ask the Logstash class to record the startup time
Logging::stashValue(STAT_TYPE_TIMER, LOGSTASH_INTERFACE_START_TIME_KEY, startupTime);
}
// update before the first render

8
libraries/networking/src/LimitedNodeList.cpp
View file

@ -19,10 +19,11 @@
#include <QtCore/QUrl>
#include <QtNetwork/QHostInfo>
#include <LogHandler.h>
#include "AccountManager.h"
#include "Assignment.h"
#include "HifiSockAddr.h"
#include "Logging.h"
#include "LimitedNodeList.h"
#include "PacketHeaders.h"
#include "SharedUtil.h"
@ -211,8 +212,11 @@ bool LimitedNodeList::packetVersionAndHashMatch(const QByteArray& packet) {
<< uuidFromPacketHeader(packet);
}
} else {
static QString repeatedMessage
= LogHandler::getInstance().addRepeatedMessageRegex("Packet of type \\d+ received from unknown node with UUID");
qDebug() << "Packet of type" << checkType << "received from unknown node with UUID"
<< uuidFromPacketHeader(packet);
<< qPrintable(uuidStringWithoutCurlyBraces(uuidFromPacketHeader(packet)));
}
} else {
return true;

126
libraries/networking/src/Logging.cpp
View file

@ -1,126 +0,0 @@
//
// Logging.cpp
// libraries/networking/src
//
// Created by Stephen Birarda on 6/11/13.
// Copyright 2013 High Fidelity, Inc.
//
// Distributed under the Apache License, Version 2.0.
// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
//
#include <cstring>
#include <cstdio>
#include <iostream>
#include <ctime>
//#include <netdb.h> // not available on windows, apparently not needed on mac
#ifdef _WIN32
#include <process.h>
#define getpid _getpid
#define getppid _getpid // hack to build
#define pid_t int // hack to build
#endif
#include <QtNetwork/QHostInfo>
#include "HifiSockAddr.h"
#include "SharedUtil.h"
#include "NodeList.h"
#include "Logging.h"
HifiSockAddr Logging::_logstashSocket = HifiSockAddr();
QString Logging::_targetName = QString();
const HifiSockAddr& Logging::socket() {
if (_logstashSocket.getAddress().isNull()) {
// we need to construct the socket object
// use the constant port
_logstashSocket.setPort(htons(LOGSTASH_UDP_PORT));
// lookup the IP address for the constant hostname
QHostInfo hostInfo = QHostInfo::fromName(LOGSTASH_HOSTNAME);
if (!hostInfo.addresses().isEmpty()) {
// use the first IP address
_logstashSocket.setAddress(hostInfo.addresses().first());
} else {
qDebug("Failed to lookup logstash IP - will try again on next log attempt.");
}
}
return _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().writeDatagram(logstashPacket, numPacketBytes,
_logstashSocket.getAddress(), _logstashSocket.getPort());
}
}
const char* stringForLogType(QtMsgType msgType) {
switch (msgType) {
case QtDebugMsg:
return "DEBUG";
case QtCriticalMsg:
return "CRITICAL";
case QtFatalMsg:
return "FATAL";
case QtWarningMsg:
return "WARNING";
default:
return "UNKNOWN";
}
}
// the following will produce 2000-10-02 13:55:36 -0700
const char DATE_STRING_FORMAT[] = "%Y-%m-%d %H:%M:%S %z";
void Logging::verboseMessageHandler(QtMsgType type, const QMessageLogContext& context, const QString& message) {
if (message.isEmpty()) {
return;
}
// 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 (!_targetName.isEmpty()) {
prefixString.append(QString(" [%1]").arg(_targetName));
}
fprintf(stdout, "%s %s\n", prefixString.toLocal8Bit().constData(), message.toLocal8Bit().constData());
}

54
libraries/networking/src/Logging.h
View file

@ -1,54 +0,0 @@
//
// Logging.h
// libraries/networking/src
//
// Created by Stephen Birarda on 6/11/13.
// Copyright 2013 High Fidelity, Inc.
//
// Distributed under the Apache License, Version 2.0.
// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
//
#ifndef hifi_Logging_h
#define hifi_Logging_h
#include <QtCore/QString>
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 HifiSockAddr;
/// 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 const HifiSockAddr& 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 QString& targetName) { _targetName = 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 HifiSockAddr _logstashSocket;
static QString _targetName;
};
#endif // hifi_Logging_h

3
libraries/networking/src/NodeList.cpp
View file

@ -15,10 +15,11 @@
#include <QtCore/QUrl>
#include <QtNetwork/QHostInfo>
#include <LogHandler.h>
#include "AccountManager.h"
#include "Assignment.h"
#include "HifiSockAddr.h"
#include "Logging.h"
#include "NodeList.h"
#include "PacketHeaders.h"
#include "SharedUtil.h"

5
libraries/networking/src/ThreadedAssignment.cpp
View file

@ -14,7 +14,8 @@
#include <QtCore/QThread>
#include <QtCore/QTimer>
#include "Logging.h"
#include <LogHandler.h>
#include "ThreadedAssignment.h"
ThreadedAssignment::ThreadedAssignment(const QByteArray& packet) :
@ -54,7 +55,7 @@ void ThreadedAssignment::setFinished(bool isFinished) {
void ThreadedAssignment::commonInit(const QString& targetName, NodeType_t nodeType, bool shouldSendStats) {
// change the logging target name while the assignment is running
Logging::setTargetName(targetName);
LogHandler::getInstance().setTargetName(targetName);
NodeList* nodeList = NodeList::getInstance();
nodeList->setOwnerType(nodeType);

144
libraries/shared/src/LogHandler.cpp Normal file
View file

@ -0,0 +1,144 @@
//
// LogHandler.cpp
// libraries/shared/src
//
// Created by Stephen Birarda on 2014-10-28.
// Migrated from Logging.cpp created on 6/11/13
// Copyright 2014 High Fidelity, Inc.
//
// Distributed under the Apache License, Version 2.0.
// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
//
#include <time.h>
#ifdef _WIN32
#include <process.h>
#define getpid _getpid
#define getppid _getpid // hack to build
#define pid_t int // hack to build
#endif
#include <qdebug.h>
#include <qtimer.h>
#include "LogHandler.h"
LogHandler& LogHandler::getInstance() {
static LogHandler staticInstance;
return staticInstance;
}
LogHandler::LogHandler() :
_shouldOutputPID(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);
}
const char* stringForLogType(LogMsgType msgType) {
switch (msgType) {
case QtDebugMsg:
return "DEBUG";
case QtCriticalMsg:
return "CRITICAL";
case QtFatalMsg:
return "FATAL";
case QtWarningMsg:
return "WARNING";
case LogSuppressed:
return "SUPPRESS";
default:
return "UNKNOWN";
}
}
// the following will produce 2000-10-02 13:55:36 -0700
const char DATE_STRING_FORMAT[] = "%Y-%m-%d %H:%M:%S %z";
void LogHandler::flushRepeatedMessages() {
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
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();
}
}
}
}
// 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));
if (_shouldOutputPID) {
prefixString.append(QString(" [%1").arg(getpid()));
pid_t parentProcessID = getppid();
if (parentProcessID != 0) {
prefixString.append(QString(":%1]").arg(parentProcessID));
} else {
prefixString.append("]");
}
}
if (!_targetName.isEmpty()) {
prefixString.append(QString(" [%1]").arg(_targetName));
}
QString logMessage = QString("%1 %2").arg(prefixString, message);
fprintf(stdout, "%s\n", qPrintable(logMessage));
return logMessage;
}
void LogHandler::verboseMessageHandler(QtMsgType type, const QMessageLogContext& context, const QString& message) {
getInstance().printMessage((LogMsgType) type, context, message);
}

63
libraries/shared/src/LogHandler.h Normal file
View file

@ -0,0 +1,63 @@
//
// LogHandler.cpp
// libraries/shared/src
//
// Created by Stephen Birarda on 2014-10-28.
// Migrated from Logging.cpp created on 6/11/13
// Copyright 2014 High Fidelity, Inc.
//
// Distributed under the Apache License, Version 2.0.
// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
//
#ifndef hifi_LogHandler_h
#define hifi_LogHandler_h
#include <qhash.h>
#include <qobject.h>
#include <qregexp.h>
#include <qset.h>
#include <qstring.h>
const int VERBOSE_LOG_INTERVAL_SECONDS = 5;
enum LogMsgType {
LogDebug,
LogWarning,
LogCritical,
LogFatal,
LogSuppressed
};
/// Handles custom message handling and sending of stats/logs to Logstash instance
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; }
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); }
private:
LogHandler();
void flushRepeatedMessages();
QString _targetName;
bool _shouldOutputPID;
QSet<QString> _repeatedMessageRegexes;
QHash<QString, int> _repeatMessageCountHash;
QHash<QString, QString> _lastRepeatedMessage;
};
#endif // hifi_LogHandler_h