diff --git a/README.md b/README.md index 5994743..d278989 100644 --- a/README.md +++ b/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 +``` diff --git a/src/anyvar/restapi/main.py b/src/anyvar/restapi/main.py index 79c817e..c99ba68 100644 --- a/src/anyvar/restapi/main.py +++ b/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) diff --git a/src/anyvar/storage/sql_storage.py b/src/anyvar/storage/sql_storage.py index c02e43a..193bc4f 100644 --- a/src/anyvar/storage/sql_storage.py +++ b/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