Improved logging

.vscode/launch.json

@@ -0,0 +1,15 @@
+{
+    // Use IntelliSense to learn about possible attributes.
+    // Hover to view descriptions of existing attributes.
+    // For more information, visit: https://go.microsoft.com/fwlink/?linkid=830387
+    "version": "0.2.0",
+    "configurations": [
+        {
+            "name": "Python: Module",
+            "type": "python",
+            "request": "launch",
+            "module": "tdp_core",
+            "justMyCode": false
+        }
+    ]
+}

tdp_core/dbmigration/manager.py

@@ -156,12 +156,11 @@ def __init__(self):
         self._migrations: Dict[str, DBMigration] = dict()
 
     def init_app(self, app: FastAPI, plugins: List[AExtensionDesc] = []):
-        _log.info("Initializing DBMigrationManager")
-
+        _log.info(f"Initializing DBMigrationManager with {', '.join([p.id for p in plugins]) or 'no plugins'}")
         auto_upgrade_default = manager.settings.tdp_core.migrations.autoUpgrade
 
         for p in plugins:
-            _log.info("DBMigration found: %s", p.id)
+            _log.info(f"Database migration found: {p.id}")
 
             # TODO: The AExtensionDesc doesn't have any typing information, so we need to cast it to Any here
             p: Any = p

tdp_core/id_mapping/manager.py

@@ -198,9 +198,9 @@ def search(self, from_idtype, to_idtype, query, max_results=None):
 
 
 def create_id_mapping_manager() -> MappingManager:
-    _log.info("Creating mapping_manager")
     # Load mapping providers
     providers = []
     for plugin in manager.registry.list("mapping_provider"):
         providers = providers + list(plugin.load().factory())
+    _log.info(f"Initializing MappingManager with {len(providers)} provider(s)")
     return MappingManager(providers)

tdp_core/middleware/exception_handler_middleware.py

@@ -30,7 +30,7 @@ async def _send(message: Message) -> None:
         try:
             await self.app(scope, receive, _send)
         except Exception as e:
