changeset 4281:d2f79a475b51

debug log for DCMTK SCU
author Sebastien Jodogne <s.jodogne@gmail.com>
date Wed, 04 Nov 2020 13:48:42 +0100
parents 58e757ded69e
children 65086904ec45
files NEWS OrthancFramework/Sources/DicomNetworking/DicomAssociation.cpp OrthancFramework/Sources/DicomNetworking/DicomControlUserConnection.cpp OrthancFramework/Sources/DicomNetworking/DicomStoreUserConnection.cpp OrthancServer/Sources/OrthancInitialization.cpp
diffstat 5 files changed, 103 insertions(+), 11 deletions(-) [+]
line wrap: on
line diff
--- a/NEWS	Wed Nov 04 07:56:22 2020 +0100
+++ b/NEWS	Wed Nov 04 13:48:42 2020 +0100
@@ -5,6 +5,7 @@
 -------
 
 * Logging categories (cf. command-line options starting with "--verbose-" and "--trace=")
+* Command-line option "--trace-dicom" can be used to access debug information from DCMTK
 
 REST API
 --------
--- a/OrthancFramework/Sources/DicomNetworking/DicomAssociation.cpp	Wed Nov 04 07:56:22 2020 +0100
+++ b/OrthancFramework/Sources/DicomNetworking/DicomAssociation.cpp	Wed Nov 04 13:48:42 2020 +0100
@@ -93,6 +93,17 @@
   {
     try
     {
+      if (cond.bad() &&
+          cond == DUL_ASSOCIATIONREJECTED)
+      {
+        T_ASC_RejectParameters rej;
+        ASC_getRejectParameters(params_, &rej);
+
+        OFString str;
+        CLOG(TRACE, DICOM) << "Association Rejected:" << std::endl
+                           << ASC_printRejectParameters(str, &rej);
+      }
+      
       CheckCondition(cond, parameters, "connecting");
     }
     catch (OrthancException&)
@@ -307,10 +318,25 @@
       presentationContextId += 2;
     }
 
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Request Parameters:" << std::endl
+                         << ASC_dumpParameters(str, params_, ASC_ASSOC_RQ);
+    }
+
     // Do the association
     CheckConnecting(parameters, ASC_requestAssociation(net_, params_, &assoc_));
     isOpen_ = true;
 
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Connection Parameters: "
+                         << ASC_dumpConnectionParameters(str, assoc_);
+      CLOG(TRACE, DICOM) << "Association Parameters Negotiated:" << std::endl
+                         << ASC_dumpParameters(str, params_, ASC_ASSOC_AC);
+    }
+
+
     // Inspect the accepted transfer syntaxes
     LST_HEAD **l = &params_->DULparams.acceptedPresentationContext;
     if (*l != NULL)
--- a/OrthancFramework/Sources/DicomNetworking/DicomControlUserConnection.cpp	Wed Nov 04 07:56:22 2020 +0100
+++ b/OrthancFramework/Sources/DicomNetworking/DicomControlUserConnection.cpp	Wed Nov 04 13:48:42 2020 +0100
@@ -70,6 +70,19 @@
     DcmDataset *responseIdentifiers /* pending response identifiers */
     )
   {
+    if (response != NULL)
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Received Find Response " << responseCount << ":" << std::endl
+                         << DIMSE_dumpMessage(str, *response, DIMSE_INCOMING);
+    }
+      
+    if (responseIdentifiers != NULL)
+    {
+      CLOG(TRACE, DICOM) << "Response Identifiers "  << responseCount << ":" << std::endl
+                         << DcmObject::PrintHelper(*responseIdentifiers);
+    }
+    
     if (responseIdentifiers != NULL)
     {
       FindPayload& payload = *reinterpret_cast<FindPayload*>(callbackData);
@@ -234,6 +247,7 @@
                                                 bool isWorklist,
                                                 const char* level)
   {
+    assert(dataset != NULL);
     assert(isWorklist ^ (level != NULL));
     assert(association_.get() != NULL);
 
@@ -267,6 +281,13 @@
     int responseCount;
 #endif
 
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Sending Find Request:" << std::endl
+                         << DIMSE_dumpMessage(str, request, DIMSE_OUTGOING, NULL, presID) << std::endl
+                         << DcmObject::PrintHelper(*dataset);
+    }
+
     OFCondition cond = DIMSE_findUser(
       &association_->GetDcmtkAssociation(), presID, &request, dataset,
 #if DCMTK_VERSION_NUMBER >= 364
@@ -284,6 +305,12 @@
 
     DicomAssociation::CheckCondition(cond, parameters_, "C-FIND");
 
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Received Final Find Response:" << std::endl
+                         << DIMSE_dumpMessage(str, response, DIMSE_INCOMING);
+    }
+
     
     /**
      * New in Orthanc 1.6.0: Deal with failures during C-FIND.
@@ -366,14 +393,20 @@
     request.DataSetType = DIMSE_DATASET_PRESENT;
     strncpy(request.MoveDestination, targetAet.c_str(), DIC_AE_LEN);
 
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Sending Move Request:" << std::endl
+                         << DIMSE_dumpMessage(str, request, DIMSE_OUTGOING, NULL, presID);
+    }
+    
     T_DIMSE_C_MoveRSP response;
     DcmDataset* statusDetail = NULL;
     DcmDataset* responseIdentifiers = NULL;
     OFCondition cond = DIMSE_moveUser(
-      &association_->GetDcmtkAssociation(), presID, &request, dataset, NULL, NULL,
+      &association_->GetDcmtkAssociation(), presID, &request, dataset, /*moveCallback*/ NULL, NULL,
       /*opt_blockMode*/ (parameters_.HasTimeout() ? DIMSE_NONBLOCKING : DIMSE_BLOCKING),
       /*opt_dimse_timeout*/ parameters_.GetTimeout(),
