[Network] Do not format discarded debug messages, parse without memmove (#7606)

* [Network] Do not format discarded debug messages, parse without memmove

Protocol debug logging gets the full protobuf message rendered through
TextFormat and reflection. On the server this happened before every
session/room/game/moderator/admin/developer command, even though the
default Server_ProtocolHandler::logDebugMessage() is a no-op and even
when servatrice has no log file configured. On the clients the same
string was built as an argument to qCDebug(), which evaluates its
arguments regardless of whether the category is enabled.

Server_ProtocolHandler now exposes a virtual logsDebugMessages() hook.
The base implementation returns false, so handlers without a log
destination spend nothing. AbstractServerSocketInterface overrides it
with ServerLogger::isLoggingEnabled(), which checks the log file and the
server/writelog setting that logMessage() itself consults. All debug
message call sites check the hook before formatting. The client
send/receive paths check QLoggingCategory::isDebugEnabled() first, the
same pattern AbstractClient already uses for its slow-command warning.
ISL message decoding does the same.

Byte stream decoding called inputBuffer.remove(0, n) for the length
header and then again for every message. Each call shifts all remaining
bytes, so a read carrying k messages cost O(k * bytes remaining). The
three receive loops (remote client, TCP server interface, ISL interface)
now parse at a read offset and compact the consumed prefix once, when
they stop because a full message is not buffered yet. No buffering or
size-limit behavior changes.

Also in this batch:
- Server_ProtocolHandler::processGameCommandContainer() copied the whole
  games map under gameListMutex just to look up one game id. A new
  getGameInfo() performs the single lookup and returns the room/player
  ids.
- The TCP receive loop's `ok` flag is initialized, so a ParseFromArray
  exception can no longer leave it indeterminate before `if (ok)`.
- The exception log prints only the message being parsed instead of
  hex-dumping the entire pending buffer.

Full build and ctest (628 tests) pass, including the server tests.

* [Network] Address review comments

- Move getGameInfo() out of the header into server_abstractuserinterface.cpp.
- Drop the consumed prefix once after the parse loop instead of on every
  early return: the two "not enough data" exits now break out of the loop.
  Applied to the remote client, TCP server and ISL receive loops.

---------

Co-authored-by: Lukas Brübach <Bruebach.Lukas@bdosecurity.de>

libcockatrice_network/libcockatrice/network/client/local/local_client.cpp

@@ -39,14 +39,18 @@ LocalClient::~LocalClient()
 
 void LocalClient::sendCommandContainer(const CommandContainer &cont)
 {
-    qCDebug(LocalClientLog).noquote() << userName << "OUT" << getSafeDebugString(cont);
+    if (LocalClientLog().isDebugEnabled()) {
+        qCDebug(LocalClientLog).noquote() << userName << "OUT" << getSafeDebugString(cont);
+    }
 
     lsi->itemFromClient(cont);
 }
 
 void LocalClient::itemFromServer(const ServerMessage &item)
 {
-    qCDebug(LocalClientLog).noquote() << userName << "IN" << getSafeDebugString(item);
+    if (LocalClientLog().isDebugEnabled()) {
+        qCDebug(LocalClientLog).noquote() << userName << "IN" << getSafeDebugString(item);
+    }
 
     processProtocolItem(item);
 }

libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp

@@ -496,9 +496,15 @@ void RemoteClient::readData()
 
     inputBuffer.append(data);
 
-    do {
+    // Parse messages straight out of inputBuffer at readOffset. Removing each
+    // consumed message from the front of the buffer would memmove all of the
+    // remaining bytes once per message; instead the consumed prefix is dropped
+    // once parsing stops.
+    qsizetype readOffset = 0;
+
+    while (true) {
         if (!messageInProgress) {
-            if (inputBuffer.size() >= 4) {
+            if (inputBuffer.size() - readOffset >= 4) {
                 // dirty hack to be compatible with v14 server that sends 60 bytes of garbage at the beginning
                 if (!handshakeStarted) {
                     handshakeStarted = true;
@@ -508,29 +514,30 @@ void RemoteClient::readData()
                     }
                 } else {
                     // end of hack
-                    messageLength = (((quint32)(unsigned char)inputBuffer[0]) << 24) +
+                    const auto *header = reinterpret_cast<const unsigned char *>(inputBuffer.constData() + readOffset);
-                                    (((quint32)(unsigned char)inputBuffer[1]) << 16) +
+                    messageLength = (static_cast<quint32>(header[0]) << 24) + (static_cast<quint32>(header[1]) << 16) +
-                                    (((quint32)(unsigned char)inputBuffer[2]) << 8) +
+                                    (static_cast<quint32>(header[2]) << 8) + static_cast<quint32>(header[3]);
-                                    ((quint32)(unsigned char)inputBuffer[3]);
+                    readOffset += 4;
-                    inputBuffer.remove(0, 4);
                     messageInProgress = true;
                 }
             } else {
-                return;
+                break;
             }
         }
-        if (inputBuffer.size() < messageLength) {
+        if (inputBuffer.size() - readOffset < messageLength) {
-            return;
+            break;
         }
 
         ServerMessage newServerMessage;
-        bool ok = newServerMessage.ParseFromArray(inputBuffer.data(), messageLength);
+        bool ok = newServerMessage.ParseFromArray(inputBuffer.constData() + readOffset, messageLength);
 
-        inputBuffer.remove(0, messageLength);
+        readOffset += messageLength;
         messageInProgress = false;
 
         if (ok) {
-            qCDebug(RemoteClientLog).noquote() << "IN" << getSafeDebugString(newServerMessage);
+            if (RemoteClientLog().isDebugEnabled()) {
+                qCDebug(RemoteClientLog).noquote() << "IN" << getSafeDebugString(newServerMessage);
+            }
 
             processProtocolItem(newServerMessage);
         } else {
@@ -540,7 +547,12 @@ void RemoteClient::readData()
         if (getStatus() == StatusDisconnecting) { // use thread-safe getter
             doDisconnectFromServer();
         }
-    } while (!inputBuffer.isEmpty());
+    }
+
+    // Drop the consumed prefix once, instead of shifting the buffer per message.
+    if (readOffset > 0) {
+        inputBuffer.remove(0, readOffset);
+    }
 }
 
 void RemoteClient::websocketMessageReceived(const QByteArray &message)
@@ -548,7 +560,9 @@ void RemoteClient::websocketMessageReceived(const QByteArray &message)
     lastDataReceived = timeRunning;
     ServerMessage newServerMessage;
     if (newServerMessage.ParseFromArray(message.data(), message.length())) {
-        qCDebug(RemoteClientLog).noquote() << "IN" << getSafeDebugString(newServerMessage);
+        if (RemoteClientLog().isDebugEnabled()) {
+            qCDebug(RemoteClientLog).noquote() << "IN" << getSafeDebugString(newServerMessage);
+        }
 
         processProtocolItem(newServerMessage);
     } else {
@@ -564,7 +578,9 @@ void RemoteClient::sendCommandContainer(const CommandContainer &cont)
     auto size = static_cast<unsigned int>(cont.ByteSize());
 #endif
 
-    qCDebug(RemoteClientLog).noquote() << "OUT" << getSafeDebugString(cont);
+    if (RemoteClientLog().isDebugEnabled()) {
+        qCDebug(RemoteClientLog).noquote() << "OUT" << getSafeDebugString(cont);
+    }
 
     QByteArray buf;
     bool ok;

libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.cpp

@@ -84,6 +84,18 @@ void Server_AbstractUserInterface::onLogin(ResponseContainer &)
 {
 }
 
+bool Server_AbstractUserInterface::getGameInfo(int gameId, int &roomId, int &playerId) const
+{
+    QMutexLocker locker(&gameListMutex);
+    const auto it = games.constFind(gameId);
+    if (it == games.constEnd()) {
+        return false;
+    }
+    roomId = it.value().first;
+    playerId = it.value().second;
+    return true;
+}
+
 void Server_AbstractUserInterface::playerRemovedFromGame(Server_Game *game)
 {
     qDebug() << "Server_AbstractUserInterface::playerRemovedFromGame(): gameId =" << game->getGameId();

libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.h

@@ -58,6 +58,13 @@ public:
         return games;
     }
 
+    /**
+     * @brief Looks up the room and player id of one game without copying the game list.
+     *
+     * @return True if the game is known; otherwise false and the outputs are untouched.
+     */
+    bool getGameInfo(int gameId, int &roomId, int &playerId) const;
+
     virtual void sendProtocolItem(const Response &item) = 0;
     virtual void sendProtocolItem(const SessionEvent &item) = 0;
     virtual void sendProtocolItem(const GameEventContainer &item) = 0;

libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.cpp

@@ -208,7 +208,7 @@ Response::ResponseCode Server_ProtocolHandler::processSessionCommandContainer(co
         Response::ResponseCode resp = Response::RespInvalidCommand;
         const SessionCommand &sc = cont.session_command(i);
         const int num = getPbExtension(sc);
-        if (num != SessionCommand::PING) { // don't log ping commands
+        if (num != SessionCommand::PING && logsDebugMessages()) { // don't log ping commands
             logDebugMessage(getSafeDebugString(sc));
         }
         const auto commandType = static_cast<SessionCommand::SessionCommandType>(num);
@@ -271,7 +271,9 @@ Response::ResponseCode Server_ProtocolHandler::processRoomCommandContainer(const
         Response::ResponseCode resp = Response::RespInvalidCommand;
         const RoomCommand &sc = cont.room_command(i);
         const int num = getPbExtension(sc);
-        logDebugMessage(getSafeDebugString(sc));
+        if (logsDebugMessages()) {
+            logDebugMessage(getSafeDebugString(sc));
+        }
         switch ((RoomCommand::RoomCommandType)num) {
             case RoomCommand::LEAVE_ROOM:
                 resp = cmdLeaveRoom(sc.GetExtension(Command_LeaveRoom::ext), room, rc);
@@ -320,14 +322,14 @@ Response::ResponseCode Server_ProtocolHandler::processGameCommandContainer(const
         return Response::RespLoginNeeded;
     }
 
-    QMap<int, QPair<int, int>> gameMap = getGames();
+    int roomId;
-    if (!gameMap.contains(cont.game_id())) {
+    int playerId;
+    if (!getGameInfo(cont.game_id(), roomId, playerId)) {
         return Response::RespNotInRoom;
     }
-    const QPair<int, int> roomIdAndPlayerId = gameMap.value(cont.game_id());
 
     QReadLocker roomsLocker(&server->roomsLock);
-    Server_Room *room = server->getRooms().value(roomIdAndPlayerId.first);
+    Server_Room *room = server->getRooms().value(roomId);
     if (!room) {
         return Response::RespNotInRoom;
     }
@@ -337,14 +339,14 @@ Response::ResponseCode Server_ProtocolHandler::processGameCommandContainer(const
     if (!game) {
         if (room->getExternalGames().contains(cont.game_id())) {
             server->sendIsl_GameCommand(cont, room->getExternalGames().value(cont.game_id()).server_id(),
-                                        userInfo->session_id(), roomIdAndPlayerId.first, roomIdAndPlayerId.second);
+                                        userInfo->session_id(), roomId, playerId);
             return Response::RespNothing;
         }
         return Response::RespNotInRoom;
     }
 
     QMutexLocker gameLocker(&game->gameMutex);
-    auto *participant = game->getParticipants().value(roomIdAndPlayerId.second);
+    auto *participant = game->getParticipants().value(playerId);
     if (!participant) {
         return Response::RespNotInRoom;
     }
@@ -357,8 +359,9 @@ Response::ResponseCode Server_ProtocolHandler::processGameCommandContainer(const
     Response::ResponseCode finalResponseCode = Response::RespOk;
     for (int i = cont.game_command_size() - 1; i >= 0; --i) {
         const GameCommand &sc = cont.game_command(i);
-        logDebugMessage(QString("game %1 player %2: ").arg(cont.game_id()).arg(roomIdAndPlayerId.second) +
+        if (logsDebugMessages()) {
-                        getSafeDebugString(sc));
+            logDebugMessage(QString("game %1 player %2: ").arg(cont.game_id()).arg(playerId) + getSafeDebugString(sc));
+        }
 
         if (commandCountingInterval > 0) {
             int totalCount = 0;
@@ -407,7 +410,9 @@ Response::ResponseCode Server_ProtocolHandler::processModeratorCommandContainer(
         Response::ResponseCode resp = Response::RespInvalidCommand;
         const ModeratorCommand &sc = cont.moderator_command(i);
         const int num = getPbExtension(sc);
-        logDebugMessage(getSafeDebugString(sc));
+        if (logsDebugMessages()) {
+            logDebugMessage(getSafeDebugString(sc));
+        }
 
         resp = processExtendedModeratorCommand(num, sc, rc);
         if (resp != Response::RespOk) {
@@ -434,7 +439,9 @@ Response::ResponseCode Server_ProtocolHandler::processAdminCommandContainer(cons
         Response::ResponseCode resp = Response::RespInvalidCommand;
         const AdminCommand &sc = cont.admin_command(i);
         const int num = getPbExtension(sc);
-        logDebugMessage(getSafeDebugString(sc));
+        if (logsDebugMessages()) {
+            logDebugMessage(getSafeDebugString(sc));
+        }
 
         resp = processExtendedAdminCommand(num, sc, rc);
         if (resp != Response::RespOk) {
@@ -461,7 +468,9 @@ Response::ResponseCode Server_ProtocolHandler::processDeveloperCommandContainer(
         Response::ResponseCode resp = Response::RespInvalidCommand;
         const DeveloperCommand &sc = cont.developer_command(i);
         const int num = getPbExtension(sc);
-        logDebugMessage(getSafeDebugString(sc));
+        if (logsDebugMessages()) {
+            logDebugMessage(getSafeDebugString(sc));
+        }
 
         resp = processExtendedDeveloperCommand(num, sc, rc);
         if (resp != Response::RespOk) {

libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h

@@ -55,6 +55,17 @@ protected:
     virtual void logDebugMessage(const QString & /* message */)
     {
     }
+    /**
+     * @brief Whether debug messages produced by this handler are actually written anywhere.
+     *
+     * Formatting a protocol message for the log is expensive, so callers only
+     * build the debug string when this returns true. The base handler has no
+     * log destination and therefore never needs one.
+     */
+    [[nodiscard]] virtual bool logsDebugMessages() const
+    {
+        return false;
+    }
 
 private:
     QList<int> messageSizeOverTime, messageCountOverTime, commandCountOverTime;

servatrice/src/isl_interface.cpp

@@ -264,13 +264,17 @@ void IslInterface::readClient()
     server->incRxBytes(data.size());
     inputBuffer.append(data);
 
-    do {
+    // Parse messages straight out of inputBuffer at readOffset. Removing each
+    // consumed message from the front would memmove the remaining bytes once
+    // per message; the consumed prefix is dropped once parsing stops.
+    qsizetype readOffset = 0;
+
+    while (true) {
         if (!messageInProgress) {
-            if (inputBuffer.size() >= 4) {
+            if (inputBuffer.size() - readOffset >= 4) {
-                messageLength = (((quint32)(unsigned char)inputBuffer[0]) << 24) +
+                const auto *header = reinterpret_cast<const unsigned char *>(inputBuffer.constData() + readOffset);
-                                (((quint32)(unsigned char)inputBuffer[1]) << 16) +
+                messageLength = (static_cast<quint32>(header[0]) << 24) + (static_cast<quint32>(header[1]) << 16) +
-                                (((quint32)(unsigned char)inputBuffer[2]) << 8) +
+                                (static_cast<quint32>(header[2]) << 8) + static_cast<quint32>(header[3]);
-                                ((quint32)(unsigned char)inputBuffer[3]);
                 // Reject implausible lengths instead of buffering until they arrive.
                 // This also handles lengths that overflow into negative int values.
                 if (messageLength < 0 || messageLength > MAX_ISL_MESSAGE_SIZE) {
@@ -278,19 +282,19 @@ void IslInterface::readClient()
                     socket->disconnectFromHost();
                     return;
                 }
-                inputBuffer.remove(0, 4);
+                readOffset += 4;
                 messageInProgress = true;
             } else {
-                return;
+                break;
             }
         }
-        if (inputBuffer.size() < messageLength) {
+        if (inputBuffer.size() - readOffset < messageLength) {
-            return;
+            break;
         }
 
         IslMessage newMessage;
-        bool ok = newMessage.ParseFromArray(inputBuffer.data(), messageLength);
+        bool ok = newMessage.ParseFromArray(inputBuffer.constData() + readOffset, messageLength);
-        inputBuffer.remove(0, messageLength);
+        readOffset += messageLength;
         messageInProgress = false;
 
         if (ok) {
@@ -298,7 +302,12 @@ void IslInterface::readClient()
         } else {
             qCWarning(IslInterfaceLog) << "parsing error!";
         }
-    } while (!inputBuffer.isEmpty());
+    }
+
+    // Drop the consumed prefix once, instead of shifting the buffer per message.
+    if (readOffset > 0) {
+        inputBuffer.remove(0, readOffset);
+    }
 }
 
 void IslInterface::catchSocketError(QAbstractSocket::SocketError socketError)
@@ -495,7 +504,9 @@ void IslInterface::processRoomCommand(const CommandContainer &cont, qint64 sessi
 
 void IslInterface::processMessage(const IslMessage &item)
 {
-    qCDebug(IslInterfaceLog) << getSafeDebugString(item);
+    if (IslInterfaceLog().isDebugEnabled()) {
+        qCDebug(IslInterfaceLog) << getSafeDebugString(item);
+    }
 
     switch (item.message_type()) {
         case IslMessage::ROOM_COMMAND_CONTAINER: {

servatrice/src/server_logger.cpp

@@ -54,6 +54,11 @@ void ServerLogger::startLog(const QString &logFileName)
     connect(this, SIGNAL(sigFlushBuffer()), this, SLOT(flushBuffer()), Qt::QueuedConnection);
 }
 
+bool ServerLogger::isLoggingEnabled() const
+{
+    return logFile != nullptr && settingsCache->value("server/writelog", 1).toBool();
+}
+
 void ServerLogger::logMessage(const QString &message, void *caller)
 {
     if (!logFile) {

servatrice/src/server_logger.h

@@ -16,6 +16,15 @@ class ServerLogger : public QObject
 public:
     ServerLogger(bool _logToConsole, QObject *parent = 0);
     ~ServerLogger();
+
+    /**
+     * @brief Whether messages passed to logMessage() would be written anywhere.
+     *
+     * Callers use this to avoid formatting expensive debug payloads that
+     * logMessage() would discard.
+     */
+    [[nodiscard]] bool isLoggingEnabled() const;
+
 public slots:
     void startLog(const QString &logFileName);
     void logMessage(const QString &message, void *caller = 0);

servatrice/src/serversocketinterface.cpp

@@ -265,6 +265,11 @@ void AbstractServerSocketInterface::logDebugMessage(const QString &message)
     logger->logMessage(message, this);
 }
 
+bool AbstractServerSocketInterface::logsDebugMessages() const
+{
+    return logger != nullptr && logger->isLoggingEnabled();
+}
+
 void AbstractServerSocketInterface::processCommandContainer(const CommandContainer &cont)
 {
     QElapsedTimer timer;
@@ -4431,13 +4436,17 @@ void TcpServerSocketInterface::readClient()
     servatrice->incRxBytes(data.size());
     inputBuffer.append(data);
 
-    do {
+    // Parse messages straight out of inputBuffer at readOffset. Removing each
+    // consumed message from the front would memmove the remaining bytes once
+    // per message; the consumed prefix is dropped once parsing stops.
+    qsizetype readOffset = 0;
+
+    while (true) {
         if (!messageInProgress) {
-            if (inputBuffer.size() >= 4) {
+            if (inputBuffer.size() - readOffset >= 4) {
-                messageLength = (((quint32)(unsigned char)inputBuffer[0]) << 24) +
+                const auto *header = reinterpret_cast<const unsigned char *>(inputBuffer.constData() + readOffset);
-                                (((quint32)(unsigned char)inputBuffer[1]) << 16) +
+                messageLength = (static_cast<quint32>(header[0]) << 24) + (static_cast<quint32>(header[1]) << 16) +
-                                (((quint32)(unsigned char)inputBuffer[2]) << 8) +
+                                (static_cast<quint32>(header[2]) << 8) + static_cast<quint32>(header[3]);
-                                ((quint32)(unsigned char)inputBuffer[3]);
                 // Reject implausible lengths instead of buffering until they arrive.
                 // This also handles lengths that overflow into negative int values.
                 if (messageLength < 0 || messageLength > MAX_TCP_MESSAGE_SIZE) {
@@ -4446,32 +4455,33 @@ void TcpServerSocketInterface::readClient()
                     prepareDestroy();
                     return;
                 }
-                inputBuffer.remove(0, 4);
+                readOffset += 4;
                 messageInProgress = true;
             } else {
-                return;
+                break;
             }
         }
-        if (inputBuffer.size() < messageLength) {
+        if (inputBuffer.size() - readOffset < messageLength) {
-            return;
+            break;
         }
 
         CommandContainer newCommandContainer;
-        bool ok;
+        bool ok = false;
         try {
-            ok = newCommandContainer.ParseFromArray(inputBuffer.data(), messageLength);
+            ok = newCommandContainer.ParseFromArray(inputBuffer.constData() + readOffset, messageLength);
         } catch (std::exception &e) {
-            qCWarning(TcpServerSocketInterfaceLog) << "Caught std::exception in" << __FILE__ << __LINE__ <<
+            qCWarning(TcpServerSocketInterfaceLog)
+                << "Caught std::exception in" << __FILE__ << __LINE__ <<
 #ifdef _MSC_VER // Visual Studio
                 __FUNCTION__
 #else
                 __PRETTY_FUNCTION__
 #endif
-                                                   << Qt::endl
+                << Qt::endl
-                                                   << "Exception:" << e.what() << Qt::endl
+                << "Exception:" << e.what() << Qt::endl
-                                                   << "Message coming from:" << getAddress() << Qt::endl
+                << "Message coming from:" << getAddress() << Qt::endl
-                                                   << "Message length:" << messageLength << Qt::endl
+                << "Message length:" << messageLength << Qt::endl
-                                                   << "Message content:" << inputBuffer.toHex();
+                << "Message content:" << inputBuffer.mid(readOffset, messageLength).toHex();
         } catch (...) {
             qCWarning(TcpServerSocketInterfaceLog) << "Unhandled exception in" << __FILE__ << __LINE__ <<
 #ifdef _MSC_VER // Visual Studio
@@ -4482,7 +4492,7 @@ void TcpServerSocketInterface::readClient()
                                                    << Qt::endl
                                                    << "Message coming from:" << getAddress();
         }
-        inputBuffer.remove(0, messageLength);
+        readOffset += messageLength;
         messageInProgress = false;
 
         if (ok) {
@@ -4499,8 +4509,12 @@ void TcpServerSocketInterface::readClient()
         } else {
             qCWarning(TcpServerSocketInterfaceLog) << "parsing error!";
         }
+    }
 
-    } while (!inputBuffer.isEmpty());
+    // Drop the consumed prefix once, instead of shifting the buffer per message.
+    if (readOffset > 0) {
+        inputBuffer.remove(0, readOffset);
+    }
 }
 
 bool TcpServerSocketInterface::initTcpSession()

servatrice/src/serversocketinterface.h

@@ -123,6 +123,7 @@ signals:
 
 protected:
     void logDebugMessage(const QString &message) override;
+    [[nodiscard]] bool logsDebugMessages() const override;
     bool tooManyRegistrationAttempts(const QString &ipAddress);
     void processCommandContainer(const CommandContainer &cont) override;
     bool acceptsCredentialFormat(bool passwordNeedsHash, const QString &password) const;