diff --git a/servatrice/src/main.cpp b/servatrice/src/main.cpp index eb019a2b7..4d513d026 100644 --- a/servatrice/src/main.cpp +++ b/servatrice/src/main.cpp @@ -41,6 +41,7 @@ #include #include #include +#include #include #include #include @@ -162,14 +163,15 @@ int main(int argc, char *argv[]) configPath = SettingsCache::guessConfigurationPath(); } else if (!QFile::exists(configPath)) { qCritical() << "Could not find configuration file at" << configPath; - return 1; + return EXIT_FAILURE; } qWarning() << "Using configuration file: " << configPath; settingsCache = new SettingsCache(configPath); loggerThread = new QThread; loggerThread->setObjectName("logger"); - logger = new ServerLogger(logToConsole); + logger = new ServerLogger(logToConsole, settingsCache->value("server/writelog", 1).toBool(), + settingsCache->value("server/logfilters").toString()); logger->moveToThread(loggerThread); loggerThread->start(); @@ -214,8 +216,16 @@ int main(int argc, char *argv[]) std::cerr << "Server quit." << std::endl; std::cerr << "-------------------------" << std::endl; + } else { + // initServer() logged the reason; a failed startup must not look like a clean exit. + std::cerr << "Server initialization failed, exiting." << std::endl; + retval = EXIT_FAILURE; } + // The handler reads the logger and settingsCache globals torn down below; leaving it + // installed lets Qt's own shutdown warnings dereference freed memory. + qInstallMessageHandler(nullptr); + delete smtpClient; delete rng; delete signalhandler; diff --git a/servatrice/src/servatrice.cpp b/servatrice/src/servatrice.cpp index b6eaf11f4..49d8e1e4c 100644 --- a/servatrice/src/servatrice.cpp +++ b/servatrice/src/servatrice.cpp @@ -308,7 +308,8 @@ bool Servatrice::initServer() authenticationMethod = AuthenticationPassword; } else { if (getRegOnlyServerEnabled()) { - qDebug() << "Registration only server enabled but no authentication method defined: Error."; + qCCritical(ServatriceLog) << "Registration only server enabled but no authentication method defined; " + "refusing to start."; return false; } qDebug() << "Authenticating method: none"; @@ -379,7 +380,7 @@ bool Servatrice::initServer() bool dbOpened = servatriceDatabaseInterface->initDatabase( "QMYSQL", getDBHostNameString(), getDBDatabaseNameString(), getDBUserNameString(), getDBPasswordString()); if (!dbOpened) { - qDebug() << "Failed to open database"; + qCCritical(ServatriceLog) << "Failed to open the database; refusing to start."; return false; } updateServerList(); @@ -600,11 +601,11 @@ bool Servatrice::initServer() if (islServer->listen(QHostAddress::Any, static_cast(getISLNetworkPort()))) { qDebug() << "ISL server listening."; } else { - throw QString("islServer->listen()"); + throw islServer->errorString(); } } } catch (QString &error) { - qDebug() << "ERROR --" << error; + qCCritical(ServatriceLog) << "Failed to start the ISL server:" << error; return false; } @@ -641,7 +642,7 @@ bool Servatrice::initServer() if (gameServer->listen(tcpHost, static_cast(getServerTCPPort()))) { qDebug() << "Server listening."; } else { - qDebug() << "gameServer->listen(): Error:" << gameServer->errorString(); + qCCritical(ServatriceLog) << "Failed to listen for TCP clients:" << gameServer->errorString(); return false; } } @@ -657,7 +658,8 @@ bool Servatrice::initServer() if (websocketGameServer->listen(webSocketHost, static_cast(getServerWebSocketPort()))) { qDebug() << "Websocket server listening."; } else { - qDebug() << "websocketGameServer->listen(): Error:" << websocketGameServer->errorString(); + qCCritical(ServatriceLog) << "Failed to listen for websocket clients:" + << websocketGameServer->errorString(); return false; } } diff --git a/servatrice/src/server_logger.cpp b/servatrice/src/server_logger.cpp index 1c83299b8..dfe51183a 100644 --- a/servatrice/src/server_logger.cpp +++ b/servatrice/src/server_logger.cpp @@ -1,7 +1,5 @@ #include "server_logger.h" -#include "settingscache.h" - #include #include #include @@ -10,33 +8,37 @@ #include #include #include -#include #include #include #include #include #include -ServerLogger::ServerLogger(bool _logToConsole, QObject *parent) +ServerLogger::ServerLogger(bool _logToConsole, bool _writeLog, const QString &_logFilters, QObject *parent) : QObject(parent), logToConsole(_logToConsole), flushRunning(false) { + reloadConfig(_writeLog, _logFilters); + connect(this, SIGNAL(sigFlushBuffer()), this, SLOT(flushBuffer()), Qt::QueuedConnection); } ServerLogger::~ServerLogger() { flushBuffer(); + // logFile is a child of this object and is closed and deleted by ~QObject. // This does not work with the destroyed() signal as this destructor is called after the main event loop is done. thread()->quit(); } void ServerLogger::startLog(const QString &logFileName) { + delete logFile; + logFile = nullptr; + if (!logFileName.isEmpty()) { QFileInfo fi(logFileName); QDir fileDir(fi.path()); if (!fileDir.exists() && !fileDir.mkpath(fileDir.absolutePath())) { std::cerr << "ERROR: logfile folder doesn't exist and i can't create it." << std::endl; - logFile = 0; return; } @@ -44,14 +46,22 @@ void ServerLogger::startLog(const QString &logFileName) if (!logFile->open(QIODevice::Append)) { std::cerr << "ERROR: can't open() logfile." << std::endl; delete logFile; - logFile = 0; + logFile = nullptr; return; } - } else { - logFile = 0; } +} - connect(this, SIGNAL(sigFlushBuffer()), this, SLOT(flushBuffer()), Qt::QueuedConnection); +void ServerLogger::reloadConfig(bool _writeLog, const QString &_logFilters) +{ + const bool filterActive = !_logFilters.trimmed().isEmpty(); + const QStringList filters = _logFilters.split(QStringLiteral(","), Qt::SkipEmptyParts); + + configMutex.lock(); + writeLog = _writeLog; + messageFilterActive = filterActive; + logFilters = filters; + configMutex.unlock(); } bool ServerLogger::isLoggingEnabled() const @@ -61,43 +71,54 @@ bool ServerLogger::isLoggingEnabled() const void ServerLogger::logMessage(const QString &message, void *caller) { - if (!logFile) { - return; - } - QString callerString; if (caller) { - callerString = QString::number((qulonglong)caller, 16) + " "; + callerString = QString::number(reinterpret_cast(caller), 16) + " "; } - // filter out all log entries based on values in configuration file - bool shouldWeWriteLog = settingsCache->value("server/writelog", 1).toBool(); - QString logFilters = settingsCache->value("server/logfilters").toString(); - QStringList listlogFilters = logFilters.split(",", Qt::SkipEmptyParts); - bool shouldWeSkipLine = false; + const QString line = QDateTime::currentDateTime().toString() + " " + callerString + message; + bool queued = false; - if (!shouldWeWriteLog) { - return; + // The console is an independent sink: writelog and logfilters only describe the logfile + // (see servatrice.ini.example), so a disabled or unopenable logfile must not swallow + // startup errors such as a refused database connection. Lines are buffered for the logger + // thread instead of written here, so a stalled stdout reader cannot stall game threads. + if (logToConsole) { + bufferMutex.lock(); + consoleBuffer.append(line); + bufferMutex.unlock(); + queued = true; } - if (!logFilters.trimmed().isEmpty()) { - shouldWeSkipLine = true; - for (const QString &logFilter : listlogFilters) { - if (message.contains(logFilter, Qt::CaseInsensitive)) { - shouldWeSkipLine = false; - break; + configMutex.lock(); + const bool shouldWriteFile = writeLog; + const bool filterMessages = messageFilterActive; + const QStringList filters = logFilters; + configMutex.unlock(); + + if (logFile && shouldWriteFile) { + // filter out all log entries based on values in configuration file + bool shouldWriteLine = !filterMessages; + if (filterMessages) { + for (const QString &logFilter : filters) { + if (message.contains(logFilter, Qt::CaseInsensitive)) { + shouldWriteLine = true; + break; + } } } + + if (shouldWriteLine) { + bufferMutex.lock(); + buffer.append(line); + bufferMutex.unlock(); + queued = true; + } } - if (shouldWeSkipLine) { - return; + if (queued) { + emit sigFlushBuffer(); } - - bufferMutex.lock(); - buffer.append(QDateTime::currentDateTime().toString() + " " + callerString + message); - bufferMutex.unlock(); - emit sigFlushBuffer(); } void ServerLogger::flushBuffer() @@ -107,25 +128,42 @@ void ServerLogger::flushBuffer() } flushRunning = true; - QTextStream stream(logFile); - forever - { - bufferMutex.lock(); - if (buffer.isEmpty()) { - bufferMutex.unlock(); - flushRunning = false; - return; - } - QString message = buffer.takeFirst(); - bufferMutex.unlock(); - stream << message << "\n"; - stream.flush(); + bufferMutex.lock(); + QStringList consoleLines; + consoleLines.swap(consoleBuffer); + bufferMutex.unlock(); - if (logToConsole) { - std::cout << message.toStdString() << std::endl; - } + for (const QString &line : consoleLines) { + std::cout << line.toStdString() << '\n'; } + if (!consoleLines.isEmpty()) { + std::cout.flush(); + } + + if (logFile) { + QTextStream stream(logFile); + forever + { + bufferMutex.lock(); + if (buffer.isEmpty()) { + bufferMutex.unlock(); + break; + } + QString message = buffer.takeFirst(); + bufferMutex.unlock(); + + stream << message << "\n"; + stream.flush(); + } + } else { + // No logfile to write to; do not let the buffer grow without bound. + bufferMutex.lock(); + buffer.clear(); + bufferMutex.unlock(); + } + + flushRunning = false; } void ServerLogger::rotateLogs() @@ -141,5 +179,3 @@ void ServerLogger::rotateLogs() std::cerr << "ERROR: Failed to open log file for writing!" << std::endl; } } - -QFile *ServerLogger::logFile; diff --git a/servatrice/src/server_logger.h b/servatrice/src/server_logger.h index e0be4b712..531430d56 100644 --- a/servatrice/src/server_logger.h +++ b/servatrice/src/server_logger.h @@ -14,7 +14,7 @@ class ServerLogger : public QObject { Q_OBJECT public: - ServerLogger(bool _logToConsole, QObject *parent = 0); + ServerLogger(bool _logToConsole, bool _writeLog, const QString &_logFilters, QObject *parent = nullptr); ~ServerLogger(); /** @@ -27,6 +27,7 @@ public: public slots: void startLog(const QString &logFileName); + void reloadConfig(bool _writeLog, const QString &_logFilters); void logMessage(const QString &message, void *caller = 0); void rotateLogs(); private slots: @@ -36,9 +37,17 @@ signals: private: bool logToConsole; - static QFile *logFile; + bool writeLog = true; + bool messageFilterActive = false; + QStringList logFilters; + // Guards writeLog/messageFilterActive/logFilters: SIGHUP rewrites them while other threads log. + QMutex configMutex; + QFile *logFile = nullptr; bool flushRunning; QStringList buffer; + // Console lines wait here for the logger thread, so game threads never block on stdout. + QStringList consoleBuffer; + // Guards buffer and consoleBuffer. QMutex bufferMutex; }; diff --git a/servatrice/src/signalhandler.cpp b/servatrice/src/signalhandler.cpp index 32cd5b206..b8a7e3538 100644 --- a/servatrice/src/signalhandler.cpp +++ b/servatrice/src/signalhandler.cpp @@ -73,6 +73,8 @@ void SignalHandler::internalSigHupHandler() logger->rotateLogs(); settingsCache->sync(); + logger->reloadConfig(settingsCache->value("server/writelog", 1).toBool(), + settingsCache->value("server/logfilters").toString()); snHup->setEnabled(true); } diff --git a/tests/CMakeLists.txt b/tests/CMakeLists.txt index c3b9a7547..c8d3fbd59 100644 --- a/tests/CMakeLists.txt +++ b/tests/CMakeLists.txt @@ -251,6 +251,17 @@ cockatrice_add_test( LABELS server ) +cockatrice_add_test( + NAME + server_logger_test + SOURCES + ${CMAKE_SOURCE_DIR}/servatrice/src/server_logger.cpp + server_logger_test.cpp + INCLUDE_DIRS + ${CMAKE_SOURCE_DIR}/servatrice/src + LABELS + server +) cockatrice_add_test( NAME server_card_counter_test diff --git a/tests/server_logger_test.cpp b/tests/server_logger_test.cpp new file mode 100644 index 000000000..94a6909bf --- /dev/null +++ b/tests/server_logger_test.cpp @@ -0,0 +1,179 @@ +#include "server_logger.h" + +#include "gtest/gtest.h" +#include +#include +#include +#include +#include +#include + +namespace +{ + +/** + * @brief Redirects std::cout for the lifetime of the object so the logger's console + * sink can be asserted on. + */ +class CoutCapture +{ +public: + CoutCapture() : previousBuffer(std::cout.rdbuf(captured.rdbuf())) + { + } + ~CoutCapture() + { + std::cout.rdbuf(previousBuffer); + } + + QString text() const + { + return QString::fromStdString(captured.str()); + } + +private: + std::ostringstream captured; + std::streambuf *previousBuffer; +}; + +// The console sink is written by the logger thread; drive it directly here, as the event +// loop would in the server. +void flushLogger(ServerLogger &logger) +{ + QMetaObject::invokeMethod(&logger, "flushBuffer", Qt::DirectConnection); +} + +// Regression: --log-to-console used to be gated behind a successfully opened logfile, so an +// empty server/logfile silenced every diagnostic, including critical startup errors. +TEST(ServerLoggerTest, ConsoleSinkDoesNotDependOnLogFile) +{ + ServerLogger logger(true, true, QString()); + logger.startLog(QString()); + + CoutCapture capture; + logger.logMessage("could not open the database"); + flushLogger(logger); + + EXPECT_TRUE(capture.text().contains("could not open the database")) << capture.text().toStdString(); +} + +// writelog only describes the logfile; disabling it must not silence the console. +TEST(ServerLoggerTest, ConsoleSinkSurvivesDisabledFileLog) +{ + QTemporaryDir dir; + ASSERT_TRUE(dir.isValid()); + + ServerLogger logger(true, false, QString()); + logger.startLog(dir.filePath("server.log")); + + CoutCapture capture; + logger.logMessage("startup failed"); + flushLogger(logger); + + EXPECT_TRUE(capture.text().contains("startup failed")) << capture.text().toStdString(); +} + +// logfilters selects what goes into the logfile; the console is not filtered. +TEST(ServerLoggerTest, ConsoleSinkIgnoresLogFilters) +{ + ServerLogger logger(true, true, "database"); + logger.startLog(QString()); + + CoutCapture capture; + logger.logMessage("unrelated message"); + flushLogger(logger); + + EXPECT_TRUE(capture.text().contains("unrelated message")) << capture.text().toStdString(); +} + +TEST(ServerLoggerTest, StaysQuietWhenConsoleIsDisabled) +{ + ServerLogger logger(false, false, QString()); + logger.startLog(QString()); + + CoutCapture capture; + logger.logMessage("not for the console"); + flushLogger(logger); + + EXPECT_TRUE(capture.text().isEmpty()) << capture.text().toStdString(); +} + +TEST(ServerLoggerTest, WritesMatchingFilteredMessagesToTheLogFile) +{ + QTemporaryDir dir; + ASSERT_TRUE(dir.isValid()); + const QString logPath = dir.filePath("server.log"); + + { + ServerLogger logger(false, true, "database"); + logger.startLog(logPath); + logger.logMessage("database is unavailable"); + logger.logMessage("unrelated message"); + } + + QFile logFile(logPath); + ASSERT_TRUE(logFile.open(QIODevice::ReadOnly)); + const QString contents = QString::fromUtf8(logFile.readAll()); + EXPECT_TRUE(contents.contains("database is unavailable")) << contents.toStdString(); + EXPECT_FALSE(contents.contains("unrelated message")) << contents.toStdString(); +} + +// SIGHUP reloads the configuration; the logger must pick up the new filter. +TEST(ServerLoggerTest, ReloadConfigAppliesANewFilter) +{ + QTemporaryDir dir; + ASSERT_TRUE(dir.isValid()); + const QString logPath = dir.filePath("server.log"); + + { + ServerLogger logger(false, true, "database"); + logger.startLog(logPath); + logger.logMessage("filtered out"); + logger.reloadConfig(true, QString()); + logger.logMessage("kept after reload"); + } + + QFile logFile(logPath); + ASSERT_TRUE(logFile.open(QIODevice::ReadOnly)); + const QString contents = QString::fromUtf8(logFile.readAll()); + EXPECT_FALSE(contents.contains("filtered out")) << contents.toStdString(); + EXPECT_TRUE(contents.contains("kept after reload")) << contents.toStdString(); +} + +TEST(ServerLoggerTest, DisabledFileLogLeavesTheLogFileEmpty) +{ + QTemporaryDir dir; + ASSERT_TRUE(dir.isValid()); + const QString logPath = dir.filePath("server.log"); + + { + ServerLogger logger(false, false, QString()); + logger.startLog(logPath); + logger.logMessage("not for the logfile"); + } + + QFile logFile(logPath); + ASSERT_TRUE(logFile.open(QIODevice::ReadOnly)); + EXPECT_TRUE(logFile.readAll().isEmpty()); +} + +// A filter list consisting only of separators activates filtering with no entries; the old +// trimmed-empty check suppressed the logfile in that case and this preserves it. +TEST(ServerLoggerTest, DegenerateFilterSuppressesTheLogFile) +{ + QTemporaryDir dir; + ASSERT_TRUE(dir.isValid()); + const QString logPath = dir.filePath("server.log"); + + { + ServerLogger logger(false, true, ","); + logger.startLog(logPath); + logger.logMessage("anything"); + } + + QFile logFile(logPath); + ASSERT_TRUE(logFile.open(QIODevice::ReadOnly)); + EXPECT_TRUE(logFile.readAll().isEmpty()); +} + +} // namespace