Compare commits

...

5 commits

Author SHA1 Message Date
Lukas Brübach
31efea146c [Client/Server/Protocol] Surface live metrics in the Developer tab
Extend Response_GetServerStats with live counters from the in-process
MetricsRegistry: cards in games, event loop stall totals/worst,
total commands processed, average command time, active command types,
and game-start count/duration. Add a repeated CommandStats message
carrying per-command breakdowns (kind, extension number, resolved
protobuf name, count, total ms) for every type that has seen at
least one sample.

Server-side cmdGetServerStats() populates all new fields after the
existing DB uptime snapshot query, resolving protobuf extension names
via the descriptor pool for human-readable labels like
session/Command_Ping.

Expand TabDeveloper with two tables: an overview section (existing
DB stats plus the new live metrics) and a per-command breakdown table
(Command / Count / Total ms / Avg ms) sorted by total_ms descending
so the hottest commands surface first.

Took 55 minutes

Took 47 seconds
2026-08-30 21:24:49 +02:00
Lukas Brübach
9eedd25464 [Server] Instrument command processing, game starts, and event loops
Add a lock-free MetricsRegistry that accumulates per-command processing
times in preallocated histogram slots (one per protobuf command type,
bucketed at 1/5/10/25/50/100/250/500/1000/2500/5000 ms +Inf). The
hot-path observeCommand() uses only relaxed atomic adds — no locks,
no allocations, no cache-line ping-pong beyond the unavoidable counter
updates.

Wire the registry into AbstractServerSocketInterface::processCommandContainer()
so every processed command is attributed with its container's wall-clock
time. When a container exceeds metrics/slow_command_ms (default 500),
a warning is logged including the connected username.

Add an EventLoopWatchdog heartbeat that runs on every socket pool thread.
If a heartbeat overshoots metrics/stall_warn_ms (default 2000 ms), the
overshoot is recorded in atomic counters and a warning is logged. Both
thresholds are configurable in servatrice.ini; setting stall_warn_ms to 0
disables the watchdogs entirely.

Track game-start durations via a separate histogram in MetricsRegistry.
Server_Game::startGameNow() measures the time from zone creation through
player materialization and reports it via Server::observeGameStartDurationMs().

Add a live card-count gauge: Server_Game exposes getCardsInGame() and
Servatrice::getCardsInGamesTotal() sums across all running games under
the appropriate read locks.

Include a standalone metrics_registry_test (Google Test) that validates
empty registries, single/multi-sample histograms, kind encoding,
overflow-slot collapse, negative-duration clamping, gauge rendering,
and the game-start histogram separation.

Took 10 minutes
2026-08-30 21:24:49 +02:00
Lukas Brübach
763b5cf74d Remove stale includes of deleted command_get_log_history proto
The Command_GetLogHistory message was folded into Command_ViewLogHistory,
which deleted command_get_log_history.proto, but serversocketinterface
still #included its generated header. Fresh CI builds fail on the missing
file; local builds masked it by reusing a previously generated header.
2026-08-30 21:24:22 +02:00
Lukas Brübach
60c6f074de Add missing trailing newline to user_context_menu.cpp 2026-08-30 21:11:08 +02:00
Lukas Brübach
914f0a2aee [Server/Client/Protocol] Address developer role review feedback
Address ZeizaZach's review of the developer staff role:

- Nudge the developer log query to exclude private chat and sender IPs
  (the ModeratorCommand path still sees everything).
- Deduplicate Command_GetLogHistory into Command_ViewLogHistory, which now
  extends both ModeratorCommand (ext) and DeveloperCommand (dev_ext); the
  client picks the DeveloperCommand-scoped extension by extendee, and the
  server reads it via the extension number.
- Pull the uptime snapshot SQL into Servatrice_DatabaseInterface as
  getLatestUptimeSnapshot() and widen the reported counters to 64-bit.
- Document the admin bitfield (1 admin, 2 moderator, 4 judge, 8 developer)
  and add a server-side test for the developer command path.
2026-08-30 21:06:31 +02:00
32 changed files with 1119 additions and 82 deletions

View file

@ -727,4 +727,4 @@ void UserContextMenu::execAdjustDeveloper(const QString &userName, bool shouldBe
PendingCommand *pend = client->prepareAdminCommand(cmd);
connect(pend, &PendingCommand::finished, this, &UserContextMenu::adjustMod_processUserResponse);
client->sendCommand(pend);
}
}

View file

