From 7108eb42c8dd6613d9b2d9878c1dc6355603e2d7 Mon Sep 17 00:00:00 2001 From: ebbit1q Date: Wed, 23 Feb 2022 23:46:23 +0100 Subject: [PATCH] implement custom protobuf debug string creation (#4532) * implement custom protobuf debug log string creation * add version guards * add missing header * debian10 repository misses headers * clean up logging messages a bit * fix some more formatting on debug messages --- cockatrice/src/remoteclient.cpp | 7 +- common/CMakeLists.txt | 1 + common/debug_pb_message.cpp | 116 ++++++++++++++++++ common/debug_pb_message.h | 15 +++ common/server.cpp | 3 +- common/server_protocolhandler.cpp | 22 ++-- servatrice/src/isl_interface.cpp | 3 +- servatrice/src/servatrice.cpp | 50 ++++---- .../src/servatrice_database_interface.cpp | 2 +- servatrice/src/serversocketinterface.cpp | 10 +- 10 files changed, 178 insertions(+), 51 deletions(-) create mode 100644 common/debug_pb_message.cpp create mode 100644 common/debug_pb_message.h diff --git a/cockatrice/src/remoteclient.cpp b/cockatrice/src/remoteclient.cpp index 6b9a0940..53037bfb 100644 --- a/cockatrice/src/remoteclient.cpp +++ b/cockatrice/src/remoteclient.cpp @@ -1,5 +1,6 @@ #include "remoteclient.h" +#include "debug_pb_message.h" #include "main.h" #include "passwordhasher.h" #include "pb/event_server_identification.pb.h" @@ -387,7 +388,7 @@ void RemoteClient::readData() ServerMessage newServerMessage; newServerMessage.ParseFromArray(inputBuffer.data(), messageLength); #ifdef QT_DEBUG - qDebug() << "IN" << messageLength << QString::fromStdString(newServerMessage.ShortDebugString()); + qDebug().noquote() << "IN" << getSafeDebugString(newServerMessage); #endif inputBuffer.remove(0, messageLength); messageInProgress = false; @@ -405,7 +406,7 @@ void RemoteClient::websocketMessageReceived(const QByteArray &message) ServerMessage newServerMessage; newServerMessage.ParseFromArray(message.data(), message.length()); #ifdef QT_DEBUG - qDebug() << "IN" << messageLength << QString::fromStdString(newServerMessage.ShortDebugString()); + qDebug().noquote() << "IN" << getSafeDebugString(newServerMessage); #endif processProtocolItem(newServerMessage); } @@ -418,7 +419,7 @@ void RemoteClient::sendCommandContainer(const CommandContainer &cont) auto size = static_cast(cont.ByteSize()); #endif #ifdef QT_DEBUG - qDebug() << "OUT" << size << QString::fromStdString(cont.ShortDebugString()); + qDebug().noquote() << "OUT" << getSafeDebugString(cont); #endif QByteArray buf; diff --git a/common/CMakeLists.txt b/common/CMakeLists.txt index 65064274..5d2e6097 100644 --- a/common/CMakeLists.txt +++ b/common/CMakeLists.txt @@ -5,6 +5,7 @@ add_subdirectory(pb) SET(common_SOURCES + debug_pb_message.cpp decklist.cpp expression.cpp featureset.cpp diff --git a/common/debug_pb_message.cpp b/common/debug_pb_message.cpp new file mode 100644 index 00000000..616957a7 --- /dev/null +++ b/common/debug_pb_message.cpp @@ -0,0 +1,116 @@ +#include "debug_pb_message.h" + +#include "stringsizes.h" + +#include +#include +#include +#include +#include + +// google/protobuf/stubs/strutil.h is missing on some systems! +namespace google +{ +namespace protobuf +{ +std::string CEscape(const std::string &src); +} // namespace protobuf +} // namespace google + +// FastFieldValuePrinter is added in protobuf 3.4, going out of our way to add the old FieldValuePrinter is not worth it +#if GOOGLE_PROTOBUF_VERSION > 3004000 + +// value printer to use for all values, will snip too long contents +class LimitedPrinter : public ::google::protobuf::TextFormat::FastFieldValuePrinter +{ +public: + void PrintString(const std::string &val, + ::google::protobuf::TextFormat::BaseTextGenerator *generator) const override; +}; + +// value printer to use for specifc values, will expunge sensitive info +class SafePrinter : public ::google::protobuf::TextFormat::FastFieldValuePrinter +{ +public: + void PrintString(const std::string &val, + ::google::protobuf::TextFormat::BaseTextGenerator *generator) const override; + + static void applySafePrinter(const ::google::protobuf::Message &message, + ::google::protobuf::TextFormat::Printer &printer); +}; + +void LimitedPrinter::PrintString(const std::string &val, + ::google::protobuf::TextFormat::BaseTextGenerator *generator) const +{ + auto length = val.length(); + if (length > MAX_TEXT_LENGTH) { + generator->PrintString("\"" + ::google::protobuf::CEscape(val.substr(0, MAX_NAME_LENGTH)) + "... ---snip--- (" + + std::to_string(length) + " bytes total) \""); + } else { + ::google::protobuf::TextFormat::FastFieldValuePrinter::PrintString(val, generator); + } +} + +void SafePrinter::PrintString(const std::string & /*val*/, + ::google::protobuf::TextFormat::BaseTextGenerator *generator) const +{ + generator->PrintLiteral("\" ---value expunged--- \""); +} + +void SafePrinter::applySafePrinter(const ::google::protobuf::Message &message, + ::google::protobuf::TextFormat::Printer &printer) +{ + const auto *reflection = message.GetReflection(); + std::vector fields; + reflection->ListFields(message, &fields); + for (const auto *field : fields) { + switch (field->cpp_type()) { + case ::google::protobuf::FieldDescriptor::CPPTYPE_STRING: + if (field->name().find("password") != std::string::npos) { // name contains password + auto *safePrinter = new SafePrinter(); + if (!printer.RegisterFieldValuePrinter(field, safePrinter)) + delete safePrinter; // in case safePrinter has not been taken ownership of + } + break; + case google::protobuf::FieldDescriptor::CPPTYPE_MESSAGE: + if (field->is_repeated()) { + for (int i = 0; i < reflection->FieldSize(message, field); ++i) { + applySafePrinter(reflection->GetRepeatedMessage(message, field, i), printer); + } + } else { + applySafePrinter(reflection->GetMessage(message, field), printer); + } + break; + default: + break; + } + } +} +#endif // GOOGLE_PROTOBUF_VERSION > 3004000 + +QString getSafeDebugString(const ::google::protobuf::Message &message) +{ +#if GOOGLE_PROTOBUF_VERSION > 3001000 + auto size = message.ByteSizeLong(); +#else + auto size = message.ByteSize(); +#endif + + ::google::protobuf::TextFormat::Printer printer; + printer.SetSingleLineMode(true); // compact mode + printer.SetExpandAny(true); // prints all fields + +#if GOOGLE_PROTOBUF_VERSION > 3004000 + // printer takes ownership of the LimitedPrinter and will delete it + printer.SetDefaultFieldValuePrinter(new LimitedPrinter()); + // check field names an create SafePrinters for necessary fields + SafePrinter::applySafePrinter(message, printer); +#else + // removing passwords from debug output will only be supported on newer protobuf versions + printer.SetTruncateStringFieldLongerThan(MAX_TEXT_LENGTH); +#endif // GOOGLE_PROTOBUF_VERSION > 3004000 + + std::string debug_string; + printer.PrintToString(message, &debug_string); + return QString::number(size) + " bytes " + QString::fromStdString(debug_string); +} diff --git a/common/debug_pb_message.h b/common/debug_pb_message.h new file mode 100644 index 00000000..34e7845c --- /dev/null +++ b/common/debug_pb_message.h @@ -0,0 +1,15 @@ +#ifndef DEBUG_PB_MESSAGE_H +#define DEBUG_PB_MESSAGE_H + +class QString; +namespace google +{ +namespace protobuf +{ +class Message; +} +} // namespace google + +QString getSafeDebugString(const ::google::protobuf::Message &message); + +#endif // DEBUG_PB_MESSAGE_H diff --git a/common/server.cpp b/common/server.cpp index af940142..7a2aa3f8 100644 --- a/common/server.cpp +++ b/common/server.cpp @@ -19,6 +19,7 @@ ***************************************************************************/ #include "server.h" +#include "debug_pb_message.h" #include "featureset.h" #include "pb/event_connection_closed.pb.h" #include "pb/event_list_rooms.pb.h" @@ -486,7 +487,7 @@ void Server::externalGameCommandContainerReceived(const CommandContainer &cont, GameEventStorage ges; for (int i = cont.game_command_size() - 1; i >= 0; --i) { const GameCommand &sc = cont.game_command(i); - qDebug() << "[ISL]" << QString::fromStdString(sc.ShortDebugString()); + qDebug() << "[ISL]" << getSafeDebugString(sc); Response::ResponseCode resp = player->processGameCommand(sc, responseContainer, ges); diff --git a/common/server_protocolhandler.cpp b/common/server_protocolhandler.cpp index 2daa1118..6db54547 100644 --- a/common/server_protocolhandler.cpp +++ b/common/server_protocolhandler.cpp @@ -1,5 +1,6 @@ #include "server_protocolhandler.h" +#include "debug_pb_message.h" #include "featureset.h" #include "get_pb_extension.h" #include "pb/commands.pb.h" @@ -134,17 +135,8 @@ 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::LOGIN) { // log login commands, but hide passwords - SessionCommand debugSc(sc); - debugSc.MutableExtension(Command_Login::ext)->clear_password(); - logDebugMessage(QString::fromStdString(debugSc.ShortDebugString())); - } else if (num == SessionCommand::REGISTER) { - SessionCommand logSc(sc); - logSc.MutableExtension(Command_Register::ext)->clear_password(); - logDebugMessage(QString::fromStdString(logSc.ShortDebugString())); - } else - logDebugMessage(QString::fromStdString(sc.ShortDebugString())); + if (num != SessionCommand::PING) { // don't log ping commands + logDebugMessage(getSafeDebugString(sc)); } switch ((SessionCommand::SessionCommandType)num) { case SessionCommand::PING: @@ -198,7 +190,7 @@ Response::ResponseCode Server_ProtocolHandler::processRoomCommandContainer(const Response::ResponseCode resp = Response::RespInvalidCommand; const RoomCommand &sc = cont.room_command(i); const int num = getPbExtension(sc); - logDebugMessage(QString::fromStdString(sc.ShortDebugString())); + logDebugMessage(getSafeDebugString(sc)); switch ((RoomCommand::RoomCommandType)num) { case RoomCommand::LEAVE_ROOM: resp = cmdLeaveRoom(sc.GetExtension(Command_LeaveRoom::ext), room, rc); @@ -277,7 +269,7 @@ Response::ResponseCode Server_ProtocolHandler::processGameCommandContainer(const 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) + - QString::fromStdString(sc.ShortDebugString())); + getSafeDebugString(sc)); if (commandCountingInterval > 0) { int totalCount = 0; @@ -321,7 +313,7 @@ Response::ResponseCode Server_ProtocolHandler::processModeratorCommandContainer( Response::ResponseCode resp = Response::RespInvalidCommand; const ModeratorCommand &sc = cont.moderator_command(i); const int num = getPbExtension(sc); - logDebugMessage(QString::fromStdString(sc.ShortDebugString())); + logDebugMessage(getSafeDebugString(sc)); resp = processExtendedModeratorCommand(num, sc, rc); if (resp != Response::RespOk) @@ -345,7 +337,7 @@ Response::ResponseCode Server_ProtocolHandler::processAdminCommandContainer(cons Response::ResponseCode resp = Response::RespInvalidCommand; const AdminCommand &sc = cont.admin_command(i); const int num = getPbExtension(sc); - logDebugMessage(QString::fromStdString(sc.ShortDebugString())); + logDebugMessage(getSafeDebugString(sc)); resp = processExtendedAdminCommand(num, sc, rc); if (resp != Response::RespOk) diff --git a/servatrice/src/isl_interface.cpp b/servatrice/src/isl_interface.cpp index cc3722f7..9ab7cc4e 100644 --- a/servatrice/src/isl_interface.cpp +++ b/servatrice/src/isl_interface.cpp @@ -1,5 +1,6 @@ #include "isl_interface.h" +#include "debug_pb_message.h" #include "get_pb_extension.h" #include "main.h" #include "pb/event_game_joined.pb.h" @@ -437,7 +438,7 @@ void IslInterface::processRoomCommand(const CommandContainer &cont, qint64 sessi void IslInterface::processMessage(const IslMessage &item) { - qDebug() << QString::fromStdString(item.DebugString()); + qDebug() << getSafeDebugString(item); switch (item.message_type()) { case IslMessage::ROOM_COMMAND_CONTAINER: { diff --git a/servatrice/src/servatrice.cpp b/servatrice/src/servatrice.cpp index eeb4c525..48b43848 100644 --- a/servatrice/src/servatrice.cpp +++ b/servatrice/src/servatrice.cpp @@ -104,7 +104,7 @@ Servatrice_ConnectionPool *Servatrice_GameServer::findLeastUsedConnectionPool() } debugStr.append(QString::number(clientCount)); } - qDebug() << "Pool utilisation:" << debugStr; + qDebug().noquote() << "Pool utilisation:" << debugStr.join(", "); return connectionPools[poolIndex]; } @@ -176,7 +176,7 @@ Servatrice_ConnectionPool *Servatrice_WebsocketGameServer::findLeastUsedConnecti } debugStr.append(QString::number(clientCount)); } - qDebug() << "Pool utilisation:" << debugStr; + qDebug().noquote() << "Pool utilisation:" << debugStr.join(", "); return connectionPools[poolIndex]; } @@ -241,18 +241,18 @@ bool Servatrice::initServer() authenticationMethod = AuthenticationNone; } - qDebug() << "Store Replays: " << getStoreReplaysEnabled(); - qDebug() << "Client ID Required: " << getClientIDRequiredEnabled(); - qDebug() << "Maximum user limit enabled: " << getMaxUserLimitEnabled(); + qDebug() << "Store Replays:" << getStoreReplaysEnabled(); + qDebug() << "Client ID Required:" << getClientIDRequiredEnabled(); + qDebug() << "Maximum user limit enabled:" << getMaxUserLimitEnabled(); if (getMaxUserLimitEnabled()) { - qDebug() << "Maximum total user limit: " << getMaxUserTotal(); - qDebug() << "Maximum tcp user limit: " << getMaxTcpUserLimit(); - qDebug() << "Maximum websocket user limit: " << getMaxWebSocketUserLimit(); + qDebug() << "Maximum total user limit:" << getMaxUserTotal(); + qDebug() << "Maximum tcp user limit:" << getMaxTcpUserLimit(); + qDebug() << "Maximum websocket user limit:" << getMaxWebSocketUserLimit(); } - qDebug() << "Accept registered users only: " << getRegOnlyServerEnabled(); - qDebug() << "Registration enabled: " << getRegistrationEnabled(); + qDebug() << "Accept registered users only:" << getRegOnlyServerEnabled(); + qDebug() << "Registration enabled:" << getRegistrationEnabled(); if (getRegistrationEnabled()) { #if (QT_VERSION >= QT_VERSION_CHECK(5, 14, 0)) QStringList emailBlackListFilters = getEmailBlackList().split(",", Qt::SkipEmptyParts); @@ -261,32 +261,32 @@ bool Servatrice::initServer() QStringList emailBlackListFilters = getEmailBlackList().split(",", QString::SkipEmptyParts); QStringList emailWhiteListFilters = getEmailWhiteList().split(",", QString::SkipEmptyParts); #endif - qDebug() << "Email blacklist: " << emailBlackListFilters; - qDebug() << "Email whitelist: " << emailWhiteListFilters; - qDebug() << "Require email address to register: " << getRequireEmailForRegistrationEnabled(); - qDebug() << "Require email activation via token: " << getRequireEmailActivationEnabled(); + qDebug() << "Email blacklist:" << emailBlackListFilters; + qDebug() << "Email whitelist:" << emailWhiteListFilters; + qDebug() << "Require email address to register:" << getRequireEmailForRegistrationEnabled(); + qDebug() << "Require email activation via token:" << getRequireEmailActivationEnabled(); if (getMaxAccountsPerEmail()) { - qDebug() << "Maximum number of accounts per email: " << getMaxAccountsPerEmail(); + qDebug() << "Maximum number of accounts per email:" << getMaxAccountsPerEmail(); } else { qDebug() << "Maximum number of accounts per email: unlimited"; } - qDebug() << "Enable Internal SMTP Client: " << getEnableInternalSMTPClient(); + qDebug() << "Enable Internal SMTP Client:" << getEnableInternalSMTPClient(); if (!getEnableInternalSMTPClient()) { qDebug() << "WARNING: Registrations are enabled but internal SMTP client is disabled. Users activation " "emails will not be automatically mailed to users!"; } } - qDebug() << "Reset password enabled: " << getEnableForgotPassword(); + qDebug() << "Reset password enabled:" << getEnableForgotPassword(); if (getEnableForgotPassword()) { - qDebug() << "Reset password token life (in minutes): " << getForgotPasswordTokenLife(); - qDebug() << "Reset password challenge on: " << getEnableForgotPasswordChallenge(); + qDebug() << "Reset password token life (in minutes):" << getForgotPasswordTokenLife(); + qDebug() << "Reset password challenge on:" << getEnableForgotPasswordChallenge(); } - qDebug() << "Auditing enabled: " << getEnableAudit(); + qDebug() << "Auditing enabled:" << getEnableAudit(); if (getEnableAudit()) { - qDebug() << "Audit registration attempts enabled: " << getEnableRegistrationAudit(); - qDebug() << "Audit reset password attepts enabled: " << getEnableForgotPasswordAudit(); + qDebug() << "Audit registration attempts enabled:" << getEnableRegistrationAudit(); + qDebug() << "Audit reset password attepts enabled:" << getEnableForgotPasswordAudit(); } if (getDBTypeString() == "mysql") { @@ -423,7 +423,7 @@ bool Servatrice::initServer() statusUpdateClock = new QTimer(this); connect(statusUpdateClock, SIGNAL(timeout()), this, SLOT(statusUpdate())); if (getServerStatusUpdateTime() != 0) { - qDebug() << "Starting status update clock, interval " << getServerStatusUpdateTime() << " ms"; + qDebug() << "Starting status update clock, interval" << getServerStatusUpdateTime() << "ms"; statusUpdateClock->start(getServerStatusUpdateTime()); } @@ -459,7 +459,7 @@ bool Servatrice::initServer() } if (getIdleClientTimeout() > 0) { - qDebug() << "Idle client timeout value: " << getIdleClientTimeout(); + qDebug() << "Idle client timeout value:" << getIdleClientTimeout(); if (getIdleClientTimeout() < 300) qDebug() << "WARNING: It is not recommended to set the IdleClientTimeout value very low. Doing so will " "cause clients to very quickly be disconnected. Many players when connected may be searching " @@ -573,7 +573,7 @@ void Servatrice::setRequiredFeatures(const QString featureList) foreach (QString reqFeature, listReqFeatures) features.enableRequiredFeature(serverRequiredFeatureList, reqFeature); - qDebug() << "Set required client features to: " << serverRequiredFeatureList; + qDebug() << "Set required client features to:" << serverRequiredFeatureList; } void Servatrice::statusUpdate() diff --git a/servatrice/src/servatrice_database_interface.cpp b/servatrice/src/servatrice_database_interface.cpp index 7c602c39..4e261da8 100644 --- a/servatrice/src/servatrice_database_interface.cpp +++ b/servatrice/src/servatrice_database_interface.cpp @@ -56,7 +56,7 @@ bool Servatrice_DatabaseInterface::openDatabase() sqlDatabase.close(); const QString poolStr = instanceId == -1 ? QString("main") : QString("pool %1").arg(instanceId); - qDebug() << QString("[%1] Opening database...").arg(poolStr); + qDebug().noquote() << QString("[%1] Opening database...").arg(poolStr); if (!sqlDatabase.open()) { qCritical() << QString("[%1] Error opening database: %2").arg(poolStr).arg(sqlDatabase.lastError().text()); return false; diff --git a/servatrice/src/serversocketinterface.cpp b/servatrice/src/serversocketinterface.cpp index 4fd68416..ce1770fb 100644 --- a/servatrice/src/serversocketinterface.cpp +++ b/servatrice/src/serversocketinterface.cpp @@ -1047,7 +1047,7 @@ Response::ResponseCode AbstractServerSocketInterface::cmdRegisterAccount(const C { QString userName = nameFromStdString(cmd.user_name()); QString clientId = nameFromStdString(cmd.clientid()); - qDebug() << "Got register command: " << userName; + qDebug() << "Got register command for user:" << userName; bool registrationEnabled = settingsCache->value("registration/enabled", false).toBool(); if (!registrationEnabled) { @@ -1189,7 +1189,7 @@ Response::ResponseCode AbstractServerSocketInterface::cmdRegisterAccount(const C country, !requireEmailActivation); if (regSucceeded) { - qDebug() << "Accepted register command for user: " << userName; + qDebug() << "Accepted register command for user:" << userName; if (requireEmailActivation) { QSqlQuery *query = sqlInterface->prepareQuery("insert into {prefix}_activation_emails (name) values(:name)"); @@ -1393,7 +1393,7 @@ Response::ResponseCode AbstractServerSocketInterface::cmdForgotPasswordRequest(c const QString userName = nameFromStdString(cmd.user_name()); const QString clientId = nameFromStdString(cmd.clientid()); - qDebug() << "Received reset password request from user: " << userName; + qDebug() << "Received reset password request from user:" << userName; if (!servatrice->getEnableForgotPassword()) { if (servatrice->getEnableForgotPasswordAudit()) @@ -1475,7 +1475,7 @@ Response::ResponseCode AbstractServerSocketInterface::cmdForgotPasswordReset(con Q_UNUSED(rc); QString userName = nameFromStdString(cmd.user_name()); QString clientId = nameFromStdString(cmd.clientid()); - qDebug() << "Received reset password reset from user: " << userName; + qDebug() << "Received reset password reset from user:" << userName; if (!sqlInterface->doesForgotPasswordExist(userName)) { if (servatrice->getEnableForgotPasswordAudit()) @@ -1526,7 +1526,7 @@ AbstractServerSocketInterface::cmdForgotPasswordChallenge(const Command_ForgotPa const QString userName = nameFromStdString(cmd.user_name()); const QString clientId = nameFromStdString(cmd.clientid()); - qDebug() << "Received reset password challenge from user: " << userName; + qDebug() << "Received reset password challenge from user:" << userName; if (!servatrice->getEnableForgotPasswordChallenge()) { if (servatrice->getEnableForgotPasswordAudit()) {