Logs working

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_<date stamp>.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
+```

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

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}"'

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...")