Add feature to allow logging configuration to be specified at runtime (…

…#106)

* Add code to load logging configuration from a file specified in environment variable

* Add logging config information to README

* Add diagnostic log statements to SQL storage

README.md

@@ -213,3 +213,44 @@ uploaded. A pytest hook ensures correct test order, but some test modules may no
 able to pass when run in isolation. By default, the tests will use a Postgres database
 installation. To run the tests against a Snowflake database, change the
 `ANYVAR_TEST_STORAGE_URI` to a Snowflake URI and run the tests.
+
+## Logging
+AnyVar uses the [Python Logging Module](https://docs.python.org/3/howto/logging.html) to
+output information and diagnostics.  By default, log output is directed to standard output
+and the level is set to `INFO`.  Alternatively, a YAML logging configuration may be specified
+using the `ANYVAR_LOGGING_CONFIG` environment variable.  The value must be the relative or
+absolute path of a YAML file containing a valid logging configuration. The configuration
+in this file will be loaded and used to configured the logging module.
+
+For example:
+```yaml
+version: 1
+disable_existing_loggers: true
+
+formatters:
+  standard:
+    format: "%(threadName)s %(asctime)s - %(name)s - %(levelname)s - %(message)s"
+
+handlers:
+  console:
+    class: logging.StreamHandler
+    level: DEBUG
+    formatter: standard
+    stream: ext://sys.stdout
+
+root:
+  level: INFO
+  handlers: [console]
+  propagate: yes
+
+loggers:
+  anyvar.restapi.main:
+    level: INFO
+    handlers: [console]
+    propagate: no
+
+  anyvar.storage.sql_storage:
+    level: DEBUG
+    handlers: [console]
+    propagate: no
+```

src/anyvar/restapi/main.py

@@ -1,11 +1,15 @@
 """Provide core route definitions for REST service."""
 
 import logging
+import logging.config
+import os
+import pathlib
 import tempfile
 from contextlib import asynccontextmanager
 from http import HTTPStatus
 
 import ga4gh.vrs
+import yaml
 from fastapi import Body, FastAPI, File, HTTPException, Path, Query, Request, UploadFile
 from fastapi.responses import FileResponse
 from pydantic import StrictStr
@@ -31,6 +35,15 @@
 )
 from anyvar.utils.types import VrsVariation, variation_class_map
 
+logging_config_file = os.environ.get("ANYVAR_LOGGING_CONFIG", None)
+if logging_config_file and pathlib.Path(logging_config_file).is_file():
+    with pathlib.Path(logging_config_file).open() as fd:
+        try:
+            config = yaml.safe_load(fd.read())
+            logging.config.dictConfig(config)
+        except Exception:
+            logging.exception("Error in Logging Configuration. Using default configs")
+
 _logger = logging.getLogger(__name__)
 
 
@@ -264,6 +277,7 @@ async def annotate_vcf(
                 _logger.error("Encountered error during VCF registration: %s", e)
                 return {"error": "Encountered ValueError when registering VCF"}
             if not allow_async_write:
+                _logger.info("Waiting for object store writes from API handler method")
                 av.object_store.wait_for_writes()
             return FileResponse(temp_out_file.name)
 

src/anyvar/storage/sql_storage.py

@@ -74,15 +74,23 @@ def __init__(
         self.batch_limit = batch_limit or int(
             os.environ.get("ANYVAR_SQL_STORE_BATCH_LIMIT", "100000")
         )
+        _logger.debug("set batch limit to %s", self.batch_limit)
+
         self.flush_on_batchctx_exit = (
             os.environ.get("ANYVAR_SQL_STORE_FLUSH_ON_BATCHCTX_EXIT", "true").lower()
             in ["true", "yes", "1"]
             if flush_on_batchctx_exit is None
             else flush_on_batchctx_exit
         )
+        _logger.debug(
+            "set flush on batch context exit to %s", self.flush_on_batchctx_exit
+        )
+
         max_pending_batches = max_pending_batches or int(
             os.environ.get("ANYVAR_SQL_STORE_MAX_PENDING_BATCHES", "50")
         )
+        _logger.debug("set max pending batches to %s", max_pending_batches)
+
         self.batch_thread = SqlStorageBatchThread(self, max_pending_batches)
         self.batch_thread.start()
 
@@ -228,6 +236,8 @@ def delete_vrs_object(self, db_conn: Connection, vrs_id: str) -> None:
 
     def wait_for_writes(self) -> None:
         """Return once any currently pending database modifications have been completed."""
+        _logger.debug("Waiting for writes")
+
         if hasattr(self, "batch_thread") and self.batch_thread is not None:
             # short circuit if the queue is empty
             with self.batch_thread.cond:
@@ -449,6 +459,7 @@ def __exit__(
         self._storage.batch_mode = False
         self._storage.batch_insert_values = None
         if self._storage.flush_on_batchctx_exit:
+            _logger.debug("Flushing on batch context exit")
             self._storage.wait_for_writes()
         return True