Stop credential fragments reaching logs and error messages (#62)

bin/validate-against-mpbiopath.py

@@ -37,6 +37,7 @@
 
 sys.path.insert(0, os.path.abspath(os.path.join(os.path.dirname(__file__), "..")))
 
+from src.credential_redaction import install as _install_credential_redaction
 from src.argument_parser import logger  # noqa: E402
 from src.neo4j_connector import get_graph  # noqa: E402
 
@@ -405,6 +406,9 @@ def validate_one_pathway(
     }
 
 
+_install_credential_redaction()
+
+
 def main():
     ap = argparse.ArgumentParser()
     ap.add_argument("--output-dir", default="output", help="Where regenerated pathway dirs live")

scripts/validate_logic_network.py

@@ -21,6 +21,11 @@
 from py2neo import Graph
 import os
 
+sys.path.insert(0, str(Path(__file__).resolve().parents[1]))
+from src.credential_redaction import install as _install_credential_redaction
+
+_install_credential_redaction()
+
 # Depth limit when resolving an EntitySet to its leaf members. Sets nest a few
 # levels at most; an unbounded traversal is slow and can revisit cycles.
 MAX_SET_NESTING = 5

src/argument_parser.py

@@ -3,6 +3,8 @@
 import sys
 from argparse import Namespace
 
+from src import credential_redaction
+
 
 def parse_args() -> Namespace:
     parser: argparse.ArgumentParser = argparse.ArgumentParser(
@@ -50,5 +52,11 @@ def configure_logging(debug_flag: bool, verbose_flag: bool) -> None:
     console_handler.setFormatter(formatter)
     logging.getLogger().addHandler(console_handler)
 
+    # Credentials must not reach debug_log.txt (mode 0664), stdout or stderr.
+    # Applied here, at the output boundary, because per-call-site redaction
+    # demonstrably misses ungated exc_info in other modules, chained
+    # __cause__, and entrypoints with no handler at all.
+    credential_redaction.install()
+
 
 logger: logging.Logger = logging.getLogger(__name__)

src/credential_redaction.py

@@ -0,0 +1,126 @@
+"""Redact credential material at the output boundary.
+
+Both Reactome repositories are public, and the realistic disclosure path is
+someone pasting a log line or a stack trace into an issue. Neo4j credentials
+can be embedded in ``NEO4J_URL``, and py2neo re-emits them in its own
+exception text via ``ConnectionProfile`` and ``IPv4Address`` reprs.
+
+Redacting at each call site does not work, and an adversarial review proved
+it: gating the fourteen ``exc_info=True`` calls inside ``neo4j_connector``
+left the same secret reaching ``debug_log.txt`` through an ungated
+``exc_info=True`` two frames up in ``reaction_generator``, and reaching stderr
+entirely unhandled from ``scripts/validate_logic_network.py``. Chained
+exceptions leak it again through ``__cause__`` even when ``str()`` is clean.
+
+So redaction belongs where the text is emitted — a logging filter on every
+handler, plus an excepthook for anything uncaught — which covers paths nobody
+enumerated.
+
+Scrubbing is structural rather than value-based wherever possible. Replacing
+occurrences of the password itself is a poor primary defence here because the
+documented dev passwords are ordinary words ("reactome", "test") that appear
+in paths, keys and prose; value replacement is applied, but it substitutes the
+token rather than discarding the whole message.
+"""
+
+from __future__ import annotations
+
+import logging
+import os
+import re
+import sys
+import traceback
+from typing import Any
+
+REDACTED = "<redacted>"
+
+# scheme://userinfo@host — the userinfo is credential material by definition.
+_URL_USERINFO = re.compile(r"(?P<scheme>[A-Za-z][A-Za-z0-9+.\-]*://)[^\s/@]*@")
+
+# py2neo's own reprs, which are how a password fragment escapes even when our
+# own message is already redacted.
+_PROFILE_REPR = re.compile(r"ConnectionProfile\((['\"]).*?\1\)")
+_ADDRESS_REPR = re.compile(r"IPv4Address\(\(.*?\)\)")
+_ADDRESS6_REPR = re.compile(r"IPv6Address\(\(.*?\)\)")
+
+
+def scrub(text: str) -> str:
+    """Remove credential material from arbitrary text.
+
+    Structural first (URL userinfo, py2neo reprs), then the literal password
+    as a backstop for paths that format it directly.
+    """
+    if not text:
+        return text
+    text = _URL_USERINFO.sub(lambda m: f"{m.group('scheme')}{REDACTED}@", text)
+    text = _PROFILE_REPR.sub(f"ConnectionProfile({REDACTED})", text)
+    text = _ADDRESS_REPR.sub(f"IPv4Address({REDACTED})", text)
+    text = _ADDRESS6_REPR.sub(f"IPv6Address({REDACTED})", text)
+
+    password = os.getenv("NEO4J_PASSWORD") or ""
+    # Substituting a 1-3 character password would corrupt almost every line
+    # for no security benefit; such a value is not a secret worth protecting.
+    if len(password) >= 4 and password in text:
+        text = text.replace(password, REDACTED)
+    return text
+
+
+class CredentialRedactingFilter(logging.Filter):
+    """Scrub every log record, including its traceback, before it is emitted.
+
+    Attached to handlers rather than loggers so it applies to records
+    propagated from any module, including third-party ones.
+    """
+
+    def filter(self, record: logging.LogRecord) -> bool:
+        try:
+            message = record.getMessage()
+        except Exception:  # pragma: no cover - a broken record must still emit
+            return True
+
+        scrubbed = scrub(message)
+        if scrubbed != message:
+            record.msg = scrubbed
+            record.args = ()
+
+        if record.exc_info:
+            # Render the traceback now and scrub it; leaving exc_info set
+            # would let the handler re-render the unredacted original.
+            rendered = "".join(traceback.format_exception(*record.exc_info))
+            record.exc_text = scrub(rendered)
+            record.exc_info = None
+        elif record.exc_text:
+            record.exc_text = scrub(record.exc_text)
+        return True
+
+
+def install_log_redaction(logger: logging.Logger | None = None) -> None:
+    """Attach the filter to every handler on the root (or given) logger."""
+    target = logger if logger is not None else logging.getLogger()
+    for handler in target.handlers:
+        if not any(isinstance(f, CredentialRedactingFilter) for f in handler.filters):
+            handler.addFilter(CredentialRedactingFilter())
+
+
+def install_excepthook() -> None:
+    """Scrub uncaught tracebacks.
+
+    `scripts/validate_logic_network.py` and `bin/validate-against-mpbiopath.py`
+    construct a Graph with no handler at all, so a first-connection failure —
+    the most likely failure — printed the full chain to stderr.
+    """
+    previous = sys.excepthook
+
+    def _hook(exc_type: type, exc: BaseException, tb: Any) -> None:
+        if previous is not sys.__excepthook__:
+            previous(exc_type, exc, tb)
+            return
+        sys.stderr.write(scrub("".join(traceback.format_exception(exc_type, exc, tb))))
+
+    sys.excepthook = _hook
+
+
+def install() -> None:
+    """Install both guards. Safe to call more than once."""
+    install_log_redaction()
+    install_excepthook()

src/neo4j_connector.py

@@ -1,4 +1,6 @@
 import os
+
+from src.credential_redaction import scrub
 from typing import Any, Dict, List, Optional, Set, Union
 
 import pandas as pd
@@ -51,11 +53,61 @@ def _safe_neo4j_url() -> str:
         authority = hostpart
     else:
         authority = rest
-    # Drop any path/query, leaving host[:port].
-    authority = authority.split("/", 1)[0].split("?", 1)[0]
+    # Drop any path/query/fragment, leaving host[:port]. "#" matters because
+    # bolt://neo4j:pw@host:7687#SECRET previously kept the fragment.
+    authority = authority.split("/", 1)[0].split("?", 1)[0].split("#", 1)[0]
     return f"{scheme}://{authority}" if authority else "<neo4j-url>"
 
 
+def _safe_exception(exc: BaseException) -> str:
+    """An exception rendered without the credentials py2neo puts in its text.
+
+    `_safe_neo4j_url()` above redacts OUR message, but every caller then
+    appended `Original error: {str(e)}` — and py2neo's own text embeds the
+    ConnectionProfile, which is exactly the mis-parse that redactor exists to
+    avoid. With NEO4J_URL=bolt://neo4j:p@ssSECRET@host the appended text read:
+
+        Cannot open connection to ConnectionProfile('bolt://ssSECRET@host')
+
+    so the password fragment survived, in the same log line as the redaction.
+    Both repositories are public, and the realistic disclosure path is someone
+    pasting a stack trace into an issue.
+
+    The exception TYPE is the part with diagnostic value; the message body is
+    py2neo boilerplate plus the profile. Return the type, and the message only
+    when it is demonstrably free of credential material.
+    """
+    detail = str(exc)
+    # Anything resembling embedded credentials, an authority with userinfo, or
+    # py2neo's profile repr means the text cannot be shown.
+    unsafe = (
+        "://" in detail
+        or "ConnectionProfile" in detail
+        or "IPv4Address" in detail
+        or "@" in detail
+    )
+    if unsafe:
+        return f"{type(exc).__name__} (message withheld: may contain credentials)"
+    # A message merely CONTAINING the password is scrubbed, not withheld. The
+    # documented dev passwords here are ordinary words ("test" in README.md,
+    # "reactome" in practice), so withholding on a substring match discarded
+    # real diagnostics: "Cannot find /opt/reactome/data/graph.db" and
+    # "KeyError: 'reactome_release'" both vanished entirely.
+    return f"{type(exc).__name__}: {scrub(detail)}"
+
+
+def _traceback_kwargs() -> Dict[str, Any]:
+    """Logger kwargs for an exception on a Neo4j path.
+
+    A traceback through py2neo carries the same ConnectionProfile the message
+    does, so `**_traceback_kwargs()` reintroduces the disclosure the message fix just
+    closed. Tracebacks are opt-in via LNG_DEBUG_TRACEBACKS=1 for local
+    debugging, off by default so nothing credential-bearing reaches
+    debug_log.txt (mode 0664) or stdout.
+    """
+    return {"exc_info": os.getenv("LNG_DEBUG_TRACEBACKS") == "1"}
+
+
 # Module-level caches for bulk pre-fetched data
 _labels_cache: Dict[str, List[str]] = {}
 _components_cache: Dict[str, Dict[str, int]] = {}
@@ -326,11 +378,11 @@ def get_reaction_connections(pathway_id: str) -> pd.DataFrame:
     except ValueError:
         raise
     except Exception as e:
-        logger.error(f"Error querying Neo4j for pathway {pathway_id}", exc_info=True)
+        logger.error(f"Error querying Neo4j for pathway {pathway_id}", **_traceback_kwargs())
         raise ConnectionError(
             f"Failed to connect to Neo4j database at "
             f"{_safe_neo4j_url()}. "
-            f"Ensure Neo4j is running and accessible. Original error: {str(e)}"
+            f"Ensure Neo4j is running and accessible. Original error: {_safe_exception(e)}"
         ) from e
 
 
@@ -358,11 +410,11 @@ def get_top_level_pathways() -> List[Dict[str, Any]]:
         logger.info(f"Found {len(result)} top-level pathways")
         return result
     except Exception as e:
-        logger.error("Error in get_top_level_pathways", exc_info=True)
+        logger.error("Error in get_top_level_pathways", **_traceback_kwargs())
         raise ConnectionError(
             f"Failed to query top-level pathways from Neo4j at "
             f"{_safe_neo4j_url()}. "
-            f"Ensure Neo4j is running and accessible. Original error: {str(e)}"
+            f"Ensure Neo4j is running and accessible. Original error: {_safe_exception(e)}"
         ) from e
 
 
@@ -406,12 +458,12 @@ def get_pathway_participating_entities(pathway_id: str) -> Set[str]:
     except Exception as e:
         logger.error(
             f"Error in get_pathway_participating_entities for {pathway_id}",
-            exc_info=True,
+            **_traceback_kwargs(),
         )
         raise ConnectionError(
             f"Failed to query participating entities from Neo4j at "
             f"{_safe_neo4j_url()}. "
-            f"Original error: {str(e)}"
+            f"Original error: {_safe_exception(e)}"
         ) from e
 
 
@@ -453,12 +505,12 @@ def get_pathway_entity_reactions(
         return out
     except Exception as e:
         logger.error(
-            f"Error in get_pathway_entity_reactions for {pathway_id}", exc_info=True
+            f"Error in get_pathway_entity_reactions for {pathway_id}", **_traceback_kwargs()
         )
         raise ConnectionError(
             f"Failed to query entity reactions from Neo4j at "
             f"{_safe_neo4j_url()}. "
-            f"Original error: {str(e)}"
+            f"Original error: {_safe_exception(e)}"
         ) from e
 
 
@@ -489,11 +541,11 @@ def get_pathway_name(pathway_id: str) -> str:
     except ValueError:
         raise
     except Exception as e:
-        logger.error(f"Error in get_pathway_name for {pathway_id}", exc_info=True)
+        logger.error(f"Error in get_pathway_name for {pathway_id}", **_traceback_kwargs())
         raise ConnectionError(
             f"Failed to query pathway name from Neo4j at "
             f"{_safe_neo4j_url()}. "
-            f"Original error: {str(e)}"
+            f"Original error: {_safe_exception(e)}"
         ) from e
 
 
@@ -509,7 +561,7 @@ def get_labels(entity_id: str) -> List[str]:
         _labels_cache[entity_id] = result
         return result
     except Exception:
-        logger.error("Error in get_labels", exc_info=True)
+        logger.error("Error in get_labels", **_traceback_kwargs())
         raise
 
 
@@ -532,7 +584,7 @@ def get_complex_components(entity_id: str) -> Dict[str, int]:
         _components_cache[entity_id] = result
         return result
     except Exception:
-        logger.error("Error in get_complex_components", exc_info=True)
+        logger.error("Error in get_complex_components", **_traceback_kwargs())
         raise
 
 
@@ -555,7 +607,7 @@ def get_set_members(entity_id: str) -> Set[str]:
         _members_cache[entity_id] = result
         return result
     except Exception:
-        logger.error("Error in get_set_members", exc_info=True)
+        logger.error("Error in get_set_members", **_traceback_kwargs())
         raise
 
 
@@ -579,7 +631,7 @@ def get_reaction_input_output_ids(reaction_id: str, input_or_output: str) -> Set
     try:
         return set(get_graph().run(query, reaction_id=reaction_id).data()[0]["io_ids"])
     except Exception:
-        logger.error("Error in get_reaction_input_output_ids", exc_info=True)
+        logger.error("Error in get_reaction_input_output_ids", **_traceback_kwargs())
         raise
 
 
@@ -607,7 +659,7 @@ def get_reaction_io_stoichiometry(reaction_id: str, input_or_output: str) -> Dic
     try:
         data = get_graph().run(query, reaction_id=reaction_id).data()
     except Exception:
-        logger.error("Error in get_reaction_io_stoichiometry", exc_info=True)
+        logger.error("Error in get_reaction_io_stoichiometry", **_traceback_kwargs())
         raise
 
     result: Dict[str, int] = {}
@@ -662,7 +714,7 @@ def get_modifier_isoform_entity_set_ids() -> Set[str]:
     try:
         data = get_graph().run(query, genes=list(_MODIFIER_GENE_NAMES)).data()
     except Exception:
-        logger.error("Error in get_modifier_isoform_entity_set_ids", exc_info=True)
+        logger.error("Error in get_modifier_isoform_entity_set_ids", **_traceback_kwargs())
         raise
     _modifier_isoform_set_cache = set(data[0]["stids"]) if data else set()
     return _modifier_isoform_set_cache
@@ -692,7 +744,7 @@ def get_reference_entity_id(entity_id: str) -> Union[str, None]:
         _reference_entity_cache[entity_id] = result
         return result
     except Exception:
-        logger.error("Error in get_reference_entity_id", exc_info=True)
+        logger.error("Error in get_reference_entity_id", **_traceback_kwargs())
         raise
 
 
@@ -721,6 +773,6 @@ def get_reactome_release() -> Optional[int]:
         logger.warning(
             "Could not read the Reactome release from DBInfo; cache fingerprints "
             "will not include it.",
-            exc_info=True,
+            **_traceback_kwargs(),
         )
     return None