Make logger thread safe (#885)

This commit is contained in:
Murat Seker 2020-07-19 15:37:47 +02:00 committed by GitHub
parent 45303e1b64
commit 4880e31562
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
10 changed files with 276 additions and 193 deletions

View File

@ -4,7 +4,6 @@
requestLoggingStart();
$(document).ready(function() {
var messages;
var loguplmess = "";
var reportUrl = 'https://report.hyperion-project.org/#';

View File

@ -5,6 +5,7 @@
//qt
#include <QMap>
#include <QVector>
class AuthTable;
class MetaTable;
@ -258,4 +259,4 @@ private slots:
/// @brief Check if there are timeouts for failed login attempts
///
void checkAuthBlockTimeout();
};
};

View File

@ -3,29 +3,33 @@
// QT includes
#include <QObject>
#include <QString>
#include <QMap>
#include <QAtomicInteger>
#include <QList>
#include <QMutex>
// stl includes
#include <stdio.h>
#include <stdarg.h>
#include <map>
#include <QVector>
#ifdef _WIN32
#include <stdexcept>
#endif
#include <utils/global_defines.h>
#define LOG_MESSAGE(severity, logger, ...) (logger)->Message(severity, __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
// standard log messages
#define Debug(logger, ...) (logger)->Message(Logger::DEBUG , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define Info(logger, ...) (logger)->Message(Logger::INFO , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define Warning(logger, ...) (logger)->Message(Logger::WARNING, __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define Error(logger, ...) (logger)->Message(Logger::ERRORR , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define Debug(logger, ...) LOG_MESSAGE(Logger::DEBUG , logger, __VA_ARGS__)
#define Info(logger, ...) LOG_MESSAGE(Logger::INFO , logger, __VA_ARGS__)
#define Warning(logger, ...) LOG_MESSAGE(Logger::WARNING, logger, __VA_ARGS__)
#define Error(logger, ...) LOG_MESSAGE(Logger::ERRORR , logger, __VA_ARGS__)
// conditional log messages
#define DebugIf(condition, logger, ...) if (condition) (logger)->Message(Logger::DEBUG , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define InfoIf(condition, logger, ...) if (condition) (logger)->Message(Logger::INFO , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define WarningIf(condition, logger, ...) if (condition) (logger)->Message(Logger::WARNING , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define ErrorIf(condition, logger, ...) if (condition) (logger)->Message(Logger::ERRORR , __FILE__, __FUNCTION__, __LINE__, __VA_ARGS__)
#define DebugIf(condition, logger, ...) if (condition) Debug(logger, __VA_ARGS__)
#define InfoIf(condition, logger, ...) if (condition) Info(logger, __VA_ARGS__)
#define WarningIf(condition, logger, ...) if (condition) Warning(logger, __VA_ARGS__)
#define ErrorIf(condition, logger, ...) if (condition) Error(logger, __VA_ARGS__)
// ================================================================
@ -35,62 +39,68 @@ class Logger : public QObject
public:
enum LogLevel {
UNSET,
DEBUG,
INFO,
WARNING,
ERRORR,
OFF
UNSET = 0,
DEBUG = 1,
INFO = 2,
WARNING = 3,
ERRORR = 4,
OFF = 5
};
typedef struct
struct T_LOG_MESSAGE
{
QString appName;
QString loggerName;
QString function;
unsigned int line;
QString fileName;
time_t utime;
uint64_t utime;
QString message;
LogLevel level;
QString levelString;
} T_LOG_MESSAGE;
};
static Logger* getInstance(QString name="", LogLevel minLevel=Logger::INFO);
static void deleteInstance(QString name="");
static void setLogLevel(LogLevel level, QString name="");
static LogLevel getLogLevel(QString name="");
static Logger* getInstance(const QString & name = "", LogLevel minLevel=Logger::INFO);
static void deleteInstance(const QString & name = "");
static void setLogLevel(LogLevel level, const QString & name = "");
static LogLevel getLogLevel(const QString & name = "");
void Message(LogLevel level, const char* sourceFile, const char* func, unsigned int line, const char* fmt, ...);
void setMinLevel(LogLevel level) { _minLevel = level; }
LogLevel getMinLevel() { return _minLevel; }
void setMinLevel(LogLevel level) { _minLevel = static_cast<int>(level); }
LogLevel getMinLevel() { return static_cast<LogLevel>(int(_minLevel)); }
QString getName() const { return _name; }
QString getAppName() const { return _appname; }
signals:
void newLogMessage(Logger::T_LOG_MESSAGE);
protected:
Logger( QString name="", LogLevel minLevel=INFO);
Logger(const QString & name="", LogLevel minLevel = INFO);
~Logger();
private:
static std::map<QString,Logger*> *LoggerMap;
static LogLevel GLOBAL_MIN_LOG_LEVEL;
void write(const Logger::T_LOG_MESSAGE & message) const;
QString _name;
QString _appname;
LogLevel _minLevel;
bool _syslogEnabled;
unsigned _loggerId;
static QMutex MapLock;
static QMap<QString,Logger*> LoggerMap;
static QAtomicInteger<int> GLOBAL_MIN_LOG_LEVEL;
const QString _name;
const QString _appname;
const bool _syslogEnabled;
const unsigned _loggerId;
/* Only non-const member, hence the atomic */
QAtomicInteger<int> _minLevel;
};
class LoggerManager : public QObject
{
Q_OBJECT
public:
static LoggerManager* getInstance();
QVector<Logger::T_LOG_MESSAGE>* getLogMessageBuffer() { return &_logMessageBuffer; }
const QList<Logger::T_LOG_MESSAGE>* getLogMessageBuffer() const { return &_logMessageBuffer; }
public slots:
void handleNewLogMessage(const Logger::T_LOG_MESSAGE&);
@ -101,8 +111,7 @@ signals:
protected:
LoggerManager();
static LoggerManager* _instance;
QVector<Logger::T_LOG_MESSAGE> _logMessageBuffer;
QList<Logger::T_LOG_MESSAGE> _logMessageBuffer;
const int _loggerMaxMsgBufferSize;
};

