merge bitcoin#15849: Thread names in logs and deadlock debug tools

Author: kwvg

configure.ac

@@ -865,8 +865,23 @@ AC_LINK_IFELSE([AC_LANG_SOURCE([
   }
   ])],
   [
-    AC_DEFINE(HAVE_THREAD_LOCAL,1,[Define if thread_local is supported.])
-    AC_MSG_RESULT(yes)
+   case $host in
+     *mingw*)
+        # mingw32's implementation of thread_local has also been shown to behave
+        # erroneously under concurrent usage; see:
+        # https://gist.github.com/jamesob/fe9a872051a88b2025b1aa37bfa98605
+        AC_MSG_RESULT(no)
+        ;;
+      *darwin*)
+        # TODO enable thread_local on later versions of Darwin where it is
+        # supported (per https://stackoverflow.com/a/29929949)
+        AC_MSG_RESULT(no)
+        ;;
+      *)
+        AC_DEFINE(HAVE_THREAD_LOCAL,1,[Define if thread_local is supported.])
+        AC_MSG_RESULT(yes)
+        ;;
+    esac
   ],
   [
     AC_MSG_RESULT(no)

doc/release-notes-15849.md

@@ -0,0 +1,6 @@
+Thread names in logs
+--------------------
+
+On platforms supporting `thread_local`, log lines can be prefixed with the name
+of the thread that caused the log. To enable this behavior, use
+`-logthreadnames=1`.

src/Makefile.am

@@ -265,6 +265,7 @@ BITCOIN_CORE_H = \
   utilmoneystr.h \
   utilstring.h \
   utiltime.h \
+  utilthreadnames.h \
   validation.h \
   validationinterface.h \
   versionbits.h \
@@ -591,6 +592,7 @@ libdash_util_a_SOURCES = \
   utilstrencodings.cpp \
   utiltime.cpp \
   utilstring.cpp \
+  utilthreadnames.cpp \
   $(BITCOIN_CORE_H)
 
 if GLIBC_BACK_COMPAT

src/Makefile.test.include

@@ -102,6 +102,7 @@ BITCOIN_TESTS =\
   test/streams_tests.cpp \
   test/subsidy_tests.cpp \
   test/sync_tests.cpp \
+  test/util_threadnames_tests.cpp \
   test/timedata_tests.cpp \
   test/torcontrol_tests.cpp \
   test/transaction_tests.cpp \

src/dashd.cpp

@@ -19,6 +19,7 @@
 #include <httpserver.h>
 #include <httprpc.h>
 #include <utilstrencodings.h>
+#include <utilthreadnames.h>
 #include <walletinitinterface.h>
 #include <stacktraces.h>
 
@@ -57,6 +58,8 @@ static bool AppInit(int argc, char* argv[])
 {
     bool fRet = false;
 
+    util::ThreadRename("init");
+
     //
     // Parameters
     //

src/httpserver.cpp

@@ -9,6 +9,7 @@
 #include <compat.h>
 #include <util.h>
 #include <utilstrencodings.h>
+#include <utilthreadnames.h>
 #include <netbase.h>
 #include <rpc/protocol.h> // For HTTP status codes
 #include <sync.h>
@@ -18,7 +19,7 @@
 #include <memory>
 #include <stdio.h>
 #include <stdlib.h>
-#include <string.h>
+#include <string>
 
 #include <sys/types.h>
 #include <sys/stat.h>
@@ -286,7 +287,7 @@ static void http_reject_request_cb(struct evhttp_request* req, void*)
 /** Event dispatcher thread */
 static bool ThreadHTTP(struct event_base* base, struct evhttp* http)
 {
-    RenameThread("dash-http");
+    util::ThreadRename("http");
     LogPrint(BCLog::HTTP, "Entering http event loop\n");
     event_base_dispatch(base);
     // Event loop will be interrupted by InterruptHTTPServer()
@@ -337,9 +338,9 @@ static bool HTTPBindAddresses(struct evhttp* http)
 }
 
 /** Simple wrapper to set thread name and run work queue */
-static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue)
+static void HTTPWorkQueueRun(WorkQueue<HTTPClosure>* queue, int worker_num)
 {
-    RenameThread("dash-httpworker");
+    util::ThreadRename(strprintf("httpworker.%i", worker_num));
     queue->Run();
 }
 
@@ -440,7 +441,7 @@ bool StartHTTPServer()
     threadHTTP = std::thread(ThreadHTTP, eventBase, eventHTTP);
 
     for (int i = 0; i < rpcThreads; i++) {
-        g_thread_http_workers.emplace_back(HTTPWorkQueueRun, workQueue);
+        g_thread_http_workers.emplace_back(HTTPWorkQueueRun, workQueue, i);
     }
     return true;
 }

