Add more detailed logging

README.md

@@ -16,6 +16,11 @@ service with the latest MassBank-data release in msp format.
 wget https://github.com/MassBank/MassBank-data/releases/latest/download/MassBank_NIST.msp
 export MSP="./MassBank_NIST.msp"
 ```
+A more verbose logging can be activated by setting environment variable VERBOSE
+to "true".
+```bash
+export VERBOSE=true
+```
 
 ## Usage
 To run the server, install the requirements, generate the server code 

similarity_service_impl/app.py

@@ -7,19 +7,21 @@
 from waitress import serve
 
 VERBOSE = os.environ.get('VERBOSE', "false")
+logging.basicConfig(
+    format='%(asctime)s %(name)s %(levelname)-8s %(message)s',
+    level=logging.INFO,
+    datefmt='%Y-%m-%d %H:%M:%S')
 
 app = connexion.App(__name__, specification_dir='..')
 app.app.json_encoder = encoder.JSONEncoder
 app.add_api('openapi.yaml',
             arguments={'title': 'Similarity score api for MassBank3'},
             pythonic_params=True)
 
-
-
 def serve_app():
     if VERBOSE == "true":
         from paste.translogger import TransLogger
-        logging.getLogger('waitress').setLevel(logging.INFO)
+        logging.getLogger('waitress').setLevel(logging.DEBUG)
         serve(TransLogger(app, setup_console_handler=False), listen='*:8080')
     else:
         serve(app, listen='*:8080')

similarity_service_impl/similarity_service_impl_controller.py

@@ -16,6 +16,7 @@
 
 # Environment variables
 MSP = os.environ.get('MSP', "./MassBank_NIST.msp")
+VERBOSE = os.environ.get('VERBOSE', "false")
 
 # Global variables for in-memory data
 timestamp = datetime.fromisoformat('2010-01-01')
@@ -24,23 +25,28 @@
 # Lock for thread safety
 lock = threading.Lock()
 
-# Global setting
-logging.basicConfig(level="INFO")
+# set log level
 set_matchms_logger_level("ERROR")
 
+logger = logging.getLogger('similarity_service_impl_controller')
+print(__name__)
+if VERBOSE == "true":
+    logger.setLevel(logging.DEBUG)
+
 def load_spectra():
     """load all spectra from the given msp file"""
     global timestamp, MSP, spectra
     with lock:
         file_timestamp = datetime.fromtimestamp(os.path.getmtime(MSP))
-        logging.info("In-memory timestamp: %s", timestamp)
-        logging.info("Data file timestamp: %s", file_timestamp)
+        logger.debug("In-memory timestamp of reference spectra: %s", timestamp)
+        logger.debug("Reference spectra data file timestamp: %s", file_timestamp)
         timestamp_diff = file_timestamp - timestamp
         if timestamp_diff.total_seconds() > 0:
-            logging.info("Data file timestamp is %s newer. Reloading...", timestamp_diff)
+            logger.info("Reference spectra data file timestamp is %s newer. Reloading...", timestamp_diff)
             spectra = list(load_from_msp(MSP))
             timestamp = file_timestamp
-            logging.info("Loaded %s spectra from the data file.", len(spectra))
+            logger.info("Finished. Loaded %s spectra from the data file.", len(spectra))
+
 
 
 def similarity_post(similarity_calculation):  # noqa: E501
@@ -59,6 +65,7 @@ def similarity_post(similarity_calculation):  # noqa: E501
         load_spectra()
 
         mz, intensities = zip(*[(peak.mz, peak.intensity) for peak in request.peak_list])
+        logger.debug("Got spectra: %s", request.peak_list)
 
         try:
             query = normalize_intensities(Spectrum(mz=numpy.array(mz), intensities=numpy.array(intensities)))
@@ -69,15 +76,18 @@ def similarity_post(similarity_calculation):  # noqa: E501
                 status=400,
             )
 
+        logger.debug("Got %s reference spectra.", len(request.reference_spectra_list))
         references = spectra
         if request.reference_spectra_list:
             references = [s for s in references if s.metadata['spectrum_id'] in request.reference_spectra_list]
+        logger.debug("Use %s for calculation.", len(references))
 
         scores = calculate_scores(references, [query], CosineGreedy())
         matches = scores.scores_by_query(query, 'CosineGreedy_score', sort=True)
         match_list = SimilarityScoreList(
             [SimilarityScore(match[0].metadata['spectrum_id'], match[1][0]) for match in matches])
 
+        logger.debug("Calculated scores for %s similar spectra.", len(match_list.similarity_score_list))
         return match_list