Skip to content
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

Jump to bottom

Thread-safety improvements for debug() #3309

Merged
merged 2 commits into from
Jul 17, 2023
Merged

Thread-safety improvements for debug() #3309

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
d5cd9de
Replace WZ_DECL_THREAD with thread_local
past-due Jul 16, 2023
51ed792
debug.cpp: Thread-safety improvements for debug()
past-due Jul 16, 2023
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
72 changes: 41 additions & 31 deletions lib/framework/debug.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -35,6 +35,7 @@
#include <map>
#include <string>
#include <regex>
#include <array>

#if defined(WZ_OS_LINUX) && defined(__GLIBC__)
#include <execinfo.h> // Nonfatal runtime backtraces.
Expand Down Expand Up @@ -115,11 +116,11 @@ static const char *code_part_names[] =
"last"
};

static char inputBuffer[2][MAX_LEN_LOG_LINE];
static bool useInputBuffer1 = false;
static bool debug_flush_stderr = false;

static std::map<std::string, int> warning_list; // only used for LOG_WARNING
static std::mutex warning_list_mutex;

/**
* Convert code_part names to enum. Case insensitive.
Expand Down Expand Up @@ -349,8 +350,6 @@ void debug_init()
enabled_debug[LOG_INFO] = true;
enabled_debug[LOG_FATAL] = true;
enabled_debug[LOG_POPUP] = true;
inputBuffer[0][0] = '\0';
inputBuffer[1][0] = '\0';
#ifdef DEBUG
enabled_debug[LOG_WARNING] = true;
#endif
Expand All @@ -371,7 +370,10 @@ void debug_exit()
free(curCallback);
curCallback = tmpCallback;
}
warning_list.clear();
{
std::lock_guard<std::mutex> guard(warning_list_mutex);
warning_list.clear();
}
callbackRegistry = nullptr;
}

Expand Down Expand Up @@ -458,8 +460,8 @@ void _realObjTrace(int id, const char *function, const char *str, ...)
// Thread local to prevent a race condition on read and write to this buffer if multiple
// threads log errors. This means we will not be reporting any errors to console from threads
// other than main. If we want to fix this, make sure accesses are protected by a mutex.
static WZ_DECL_THREAD char errorStore[512];
static WZ_DECL_THREAD bool errorWaiting = false;
static thread_local char errorStore[512];
static thread_local bool errorWaiting = false;
const char *debugLastError()
{
if (errorWaiting)
Expand All @@ -475,23 +477,28 @@ const char *debugLastError()

void _debug(int line, code_part part, const char *function, const char *str, ...)
{
va_list ap;
static char outputBuffer[MAX_LEN_LOG_LINE];
static unsigned int repeated = 0; /* times current message repeated */
static unsigned int next = 2; /* next total to print update */
static unsigned int prev = 0; /* total on last update */
thread_local std::vector<char> outputBuffer(MAX_LEN_LOG_LINE, 0);
thread_local std::array<std::vector<char>, 2> inputBuffer = {std::vector<char>(MAX_LEN_LOG_LINE, 0), std::vector<char>(MAX_LEN_LOG_LINE, 0)};
thread_local unsigned int repeated = 0; /* times current message repeated */
thread_local unsigned int next = 2; /* next total to print update */
thread_local unsigned int prev = 0; /* total on last update */

va_list ap;
va_start(ap, str);
vssprintf(outputBuffer, str, ap);
vsnprintf(outputBuffer.data(), outputBuffer.size(), str, ap);
va_end(ap);