-            logging.exception("An error occurred in FastAPI")
+            logging.exception(repr(e))
             response = await http_exception_handler(
                 None,  # type: ignore
                 e if isinstance(e, HTTPException) else HTTPException(status_code=500, detail=detail_from_exception(e)),

tdp_core/plugin/parser.py

@@ -84,7 +84,7 @@ def load_all_plugins() -> List[EntryPointPlugin]:
     plugins: List[EntryPointPlugin] = [p for p in _find_entry_point_plugins() if not is_disabled_plugin(p)]
     plugins.sort(key=lambda p: p.id)
 
-    _log.info(f"Discovered {len(plugins)} plugins: {', '.join([d.id for d in plugins])}")
+    _log.info(f"Discovered {len(plugins)} plugin(s): {', '.join([d.id for d in plugins])}")
 
     return plugins
 
@@ -95,7 +95,7 @@ def get_extensions_from_plugins(plugins: List[EntryPointPlugin]) -> List:
         reg = RegHelper(plugin)
         plugin.plugin.register(reg)
         ext = [r for r in reg if not is_disabled_extension(r, "python", plugin)]
-        logging.info(f"plugin {plugin.id} registered {len(ext)} extension(s)")
+        _log.info(f"Plugin {plugin.id} registered {len(ext)} extension(s)")
         plugin.extensions = ext
         server_extensions.extend(ext)
 
@@ -111,7 +111,7 @@ def get_config_from_plugins(plugins: List[EntryPointPlugin]) -> Tuple[List[Dict[
     for plugin in plugins:
         plugin_settings_model = plugin.plugin.setting_class
         if plugin_settings_model:
-            logging.info(f"Plugin {plugin.id} has a settings model")
+            _log.info(f"Plugin {plugin.id} has a settings model")
             # Load the class of the config and wrap it in a tuple like (<clazz>, ...),
             # such that pydantic can use it as type-hint in the create_model class.
             # Otherwise, it would except <clazz> to be the default value...

tdp_core/security/manager.py

@@ -232,13 +232,13 @@ def create_security_manager():
     """
     :return: the security manager
     """
-    _log.info("Creating security_manager")
-
     user_stores = list(filter(None, [p.load().factory() for p in manager.registry.list("user_stores")]))
     if len(user_stores) == 0 or manager.settings.tdp_core.alwaysAppendDummyStore:
-        from .store import dummy_store
+        from .store.dummy_store import DummyStore
+
+        user_stores.append(DummyStore())
 
-        user_stores.append(dummy_store.create())
+    _log.info(f"Initializing SecurityManager with {', '.join([s.__class__.__name__ for s in user_stores]) or 'no user stores'}")
 
     return SecurityManager(user_stores=user_stores)
 

tdp_core/security/store/dummy_store.py

@@ -50,8 +50,3 @@ def login(self, username, extra_fields={}):
 
     def logout(self, user):
         pass
-
-
-def create():
-    _log.info("Creating dummy store")
-    return DummyStore()

tdp_core/server/utils.py

@@ -33,7 +33,7 @@ def init_legacy_app(app: Flask):
     @app.errorhandler(Exception)  # type: ignore
     async def handle_exception(e):
         """Handles Flask exceptions by returning the same JSON response as FastAPI#HTTPException would."""
-        _log.exception("An error occurred in Flask")
+        _log.exception(repr(e))
         # Extract status information if a Flask#HTTPException is given, otherwise return 500 with exception information
         status_code = e.code if isinstance(e, HTTPException) else 500
         detail = detail_from_exception(e)
@@ -56,12 +56,13 @@ def load_after_server_started_hooks():
 
     after_server_started_hooks = [p.load().factory() for p in manager.registry.list("after_server_started")]
 
-    _log.info(f"Found {len(after_server_started_hooks)} `after_server_started` extension points to run")
+    if after_server_started_hooks:
+        _log.info(f"Found {len(after_server_started_hooks)} after_server_started extension(s) to run")
 
-    for hook in after_server_started_hooks:
-        hook()
+        for hook in after_server_started_hooks:
+            hook()
 
-    _log.info("Elapsed time for server startup hooks: %d seconds", time.time() - start)
+        _log.info("Elapsed time for server startup hooks: %d seconds", time.time() - start)
 
 
 def detail_from_exception(e: Exception) -> Optional[str]:
@@ -75,4 +76,4 @@ def detail_from_exception(e: Exception) -> Optional[str]:
     if isinstance(e, HTTPException):
         return e.description
     # Fallback to the string representation of the exception
-    return str(e)
+    return repr(e)

tdp_core/server/visyn_server.py

@@ -36,8 +36,15 @@ def create_visyn_server(
     workspace_config = workspace_config if isinstance(workspace_config, dict) else load_workspace_config()
     manager.settings = GlobalSettings(**workspace_config)
     logging.config.dictConfig(manager.settings.tdp_core.logging)
+
+    # Filter out the metrics endpoint from the access log
+    class EndpointFilter(logging.Filter):
+        def filter(self, record: logging.LogRecord) -> bool:
+            return "GET /metrics" not in record.getMessage()
+
+    logging.getLogger("uvicorn.access").addFilter(EndpointFilter())
+
     _log = logging.getLogger(__name__)
-    _log.info("Workspace settings successfully loaded")
 
     # Load the initial plugins
     from ..plugin.parser import get_config_from_plugins, load_all_plugins
@@ -48,7 +55,6 @@ def create_visyn_server(
     visyn_server_settings = create_model("VisynServerSettings", __base__=GlobalSettings, **plugin_settings_models)
     # Patch the global settings by instantiating the new settings model with the global config, all config.json(s), and pydantic models
     manager.settings = visyn_server_settings(**deep_update(*plugin_config_files, workspace_config))
-    _log.info("All settings successfully loaded")
 
     app = FastAPI(
         debug=manager.settings.is_development_mode,
@@ -75,8 +81,6 @@ def create_visyn_server(
     app.state.registry = manager.registry = Registry()
     manager.registry.init_app(app, plugins)
 
-    _log.info("Plugin registry successfully initialized")
-
     from ..dbmanager import DBManager
 
     app.state.db = manager.db = DBManager()
@@ -111,10 +115,9 @@ def create_visyn_server(
     from .utils import init_legacy_app, load_after_server_started_hooks
 
     namespace_plugins = manager.registry.list("namespace")
-    _log.info(f"Registering {len(namespace_plugins)} legacy namespaces via WSGIMiddleware")
+    _log.info(f"Registering {len(namespace_plugins)} legacy namespace(s) via WSGIMiddleware")
     for p in namespace_plugins:
         namespace = p.namespace  # type: ignore
-        _log.info(f"Registering legacy namespace: {namespace}")
 
         sub_app = p.load().factory()
         init_legacy_app(sub_app)
@@ -123,10 +126,9 @@ def create_visyn_server(
 
     # Load all FastAPI apis
     router_plugins = manager.registry.list("fastapi_router")
-    _log.info(f"Registering {len(router_plugins)} API-routers")
+    _log.info(f"Registering {len(router_plugins)} FastAPI router(s)")
     # Load all namespace plugins as WSGIMiddleware plugins
     for p in router_plugins:
-        _log.info(f"Registering router: {p.id}")
         app.include_router(p.load().factory())
 
     # load `after_server_started` extension points which are run immediately after server started,

tdp_core/settings/constants.py

@@ -1,19 +1,22 @@
 default_logging_dict = {
     "version": 1,
-    # "disable_existing_loggers": False,
+    "disable_existing_loggers": False,
     "formatters": {
-        "simple": {
-            "format": "%(asctime)s %(levelname)s %(name)s: %(message)s",
-            "datefmt": "%H:%M:%S",
+        "default": {
+            "()": "uvicorn.logging.DefaultFormatter",
+            "format": "%(levelprefix)s %(asctime)s | %(name)30s | %(message)s",
+            "datefmt": "%Y-%m-%d %H:%M:%S",
         },
-        "line": {"format": "%(asctime)s %(levelname)s %(name)s(%(pathname)s:%(lineno)s): %(message)s"},
+    },
+    "loggers": {
+        "uvicorn": {"handlers": ["default"]},
     },
     "handlers": {
-        "console": {
+        "default": {
             "class": "logging.StreamHandler",
-            "formatter": "simple",
-            "stream": "ext://sys.stdout",
+            "formatter": "default",
+            "stream": "ext://sys.stderr",
         }
     },
-    "root": {"level": "INFO", "handlers": ["console"]},
+    "root": {"level": "INFO", "handlers": ["default"]},
 }

tdp_core/settings/utils.py

@@ -18,7 +18,7 @@ def load_workspace_config() -> Dict[str, Any]:
         _log.info(f"Loading workspace config.json from {global_}")
         return load_config_file(global_)
     else:
-        _log.info(f"No workspace config.json found at {global_}, using empty dict as default")
+        _log.info(f"No {global_} found, using empty dict")
         return {}