Mercurial > hg > orthanc

changeset 5450:9ffd6d18daf3 pg-transactions

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
log lines now contain the thread name
author Alain Mazy <am@osimis.io>
date Tue, 05 Dec 2023 16:26:35 +0100
parents 29858f424fc7
children b19bfb939323 099d45f49fe1
files NEWS OrthancFramework/Sources/DicomNetworking/DicomServer.cpp OrthancFramework/Sources/HttpServer/HttpServer.cpp OrthancFramework/Sources/JobsEngine/JobsEngine.cpp OrthancFramework/Sources/Logging.cpp OrthancFramework/Sources/Logging.h OrthancFramework/Sources/MultiThreading/RunnableWorkersPool.cpp OrthancFramework/Sources/MultiThreading/RunnableWorkersPool.h OrthancServer/Sources/LuaScripting.cpp OrthancServer/Sources/OrthancWebDav.cpp OrthancServer/Sources/ServerContext.cpp OrthancServer/Sources/ServerIndex.cpp OrthancServer/Sources/ServerJobs/ArchiveJob.cpp OrthancServer/Sources/ServerJobs/ThreadedSetOfInstancesJob.cpp OrthancServer/Sources/main.cpp TODO
diffstat 16 files changed, 127 insertions(+), 14 deletions(-) [+]
line wrap: on
line diff
--- a/NEWS	Wed Nov 29 09:28:21 2023 +0100
+++ b/NEWS	Tue Dec 05 16:26:35 2023 +0100
@@ -27,6 +27,11 @@
     This notably greatly improve loading time of large DICOM 
     files through WADO-RS e.g in StoneViewer when working on large bandwidth networks.
   - When "HttpCompressionEnabled" is true, content < 2KB are never compressed.
+* Logs:
+  - Each line of log now contains the name of the thread that is logging the message.
+    A new '--logs-no-thread' command line option can be used to get back to the previous behavior to
+    keep backward compatibility.
+
 
 Bug Fixes
 ---------
--- a/OrthancFramework/Sources/DicomNetworking/DicomServer.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/DicomNetworking/DicomServer.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -61,6 +61,7 @@
                                  unsigned int maximumPduLength,
                                  bool useDicomTls)
   {
+    Logging::SetCurrentThreadName("DICOM-SERVER");
     CLOG(INFO, DICOM) << "DICOM server started";
 
     while (server->continue_)
@@ -429,7 +430,7 @@
 
     CLOG(INFO, DICOM) << "The embedded DICOM server will use " << threadsCount_ << " threads";
 
-    pimpl_->workers_.reset(new RunnableWorkersPool(threadsCount_));
+    pimpl_->workers_.reset(new RunnableWorkersPool(threadsCount_, "DICOM-"));
     pimpl_->thread_ = boost::thread(ServerThread, this, maximumPduLength_, useDicomTls_);
   }
 
--- a/OrthancFramework/Sources/HttpServer/HttpServer.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/HttpServer/HttpServer.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -1533,6 +1533,7 @@
     }
   }
 
