BUG: Update logging in PyRadiomics scripts

- Fix bug where a more verbose log level for the file is ignored (logger level was not updated)
- Prevent repeated configuration of logging, leading to multiple file handlers and duplicate messages in the log
- Update format of the main thread to more closely match those in a parallel thread

radiomics/scripts/__init__.py

@@ -260,13 +260,18 @@ def _configureLogging(args):
   rLogger = radiomics.logger
   logging_config['logLevel'] = logLevel
 
+  fmt = logging.Formatter("[%(asctime)-.19s] %(levelname)-.1s: %(name)s: %(message)s")
+  rLogger.handlers[0].setFormatter(fmt)
+
   # Set up optional logging to file
   if args.log_file is not None:
-    rLogger.setLevel(logLevel)
-    handler = logging.FileHandler(filename=args.log_file, mode='a')
-    handler.setFormatter(logging.Formatter("%(levelname)s:%(name)s: %(message)s"))
-    rLogger.addHandler(handler)
     logging_config['logFile'] = args.log_file
+    logHandler = logging.FileHandler(filename=args.log_file, mode='a')
+    logHandler.setFormatter(fmt)
+    logHandler.setLevel(logLevel)
+    rLogger.addHandler(logHandler)
+    if rLogger.level > logHandler.level:
+      rLogger.level = logHandler.level
 
   # Set verbosity of output (stderr)
   verboseLevel = (6 - args.verbosity) * 10  # convert to python logging level

radiomics/scripts/segment.py

@@ -14,6 +14,7 @@
 from radiomics import featureextractor, setVerbosity
 
 caseLogger = logging.getLogger('radiomics.script')
+_parallel_extraction_configured = False
 
 
 def extractSegment(case_idx, case, config, config_override):
@@ -49,9 +50,9 @@ def extractSegment(case_idx, case, config, config_override):
 
 def extractSegment_parallel(args, parallel_config=None):
   if parallel_config is not None:
-    _configurParallelExtraction(parallel_config)
     # set thread name to patient name
     threading.current_thread().name = 'case %s' % args[0]  # args[0] = case_idx
+    _configurParallelExtraction(parallel_config)
   return extractSegment(*args)
 
 
@@ -149,6 +150,10 @@ def _configurParallelExtraction(parallel_config):
   Initialize logging for parallel extraction. This needs to be done here, as it needs to be done for each thread that is
   created.
   """
+  global _parallel_extraction_configured
+  if _parallel_extraction_configured:
+    return
+
   # Configure logging
   ###################
 
@@ -160,6 +165,8 @@ def _configurParallelExtraction(parallel_config):
     logHandler = logging.FileHandler(filename=logFile, mode='a')
     logHandler.setLevel(parallel_config.get('logLevel', logging.INFO))
     rLogger.addHandler(logHandler)
+    if rLogger.level > logHandler.level:
+      rLogger.level = logHandler.level
 
   # Include thread name in Log-message output for all handlers.
   parallelFormatter = logging.Formatter('[%(asctime)-.19s] %(levelname)-.1s: (%(threadName)s) %(name)s: %(message)s')
@@ -194,3 +201,6 @@ def filter(self, record):
   ####################################################################
 
   sitk.ProcessObject_SetGlobalDefaultNumberOfThreads(1)
+
+  _parallel_extraction_configured = True
+  rLogger.debug('parallel extraction configured')