From 825aba953a52c4a325a971e8aa52e62e6f17efd0 Mon Sep 17 00:00:00 2001 From: BruebachL <44814898+BruebachL@users.noreply.github.com> Date: Sat, 31 Oct 2026 19:02:49 +0100 Subject: [PATCH] [Servatrice] Fail loudly when startup initialization fails (#7602) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * [Servatrice] Exit non-zero when server initialization fails initServer() reported every startup failure through a zero exit code: the database could not be opened, the server printed nothing of its own, and the process looked like a clean shutdown. Log the two refusal reasons at critical level and return 1 so supervisors and the Docker exit status can tell the difference. * [Servatrice] Keep console logging independent of the logfile logMessage() returned before the console echo unless a logfile was open and server/writelog was true, so --log-to-console produced nothing when server/logfile was empty or could not be opened. That is how a refused database connection could end in a silent exit. Print to the console before the logfile gates, drop the duplicate echo from flushBuffer(), and read writelog/logfilters once in main instead of calling the non-thread-safe global QSettings from every logging thread. * [Servatrice] Uninstall the log handler before tearing down globals The handler reaches into the global logger and settingsCache. Leaving it installed while main deletes those objects turns any Qt warning emitted during QCoreApplication/QFactoryLoader teardown into a use-after-free; with QT_DEBUG_PLUGINS=1 that warning exists, and Servatrice died with SIGSEGV in QSettings::value() on the way out. * [Servatrice] Buffer console logs on the logger thread Address review feedback on the startup failure change: - Append console lines to a buffer drained by the logger thread, so a stalled stdout reader cannot block game threads. - Report islServer->errorString() instead of the literal call text. - Let the constructor reuse reloadConfig() instead of parsing the filter list twice. --------- Co-authored-by: Lukas Brübach --- servatrice/src/main.cpp | 14 ++- servatrice/src/servatrice.cpp | 14 +-- servatrice/src/server_logger.cpp | 140 +++++++++++++++--------- servatrice/src/server_logger.h | 13 ++- servatrice/src/signalhandler.cpp | 2 + tests/CMakeLists.txt | 11 ++ tests/server_logger_test.cpp | 179 +++++++++++++++++++++++++++++++ 7 files changed, 311 insertions(+), 62 deletions(-) create mode 100644 tests/server_logger_test.cpp 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