View File

@ -1548,7 +1548,7 @@ void JsonAPI::incommingLogMessage(const Logger::T_LOG_MESSAGE &msg)
if (!_streaming_logging_activated)
{
_streaming_logging_activated = true;
QVector<Logger::T_LOG_MESSAGE> *logBuffer = LoggerManager::getInstance()->getLogMessageBuffer();
const QList<Logger::T_LOG_MESSAGE> *logBuffer = LoggerManager::getInstance()->getLogMessageBuffer();
for (int i = 0; i < logBuffer->length(); i++)
{
message["appName"] = logBuffer->at(i).appName;

View File

@ -12,7 +12,7 @@ FlatBufferConnection::FlatBufferConnection(const QString& origin, const QString
, _origin(origin)
, _priority(priority)
, _prevSocketState(QAbstractSocket::UnconnectedState)
, _log(Logger::getInstance("FLATBUFCONNECTION"))
, _log(Logger::getInstance("FLATBUFCONN"))
, _registered(false)
{
QStringList parts = address.split(":");

View File

@ -7,7 +7,7 @@ using namespace hyperion;
ComponentRegister::ComponentRegister(Hyperion* hyperion)
: _hyperion(hyperion)
, _log(Logger::getInstance("ComponentRegister"))
, _log(Logger::getInstance("COMPONENTREG"))
{
// init all comps to false
QVector<hyperion::Components> vect;

View File

@ -14,7 +14,7 @@ Grabber::Grabber(QString grabberName, int width, int height, int cropLeft, int c
, _cropTop(0)
, _cropBottom(0)
, _enabled(true)
, _log(Logger::getInstance(grabberName))
, _log(Logger::getInstance(grabberName.toUpper()))
{
Grabber::setVideoMode(VideoMode::VIDEO_2D);
Grabber::setCropping(cropLeft, cropRight, cropTop, cropBottom);

View File

@ -16,7 +16,7 @@ QJsonObject SettingsManager::schemaJson;
SettingsManager::SettingsManager(const quint8& instance, QObject* parent)
: QObject(parent)
, _log(Logger::getInstance("SettingsManager"))
, _log(Logger::getInstance("SETTINGSMGR"))
, _sTable(new SettingsTable(instance, this))
{
// get schema

View File

@ -16,6 +16,35 @@
namespace DefaultSignalHandler
{
struct Signal
{
int number;
const char * name;
};
const Signal ALL_SIGNALS[] = {
{ SIGABRT, "SIGABRT" },
{ SIGBUS, "SIGBUS" },
{ SIGFPE, "SIGFPE" },
{ SIGILL, "SIGILL" },
{ SIGSEGV, "SIGSEGV" },
{ SIGTERM, "SIGTERM" },
{ SIGHUP, "SIGHUP" },
{ SIGINT, "SIGINT" },
{ SIGPIPE, "SIGPIPE" },
};
void write_to_stderr(const char* data, size_t size)
{
int res = write(STDERR_FILENO, data, size);
Q_UNUSED(res);
}
void write_to_stderr(const char* data)
{
write_to_stderr(data, strlen(data));
}
std::string decipher_trace(const std::string &trace)
{
@ -70,26 +99,48 @@ void print_trace()
free(symbols);
}
void install_default_handler(int signum)
{
struct sigaction action{};
sigemptyset(&action.sa_mask);
action.sa_handler = SIG_DFL;
(void)sigaction(signum, &action, nullptr);
}
/* Note that this signal handler is not async signal safe !
* Ideally a signal handler should only flip a bit and defer
* heavy work to some kind of bottom-half processing. */
void signal_handler(int signum, siginfo_t * /*info*/, void * /*context*/)
{
Logger* log = Logger::getInstance("SIGNAL");
const char * name = "UNKNOWN SIGNAL";
char *name = strsignal(signum);
if (name)
{
Info(log, "Signal received : %s", name);
for (const auto& s : ALL_SIGNALS) {
if (s.number == signum) {
name = s.name;
break;
}
}
write_to_stderr("\n");
write_to_stderr("Hyperion caught signal :");
write_to_stderr(name);
write_to_stderr("\n");
/* Anything below here is unsafe ! */
switch(signum)
{
case SIGBUS:
case SIGSEGV:
case SIGABRT:
case SIGFPE :
print_trace();
exit(1);
/* Don't catch our own signal */
install_default_handler(signum);
kill(getpid(), signum);
return;
case SIGINT :
case SIGTERM:
case SIGPIPE:
@ -101,10 +152,7 @@ void signal_handler(int signum, siginfo_t * /*info*/, void * /*context*/)
QMetaObject::invokeMethod(qApp, "quit", Qt::QueuedConnection);
// Reset signal handler to default (in case this handler is not capable of stopping)
struct sigaction action{};
action.sa_handler = SIG_DFL;
sigaction(signum, &action, nullptr);
install_default_handler(signum);
}
}
@ -116,17 +164,20 @@ namespace DefaultSignalHandler
void install()
{
#ifndef _WIN32
struct sigaction action{};
action.sa_sigaction = signal_handler;
action.sa_flags = SA_RESTART | SA_SIGINFO;
Logger* log = Logger::getInstance("CORE");
sigaction(SIGHUP , &action, nullptr);
sigaction(SIGFPE , &action, nullptr);
sigaction(SIGINT , &action, nullptr);
sigaction(SIGTERM, &action, nullptr);
sigaction(SIGABRT, &action, nullptr);
sigaction(SIGSEGV, &action, nullptr);
sigaction(SIGPIPE, &action, nullptr);
struct sigaction action{};
sigemptyset(&action.sa_mask);
action.sa_sigaction = signal_handler;
action.sa_flags |= SA_SIGINFO;
for (const auto& s : ALL_SIGNALS)
{
if (sigaction(s.number, &action, nullptr)!= 0)
{
Error(log, "Failed to install handler for %s]\n", s.name);
}
}
#endif // _WIN32
}
} // namespace DefaultSignalHandler

View File

@ -11,99 +11,33 @@
#include <Shlwapi.h>
#pragma comment(lib, "Shlwapi.lib")
#endif
#include <QDateTime>
#include <QFileInfo>
#include <QMutexLocker>
#include <QThreadStorage>
#include <time.h>
static const char * LogLevelStrings[] = { "", "DEBUG", "INFO", "WARNING", "ERROR" };
QMutex Logger::MapLock { QMutex::Recursive };
QMap<QString,Logger*> Logger::LoggerMap { };
QAtomicInteger<int> Logger::GLOBAL_MIN_LOG_LEVEL { static_cast<int>(Logger::UNSET)};
namespace
{
const char * LogLevelStrings[] = { "", "DEBUG", "INFO", "WARNING", "ERROR" };
#ifndef _WIN32
static const int LogLevelSysLog[] = { LOG_DEBUG, LOG_DEBUG, LOG_INFO, LOG_WARNING, LOG_ERR };
const int LogLevelSysLog[] = { LOG_DEBUG, LOG_DEBUG, LOG_INFO, LOG_WARNING, LOG_ERR };
#endif
static unsigned int loggerCount = 0;
static unsigned int loggerId = 0;
std::map<QString,Logger*> *Logger::LoggerMap = nullptr;
Logger::LogLevel Logger::GLOBAL_MIN_LOG_LEVEL = Logger::UNSET;
LoggerManager* LoggerManager::_instance = nullptr;
int _repeatCount = 0;
Logger::T_LOG_MESSAGE _repeatMessage;
const int _maxRepeatCountSize = 200;
const size_t MAX_IDENTIFICATION_LENGTH = 22;
Logger* Logger::getInstance(QString name, Logger::LogLevel minLevel)
{
qRegisterMetaType<Logger::T_LOG_MESSAGE>();
Logger* log = nullptr;
if (LoggerMap == nullptr)
{
LoggerMap = new std::map<QString,Logger*>;
}
QAtomicInteger<unsigned int> LoggerCount = 0;
QAtomicInteger<unsigned int> LoggerId = 0;
if (LoggerMap->find(name) == LoggerMap->end())
{
log = new Logger(name,minLevel);
LoggerMap->insert(std::pair<QString,Logger*>(name,log)); // compat version, replace it with following line if we have 100% c++11
//LoggerMap->emplace(name,log); // not compat with older linux distro's e.g. wheezy
connect(log, &Logger::newLogMessage, LoggerManager::getInstance(), &LoggerManager::handleNewLogMessage);
}
else
{
log = LoggerMap->at(name);
}
const int MaxRepeatCountSize = 200;
QThreadStorage<int> RepeatCount;
QThreadStorage<Logger::T_LOG_MESSAGE> RepeatMessage;
return log;
}
void Logger::deleteInstance(QString name)
{
if (LoggerMap == nullptr)
return;
if (name.isEmpty())
{
std::map<QString,Logger*>::iterator it;
for (it = LoggerMap->begin(); it != LoggerMap->end(); it++)
{
delete it->second;
}
LoggerMap->clear();
}
else if (LoggerMap->find(name) != LoggerMap->end())
{
delete LoggerMap->at(name);
LoggerMap->erase(name);
}
}
void Logger::setLogLevel(LogLevel level,QString name)
{
if (name.isEmpty())
{
GLOBAL_MIN_LOG_LEVEL = level;
}
else
{
Logger* log = Logger::getInstance(name,level);
log->setMinLevel(level);
}
}
Logger::LogLevel Logger::getLogLevel(QString name)
{
if (name.isEmpty())
{
return GLOBAL_MIN_LOG_LEVEL;
}
Logger* log = Logger::getInstance(name);
return log->getMinLevel();
}
Logger::Logger (QString name, LogLevel minLevel)
: QObject()
, _name(name)
, _minLevel(minLevel)
, _syslogEnabled(true)
, _loggerId(loggerId++)
QString getApplicationName()
{
#ifdef __GLIBC__
const char* _appname_char = program_invocation_short_name;
@ -121,32 +55,132 @@ Logger::Logger (QString name, LogLevel minLevel)
else
_appname_char = "unknown";
#endif
_appname = QString(_appname_char).toLower();
return QString(_appname_char).toLower();
loggerCount++;
}
} // namespace
if (_syslogEnabled && loggerCount == 1)
Logger* Logger::getInstance(const QString & name, Logger::LogLevel minLevel)
{
QMutexLocker lock(&MapLock);
Logger* log = LoggerMap.value(name, nullptr);
if (log == nullptr)
{
#ifndef _WIN32
openlog (_appname_char, LOG_CONS | LOG_PID | LOG_NDELAY, LOG_LOCAL0);
#endif
log = new Logger(name, minLevel);
LoggerMap.insert(name, log); // compat version, replace it with following line if we have 100% c++11
//LoggerMap.emplace(name, log); // not compat with older linux distro's e.g. wheezy
connect(log, &Logger::newLogMessage, LoggerManager::getInstance(), &LoggerManager::handleNewLogMessage);
}
return log;
}
void Logger::deleteInstance(const QString & name)
{
QMutexLocker lock(&MapLock);
if (name.isEmpty())
{
for (auto logger : LoggerMap)
delete logger;
LoggerMap.clear();
}
else
{
delete LoggerMap.value(name, nullptr);
LoggerMap.remove(name);
}
}
void Logger::setLogLevel(LogLevel level, const QString & name)
{
if (name.isEmpty())
{
GLOBAL_MIN_LOG_LEVEL = static_cast<int>(level);
}
else
{
Logger* log = Logger::getInstance(name, level);
log->setMinLevel(level);
}
}
Logger::LogLevel Logger::getLogLevel(const QString & name)
{
if (name.isEmpty())
{
return static_cast<Logger::LogLevel>(int(GLOBAL_MIN_LOG_LEVEL));
}
Logger* log = Logger::getInstance(name);
return log->getMinLevel();
}
Logger::Logger (const QString & name, LogLevel minLevel)
: QObject()
, _name(name)
, _appname(getApplicationName())
, _syslogEnabled(true)
, _loggerId(LoggerId++)
, _minLevel(static_cast<int>(minLevel))
{
qRegisterMetaType<Logger::T_LOG_MESSAGE>();
int count = LoggerCount.fetchAndAddOrdered(1);
if (_syslogEnabled && count == 1)
{
#ifndef _WIN32
openlog (_appname.toLocal8Bit(), LOG_CONS | LOG_PID | LOG_NDELAY, LOG_LOCAL0);
#endif
}
}
Logger::~Logger()
{
//Debug(this, "logger '%s' destroyed", QSTRING_CSTR(_name) );
loggerCount--;
int count = LoggerCount.fetchAndSubOrdered(1);
#ifndef _WIN32
if (loggerCount == 0)
if (_syslogEnabled && count == 0)
closelog();
#endif
}
void Logger::write(const Logger::T_LOG_MESSAGE & message) const
{
QString location;
if (message.level == Logger::DEBUG)
{
location = QString("%1:%2:%3() | ")
.arg(message.fileName)
.arg(message.line)
.arg(message.function);
}
QString name = message.appName + " " + message.loggerName;
name.resize(MAX_IDENTIFICATION_LENGTH, ' ');
const QDateTime timestamp = QDateTime::fromMSecsSinceEpoch(message.utime);
std::cout << QString("%1 %2 : <%3> %4%5")
.arg(timestamp.toString("yyyy-MM-ddThh:mm:ss.zzz"))
.arg(name)
.arg(LogLevelStrings[message.level])
.arg(location)
.arg(message.message)
.toStdString()
<< std::endl;
}
void Logger::Message(LogLevel level, const char* sourceFile, const char* func, unsigned int line, const char* fmt, ...)
{
if ( (GLOBAL_MIN_LOG_LEVEL == Logger::UNSET && level < _minLevel) // no global level, use level from logger
|| (GLOBAL_MIN_LOG_LEVEL > Logger::UNSET && level < GLOBAL_MIN_LOG_LEVEL) ) // global level set, use global level
Logger::LogLevel globalLevel = static_cast<Logger::LogLevel>(int(GLOBAL_MIN_LOG_LEVEL));
if ( (globalLevel == Logger::UNSET && level < _minLevel) // no global level, use level from logger
|| (globalLevel > Logger::UNSET && level < globalLevel) ) // global level set, use global level
return;
const size_t max_msg_length = 1024;
@ -156,38 +190,35 @@ void Logger::Message(LogLevel level, const char* sourceFile, const char* func, u
vsnprintf (msg, max_msg_length, fmt, args);
va_end (args);
auto repeatedSummary = [=]
const auto repeatedSummary = [&]
{
Logger::T_LOG_MESSAGE repMsg = _repeatMessage;
repMsg.message = "Previous line repeats " + QString::number(_repeatCount) + " times";
emit newLogMessage(repMsg);
std::cout << QString("[" + repMsg.appName + " " + repMsg.loggerName + "] <" + LogLevelStrings[repMsg.level] + "> " + repMsg.message).toStdString() << std::endl;
Logger::T_LOG_MESSAGE repMsg = RepeatMessage.localData();
repMsg.message = "Previous line repeats " + QString::number(RepeatCount.localData()) + " times";
repMsg.utime = QDateTime::currentMSecsSinceEpoch();
write(repMsg);
#ifndef _WIN32
if ( _syslogEnabled && repMsg.level >= Logger::WARNING )
syslog (LogLevelSysLog[repMsg.level], "Previous line repeats %d times", _repeatCount);
syslog (LogLevelSysLog[repMsg.level], "Previous line repeats %d times", RepeatCount.localData());
#endif
_repeatCount = 0;
RepeatCount.setLocalData(0);
};
if (_repeatMessage.loggerName == _name
&& _repeatMessage.function == QString(func)
&& _repeatMessage.line == line
&& _repeatMessage.message == QString(msg))
if (RepeatMessage.localData().loggerName == _name &&
RepeatMessage.localData().function == func &&
RepeatMessage.localData().message == msg &&
RepeatMessage.localData().line == line)
{
if (_repeatCount >= _maxRepeatCountSize)
if (RepeatCount.localData() >= MaxRepeatCountSize)
repeatedSummary();
else
_repeatCount++;
return;
RepeatCount.setLocalData(RepeatCount.localData() + 1);
}
else
{
if (_repeatCount) repeatedSummary();
if (RepeatCount.localData())
repeatedSummary();
Logger::T_LOG_MESSAGE logMsg;
@ -196,25 +227,17 @@ void Logger::Message(LogLevel level, const char* sourceFile, const char* func, u
logMsg.function = QString(func);
logMsg.line = line;
logMsg.fileName = FileUtils::getBaseName(sourceFile);
time(&(logMsg.utime));
logMsg.utime = QDateTime::currentMSecsSinceEpoch();
logMsg.message = QString(msg);
logMsg.level = level;
logMsg.levelString = LogLevelStrings[level];
emit newLogMessage(logMsg);
QString location;
if ( level == Logger::DEBUG )
{
location = "<" + logMsg.fileName + ":" + QString::number(line)+":"+ logMsg.function + "()> ";
}
std::cout << QString("[" + _appname + " " + _name + "] <" + LogLevelStrings[level] + "> " + location + msg).toStdString() << std::endl;
write(logMsg);
#ifndef _WIN32
if ( _syslogEnabled && level >= Logger::WARNING )
syslog (LogLevelSysLog[level], "%s", msg);
#endif
_repeatMessage = logMsg;
RepeatMessage.setLocalData(logMsg);
}
}
@ -222,14 +245,15 @@ LoggerManager::LoggerManager()
: QObject()
, _loggerMaxMsgBufferSize(200)
{
_logMessageBuffer.reserve(_loggerMaxMsgBufferSize);
}
void LoggerManager::handleNewLogMessage(const Logger::T_LOG_MESSAGE &msg)
void LoggerManager::handleNewLogMessage(const Logger::T_LOG_MESSAGE & msg)
{
_logMessageBuffer.append(msg);
_logMessageBuffer.push_back(msg);
if (_logMessageBuffer.length() > _loggerMaxMsgBufferSize)
{
_logMessageBuffer.erase(_logMessageBuffer.begin());
_logMessageBuffer.pop_front();
}
emit newLogMessage(msg);
@ -237,7 +261,6 @@ void LoggerManager::handleNewLogMessage(const Logger::T_LOG_MESSAGE &msg)
LoggerManager* LoggerManager::getInstance()
{
if (_instance == nullptr)
_instance = new LoggerManager();
return _instance;
static LoggerManager instance;
return &instance;
}