Skip to content

Logging: improve suppression thread safety; fix file/line logging in gamelogic #1829

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
slipher merged 4 commits into from
Oct 5, 2025
Merged

Logging: improve suppression thread safety; fix file/line logging in gamelogic #1829

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
f7af56d
Simplify Logger::Prefix (function that adds prefix)
slipher Sep 28, 2025
649dc2a
Fix unused Log::(Warn|Notice|Verbose|Debug) decls
slipher Sep 28, 2025
7f5dcd4
Access log suppression cvars less thread-unsafely
slipher Sep 28, 2025
a235cb3
Fix file:line logging in gamelogic
slipher Sep 29, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
97 changes: 67 additions & 30 deletions src/common/Log.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -30,33 +30,79 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.

#include "Common.h"

#ifdef BUILD_ENGINE
// TODO: when cvar multiple registration is available, just declare the cvars in each module.
static Cvar::Cvar<bool> suppressionEnabled(
"logs.suppression.enabled", "Whether to suppress log messages that are printed too many times", Cvar::NONE, true);
static Cvar::Range<Cvar::Cvar<int>> suppressionInterval(
"logs.suppression.interval", "Interval in milliseconds for detecting log spam", Cvar::NONE, 2000, 1, 1000000);
static Cvar::Range<Cvar::Cvar<int>> suppressionCount(
"logs.suppression.count", "Number of occurrences for a message to be considered log spam", Cvar::NONE, 10, 1, 1000000);
static Cvar::Range<Cvar::Cvar<int>> suppressionBufSize(
"logs.suppression.bufferSize", "How many distinct messages to track for log suppression", Cvar::NONE, 50, 1, 1000000);
static Cvar::Cvar<bool> logExtendAll(
"logs.writeSrcLocation.all", "Always print source code location for logs", Cvar::NONE, false);
static Cvar::Cvar<bool> logExtendWarn(
"logs.writeSrcLocation.warn", "Print source code location for Warn logs", Cvar::NONE, false);
static Cvar::Cvar<bool> logExtendNotice(
"logs.writeSrcLocation.notice", "Print source code location for Notice logs", Cvar::NONE, false);
static Cvar::Cvar<bool> logExtendVerbose(
"logs.writeSrcLocation.verbose", "Print source code location for Verbose logs", Cvar::NONE, false);
static Cvar::Cvar<bool> logExtendDebug(
"logs.writeSrcLocation.debug", "Print source code location for Debug logs", Cvar::NONE, false);

#define GET_LOG_CVAR(type, name, object) (object.Get())
#else
#define GET_LOG_CVAR(type, name, object) (GetCvarOrDie<type>(name))
template <typename T>
static T GetCvarOrDie(Str::StringRef cvar) {
T value;
std::string valueString = Cvar::GetValue(cvar);
if (!Cvar::ParseCvarValue(valueString, value)) {
Sys::Error("Failed to deserialize cvar %s with value: %s", cvar, valueString);
}
return value;
}
#endif

