[Servatrice] Fail loudly when startup initialization fails (#7602)

* [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 <Bruebach.Lukas@bdosecurity.de>

servatrice/src/main.cpp

@@ -41,6 +41,7 @@
 #include <QThread>
 #include <QVariant>
 #include <QVector>
+#include <cstdlib>
 #include <google/protobuf/stubs/common.h>
 #include <iostream>
 #include <libcockatrice/rng/rng_sfmt.h>
@@ -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;

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<quint16>(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<quint16>(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<quint16>(getServerWebSocketPort()))) {
             qDebug() << "Websocket server listening.";
         } else {
-            qDebug() << "websocketGameServer->listen(): Error:" << websocketGameServer->errorString();
+            qCCritical(ServatriceLog) << "Failed to listen for websocket clients:"
+                                      << websocketGameServer->errorString();
             return false;
         }
     }

servatrice/src/server_logger.cpp

@@ -1,7 +1,5 @@
 #include "server_logger.h"
 
-#include "settingscache.h"
-
 #include <QDateTime>
 #include <QDir>
 #include <QFile>
@@ -10,33 +8,37 @@
 #include <QIODevice>
 #include <QTextStream>
 #include <QThread>
-#include <QVariant>
 #include <QtGlobal>
 #include <iostream>
 #include <qnamespace.h>
 #include <qobjectdefs.h>
 #include <string>
 
-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<qulonglong>(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;

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;
 };
 

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);
 }

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

tests/server_logger_test.cpp

@@ -0,0 +1,179 @@
+#include "server_logger.h"
+
+#include "gtest/gtest.h"
+#include <QFile>
+#include <QMetaObject>
+#include <QTemporaryDir>
+#include <iostream>
+#include <sstream>
+#include <streambuf>
+
+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