Improve logging, and other minor refactoring (#62)

* Add stdout logger

* Dockerfile formatting

* Move CustomJSONEncoder to utils submodule

* Add logged_route decorator for, er, logging routes

* Tidy up route logging/printing/error handling

* Set DEBUG mode to by default

* Update test error message

* Tweak CI config: do not run 3.9 tests if 3.8 fails

* Reblacken

* Revert error handling changes

Author: ml-evs

.docker/server_dockerfile

@@ -10,5 +10,12 @@ COPY ./pydatalab/ /app
 RUN pip install pipenv
 RUN pipenv install --deploy --dev
 
-# Run flask server
-CMD ["pipenv", "run", "gunicorn", "-w", "2", "--error-logfile", "logs/pydatalab_error.log", "--access-logfile", "logs/pydatalab_access.log", "-b", "0.0.0.0:5001", "pydatalab.main:create_app()"]
+# Launch the server
+CMD ["pipenv", "run", \
+     "gunicorn", \
+     "-w", "2", \
+     "--error-logfile", "logs/pydatalab_error.log", \
+     "--access-logfile", "logs/pydatalab_access.log", \
+     "-b", "0.0.0.0:5001", \
+     "pydatalab.main:create_app()" \
+]

.github/workflows/ci.yml

@@ -37,8 +37,8 @@ jobs:
     runs-on: ubuntu-latest
 
     strategy:
-      fail-fast: false
-      max-parallel: 4
+      fail-fast: true
+      max-parallel: 1
       matrix:
         python-version: [3.8, 3.9]
 

pydatalab/pydatalab/blocks/blocks.py

@@ -122,7 +122,9 @@ def update_from_web(self, data):
         """update the object with data received from the website. Only updates fields
         that are specified in the dictionary- other fields are left alone"""
         LOGGER.debug(
-            "Updating block %s from web request with data %s", self.__class__.__name__, data
+            "Updating block %s from web request with data %s",
+            self.__class__.__name__,
+            data,
         )
         self.data.update(data)
 
@@ -151,26 +153,25 @@ def plot_functions(self):
 
     def generate_xrd_plot(self):
         if "file_id" not in self.data:
-            print("XRDBlock.generate_xrd_plot(): No file set in the DataBlock")
-            return None
+            LOGGER.warning("XRDBlock.generate_xrd_plot(): No file set in the DataBlock")
+            return
         file_info = get_file_info_by_id(self.data["file_id"], update_if_live=True)
 
         filename = file_info["name"]
         ext = os.path.splitext(filename)[-1].lower()
 
         if ext not in [".xrdml", ".xy"]:
-            print(
+            LOGGER.warning(
                 "XRDBlock.generate_xrd_plot(): Unsupported file extension (must be .xrdml or .xy)"
             )
-            return None
+            return
 
-        print(f"The XRD file to plot is found at: {file_info['location']}")
+        LOGGER.debug(f"The XRD file to plot is found at: {file_info['location']}")
         if ext == ".xrdml":
-            print("xrdml data received. converting to .xy")
             filename = xrd_utils.convertSinglePattern(
                 file_info["location"]
             )  # should give .xrdml.xy file
-            print(f"the path is now: {filename}")
+            LOGGER.debug("the path is now: %s", filename)
         else:
             filename = os.path.join(file_info["location"])
 

pydatalab/pydatalab/blocks/echem_block.py

@@ -9,6 +9,7 @@
 from pydatalab import bokeh_plots
 from pydatalab.blocks.blocks import DataBlock
 from pydatalab.file_utils import get_file_info_by_id
+from pydatalab.logger import LOGGER
 from pydatalab.simple_bokeh_plot import mytheme
 from pydatalab.utils import reduce_df_size
 
@@ -184,15 +185,16 @@ def plot_cycle(self):
         )
 
         if "file_id" not in self.data:
-            print("No file_id given")
+            LOGGER.warning("No file_id given")
             return
 
         derivative_modes = (None, "dQ/dV", "dV/dQ")
 
         if self.data["derivative_mode"] not in derivative_modes:
-            print(
-                f"Invalid derivative_mode provided: {self.data['derivative_mode']!r}. "
-                f"Expected one of {derivative_modes}. Falling back to `None`."
+            LOGGER.warning(
+                "Invalid derivative_mode provided: %s. Expected one of %s. Falling back to `None`.",
+                self.data["derivative_mode"],
+                derivative_modes,
             )
             self.data["derivative_mode"] = None
 
@@ -227,7 +229,9 @@ def plot_cycle(self):
         ext = os.path.splitext(filename)[-1].lower()
 
         if ext not in self.accepted_file_extensions:
-            print("Unrecognized filetype")
+            LOGGER.warning(
+                f"Unrecognized filetype {ext}, must be one of {self.accepted_file_extensions}"
+            )
             return
 
         if file_id in self.cache.get("parsed_file", {}):

pydatalab/pydatalab/config.py

@@ -8,15 +8,16 @@ class ServerConfig(BaseSettings):
     SECRET_KEY: str = Field("dummy key", description="The secret key to use for Flask.")
 
     MONGO_URI: str = Field(
-        "mongodb://localhost:27017/datalabvue", description="The URI for the underlying MongoDB."
+        "mongodb://localhost:27017/datalabvue",
+        description="The URI for the underlying MongoDB.",
     )
 
     FILE_DIRECTORY: Union[str, Path] = Field(
         Path(__file__).parent.joinpath("../files").resolve(),
         description="The path under which to place stored files uploaded to the server.",
     )
 
-    DEBUG: bool = Field(False, description="Whether to enable debug-level logging in the server.")
+    DEBUG: bool = Field(True, description="Whether to enable debug-level logging in the server.")
 
     class Config:
         env_prefix = "pydatalab_"

pydatalab/pydatalab/file_utils.py

@@ -8,6 +8,7 @@
 
 import pydatalab.mongo
 from pydatalab.config import CONFIG
+from pydatalab.logger import LOGGER
 from pydatalab.models import File
 from pydatalab.resources import DIRECTORIES_DICT
 
@@ -16,7 +17,7 @@
 
 def get_file_info_by_id(file_id, update_if_live=True):
     """file_id can be either the string representation or the ObjectId() object. Returns the file information dictionary"""
-    print(f"getting file for file_id: {file_id}")
+    LOGGER.debug("getting file for file_id: %s", file_id)
     file_collection = pydatalab.mongo.flask_mongo.db.files
     file_id = ObjectId(file_id)
     file_info = file_collection.find_one({"_id": file_id})
@@ -32,19 +33,20 @@ def get_file_info_by_id(file_id, update_if_live=True):
         try:
             stat_results = os.stat(full_remote_path)
         except FileNotFoundError:
-            print(
+            LOGGER.debug(
                 "when trying to check if live file needs to be updated, could not access remote file"
             )
             file_info["live_update_error"] = "Could not reach remote server to update"
             return file_info
 
         current_timestamp_on_server = datetime.datetime.fromtimestamp(stat_results.st_mtime)
-        print(
-            f"checking if update is necessary. Cached timestamp: {cached_timestamp}. Current timestamp: {current_timestamp_on_server}."
+        LOGGER.debug(
+            "checking if update is necessary. Cached timestamp: %s. Current timestamp: %s.",
+            cached_timestamp,
+            current_timestamp_on_server,
         )
-        print(f"\tDifference: {current_timestamp_on_server - cached_timestamp} seconds")
+        LOGGER.debug("\tDifference: %s seconds", current_timestamp_on_server - cached_timestamp)
         if current_timestamp_on_server > cached_timestamp:
-            print("updating file")
             shutil.copy(full_remote_path, file_info.location)
             updated_file_info = file_collection.find_one_and_update(
                 {"_id": file_id},

pydatalab/pydatalab/logger.py

@@ -1,7 +1,16 @@
 import logging
+from functools import wraps
+from typing import Callable
 
 
 def setup_log():
+    """Creates a logger for pydatalab with a simple
+    stdout output.
+
+    Verbosity is set in the config file via
+    the DEBUG option.
+
+    """
     from pydatalab.config import CONFIG
 
     logging.basicConfig()
@@ -13,4 +22,28 @@ def setup_log():
     return logger
 
 
+"""The main logging object to be imported from elsewhere in the package."""
 LOGGER = setup_log()
+
+
+def logged_route(fn: Callable):
+    """A decorator that enables logging of inputs and
+    outputs when debug mode is enabled.
+
+    """
+
+    @wraps(fn)
+    def wrapped_logged_route(*args, **kwargs):
+        from flask import request
+
+        LOGGER.debug(
+            "Calling %s with request: %s, JSON payload: %s",
+            fn.__name__,
+            request,
+            request.get_json(),
+        )
+        result = fn(*args, **kwargs)
+        LOGGER.debug("%s returned %s", fn.__name__, result)
+        return result
+
+    return wrapped_logged_route

pydatalab/pydatalab/main.py

@@ -1,22 +1,12 @@
-import datetime
 from typing import Any, Dict
 
-from bson import json_util
 from flask import Flask
-from flask.json import JSONEncoder
 from flask_cors import CORS
 
 import pydatalab.mongo
 from pydatalab.config import CONFIG
-
-
-class CustomJSONEncoder(JSONEncoder):
-    """Use a JSON encoder that can handle pymongo's bson."""
-
-    def default(self, obj):
-        if isinstance(obj, datetime.datetime):
-            return datetime.datetime.isoformat(obj)
-        return json_util.default(obj)
+from pydatalab.logger import logged_route
+from pydatalab.utils import CustomJSONEncoder
 
 
 def create_app(config_override: Dict[str, Any] = None) -> Flask:
@@ -57,9 +47,9 @@ def register_endpoints(app):
     from pydatalab.routes import ENDPOINTS  # pylint: disable=import-outside-toplevel
 
     for rule, func in ENDPOINTS.items():
-        app.add_url_rule(rule, func.__name__, func)
+        app.add_url_rule(rule, func.__name__, logged_route(func))
 
 
 if __name__ == "__main__":
     app_ = create_app()
-    app_.run(host="0.0.0.0", debug=True, port=5001)
+    app_.run(host="0.0.0.0", debug=CONFIG.DEBUG, port=5001)

pydatalab/pydatalab/remote_filesystems.py

@@ -4,6 +4,7 @@
 import subprocess
 
 import pydatalab.mongo
+from pydatalab.logger import LOGGER
 from pydatalab.resources import DIRECTORIES
 
 # from fs.smbfs import SMBFS
@@ -57,8 +58,7 @@ def save_directory_structure_to_db(directory_name, dir_structure):
         },
         upsert=True,
     )
-    print("Result of saving directory structure to the db:")
-    print(result.raw_result)
+    LOGGER.debug("Result of saving directory structure to the db: %s", result.raw_result)
 
 
 def get_cached_directory_structure_from_db(directory_name):
@@ -68,12 +68,12 @@ def get_cached_directory_structure_from_db(directory_name):
 def get_all_directory_structures(directories=DIRECTORIES):
     all_directory_structures = []
     for directory in directories:
-        print(f"Retrieving remote directory {directory['name']} at {directory['path']}")
+        LOGGER.debug("Retrieving remote directory %s at %s", directory["name"], directory["path"])
         try:
             dir_structure = get_directory_structure_json(directory["path"])
             save_directory_structure_to_db(directory["name"], dir_structure)
-        except (json.JSONDecodeError, KeyError):
-            print("Error reading remote filetree json.")
+        except (json.JSONDecodeError, KeyError) as exc:
+            LOGGER.warning("Error reading remote filetree json: %s", exc)
             dir_structure = [{"type": "error", "name": "Could not reach remote server"}]
 
         wrapped_dir_structure = {

pydatalab/pydatalab/routes/blocks.py

@@ -16,7 +16,6 @@ def add_data_block():
     item_id = request_json["item_id"]
     insert_index = request_json["index"]
 
-    print(f"Adding a block of type: {block_type} to items: {item_id}")
     if block_type not in BLOCK_TYPES:
         return jsonify(status="error", message="Invalid block type"), 400
 
@@ -42,19 +41,17 @@ def add_data_block():
         },
     )
 
-    print(result.raw_result)
     if result.modified_count < 1:
         return (
             jsonify(
                 status="error",
-                message="Update failed. The item_id probably incorrect: {}".format(item_id),
+                message=f"Update failed. {item_id=} is probably incorrect.",
             ),
             400,
         )
 
     # get the new display_order:
     display_order_result = flask_mongo.db.items.find_one({"item_id": item_id}, {"display_order": 1})
-    print("new document: {}".format(display_order_result))
 
     return jsonify(
         status="success",
@@ -73,7 +70,6 @@ def update_block():
     plot
     """
     request_json = request.get_json()
-    print("update_block called with : " + str(request_json)[:1000])
     block_data = request_json["block_data"]
     blocktype = block_data["blocktype"]
 
@@ -93,7 +89,6 @@ def delete_block():
     item_id = request_json["item_id"]
     block_id = request_json["block_id"]
 
-    # print(update)
     result = flask_mongo.db.items.update_one(
         {"item_id": item_id},
         {
@@ -105,10 +100,6 @@ def delete_block():
         },
     )
 
-    print("Removing block: {} , from sample: {}".format(block_id, item_id))
-    print("result:")
-    print(result.raw_result)
-
     if result.modified_count < 1:
         return (
             jsonify(