if (part == LOG_WARNING)
{
std::pair<std::map<std::string, int>::iterator, bool> ret;
ret = warning_list.insert(std::pair<std::string, int>(std::string(function) + "-" + std::string(outputBuffer), line));
if (ret.second)
bool addedNew = false;
{
ssprintf(inputBuffer[useInputBuffer1 ? 1 : 0], "[%s:%d] %s (**Further warnings of this type are suppressed.)", function, line, outputBuffer);
std::lock_guard<std::mutex> guard(warning_list_mutex);
addedNew = warning_list.insert(std::pair<std::string, int>(std::string(function) + "-" + std::string(outputBuffer.data()), line)).second;
}
if (addedNew)
{
auto& currInputBuffer = inputBuffer[useInputBuffer1 ? 1 : 0];
snprintf(currInputBuffer.data(), currInputBuffer.size(), "[%s:%d] %s (**Further warnings of this type are suppressed.)", function, line, outputBuffer.data());
}
else
{
Expand All @@ -500,24 +507,25 @@ void _debug(int line, code_part part, const char *function, const char *str, ...
}
else
{
ssprintf(inputBuffer[useInputBuffer1 ? 1 : 0], "[%s:%d] %s", function, line, outputBuffer);
auto& currInputBuffer = inputBuffer[useInputBuffer1 ? 1 : 0];
snprintf(currInputBuffer.data(), currInputBuffer.size(), "[%s:%d] %s", function, line, outputBuffer.data());
}

if (sstrcmp(inputBuffer[0], inputBuffer[1]) == 0)
if (strncmp(inputBuffer[0].data(), inputBuffer[1].data(), std::min(inputBuffer[0].size(), inputBuffer[1].size())) == 0)
{
// Received again the same line
repeated++;
if (repeated == next)
{
if (repeated > 2)
{
ssprintf(outputBuffer, "last message repeated %u times (total %u repeats)", repeated - prev, repeated);
snprintf(outputBuffer.data(), outputBuffer.size(), "last message repeated %u times (total %u repeats)", repeated - prev, repeated);
}
else
{
ssprintf(outputBuffer, "last message repeated %u times", repeated - prev);
snprintf(outputBuffer.data(), outputBuffer.size(), "last message repeated %u times", repeated - prev);
}
printToDebugCallbacks(outputBuffer, part);
printToDebugCallbacks(outputBuffer.data(), part);
prev = repeated;
next *= 2;
}
Expand All @@ -530,13 +538,13 @@ void _debug(int line, code_part part, const char *function, const char *str, ...
/* just repeat the previous message when only one repeat occurred */
if (repeated > 2)
{
ssprintf(outputBuffer, "last message repeated %u times (total %u repeats)", repeated - prev, repeated);
snprintf(outputBuffer.data(), outputBuffer.size(), "last message repeated %u times (total %u repeats)", repeated - prev, repeated);
}
else
{
ssprintf(outputBuffer, "last message repeated %u times", repeated - prev);
snprintf(outputBuffer.data(), outputBuffer.size(), "last message repeated %u times", repeated - prev);
}
printToDebugCallbacks(outputBuffer, part);
printToDebugCallbacks(outputBuffer.data(), part);
}
repeated = 0;
next = 2;
Expand All @@ -553,15 +561,17 @@ void _debug(int line, code_part part, const char *function, const char *str, ...
timeinfo = getLocalTime(rawtime);
strftime(ourtime, 15, "%H:%M:%S", &timeinfo);

auto& currInputBuffer = inputBuffer[useInputBuffer1 ? 1 : 0];

// Assemble the outputBuffer:
ssprintf(outputBuffer, "%-8s|%s: %s", code_part_names[part], ourtime, useInputBuffer1 ? inputBuffer[1] : inputBuffer[0]);
snprintf(outputBuffer.data(), outputBuffer.size(), "%-8s|%s: %s", code_part_names[part], ourtime, currInputBuffer.data());

printToDebugCallbacks(outputBuffer, part);
printToDebugCallbacks(outputBuffer.data(), part);

if (part == LOG_ERROR)
{
// used to signal user that there was a error condition, and to check the logs.
sstrcpy(errorStore, useInputBuffer1 ? inputBuffer[1] : inputBuffer[0]);
sstrcpy(errorStore, currInputBuffer.data());
errorWaiting = true;
}

Expand All @@ -575,11 +585,11 @@ void _debug(int line, code_part part, const char *function, const char *str, ...
#if defined(WZ_OS_WIN)
char wbuf[MAX_LEN_LOG_LINE+512];
ssprintf(wbuf, "%s\n\nPlease check the file (%s) in your configuration directory for more details. \
\nDo not forget to upload the %s file, WZdebuginfo.txt and the warzone2100.rpt files in your bug reports at https://github.com/Warzone2100/warzone2100/issues/new!", useInputBuffer1 ? inputBuffer[1] : inputBuffer[0], WZ_DBGFile, WZ_DBGFile);
\nDo not forget to upload the %s file, WZdebuginfo.txt and the warzone2100.rpt files in your bug reports at https://github.com/Warzone2100/warzone2100/issues/new!", currInputBuffer.data(), WZ_DBGFile, WZ_DBGFile);
wzDisplayDialog(Dialog_Error, "Warzone has terminated unexpectedly", wbuf);
#elif defined(WZ_OS_MAC)
char wbuf[MAX_LEN_LOG_LINE+128];
ssprintf(wbuf, "%s\n\nPlease check your logs and attach them along with a bug report. Thanks!", useInputBuffer1 ? inputBuffer[1] : inputBuffer[0]);
ssprintf(wbuf, "%s\n\nPlease check your logs and attach them along with a bug report. Thanks!", currInputBuffer.data());
int clickedIndex = \
cocoaShowAlert("Warzone has quit unexpectedly.",
wbuf,
Expand Down Expand Up @@ -610,7 +620,7 @@ void _debug(int line, code_part part, const char *function, const char *str, ...
cocoaOpenUserCrashReportFolder();
}
#else
const char *popupBuf = useInputBuffer1 ? inputBuffer[1] : inputBuffer[0];
const char *popupBuf = currInputBuffer.data();
wzDisplayDialog(Dialog_Error, "Warzone has terminated unexpectedly", popupBuf);
#endif
}
Expand All @@ -619,7 +629,7 @@ void _debug(int line, code_part part, const char *function, const char *str, ...
// This is a popup dialog used for times when the error isn't fatal, but we still need to notify user what is going on.
if (part == LOG_POPUP)
{
wzDisplayDialog(Dialog_Information, "Warzone has detected a problem.", inputBuffer[useInputBuffer1 ? 1 : 0]);
wzDisplayDialog(Dialog_Information, "Warzone has detected a problem.", currInputBuffer.data());
}

}
Expand Down
13 changes: 0 additions & 13 deletions lib/framework/wzglobal.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -520,19 +520,6 @@
#endif


/*! \def WZ_DECL_THREAD
* Declares a variable to be local to the running thread, and not shared between threads.
*/
#if defined(__MACOSX__)
# define WZ_DECL_THREAD // nothing, MacOSX does not yet support this
#elif defined(WZ_CC_GNU) || defined(WZ_CC_INTEL)
# define WZ_DECL_THREAD __thread
#elif defined(WZ_CC_MSVC)
# define WZ_DECL_THREAD __declspec(thread)
#else
# error "Thread local storage attribute required"
#endif

/* ---- Platform specific setup ---- */

#if defined(WZ_OS_WIN)
Expand Down