Introduce logging (Materials-Consortia#432)

* Add OPTIMADE logger:

The logger can be imported from optimade.server.logger as LOGGER.
It will write out logs at DEBUG level to a file `optimade.log` at
the OPTIMADE_LOG_DIR environment variable, default is /var/log/optimade/,
rotating between 5 files when reaching 1 MB.

The validator logger now get it's logger as a Child logger from this.

`run.sh` has been updated to set the new `OPTIMADE_LOG_LEVEL`
configuration option, since this is the only way we can get the logging
level to the terminal/console handler, while avoiding circular imports.

If `OPTIMADE_DEBUG` is set to "true", the `OPTIMADE_LOG_LEVEL` will be
overwritten to "DEBUG".

* Convert various print-statements to log-statements:

Keeping some print-statements still, mainly in tests, where it's nicer
to print than log in order to not unneccesarily pollute the logs.

* Add `log_dir` configuration option:

The default for `log_dir` is `/var/log/optimade/`.
If a `PermissionError` is raised during setting up the logging folder, a
warning will be logged (to the console), which will include instructions
on how to deal with the issue.

.gitignore

@@ -64,3 +64,4 @@ venv.bak/
 # Package-specific
 local_openapi.json
 local_index_openapi.json
+logs

optimade/adapters/base.py

@@ -5,6 +5,8 @@
 
 from optimade.models import EntryResource
 
+from optimade.adapters.logger import LOGGER
+
 
 class EntryAdapter:
     """Base class for lazy resource entry adapters
@@ -34,12 +36,12 @@ def entry(self):
     @entry.setter
     def entry(self, value: dict):
         """Set OPTIMADE entry
-        If already set, print that this can _only_ be set once.
+        If already set, report that this can _only_ be set once.
         """
         if self._entry is None:
             self._entry = self.ENTRY_RESOURCE(**value)
         else:
-            print("entry can only be set once and is already set.")
+            LOGGER.warning("entry can only be set once and is already set.")
 
     def convert(self, format: str) -> Any:
         """Convert OPTIMADE entry to desired format"""

optimade/adapters/logger.py

@@ -0,0 +1,4 @@
+"""Logger for optimade.adapters"""
+import logging
+
+LOGGER = logging.getLogger("optimade").getChild("adapters")

optimade/server/config.py

@@ -1,6 +1,6 @@
 # pylint: disable=no-self-argument
+from enum import Enum
 import json
-import logging
 from typing import Optional, Dict, List
 
 try:
@@ -22,11 +22,17 @@
 
 
 DEFAULT_CONFIG_FILE_PATH = str(Path.home().joinpath(".optimade.json"))
-logger = logging.getLogger("optimade")
 
 
-class NoFallback(Exception):
-    """No fallback value can be found."""
+class LogLevel(Enum):
+    """Replication of logging LogLevels"""
+
+    NOTSET = "notset"
+    DEBUG = "debug"
+    INFO = "info"
+    WARNING = "warning"
+    ERROR = "error"
+    CRITICAL = "critical"
 
 
 class ServerConfig(BaseSettings):
@@ -102,7 +108,6 @@ class ServerConfig(BaseSettings):
         {},
         description="A mapping between field names in the database with their corresponding OPTIMADE field names, broken down by endpoint.",
     )
-
     length_aliases: Dict[
         Literal["links", "references", "structures"], Dict[str, str]
     ] = Field(
@@ -113,35 +118,53 @@ class ServerConfig(BaseSettings):
             "API fields, not the database fields."
         ),
     )
-
     index_links_path: Path = Field(
         Path(__file__).parent.joinpath("index_links.json"),
         description="Absolute path to a JSON file containing the MongoDB collection of /links resources for the index meta-database",
     )
+    log_level: LogLevel = Field(
+        LogLevel.INFO, description="Logging level for the OPTIMADE server."
+    )
+    log_dir: Path = Field(
+        Path("/var/log/optimade/"),
+        description="Folder in which log files will be saved.",
+    )
 
     @validator("implementation", pre=True)
     def set_implementation_version(cls, v):
-        """Set defaults and modify by passed value(s)"""
+        """Set defaults and modify bypassed value(s)"""
         res = {"version": __version__}
         res.update(v)
         return res
 
+    @validator("log_level")
+    def force_debug_log_level(cls, v, values):
+        """If `debug` is `True`, then force `log_level` to be `DEBUG` as well"""
+        from optimade.server.logger import CONSOLE_HANDLER
+
+        if values.get("debug", False):
+            v = LogLevel.DEBUG
+        CONSOLE_HANDLER.setLevel(v.value.upper())
+        return v
+
     @root_validator(pre=True)
     def load_default_settings(cls, values):  # pylint: disable=no-self-argument
         """
         Loads settings from a root file if available and uses that as defaults in
         place of built in defaults
         """
+        from optimade.server.logger import LOGGER
+
         config_file_path = Path(values.get("config_file", DEFAULT_CONFIG_FILE_PATH))
 
         new_values = {}
 
         if config_file_path.exists() and config_file_path.is_file():
-            logger.debug("Found config file at: %s", config_file_path)
+            LOGGER.debug("Found config file at: %s", config_file_path)
             with open(config_file_path) as f:
                 new_values = json.load(f)
         else:
-            logger.debug(  # pragma: no cover
+            LOGGER.debug(  # pragma: no cover
                 "Did not find config file at: %s", config_file_path
             )
 

optimade/server/entry_collections/mongo.py

@@ -7,11 +7,12 @@
 
 from optimade.filterparser import LarkParser
 from optimade.filtertransformers.mongo import MongoTransformer
-from optimade.server.config import CONFIG
 from optimade.models import EntryResource
+from optimade.server.config import CONFIG
+from optimade.server.entry_collections import EntryCollection
+from optimade.server.logger import LOGGER
 from optimade.server.mappers import BaseResourceMapper
 from optimade.server.query_params import EntryListingQueryParams, SingleEntryQueryParams
-from .entry_collections import EntryCollection
 
 try:
     CI_FORCE_MONGO = bool(int(os.environ.get("OPTIMADE_CI_FORCE_MONGO", 0)))
@@ -23,12 +24,12 @@
     from pymongo import MongoClient
 
     client = MongoClient(CONFIG.mongo_uri)
-    print("Using: Real MongoDB (pymongo)")
+    LOGGER.info("Using: Real MongoDB (pymongo)")
 else:
     from mongomock import MongoClient
 
     client = MongoClient()
-    print("Using: Mock MongoDB (mongomock)")
+    LOGGER.info("Using: Mock MongoDB (mongomock)")
 
 
 class MongoCollection(EntryCollection):

optimade/server/exception_handlers.py

@@ -11,8 +11,9 @@
 
 from optimade.models import OptimadeError, ErrorResponse, ErrorSource
 
-from .config import CONFIG
-from .routers.utils import meta_values
+from optimade.server.config import CONFIG
+from optimade.server.logger import LOGGER
+from optimade.server.routers.utils import meta_values
 
 
 def general_exception(
@@ -26,7 +27,7 @@ def general_exception(
         tb = "".join(
             traceback.format_exception(etype=type(exc), value=exc, tb=exc.__traceback__)
         )
-        print(tb)
+        LOGGER.error("Traceback:\n%s", tb)
         debug_info[f"_{CONFIG.provider.prefix}_traceback"] = tb
 
     try:

optimade/server/logger.py

@@ -0,0 +1,67 @@
+"""Logging to both file and terminal"""
+import logging
+import os
+from pathlib import Path
+import sys
+
+from uvicorn.logging import DefaultFormatter
+
+
+# Instantiate LOGGER
+LOGGER = logging.getLogger("optimade")
+LOGGER.setLevel(logging.DEBUG)
+
+# Handler
+CONSOLE_HANDLER = logging.StreamHandler(sys.stdout)
+try:
+    from optimade.server.config import CONFIG
+
+    CONSOLE_HANDLER.setLevel(CONFIG.log_level.value.upper())
+except ImportError:
+    CONSOLE_HANDLER.setLevel(os.getenv("OPTIMADE_LOG_LEVEL", "INFO").upper())
+
+# Formatter
+CONSOLE_FORMATTER = DefaultFormatter("%(levelprefix)s [%(name)s] %(message)s")
+CONSOLE_HANDLER.setFormatter(CONSOLE_FORMATTER)
+
+# Add handler to LOGGER
+LOGGER.addHandler(CONSOLE_HANDLER)
+
+# Save a file with all messages (DEBUG level)
+try:
+    from optimade.server.config import CONFIG
+
+    LOGS_DIR = CONFIG.log_dir
+except ImportError:
+    LOGS_DIR = Path(os.getenv("OPTIMADE_LOG_DIR", "/var/log/optimade/")).resolve()
+
+try:
+    LOGS_DIR.mkdir(exist_ok=True)
+except PermissionError:
+    LOGGER.warning(
+        """Log files are not saved.
+
+    This is usually due to not being able to access a specified log folder or write to files
+    in the specified log location, i.e., a `PermissionError` has been raised.
+
+    To solve this, either set the OPTIMADE_LOG_DIR environment variable to a location
+    you have permission to write to or create the /var/log/optimade folder, which is
+    the default logging folder, with write permissions for the Unix user running the server.
+    """
+    )
+else:
+    # Handlers
+    FILE_HANDLER = logging.handlers.RotatingFileHandler(
+        LOGS_DIR.joinpath("optimade.log"), maxBytes=1000000, backupCount=5
+    )
+    FILE_HANDLER.setLevel(logging.DEBUG)
+
+    # Formatter
+    FILE_FORMATTER = logging.Formatter(
+        "[%(levelname)-8s %(asctime)s %(filename)s:%(lineno)d][%(name)s] %(message)s",
+        "%d-%m-%Y %H:%M:%S",
+    )
+    FILE_HANDLER.setFormatter(FILE_FORMATTER)
+
+    # Add handler to LOGGER
+    LOGGER.addHandler(FILE_HANDLER)

optimade/server/main.py

@@ -1,5 +1,11 @@
-# pylint: disable=line-too-long
+"""The OPTIMADE server
+
+The server is based on MongoDB, using either `pymongo` or `mongomock`.
 
+This is an example implementation with example data.
+To implement your own server see the documentation at https://optimade.org/optimade-python-tools.
+"""
+# pylint: disable=line-too-long
 from lark.exceptions import VisitError
 
 from pydantic import ValidationError
@@ -10,19 +16,27 @@
 from optimade import __api_version__, __version__
 import optimade.server.exception_handlers as exc_handlers
 
-from .entry_collections import MongoCollection
-from .config import CONFIG
-from .middleware import (
+from optimade.server.entry_collections import MongoCollection
+from optimade.server.config import CONFIG
+from optimade.server.logger import LOGGER
+from optimade.server.middleware import (
     AddWarnings,
     CheckWronglyVersionedBaseUrls,
     EnsureQueryParamIntegrity,
 )
-from .routers import info, links, references, structures, landing, versions
-from .routers.utils import get_providers, BASE_URL_PREFIXES
+from optimade.server.routers import (
+    info,
+    landing,
+    links,
+    references,
+    structures,
+    versions,
+)
+from optimade.server.routers.utils import get_providers, BASE_URL_PREFIXES
 
 
 if CONFIG.debug:  # pragma: no cover
-    print("DEBUG MODE")
+    LOGGER.info("DEBUG MODE")
 
 
 app = FastAPI(
@@ -45,15 +59,17 @@
     from .routers import ENTRY_COLLECTIONS
 
     def load_entries(endpoint_name: str, endpoint_collection: MongoCollection):
-        print(f"loading test {endpoint_name}...")
+        LOGGER.debug(f"Loading test {endpoint_name}...")
 
         endpoint_collection.collection.insert_many(getattr(data, endpoint_name, []))
         if endpoint_name == "links":
-            print("adding Materials-Consortia providers to links from optimade.org")
+            LOGGER.debug(
+                "Adding Materials-Consortia providers to links from optimade.org"
+            )
             endpoint_collection.collection.insert_many(
                 bson.json_util.loads(bson.json_util.dumps(get_providers()))
             )
-        print(f"done inserting test {endpoint_name}...")
+        LOGGER.debug(f"Done inserting test {endpoint_name}...")
 
     for name, collection in ENTRY_COLLECTIONS.items():
         load_entries(name, collection)

optimade/server/main_index.py

@@ -1,3 +1,10 @@
+"""The OPTIMADE Index Meta-Database server
+
+The server is based on MongoDB, using either `pymongo` or `mongomock`.
+
+This is an example implementation with example data.
+To implement your own index meta-database server see the documentation at https://optimade.org/optimade-python-tools.
+"""
 # pylint: disable=line-too-long
 import json
 
@@ -12,6 +19,7 @@
 import optimade.server.exception_handlers as exc_handlers
 
 from optimade.server.config import CONFIG
+from optimade.server.logger import LOGGER
 from optimade.server.middleware import (
     AddWarnings,
     CheckWronglyVersionedBaseUrls,
@@ -22,7 +30,7 @@
 
 
 if CONFIG.debug:  # pragma: no cover
-    print("DEBUG MODE")
+    LOGGER.info("DEBUG MODE")
 
 
 app = FastAPI(
@@ -45,7 +53,7 @@
     from .routers.links import links_coll
     from .routers.utils import mongo_id_for_database
 
-    print("loading index links...")
+    LOGGER.debug("Loading index links...")
     with open(CONFIG.index_links_path) as f:
         data = json.load(f)
 
@@ -55,11 +63,11 @@
             db["_id"] = {"$oid": mongo_id_for_database(db["id"], db["type"])}
             processed.append(db)
 
-        print("inserting index links into collection...")
+        LOGGER.debug("Inserting index links into collection...")
         links_coll.collection.insert_many(
             bson.json_util.loads(bson.json_util.dumps(processed))
         )
-        print("done inserting index links...")
+        LOGGER.debug("Done inserting index links...")
 
 
 # Add various middleware

optimade/validator/validator.py

@@ -387,7 +387,7 @@ def __init__(  # pylint: disable=too-many-arguments
 
     def _setup_log(self):
         """ Define stdout log based on given verbosity. """
-        self._log = logging.getLogger(__name__)
+        self._log = logging.getLogger("optimade").getChild("validator")
         self._log.handlers = []
         stdout_handler = logging.StreamHandler(sys.stdout)
         stdout_handler.setFormatter(