diff --git a/libcockatrice_network/libcockatrice/network/client/local/local_client.cpp b/libcockatrice_network/libcockatrice/network/client/local/local_client.cpp index c1c1cc976..f7d8645e8 100644 --- a/libcockatrice_network/libcockatrice/network/client/local/local_client.cpp +++ b/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); } diff --git a/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp b/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp index cbf7dbda2..e02f5d3d8 100644 --- a/libcockatrice_network/libcockatrice/network/client/remote/remote_client.cpp +++ b/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) + - (((quint32)(unsigned char)inputBuffer[1]) << 16) + - (((quint32)(unsigned char)inputBuffer[2]) << 8) + - ((quint32)(unsigned char)inputBuffer[3]); - inputBuffer.remove(0, 4); + const auto *header = reinterpret_cast(inputBuffer.constData() + readOffset); + messageLength = (static_cast(header[0]) << 24) + (static_cast(header[1]) << 16) + + (static_cast(header[2]) << 8) + static_cast(header[3]); + readOffset += 4; messageInProgress = true; } } else { - return; + break; } } - if (inputBuffer.size() < messageLength) { - return; + if (inputBuffer.size() - readOffset < messageLength) { + 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(cont.ByteSize()); #endif - qCDebug(RemoteClientLog).noquote() << "OUT" << getSafeDebugString(cont); + if (RemoteClientLog().isDebugEnabled()) { + qCDebug(RemoteClientLog).noquote() << "OUT" << getSafeDebugString(cont); + } QByteArray buf; bool ok; diff --git a/libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.cpp b/libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.cpp index 25aa415fc..c3524bb93 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.cpp +++ b/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(); diff --git a/libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.h b/libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.h index a19475e34..a2a4ed8c7 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/server_abstractuserinterface.h +++ b/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; diff --git a/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.cpp b/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.cpp index eb2b2fc1c..dd074a517 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.cpp +++ b/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(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> gameMap = getGames(); - if (!gameMap.contains(cont.game_id())) { + int roomId; + int playerId; + if (!getGameInfo(cont.game_id(), roomId, playerId)) { return Response::RespNotInRoom; } - const QPair 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) + - getSafeDebugString(sc)); + if (logsDebugMessages()) { + 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) { diff --git a/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h b/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h index c0a1ffe9a..266c4b26c 100644 --- a/libcockatrice_network/libcockatrice/network/server/remote/server_protocolhandler.h +++ b/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 messageSizeOverTime, messageCountOverTime, commandCountOverTime; diff --git a/servatrice/src/isl_interface.cpp b/servatrice/src/isl_interface.cpp index 8733c9a40..7121bfa48 100644 --- a/servatrice/src/isl_interface.cpp +++ b/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) { - messageLength = (((quint32)(unsigned char)inputBuffer[0]) << 24) + - (((quint32)(unsigned char)inputBuffer[1]) << 16) + - (((quint32)(unsigned char)inputBuffer[2]) << 8) + - ((quint32)(unsigned char)inputBuffer[3]); + if (inputBuffer.size() - readOffset >= 4) { + const auto *header = reinterpret_cast(inputBuffer.constData() + readOffset); + messageLength = (static_cast(header[0]) << 24) + (static_cast(header[1]) << 16) + + (static_cast(header[2]) << 8) + static_cast(header[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) { - return; + if (inputBuffer.size() - readOffset < messageLength) { + break; } IslMessage newMessage; - bool ok = newMessage.ParseFromArray(inputBuffer.data(), messageLength); - inputBuffer.remove(0, messageLength); + bool ok = newMessage.ParseFromArray(inputBuffer.constData() + readOffset, 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: { diff --git a/servatrice/src/server_logger.cpp b/servatrice/src/server_logger.cpp index 1972444f1..1c83299b8 100644 --- a/servatrice/src/server_logger.cpp +++ b/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) { diff --git a/servatrice/src/server_logger.h b/servatrice/src/server_logger.h index f2875a6a3..e0be4b712 100644 --- a/servatrice/src/server_logger.h +++ b/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); diff --git a/servatrice/src/serversocketinterface.cpp b/servatrice/src/serversocketinterface.cpp index 890a93fbc..fc911950e 100644 --- a/servatrice/src/serversocketinterface.cpp +++ b/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) { - messageLength = (((quint32)(unsigned char)inputBuffer[0]) << 24) + - (((quint32)(unsigned char)inputBuffer[1]) << 16) + - (((quint32)(unsigned char)inputBuffer[2]) << 8) + - ((quint32)(unsigned char)inputBuffer[3]); + if (inputBuffer.size() - readOffset >= 4) { + const auto *header = reinterpret_cast(inputBuffer.constData() + readOffset); + messageLength = (static_cast(header[0]) << 24) + (static_cast(header[1]) << 16) + + (static_cast(header[2]) << 8) + static_cast(header[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) { - return; + if (inputBuffer.size() - readOffset < messageLength) { + 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 - << "Exception:" << e.what() << Qt::endl - << "Message coming from:" << getAddress() << Qt::endl - << "Message length:" << messageLength << Qt::endl - << "Message content:" << inputBuffer.toHex(); + << Qt::endl + << "Exception:" << e.what() << Qt::endl + << "Message coming from:" << getAddress() << Qt::endl + << "Message length:" << messageLength << Qt::endl + << "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() diff --git a/servatrice/src/serversocketinterface.h b/servatrice/src/serversocketinterface.h index dd9d3f2bb..71854513f 100644 --- a/servatrice/src/serversocketinterface.h +++ b/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;