Mercurial > hg > orthanc
changeset 5451:b19bfb939323
log lines now contain the thread name
| author | Alain Mazy <am@osimis.io> |
|---|---|
| date | Tue, 05 Dec 2023 16:28:16 +0100 |
| parents | 29858f424fc7 (current diff) 9ffd6d18daf3 (diff) |
| children | 8345267e8de5 |
| files | |
| 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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:28:16 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