-      &association_->GetDcmtkNetwork(), NULL, NULL,
+      &association_->GetDcmtkNetwork(), /*subOpCallback*/ NULL, NULL,
       &response, &statusDetail, &responseIdentifiers);
 
     if (statusDetail)
@@ -388,6 +421,11 @@
 
     DicomAssociation::CheckCondition(cond, parameters_, "C-MOVE");
 
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Received Final Move Response:" << std::endl
+                         << DIMSE_dumpMessage(str, response, DIMSE_INCOMING);
+    }
     
     /**
      * New in Orthanc 1.6.0: Deal with failures during C-MOVE.
@@ -472,6 +510,7 @@
     }
     
     DcmDataset* dataset = query->GetDcmtkObject().getDataset();
+    assert(dataset != NULL);
 
     const char* clevel = NULL;
     const char* sopClass = NULL;
--- a/OrthancFramework/Sources/DicomNetworking/DicomStoreUserConnection.cpp	Wed Nov 04 07:56:22 2020 +0100
+++ b/OrthancFramework/Sources/DicomNetworking/DicomStoreUserConnection.cpp	Wed Nov 04 13:48:42 2020 +0100
@@ -34,6 +34,20 @@
 
 namespace Orthanc
 {
+  static void ProgressCallback(void * /*callbackData*/,
+                               T_DIMSE_StoreProgress *progress,
+                               T_DIMSE_C_StoreRQ * req)
+  {
+    if (req != NULL &&
+        progress->state == DIMSE_StoreBegin)
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Sending Store Request:" << std::endl
+                         << DIMSE_dumpMessage(str, *req, DIMSE_OUTGOING);
+    }
+  }
+
+
   bool DicomStoreUserConnection::ProposeStorageClass(const std::string& sopClassUid,
                                                      const std::set<DicomTransferSyntax>& syntaxes)
   {
@@ -357,7 +371,7 @@
     DcmDataset* statusDetail = NULL;
     DicomAssociation::CheckCondition(
       DIMSE_storeUser(&association_->GetDcmtkAssociation(), presID, &request,
-                      NULL, dicom.getDataset(), /*progressCallback*/ NULL, NULL,
+                      NULL, dicom.getDataset(), ProgressCallback, NULL,
                       /*opt_blockMode*/ (GetParameters().HasTimeout() ? DIMSE_NONBLOCKING : DIMSE_BLOCKING),
                       /*opt_dimse_timeout*/ GetParameters().GetTimeout(),
                       &response, &statusDetail, NULL),
@@ -367,6 +381,12 @@
     {
       delete statusDetail;
     }
+
+    {
+      OFString str;
+      CLOG(TRACE, DICOM) << "Received Store Response:" << std::endl
+                         << DIMSE_dumpMessage(str, response, DIMSE_INCOMING, NULL, presID);
+    }
     
     /**
      * New in Orthanc 1.6.0: Deal with failures during C-STORE.
--- a/OrthancServer/Sources/OrthancInitialization.cpp	Wed Nov 04 07:56:22 2020 +0100
+++ b/OrthancServer/Sources/OrthancInitialization.cpp	Wed Nov 04 13:48:42 2020 +0100
@@ -399,32 +399,38 @@
 
   static void SetDcmtkVerbosity(Verbosity verbosity)
   {
+    // INFO_LOG_LEVEL was the DCMTK log level in Orthanc <= 1.8.0    
     // https://support.dcmtk.org/docs-dcmrt/classOFLogger.html#ae20bf2616f15313c1f089da2eefb8245
-    OFLogger::LogLevel level;
+
+    OFLogger::LogLevel dataLevel, networkLevel;
 
     switch (verbosity)
     {
       case Verbosity_Default:
-        level = OFLogger::OFF_LOG_LEVEL;  // No log
+        // Turn off logging in DCMTK core
+        dataLevel = OFLogger::OFF_LOG_LEVEL;
+        networkLevel = OFLogger::OFF_LOG_LEVEL;
         break;
 
       case Verbosity_Verbose:
-        level = OFLogger::INFO_LOG_LEVEL;  // This was the default log level in Orthanc <= 1.8.0
+        dataLevel = OFLogger::INFO_LOG_LEVEL;
+        networkLevel = OFLogger::INFO_LOG_LEVEL;
         break;
 
       case Verbosity_Trace:
-        level = OFLogger::DEBUG_LOG_LEVEL;
+        dataLevel = OFLogger::INFO_LOG_LEVEL;  // DEBUG here makes DCMTK too verbose to be useful
+        networkLevel = OFLogger::DEBUG_LOG_LEVEL;
         break;
 
       default:
         throw OrthancException(ErrorCode_ParameterOutOfRange);
     }
 
-    OFLog::configure(level);
-    assert(dcmtk::log4cplus::Logger::getRoot().getChainedLogLevel() == level);
+    OFLog::configure(dataLevel);
+    assert(dcmtk::log4cplus::Logger::getRoot().getChainedLogLevel() == dataLevel);
     
-    DCM_dcmdataLogger.setLogLevel(level);
-    DCM_dcmnetLogger.setLogLevel(level);
+    DCM_dcmdataLogger.setLogLevel(dataLevel);    // This seems to be implied by "OFLog::configure()"
+    DCM_dcmnetLogger.setLogLevel(networkLevel);  // This will display PDU in DICOM networking
   }