aly/servatrice
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

implement custom protobuf debug string creation (#4532)

Browse source 
* 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
This commit is contained in:
ebbit1q 2022-02-23 23:46:23 +01:00 committed by GitHub
parent eb3ce1fd7e
commit 7108eb42c8
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
10 changed files with 178 additions and 51 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

7
cockatrice/src/remoteclient.cpp
View file

@ -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<unsigned int>(cont.ByteSize());
#endif
#ifdef QT_DEBUG
qDebug() << "OUT" << size << QString::fromStdString(cont.ShortDebugString());
qDebug().noquote() << "OUT" << getSafeDebugString(cont);
#endif
QByteArray buf;

1
common/CMakeLists.txt
View file

@ -5,6 +5,7 @@
add_subdirectory(pb)
SET(common_SOURCES
debug_pb_message.cpp
decklist.cpp
expression.cpp
featureset.cpp

116
common/debug_pb_message.cpp Normal file
View file

@ -0,0 +1,116 @@
#include "debug_pb_message.h"
#include "stringsizes.h"
#include <QList>
#include <QString>
#include <google/protobuf/descriptor.h>
#include <google/protobuf/message.h>
#include <google/protobuf/text_format.h>
// 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<const google::protobuf::FieldDescriptor *> 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);
}

15
common/debug_pb_message.h Normal file
View file

@ -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

3
common/server.cpp
View file

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

22
common/server_protocolhandler.cpp
View file

@ -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)

3
servatrice/src/isl_interface.cpp
View file

@ -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: {

50
servatrice/src/servatrice.cpp
View file

@ -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()

2
servatrice/src/servatrice_database_interface.cpp
View file

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

10
servatrice/src/serversocketinterface.cpp
View file

@ -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()) {