From 3d9af6e370123ecf137d95fe800b3ef978fc40fc Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Adri=C3=A1n=20Diaz?= Date: Wed, 20 May 2026 15:01:14 +0200 Subject: [PATCH] Logs working --- apps/README.md | 28 +++++ apps/common/logging_utils.py | 95 ++++++++++++++++- apps/common/session_metadata.py | 159 ++++++++++++++++++++++++++++ apps/mutation_effect/app.py | 7 +- apps/peptide_mapper/app.py | 12 ++- apps/portal/main.py | 21 +++- apps/structure_viz/app.py | 33 +++++- docker-compose.yml | 8 ++ docker/Dockerfile | 21 +++- tests/integration/test_app_smoke.py | 9 ++ tests/unit/test_logging_utils.py | 95 ++++++++++++++++- tests/unit/test_session_metadata.py | 46 ++++++++ 12 files changed, 521 insertions(+), 13 deletions(-) create mode 100644 apps/common/session_metadata.py create mode 100644 tests/unit/test_session_metadata.py diff --git a/apps/README.md b/apps/README.md index 51bc1c7..b84aa0c 100644 --- a/apps/README.md +++ b/apps/README.md @@ -123,3 +123,31 @@ docker compose logs -f structure-viz docker compose logs -f mutation-effect docker compose logs -f scop3p-toolkit ``` + +Each service also writes the same Python logging records to a timestamped file inside +`/var/log/scop3p_toolkit` in the container. Docker Compose mounts that directory to +service-specific host paths: + +- `logs/peptide-mapper/` +- `logs/structure-viz/` +- `logs/mutation-effect/` +- `logs/scop3p-toolkit/` + +The log filename is `scop3p_toolkit_log_.log`. Each mounted directory +also contains `metadata.yml`, which records context-only FAIR execution metadata +such as app name, session start time, image version/revision/build date, Python +runtime, relevant package versions, and available external tools. + +Interactive clicks are logged explicitly. Shiny action buttons emit +`event=action_button_click` with the button id and Shiny click count; the portal +selector navbar emits `event=navbar_click` with the requested and selected app. + +Override the log location inside a container with `SCOP3P_LOG_DIR` if needed: + +```bash +docker run --rm \ + -e SCOP3P_LOG_DIR=/var/log/scop3p_toolkit \ + -v "$(pwd)/logs/peptide-mapper:/var/log/scop3p_toolkit" \ + -p 8001:8000 \ + bio2byte/peptide-mapper:0.1.0 +``` diff --git a/apps/common/logging_utils.py b/apps/common/logging_utils.py index 3a2fa07..67e767b 100644 --- a/apps/common/logging_utils.py +++ b/apps/common/logging_utils.py @@ -1,12 +1,22 @@ from __future__ import annotations +from datetime import UTC, datetime import logging import os +from pathlib import Path import sys +import tempfile from typing import Any +from common.session_metadata import write_metadata + _CONFIGURED = False +_LOG_FILE_PATH: Path | None = None +_METADATA_PATH: Path | None = None +_SESSION_STARTED_AT: str | None = None +_LOG_FORMAT = "%(asctime)s %(levelname)s %(name)s event=%(event)s %(message)s" +_DEFAULT_LOG_DIR = Path("/var/log/scop3p_toolkit") class _SafeExtraFormatter(logging.Formatter): @@ -17,20 +27,63 @@ def format(self, record: logging.LogRecord) -> str: def configure_logging() -> None: - global _CONFIGURED + global _CONFIGURED, _LOG_FILE_PATH, _METADATA_PATH, _SESSION_STARTED_AT if _CONFIGURED: return level_name = os.getenv("SCOP3P_LOG_LEVEL", "INFO").upper() level = getattr(logging, level_name, logging.INFO) + session_started_at = datetime.now(UTC).isoformat() + date_stamp = datetime.now(UTC).strftime("%Y%m%d_%H%M%S_%f") + formatter = _SafeExtraFormatter(_LOG_FORMAT) + + log_dir = _resolve_log_dir() + log_file_path = log_dir / f"scop3p_toolkit_log_{date_stamp}.log" + metadata_path = log_dir / "metadata.yml" + + stdout_handler = logging.StreamHandler(sys.stdout) + stdout_handler.setFormatter(formatter) - handler = logging.StreamHandler(sys.stdout) - handler.setFormatter( - _SafeExtraFormatter("%(asctime)s %(levelname)s %(name)s event=%(event)s %(message)s") + file_handler = logging.FileHandler(log_file_path, encoding="utf-8") + file_handler.setFormatter(formatter) + + root_logger = logging.getLogger() + root_logger.setLevel(level) + root_logger.handlers = [stdout_handler, file_handler] + + write_metadata( + metadata_path=metadata_path, + log_file_path=log_file_path, + log_dir=log_dir, + session_started_at=session_started_at, ) - logging.basicConfig(level=level, handlers=[handler]) + + _LOG_FILE_PATH = log_file_path + _METADATA_PATH = metadata_path + _SESSION_STARTED_AT = session_started_at _CONFIGURED = True + logging.getLogger("scop3p.logging").info( + "logging configured app=%s log_file=%s metadata=%s level=%s session_started_at=%s", + os.getenv("SCOP3P_APP_NAME", "unknown"), + log_file_path, + metadata_path, + logging.getLevelName(level), + session_started_at, + extra={"event": "startup"}, + ) + + +def _resolve_log_dir() -> Path: + requested = Path(os.getenv("SCOP3P_LOG_DIR", str(_DEFAULT_LOG_DIR))) + try: + requested.mkdir(parents=True, exist_ok=True) + return requested + except OSError: + fallback = Path(tempfile.gettempdir()) / "scop3p_toolkit" + fallback.mkdir(parents=True, exist_ok=True) + return fallback + class _EventAdapter(logging.LoggerAdapter): def process(self, msg: str, kwargs: dict[str, Any]) -> tuple[str, dict[str, Any]]: @@ -43,3 +96,35 @@ def process(self, msg: str, kwargs: dict[str, Any]) -> tuple[str, dict[str, Any] def get_logger(name: str) -> logging.LoggerAdapter: configure_logging() return _EventAdapter(logging.getLogger(name), {}) + + +def log_action_button_click(logger: logging.LoggerAdapter, button_id: str, click_count: Any) -> None: + logger.info( + "action_button clicked button=%s click_count=%s", + button_id, + click_count, + extra={"event": "action_button_click"}, + ) + + +def get_log_file_path() -> Path | None: + return _LOG_FILE_PATH + + +def get_metadata_path() -> Path | None: + return _METADATA_PATH + + +def get_session_started_at() -> str | None: + return _SESSION_STARTED_AT + + +def _reset_logging_for_tests() -> None: + global _CONFIGURED, _LOG_FILE_PATH, _METADATA_PATH, _SESSION_STARTED_AT + for handler in logging.getLogger().handlers: + handler.close() + logging.getLogger().handlers = [] + _CONFIGURED = False + _LOG_FILE_PATH = None + _METADATA_PATH = None + _SESSION_STARTED_AT = None diff --git a/apps/common/session_metadata.py b/apps/common/session_metadata.py new file mode 100644 index 0000000..785dbbd --- /dev/null +++ b/apps/common/session_metadata.py @@ -0,0 +1,159 @@ +from __future__ import annotations + +from importlib import metadata +import os +from pathlib import Path +import platform +import shutil +import subprocess +import sys +from typing import Any + + +_DEPENDENCIES = ( + "shiny", + "pandas", + "requests", + "numpy", + "scipy", + "networkx", + "biopython", + "py3Dmol", + "pyvis", + "bokeh", + "b2bTools", + "scop3p", +) +_TOOL_PROBES = { + "TM-align": ("TM-align",), + "hmmer": ("hmmsearch", "-h"), + "t_coffee": ("t_coffee", "-version"), +} + + +def write_metadata( + *, + metadata_path: Path, + log_file_path: Path, + log_dir: Path, + session_started_at: str, +) -> Path: + metadata_path.parent.mkdir(parents=True, exist_ok=True) + payload = build_metadata( + log_file_path=log_file_path, + log_dir=log_dir, + session_started_at=session_started_at, + ) + metadata_path.write_text(_to_yaml(payload), encoding="utf-8") + return metadata_path + + +def build_metadata(*, log_file_path: Path, log_dir: Path, session_started_at: str) -> dict[str, Any]: + return { + "schema_version": "1.0", + "application": { + "name": os.getenv("SCOP3P_APP_NAME", "unknown"), + "title": "Scop3P-Toolkit", + "description": "Tools for exploring and extending Scop3P", + }, + "session": { + "started_at_utc": session_started_at, + "working_directory": str(Path.cwd()), + "log_directory": str(log_dir), + "log_file": str(log_file_path), + }, + "image": { + "title": os.getenv("SCOP3P_IMAGE_TITLE", "Scop3P-Toolkit"), + "version": os.getenv("SCOP3P_IMAGE_VERSION", "unknown"), + "revision": os.getenv("SCOP3P_IMAGE_REVISION", "unknown"), + "created": os.getenv("SCOP3P_IMAGE_CREATED", "unknown"), + "source": os.getenv("SCOP3P_IMAGE_SOURCE", "https://github.com/Bio2Byte/Scop3P-notebooks"), + "license": os.getenv("SCOP3P_IMAGE_LICENSE", "Apache-2.0"), + }, + "runtime": { + "python": sys.version.split()[0], + "python_implementation": platform.python_implementation(), + "platform": platform.platform(), + "machine": platform.machine(), + }, + "dependencies": _dependency_versions(), + "external_tools": _external_tool_versions(), + } + + +def _dependency_versions() -> dict[str, str | None]: + versions: dict[str, str | None] = {} + for package in _DEPENDENCIES: + try: + versions[package] = metadata.version(package) + except metadata.PackageNotFoundError: + versions[package] = None + return versions + + +def _external_tool_versions() -> dict[str, dict[str, str | None]]: + return {name: _probe_tool(command) for name, command in _TOOL_PROBES.items()} + + +def _probe_tool(command: tuple[str, ...]) -> dict[str, str | None]: + executable = shutil.which(command[0]) + if executable is None: + return {"path": None, "version": None} + + try: + process = subprocess.run( + command, + check=False, + capture_output=True, + text=True, + timeout=2, + ) + except (OSError, subprocess.TimeoutExpired): + return {"path": executable, "version": None} + + output = "\n".join(part.strip() for part in (process.stdout, process.stderr) if part.strip()) + first_line = output.splitlines()[0] if output else None + return {"path": executable, "version": first_line if process.returncode == 0 else None} + + +def _to_yaml(value: Any, *, indent: int = 0) -> str: + lines = list(_yaml_lines(value, indent=indent)) + return "\n".join(lines) + "\n" + + +def _yaml_lines(value: Any, *, indent: int) -> list[str]: + prefix = " " * indent + if isinstance(value, dict): + lines: list[str] = [] + for key, item in value.items(): + if isinstance(item, dict): + lines.append(f"{prefix}{key}:") + lines.extend(_yaml_lines(item, indent=indent + 2)) + elif isinstance(item, list): + lines.append(f"{prefix}{key}:") + lines.extend(_yaml_lines(item, indent=indent + 2)) + else: + lines.append(f"{prefix}{key}: {_yaml_scalar(item)}") + return lines + if isinstance(value, list): + lines = [] + for item in value: + if isinstance(item, dict): + lines.append(f"{prefix}-") + lines.extend(_yaml_lines(item, indent=indent + 2)) + else: + lines.append(f"{prefix}- {_yaml_scalar(item)}") + return lines + return [f"{prefix}{_yaml_scalar(value)}"] + + +def _yaml_scalar(value: Any) -> str: + if value is None: + return "null" + if isinstance(value, bool): + return "true" if value else "false" + if isinstance(value, int | float): + return str(value) + text = str(value) + escaped = text.replace("\\", "\\\\").replace('"', '\\"') + return f'"{escaped}"' diff --git a/apps/mutation_effect/app.py b/apps/mutation_effect/app.py index b170fbc..0e0e383 100644 --- a/apps/mutation_effect/app.py +++ b/apps/mutation_effect/app.py @@ -14,7 +14,7 @@ MutationEffectService, MutationEffectViews, ) -from common.logging_utils import get_logger # noqa: E402 +from common.logging_utils import get_logger, log_action_button_click # noqa: E402 from common.ui_shell import scop3p_card, scop3p_shell, scop3p_footer # noqa: E402 @@ -119,6 +119,7 @@ def status() -> str: def _run_wt() -> None: try: accession_value = input.accession().strip() + log_action_button_click(LOGGER, "run_wt", input.run_wt()) LOGGER.info("run_wt requested accession=%s", accession_value or "-", extra={"event": "run_wt"}) status_text.set("Fetching UniProt sequence and Scop3P PTMs...") sequence_value = service.fetch_uniprot_sequence(accession_value) @@ -169,8 +170,10 @@ def _run_wt() -> None: @reactive.event(input.run_mut) def _run_mut() -> None: try: + log_action_button_click(LOGGER, "run_mut", input.run_mut()) LOGGER.info("run_mut requested positions=%s aas=%s", input.positions(), input.mut_aas(), extra={"event": "run_mut"}) if wt_df.get() is None or not sequence.get(): + LOGGER.warning("run_mut blocked wt prediction missing", extra={"event": "run_mut"}) raise ValueError("Run WT prediction first.") parsed_mutations = service.parse_mutations(input.positions(), input.mut_aas()) @@ -217,8 +220,10 @@ def _run_mut() -> None: @reactive.event(input.run_inf) def _run_inf() -> None: try: + log_action_button_click(LOGGER, "run_inf", input.run_inf()) LOGGER.info("run_inf requested mutations=%s", len(mutations.get()), extra={"event": "run_inf"}) if wt_df.get() is None or mut_df.get() is None: + LOGGER.warning("run_inf blocked required predictions missing", extra={"event": "run_inf"}) raise ValueError("Run WT prediction and Mutant prediction first.") status_text.set("Running inference...") diff --git a/apps/peptide_mapper/app.py b/apps/peptide_mapper/app.py index 93d7306..5781beb 100644 --- a/apps/peptide_mapper/app.py +++ b/apps/peptide_mapper/app.py @@ -10,7 +10,7 @@ import pandas as pd from shiny import App, reactive, render, ui -from common.logging_utils import get_logger +from common.logging_utils import get_logger, log_action_button_click from common.models import PeptideSelectionMode from common.peptide_mapper import PeptideMapperService, map_selection from common.services import AlphaFoldService, Scop3PClient @@ -184,8 +184,10 @@ def server(input, output, session): @reactive.event(input.load_btn) def _load_data() -> None: accession = input.accession().strip() + log_action_button_click(LOGGER, "load_btn", input.load_btn()) LOGGER.info("load requested accession=%s", accession or "-", extra={"event": "load_btn"}) if not accession: + LOGGER.warning("load blocked missing accession", extra={"event": "load_btn"}) controller.status_text.set("Enter an accession (e.g., O00571), then click Load.") return @@ -205,6 +207,7 @@ def _load_data() -> None: controller.clear_render_state() if dataframe.empty: + LOGGER.warning("load completed without rows accession=%s", accession, extra={"event": "load_btn"}) controller.status_text.set(f"No peptides returned for {accession}.") ui.update_selectize("peptides", choices={}, selected=[]) return @@ -251,8 +254,10 @@ def _update_filter_and_choices() -> None: @reactive.event(input.map_all) def _map_all() -> None: filtered = controller.filtered_dataframe.get() + log_action_button_click(LOGGER, "map_all", input.map_all()) LOGGER.info("map_all requested", extra={"event": "map_all"}) if filtered is None or filtered.empty: + LOGGER.warning("map_all blocked no filtered rows", extra={"event": "map_all"}) controller.status_text.set("No filtered rows available. Load data first.") return @@ -279,12 +284,14 @@ def _render_selection() -> None: extra={"event": "render_selection"}, ) if not accession: + LOGGER.warning("render blocked missing accession", extra={"event": "render_selection"}) controller.status_text.set("Enter an accession and click Load first.") return dataframe_all = controller.dataframe.get() dataframe_filtered = controller.filtered_dataframe.get() if dataframe_all is None or dataframe_all.empty: + LOGGER.warning("render blocked no data loaded", extra={"event": "render_selection"}) controller.status_text.set("No data loaded. Click Load first.") return @@ -353,12 +360,15 @@ def _render_selection() -> None: @reactive.event(input.export_html) def _export_html() -> None: accession = input.accession().strip() + log_action_button_click(LOGGER, "export_html", input.export_html()) LOGGER.info("export requested accession=%s", accession or "-", extra={"event": "export_html"}) if not accession: + LOGGER.warning("export blocked missing accession", extra={"event": "export_html"}) controller.status_text.set("Enter an accession first.") return if not controller.viewer_html.get() or controller.last_pdb_path.get() is None: + LOGGER.warning("export blocked no rendered selection", extra={"event": "export_html"}) controller.status_text.set("Render a selection first before exporting.") return diff --git a/apps/portal/main.py b/apps/portal/main.py index 07566a5..78f3f6c 100644 --- a/apps/portal/main.py +++ b/apps/portal/main.py @@ -8,11 +8,13 @@ from starlette.datastructures import Headers, MutableHeaders +from common.logging_utils import get_logger from mutation_effect.app import app as mutation_effect_app from peptide_mapper.app import app as peptide_mapper_app from structure_viz.app import app as structure_viz_app +LOGGER = get_logger("scop3p.portal") APP_OPTIONS = { "peptide-mapper": ("Peptide Mapper", "fa-solid fa-map-pin", peptide_mapper_app), "structure-viz": ("Structure Visualisation", "fa-solid fa-cube", structure_viz_app), @@ -30,7 +32,14 @@ def _normalize_app_key(value: str | None) -> str: def _get_selected_app_key(scope: dict[str, Any]) -> str: query_items = dict(parse_qsl(scope.get("query_string", b"").decode("utf-8"), keep_blank_values=True)) if "app" in query_items: - return _normalize_app_key(query_items["app"]) + selected = _normalize_app_key(query_items["app"]) + LOGGER.info( + "portal navbar clicked requested_app=%s selected_app=%s", + query_items["app"], + selected, + extra={"event": "navbar_click"}, + ) + return selected headers = Headers(scope=scope) cookie_header = headers.get("cookie", "") @@ -191,6 +200,7 @@ def _set_selection_cookie(headers: MutableHeaders, selected_key: str) -> None: class SingleRootPortal: def __init__(self) -> None: self.apps = {key: app for key, (_, _, app) in APP_OPTIONS.items()} + LOGGER.info("portal initialized apps=%s", ",".join(self.apps), extra={"event": "portal_startup"}) async def __call__(self, scope, receive, send) -> None: # noqa: ANN001 scope_type = scope["type"] @@ -201,6 +211,13 @@ async def __call__(self, scope, receive, send) -> None: # noqa: ANN001 selected_key = _get_selected_app_key(scope) selected_app = self.apps[selected_key] delegated_scope = _strip_selector_query(scope) + LOGGER.info( + "portal dispatch scope=%s selected_app=%s path=%s", + scope_type, + selected_key, + scope.get("path", "-"), + extra={"event": "portal_dispatch"}, + ) if scope_type == "http": await self._dispatch_http(selected_app, delegated_scope, receive, send, selected_key) @@ -261,8 +278,10 @@ async def _handle_lifespan(self, receive, send) -> None: # noqa: ANN001 while True: message = await receive() if message["type"] == "lifespan.startup": + LOGGER.info("portal lifespan startup", extra={"event": "portal_lifespan"}) await send({"type": "lifespan.startup.complete"}) elif message["type"] == "lifespan.shutdown": + LOGGER.info("portal lifespan shutdown", extra={"event": "portal_lifespan"}) await send({"type": "lifespan.shutdown.complete"}) return diff --git a/apps/structure_viz/app.py b/apps/structure_viz/app.py index bc70196..3f006ab 100644 --- a/apps/structure_viz/app.py +++ b/apps/structure_viz/app.py @@ -17,7 +17,7 @@ StructureViewerBuilder, StructureVizService, ) -from common.logging_utils import get_logger # noqa: E402 +from common.logging_utils import get_logger, log_action_button_click # noqa: E402 from common.ui_shell import scop3p_card, scop3p_shell, scop3p_footer # noqa: E402 @@ -250,6 +250,7 @@ def server(input, output, session): def require_accession() -> str | None: accession = input.accession().strip() if not accession: + LOGGER.warning("action blocked missing accession", extra={"event": "require_accession"}) controller.status.set("Please enter a UniProt accession.") return None return accession @@ -257,6 +258,7 @@ def require_accession() -> str | None: @reactive.effect @reactive.event(input.set_accession) def _set_accession() -> None: + log_action_button_click(LOGGER, "set_accession", input.set_accession()) accession = require_accession() LOGGER.info("set_accession requested accession=%s", accession or "-", extra={"event": "set_accession"}) if not accession: @@ -269,8 +271,10 @@ def _set_accession() -> None: @reactive.event(input.fetch_ptm) def _fetch_ptm() -> None: accession = controller.accession.get() + log_action_button_click(LOGGER, "fetch_ptm", input.fetch_ptm()) LOGGER.info("fetch_ptm requested accession=%s", accession or "-", extra={"event": "fetch_ptm"}) if not accession: + LOGGER.warning("fetch_ptm blocked accession not set", extra={"event": "fetch_ptm"}) controller.status.set("Set a UniProt accession first.") return dataframe = controller.service.fetch_ptms(accession) @@ -282,8 +286,10 @@ def _fetch_ptm() -> None: @reactive.event(input.fetch_variants) def _fetch_variants() -> None: accession = controller.accession.get() + log_action_button_click(LOGGER, "fetch_variants", input.fetch_variants()) LOGGER.info("fetch_variants requested accession=%s", accession or "-", extra={"event": "fetch_variants"}) if not accession: + LOGGER.warning("fetch_variants blocked accession not set", extra={"event": "fetch_variants"}) controller.status.set("Set a UniProt accession first.") return dataframe = controller.service.fetch_variants(accession) @@ -295,8 +301,10 @@ def _fetch_variants() -> None: @reactive.event(input.fetch_af) def _fetch_af() -> None: accession = controller.accession.get() + log_action_button_click(LOGGER, "fetch_af", input.fetch_af()) LOGGER.info("fetch_af requested accession=%s", accession or "-", extra={"event": "fetch_af"}) if not accession: + LOGGER.warning("fetch_af blocked accession not set", extra={"event": "fetch_af"}) controller.status.set("Set a UniProt accession first.") return af_path = controller.service.download_alphafold_pdb(accession) @@ -308,8 +316,10 @@ def _fetch_af() -> None: @reactive.event(input.render_structure) def _render_structure() -> None: accession = controller.accession.get() + log_action_button_click(LOGGER, "render_structure", input.render_structure()) LOGGER.info("render_structure requested accession=%s source=%s", accession or "-", input.structure_source(), extra={"event": "render_structure"}) if not accession: + LOGGER.warning("render_structure blocked accession not set", extra={"event": "render_structure"}) controller.status.set("Set a UniProt accession first.") return @@ -319,11 +329,13 @@ def _render_structure() -> None: if source == "af": pdb_path = controller.af_path.get() if pdb_path is None: + LOGGER.warning("render_structure blocked alphafold missing", extra={"event": "render_structure"}) controller.status.set("Fetch AlphaFold first.") return else: pdb_id = input.pdb_id().strip() if not pdb_id: + LOGGER.warning("render_structure blocked pdb id missing", extra={"event": "render_structure"}) controller.status.set("Provide a PDB ID for PDB source.") return pdb_path = controller.service.download_pdb(pdb_id) @@ -344,8 +356,10 @@ def _render_structure() -> None: @reactive.event(input.fetch_seq) def _fetch_seq() -> None: accession = controller.accession.get() + log_action_button_click(LOGGER, "fetch_seq", input.fetch_seq()) LOGGER.info("fetch_seq requested accession=%s", accession or "-", extra={"event": "fetch_seq"}) if not accession: + LOGGER.warning("fetch_seq blocked accession not set", extra={"event": "fetch_seq"}) controller.status.set("Set a UniProt accession first.") return controller.b2b_html.set("") @@ -359,8 +373,10 @@ def _fetch_seq() -> None: def _run_b2b() -> None: accession = controller.accession.get() sequence = controller.sequence.get() + log_action_button_click(LOGGER, "run_b2b", input.run_b2b()) LOGGER.info("run_b2b requested accession=%s sequence_length=%s", accession or "-", len(sequence), extra={"event": "run_b2b"}) if not accession or not sequence: + LOGGER.warning("run_b2b blocked sequence missing", extra={"event": "run_b2b"}) controller.status.set("Fetch sequence first.") return @@ -382,6 +398,7 @@ def _render_b2b() -> None: normalized = bool(input.b2b_normalized()) metric_column = _selected_b2b_metric_column(metric, normalized=normalized) af_path = controller.af_path.get() + log_action_button_click(LOGGER, "render_b2b_3d", input.render_b2b_3d()) LOGGER.info( "render_b2b requested accession=%s metric=%s normalized=%s", accession or "-", @@ -390,9 +407,11 @@ def _render_b2b() -> None: extra={"event": "render_b2b"}, ) if dataframe is None or dataframe.empty or not metric or metric_column is None: + LOGGER.warning("render_b2b blocked prediction or metric missing", extra={"event": "render_b2b"}) controller.status.set("Run predictions and choose a metric first.") return if af_path is None: + LOGGER.warning("render_b2b blocked alphafold missing", extra={"event": "render_b2b"}) controller.b2b_html.set("") controller.status.set("Fetch AlphaFold first (tab 3).") return @@ -413,6 +432,7 @@ def _render_b2b() -> None: @reactive.effect @reactive.event(input.reset_b2b) def _reset_b2b() -> None: + log_action_button_click(LOGGER, "reset_b2b", input.reset_b2b()) LOGGER.info("reset_b2b requested", extra={"event": "reset_b2b"}) _reset_b2b_state() controller.status.set("Bio2Byte results cleared.") @@ -421,8 +441,10 @@ def _reset_b2b() -> None: @reactive.event(input.rin_dl_af) def _rin_dl_af() -> None: accession = controller.accession.get() + log_action_button_click(LOGGER, "rin_dl_af", input.rin_dl_af()) LOGGER.info("rin_dl_af requested accession=%s", accession or "-", extra={"event": "rin_dl_af"}) if not accession: + LOGGER.warning("rin_dl_af blocked accession not set", extra={"event": "rin_dl_af"}) controller.status.set("Set a UniProt accession first.") return path = controller.service.download_alphafold_pdb(accession) @@ -433,6 +455,7 @@ def _rin_dl_af() -> None: @reactive.effect @reactive.event(input.build_rin) def _build_rin() -> None: + log_action_button_click(LOGGER, "build_rin", input.build_rin()) LOGGER.info("build_rin requested", extra={"event": "build_rin"}) pdb_path = controller.service.resolve_uploaded_or_remote_pdb( input.rin_upload(), @@ -442,6 +465,7 @@ def _build_rin() -> None: pdb_path = Path(controller.rin_path.get()) if pdb_path is None: + LOGGER.warning("build_rin blocked pdb source missing", extra={"event": "build_rin"}) controller.status.set("Provide a local PDB upload, an RCSB PDB ID, or download AlphaFold first.") return @@ -472,6 +496,7 @@ def _build_rin() -> None: @reactive.effect @reactive.event(input.run_tmalign) def _run_tmalign() -> None: + log_action_button_click(LOGGER, "run_tmalign", input.run_tmalign()) LOGGER.info("run_tmalign requested", extra={"event": "run_tmalign"}) try: current_signature_1 = _tm_source_signature(input.tm_pdb1(), input.tm_pdb1_id().strip()) @@ -479,6 +504,7 @@ def _run_tmalign() -> None: f1 = controller.tm_input_1.get() f2 = controller.tm_input_2.get() if f1 is None or f2 is None: + LOGGER.warning("run_tmalign blocked structures not loaded", extra={"event": "run_tmalign"}) controller.tm_report.set("Load both structures first.") controller.tm_html.set("") return @@ -487,6 +513,7 @@ def _run_tmalign() -> None: or current_signature_2 != controller.tm_loaded_signature_2.get() ): controller.tm_structures_loaded.set(False) + LOGGER.warning("run_tmalign blocked stale inputs", extra={"event": "run_tmalign"}) controller.tm_report.set("TM-align inputs changed. Reload both structures first.") controller.tm_html.set("") return @@ -523,6 +550,7 @@ def _run_tmalign() -> None: @reactive.effect @reactive.event(input.load_tmalign_structures) def _load_tmalign_structures() -> None: + log_action_button_click(LOGGER, "load_tmalign_structures", input.load_tmalign_structures()) LOGGER.info("load_tmalign_structures requested", extra={"event": "load_tmalign_structures"}) controller.tm_html.set("") controller.tm_structures_loaded.set(False) @@ -545,6 +573,7 @@ def _load_tmalign_structures() -> None: target_name="tm_input_2.pdb", ) if f1 is None or f2 is None: + LOGGER.warning("load_tmalign_structures blocked missing structure input", extra={"event": "load_tmalign_structures"}) controller.tm_input_1.set(None) controller.tm_input_2.set(None) controller.tm_chain_ranges_1.set({}) @@ -658,8 +687,10 @@ def _sync_tm_chain2_range() -> None: @reactive.effect @reactive.event(input.show_rin) def _show_rin() -> None: + log_action_button_click(LOGGER, "show_rin", input.show_rin()) LOGGER.info("show_rin requested has_html=%s", bool(controller.rin_html.get()), extra={"event": "show_rin"}) if not controller.rin_html.get(): + LOGGER.warning("show_rin blocked no rin html", extra={"event": "show_rin"}) controller.status.set("No RIN HTML yet. Build RIN first.") @render.text diff --git a/docker-compose.yml b/docker-compose.yml index 94a11f5..9fe51a3 100644 --- a/docker-compose.yml +++ b/docker-compose.yml @@ -8,6 +8,8 @@ services: image: bio2byte/scop3p-toolkit:0.1.0 ports: - "8000:8000" + volumes: + - ./logs/scop3p-toolkit:/var/log/scop3p_toolkit peptide-mapper: platform: linux/amd64 @@ -18,6 +20,8 @@ services: image: bio2byte/peptide-mapper:0.1.0 ports: - "8001:8000" + volumes: + - ./logs/peptide-mapper:/var/log/scop3p_toolkit structure-viz: platform: linux/amd64 @@ -28,6 +32,8 @@ services: image: bio2byte/structure-viz:0.1.0 ports: - "8002:8000" + volumes: + - ./logs/structure-viz:/var/log/scop3p_toolkit mutation-effect: platform: linux/amd64 @@ -38,3 +44,5 @@ services: image: bio2byte/mutation-effect:0.1.0 ports: - "8003:8000" + volumes: + - ./logs/mutation-effect:/var/log/scop3p_toolkit diff --git a/docker/Dockerfile b/docker/Dockerfile index 1cd4acf..cff988e 100644 --- a/docker/Dockerfile +++ b/docker/Dockerfile @@ -26,6 +26,10 @@ RUN --mount=type=cache,target=/root/.cache/pip \ FROM python:3.12-slim AS runtime +ARG BUILD_DATE +ARG VCS_REF +ARG VERSION=dev + LABEL org.opencontainers.image.title="Scop3P-Toolkit" \ org.opencontainers.image.description="Scop3P-Toolkit: Tools for exploring and extending Scop3P" \ org.opencontainers.image.url="https://github.com/Bio2Byte/Scop3P-notebooks" \ @@ -39,7 +43,14 @@ ENV VIRTUAL_ENV=/opt/venv \ PATH=/opt/venv/bin:$PATH \ PYTHONDONTWRITEBYTECODE=1 \ PYTHONUNBUFFERED=1 \ - PYTHONPATH=/apps + PYTHONPATH=/apps \ + SCOP3P_LOG_DIR=/var/log/scop3p_toolkit \ + SCOP3P_IMAGE_TITLE=Scop3P-Toolkit \ + SCOP3P_IMAGE_VERSION=${VERSION} \ + SCOP3P_IMAGE_REVISION=${VCS_REF} \ + SCOP3P_IMAGE_CREATED=${BUILD_DATE} \ + SCOP3P_IMAGE_SOURCE=https://github.com/Bio2Byte/Scop3P-notebooks \ + SCOP3P_IMAGE_LICENSE=Apache-2.0 RUN apt-get update && apt-get install -y --no-install-recommends \ 't-coffee' hmmer && \ @@ -47,8 +58,8 @@ RUN apt-get update && apt-get install -y --no-install-recommends \ RUN groupadd --system scop3p && \ useradd --system --gid scop3p --create-home --home-dir /home/scop3p scop3p && \ - mkdir -p /apps /tmp/scop3p && \ - chown -R scop3p:scop3p /apps /tmp/scop3p /home/scop3p + mkdir -p /apps /tmp/scop3p /var/log/scop3p_toolkit && \ + chown -R scop3p:scop3p /apps /tmp/scop3p /home/scop3p /var/log/scop3p_toolkit RUN printf '%s\n' 'export VIRTUAL_ENV=/opt/venv' 'export PATH=/opt/venv/bin:$PATH' > /etc/profile.d/scop3p-venv.sh @@ -63,13 +74,17 @@ EXPOSE 8000 USER scop3p FROM runtime AS peptide-mapper +ENV SCOP3P_APP_NAME=peptide-mapper CMD ["shiny", "run", "--host", "0.0.0.0", "--port", "8000", "/apps/peptide_mapper/app.py"] FROM runtime AS structure-viz +ENV SCOP3P_APP_NAME=structure-viz CMD ["shiny", "run", "--host", "0.0.0.0", "--port", "8000", "/apps/structure_viz/app.py"] FROM runtime AS mutation-effect +ENV SCOP3P_APP_NAME=mutation-effect CMD ["shiny", "run", "--host", "0.0.0.0", "--port", "8000", "/apps/mutation_effect/app.py"] FROM runtime AS scop3p-toolkit +ENV SCOP3P_APP_NAME=scop3p-toolkit CMD ["python", "-m", "uvicorn", "portal.main:app", "--host", "0.0.0.0", "--port", "8000"] diff --git a/tests/integration/test_app_smoke.py b/tests/integration/test_app_smoke.py index f1587fa..80246a8 100644 --- a/tests/integration/test_app_smoke.py +++ b/tests/integration/test_app_smoke.py @@ -1,5 +1,6 @@ from __future__ import annotations +from common.logging_utils import configure_logging, get_log_file_path, get_metadata_path from shiny import App from starlette.testclient import TestClient @@ -38,3 +39,11 @@ def test_portal_root_selector_and_cookie() -> None: assert selected_response.status_code == 200 assert "Structure Visualisation" in selected_response.text assert "scop3p_app=structure-viz" in selected_response.headers["set-cookie"] + + +def test_portal_logging_metadata_configured() -> None: + configure_logging() + assert get_log_file_path() is not None + metadata_path = get_metadata_path() + assert metadata_path is not None + assert metadata_path.exists() diff --git a/tests/unit/test_logging_utils.py b/tests/unit/test_logging_utils.py index 7c30a55..8a44371 100644 --- a/tests/unit/test_logging_utils.py +++ b/tests/unit/test_logging_utils.py @@ -2,8 +2,17 @@ import io import logging +import re -from common.logging_utils import _SafeExtraFormatter +from common.logging_utils import ( + _SafeExtraFormatter, + _EventAdapter, + _reset_logging_for_tests, + configure_logging, + get_log_file_path, + get_metadata_path, + log_action_button_click, +) def test_safe_extra_formatter_defaults_missing_event() -> None: @@ -19,3 +28,87 @@ def test_safe_extra_formatter_defaults_missing_event() -> None: logger.info("hello") assert "INFO event=- hello" in stream.getvalue() + + +def test_log_action_button_click_records_button_and_count() -> None: + stream = io.StringIO() + handler = logging.StreamHandler(stream) + handler.setFormatter(_SafeExtraFormatter("%(levelname)s event=%(event)s %(message)s")) + + logger = logging.getLogger("test.action_button_click") + logger.handlers = [handler] + logger.propagate = False + logger.setLevel(logging.INFO) + + log_action_button_click(_EventAdapter(logger, {}), "run_wt", 3) + + assert "INFO event=action_button_click action_button clicked button=run_wt click_count=3" in stream.getvalue() + + +def test_configure_logging_mirrors_records_to_log_file(tmp_path, monkeypatch) -> None: + _reset_logging_for_tests() + monkeypatch.setenv("SCOP3P_LOG_DIR", str(tmp_path)) + monkeypatch.setenv("SCOP3P_LOG_LEVEL", "INFO") + monkeypatch.setenv("SCOP3P_APP_NAME", "test-app") + + try: + configure_logging() + logger = logging.getLogger("test.file_logging") + logger.info("hello file", extra={"event": "unit"}) + + log_file = get_log_file_path() + assert log_file is not None + assert log_file.parent == tmp_path + assert re.fullmatch(r"scop3p_toolkit_log_\d{8}_\d{6}_\d{6}\.log", log_file.name) + + contents = log_file.read_text(encoding="utf-8") + assert "INFO test.file_logging event=unit hello file" in contents + assert "INFO scop3p.logging event=startup logging configured app=test-app" in contents + finally: + _reset_logging_for_tests() + + +def test_configure_logging_is_idempotent(tmp_path, monkeypatch) -> None: + _reset_logging_for_tests() + monkeypatch.setenv("SCOP3P_LOG_DIR", str(tmp_path)) + + try: + configure_logging() + first_log_file = get_log_file_path() + first_handlers = list(logging.getLogger().handlers) + + configure_logging() + + assert get_log_file_path() == first_log_file + assert logging.getLogger().handlers == first_handlers + assert len(logging.getLogger().handlers) == 2 + finally: + _reset_logging_for_tests() + + +def test_configure_logging_writes_metadata(tmp_path, monkeypatch) -> None: + _reset_logging_for_tests() + monkeypatch.setenv("SCOP3P_LOG_DIR", str(tmp_path)) + monkeypatch.setenv("SCOP3P_APP_NAME", "metadata-test") + monkeypatch.setenv("SCOP3P_IMAGE_VERSION", "v1.2.3") + monkeypatch.setenv("SCOP3P_IMAGE_REVISION", "abc123") + monkeypatch.setenv("SCOP3P_IMAGE_CREATED", "2026-05-19T00:00:00Z") + + try: + configure_logging() + + metadata_path = get_metadata_path() + log_file = get_log_file_path() + assert metadata_path == tmp_path / "metadata.yml" + assert log_file is not None + + contents = metadata_path.read_text(encoding="utf-8") + assert 'name: "metadata-test"' in contents + assert 'version: "v1.2.3"' in contents + assert 'revision: "abc123"' in contents + assert f'log_directory: "{tmp_path}"' in contents + assert f'log_file: "{log_file}"' in contents + assert "dependencies:" in contents + assert "external_tools:" in contents + finally: + _reset_logging_for_tests() diff --git a/tests/unit/test_session_metadata.py b/tests/unit/test_session_metadata.py new file mode 100644 index 0000000..642b171 --- /dev/null +++ b/tests/unit/test_session_metadata.py @@ -0,0 +1,46 @@ +from __future__ import annotations + +from pathlib import Path + +from common.session_metadata import build_metadata, write_metadata + + +def test_build_metadata_contains_context_only_fields(tmp_path, monkeypatch) -> None: + monkeypatch.setenv("SCOP3P_APP_NAME", "peptide-mapper") + monkeypatch.setenv("SCOP3P_IMAGE_VERSION", "v9") + monkeypatch.setenv("SCOP3P_IMAGE_REVISION", "deadbeef") + + log_file = tmp_path / "scop3p_toolkit_log_20260519_120000_000001.log" + payload = build_metadata( + log_file_path=log_file, + log_dir=tmp_path, + session_started_at="2026-05-19T12:00:00+00:00", + ) + + assert payload["application"]["name"] == "peptide-mapper" + assert payload["session"]["started_at_utc"] == "2026-05-19T12:00:00+00:00" + assert payload["session"]["log_file"] == str(log_file) + assert payload["image"]["version"] == "v9" + assert payload["image"]["revision"] == "deadbeef" + assert "python" in payload["runtime"] + assert "shiny" in payload["dependencies"] + assert "TM-align" in payload["external_tools"] + + +def test_write_metadata_creates_yaml_file(tmp_path, monkeypatch) -> None: + monkeypatch.setenv("SCOP3P_APP_NAME", "structure-viz") + metadata_path = tmp_path / "metadata.yml" + log_file = tmp_path / "scop3p_toolkit_log_20260519_120000_000001.log" + + result = write_metadata( + metadata_path=metadata_path, + log_file_path=log_file, + log_dir=Path(tmp_path), + session_started_at="2026-05-19T12:00:00+00:00", + ) + + assert result == metadata_path + contents = metadata_path.read_text(encoding="utf-8") + assert 'schema_version: "1.0"' in contents + assert 'name: "structure-viz"' in contents + assert f'log_file: "{log_file}"' in contents