src/init.cpp

@@ -39,6 +39,7 @@
 #include <script/standard.h>
 #include <script/sigcache.h>
 #include <scheduler.h>
+#include <utilthreadnames.h>
 #include <timedata.h>
 #include <txdb.h>
 #include <txmempool.h>
@@ -243,7 +244,7 @@ void PrepareShutdown()
     /// for example if the data directory was found to be locked.
     /// Be sure that anything that writes files or flushes caches only does this if the respective
     /// module was initialized.
-    RenameThread("dash-shutoff");
+    util::ThreadRename("shutoff");
     mempool.AddTransactionsUpdated(1);
     StopHTTPRPC();
     StopREST();
@@ -606,6 +607,7 @@ void SetupServerArgs()
     gArgs.AddArg("-llmqinstantsend=<quorum name>", strprintf("Override the default LLMQ type used for InstantSend on a devnet. Allows using InstantSend with smaller LLMQs. (default: %s)", devnetConsensus.llmqs.at(devnetConsensus.llmqTypeInstantSend).name), false, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-llmqtestparams=<size:threshold>", strprintf("Override the default LLMQ size for the LLMQ_TEST quorum (default: %u:%u)", regtestLLMQ.size, regtestLLMQ.threshold), false, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-logips", strprintf("Include IP addresses in debug output (default: %u)", DEFAULT_LOGIPS), false, OptionsCategory::DEBUG_TEST);
+    gArgs.AddArg("-logtimestamps", strprintf("Prepend debug output with timestamp (default: %u)", DEFAULT_LOGTIMESTAMPS), false, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-logthreadnames", strprintf("Add thread names to debug messages (default: %u)", DEFAULT_LOGTHREADNAMES), true, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-logtimemicros", strprintf("Add microsecond precision to debug timestamps (default: %u)", DEFAULT_LOGTIMEMICROS), true, OptionsCategory::DEBUG_TEST);
     gArgs.AddArg("-maxsigcachesize=<n>", strprintf("Limit sum of signature cache and script execution cache sizes to <n> MiB (default: %u)", DEFAULT_MAX_SIG_CACHE_SIZE), true, OptionsCategory::DEBUG_TEST);