+  static uint16_t threadCounter = 0;
 
 #if MONGOOSE_USE_CALLBACKS == 0
   static void* Callback(enum mg_event event,
@@ -1557,6 +1558,11 @@
   {
     const struct mg_request_info *request = mg_get_request_info(connection);
 
+    if (!Logging::HasCurrentThreadName())
+    {
+      Logging::SetCurrentThreadName(std::string("HTTP-") + boost::lexical_cast<std::string>(threadCounter++));
+    }
+
     ProtectedCallback(connection, request);
 
     return 1;  // Do not let Mongoose handle the request by itself
@@ -1643,6 +1649,9 @@
 
   void HttpServer::Start()
   {
+    // reset thread counter used to generate HTTP thread names.
+    threadCounter = 0;
+
 #if ORTHANC_ENABLE_MONGOOSE == 1
     CLOG(INFO, HTTP) << "Starting embedded Web server using Mongoose";
 #elif ORTHANC_ENABLE_CIVETWEB == 1
--- a/OrthancFramework/Sources/JobsEngine/JobsEngine.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/JobsEngine/JobsEngine.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -122,7 +122,7 @@
                           size_t workerIndex)
   {
     assert(engine != NULL);
-
+    Logging::SetCurrentThreadName(std::string("JOBS-WORKER-") + boost::lexical_cast<std::string>(workerIndex));
     CLOG(INFO, JOBS) << "Worker thread " << workerIndex << " has started";
 
     while (engine->IsRunning())
--- a/OrthancFramework/Sources/Logging.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/Logging.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -27,6 +27,7 @@
 #include "OrthancException.h"
 
 #include <stdint.h>
+#include <boost/thread/thread.hpp>
 
 
 /*********************************************************
@@ -534,16 +535,24 @@
 
 
 
-static std::unique_ptr<LoggingStreamsContext> loggingStreamsContext_;
-static boost::mutex                           loggingStreamsMutex_;
-static Orthanc::Logging::NullStream           nullStream_;
-static OrthancPluginContext*                  pluginContext_ = NULL;
+static std::unique_ptr<LoggingStreamsContext>   loggingStreamsContext_;
+static boost::mutex                             loggingStreamsMutex_;
+static Orthanc::Logging::NullStream             nullStream_;
+static OrthancPluginContext*                    pluginContext_ = NULL;
+static std::map<boost::thread::id, std::string> threadNames_;
+static bool                                     enableThreadNames_ = true;
+
 
 
 namespace Orthanc
 {
   namespace Logging
   {
+    void EnableThreadNames(bool enabled)
+    {
+      enableThreadNames_ = enabled;
+    }
+
     static void GetLogPath(boost::filesystem::path& log,
                            boost::filesystem::path& link,
                            const std::string& suffix,
@@ -612,7 +621,45 @@
         throw OrthancException(ErrorCode_CannotWriteFile);
       }
     }
-    
+
+    void SetCurrentThreadNameInternal(const boost::thread::id& id, const std::string& name)
+    {
+      // this method assumes that the loggingStreamsMutex is already locked
+      if (name.size() > 16)
+      {
+        throw OrthancException(ErrorCode_InternalError, std::string("Thread name can not exceed 16 characters: ") + name);
+      }
+
+      threadNames_[id] = name;
+    }
+
+    void SetCurrentThreadName(const std::string& name)
+    {
+      boost::mutex::scoped_lock lock(loggingStreamsMutex_);
+      SetCurrentThreadNameInternal(boost::this_thread::get_id(), name);
+    }
+
+    bool HasCurrentThreadName()
+    {
+      boost::thread::id threadId = boost::this_thread::get_id();
+
+      boost::mutex::scoped_lock lock(loggingStreamsMutex_);
+      return threadNames_.find(threadId) != threadNames_.end();
+    }
+
+    static std::string GetCurrentThreadName()
+    {
+      // this method assumes that the loggingStreamsMutex is already locked
+      boost::thread::id threadId = boost::this_thread::get_id();
+
+      if (threadNames_.find(threadId) == threadNames_.end())
+      {
+        // set the threadId as the thread name
+        SetCurrentThreadNameInternal(threadId, boost::lexical_cast<std::string>(threadId));
+      }
+
+      return threadNames_[threadId];
+    }    
 
     static void GetLinePrefix(std::string& prefix,
                               LogLevel level,
@@ -679,7 +726,17 @@
               static_cast<int>(duration.seconds()),
               static_cast<int>(duration.fractional_seconds()));
 
-      prefix = (std::string(date) + path.filename().string() + ":" +
+      char threadName[20]; // thread names are limited to 16 char + a space
+      if (enableThreadNames_)
+      {
+        sprintf(threadName, "%16s ", GetCurrentThreadName().c_str());
+      }
+      else
+      {
+        threadName[0] = '\0';
+      }
+
+      prefix = (std::string(date) + threadName + path.filename().string() + ":" +
                 boost::lexical_cast<std::string>(line) + "] ");
 
       if (level != LogLevel_ERROR &&
--- a/OrthancFramework/Sources/Logging.h	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/Logging.h	Tue Dec 05 16:26:35 2023 +0100
@@ -86,6 +86,12 @@
 
     ORTHANC_PUBLIC void Flush();
 
+    ORTHANC_PUBLIC void SetCurrentThreadName(const std::string& name);
+
+    ORTHANC_PUBLIC bool HasCurrentThreadName();
+
+    ORTHANC_PUBLIC void EnableThreadNames(bool enabled);
+
     ORTHANC_PUBLIC void EnableInfoLevel(bool enabled);
 
     ORTHANC_PUBLIC void EnableTraceLevel(bool enabled);
--- a/OrthancFramework/Sources/MultiThreading/RunnableWorkersPool.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/MultiThreading/RunnableWorkersPool.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -39,9 +39,12 @@
       const bool&           continue_;
       SharedMessageQueue&   queue_;
       boost::thread         thread_;
+      std::string           name_;
  
       static void WorkerThread(Worker* that)
       {
+        Logging::SetCurrentThreadName(that->name_);
+
         while (that->continue_)
         {
           try
@@ -81,9 +84,11 @@
 
     public:
       Worker(const bool& globalContinue,
-             SharedMessageQueue& queue) : 
+             SharedMessageQueue& queue,
+             const std::string& name) : 
         continue_(globalContinue),
-        queue_(queue)
+        queue_(queue),
+        name_(name)
       {
         thread_ = boost::thread(WorkerThread, this);
       }
@@ -105,7 +110,7 @@
 
 
 
-  RunnableWorkersPool::RunnableWorkersPool(size_t countWorkers) : pimpl_(new PImpl)
+  RunnableWorkersPool::RunnableWorkersPool(size_t countWorkers, const std::string& name) : pimpl_(new PImpl)
   {
     pimpl_->continue_ = true;
 
@@ -118,7 +123,8 @@
 
     for (size_t i = 0; i < countWorkers; i++)
     {
-      pimpl_->workers_[i] = new PImpl::Worker(pimpl_->continue_, pimpl_->queue_);
+      std::string workerName = name + boost::lexical_cast<std::string>(i);
+      pimpl_->workers_[i] = new PImpl::Worker(pimpl_->continue_, pimpl_->queue_, workerName);
     }
   }
 
--- a/OrthancFramework/Sources/MultiThreading/RunnableWorkersPool.h	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancFramework/Sources/MultiThreading/RunnableWorkersPool.h	Tue Dec 05 16:26:35 2023 +0100
@@ -38,7 +38,7 @@
     void Stop();
 
   public:
-    explicit RunnableWorkersPool(size_t countWorkers);
+    explicit RunnableWorkersPool(size_t countWorkers, const std::string& name);
 
     ~RunnableWorkersPool();
 
--- a/OrthancServer/Sources/LuaScripting.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/LuaScripting.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -776,6 +776,8 @@
 
   void LuaScripting::HeartBeatThread(LuaScripting* that)
   {
+    Logging::SetCurrentThreadName("LUA-HEARTBEAT");
+
     static const unsigned int GRANULARITY = 100;  // In milliseconds
     
     const boost::posix_time::time_duration PERIODICITY =
@@ -812,6 +814,8 @@
 
   void LuaScripting::EventThread(LuaScripting* that)
   {
+    Logging::SetCurrentThreadName("LUA-EVENTS");
+
     for (;;)
     {
       std::unique_ptr<IDynamicObject> event(that->pendingEvents_.Dequeue(100));
--- a/OrthancServer/Sources/OrthancWebDav.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/OrthancWebDav.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -1221,6 +1221,8 @@
 
   void OrthancWebDav::UploadWorker(OrthancWebDav* that)
   {
+    Logging::SetCurrentThreadName("WEBDAV-UPLOAD");
+
     assert(that != NULL);
 
     boost::posix_time::ptime lastModification = GetNow();
--- a/OrthancServer/Sources/ServerContext.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/ServerContext.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -112,6 +112,8 @@
   void ServerContext::MemoryTrimmingThread(ServerContext* that,
                                            unsigned int intervalInSeconds)
   {
+    Logging::SetCurrentThreadName("MEMORY-TRIM");
+
     boost::posix_time::ptime lastExecution = boost::posix_time::second_clock::universal_time();
 
     // This thread is started only if malloc_trim is defined
@@ -140,6 +142,8 @@
   void ServerContext::ChangeThread(ServerContext* that,
                                    unsigned int sleepDelay)
   {
+    Logging::SetCurrentThreadName("CHANGES");
+
     while (!that->done_)
     {
       std::unique_ptr<IDynamicObject> obj(that->pendingChanges_.Dequeue(sleepDelay));
@@ -182,6 +186,8 @@
   void ServerContext::JobEventsThread(ServerContext* that,
                                       unsigned int sleepDelay)
   {
+    Logging::SetCurrentThreadName("JOB-EVENTS");
+
     while (!that->done_)
     {
       std::unique_ptr<IDynamicObject> obj(that->pendingJobEvents_.Dequeue(sleepDelay));
@@ -224,6 +230,8 @@
   void ServerContext::SaveJobsThread(ServerContext* that,
                                      unsigned int sleepDelay)
   {
+    Logging::SetCurrentThreadName("SAVE-JOBS");
+
     static const boost::posix_time::time_duration PERIODICITY =
       boost::posix_time::seconds(10);
     
--- a/OrthancServer/Sources/ServerIndex.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/ServerIndex.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -276,6 +276,8 @@
   void ServerIndex::FlushThread(ServerIndex* that,
                                 unsigned int threadSleepGranularityMilliseconds)
   {
+    Logging::SetCurrentThreadName("DB-FLUSH");
+
     // By default, wait for 10 seconds before flushing
     static const unsigned int SLEEP_SECONDS = 10;
 
@@ -429,6 +431,8 @@
   void ServerIndex::UnstableResourcesMonitorThread(ServerIndex* that,
                                                    unsigned int threadSleepGranularityMilliseconds)
   {
+    Logging::SetCurrentThreadName("UNSTABLE-MON");
+
     int stableAge;
     
     {
--- a/OrthancServer/Sources/ServerJobs/ArchiveJob.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/ServerJobs/ArchiveJob.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -223,6 +223,9 @@
 
     static void PreloaderWorkerThread(ThreadedInstanceLoader* that)
     {
+      static uint16_t threadCounter = 0;
+      Logging::SetCurrentThreadName(std::string("ARCH-LOAD-") + boost::lexical_cast<std::string>(threadCounter++));
+
       while (true)
       {
         std::unique_ptr<InstanceId> instanceId(dynamic_cast<InstanceId*>(that->instancesToPreload_.Dequeue(0)));
--- a/OrthancServer/Sources/ServerJobs/ThreadedSetOfInstancesJob.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/ServerJobs/ThreadedSetOfInstancesJob.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -243,6 +243,9 @@
 
   void ThreadedSetOfInstancesJob::InstanceWorkerThread(ThreadedSetOfInstancesJob* that)
   {
+    static uint8_t threadCounter = 0;
+    Logging::SetCurrentThreadName(std::string("JOB-INS-WORK-") + boost::lexical_cast<std::string>(threadCounter++));
+
     while (true)
     {
       std::unique_ptr<SingleValueObject<std::string> > instanceId(dynamic_cast<SingleValueObject<std::string>*>(that->instancesToProcessQueue_.Dequeue(0)));
--- a/OrthancServer/Sources/main.cpp	Wed Nov 29 09:28:21 2023 +0100
+++ b/OrthancServer/Sources/main.cpp	Tue Dec 05 16:26:35 2023 +0100
@@ -1780,6 +1780,7 @@
 int main(int argc, char* argv[]) 
 {
   Logging::Initialize();
+  Logging::SetCurrentThreadName("MAIN");
   SetGlobalVerbosity(Verbosity_Default);
 
   bool upgradeDatabase = false;
@@ -1834,6 +1835,10 @@
     {
       SetGlobalVerbosity(Verbosity_Verbose);
     }
+    else if (argument == "--logs-no-thread")
+    {
+      Logging::EnableThreadNames(false);
+    }
     else if (argument == "--trace")
     {
       SetGlobalVerbosity(Verbosity_Trace);
--- a/TODO	Wed Nov 29 09:28:21 2023 +0100
+++ b/TODO	Tue Dec 05 16:26:35 2023 +0100
@@ -24,7 +24,7 @@
   https://orthanc.uclouvain.be/hg/orthanc/file/Orthanc-1.9.3/OrthancFramework/Sources/OrthancFramework.cpp#l88
 * Toolbox::ComputeMD5() fails on files larger than 4GB
 * Add an option to run Orthanc in read-only mode both for DICOM and for Rest API.
-* Logging: add some information like Thread-Id/job-id to contextualize the logs.
+* Logging: add more specific information to contextualize the logs.
   For a DICOM Transfer, that would be nice to include the modality in the context + a study identifier or a job id.
 * (1) Accept extra DICOM tags dictionaries in the DCMTK format '.dic' (easier to use than declare
   them in the Orthanc configuration file).  Even the standard dictionaries could be