namespace Log {
Cvar::Cvar<bool> logExtendAll(
"logs.writeSrcLocation.all", "Always print source code location for logs", Cvar::NONE, false );
Cvar::Cvar<bool> logExtendWarn(
"logs.writeSrcLocation.warn", "Print source code location for Warn logs", Cvar::NONE, false );
Cvar::Cvar<bool> logExtendNotice(
"logs.writeSrcLocation.notice", "Print source code location for Notice logs", Cvar::NONE, false );
Cvar::Cvar<bool> logExtendVerbose(
"logs.writeSrcLocation.verbose", "Print source code location for Verbose logs", Cvar::NONE, false );
Cvar::Cvar<bool> logExtendDebug(
"logs.writeSrcLocation.debug", "Print source code location for Debug logs", Cvar::NONE, false );

Logger::Logger(Str::StringRef name, std::string prefix, Level defaultLevel)
: filterLevel(new Cvar::Cvar<Log::Level>(
"logs.level." + name, "Log::Level - logs from '" + name + "' below the level specified are filtered", 0, defaultLevel)),
prefix(prefix), enableSuppression(true) {
enableSuppression(true)
{
if (!prefix.empty()) {
// TODO allow prefixes without a space, e.g. a color code
this->prefix = prefix + " ";
}
}

std::string Logger::Prefix(std::string message) const {
if (prefix.empty()) {
return message;
} else {
return prefix + " " + message;
std::string Logger::Prefix(Str::StringRef message) const {
return prefix + message;
}

static bool WantLocationInfo(Log::Level level) {
if (GET_LOG_CVAR(bool, "logs.writeSrcLocation.all", logExtendAll)) {
return true;
}
switch (level) {
case Log::Level::DEBUG:
return GET_LOG_CVAR(bool, "logs.writeSrcLocation.debug", logExtendDebug);
case Log::Level::VERBOSE:
return GET_LOG_CVAR(bool, "logs.writeSrcLocation.verbose", logExtendVerbose);
case Log::Level::NOTICE:
return GET_LOG_CVAR(bool, "logs.writeSrcLocation.notice", logExtendNotice);
case Log::Level::WARNING:
return GET_LOG_CVAR(bool, "logs.writeSrcLocation.warn", logExtendWarn);
}
ASSERT_UNREACHABLE();
}

void Logger::Dispatch(std::string message, Log::Level level, Str::StringRef format) {
void Logger::Dispatch(std::string message, Log::Level level, Str::StringRef format, const char* file, const char* function, int line) {
if (WantLocationInfo(level)) {
message = Str::Format("%s ^F(%s:%u, %s)", message, file, line, function);
}
if (enableSuppression) {
Log::DispatchWithSuppression(std::move(message), level, format);
} else {
Expand Down Expand Up @@ -136,15 +182,6 @@ namespace Log {
}
}

template <typename T>
static T GetCvarOrDie(Str::StringRef cvar) {
T value;
std::string valueString = Cvar::GetValue(cvar);
if (!Cvar::ParseCvarValue(valueString, value)) {
Sys::Error("Failed to deserialize cvar %s with value: %s", cvar, valueString);
}
return value;
}
namespace {
// Log-spam suppression: if more than MAX_OCCURRENCES log messages with the same format string
// are sent in less than INTERVAL_MS milliseconds, they will stop being printed.
Expand All @@ -166,9 +203,9 @@ namespace Log {
};
Result UpdateAndEvaluate(Str::StringRef messageFormat) {
std::lock_guard<std::mutex> lock(mutex);
int intervalMs = GetCvarOrDie<int>("logs.suppression.interval");
int maxOccurrences = GetCvarOrDie<int>("logs.suppression.count");
int bufferSize = GetCvarOrDie<int>("logs.suppression.bufferSize");
int intervalMs = GET_LOG_CVAR(int, "logs.suppression.interval", suppressionInterval);
int maxOccurrences = GET_LOG_CVAR(int, "logs.suppression.count", suppressionCount);
int bufferSize = GET_LOG_CVAR(int, "logs.suppression.bufferSize", suppressionBufSize);
buf.resize(bufferSize);
MessageStatistics* oldest = &buf[0];
int now = Sys::Milliseconds();
Expand Down Expand Up @@ -199,7 +236,7 @@ namespace Log {

void DispatchWithSuppression(std::string message, Log::Level level, Str::StringRef format) {
static LogSpamSuppressor suppressor;
if (level == Level::DEBUG || !GetCvarOrDie<bool>("logs.suppression.enabled")) {
if (level == Level::DEBUG || !GET_LOG_CVAR(bool, "logs.suppression.enabled", suppressionEnabled)) {
DispatchByLevel(std::move(message), level);
return;
}
Expand Down
68 changes: 20 additions & 48 deletions src/common/Log.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -51,12 +51,6 @@ namespace Log {
// The default filtering level
const Level DEFAULT_FILTER_LEVEL = Level::WARNING;

extern Cvar::Cvar<bool> logExtendAll;
extern Cvar::Cvar<bool> logExtendWarn;
extern Cvar::Cvar<bool> logExtendNotice;
extern Cvar::Cvar<bool> logExtendVerbose;
extern Cvar::Cvar<bool> logExtendDebug;

/*
* Loggers are used to group logs by subsystems and allow logs
* to be filtered by log level by subsystem. They are used like so
Expand Down Expand Up @@ -116,9 +110,10 @@ namespace Log {
Logger WithoutSuppression();

private:
void Dispatch(std::string message, Log::Level level, Str::StringRef format);
void Dispatch(std::string message, Log::Level level, Str::StringRef format,
const char* file, const char* function, int line);

std::string Prefix(std::string message) const;
std::string Prefix(Str::StringRef message) const;

// the cvar logs.level.<name>
std::shared_ptr<Cvar::Cvar<Level>> filterLevel;
Expand All @@ -131,22 +126,26 @@ namespace Log {

/*
* When debugging a function or before a logger is introduced for
* a module the following functions can be used for less typing.
* a module, the following signatures can be used for less typing.
* However it shouldn't stay in production code because it
* cannot be filtered and will clutter the console.
*
* These are not the real function declarations because macros are involved to get __LINE__ etc.
*/

#if 0
template<typename ... Args>
void Warn( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args );
void Warn( Str::StringRef format, Args&& ... args );

template<typename ... Args>
void Notice( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args );
void Notice( Str::StringRef format, Args&& ... args );

template<typename ... Args>
void Verbose( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args );
void Verbose( Str::StringRef format, Args&& ... args );

template<typename ... Args>
void Debug( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args );
void Debug( Str::StringRef format, Args&& ... args );
#endif

/*
* For messages which are not true log messages, but rather are produced by
Expand Down Expand Up @@ -199,62 +198,35 @@ namespace Log {

// Logger

inline std::string AddSrcLocation( const std::string& message,
const char* file, const char* function, const int line,
const bool extend ) {
if ( logExtendAll.Get() || extend ) {
return message + Str::Format( " ^F(%s:%u, %s)",
file, line, function );
}

return message;
}

template<typename ... Args>
void Logger::WarnExt( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args ) {
if ( filterLevel->Get() <= Level::WARNING ) {
this->Dispatch(
AddSrcLocation(
Prefix( Str::Format( format, std::forward<Args>( args ) ... ) ),
file, function, line, logExtendWarn.Get()
),
Level::WARNING, format );
this->Dispatch(Prefix(Str::Format(format, std::forward<Args>(args)...)),
Level::WARNING, format, file, function, line);
}
}

template<typename ... Args>
void Logger::NoticeExt( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args ) {
if ( filterLevel->Get() <= Level::NOTICE ) {
this->Dispatch(
AddSrcLocation(
Prefix( Str::Format( format, std::forward<Args>( args ) ... ) ),
file, function, line, logExtendNotice.Get()
),
Level::NOTICE, format );
this->Dispatch(Prefix(Str::Format(format, std::forward<Args>(args)...)),
Level::NOTICE, format, file, function, line);
}
}

template<typename ... Args>
void Logger::VerboseExt( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args ) {
if ( filterLevel->Get() <= Level::VERBOSE ) {
this->Dispatch(
AddSrcLocation(
Prefix( Str::Format( format, std::forward<Args>( args ) ... ) ),
file, function, line, logExtendVerbose.Get()
),
Level::VERBOSE, format );
this->Dispatch(Prefix(Str::Format(format, std::forward<Args>(args)...)),
Level::VERBOSE, format, file, function, line);
}
}

template<typename ... Args>
void Logger::DebugExt( const char* file, const char* function, const int line, Str::StringRef format, Args&& ... args ) {
if ( filterLevel->Get() <= Level::DEBUG ) {
this->Dispatch(
AddSrcLocation(
Prefix( Str::Format( format, std::forward<Args>( args ) ... ) ),
file, function, line, logExtendDebug.Get()
),
Level::DEBUG, format );
this->Dispatch(Prefix(Str::Format(format, std::forward<Args>(args)...)),
Level::DEBUG, format, file, function, line);
}
}

Expand Down
10 changes: 0 additions & 10 deletions src/engine/framework/LogSystem.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -34,16 +34,6 @@ SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
#include "LogSystem.h"

namespace Log {

static Cvar::Cvar<bool> suppressionEnabled(
"logs.suppression.enabled", "Whether to suppress log messages that are printed too many times", Cvar::NONE, true);
static Cvar::Range<Cvar::Cvar<int>> suppressionInterval(
"logs.suppression.interval", "Interval in milliseconds for detecting log spam", Cvar::NONE, 2000, 1, 1000000);
static Cvar::Range<Cvar::Cvar<int>> suppressionCount(
"logs.suppression.count", "Number of occurrences for a message to be considered log spam", Cvar::NONE, 10, 1, 1000000);
static Cvar::Range<Cvar::Cvar<int>> suppressionBufSize(
"logs.suppression.bufferSize", "How many distinct messages to track for log suppression", Cvar::NONE, 50, 1, 1000000);

static Target* targets[MAX_TARGET_ID];


Expand Down