@@ -774,7 +776,7 @@ static void CleanupBlockRevFiles()
 static void ThreadImport(std::vector<fs::path> vImportFiles)
 {
     const CChainParams& chainparams = Params();
-    RenameThread("dash-loadblk");
+    util::ThreadRename("loadblk");
     ScheduleBatchPriority();
 
     {
@@ -1092,7 +1094,7 @@ void InitLogging()
     g_logger->m_print_to_console = gArgs.GetBoolArg("-printtoconsole", !gArgs.GetBoolArg("-daemon", false));
     g_logger->m_log_timestamps = gArgs.GetBoolArg("-logtimestamps", DEFAULT_LOGTIMESTAMPS);
     g_logger->m_log_time_micros = gArgs.GetBoolArg("-logtimemicros", DEFAULT_LOGTIMEMICROS);
-    g_logger->m_log_thread_names = gArgs.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
+    g_logger->m_log_threadnames = gArgs.GetBoolArg("-logthreadnames", DEFAULT_LOGTHREADNAMES);
 
     fLogIPs = gArgs.GetBoolArg("-logips", DEFAULT_LOGIPS);
 
@@ -1731,7 +1733,7 @@ bool AppInitMain()
     LogPrintf("Using %u threads for script verification\n", nScriptCheckThreads);
     if (nScriptCheckThreads) {
         for (int i=0; i<nScriptCheckThreads-1; i++)
-            threadGroup.create_thread(&ThreadScriptCheck);
+            threadGroup.create_thread([i]() { return ThreadScriptCheck(i); });
     }
 
     std::vector<std::string> vSporkAddresses;

src/logging.cpp

@@ -6,6 +6,9 @@
 #include <logging.h>
 #include <util.h>
 #include <utiltime.h>
+#include <utilthreadnames.h>
+
+#include <mutex>
 
 const char * const DEFAULT_DEBUGLOGFILE = "debug.log";
 
@@ -219,7 +222,7 @@ std::string ListActiveLogCategoriesString()
     return ret;
 }
 
-std::string BCLog::Logger::LogTimestampStr(const std::string &str)
+std::string BCLog::Logger::LogTimestampStr(const std::string& str)
 {
     std::string strStamped;
 
@@ -244,59 +247,44 @@ std::string BCLog::Logger::LogTimestampStr(const std::string &str)
     return strStamped;
 }
 
-std::string BCLog::Logger::LogThreadNameStr(const std::string &str)
+void BCLog::Logger::LogPrintStr(const std::string &str)
 {
-    std::string strThreadLogged;
-
-    if (!m_log_thread_names)
-        return str;
+    std::string str_prefixed = str;
 
-    std::string strThreadName = GetThreadName();
-
-    if (m_started_new_line)
-        strThreadLogged = strprintf("%16s | %s", strThreadName.c_str(), str.c_str());
-    else
-        strThreadLogged = str;
+    if (m_log_threadnames && m_started_new_line) {
+        str_prefixed.insert(0, "[" + util::ThreadGetInternalName() + "] ");
+    }
 
-    return strThreadLogged;
-}
+    str_prefixed = LogTimestampStr(str_prefixed);
 
-void BCLog::Logger::LogPrintStr(const std::string& str)
-{
-    StdLockGuard scoped_lock(m_cs);
-    std::string strThreadLogged = LogThreadNameStr(str);
-    std::string strTimestamped = LogTimestampStr(strThreadLogged);
-
-    if (!str.empty() && str[str.size()-1] == '\n')
-        m_started_new_line = true;
-    else
-        m_started_new_line = false;
-
-    if (m_buffering) {
-        // buffer if we haven't started logging yet
-        m_msgs_before_open.push_back(strTimestamped);
-        return;
-    }
+    m_started_new_line = !str.empty() && str[str.size()-1] == '\n';
 
     if (m_print_to_console) {
         // print to console
-        fwrite(strTimestamped.data(), 1, strTimestamped.size(), stdout);
+        fwrite(str_prefixed.data(), 1, str_prefixed.size(), stdout);
         fflush(stdout);
     }
     if (m_print_to_file) {
-        assert(m_fileout != nullptr);
-
-        // reopen the log file, if requested
-        if (m_reopen_file) {
-            m_reopen_file = false;
-            FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
-            if (new_fileout) {
-                setbuf(new_fileout, nullptr); // unbuffered
-                fclose(m_fileout);
-                m_fileout = new_fileout;
+        std::lock_guard<std::mutex> scoped_lock(m_cs);
+
+        // buffer if we haven't opened the log yet
+        if (m_fileout == nullptr) {
+            m_msgs_before_open.push_back(str_prefixed);
+        }
+        else
+        {
+            // reopen the log file, if requested
+            if (m_reopen_file) {
+                m_reopen_file = false;
+                FILE* new_fileout = fsbridge::fopen(m_file_path, "a");
+                if (new_fileout) {
+                    setbuf(new_fileout, nullptr); // unbuffered
+                    fclose(m_fileout);
+                    m_fileout = new_fileout;
+                }
             }
+            FileWriteStr(str_prefixed, m_fileout);
         }
-        FileWriteStr(strTimestamped, m_fileout);
     }
 }
 

src/logging.h

@@ -108,7 +108,7 @@ namespace BCLog {
 
         bool m_log_timestamps = DEFAULT_LOGTIMESTAMPS;
         bool m_log_time_micros = DEFAULT_LOGTIMEMICROS;
-        bool m_log_thread_names = DEFAULT_LOGTHREADNAMES;
+        bool m_log_threadnames = DEFAULT_LOGTHREADNAMES;
 
         fs::path m_file_path;
         std::atomic<bool> m_reopen_file{false};

src/qt/dash.cpp

@@ -257,6 +257,7 @@ void BitcoinCore::initialize()
     try
     {
         qDebug() << __func__ << ": Running initialization in thread";
+        util::ThreadRename("qt-init");
         bool rv = m_node.appInitMain();
         Q_EMIT initializeResult(rv);
     } catch (...) {
@@ -577,6 +578,7 @@ int main(int argc, char *argv[])
     RegisterPrettySignalHandlers();
 
     SetupEnvironment();
+    util::ThreadRename("main");
 
     std::unique_ptr<interfaces::Node> node = interfaces::MakeNode();
 

src/sync.cpp

@@ -3,9 +3,11 @@
 // file COPYING or http://www.opensource.org/licenses/mit-license.php.
 
 #include <sync.h>
+#include <tinyformat.h>
 
 #include <logging.h>
 #include <utilstrencodings.h>
+#include <utilthreadnames.h>
 
 #include <stdio.h>
 
@@ -36,23 +38,30 @@ void PrintLockContention(const char* pszName, const char* pszFile, int nLine)
 //
 
 struct CLockLocation {
-    CLockLocation(const char* pszName, const char* pszFile, int nLine, bool fTryIn)
-    {
-        mutexName = pszName;
-        sourceFile = pszFile;
-        sourceLine = nLine;
-        fTry = fTryIn;
-    }
+    CLockLocation(
+        const char* pszName,
+        const char* pszFile,
+        int nLine,
+        bool fTryIn,
+        const std::string& thread_name)
+        : fTry(fTryIn),
+          mutexName(pszName),
+          sourceFile(pszFile),
+          m_thread_name(thread_name),
+          sourceLine(nLine) {}
 
     std::string ToString() const
     {
-        return mutexName + "  " + sourceFile + ":" + itostr(sourceLine) + (fTry ? " (TRY)" : "");
+        return tfm::format(
+            "%s %s:%s%s (in thread %s)",
+            mutexName, sourceFile, itostr(sourceLine), (fTry ? " (TRY)" : ""), m_thread_name);
     }
 
 private:
     bool fTry;
     std::string mutexName;
     std::string sourceFile;
+    const std::string& m_thread_name;
     int sourceLine;
 };
 
@@ -124,7 +133,7 @@ static void push_lock(void* c, const CLockLocation& locklocation)
         std::pair<void*, void*> p1 = std::make_pair(i.first, c);
         if (lockdata.lockorders.count(p1))
             continue;
-        lockdata.lockorders[p1] = g_lockstack;
+        lockdata.lockorders.emplace(p1, g_lockstack);
 
         std::pair<void*, void*> p2 = std::make_pair(c, i.first);
         lockdata.invlockorders.insert(p2);
@@ -140,7 +149,7 @@ static void pop_lock()
 
 void EnterCritical(const char* pszName, const char* pszFile, int nLine, void* cs, bool fTry)
 {
-    push_lock(cs, CLockLocation(pszName, pszFile, nLine, fTry));
+    push_lock(cs, CLockLocation(pszName, pszFile, nLine, fTry, util::ThreadGetInternalName()));
 }
 
 void LeaveCritical()

src/test/test_dash.cpp

@@ -128,7 +128,7 @@ TestingSetup::TestingSetup(const std::string& chainName) : BasicTestingSetup(cha
         }
         nScriptCheckThreads = 3;
         for (int i=0; i < nScriptCheckThreads-1; i++)
-            threadGroup.create_thread(&ThreadScriptCheck);
+            threadGroup.create_thread([i]() { return ThreadScriptCheck(i); });
         peerLogic.reset(new PeerLogicValidation(connman, scheduler, /*enable_bip61=*/true));
 }