@ -7,11 +7,13 @@
#include "tab_developer.h"
#include <QDateTime>
#include <QHBoxLayout>
#include <QHeaderView>
#include <QLabel>
#include <QPushButton>
#include <QTableWidget>
#include <QVBoxLayout>
#include <algorithm>
#include <libcockatrice/network/client/abstract/abstract_client.h>
#include <libcockatrice/protocol/pb/command_get_server_stats.pb.h>
#include <libcockatrice/protocol/pb/response_get_server_stats.pb.h>
@ -21,12 +23,25 @@ TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_clien
: Tab(_tabSupervisor), client(_client)
{
statsTable = new QTableWidget(0, 2);
statsTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Expanding);
statsTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Preferred);
statsTable->setEditTriggers(QAbstractItemView::NoEditTriggers);
statsTable->setSelectionBehavior(QAbstractItemView::SelectRows);
statsTable->setSelectionMode(QAbstractItemView::SingleSelection);
statsTable->horizontalHeader()->setStretchLastSection(true);
statsTable->verticalHeader()->setVisible(false);
statsTable->horizontalHeader()->setSectionResizeMode(0, QHeaderView::Interactive);
statsTable->horizontalHeader()->setSectionResizeMode(1, QHeaderView::Interactive);
statsTable->horizontalHeader()->setStretchLastSection(true);
commandTable = new QTableWidget(0, 4);
commandTable->setSizePolicy(QSizePolicy::Expanding, QSizePolicy::Expanding);
commandTable->setEditTriggers(QAbstractItemView::NoEditTriggers);
commandTable->setSelectionBehavior(QAbstractItemView::SelectRows);
commandTable->setSelectionMode(QAbstractItemView::SingleSelection);
commandTable->verticalHeader()->setVisible(false);
commandTable->horizontalHeader()->setSectionResizeMode(0, QHeaderView::Interactive);
commandTable->horizontalHeader()->setSectionResizeMode(1, QHeaderView::Interactive);
commandTable->horizontalHeader()->setSectionResizeMode(2, QHeaderView::Interactive);
commandTable->horizontalHeader()->setSectionResizeMode(3, QHeaderView::Interactive);
statusLabel = new QLabel;
@ -38,8 +53,12 @@ TabDeveloper::TabDeveloper(TabSupervisor *_tabSupervisor, AbstractClient *_clien
buttonLayout->addWidget(statusLabel, 1, Qt::AlignLeft);
buttonLayout->addWidget(refreshButton, 0, Qt::AlignRight);
auto *tableLayout = new QHBoxLayout;
tableLayout->addWidget(statsTable, 1);
tableLayout->addWidget(commandTable, 2);
auto *mainLayout = new QVBoxLayout;
mainLayout->addWidget(statsTable);
mainLayout->addLayout(tableLayout, 1);
mainLayout->addLayout(buttonLayout);
auto *central = new QWidget;
@ -53,6 +72,7 @@ void TabDeveloper::retranslateUi()
{
refreshButton->setText(tr("Refresh server stats"));
statsTable->setHorizontalHeaderLabels(QString(tr("Statistic;Value")).split(";"));
commandTable->setHorizontalHeaderLabels(QString(tr("Command;Count;Total ms;Avg ms")).split(";"));
if (statsTable->rowCount() == 0) {
statusLabel->clear();
}
@ -75,6 +95,14 @@ QString TabDeveloper::formatBytes(quint64 bytes)
return tr("%1 bytes").arg(bytes);
}
QString TabDeveloper::formatDurationMs(qint64 ms)
{
if (ms >= 1000) {
return tr("%1 s").arg(QString::number(ms / 1000.0, 'f', 2));
}
return tr("%1 ms").arg(ms);
}
void TabDeveloper::appendStatRow(const QString &name, const QString &value)
{
const int row = statsTable->rowCount();
@ -83,6 +111,19 @@ void TabDeveloper::appendStatRow(const QString &name, const QString &value)
statsTable->setItem(row, 1, new QTableWidgetItem(value));
}
void TabDeveloper::appendSeparatorRow(const QString &sectionTitle)
{
const int row = statsTable->rowCount();
statsTable->insertRow(row);
auto *labelItem = new QTableWidgetItem(sectionTitle);
auto font = labelItem->font();
font.setBold(true);
labelItem->setFont(font);
labelItem->setFlags(labelItem->flags() & ~Qt::ItemIsSelectable);
statsTable->setItem(row, 0, labelItem);
statsTable->setItem(row, 1, new QTableWidgetItem(QString()));
}
void TabDeveloper::refreshClicked()
{
Command_GetServerStats cmd;
@ -94,13 +135,15 @@ void TabDeveloper::refreshClicked()
void TabDeveloper::serverStatsResponse(const Response &resp)
{
if (resp.response_code() != Response::RespOk) {
statusLabel->setText(tr("Failed to collect server statistics."));
statusLabel->setText(tr("No server statistics available yet."));
return;
}
const Response_GetServerStats &response = resp.GetExtension(Response_GetServerStats::ext);
statsTable->setRowCount(0);
// Overview section
appendStatRow(tr("Registered users online"), QString::number(response.users_count()));
appendStatRow(tr("Moderators online"), QString::number(response.mods_count()));
appendStatRow(tr("Games running"), QString::number(response.games_count()));
@ -117,6 +160,54 @@ void TabDeveloper::serverStatsResponse(const Response &resp)
const QDateTime snapshotTime = QDateTime::fromSecsSinceEpoch(static_cast<qint64>(response.timest()));
appendStatRow(tr("Snapshot taken"), snapshotTime.toLocalTime().toString("yyyy-MM-dd HH:mm"));
// Live metrics section
appendSeparatorRow(tr("Live Metrics"));
appendStatRow(tr("Cards in live games"), QString::number(response.cards_in_games()));
appendStatRow(tr("Total commands processed"), QString::number(response.total_commands()));
if (response.total_commands() > 0) {
const double avgMs = static_cast<double>(response.total_command_time_ms()) / response.total_commands();
appendStatRow(tr("Avg command time"), QString::number(avgMs, 'f', 2) + " ms");
}
appendStatRow(tr("Active command types"), QString::number(response.active_command_types()));
appendStatRow(tr("Event loop stalls"), QString::number(response.eventloop_stalls_total()));
appendStatRow(tr("Last stall overshoot"), formatDurationMs(response.eventloop_last_stall_ms()));
appendStatRow(tr("Worst stall overshoot"), formatDurationMs(response.eventloop_max_stall_ms()));
if (response.game_start_count() > 0) {
appendStatRow(tr("Game starts"), QString::number(response.game_start_count()));
const double avgStartMs = static_cast<double>(response.game_start_total_ms()) / response.game_start_count();
appendStatRow(tr("Avg game start time"), QString::number(avgStartMs, 'f', 1) + " ms");
}
// Per-command breakdown table
QList<CommandStats> sortedStats(response.command_stats().begin(), response.command_stats().end());
std::sort(sortedStats.begin(), sortedStats.end(),
[](const auto &a, const auto &b) { return a.total_ms() > b.total_ms(); });
commandTable->setRowCount(0);
for (const auto &cs : sortedStats) {
const int row = commandTable->rowCount();
commandTable->insertRow(row);
commandTable->setItem(row, 0, new QTableWidgetItem(QString::fromStdString(cs.command_name())));
auto *countItem = new QTableWidgetItem(QString::number(cs.count()));
countItem->setTextAlignment(Qt::AlignRight | Qt::AlignVCenter);
commandTable->setItem(row, 1, countItem);
auto *totalItem = new QTableWidgetItem(QString::number(cs.total_ms()));
totalItem->setTextAlignment(Qt::AlignRight | Qt::AlignVCenter);
commandTable->setItem(row, 2, totalItem);
const double avg = cs.count() > 0 ? static_cast<double>(cs.total_ms()) / cs.count() : 0.0;
auto *avgItem = new QTableWidgetItem(QString::number(avg, 'f', 2));
avgItem->setTextAlignment(Qt::AlignRight | Qt::AlignVCenter);
commandTable->setItem(row, 3, avgItem);
}
commandTable->resizeColumnsToContents();
statsTable->resizeColumnsToContents();
commandTable->resizeColumnsToContents();
statusLabel->setText(tr("Updated %1").arg(QDateTime::currentDateTime().toString("yyyy-MM-dd HH:mm")));
}

View file

@ -21,11 +21,14 @@ class TabDeveloper : public Tab
private:
AbstractClient *client;
QTableWidget *statsTable;
QTableWidget *commandTable;
QPushButton *refreshButton;
QLabel *statusLabel;
void appendStatRow(const QString &name, const QString &value);
void appendSeparatorRow(const QString &sectionTitle);
static QString formatBytes(quint64 bytes);
static QString formatDurationMs(qint64 ms);
private slots:
void refreshClicked();

View file

@ -14,7 +14,6 @@
#include <QTabWidget>
#include <QTableWidget>
#include <libcockatrice/network/client/abstract/abstract_client.h>
#include <libcockatrice/protocol/pb/command_get_log_history.pb.h>
#include <libcockatrice/protocol/pb/moderator_commands.pb.h>
#include <libcockatrice/protocol/pb/response_viewlog_history.pb.h>
#include <libcockatrice/protocol/pending_command.h>
@ -82,7 +81,9 @@ void TabLog::getClicked()
if (!mainRoom->isChecked() && !gameRoom->isChecked() && !privateChat->isChecked()) {
mainRoom->setChecked(true);
gameRoom->setChecked(true);
privateChat->setChecked(true);
if (!canUseDeveloperCommands) {
privateChat->setChecked(true);
}
}
if (maximumResults->value() == 0) {
@ -123,18 +124,7 @@ void TabLog::getClicked()
PendingCommand *pend;
if (canUseDeveloperCommands) {
// Developers query logs through the developer command family.
Command_GetLogHistory devCmd;
devCmd.set_user_name(cmd.user_name());
devCmd.set_ip_address(cmd.ip_address());
devCmd.set_game_name(cmd.game_name());
devCmd.set_game_id(cmd.game_id());
devCmd.set_message(cmd.message());
for (int i = 0; i < cmd.log_location_size(); ++i) {
devCmd.add_log_location(cmd.log_location(i));
}
devCmd.set_date_range(cmd.date_range());
devCmd.set_maximum_results(cmd.maximum_results());
pend = client->prepareDeveloperCommand(devCmd);
pend = client->prepareDeveloperCommand(cmd);
} else {
pend = client->prepareModeratorCommand(cmd);
}
@ -192,6 +182,10 @@ void TabLog::createDock()
mainRoom = new QCheckBox(tr("Main Room"));
gameRoom = new QCheckBox(tr("Game Room"));
privateChat = new QCheckBox(tr("Private Chat"));
if (canUseDeveloperCommands) {
// Developers cannot query private conversations.
privateChat->setVisible(false);
}
pastDays = new QRadioButton(tr("Past X Days: "));
today = new QRadioButton(tr("Today"));

View file

@ -834,10 +834,10 @@ void TabSupervisor::actTabLog(bool checked)
void TabSupervisor::openTabLog()
{
// Developers without moderation rights query logs through the developer
// command family, so tell the tab which family to use.
const bool isDeveloper = (userInfo->user_level() & ServerInfo_User::IsDeveloper) != 0;
tabLog = new TabLog(this, client, isDeveloper);
// Developers query logs through the developer command family, so tell the
// tab which family to use.
const bool useDeveloperCommands = (userInfo->user_level() & ServerInfo_User::IsDeveloper) != 0;
tabLog = new TabLog(this, client, useDeveloperCommands);
myAddTab(tabLog, aTabLog);
connect(tabLog, &QObject::destroyed, this, [this] {
tabLog = nullptr;

View file

@ -258,6 +258,19 @@ PendingCommand *AbstractClient::prepareDeveloperCommand(const ::google::protobuf
{
CommandContainer cont;
DeveloperCommand *c = cont.add_developer_command();
c->GetReflection()->MutableMessage(c, cmd.GetDescriptor()->FindExtensionByName("ext"))->CopyFrom(cmd);
// A developer command message may also be usable through other command
// families, so select the extension scoped to DeveloperCommand rather than
// guessing by name.
const ::google::protobuf::Descriptor *cmdDescriptor = cmd.GetDescriptor();
const ::google::protobuf::Descriptor *developerDescriptor = DeveloperCommand::descriptor();
const ::google::protobuf::FieldDescriptor *developerExtension = nullptr;
for (int i = 0; i < cmdDescriptor->extension_count(); ++i) {
if (cmdDescriptor->extension(i)->containing_type() == developerDescriptor) {
developerExtension = cmdDescriptor->extension(i);
break;
}
}
Q_ASSERT(developerExtension != nullptr);
c->GetReflection()->MutableMessage(c, developerExtension)->CopyFrom(cmd);
return new PendingCommand(cont);
}

View file

@ -66,6 +66,15 @@ Server_AbstractPlayer::Server_AbstractPlayer(Server_Game *_game,
Server_AbstractPlayer::~Server_AbstractPlayer() = default;
int Server_AbstractPlayer::getCardCount() const
{
int result = 0;
for (auto *zone : zones) {
result += zone->getCards().size();
}
return result;
}
void Server_AbstractPlayer::prepareDestroy()
{
delete deck;

View file

@ -43,6 +43,8 @@ public:
Server_AbstractUserInterface *_handler);
~Server_AbstractPlayer() override;
void prepareDestroy() override;
/// Total cards across all of this player's zones. The caller must hold the game's mutex.
int getCardCount() const;
const DeckList *getDeckList() const
{
return deck;

View file

@ -32,6 +32,7 @@
#include "server_spectator.h"
#include <QDebug>
#include <QElapsedTimer>
#include <QRegularExpression>
#include <QTimer>
#include <google/protobuf/descriptor.h>
@ -238,6 +239,17 @@ int Server_Game::getPlayerCount() const
return participants.size() - getSpectatorCount();
}
int Server_Game::getCardsInGame() const
{
QMutexLocker locker(&gameMutex);
int result = 0;
for (auto *player : getPlayers()) {
result += player->getCardCount();
}
return result;
}
int Server_Game::getSpectatorCount() const
{
QMutexLocker locker(&gameMutex);
@ -330,6 +342,9 @@ void Server_Game::doStartGameIfReady(bool forceStartGame)
}
}
// Only actual starts are timed. The early returns above are no-ops.
QElapsedTimer startupTimer;
startupTimer.start();
players = getPlayers(); // players could have been kicked, get new list of players
if (lifecycleStrategy->onGameStarting(this) == Server_GameLifecycleStrategy::StartAction::Handled) {
locker.unlock();
@ -373,6 +388,7 @@ void Server_Game::doStartGameIfReady(bool forceStartGame)
activePlayer = -1;
nextTurn();
room->getServer()->observeGameStartDurationMs(startupTimer.nsecsElapsed() / 1000000);
locker.unlock();

View file

@ -123,6 +123,8 @@ public:
return gameStarted;
}
int getPlayerCount() const;
/// Total cards across all players' zones. Takes gameMutex itself.
int getCardsInGame() const;
int getSpectatorCount() const;
QMap<int, Server_AbstractPlayer *> getPlayers() const;
Server_AbstractPlayer *getPlayer(int id) const;

View file

@ -180,6 +180,11 @@ public:
{
return false;
}
/// Called once per actual game start with how long bringing every player's
/// zones online took, so servers can spot deck sizes that wedge threads.
virtual void observeGameStartDurationMs(qint64 /* elapsedMs */)
{
}
Server_DatabaseInterface *getDatabaseInterface() const;
int getNextLocalGameId()

View file

@ -136,7 +136,7 @@ public:
return timeRunning - lastDataReceived;
}
bool addSaidMessageSize(int size);
void processCommandContainer(const CommandContainer &cont);
virtual void processCommandContainer(const CommandContainer &cont);
void sendProtocolItem(const Response &item);
void sendProtocolItem(const SessionEvent &item);

View file

@ -22,11 +22,10 @@ set(PROTO_FILES
command_del_counter.proto
command_delete_arrow.proto
command_draw_cards.proto
command_get_log_history.proto
command_get_server_stats.proto
command_dump_zone.proto
command_flip_card.proto
command_game_say.proto
command_get_server_stats.proto
command_inc_card_counter.proto
command_inc_counter.proto
command_kick_from_game.proto

View file

@ -1,19 +0,0 @@
syntax = "proto2";
import "developer_commands.proto";
// Developer counterpart of Command_ViewLogHistory: identical query fields, but
// routed through the developer command family so developers never need the
// moderator command container.
message Command_GetLogHistory {
extend DeveloperCommand {
optional Command_GetLogHistory ext = 1001;
}
optional string user_name = 1; // user that created message
optional string ip_address = 2; // ip address of user that created message
optional string game_name = 3; // client id of user that created the message
optional string game_id = 4; // game number the message was sent to
optional string message = 5; // raw message that was sent
repeated string log_location = 6; // destination of message (ex: main room, game room, private chat)
required uint32 date_range = 7; // the length of time (in minutes) to look back for
optional uint32 maximum_results = 8; // the maximum number of query results
}

View file

@ -1,4 +1,5 @@
syntax = "proto2";
import "developer_commands.proto";
message ModeratorCommand {
enum ModeratorCommandType {
BAN_FROM_SERVER = 1000;
@ -80,6 +81,9 @@ message Command_ViewLogHistory {
extend ModeratorCommand {
optional Command_ViewLogHistory ext = 1005;
}
extend DeveloperCommand {
optional Command_ViewLogHistory dev_ext = 1001;
}
optional string user_name = 1; // user that created message
optional string ip_address = 2; // ip address of user that created message
optional string game_name = 3; // client id of user that created the message

View file

@ -1,6 +1,14 @@
syntax = "proto2";
import "response.proto";
message CommandStats {
optional uint32 kind_index = 1; // 0=session, 1=room, 2=game, 3=moderator, 4=admin
optional uint32 extension_number = 2; // protobuf extension number within the kind
optional string command_name = 3; // e.g. "session/Command_Ping"
optional uint64 count = 4; // number of times observed
optional uint64 total_ms = 5; // cumulative processing milliseconds
}
message Response_GetServerStats {
extend Response {
optional Response_GetServerStats ext = 1220;
@ -16,4 +24,18 @@ message Response_GetServerStats {
optional uint64 uptime_secs = 6;
optional uint64 timest = 7; // unix timestamp of the snapshot
// Live metrics from MetricsRegistry (reset on server restart)
optional uint64 cards_in_games = 8;
optional uint64 eventloop_stalls_total = 9;
optional uint64 eventloop_last_stall_ms = 10;
optional uint64 eventloop_max_stall_ms = 11;
optional uint64 total_commands = 12;
optional uint64 total_command_time_ms = 13;
optional int32 active_command_types = 14;
optional uint64 game_start_count = 15;
optional uint64 game_start_total_ms = 16;
// Per-command breakdown (only types with count > 0)
repeated CommandStats command_stats = 20;
}

View file

@ -6,7 +6,9 @@ project(Servatrice VERSION "${PROJECT_VERSION_MAJOR}.${PROJECT_VERSION_MINOR}.${
set(servatrice_SOURCES
src/email_parser.cpp
src/event_loop_watchdog.cpp
src/main.cpp
src/metrics_registry.cpp
src/servatrice.cpp
src/servatrice_connection_pool.cpp
src/servatrice_database_interface.cpp

View file

@ -382,6 +382,17 @@ max_reports_per_day=10
; Maximum number of report comments a single user can post per hour; default is 30; set to 0 to disable the limit
max_comments_per_hour=30
[metrics]
; Command containers that take longer than this many milliseconds are logged
; as slow commands. Set to 0 to disable the log line.
slow_command_ms=500
; Each socket pool thread runs a watchdog heartbeat. If a heartbeat arrives
; this many milliseconds late, the stall is logged and exposed as
; servatrice_eventloop_* metrics in the Developer tab. Set to 0 to disable
; the watchdogs.
stall_warn_ms=2000
[logging]
; Admin/Moderators can query the stored logs for information when looking up reports by various players. This
; option can allow or disallow them from doing so.

View file

@ -25,6 +25,9 @@ INSERT INTO cockatrice_schema_version VALUES(36);
-- users and user data tables
CREATE TABLE IF NOT EXISTS `cockatrice_users` (
`id` int(7) unsigned zerofill NOT NULL auto_increment,
-- Bitfield of staff levels: 1 = admin (implies moderator), 2 = moderator,
-- 4 = judge, 8 = developer. Operators set these by hand with
-- "UPDATE cockatrice_users SET admin = ...".
`admin` tinyint(1) NOT NULL,
`name` varchar(35) NOT NULL,
`realname` varchar(255) NOT NULL,

View file

@ -0,0 +1,34 @@
/**
* @file event_loop_watchdog.cpp
* @ingroup Servatrice
*/
#include "event_loop_watchdog.h"
#include "servatrice.h"
#include <QTimer>
EventLoopWatchdog::EventLoopWatchdog(Servatrice *_servatrice, QString _threadName)
: QObject(nullptr), servatrice(_servatrice), threadName(std::move(_threadName))
{
}
void EventLoopWatchdog::start()
{
heartbeatTimer = new QTimer(this);
sinceLastTick.start();
connect(heartbeatTimer, &QTimer::timeout, this, &EventLoopWatchdog::checkHeartbeat);
heartbeatTimer->start(HeartbeatIntervalMs);
}
void EventLoopWatchdog::checkHeartbeat()
{
const qint64 elapsedMs = sinceLastTick.restart();
const qint64 overshootMs = qMax<qint64>(0, elapsedMs - HeartbeatIntervalMs);
if (overshootMs < servatrice->getMetricsStallWarnMs()) {
return;
}
servatrice->observeEventLoopStall(threadName, overshootMs);
}

View file

@ -0,0 +1,50 @@
/**
* @file event_loop_watchdog.h
* @ingroup Servatrice
*/
#ifndef EVENT_LOOP_WATCHDOG_H
#define EVENT_LOOP_WATCHDOG_H
#include <QElapsedTimer>
#include <QObject>
#include <QString>
class Servatrice;
class QTimer;
/**
* @brief Detects blocked or overloaded worker event loops.
*
* One instance lives in each socket pool thread. A heartbeat timer tick that
* arrives late means the loop spent that time elsewhere: busy work, a queued
* slot, or a hard wedge. Overshoots past the configured threshold bump
* lock-free counters on the metrics registry and log one warning per stall,
* so a stuck pool thread becomes visible instead of silent lag.
*/
class EventLoopWatchdog : public QObject
{
Q_OBJECT
public:
/// How often the heartbeat expects to fire. Small enough to catch short stalls.
static constexpr int HeartbeatIntervalMs = 500;
EventLoopWatchdog(Servatrice *_servatrice, QString _threadName);
/**
* Starts the heartbeat timer. Must be invoked queued after the instance
* was moved to its target thread so the timer lives there too.
*/
void start();
private slots:
void checkHeartbeat();
private:
Servatrice *servatrice;
QString threadName;
QElapsedTimer sinceLastTick;
QTimer *heartbeatTimer = nullptr;
};
#endif

View file

@ -0,0 +1,142 @@
#include "metrics_registry.h"
#include <QList>
int MetricsRegistry::bucketIndexFor(qint64 elapsedMs)
{
const int lastFiniteBucket = static_cast<int>(BucketBounds.size()) - 1;
int bucket = 0;
while (bucket < lastFiniteBucket && elapsedMs > BucketBounds[static_cast<size_t>(bucket)]) {
++bucket;
}
return bucket;
}
void MetricsRegistry::appendCumulativeBuckets(QString &out,
const QString &bucketLine,
const std::array<std::atomic<qint64>, BucketCount> &buckets)
{
// Cumulative buckets are required by the Prometheus histogram convention.
qint64 cumulative = 0;
for (int bucket = 0; bucket < static_cast<int>(BucketBounds.size()); ++bucket) {
cumulative += buckets[static_cast<size_t>(bucket)].load(std::memory_order_relaxed);
out += QStringLiteral("%1,le=\"%2\"} %3\n")
.arg(bucketLine)
.arg(BucketBounds[static_cast<size_t>(bucket)])
.arg(cumulative);
}
cumulative += buckets[BucketCount - 1].load(std::memory_order_relaxed);
out += QStringLiteral("%1,le=\"+Inf\"} %2\n").arg(bucketLine).arg(cumulative);
}
void MetricsRegistry::observeCommand(int typeId, qint64 elapsedMs)
{
if (typeId < 0 || typeId >= MaxTypes) {
typeId = MaxTypes - 1; // overflow slot keeps misrouted ids visible
}
if (elapsedMs < 0) {
elapsedMs = 0;
}
TypeStats &stats = slotFor(typeId);
stats.count.fetch_add(1, std::memory_order_relaxed);
stats.totalMs.fetch_add(elapsedMs, std::memory_order_relaxed);
totalCommandsCounter.fetch_add(1, std::memory_order_relaxed);
totalTimeCounter.fetch_add(elapsedMs, std::memory_order_relaxed);
stats.buckets[static_cast<size_t>(bucketIndexFor(elapsedMs))].fetch_add(1, std::memory_order_relaxed);
}
void MetricsRegistry::observeGameStartDurationMs(qint64 elapsedMs)
{
if (elapsedMs < 0) {
elapsedMs = 0;
}
gameStartStats.count.fetch_add(1, std::memory_order_relaxed);
gameStartStats.totalMs.fetch_add(elapsedMs, std::memory_order_relaxed);
gameStartStats.buckets[static_cast<size_t>(bucketIndexFor(elapsedMs))].fetch_add(1, std::memory_order_relaxed);
}
MetricsRegistry::TypeStats &MetricsRegistry::slotFor(int typeId)
{
return typeSlots[static_cast<size_t>(typeId)];
}
const MetricsRegistry::TypeStats &MetricsRegistry::slotFor(int typeId) const
{
return typeSlots[static_cast<size_t>(typeId)];
}
int MetricsRegistry::activeTypeCount() const
{
int active = 0;
for (int type = 0; type < MaxTypes; ++type) {
if (slotFor(type).count.load(std::memory_order_relaxed) > 0) {
++active;
}
}
return active;
}
QString MetricsRegistry::toPrometheusText(const std::function<QString(int)> &nameForType,
const QHash<QString, qint64> &gauges) const
{
QString out;
out.reserve(4096);
for (auto it = gauges.constBegin(); it != gauges.constEnd(); ++it) {
out += QStringLiteral("# TYPE %1 gauge\n").arg(it.key());
out += QStringLiteral("%1 %2\n").arg(it.key()).arg(it.value());
}
// Cumulative buckets are required by the Prometheus histogram convention.
out += QLatin1String("# TYPE servatrice_commands_duration_ms histogram\n");
for (int type = 0; type < MaxTypes; ++type) {
const TypeStats &stats = slotFor(type);
const qint64 count = stats.count.load(std::memory_order_relaxed);
if (count == 0) {
continue;
}
const QString label = nameForType ? nameForType(type) : QString::number(type);
appendCumulativeBuckets(out, QStringLiteral("servatrice_commands_duration_ms_bucket{command=\"%1\"").arg(label),
stats.buckets);
out += QStringLiteral("servatrice_commands_duration_ms_sum{command=\"%1\"} %2\n")
.arg(label)
.arg(stats.totalMs.load(std::memory_order_relaxed));
out += QStringLiteral("servatrice_commands_duration_ms_count{command=\"%1\"} %2\n").arg(label).arg(count);
}
const qint64 startCount = gameStartStats.count.load(std::memory_order_relaxed);
if (startCount > 0) {
out += QLatin1String("# TYPE servatrice_game_start_duration_ms histogram\n");
appendCumulativeBuckets(out, QLatin1String("servatrice_game_start_duration_ms_bucket"), gameStartStats.buckets);
out += QStringLiteral("servatrice_game_start_duration_ms_sum %1\n")
.arg(gameStartStats.totalMs.load(std::memory_order_relaxed));
out += QStringLiteral("servatrice_game_start_duration_ms_count %1\n").arg(startCount);
}
return out;
}
QList<MetricsRegistry::ActiveTypeStats> MetricsRegistry::collectActiveStats() const
{
QList<ActiveTypeStats> result;
for (int type = 0; type < MaxTypes; ++type) {
const TypeStats &stats = slotFor(type);
const qint64 count = stats.count.load(std::memory_order_relaxed);
if (count == 0) {
continue;
}
result.append({type, count, stats.totalMs.load(std::memory_order_relaxed)});
}
return result;
}
MetricsRegistry::GameStartSnapshot MetricsRegistry::getGameStartSnapshot() const
{
return {gameStartStats.count.load(std::memory_order_relaxed),
gameStartStats.totalMs.load(std::memory_order_relaxed)};
}

View file

@ -0,0 +1,135 @@
/**
* @file metrics_registry.h
* @ingroup Servatrice
*/
#ifndef METRICS_REGISTRY_H
#define METRICS_REGISTRY_H
#include <QHash>
#include <QString>
#include <array>
#include <atomic>
#include <functional>
/**
* @brief Lock-free accumulation of command processing statistics.
*
* observeCommand() is called once per processed command from whichever socket
* thread handled it. It uses relaxed atomic adds on preallocated storage only,
* so it introduces no locks, allocations, or shared cache-line ping-pong
* beyond the unavoidable counter updates.
*
* Reading happens rarely (metrics scraping), accepts momentary tears between
* related counters, and therefore also needs no synchronization.
*/
class MetricsRegistry
{
public:
/**
* Extension numbers are only unique per command kind, so recorded ids
* combine the kind index with the protobuf extension number.
*/
static constexpr int KindStride = 2048;
static constexpr int NumKinds = 5;
static constexpr const char *KindNames[NumKinds] = {"session", "room", "game", "moderator", "admin"};
/// Upper bound on distinct command type ids (see typeIdFor).
static constexpr int MaxTypes = NumKinds * KindStride;
/// Histogram bucket upper bounds in milliseconds. Anything above the last
/// bound lands in the trailing +Inf bucket. Constexpr so the recording
/// hot path never allocates.
static constexpr std::array<qint64, 11> BucketBounds{1, 5, 10, 25, 50, 100, 250, 500, 1000, 2500, 5000};
static int typeIdFor(int kindIndex, int extensionNumber)
{
return kindIndex * KindStride + extensionNumber;
}
void observeCommand(int typeId, qint64 elapsedMs);
/**
* Records how long one game start took to bring every player's zones
* online. Kept separate from command timings because it is triggered by
* the server itself and can dwarf any single command when decks are huge.
*/
void observeGameStartDurationMs(qint64 elapsedMs);
/// Total number of observed commands across all types.
qint64 totalCommands() const
{
return totalCommandsCounter.load(std::memory_order_relaxed);
}
/// Cumulative processing milliseconds across all types.
qint64 totalTimeMs() const
{
return totalTimeCounter.load(std::memory_order_relaxed);
}
/// Number of distinct type slots that have seen at least one sample.
int activeTypeCount() const;
struct ActiveTypeStats
{
int typeId;
qint64 count;
qint64 totalMs;
};
/**
* Returns stats for every type slot that has seen at least one sample.
* The caller-provided @p labelForType maps a numeric type id to a stable
* human-readable label. Pass nullptr to skip label resolution.
*/
QList<ActiveTypeStats> collectActiveStats() const;
struct GameStartSnapshot
{
qint64 count;
qint64 totalMs;
};
GameStartSnapshot getGameStartSnapshot() const;
/**
* @brief Renders all recorded data in Prometheus text exposition format.
*
* @param nameForType maps a numeric command type id to a stable label
* value. Ids without a mapping are rendered as their number.
* @param gauges simple name/value pairs emitted as gauge samples.
*/
QString toPrometheusText(const std::function<QString(int)> &nameForType,
const QHash<QString, qint64> &gauges) const;
private:
static constexpr int BucketCount = static_cast<int>(BucketBounds.size()) + 1; ///< bounds + the +Inf bucket
struct TypeStats
{
std::atomic<qint64> count{0};
std::atomic<qint64> totalMs{0};
std::array<std::atomic<qint64>, BucketCount> buckets{};
};
TypeStats &slotFor(int typeId);
const TypeStats &slotFor(int typeId) const;
/// Index of the histogram bucket the sample falls into. The last index is +Inf.
static int bucketIndexFor(qint64 elapsedMs);
/// Appends one series of cumulative +Inf-terminated buckets to @p out.
static void appendCumulativeBuckets(QString &out,
const QString &bucketLine,
const std::array<std::atomic<qint64>, BucketCount> &buckets);
std::array<TypeStats, MaxTypes> typeSlots{};
TypeStats gameStartStats{};
std::atomic<qint64> totalCommandsCounter{0};
std::atomic<qint64> totalTimeCounter{0};
};
#endif

View file

@ -20,6 +20,7 @@
#include "servatrice.h"
#include "email_parser.h"
#include "event_loop_watchdog.h"
#include "isl_interface.h"
#include "main.h"
#include "servatrice_connection_pool.h"
@ -38,6 +39,7 @@
#include <QStringList>
#include <QTimer>
#include <QUrl>
#include <game/server_game.h>
#include <iostream>
#include <libcockatrice/deck_list/deck_list.h>
#include <libcockatrice/protocol/featureset.h>
@ -63,6 +65,7 @@ Servatrice_GameServer::Servatrice_GameServer(Servatrice *_server,
server->addDatabaseInterface(newThread, newDatabaseInterface);
newThread->start();
server->watchWorkerThread(newThread);
QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection,
Q_ARG(QSqlDatabase, _sqlDatabase));
@ -131,6 +134,7 @@ Servatrice_WebsocketGameServer::Servatrice_WebsocketGameServer(Servatrice *_serv
server->addDatabaseInterface(newThread, newDatabaseInterface);
newThread->start();
server->watchWorkerThread(newThread);
QMetaObject::invokeMethod(newDatabaseInterface, "initDatabase", Qt::BlockingQueuedConnection,
Q_ARG(QSqlDatabase, _sqlDatabase));
@ -470,9 +474,60 @@ bool Servatrice::initServer()
}
setRequiredFeatures(getRequiredFeatures());
// METRICS (always active. Slow-command logging and stall watchdogs are
// controlled by their respective thresholds below)
metricsSlowCommandMs = settingsCache->value("metrics/slow_command_ms", 500).toInt();
metricsStallWarnMs = qMax(0, settingsCache->value("metrics/stall_warn_ms", 2000).toInt());
return true;
}
void Servatrice::observeGameStartDurationMs(qint64 elapsedMs)
{
metricsRegistry.observeGameStartDurationMs(elapsedMs);
}
void Servatrice::observeEventLoopStall(const QString &threadName, qint64 overshootMs)
{
eventLoopStallsTotal.fetch_add(1, std::memory_order_relaxed);
eventLoopLastStallMs.store(overshootMs, std::memory_order_relaxed);
qint64 prevMax = eventLoopMaxStallMs.load(std::memory_order_relaxed);
while (overshootMs > prevMax &&
!eventLoopMaxStallMs.compare_exchange_weak(prevMax, overshootMs, std::memory_order_relaxed)) {
// retry until the max is at least as high as the new sample
}
qWarning() << "Event loop stall in" << threadName << "- heartbeat overshot by" << overshootMs << "ms";
}
void Servatrice::watchWorkerThread(QThread *thread)
{
if (metricsStallWarnMs <= 0) {
return; // watchdogs disabled via metrics/stall_warn_ms = 0
}
auto *watchdog = new EventLoopWatchdog(this, thread->objectName());
connect(thread, &QThread::finished, watchdog, &QObject::deleteLater);
watchdog->moveToThread(thread);
QMetaObject::invokeMethod(watchdog, &EventLoopWatchdog::start, Qt::QueuedConnection);
}
qint64 Servatrice::getCardsInGamesTotal() const
{
qint64 total = 0;
QReadLocker roomsLocker(&roomsLock); // locking order: roomsLock before gamesLock/gameMutex
QMapIterator<int, Server_Room *> roomIterator(rooms);
while (roomIterator.hasNext()) {
Server_Room *room = roomIterator.next().value();
QReadLocker gamesLocker(&room->gamesLock);
for (auto *game : room->getGames()) {
total += game->getCardsInGame();
}
}
return total;
}
void Servatrice::addDatabaseInterface(QThread *thread, Servatrice_DatabaseInterface *databaseInterface)
{
databaseInterfaces.insert(thread, databaseInterface);
@ -728,6 +783,7 @@ void Servatrice::incTxBytes(quint64 num)
txBytesMutex.lock();
txBytes += num;
txBytesMutex.unlock();
txBytesTotal.fetch_add(num, std::memory_order_relaxed);
}
void Servatrice::incRxBytes(quint64 num)
@ -735,6 +791,7 @@ void Servatrice::incRxBytes(quint64 num)
rxBytesMutex.lock();
rxBytes += num;
rxBytesMutex.unlock();
rxBytesTotal.fetch_add(num, std::memory_order_relaxed);
}
void Servatrice::shutdownTimeout()

View file

@ -20,6 +20,8 @@
#ifndef SERVATRICE_H
#define SERVATRICE_H
#include "metrics_registry.h"
#include <QDateTime>
#include <QHostAddress>
#include <QMetaType>
@ -30,6 +32,7 @@
#include <QSslKey>
#include <QTcpServer>
#include <QWebSocketServer>
#include <atomic>
#include <libcockatrice/protocol/pb/response_report_stats.pb.h>
#include <memory>
#include <server.h>
@ -170,6 +173,14 @@ private:
int uptime;
QMutex txBytesMutex, rxBytesMutex;
quint64 txBytes, rxBytes;
std::atomic<quint64> txBytesTotal{0}; ///< cumulative bytes sent since process start
std::atomic<quint64> rxBytesTotal{0}; ///< cumulative bytes received since process start
MetricsRegistry metricsRegistry;
int metricsSlowCommandMs = 500;
int metricsStallWarnMs = 2000;
std::atomic<qint64> eventLoopStallsTotal{0}; ///< heartbeat overshoots past the warn threshold
std::atomic<qint64> eventLoopLastStallMs{0}; ///< overshoot of the most recent stall
std::atomic<qint64> eventLoopMaxStallMs{0}; ///< worst overshoot seen since process start
QString shutdownReason;
int shutdownMinutes;
@ -286,6 +297,58 @@ public:
void incRxBytes(quint64 num);
void addDatabaseInterface(QThread *thread, Servatrice_DatabaseInterface *databaseInterface);
// Metrics (see [metrics] section in servatrice.ini.example)
MetricsRegistry &getMetricsRegistry()
{
return metricsRegistry;
}
quint64 getTxBytesTotal() const
{
return txBytesTotal.load(std::memory_order_relaxed);
}
quint64 getRxBytesTotal() const
{
return rxBytesTotal.load(std::memory_order_relaxed);
}
int getUptimeSeconds() const
{
return uptime;
}
/**
* Sums cards across all zones of all running games. Locks rooms and games
* briefly per level, so scrape-time cost grows with live game count only.
*/
qint64 getCardsInGamesTotal() const;
int getMetricsSlowCommandMs() const
{
return metricsSlowCommandMs;
}
/// Heartbeat overshoot that counts as a stall. A value of 0 disables the watchdogs.
int getMetricsStallWarnMs() const
{
return metricsStallWarnMs;
}
void observeGameStartDurationMs(qint64 elapsedMs) override;
qint64 getEventLoopStallsTotal() const
{
return eventLoopStallsTotal.load(std::memory_order_relaxed);
}
qint64 getEventLoopLastStallMs() const
{
return eventLoopLastStallMs.load(std::memory_order_relaxed);
}
qint64 getEventLoopMaxStallMs() const
{
return eventLoopMaxStallMs.load(std::memory_order_relaxed);
}
/// Records one heartbeat overshoot and logs a single warning for it.
void observeEventLoopStall(const QString &threadName, qint64 overshootMs);
/**
* Installs an EventLoopWatchdog in @p thread. Called once per socket pool
* thread right after it starts.
*/
void watchWorkerThread(QThread *thread);
bool islConnectionExists(int _serverId) const;
void addIslInterface(int _serverId, IslInterface *interface);
void removeIslInterface(int _serverId);

View file

@ -1487,6 +1487,38 @@ QList<ServerInfo_ModeratorLogin> Servatrice_DatabaseInterface::getModeratorLastL
return results;
}
Servatrice_DatabaseInterface::UptimeSnapshot Servatrice_DatabaseInterface::getLatestUptimeSnapshot(int serverId)
{
UptimeSnapshot snapshot;
if (!checkSql()) {
return snapshot;
}
QSqlQuery *query = prepareQuery("SELECT users_count, mods_count, games_count, tx_bytes, rx_bytes, uptime, "
"UNIX_TIMESTAMP(timest) FROM {prefix}_uptime "
"WHERE id_server = :id_server ORDER BY timest DESC LIMIT 1");
query->bindValue(":id_server", serverId);
if (!execSqlQuery(query)) {
qCWarning(DatabaseInterfaceLog) << "Failed to collect server stats snapshot: SQL Error";
return snapshot;
}
if (query->next()) {
snapshot.valid = true;
snapshot.usersCount = query->value(0).toULongLong();
snapshot.modsCount = query->value(1).toULongLong();
snapshot.gamesCount = query->value(2).toULongLong();
snapshot.txBytes = query->value(3).toULongLong();
snapshot.rxBytes = query->value(4).toULongLong();
snapshot.uptimeSecs = query->value(5).toULongLong();
snapshot.timest = query->value(6).toULongLong();
}
return snapshot;
}
bool Servatrice_DatabaseInterface::removeUserAvatar(const QString &userName)
{
if (!checkSql()) {

View file

@ -140,6 +140,21 @@ public:
QList<ServerInfo_UserSession> getUserSessions(const QString &userName, int limit);
QList<ServerInfo_UserAlt> getUserAlts(const QString &userName);
QList<ServerInfo_ModeratorLogin> getModeratorLastLogins();
// Uptime snapshot as recorded by Servatrice::statusUpdate() into the
// {prefix}_uptime table. valid is false when no snapshot exists yet.
struct UptimeSnapshot
{
bool valid = false;
quint64 usersCount = 0;
quint64 modsCount = 0;
quint64 gamesCount = 0;
quint64 txBytes = 0;
quint64 rxBytes = 0;
quint64 uptimeSecs = 0;
quint64 timest = 0;
};
UptimeSnapshot getLatestUptimeSnapshot(int serverId);
bool removeUserAvatar(const QString &userName);
bool addForgotPassword(const QString &user);
bool removeForgotPassword(const QString &user) override;

View file

@ -30,6 +30,7 @@
#include <QDateTime>
#include <QDebug>
#include <QElapsedTimer>
#include <QHostAddress>
#include <QJsonDocument>
#include <QJsonObject>
@ -39,15 +40,16 @@
#include <QSqlQuery>
#include <QString>
#include <game/server_player.h>
#include <google/protobuf/descriptor.h>
#include <iostream>
#include <libcockatrice/deck_list/deck_list.h>
#include <libcockatrice/protocol/get_pb_extension.h>
#include <libcockatrice/protocol/pb/command_deck_del.pb.h>
#include <libcockatrice/protocol/pb/command_deck_del_dir.pb.h>
#include <libcockatrice/protocol/pb/command_deck_download.pb.h>
#include <libcockatrice/protocol/pb/command_deck_list.pb.h>
#include <libcockatrice/protocol/pb/command_deck_new_dir.pb.h>
#include <libcockatrice/protocol/pb/command_deck_upload.pb.h>
#include <libcockatrice/protocol/pb/command_get_log_history.pb.h>
#include <libcockatrice/protocol/pb/command_get_server_stats.pb.h>
#include <libcockatrice/protocol/pb/command_replay_delete_match.pb.h>
#include <libcockatrice/protocol/pb/command_replay_download.pb.h>
@ -193,6 +195,41 @@ void AbstractServerSocketInterface::logDebugMessage(const QString &message)
logger->logMessage(message, this);
}
void AbstractServerSocketInterface::processCommandContainer(const CommandContainer &cont)
{
QElapsedTimer timer;
timer.start();
Server_ProtocolHandler::processCommandContainer(cont);
const qint64 elapsedMs = timer.nsecsElapsed() / 1000000;
// A container usually holds a single command. When several are batched,
// each is attributed the container's total processing time.
for (const auto &cmd : cont.session_command()) {
servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(0, getPbExtension(cmd)), elapsedMs);
}
for (const auto &cmd : cont.room_command()) {
servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(1, getPbExtension(cmd)), elapsedMs);
}
for (const auto &cmd : cont.game_command()) {
servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(2, getPbExtension(cmd)), elapsedMs);
}
for (const auto &cmd : cont.moderator_command()) {
servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(3, getPbExtension(cmd)), elapsedMs);
}
for (const auto &cmd : cont.admin_command()) {
servatrice->getMetricsRegistry().observeCommand(MetricsRegistry::typeIdFor(4, getPbExtension(cmd)), elapsedMs);
}
const int slowCommandMs = servatrice->getMetricsSlowCommandMs();
if (slowCommandMs > 0 && elapsedMs >= slowCommandMs) {
const ServerInfo_User *info = getUserInfo();
const QString user = authState == PasswordRight && info ? QString::fromStdString(info->name())
: QStringLiteral("unauthenticated");
qCWarning(AbstractServerSocketInterfaceLog) << "slow command container from" << user << "processed in"
<< elapsedMs << "ms (" << cont.ByteSizeLong() << "bytes)";
}
}
Response::ResponseCode AbstractServerSocketInterface::processExtendedSessionCommand(int cmdType,
const SessionCommand &cmd,
ResponseContainer &rc)
@ -287,7 +324,7 @@ Response::ResponseCode AbstractServerSocketInterface::processExtendedModeratorCo
case ModeratorCommand::REPORT_RESOLVE:
return cmdReportResolve(cmd.GetExtension(Command_ReportResolve::ext), rc);
case ModeratorCommand::VIEWLOG_HISTORY:
return cmdGetLogHistory(cmd.GetExtension(Command_ViewLogHistory::ext), rc);
return cmdGetLogHistory(cmd.GetExtension(Command_ViewLogHistory::ext), rc, true);
case ModeratorCommand::GRANT_REPLAY_ACCESS:
return cmdGrantReplayAccess(cmd.GetExtension(Command_GrantReplayAccess::ext), rc);
case ModeratorCommand::REPLAY_DOWNLOAD_BY_GAME_ID:
@ -351,21 +388,9 @@ Response::ResponseCode AbstractServerSocketInterface::processExtendedDeveloperCo
case DeveloperCommand::GET_SERVER_STATS:
return cmdGetServerStats(cmd.GetExtension(Command_GetServerStats::ext), rc);
case DeveloperCommand::VIEWLOG_HISTORY: {
// Same query as the moderator log view, just carried by the
// developer command family.
const Command_GetLogHistory &devCmd = cmd.GetExtension(Command_GetLogHistory::ext);
Command_ViewLogHistory modCmd;
modCmd.set_user_name(devCmd.user_name());
modCmd.set_ip_address(devCmd.ip_address());
modCmd.set_game_name(devCmd.game_name());
modCmd.set_game_id(devCmd.game_id());
modCmd.set_message(devCmd.message());
for (int i = 0; i < devCmd.log_location_size(); ++i) {
modCmd.add_log_location(devCmd.log_location(i));
}
modCmd.set_date_range(devCmd.date_range());
modCmd.set_maximum_results(devCmd.maximum_results());
return cmdGetLogHistory(modCmd, rc);
// Same query as the moderator log view, carried by the developer
// command family, but narrows out private chats and sender IPs.
return cmdGetLogHistory(cmd.GetExtension(Command_ViewLogHistory::dev_ext), rc, false);
}
default:
return Response::RespFunctionNotAllowed;
@ -1055,12 +1080,13 @@ Response::ResponseCode AbstractServerSocketInterface::cmdReplaySubmitCode(const
// MODERATOR FUNCTIONS.
// May be called by admins and moderators. Permission is checked by the calling function.
Response::ResponseCode AbstractServerSocketInterface::cmdGetLogHistory(const Command_ViewLogHistory &cmd,
ResponseContainer &rc)
ResponseContainer &rc,
bool allowPrivateChat)
{
QList<ServerInfo_ChatMessage> messageList;
QString userName = nameFromStdString(cmd.user_name());
QString ipAddress = nameFromStdString(cmd.ip_address());
QString ipAddress = allowPrivateChat ? nameFromStdString(cmd.ip_address()) : QString();
QString gameName = nameFromStdString(cmd.game_name());
QString gameID = nameFromStdString(cmd.game_id());
QString message = textFromStdString(cmd.message());
@ -1075,7 +1101,7 @@ Response::ResponseCode AbstractServerSocketInterface::cmdGetLogHistory(const Com
if (nameFromStdString(cmd.log_location(i)).simplified() == "game") {
gameType = true;
}
if (nameFromStdString(cmd.log_location(i)).simplified() == "chat") {
if (nameFromStdString(cmd.log_location(i)).simplified() == "chat" && allowPrivateChat) {
chatType = true;
}
}
@ -1089,7 +1115,11 @@ Response::ResponseCode AbstractServerSocketInterface::cmdGetLogHistory(const Com
QListIterator<ServerInfo_ChatMessage> messageIterator(sqlInterface->getMessageLogHistory(
userName, ipAddress, gameName, gameID, message, chatType, gameType, roomType, dateRange, maximumResults));
while (messageIterator.hasNext()) {
re->add_log_message()->CopyFrom(messageIterator.next());
ServerInfo_ChatMessage chatMessage = messageIterator.next();
if (!allowPrivateChat) {
chatMessage.clear_sender_ip();
}
re->add_log_message()->CopyFrom(chatMessage);
}
} else {
ServerInfo_ChatMessage chatMessage;
@ -1687,23 +1717,64 @@ Response::ResponseCode AbstractServerSocketInterface::cmdGetServerStats(const Co
// Servatrice::statusUpdate() periodically snapshots server health into the
// uptime table. Serve the freshest snapshot for this server.
QSqlQuery *query = sqlInterface->prepareQuery(
"SELECT users_count, mods_count, games_count, tx_bytes, rx_bytes, uptime, UNIX_TIMESTAMP(timest) "
"FROM {prefix}_uptime WHERE id_server = :id_server ORDER BY timest DESC LIMIT 1");
query->bindValue(":id_server", servatrice->getServerID());
if (!sqlInterface->execSqlQuery(query)) {
const auto snapshot = sqlInterface->getLatestUptimeSnapshot(servatrice->getServerID());
if (!snapshot.valid) {
// No snapshot yet (fresh server, or statusUpdate() has not ticked).
return Response::RespInternalError;
}
auto *re = new Response_GetServerStats;
if (query->next()) {
re->set_users_count(query->value(0).toUInt());
re->set_mods_count(query->value(1).toUInt());
re->set_games_count(query->value(2).toUInt());
re->set_tx_bytes(query->value(3).toUInt());
re->set_rx_bytes(query->value(4).toUInt());
re->set_uptime_secs(query->value(5).toUInt());
re->set_timest(query->value(6).toUInt());
re->set_users_count(snapshot.usersCount);
re->set_mods_count(snapshot.modsCount);
re->set_games_count(snapshot.gamesCount);
re->set_tx_bytes(snapshot.txBytes);
re->set_rx_bytes(snapshot.rxBytes);
re->set_uptime_secs(snapshot.uptimeSecs);
re->set_timest(snapshot.timest);
// Live metrics from the in-process MetricsRegistry (resets on server restart)
re->set_cards_in_games(static_cast<google::protobuf::uint64>(servatrice->getCardsInGamesTotal()));
re->set_eventloop_stalls_total(static_cast<google::protobuf::uint64>(servatrice->getEventLoopStallsTotal()));
re->set_eventloop_last_stall_ms(static_cast<google::protobuf::uint64>(servatrice->getEventLoopLastStallMs()));
re->set_eventloop_max_stall_ms(static_cast<google::protobuf::uint64>(servatrice->getEventLoopMaxStallMs()));
re->set_total_commands(static_cast<google::protobuf::uint64>(servatrice->getMetricsRegistry().totalCommands()));
re->set_total_command_time_ms(
static_cast<google::protobuf::uint64>(servatrice->getMetricsRegistry().totalTimeMs()));
re->set_active_command_types(servatrice->getMetricsRegistry().activeTypeCount());
const auto gameStart = servatrice->getMetricsRegistry().getGameStartSnapshot();
re->set_game_start_count(static_cast<google::protobuf::uint64>(gameStart.count));
re->set_game_start_total_ms(static_cast<google::protobuf::uint64>(gameStart.totalMs));
// Per-command breakdown: resolve protobuf extension names via the descriptor pool
static const char *messageNames[] = {"SessionCommand", "RoomCommand", "GameCommand", "ModeratorCommand",
"AdminCommand"};
const auto activeStats = servatrice->getMetricsRegistry().collectActiveStats();
for (const auto &stat : activeStats) {
const int kind = stat.typeId / MetricsRegistry::KindStride;
const int number = stat.typeId % MetricsRegistry::KindStride;
QString label;
if (kind >= 0 && kind < MetricsRegistry::NumKinds) {
const google::protobuf::DescriptorPool *pool = google::protobuf::DescriptorPool::generated_pool();
const google::protobuf::Descriptor *message = pool->FindMessageTypeByName(messageNames[kind]);
const google::protobuf::FieldDescriptor *extension =
message ? pool->FindExtensionByNumber(message, number) : nullptr;
if (extension) {
label = QString::fromLatin1(MetricsRegistry::KindNames[kind]) + QStringLiteral("/") +
QString::fromStdString(std::string(extension->message_type()->name()));
}
}
if (label.isEmpty()) {
label = QString::number(stat.typeId);
}
CommandStats *cs = re->add_command_stats();
cs->set_kind_index(static_cast<google::protobuf::uint32>(kind));
cs->set_extension_number(static_cast<google::protobuf::uint32>(number));
cs->set_command_name(label.toStdString());
cs->set_count(static_cast<google::protobuf::uint64>(stat.count));
cs->set_total_ms(static_cast<google::protobuf::uint64>(stat.totalMs));
}
rc.setResponseExtension(re);

View file

@ -24,7 +24,6 @@
#include <QMutex>
#include <QTcpSocket>
#include <QWebSocket>
#include <libcockatrice/protocol/pb/command_get_log_history.pb.h>
#include <libcockatrice/protocol/pb/command_get_server_stats.pb.h>
#include <libcockatrice/protocol/pb/command_replay_download_by_game_id.pb.h>
#include <libcockatrice/protocol/pb/command_report.pb.h>
@ -82,6 +81,7 @@ signals:
protected:
void logDebugMessage(const QString &message) override;
bool tooManyRegistrationAttempts(const QString &ipAddress);
void processCommandContainer(const CommandContainer &cont) override;
virtual void writeToSocket(QByteArray &data) = 0;
virtual void flushSocket() = 0;
@ -117,7 +117,8 @@ private:
Response::ResponseCode cmdBanFromServer(const Command_BanFromServer &cmd, ResponseContainer &rc);
Response::ResponseCode cmdReportList(const Command_ReportList &cmd, ResponseContainer &rc);
Response::ResponseCode cmdWarnUser(const Command_WarnUser &cmd, ResponseContainer &rc);
Response::ResponseCode cmdGetLogHistory(const Command_ViewLogHistory &cmd, ResponseContainer &rc);
Response::ResponseCode
cmdGetLogHistory(const Command_ViewLogHistory &cmd, ResponseContainer &rc, bool allowPrivateChat);
Response::ResponseCode cmdGetBanHistory(const Command_GetBanHistory &cmd, ResponseContainer &rc);
Response::ResponseCode cmdGetWarnList(const Command_GetWarnList &cmd, ResponseContainer &rc);
Response::ResponseCode cmdGetWarnHistory(const Command_GetWarnHistory &cmd, ResponseContainer &rc);

View file

@ -11,9 +11,11 @@ add_test(NAME playmat_resolver_test COMMAND playmat_resolver_test)
add_test(NAME server_card_counter_test COMMAND server_card_counter_test)
add_test(NAME server_counter_test COMMAND server_counter_test)
add_test(NAME server_rate_limiter_test COMMAND server_rate_limiter_test)
add_test(NAME server_developer_role_test COMMAND server_developer_role_test)
add_test(NAME warning_categories_test COMMAND warning_categories_test)
add_test(NAME lag_monitor_test COMMAND lag_monitor_test)
add_test(NAME latency_tracker_test COMMAND latency_tracker_test)
add_test(NAME metrics_registry_test COMMAND metrics_registry_test)
add_test(NAME deck_hash_performance_test COMMAND deck_hash_performance_test)
set_tests_properties(deck_hash_performance_test PROPERTIES TIMEOUT 15)
@ -30,10 +32,12 @@ add_executable(deck_hash_performance_test deck_hash_performance_test.cpp)
add_executable(server_card_counter_test server_card_counter_test.cpp)
add_executable(server_counter_test server_counter_test.cpp)
add_executable(server_rate_limiter_test server_rate_limiter_test.cpp)
add_executable(server_developer_role_test server_developer_role_test.cpp)
add_executable(warning_categories_test warning_categories_test.cpp)
add_executable(lag_monitor_test ${CMAKE_SOURCE_DIR}/cockatrice/src/client/lag_monitor.cpp lag_monitor_test.cpp)
target_include_directories(lag_monitor_test PRIVATE ${CMAKE_SOURCE_DIR}/cockatrice/src)
add_executable(latency_tracker_test latency_tracker_test.cpp)
add_executable(metrics_registry_test ../servatrice/src/metrics_registry.cpp metrics_registry_test.cpp)
find_package(GTest)
@ -70,9 +74,11 @@ if(NOT GTEST_FOUND)
add_dependencies(server_card_counter_test gtest)
add_dependencies(server_counter_test gtest)
add_dependencies(server_rate_limiter_test gtest)
add_dependencies(server_developer_role_test gtest)
add_dependencies(warning_categories_test gtest)
add_dependencies(lag_monitor_test gtest)
add_dependencies(latency_tracker_test gtest)
add_dependencies(metrics_registry_test gtest)
endif()
include_directories(${GTEST_INCLUDE_DIRS})
@ -104,6 +110,10 @@ target_link_libraries(
target_link_libraries(
server_rate_limiter_test libcockatrice_utility Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES}
)
target_link_libraries(
server_developer_role_test libcockatrice_network libcockatrice_rng Threads::Threads ${GTEST_BOTH_LIBRARIES}
${TEST_QT_MODULES}
)
target_link_libraries(
warning_categories_test libcockatrice_utility Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES}
)
@ -111,6 +121,8 @@ target_link_libraries(lag_monitor_test Threads::Threads ${GTEST_BOTH_LIBRARIES}
target_link_libraries(
latency_tracker_test libcockatrice_network Threads::Threads ${GTEST_BOTH_LIBRARIES} ${TEST_QT_MODULES}
)
target_include_directories(metrics_registry_test PRIVATE ${CMAKE_SOURCE_DIR}/servatrice/src)
target_link_libraries(metrics_registry_test ${TEST_QT_MODULES} Threads::Threads ${GTEST_BOTH_LIBRARIES})
add_subdirectory(card_zone_algorithms)
add_subdirectory(carddatabase)

View file

@ -0,0 +1,131 @@
#include <QRegularExpression>
#include <gtest/gtest.h>
#include <metrics_registry.h>
TEST(MetricsRegistryTest, EmptyRegistryProducesNoHistogramLines)
{
MetricsRegistry registry;
EXPECT_EQ(0, registry.totalCommands());
EXPECT_EQ(0, registry.totalTimeMs());
EXPECT_EQ(0, registry.activeTypeCount());
const QString text = registry.toPrometheusText([](int) { return QString("x"); }, {});
// The family TYPE declaration may stand alone. What must not exist is a
// histogram sample without data behind it.
EXPECT_FALSE(text.contains(QRegularExpression("servatrice_commands_duration_ms_(bucket|sum|count)")));
}
TEST(MetricsRegistryTest, SingleSampleIsRecordedInTotalsAndBuckets)
{
MetricsRegistry registry;
registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 7);
EXPECT_EQ(1, registry.totalCommands());
EXPECT_EQ(7, registry.totalTimeMs());
EXPECT_EQ(1, registry.activeTypeCount());
const QString text = registry.toPrometheusText(
[](int typeId) {
return QString("%1/%2").arg(typeId / MetricsRegistry::KindStride).arg(typeId % MetricsRegistry::KindStride);
},
{});
// 7ms falls into the le="10" bucket. Smaller buckets stay empty
EXPECT_TRUE(text.contains("# TYPE servatrice_commands_duration_ms histogram\n"));
EXPECT_TRUE(text.contains(",le=\"10\"} 1"));
EXPECT_TRUE(text.contains(",le=\"5\"} 0"));
EXPECT_TRUE(text.contains("_sum{command=\"0/1000\"} 7"));
EXPECT_TRUE(text.contains("_count{command=\"0/1000\"} 1"));
}
TEST(MetricsRegistryTest, BucketsAreCumulative)
{
MetricsRegistry registry;
registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 2);
registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), 30);
const QString text = registry.toPrometheusText([](int) { return QString("cmd"); }, {});
// cumulative counts: <=25 -> 1 sample, <=50 -> 2 samples
EXPECT_TRUE(text.contains(",le=\"25\"} 1\n"));
EXPECT_TRUE(text.contains(",le=\"50\"} 2\n"));
EXPECT_TRUE(text.contains(",le=\"+Inf\"} 2\n"));
}
TEST(MetricsRegistryTest, KindEncodingSeparatesSameExtensionNumber)
{
MetricsRegistry registry;
const int sessionPing = MetricsRegistry::typeIdFor(0, 1000);
const int roomLeaveRoom = MetricsRegistry::typeIdFor(1, 1000);
ASSERT_NE(sessionPing, roomLeaveRoom);
registry.observeCommand(sessionPing, 1);
registry.observeCommand(roomLeaveRoom, 5000);
EXPECT_EQ(2, registry.activeTypeCount());
}
TEST(MetricsRegistryTest, OutOfRangeIdsLandInOverflowSlot)
{
MetricsRegistry registry;
registry.observeCommand(-1, 4);
registry.observeCommand(MetricsRegistry::MaxTypes + 12345, 4);
EXPECT_EQ(2, registry.totalCommands());
EXPECT_EQ(1, registry.activeTypeCount()); // both collapsed into one slot
EXPECT_EQ(8, registry.totalTimeMs());
}
TEST(MetricsRegistryTest, NegativeDurationsAreClamped)
{
MetricsRegistry registry;
registry.observeCommand(MetricsRegistry::typeIdFor(0, 1000), -50);
EXPECT_EQ(0, registry.totalTimeMs());
}
TEST(MetricsRegistryTest, GaugesAndLabelEscapingAreRendered)
{
MetricsRegistry registry;
QHash<QString, qint64> gauges;
gauges.insert("servatrice_users_current", 42);
const QString text = registry.toPrometheusText(nullptr, gauges);
EXPECT_TRUE(text.contains("# TYPE servatrice_users_current gauge\n"));
EXPECT_TRUE(text.contains("servatrice_users_current 42\n"));
}
TEST(MetricsRegistryTest, UnnamedTypesFallBackToNumericLabel)
{
MetricsRegistry registry;
registry.observeCommand(MetricsRegistry::typeIdFor(2, 1042), 9);
const QString text = registry.toPrometheusText(nullptr, {});
EXPECT_TRUE(text.contains("{command=\"" + QString::number(MetricsRegistry::typeIdFor(2, 1042)) + "\"}"));
}
TEST(MetricsRegistryTest, GameStartHistogramOnlyAppearsAfterSamples)
{
MetricsRegistry registry;
EXPECT_FALSE(registry.toPrometheusText(nullptr, {}).contains("servatrice_game_start_duration_ms"));
registry.observeGameStartDurationMs(120);
const QString text = registry.toPrometheusText(nullptr, {});
// 120ms falls into the le="250" bucket
EXPECT_TRUE(text.contains("# TYPE servatrice_game_start_duration_ms histogram\n"));
EXPECT_TRUE(text.contains(",le=\"100\"} 0\n"));
EXPECT_TRUE(text.contains(",le=\"250\"} 1\n"));
EXPECT_TRUE(text.contains("servatrice_game_start_duration_ms_sum 120\n"));
EXPECT_TRUE(text.contains("servatrice_game_start_duration_ms_count 1\n"));
}
TEST(MetricsRegistryTest, GameStartHistogramIsSeparateFromCommandTotals)
{
MetricsRegistry registry;
registry.observeGameStartDurationMs(10);
EXPECT_EQ(0, registry.totalCommands());
EXPECT_EQ(0, registry.totalTimeMs());
EXPECT_EQ(0, registry.activeTypeCount());
}

View file

@ -0,0 +1,137 @@
/** @file server_developer_role_test.cpp
* @brief Tests for the developer staff role authorization and dispatch.
* @ingroup Tests
*/
#include <gtest/gtest.h>
#include <libcockatrice/network/server/remote/server.h>
#include <libcockatrice/network/server/remote/server_protocolhandler.h>
#include <libcockatrice/protocol/pb/command_get_server_stats.pb.h>
#include <libcockatrice/protocol/pb/commands.pb.h>
#include <libcockatrice/protocol/pb/developer_commands.pb.h>
#include <libcockatrice/protocol/pb/serverinfo_user.pb.h>
#include <libcockatrice/rng/rng_abstract.h>
// The server_remote library references the global RNG, which is normally
// defined by the servatrice/client executable main(). Provide a stub so the
// unit test can link against it.
RNG_Abstract *rng = nullptr;
namespace
{
class TestDeveloperHandler : public Server_ProtocolHandler
{
public:
explicit TestDeveloperHandler(Server *_server) : Server_ProtocolHandler(_server, nullptr)
{
}
QString getAddress() const override
{
return {};
}
QString getConnectionType() const override
{
return {};
}
// Buffer the last response code sent to the client so tests can assert on
// the outcome of processCommandContainer().
Response::ResponseCode lastResponseCode = Response::RespNothing;
int dispatchCount = 0;
protected:
void transmitProtocolItem(const ServerMessage &item) override
{
if (item.message_type() == ServerMessage::RESPONSE) {
lastResponseCode = item.response().response_code();
}
}
Response::ResponseCode
processExtendedDeveloperCommand(int cmdType, const DeveloperCommand &, ResponseContainer &) override
{
++dispatchCount;
// Fail closed for anything not explicitly handled.
if (cmdType != DeveloperCommand::GET_SERVER_STATS) {
return Response::RespFunctionNotAllowed;
}
return Response::RespOk;
}
};
class DeveloperRoleTest : public ::testing::Test
{
protected:
Server server;
TestDeveloperHandler handler{&server};
void setUserLevel(uint32_t level)
{
ServerInfo_User user;
user.set_user_level(level);
handler.setUserInfo(user);
}
};
TEST_F(DeveloperRoleTest, RejectsWhenNotLoggedIn)
{
CommandContainer cont;
cont.add_developer_command();
handler.processCommandContainer(cont);
EXPECT_EQ(handler.lastResponseCode, Response::RespLoginNeeded);
EXPECT_EQ(handler.dispatchCount, 0);
}
TEST_F(DeveloperRoleTest, RejectsPlainUser)
{
setUserLevel(ServerInfo_User::IsUser | ServerInfo_User::IsRegistered);
CommandContainer cont;
cont.add_developer_command();
handler.processCommandContainer(cont);
EXPECT_EQ(handler.lastResponseCode, Response::RespLoginNeeded);
EXPECT_EQ(handler.dispatchCount, 0);
}
TEST_F(DeveloperRoleTest, RejectsModeratorThatIsNotDeveloper)
{
setUserLevel(ServerInfo_User::IsModerator);
CommandContainer cont;
cont.add_developer_command();
handler.processCommandContainer(cont);
EXPECT_EQ(handler.lastResponseCode, Response::RespLoginNeeded);
}
TEST_F(DeveloperRoleTest, DispatchesToDeveloperCommandForDeveloper)
{
setUserLevel(ServerInfo_User::IsDeveloper);
CommandContainer cont;
DeveloperCommand *cmd = cont.add_developer_command();
cmd->MutableExtension(Command_GetServerStats::ext);
handler.processCommandContainer(cont);
EXPECT_EQ(handler.lastResponseCode, Response::RespOk);
EXPECT_EQ(handler.dispatchCount, 1);
}
TEST_F(DeveloperRoleTest, FailClosedForUnknownDeveloperCommand)
{
setUserLevel(ServerInfo_User::IsDeveloper);
CommandContainer cont;
cont.add_developer_command(); // no extension set -> getPbExtension() returns -1
handler.processCommandContainer(cont);
EXPECT_EQ(handler.lastResponseCode, Response::RespFunctionNotAllowed);
EXPECT_EQ(handler.dispatchCount, 1);
}
} // namespace
int main(int argc, char **argv)
{
::testing::InitGoogleTest(&argc, argv);
return RUN_ALL_TESTS();
}