diff --git a/AGENTS.md b/AGENTS.md index be65f2a0a..50710a717 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -437,6 +437,7 @@ TruffleHog, detect-secrets, large file check (max 1000KB), merge conflict marker - FL clients intentionally have no Central Hub credentials. - Cohort-query validation is three-layer and **deliberately asymmetric — do not "sync" the layers**. Only the trust-side `data_access_api.services.cohort.validate_query` is authoritative (single parse-validate-emit; length, single-statement, SELECT-only, no `INSERT`/`UPDATE`/`DELETE`/`MERGE` anywhere in the tree — a writable CTE parses as a top-level `Select`, so the shape check alone misses it — `omop`-schema pin, literal `LIMIT`/`OFFSET`; re-emits from the checked AST; backed by the read-only `data_analyst_reader` role — pass its return value to the engine, never the caller's raw string). The hub-side `flip_api.cohort_services.submit_cohort_query.validate_query` is a *fast-feedback validity pre-check only, not a security control*: it exists so a malformed query fails in-hand instead of after an async fan-out to every trust, and enforces only what every trust would reject anyway. The flip-ui cohort form validates required-field only. A trust must stay safe regardless of what the hub checked, so hub drift is safe by construction. **No layer uses a keyword denylist** — the removed one blocked legitimate `SUBSTRING()` while stopping nothing; blind extraction is defeated by the literal-`LIMIT` rule and DDL/DML by the read-only role. See [`trust/data-access-api/README.md`](trust/data-access-api/README.md#cohort-query-validation). - Row-level cohort egress is gated on `COHORT_QUERY_THRESHOLD` at **both** row-level routes — `/cohort/dataframe` (FL training data) and `/cohort/accession-ids` (the accession list that decides whose imaging is pulled into XNAT) — sharing one fixed refusal string so a below-threshold cohort is indistinguishable from an empty one. The threshold is the trust's own disclosure floor (default 10, set per trust in its kit file), enforced trust-side rather than relying on the hub's staging guard. Both gates evaluate the **live** cohort on every call: FLIP stores the cohort only as a SQL string and re-runs it against OMOP at every stage, so a project can import cleanly and later start refusing (FLIP#857). +- Logging policy (`docs/source/sys-admin.rst`, "Logging policy" / `#logging-policy`): sensitive values never appear in logs at **any** level — cohort SQL (log the 12-hex SHA-256 fingerprint from each service's `utils/log_hygiene.py`; raw driver/parser error text embeds the statement, so log exception class + SQLSTATE + fingerprint instead — both SQLAlchemy engines also set `hide_parameters=True`), accession numbers / patient-level attributes (ordinals, counts, or `flip.utils.Utils.hash_for_log`; response bodies from trust data/imaging APIs are patient-level and never logged), secrets (no request headers or bodies, no presigned URLs), full URLs (host + path only, query string always dropped), and verbatim S3 keys (bucket + `hash_s3_key` prefix, or the model-id/file-name identifiers the key derives from). Pin new log lines with a caplog test asserting the sensitive value stays out. - Do not hardcode env values in Dockerfiles or compose files. - 72-hour supply-chain cooldown on Python/npm package installs — enforced by uv `exclude-newer` (`[tool.uv]` in every `pyproject.toml`) and npm `min-release-age` (`flip-ui/.npmrc`, requires npm >= 11.10 which Node 24 LTS ships), backstopped by a `uv lock --check` CI gate in `secret-scanning.yml`. See CONTRIBUTING.md ("Dependency cooldown"). diff --git a/CLAUDE.md b/CLAUDE.md index 15bbed29b..2dfd85ad2 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -437,6 +437,7 @@ TruffleHog, detect-secrets, large file check (max 1000KB), merge conflict marker - FL clients intentionally have no Central Hub credentials. - Cohort-query validation is three-layer and **deliberately asymmetric — do not "sync" the layers**. Only the trust-side `data_access_api.services.cohort.validate_query` is authoritative (single parse-validate-emit; length, single-statement, SELECT-only, no `INSERT`/`UPDATE`/`DELETE`/`MERGE` anywhere in the tree — a writable CTE parses as a top-level `Select`, so the shape check alone misses it — `omop`-schema pin, literal `LIMIT`/`OFFSET`; re-emits from the checked AST; backed by the read-only `data_analyst_reader` role — pass its return value to the engine, never the caller's raw string). The hub-side `flip_api.cohort_services.submit_cohort_query.validate_query` is a *fast-feedback validity pre-check only, not a security control*: it exists so a malformed query fails in-hand instead of after an async fan-out to every trust, and enforces only what every trust would reject anyway. The flip-ui cohort form validates required-field only. A trust must stay safe regardless of what the hub checked, so hub drift is safe by construction. **No layer uses a keyword denylist** — the removed one blocked legitimate `SUBSTRING()` while stopping nothing; blind extraction is defeated by the literal-`LIMIT` rule and DDL/DML by the read-only role. See [`trust/data-access-api/README.md`](trust/data-access-api/README.md#cohort-query-validation). - Row-level cohort egress is gated on `COHORT_QUERY_THRESHOLD` at **both** row-level routes — `/cohort/dataframe` (FL training data) and `/cohort/accession-ids` (the accession list that decides whose imaging is pulled into XNAT) — sharing one fixed refusal string so a below-threshold cohort is indistinguishable from an empty one. The threshold is the trust's own disclosure floor (default 10, set per trust in its kit file), enforced trust-side rather than relying on the hub's staging guard. Both gates evaluate the **live** cohort on every call: FLIP stores the cohort only as a SQL string and re-runs it against OMOP at every stage, so a project can import cleanly and later start refusing (FLIP#857). +- Logging policy (`docs/source/sys-admin.rst`, "Logging policy" / `#logging-policy`): sensitive values never appear in logs at **any** level — cohort SQL (log the 12-hex SHA-256 fingerprint from each service's `utils/log_hygiene.py`; raw driver/parser error text embeds the statement, so log exception class + SQLSTATE + fingerprint instead — both SQLAlchemy engines also set `hide_parameters=True`), accession numbers / patient-level attributes (ordinals, counts, or `flip.utils.Utils.hash_for_log`; response bodies from trust data/imaging APIs are patient-level and never logged), secrets (no request headers or bodies, no presigned URLs), full URLs (host + path only, query string always dropped), and verbatim S3 keys (bucket + `hash_s3_key` prefix, or the model-id/file-name identifiers the key derives from). Pin new log lines with a caplog test asserting the sensitive value stays out. - Do not hardcode env values in Dockerfiles or compose files. - 72-hour supply-chain cooldown on Python/npm package installs — enforced by uv `exclude-newer` (`[tool.uv]` in every `pyproject.toml`) and npm `min-release-age` (`flip-ui/.npmrc`, requires npm >= 11.10 which Node 24 LTS ships), backstopped by a `uv lock --check` CI gate in `secret-scanning.yml`. See CONTRIBUTING.md ("Dependency cooldown"). diff --git a/docs/source/components/component-logging-stack.rst b/docs/source/components/component-logging-stack.rst index 8a7c5a155..12cc32654 100644 --- a/docs/source/components/component-logging-stack.rst +++ b/docs/source/components/component-logging-stack.rst @@ -52,6 +52,11 @@ pre-provisioned datasource. Application Logging ******************* +.. seealso:: + + What may appear in a log line — and what never may — is governed by the + platform :ref:`logging-policy`. + Shared library: ``log_config`` ================================ diff --git a/docs/source/sys-admin.rst b/docs/source/sys-admin.rst index 50ad2ad5b..40ecd9855 100644 --- a/docs/source/sys-admin.rst +++ b/docs/source/sys-admin.rst @@ -22,3 +22,72 @@ System administration ``deploy/providers/kubernetes/`` and the `K8s README `_ for operational notes, troubleshooting, and configuration reference. + +.. _logging-policy: + +************** +Logging policy +************** + +FLIP handles patient-level data, and log pipelines have far weaker access +control than the data paths they sit beside: trust logs are aggregated into the +observability stack, hub logs into CloudWatch, and FL run logs can be read by +model developers outside the trust. Every service therefore follows one rule +set for what may appear in a log line, at **every** log level — ``DEBUG`` +included, since a dev-tuned log level must never change what can leak. + +What is never logged +==================== + +**Cohort SQL.** A cohort query encodes patient-level selection criteria. +Log its *fingerprint* instead: the SHA-256 of the whitespace-normalised, +lower-cased query, truncated to 12 hex chars (``query sha256:ab12…``). Every +service carries the same helper (``utils/log_hygiene.py`` in flip-api, +data-access-api, and imaging-api) with the same normalisation, so hub and +trust log lines for one query carry one fingerprint — and because the hub +stores every cohort query, an operator can re-hash the stored SQL to find the +log lines it produced. This also means raw driver/parser error text +(psycopg2's ``LINE 1:`` context, SQLAlchemy's ``[SQL: …]`` suffix, sqlglot's +quoted fragment) never reaches a log — log the exception class, the SQLSTATE +where available, and the fingerprint. Both SQLAlchemy engines are additionally +built with ``hide_parameters=True`` so bound parameter values never render in +wrapped driver errors. + +**Accession numbers and any patient-level identifier or attribute.** Log +ordinals (``accession 3/17``), counts, or a fingerprint +(``flip.utils.Utils.hash_for_log``) — never the value. Response *bodies* from +the trust data and imaging APIs are patient-level material (a cohort dataframe, +DQR study metadata) and are never logged; log the status code and row/object +counts only. + +**Secrets and credentials.** No request headers (they carry the trust-internal +service key and XNAT tokens), no request bodies, no presigned URLs in any form. + +**Full URLs.** Log scheme-less host + path only; the query string is always +dropped (``encoded_query`` is base64-wrapped SQL). Exception text from HTTP +client libraries interpolates the full URL, so those messages are reduced to +the exception class before logging. + +**S3 object keys.** Log the bucket plus either a SHA-256 prefix of the key +(``flip_api.utils.s3_client.hash_s3_key``, which hashes exact bytes — keys are +case-sensitive) or the platform identifiers the key is derived from (model id, +uploaded file name — both already user-visible metadata). Never the verbatim +key or full ``s3://`` path, and never a presigned form of it. + +Working with scrubbed logs +========================== + +Fingerprints are correlation handles, not redaction theatre: the party that +legitimately holds a value (the hub's stored cohort SQL, a model developer's +own accession list, a caller's S3 key) can re-derive the fingerprint and grep +for it. When you need more context than a class name — for example a failing +cohort query — re-run the stored query against the target system rather than +relaxing a log line. + +HTTP **error response bodies** are governed separately (category-only details; +see the cohort validation notes in +`trust/data-access-api/README.md `_) +— this policy covers what lands in logs. When adding a log line, assume it will +be read by someone who must not see patient data, and pin the behaviour with a +unit test asserting the sensitive value stays out of ``caplog`` (see +``tests/services/test_cohort.py`` in data-access-api for the pattern). diff --git a/flip-api/src/flip_api/cohort_services/save_cohort_query.py b/flip-api/src/flip_api/cohort_services/save_cohort_query.py index d817bd3d3..014f185ac 100644 --- a/flip-api/src/flip_api/cohort_services/save_cohort_query.py +++ b/flip-api/src/flip_api/cohort_services/save_cohort_query.py @@ -105,5 +105,7 @@ def save_cohort_query( # Re-raise HTTP exceptions raise except Exception as e: - logger.error(f"Error saving cohort query: {str(e)}") + # Class-only: a DB error on this path renders the INSERT whose bound + # parameters include the raw cohort SQL (logging policy). + logger.error(f"Error saving cohort query: {type(e).__name__}") raise HTTPException(status_code=500, detail=f"Internal server error: {str(e)}") diff --git a/flip-api/src/flip_api/cohort_services/submit_cohort_query.py b/flip-api/src/flip_api/cohort_services/submit_cohort_query.py index dce129da9..ba670af68 100644 --- a/flip-api/src/flip_api/cohort_services/submit_cohort_query.py +++ b/flip-api/src/flip_api/cohort_services/submit_cohort_query.py @@ -31,6 +31,7 @@ ) from flip_api.domain.schemas.status import TaskType from flip_api.utils.encryption import encrypt +from flip_api.utils.log_hygiene import hash_query from flip_api.utils.logger import logger router = APIRouter(prefix="/cohort", tags=["cohort_services"]) @@ -101,8 +102,13 @@ def validate_query(query: str) -> None: except SqlglotError as e: # SqlglotError covers both ParseError and TokenError (e.g. an # unterminated string literal), so a tokenizer failure cannot bubble up - # as an unhandled 500. - logger.info({"message": "Cohort query rejected: could not be parsed as SQL.", "error": str(e)}) + # as an unhandled 500. Class + fingerprint only: sqlglot interpolates + # the offending SQL fragment into its message (logging policy). + logger.info({ + "message": "Cohort query rejected: could not be parsed as SQL.", + "error": type(e).__name__, + "query_sha256": hash_query(query), + }) raise ValueError("Query could not be parsed as SQL.") from e # sqlglot yields None for empty input and for stray semicolons (``SELECT 1; ;`` @@ -242,5 +248,7 @@ def submit_cohort_query( raise except Exception as e: db.rollback() - logger.error(f"Error submitting cohort query: {str(e)}") + # Class-only: a DB error on this path renders the INSERT whose bound + # parameters include the raw cohort SQL (logging policy). + logger.error(f"Error submitting cohort query: {type(e).__name__}") raise HTTPException(status_code=500, detail=f"Internal server error: {str(e)}") diff --git a/flip-api/src/flip_api/db/database.py b/flip-api/src/flip_api/db/database.py index 4a028e537..ba3319d6a 100644 --- a/flip-api/src/flip_api/db/database.py +++ b/flip-api/src/flip_api/db/database.py @@ -125,6 +125,11 @@ def _build_engine() -> Engine: engine = create_engine( db_url, echo=False, + # Keep bound parameter values (cohort SQL, user emails, ...) out of + # SQLAlchemy error text, which otherwise renders them in a + # ``[parameters: ...]`` suffix on every wrapped driver error + # (logging policy). + hide_parameters=True, pool_pre_ping=True, pool_recycle=_POOL_RECYCLE_SECONDS, connect_args={"sslmode": "require"}, @@ -140,7 +145,8 @@ def _build_engine() -> Engine: # encoded, which the default quote(safe="/") would not. encoded_password = quote(stt.POSTGRES_PASSWORD.strip(), safe="") db_url = f"postgresql+psycopg2://{stt.POSTGRES_USER}:{encoded_password}@{stt.DB_HOST}:{stt.DB_PORT}/{stt.POSTGRES_DB}" - return create_engine(db_url, echo=False) + # hide_parameters for the same reason as the production engine above. + return create_engine(db_url, echo=False, hide_parameters=True) # Lazily-created, reused engine. Built on first use rather than at import time diff --git a/flip-api/src/flip_api/model_services/retrieve_model.py b/flip-api/src/flip_api/model_services/retrieve_model.py index 48a015c6f..b6ddf7539 100644 --- a/flip-api/src/flip_api/model_services/retrieve_model.py +++ b/flip-api/src/flip_api/model_services/retrieve_model.py @@ -149,13 +149,14 @@ def retrieve_model( ModelStatus(result["status"]) if result["status"] in ModelStatus.__members__ else ModelStatus.ERROR ) - # Parse query from SQL result + # Parse query from SQL result. Log id-only: the IQuery repr carries the + # raw cohort SQL (logging policy). query = parse_query_from_result(result.get("query")) if result.get("query") else None - logger.debug(f"Parsed query: {query}") + logger.debug(f"Parsed query: {query.id if query else None}") # Parse files from SQL result files = parse_files_from_result(result.get("files"), model_id) if result.get("files") else [] - logger.debug(f"Parsed files: {files}") + logger.debug(f"Parsed {len(files)} files") # Lifecycle timestamps — one tiny query for creation_timestamp, one for # the tracked audit dates. Cheap; the raw SQL was already opinionated diff --git a/flip-api/src/flip_api/step_functions_services/cohort_query_step_function.py b/flip-api/src/flip_api/step_functions_services/cohort_query_step_function.py index 04f67a04d..acb80b82d 100644 --- a/flip-api/src/flip_api/step_functions_services/cohort_query_step_function.py +++ b/flip-api/src/flip_api/step_functions_services/cohort_query_step_function.py @@ -91,7 +91,10 @@ def cohort_query_step_function_endpoint( # Re-raise HTTP exceptions raise except Exception as e: - logger.exception(f"Unhandled error in cohort_query: {str(e)}") + # No ``str(e)`` in the message: the traceback logger.exception emits + # already carries the detail, and the hub engine's ``hide_parameters`` + # keeps the cohort SQL bound into DB statements out of it (logging policy). + logger.exception("Unhandled error in cohort_query") raise HTTPException( status_code=status.HTTP_500_INTERNAL_SERVER_ERROR, detail=f"Failed to process cohort query: {str(e)}" ) diff --git a/flip-api/src/flip_api/utils/log_hygiene.py b/flip-api/src/flip_api/utils/log_hygiene.py new file mode 100644 index 000000000..644df90c4 --- /dev/null +++ b/flip-api/src/flip_api/utils/log_hygiene.py @@ -0,0 +1,37 @@ +# Copyright (c) Guy's and St Thomas' NHS Foundation Trust & King's College London +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# http://www.apache.org/licenses/LICENSE-2.0 +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# + +import hashlib + + +def hash_query(query: object) -> str: + """Returns a short, stable fingerprint of a SQL query for log correlation. + + Cohort SQL encodes patient-level selection criteria, so the platform logging + policy (``docs/source/sys-admin.rst``, "Logging policy") keeps it out of logs + entirely. Log this fingerprint instead: the SHA-256 of the whitespace-normalised, + lower-cased query, truncated to 12 hex chars. The normalisation matches the + trust services' ``utils.log_hygiene.hash_query``, so hub and trust log lines + for the same cohort query carry the same fingerprint — and since the hub + stores every cohort query, an operator can re-hash the stored SQL to find + the log lines it produced. (S3 keys have their own helper: + ``utils.s3_client.hash_s3_key``, which hashes the exact bytes because keys + are case-sensitive.) + + Args: + query: The SQL query, as a string or anything whose ``str()`` is the SQL text. + + Returns: + str: A 12-hex-char fingerprint of the query. + """ + normalised = " ".join(str(query).strip().lower().split()) + return hashlib.sha256(normalised.encode()).hexdigest()[:12] diff --git a/flip-api/src/flip_api/utils/s3_client.py b/flip-api/src/flip_api/utils/s3_client.py index 68ba96202..b0b23870d 100644 --- a/flip-api/src/flip_api/utils/s3_client.py +++ b/flip-api/src/flip_api/utils/s3_client.py @@ -229,10 +229,13 @@ def delete_object(self, s3_path: str) -> None: try: bucket, key = parse_s3_path(s3_path) self.client.delete_object(Bucket=bucket, Key=key) - logger.info(f"Deleted object {key} from bucket {bucket}") + logger.info(f"Deleted object bucket={bucket} key_hash={hash_s3_key(key)}") except ClientError as e: - logger.error(f"Error deleting object {key} from bucket {bucket}: {e}") - raise Exception(f"Unable to delete object {key} from bucket {bucket}") + error_code = e.response.get("Error", {}).get("Code", "Unknown") + logger.error( + f"Error deleting object bucket={bucket} key_hash={hash_s3_key(key)} error_code={error_code}" + ) + raise Exception(f"Unable to delete object from bucket {bucket}") def delete_object_if_match(self, s3_path: str, etag: str) -> None: """ @@ -254,14 +257,21 @@ def delete_object_if_match(self, s3_path: str, etag: str) -> None: bucket, key = parse_s3_path(s3_path) try: self.client.delete_object(Bucket=bucket, Key=key, IfMatch=etag) - logger.info(f"Deleted object {key} from bucket {bucket} (ETag-pinned)") + logger.info(f"Deleted object bucket={bucket} key_hash={hash_s3_key(key)} (ETag-pinned)") except ClientError as e: error_code = e.response.get("Error", {}).get("Code", "Unknown") if error_code in ("PreconditionFailed", "412"): - logger.warning(f"ETag precondition failed deleting {s3_path}: object changed since it was scanned") - raise S3PreconditionFailedError(f"Object changed: {s3_path}") from e - logger.error(f"Error deleting object {key} from bucket {bucket}: {error_code}") - raise Exception(f"Unable to delete object {key} from bucket {bucket}") from e + logger.warning( + f"ETag precondition failed deleting bucket={bucket} key_hash={hash_s3_key(key)}: " + "object changed since it was scanned" + ) + raise S3PreconditionFailedError( + f"Object changed: bucket={bucket} key_hash={hash_s3_key(key)}" + ) from e + logger.error( + f"Error deleting object bucket={bucket} key_hash={hash_s3_key(key)} error_code={error_code}" + ) + raise Exception(f"Unable to delete object from bucket {bucket}") from e def delete_objects(self, s3_paths: list[str]) -> dict[str, Any]: """ @@ -282,7 +292,7 @@ def delete_objects(self, s3_paths: list[str]) -> dict[str, Any]: for s3_path in s3_paths: bucket, key = parse_s3_path(s3_path) if not bucket: - logger.error(f"Invalid S3 path: {s3_path}") + logger.error(f"Invalid S3 path (path_hash={hash_s3_key(s3_path)})") continue bucket_objects[bucket].append({"Key": key}) @@ -297,7 +307,10 @@ def delete_objects(self, s3_paths: list[str]) -> dict[str, Any]: }, ) deleted = [obj["Key"] for obj in response.get("Deleted", [])] - errors = [f"{err['Key']} - {err['Code']}: {err['Message']}" for err in response.get("Errors", [])] + errors = [ + f"key_hash={hash_s3_key(err['Key'])} - {err['Code']}: {err['Message']}" + for err in response.get("Errors", []) + ] if errors: logger.warning(f"Partial success deleting objects from bucket {bucket}. Errors: {errors}") @@ -307,7 +320,8 @@ def delete_objects(self, s3_paths: list[str]) -> dict[str, Any]: all_responses[bucket] = response except ClientError as e: - logger.error(f"Error batch deleting objects from bucket {bucket}: {e}") + error_code = e.response.get("Error", {}).get("Code", "Unknown") + logger.error(f"Error batch deleting objects from bucket {bucket}: error_code={error_code}") raise Exception(f"Unable to delete objects from bucket {bucket}: {str(e)}") return all_responses @@ -334,9 +348,12 @@ def get_object(self, s3_path: str) -> dict[str, Any]: response = self.client.get_object(Bucket=bucket, Key=key) return response except ClientError as e: - logger.error(f"Error getting object {key} from bucket {bucket}: {e}") + error_code = e.response.get("Error", {}).get("Code", "Unknown") + logger.error( + f"Error getting object bucket={bucket} key_hash={hash_s3_key(key)} error_code={error_code}" + ) raise EndpointConnectionError( - endpoint_url=f"https://{bucket}.s3.your-region.amazonaws.com/{key}", + endpoint_url=f"https://{bucket}.s3.your-region.amazonaws.com/{hash_s3_key(key)}", error=e, ) @@ -358,8 +375,12 @@ def head_object(self, s3_path: str) -> dict[str, Any]: response = self.client.head_object(Bucket=bucket, Key=key) return response except ClientError as e: - logger.error(f"Error getting object metadata for {key} from bucket {bucket}: {e}") - raise Exception(f"Unable to get object metadata for {key} from bucket {bucket}") + error_code = e.response.get("Error", {}).get("Code", "Unknown") + logger.error( + f"Error getting object metadata bucket={bucket} key_hash={hash_s3_key(key)} " + f"error_code={error_code}" + ) + raise Exception(f"Unable to get object metadata from bucket {bucket}") def object_exists(self, s3_path: str) -> bool: """ @@ -382,7 +403,10 @@ def object_exists(self, s3_path: str) -> bool: except ClientError as e: if e.response["Error"]["Code"] == "404": return False - logger.error(f"Error checking if object {key} exists in bucket {bucket}: {e}") + logger.error( + f"Error checking object existence bucket={bucket} key_hash={hash_s3_key(key)} " + f"error_code={e.response['Error']['Code']}" + ) raise def upload_file(self, local_path: str, s3_path: str) -> None: @@ -407,10 +431,16 @@ def upload_file(self, local_path: str, s3_path: str) -> None: # S3UploadFailedError — a boto3.exceptions type, not a botocore ClientError — so it must # be caught explicitly alongside ClientError; OSError covers a local-file read failure. self.client.upload_file(local_path, bucket, key) - logger.info(f"Successfully uploaded {local_path} to {s3_path}") + logger.info(f"Successfully uploaded {local_path} to bucket={bucket} key_hash={hash_s3_key(key)}") except (S3UploadFailedError, ClientError, OSError) as e: - logger.error(f"Error uploading {local_path} to {s3_path}: {e}") - raise Exception(f"Unable to upload file {local_path} to {s3_path}: {e}") from e + # Class-only: S3UploadFailedError's message interpolates the full + # destination key (logging policy). local_path is a hub-local + # template/temp path, which the policy allows. + logger.error( + f"Error uploading {local_path} to bucket={bucket} key_hash={hash_s3_key(key)}: " + f"{type(e).__name__}" + ) + raise Exception(f"Unable to upload file {local_path} to bucket {bucket}: {type(e).__name__}") from e def copy_object(self, source_s3_path: str, dest_s3_path: str) -> None: """ @@ -429,10 +459,17 @@ def copy_object(self, source_s3_path: str, dest_s3_path: str) -> None: copy_source = {"Bucket": source_bucket, "Key": source_key} self.client.copy_object(CopySource=copy_source, Bucket=dest_bucket, Key=dest_key) - logger.info(f"Successfully copied {source_s3_path} to {dest_s3_path}") + logger.info( + f"Successfully copied src_bucket={source_bucket} src_key_hash={hash_s3_key(source_key)} " + f"to dest_bucket={dest_bucket} dest_key_hash={hash_s3_key(dest_key)}" + ) except ClientError as e: - logger.error(f"Error copying {source_s3_path} to {dest_s3_path}: {e}") - raise Exception(f"Unable to copy object: {e}") + error_code = e.response.get("Error", {}).get("Code", "Unknown") + logger.error( + f"Error copying src_bucket={source_bucket} src_key_hash={hash_s3_key(source_key)} " + f"to dest_bucket={dest_bucket} dest_key_hash={hash_s3_key(dest_key)} error_code={error_code}" + ) + raise Exception(f"Unable to copy object: {error_code}") def copy_object_if_match(self, source_s3_path: str, dest_s3_path: str, etag: str) -> None: """ @@ -464,17 +501,25 @@ def copy_object_if_match(self, source_s3_path: str, dest_s3_path: str, etag: str dest_key, ExtraArgs={"CopySourceIfMatch": etag}, ) - logger.info(f"Successfully copied {source_s3_path} to {dest_s3_path} (ETag-pinned)") + logger.info( + f"Successfully copied src_bucket={source_bucket} src_key_hash={hash_s3_key(source_key)} " + f"to dest_bucket={dest_bucket} dest_key_hash={hash_s3_key(dest_key)} (ETag-pinned)" + ) except ClientError as e: error_code = e.response.get("Error", {}).get("Code", "Unknown") if error_code in ("PreconditionFailed", "412"): logger.warning( - f"ETag precondition failed copying {source_s3_path} to {dest_s3_path}: " - "source object changed since it was scanned" + f"ETag precondition failed copying src_bucket={source_bucket} " + f"src_key_hash={hash_s3_key(source_key)}: source object changed since it was scanned" ) - raise S3PreconditionFailedError(f"Source object changed: {source_s3_path}") from e - logger.error(f"Error copying {source_s3_path} to {dest_s3_path}: {e}") - raise Exception(f"Unable to copy object: {e}") from e + raise S3PreconditionFailedError( + f"Source object changed: bucket={source_bucket} key_hash={hash_s3_key(source_key)}" + ) from e + logger.error( + f"Error copying src_bucket={source_bucket} src_key_hash={hash_s3_key(source_key)} " + f"to dest_bucket={dest_bucket} dest_key_hash={hash_s3_key(dest_key)} error_code={error_code}" + ) + raise Exception(f"Unable to copy object: {error_code}") from e def download_file(self, s3_path: str, local_path: str) -> None: """ @@ -494,10 +539,12 @@ def download_file(self, s3_path: str, local_path: str) -> None: try: bucket, key = parse_s3_path(s3_path) self.client.download_file(bucket, key, local_path) - logger.info(f"Successfully downloaded {s3_path} to local disk") + logger.info(f"Successfully downloaded bucket={bucket} key_hash={hash_s3_key(key)} to local disk") except (ClientError, OSError) as e: - logger.error(f"Error downloading {s3_path}: {e}") - raise Exception(f"Unable to download file {s3_path}: {e}") from e + logger.error( + f"Error downloading bucket={bucket} key_hash={hash_s3_key(key)}: {type(e).__name__}" + ) + raise Exception(f"Unable to download file from bucket {bucket}: {type(e).__name__}") from e def list_objects(self, s3_path: str, delimiter: str = "") -> list[str]: """ @@ -535,7 +582,11 @@ def list_objects(self, s3_path: str, delimiter: str = "") -> list[str]: return full_s3_paths except ClientError as e: - error_message = f"Error listing objects under '{s3_path}': {e}" + error_code = e.response.get("Error", {}).get("Code", "Unknown") + error_message = ( + f"Error listing objects under bucket={bucket} prefix_hash={hash_s3_key(prefix)}: " + f"error_code={error_code}" + ) logger.error(error_message, exc_info=True) raise Exception(error_message) except ValueError as ve: diff --git a/flip-api/tests/unit/cohort_services/test_submit_cohort_query.py b/flip-api/tests/unit/cohort_services/test_submit_cohort_query.py index 7153203d3..adff0fde6 100644 --- a/flip-api/tests/unit/cohort_services/test_submit_cohort_query.py +++ b/flip-api/tests/unit/cohort_services/test_submit_cohort_query.py @@ -24,6 +24,7 @@ from flip_api.db.models.main_models import TrustTask from flip_api.domain.schemas.cohort import SubmitCohortQuery from flip_api.domain.schemas.status import TaskType +from flip_api.utils.log_hygiene import hash_query # Mocking the project ID for the test project_id = uuid.uuid4() @@ -193,6 +194,23 @@ def test_submit_cohort_query_rejects_unparseable_sql(mock_can_modify, mock_auth_ assert exc_info.value.status_code == 400 +@patch("flip_api.cohort_services.submit_cohort_query.can_modify_project", return_value=True) +def test_submit_cohort_query_parse_reject_log_omits_sql(mock_can_modify, mock_auth_request, caplog): + """The parse-reject log carries class + fingerprint, never the SQL. + + sqlglot interpolates the offending fragment into its error message, and + cohort SQL stays out of logs (logging policy). + """ + bad_query = "SELECT secret_criterion FRO omop.person WHERE" + + with caplog.at_level("INFO"), pytest.raises(HTTPException) as exc_info: + submit_cohort_query(mock_auth_request, _query(bad_query), MagicMock(), user_id) + + assert exc_info.value.status_code == 400 + assert "secret_criterion" not in caplog.text + assert hash_query(bad_query) in caplog.text + + @patch("flip_api.cohort_services.submit_cohort_query.can_modify_project", return_value=True) def test_submit_cohort_query_rejects_stacked_statements(mock_can_modify, mock_auth_request): """Query stacking is rejected — only one statement may be submitted.""" diff --git a/flip-api/tests/unit/file_services/test_retrieve_federated_results.py b/flip-api/tests/unit/file_services/test_retrieve_federated_results.py index d22d4a3e0..6cef9ae57 100644 --- a/flip-api/tests/unit/file_services/test_retrieve_federated_results.py +++ b/flip-api/tests/unit/file_services/test_retrieve_federated_results.py @@ -285,7 +285,9 @@ def test_list_objects_error(self): with pytest.raises(Exception, match="Error listing objects") as exc_info: s3_client.list_objects(test_bucket) - assert f"Error listing objects under '{test_bucket}'" in str(exc_info.value) + # Bucket + error code only — the prefix is hashed (logging policy). + assert "Error listing objects under bucket=test-bucket" in str(exc_info.value) + assert "error_code=NoSuchBucket" in str(exc_info.value) def test_get_presigned_url_success(self): """Test successful generation of presigned URL.""" diff --git a/flip-api/tests/unit/utils/test_s3_client.py b/flip-api/tests/unit/utils/test_s3_client.py index 580a138ce..5931d4bc6 100644 --- a/flip-api/tests/unit/utils/test_s3_client.py +++ b/flip-api/tests/unit/utils/test_s3_client.py @@ -378,7 +378,10 @@ def test_upload_file_wraps_s3_upload_failed_error(s3_client_with_mock_boto): s3, boto_instance = s3_client_with_mock_boto boto_instance.upload_file.side_effect = S3UploadFailedError("Failed to upload: AccessDenied") - with pytest.raises(Exception, match="Unable to upload file /local/f.py to s3://dest-bucket/k"): + # The wrapped message names the bucket and the error class but not the key: + # S3UploadFailedError's own text interpolates the destination key, and S3 + # keys stay out of logs and error messages (logging policy). + with pytest.raises(Exception, match="Unable to upload file /local/f.py to bucket dest-bucket"): s3.upload_file("/local/f.py", "s3://dest-bucket/k") diff --git a/flip-utils/flip/core/standard.py b/flip-utils/flip/core/standard.py index 07384c86c..e1a2bfbb9 100644 --- a/flip-utils/flip/core/standard.py +++ b/flip-utils/flip/core/standard.py @@ -152,7 +152,9 @@ def get_dataframe(self, project_id: str, query: str) -> pd.DataFrame: headers=_trust_internal_headers(), ) - self.logger.info(f"Received response status code: {response.status_code}, response text: {response.text}") + # Status only: this body IS the row-level cohort dataframe — patient rows + # including accession IDs — and FL run logs can leave the trust (logging policy). + self.logger.info(f"Received response status code: {response.status_code}") response.raise_for_status() @@ -188,7 +190,10 @@ def get_by_accession_number( self.check_accession_id(accession_id) resources = self.check_resource_type(resource_type) - self.logger.info(f"Attempting to download {resources} images for {accession_id}") + # Fingerprint only: accession numbers are patient-level identifiers and FL + # run logs can leave the trust (logging policy). + accession_ref = f"accession sha256:{Utils.hash_for_log(accession_id)}" + self.logger.info(f"Attempting to download {resources} images for {accession_ref}") payload = { "encrypted_central_hub_project_id": project_id, @@ -212,11 +217,12 @@ def get_by_accession_number( }, headers=_trust_internal_headers(), ) - self.logger.info(f"Received response status code: {response.status_code}, response text: {response.text}") + # Status only: response bodies stay out of logs (logging policy). + self.logger.info(f"Received response status code: {response.status_code}") response.raise_for_status() - self.logger.info(f"Successfully downloaded {resource} images for {accession_id}") + self.logger.info(f"Successfully downloaded {resource} images for {accession_ref}") imaging_service_response_json = response.json() @@ -307,7 +313,8 @@ def update_status(self, model_id: str, new_model_status: ModelStatus) -> None: headers=_hub_internal_headers(), timeout=_HUB_POST_TIMEOUT_SECONDS, ) - self.logger.info(f"Received response status code: {response.status_code}, response text: {response.text}") + # Status only: response bodies stay out of logs (logging policy). + self.logger.info(f"Received response status code: {response.status_code}") response.raise_for_status() self.logger.info(f"Successfully updated model status to [{new_model_status}]") @@ -373,7 +380,8 @@ def send_metrics( headers=_hub_internal_headers(), timeout=_HUB_POST_TIMEOUT_SECONDS, ) - self.logger.info(f"Received response status code: {response.status_code}, response text: {response.text}") + # Status only: response bodies stay out of logs (logging policy). + self.logger.info(f"Received response status code: {response.status_code}") response.raise_for_status() self.logger.info(f"Successfully sent metrics for {client_name}") @@ -428,7 +436,8 @@ def send_handled_exception(self, formatted_exception: str, client_name: str | No headers=_hub_internal_headers(), timeout=_HUB_POST_TIMEOUT_SECONDS, ) - self.logger.info(f"Received response status code: {response.status_code}, response text: {response.text}") + # Status only: response bodies stay out of logs (logging policy). + self.logger.info(f"Received response status code: {response.status_code}") response.raise_for_status() self.logger.info(f"Successfully sent the exception raised by {client_name}") @@ -495,7 +504,8 @@ def send_event( # and then stalls would freeze result acceptance mid-round. timeout=_HUB_POST_TIMEOUT_SECONDS, ) - self.logger.info(f"Received response status code: {response.status_code}, response text: {response.text}") + # Status only: response bodies stay out of logs (logging policy). + self.logger.info(f"Received response status code: {response.status_code}") response.raise_for_status() self.logger.info(f"Successfully sent {event_type} for round {global_round}") @@ -570,13 +580,15 @@ def upload_results_to_s3(self, results_folder: Path, model_id: str) -> None: @override def cleanup(self, path: Path) -> None: """Cleans up local files by deleting the specified path.""" - self.logger.info(f"Cleaning up path: {path}") + # Fingerprint only: the download path is named after the accession it + # holds, and rmtree error text names the files it failed on (logging policy). + path_ref = f"path sha256:{Utils.hash_for_log(path)}" + self.logger.info(f"Cleaning up downloaded data ({path_ref})") try: shutil.rmtree(path) except Exception as e: - self.logger.error(f"Failed to clean up path: {path}, see exception below") - self.logger.exception(e) - raise Exception(f"Failed to clean up path: {path}") from e + self.logger.error(f"Failed to clean up downloaded data ({path_ref}): {type(e).__name__}") + raise Exception("Failed to clean up downloaded data") from e class FLIPStandardDev(FLIPBase): diff --git a/flip-utils/flip/utils/utils.py b/flip-utils/flip/utils/utils.py index 08c121ca0..00597bb4f 100644 --- a/flip-utils/flip/utils/utils.py +++ b/flip-utils/flip/utils/utils.py @@ -12,6 +12,7 @@ """Utility functions for FLIP.""" +import hashlib from typing import Any from uuid import UUID @@ -48,3 +49,26 @@ def is_string_empty(val: str) -> bool: bool: True if empty or whitespace-only, False otherwise """ return val.strip() == "" + + @staticmethod + def hash_for_log(value: Any) -> str: + """ + Return a short, stable fingerprint of a sensitive value for log correlation. + + Accession numbers are patient-level linkage identifiers and download paths + are named after them, so the platform logging policy (FLIP docs, + sys-admin "Logging policy") keeps them out of logs — including the FL run + logs this package writes, which can leave the trust. Log this fingerprint + instead: the SHA-256 of the whitespace-normalised, lower-cased value, + truncated to 12 hex chars. Anyone holding the original value (e.g. a model + developer with their cohort's accession list) can re-derive it to find + matching log lines. + + Args: + value: The sensitive value (will be converted to string). + + Returns: + str: A 12-hex-char fingerprint of the value. + """ + normalised = " ".join(str(value).strip().lower().split()) + return hashlib.sha256(normalised.encode()).hexdigest()[:12] diff --git a/flip-utils/tests/unit/core/test_standard.py b/flip-utils/tests/unit/core/test_standard.py index 85abd0fcb..4f3f3657c 100644 --- a/flip-utils/tests/unit/core/test_standard.py +++ b/flip-utils/tests/unit/core/test_standard.py @@ -25,6 +25,7 @@ from flip.core.standard import FLIPStandardDev, FLIPStandardProd from flip.exceptions import ResultsUploadError from flip.schemas import FLLogEvent +from flip.utils.utils import Utils class TestFLIPStandardDevGetDataframe: @@ -832,7 +833,9 @@ def test_cleanup_raises_when_rmtree_fails(self, flip_prod, tmp_path): cleanup_dir = tmp_path / "to_cleanup" with patch("flip.core.standard.shutil.rmtree", side_effect=OSError("permission denied")) as mock_rmtree: - with pytest.raises(Exception, match="Failed to clean up path"): + # The message names no path: cleanup paths are accession-named and the + # exception can surface in FL run logs (logging policy). + with pytest.raises(Exception, match="Failed to clean up downloaded data"): flip_prod.cleanup(cleanup_dir) mock_rmtree.assert_called_once_with(cleanup_dir) @@ -862,3 +865,80 @@ def test_cleanup_does_not_delete_path_in_dev_mode(self, flip_dev, tmp_path): flip_dev.cleanup(cleanup_dir) assert cleanup_dir.exists() + + +class TestFLIPStandardProdLogHygiene: + """FL run logs can leave the trust, so patient-level values stay out of them (logging policy). + + The package logger sets ``propagate = False``, so these tests patch the + instance logger and inspect its call args instead of using ``caplog``. + """ + + @pytest.fixture + def flip_prod(self): + """Create a FLIPStandardProd instance.""" + return FLIPStandardProd() + + @staticmethod + def _logged_text(mock_logger): + calls = mock_logger.info.call_args_list + mock_logger.error.call_args_list + return " | ".join(str(arg) for call in calls for arg in call.args) + + def test_get_by_accession_number_log_omits_accession_id(self, flip_prod, tmp_path): + """Logs carry the accession fingerprint, never the accession number itself.""" + mock_response = Mock() + mock_response.status_code = 200 + mock_response.json.return_value = {"path": str(tmp_path / "data")} + + with ( + patch("flip.core.standard.FlipConstants") as mock_constants, + patch("flip.core.standard.requests.post", return_value=mock_response), + patch.object(flip_prod, "logger") as mock_logger, + ): + mock_constants.IMAGING_API_URL = "https://imaging.example.com" + mock_constants.NET_ID = "net-1" + mock_constants.TRUST_INTERNAL_SERVICE_KEY_HEADER = "x-trust-internal-service-key" + mock_constants.TRUST_INTERNAL_SERVICE_KEY = "test-trust-internal-key" + + flip_prod.get_by_accession_number( + project_id="proj-1", accession_id="ACC001", resource_type=ResourceType.DICOM + ) + + logged = self._logged_text(mock_logger) + assert "ACC001" not in logged + assert f"sha256:{Utils.hash_for_log('ACC001')}" in logged + + def test_get_dataframe_log_omits_response_body(self, flip_prod): + """The row-level cohort body never reaches the log — status code only.""" + mock_response = Mock() + mock_response.status_code = 200 + mock_response.text = json.dumps({"accession_id": ["ACC001"], "condition": ["sensitive_condition"]}) + + with ( + patch("flip.core.standard.FlipConstants") as mock_constants, + patch("flip.core.standard.requests.post", return_value=mock_response), + patch.object(flip_prod, "logger") as mock_logger, + ): + mock_constants.DATA_ACCESS_API_URL = "https://data.example.com" + mock_constants.TRUST_INTERNAL_SERVICE_KEY_HEADER = "x-trust-internal-service-key" + mock_constants.TRUST_INTERNAL_SERVICE_KEY = "test-trust-internal-key" + + df = flip_prod.get_dataframe(project_id="proj-1", query="SELECT * FROM omop.person") + + assert list(df["accession_id"]) == ["ACC001"] + logged = self._logged_text(mock_logger) + assert "ACC001" not in logged + assert "sensitive_condition" not in logged + + def test_cleanup_log_omits_path(self, flip_prod, tmp_path): + """Cleanup logs a path fingerprint — the path itself is accession-named.""" + cleanup_dir = tmp_path / "ACC001" + cleanup_dir.mkdir() + + with patch.object(flip_prod, "logger") as mock_logger: + flip_prod.cleanup(cleanup_dir) + + assert not cleanup_dir.exists() + logged = self._logged_text(mock_logger) + assert "ACC001" not in logged + assert f"sha256:{Utils.hash_for_log(cleanup_dir)}" in logged diff --git a/flip-utils/tests/unit/utils/test_utils.py b/flip-utils/tests/unit/utils/test_utils.py index 0bb82be3f..6e051d47f 100644 --- a/flip-utils/tests/unit/utils/test_utils.py +++ b/flip-utils/tests/unit/utils/test_utils.py @@ -96,3 +96,24 @@ def test_none_value_raises_error(self): """Should raise AttributeError for None value.""" with pytest.raises(AttributeError): Utils.is_string_empty(None) + + +class TestUtilsHashForLog: + """Test Utils.hash_for_log static method.""" + + def test_stable_across_whitespace_and_case(self): + """The fingerprint normalises whitespace and case before hashing.""" + assert Utils.hash_for_log("ACC001") == Utils.hash_for_log(" acc001\n") + + def test_is_short_hex(self): + """The fingerprint is a 12-char hex string, not the original value.""" + fingerprint = Utils.hash_for_log("ACC001") + assert len(fingerprint) == 12 + assert "ACC001" not in fingerprint + int(fingerprint, 16) # raises if not hex + + def test_accepts_non_string_values(self): + """Path-like and other objects hash via their string form.""" + from pathlib import Path + + assert Utils.hash_for_log(Path("/data/ACC001")) == Utils.hash_for_log("/data/acc001") diff --git a/trust/data-access-api/data_access_api/db/database.py b/trust/data-access-api/data_access_api/db/database.py index a48f7c809..134fddf22 100644 --- a/trust/data-access-api/data_access_api/db/database.py +++ b/trust/data-access-api/data_access_api/db/database.py @@ -17,4 +17,8 @@ engine = create_engine( get_settings().OMOP_DATABASE_URL.get_secret_value(), echo=False, + # Keep bind-parameter values (e.g. person_id lists from the statistics + # queries) out of SQLAlchemy error text, which otherwise renders them in a + # ``[parameters: ...]`` suffix on every wrapped driver error (logging policy). + hide_parameters=True, ) diff --git a/trust/data-access-api/data_access_api/routers/cohort.py b/trust/data-access-api/data_access_api/routers/cohort.py index 8df5cb4db..809ae4c96 100644 --- a/trust/data-access-api/data_access_api/routers/cohort.py +++ b/trust/data-access-api/data_access_api/routers/cohort.py @@ -80,7 +80,10 @@ def receive_cohort_query(query_input: CohortQueryInput) -> StatisticsResponse: # drop duplicate columns df = df.loc[:, ~df.columns.duplicated()] except Exception as e: - logger.error(f"Error executing query: {str(e)}") + # Class-only: get_records has already logged the categorised driver error + # with a query fingerprint, and raw exception text on this path can embed + # the cohort SQL (logging policy). + logger.error(f"Error executing query: {type(e).__name__}") raise e try: diff --git a/trust/data-access-api/data_access_api/services/cohort.py b/trust/data-access-api/data_access_api/services/cohort.py index be36a9282..bd988fda2 100644 --- a/trust/data-access-api/data_access_api/services/cohort.py +++ b/trust/data-access-api/data_access_api/services/cohort.py @@ -29,6 +29,7 @@ from data_access_api.db.database import engine from data_access_api.routers.schema import CohortQueryInput, StatisticsResponse from data_access_api.services.query_cache import get_cached_result, set_cached_result +from data_access_api.utils.log_hygiene import hash_query from data_access_api.utils.logger import logger from data_access_api.utils.sql_parsers import extract_missing_identifier @@ -66,11 +67,27 @@ ) -def _invalid_query(detail: str) -> HTTPException: - logger.warning(f"Query validation failed: {detail}") +def _invalid_query(detail: str, log_detail: str | None = None) -> HTTPException: + logger.warning(f"Query validation failed: {log_detail or detail}") return HTTPException(status_code=400, detail=detail) +def _describe_db_error(exc: BaseException | None) -> str: + """Category-only description of a driver error, safe to log. + + Driver error text interpolates the statement — psycopg2 appends the offending + line as ``LINE 1: ...`` context and SQLAlchemy appends a full ``[SQL: ...]`` + suffix — and the statement here is the caller's cohort SQL, which the logging + policy keeps out of logs entirely. Log the error class and SQLSTATE instead; + the query fingerprint logged alongside identifies which query failed. + ``None`` is accepted because ``DBAPIError.orig`` is optional in SQLAlchemy's types. + """ + if exc is None: + return "UnknownDriverError" + pgcode = getattr(exc, "pgcode", None) + return f"{type(exc).__name__} (sqlstate={pgcode})" if pgcode else type(exc).__name__ + + def validate_query(query: str) -> str: """ Validates that an inbound SQL query is structurally safe to run against OMOP. @@ -138,7 +155,17 @@ def validate_query(query: str) -> str: # SqlglotError is the parent of both ParseError (e.g. "SELECT FROM") and # TokenError (e.g. unterminated string literals); catch the parent so a # tokenizer failure can't bubble up as an unhandled 500. - raise _invalid_query(f"Could not parse SQL query: {e}") from e + # + # Neither the detail nor the log carries the parser's message: sqlglot + # interpolates the offending SQL fragment into it, and SQL stays out of + # logs (and out of bodies the trust forwards) per the logging policy. + # Friendly parse feedback is the hub pre-check's job — a parse-invalid + # query normally fails there before it ever reaches a trust, so this + # branch only fires for callers that bypassed or outran the hub. + raise _invalid_query( + "Could not parse SQL query.", + log_detail=f"could not parse SQL ({type(e).__name__}, query sha256:{hash_query(query)})", + ) from e # sqlglot returns ``None`` for empty/whitespace input and for stray semicolons # (e.g. ``SELECT 1; ;`` parses to ``[Select, None]``). Reject if the result is @@ -229,8 +256,13 @@ def get_records( # Error responses are deliberately category-only (S-8): the trust forwards # this HTTPException detail to the central hub, which surfaces it through # the cohort UI to every project member. Raw psycopg / SQLAlchemy text can - # leak row values, constraint names, and connection-pool internals — so we - # log the full error here for ops and return only a category to the caller. + # leak row values, constraint names, and connection-pool internals. + # The LOG is category-only too: driver error text interpolates the statement + # (psycopg2's ``LINE 1: ...`` context, SQLAlchemy's ``[SQL: ...]`` suffix), + # and the statement here is the caller's cohort SQL, which the logging + # policy keeps out of logs. Ops diagnostics keep the error class, SQLSTATE, + # and a query fingerprint (``hash_query``) that the hub-stored SQL can be + # re-hashed against to identify the failing query. # UndefinedTable / UndefinedColumn are an intentional exception: they echo # back identifiers the OPERATOR typed in their own SQL (against the public # OMOP CDM schema), so they leak no data while remaining a useful diagnostic. @@ -240,47 +272,49 @@ def get_records( # __cause__. We unwrap the cause here so the UndefinedTable / UndefinedColumn # diagnostic path still works when pd.read_sql is used directly. except PandasDatabaseError as e: + query_ref = f"query sha256:{hash_query(query)}" cause = e.__cause__ if isinstance(cause, DBAPIError): orig = cause.orig error_msg = str(orig).strip() if isinstance(orig, pg_errors.UndefinedTable): table_name = extract_missing_identifier(error_msg, r'relation "([^"]+)" does not exist') - logger.error(f"UndefinedTable: {error_msg}") + logger.error(f"UndefinedTable: relation '{table_name}' does not exist ({query_ref})") raise HTTPException(status_code=400, detail=f"The table '{table_name}' does not exist.") from e elif isinstance(orig, pg_errors.UndefinedColumn): column_name = extract_missing_identifier(error_msg, r'column "([^"]+)" does not exist') - logger.error(f"UndefinedColumn: {error_msg}") + logger.error(f"UndefinedColumn: column '{column_name}' does not exist ({query_ref})") raise HTTPException(status_code=400, detail=f"The column '{column_name}' does not exist.") from e else: - logger.error(f"Database error (via pandas): {error_msg}") + logger.error(f"Database error (via pandas): {_describe_db_error(orig)} ({query_ref})") raise HTTPException(status_code=500, detail="query_failed") from e - logger.error(f"Pandas database error: {str(e)}") + logger.error(f"Pandas database error: {type(e).__name__} ({query_ref})") raise HTTPException(status_code=500, detail="internal_error") from e except DBAPIError as e: + query_ref = f"query sha256:{hash_query(query)}" orig = e.orig error_msg = str(orig).strip() if isinstance(orig, pg_errors.UndefinedTable): table_name = extract_missing_identifier(error_msg, r'relation "([^"]+)" does not exist') - logger.error(f"UndefinedTable: {error_msg}") + logger.error(f"UndefinedTable: relation '{table_name}' does not exist ({query_ref})") raise HTTPException(status_code=400, detail=f"The table '{table_name}' does not exist.") from e elif isinstance(orig, pg_errors.UndefinedColumn): column_name = extract_missing_identifier(error_msg, r'column "([^"]+)" does not exist') - logger.error(f"UndefinedColumn: {error_msg}") + logger.error(f"UndefinedColumn: column '{column_name}' does not exist ({query_ref})") raise HTTPException(status_code=400, detail=f"The column '{column_name}' does not exist.") from e else: - logger.error(f"Database error: {error_msg}") + logger.error(f"Database error: {_describe_db_error(orig)} ({query_ref})") raise HTTPException(status_code=500, detail="query_failed") from e except SQLAlchemyError as e: - logger.error(f"SQLAlchemy error: {str(e)}") + logger.error(f"SQLAlchemy error: {type(e).__name__} (query sha256:{hash_query(query)})") raise HTTPException(status_code=500, detail="internal_error") from e except Exception as e: - logger.error(f"Unexpected error executing query: {str(e)}") + logger.error(f"Unexpected error executing query: {type(e).__name__} (query sha256:{hash_query(query)})") raise HTTPException(status_code=500, detail="internal_error") from e diff --git a/trust/data-access-api/data_access_api/utils/log_hygiene.py b/trust/data-access-api/data_access_api/utils/log_hygiene.py new file mode 100644 index 000000000..e862b7a31 --- /dev/null +++ b/trust/data-access-api/data_access_api/utils/log_hygiene.py @@ -0,0 +1,36 @@ +# Copyright (c) Guy's and St Thomas' NHS Foundation Trust & King's College London +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# http://www.apache.org/licenses/LICENSE-2.0 +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# + +import hashlib + + +def hash_query(query: object) -> str: + """Returns a short, stable fingerprint of a SQL query for log correlation. + + Cohort SQL encodes patient-level selection criteria, so the platform logging + policy (``docs/source/sys-admin.rst``, "Logging policy") keeps it out of logs + entirely. Log this fingerprint instead: the SHA-256 of the whitespace-normalised, + lower-cased query, truncated to 12 hex chars. The normalisation matches + ``services.query_cache._make_cache_key`` for a parameterless query, so cache + log lines and error log lines for the same query carry the same fingerprint, + and an operator holding the original SQL can re-derive it to find matching + log lines. + + Args: + query: The SQL query, as a string or anything whose ``str()`` is the SQL + text (e.g. a SQLAlchemy ``TextClause``). + + Returns: + str: A 12-hex-char fingerprint of the query. + """ + normalised = " ".join(str(query).strip().lower().split()) + return hashlib.sha256(normalised.encode()).hexdigest()[:12] diff --git a/trust/data-access-api/tests/services/test_cohort.py b/trust/data-access-api/tests/services/test_cohort.py index 095d4339a..762619f3f 100644 --- a/trust/data-access-api/tests/services/test_cohort.py +++ b/trust/data-access-api/tests/services/test_cohort.py @@ -34,7 +34,8 @@ validate_query, verify_cardinality, ) -from data_access_api.services.query_cache import clear_cache +from data_access_api.services.query_cache import _make_cache_key, clear_cache +from data_access_api.utils.log_hygiene import hash_query @pytest.fixture(autouse=True) @@ -228,9 +229,10 @@ def test_get_records_other_dbapi_error(mock_read_sql): query = "SELECT * FROM test_table" - # S-8: error details are category-only — raw psycopg text stays in trust - # logs but never reaches the HTTPException body (which the hub forwards - # to every project member via the cohort UI). + # S-8: error details are category-only — never reaching the HTTPException + # body (which the hub forwards to every project member via the cohort UI). + # The trust log is category-only too: error class + SQLSTATE + query + # fingerprint, never the raw driver text (logging policy). with pytest.raises(HTTPException) as exc_info: get_records(query) assert exc_info.value.detail == "query_failed" @@ -240,7 +242,8 @@ def test_get_records_other_dbapi_error(mock_read_sql): @patch("pandas.read_sql") def test_get_records_sqlalchemy_error(mock_read_sql): """SQLAlchemy errors collapse to ``internal_error`` — the raw text - (which can include connection strings, pool internals) stays in logs. + (which can include connection strings, pool internals, and the statement) + reaches neither the body nor the log (logging policy). """ mock_sqlalchemy_error = SQLAlchemyError("SQLAlchemy connection error") mock_read_sql.side_effect = mock_sqlalchemy_error @@ -1299,3 +1302,100 @@ def read_sql_side_effect(query, *args, **kwargs): other_sex = next((item for item in sex_data["results"] if item["value"] == "Other"), None) assert other_sex is not None assert other_sex["count"] == 8 + + +# --------------------------------------------------------------------------- +# Logging policy: SQL never appears in logs (docs/source/sys-admin.rst, +# "Logging policy"). Errors log the exception class + a query fingerprint. +# --------------------------------------------------------------------------- + + +@patch("pandas.read_sql") +def test_get_records_db_error_log_omits_sql(mock_read_sql, caplog): + """A driver error whose text embeds the statement must not reach the log. + + psycopg2 appends the offending line as ``LINE 1: ...`` context; the log must + carry only the error class, SQLSTATE, and a query fingerprint. + """ + query = "SELECT secret_criterion FROM omop.person WHERE person_id = 42" + + mock_pg_error = Exception(f"syntax error at or near \"secret_criterion\"\nLINE 1: {query}") + mock_dbapi_error = DBAPIError("statement", "params", mock_pg_error) + mock_dbapi_error.orig = mock_pg_error + + mock_read_sql.side_effect = mock_dbapi_error + + with caplog.at_level("ERROR"), pytest.raises(HTTPException): + get_records(query) + + assert "secret_criterion" not in caplog.text + assert "LINE 1" not in caplog.text + assert f"query sha256:{hash_query(query)}" in caplog.text + + +@patch("pandas.read_sql") +def test_get_records_undefined_table_log_identifier_only(mock_read_sql, caplog): + """UndefinedTable logs the extracted identifier, not the raw driver text. + + The identifier is an operator-echo diagnostic (it names a table the operator + typed against the public OMOP CDM schema); the psycopg2 ``LINE 1: ...`` + context around it embeds the rest of the query and must be dropped. + """ + query = "SELECT sensitive_condition FROM missing_table" + + mock_pg_error = pg_errors.UndefinedTable() + mock_pg_error.args = (f'relation "missing_table" does not exist\nLINE 1: {query}',) + mock_dbapi_error = DBAPIError("statement", "params", mock_pg_error) + mock_dbapi_error.orig = mock_pg_error + + mock_read_sql.side_effect = mock_dbapi_error + + with caplog.at_level("ERROR"), pytest.raises(HTTPException, match="The table 'missing_table' does not exist"): + get_records(query) + + assert "missing_table" in caplog.text + assert "sensitive_condition" not in caplog.text + assert "LINE 1" not in caplog.text + assert f"query sha256:{hash_query(query)}" in caplog.text + + +@patch("pandas.read_sql") +def test_get_records_sqlalchemy_error_log_omits_sql(mock_read_sql, caplog): + """The SQLAlchemyError fallback logs class + fingerprint, not ``str(e)``.""" + query = "SELECT secret_criterion FROM omop.person" + mock_read_sql.side_effect = SQLAlchemyError(f"statement failed: {query}") + + with caplog.at_level("ERROR"), pytest.raises(HTTPException): + get_records(query) + + assert "secret_criterion" not in caplog.text + assert "SQLAlchemyError" in caplog.text + assert f"query sha256:{hash_query(query)}" in caplog.text + + +def test_validate_query_parse_error_scrubbed(caplog): + """A parse failure keeps the SQL out of both the 400 detail and the log. + + sqlglot interpolates the offending fragment into its message, the trust + forwards details to the hub, and trust-api logs error bodies — so the + detail is a fixed string and the log carries class + fingerprint only. + Friendly parse feedback is the hub pre-check's job. + """ + query = "SELECT secret_criterion FRO omop.person WHERE" + + with caplog.at_level("WARNING"), pytest.raises(HTTPException) as exc_info: + validate_query(query) + + assert exc_info.value.detail == "Could not parse SQL query." + assert "secret_criterion" not in str(exc_info.value.detail) + assert "secret_criterion" not in caplog.text + assert f"query sha256:{hash_query(query)}" in caplog.text + + +def test_hash_query_normalises_whitespace_and_case(): + """The fingerprint is stable across whitespace/case variants and matches the cache-key prefix.""" + a = hash_query("SELECT * FROM omop.person") + b = hash_query(" select *\nfrom OMOP.person ") + assert a == b + assert len(a) == 12 + assert a == _make_cache_key("SELECT * FROM omop.person")[:12] diff --git a/trust/imaging-api/imaging_api/routers/retrieval.py b/trust/imaging-api/imaging_api/routers/retrieval.py index be4d105ca..f566df84e 100644 --- a/trust/imaging-api/imaging_api/routers/retrieval.py +++ b/trust/imaging-api/imaging_api/routers/retrieval.py @@ -26,6 +26,7 @@ from imaging_api.utils.auth import get_xnat_auth_headers from imaging_api.utils.exceptions import NotFoundError from imaging_api.utils.internal_auth import authenticate_internal_service +from imaging_api.utils.log_hygiene import hash_query from imaging_api.utils.logger import logger router = APIRouter(prefix="/retrieval", tags=["Retrieval"], dependencies=[Depends(authenticate_internal_service)]) @@ -75,7 +76,8 @@ async def get_import_status_count(project_id: str, encoded_query: str, headers: # Decode the query query = base64_url_decode(encoded_query) - logger.info(f"Decoded query: {query}") + # Fingerprint only: cohort SQL never appears in logs (logging policy). + logger.info(f"Decoded cohort query (sha256:{hash_query(query)})") # Get import status import_status = await get_import_status(project_id, query, headers) @@ -128,7 +130,8 @@ async def reimport_imaging_project_studies( # Decode the query query = base64_url_decode(encoded_query) - logger.info(f"Decoded query: {query}") + # Fingerprint only: cohort SQL never appears in logs (logging policy). + logger.info(f"Decoded cohort query (sha256:{hash_query(query)})") # queue the actual retry work in the background (non-blocking) background_tasks.add_task(retry_retrieve_images_for_project, project_id, query, headers) diff --git a/trust/imaging-api/imaging_api/services/imaging.py b/trust/imaging-api/imaging_api/services/imaging.py index f4c1054f2..f1a795e9a 100644 --- a/trust/imaging-api/imaging_api/services/imaging.py +++ b/trust/imaging-api/imaging_api/services/imaging.py @@ -107,7 +107,9 @@ def query_by_accession_number(accession_number: str, headers: dict[str, str]) -> headers=headers, json=study_query.model_dump(by_alias=True), ) - logger.debug(f"Query response: {response.text} - {response.status_code} - {response.reason}") + # Status only: the DQR response body is patient-level study metadata for the + # queried accession and must never be logged (logging policy). + logger.debug(f"Query response: {response.status_code} - {response.reason}") if response.status_code == 200: logger.info("Successfully queried PACS via DQR") diff --git a/trust/imaging-api/imaging_api/services/retrieval.py b/trust/imaging-api/imaging_api/services/retrieval.py index 586178d76..16c50ab02 100644 --- a/trust/imaging-api/imaging_api/services/retrieval.py +++ b/trust/imaging-api/imaging_api/services/retrieval.py @@ -114,7 +114,12 @@ async def retrieve_images_for_project(project_id: str, query: str, headers: XNAT try: studies_found = query_by_accession_number(accession_number, headers) except Exception as e: - logger.error(f"Unexpected error querying PACS for accession number {idx}/{total_accessions}: {e}") + # Class-only: exception text here can embed the accession number or + # study metadata (e.g. a pydantic ValidationError renders its input, + # a requests error renders the full URL) — logging policy. + logger.error( + f"Unexpected error querying PACS for accession number {idx}/{total_accessions}: {type(e).__name__}" + ) continue # TODO What if multiple studies are found here for a given accession number? @@ -350,7 +355,11 @@ async def retry_retrieve_images_for_project(project_id: str, query: str, headers try: studies_found = query_by_accession_number(accession_number, headers) except Exception as e: - logger.error(f"Unexpected error querying PACS for accession number {idx}/{total_retries}: {e}") + # Class-only: exception text here can embed the accession number or + # study metadata (logging policy). + logger.error( + f"Unexpected error querying PACS for accession number {idx}/{total_retries}: {type(e).__name__}" + ) continue # TODO What if multiple studies are found here for a given accession number? diff --git a/trust/imaging-api/imaging_api/utils/log_hygiene.py b/trust/imaging-api/imaging_api/utils/log_hygiene.py new file mode 100644 index 000000000..e1d65ba52 --- /dev/null +++ b/trust/imaging-api/imaging_api/utils/log_hygiene.py @@ -0,0 +1,34 @@ +# Copyright (c) Guy's and St Thomas' NHS Foundation Trust & King's College London +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License at +# http://www.apache.org/licenses/LICENSE-2.0 +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. +# + +import hashlib + + +def hash_query(query: object) -> str: + """Returns a short, stable fingerprint of a SQL query for log correlation. + + Cohort SQL encodes patient-level selection criteria, so the platform logging + policy (``docs/source/sys-admin.rst``, "Logging policy") keeps it out of logs + entirely. Log this fingerprint instead: the SHA-256 of the whitespace-normalised, + lower-cased query, truncated to 12 hex chars. The normalisation matches + data-access-api's ``utils.log_hygiene.hash_query``, so log lines for the same + cohort query carry the same fingerprint across trust services, and an operator + holding the original SQL can re-derive it to find matching log lines. + + Args: + query: The SQL query, as a string or anything whose ``str()`` is the SQL text. + + Returns: + str: A 12-hex-char fingerprint of the query. + """ + normalised = " ".join(str(query).strip().lower().split()) + return hashlib.sha256(normalised.encode()).hexdigest()[:12] diff --git a/trust/imaging-api/tests/routers/test_retrieval.py b/trust/imaging-api/tests/routers/test_retrieval.py index 5e652a33f..14346f6c1 100644 --- a/trust/imaging-api/tests/routers/test_retrieval.py +++ b/trust/imaging-api/tests/routers/test_retrieval.py @@ -16,6 +16,7 @@ from imaging_api.routers.retrieval import base64_url_decode from imaging_api.routers.schemas import ImportStatus from imaging_api.utils.exceptions import NotFoundError +from imaging_api.utils.log_hygiene import hash_query def test_base64_url_decode(): @@ -121,3 +122,48 @@ def test_reimport_disabled(client): assert response.status_code == 418 assert "not enabled" in response.json()["detail"] + + +def test_import_status_count_log_omits_sql(client, caplog): + """The decoded cohort SQL never reaches the log — only its fingerprint does (logging policy).""" + query = "SELECT secret_criterion FROM cohort" + + mock_status = ImportStatus(successful=[], failed=[], processing=[], queued=[], queue_failed=[]) + with ( + patch("imaging_api.routers.retrieval.get_project", return_value=MagicMock()), + patch( + "imaging_api.routers.retrieval.get_import_status", + new_callable=AsyncMock, + return_value=mock_status, + ), + caplog.at_level("INFO"), + ): + response = client.get( + "/retrieval/import_status_count/PROJ1", + params={"encoded_query": _encode_query(query)}, + ) + + assert response.status_code == 200 + assert "secret_criterion" not in caplog.text + assert f"sha256:{hash_query(query)}" in caplog.text + + +def test_reimport_log_omits_sql(client, caplog): + """The reimport route logs the query fingerprint, never the SQL (logging policy).""" + query = "SELECT secret_criterion FROM cohort" + + with ( + patch("imaging_api.routers.retrieval.get_settings") as mock_settings, + patch("imaging_api.routers.retrieval.retry_retrieve_images_for_project", new_callable=AsyncMock), + caplog.at_level("INFO"), + ): + mock_settings.return_value = MagicMock(REIMPORT_STUDIES_ENABLED=True) + + response = client.put( + "/retrieval/reimport_imaging_project_studies/PROJ1", + params={"encoded_query": _encode_query(query)}, + ) + + assert response.status_code == 202 + assert "secret_criterion" not in caplog.text + assert f"sha256:{hash_query(query)}" in caplog.text diff --git a/trust/trust-api/tests/utils/test_http.py b/trust/trust-api/tests/utils/test_http.py index f6398739d..57845fc23 100644 --- a/trust/trust-api/tests/utils/test_http.py +++ b/trust/trust-api/tests/utils/test_http.py @@ -63,3 +63,49 @@ async def test_make_request_http_status_error(mock_client): assert exc_info.value.status_code == 404 assert exc_info.value.detail == "Not Found" + + +@pytest.mark.asyncio +@patch("trust_api.utils.http.httpx.AsyncClient") +async def test_make_request_log_omits_headers_body_and_params(mock_client, caplog): + """The request debug log carries method + URL only (logging policy). + + Headers carry the trust-internal service key, bodies carry cohort SQL, and + ``encoded_query`` params are base64-wrapped SQL — none may reach the log. + """ + mock_response = AsyncMock() + mock_response.status_code = 200 + mock_response.json = Mock(return_value={"message": "success"}) + mock_client.return_value.__aenter__.return_value.request.return_value = mock_response + + with caplog.at_level("DEBUG"): + await make_request( + "POST", + "http://example.com/cohort", + json_body={"query": "SELECT secret_criterion FROM omop.person"}, + params={"encoded_query": "c2VjcmV0X2NyaXRlcmlvbg"}, + headers={"X-Trust-Internal-Service-Key": "test-internal-key"}, + ) + + assert "http://example.com/cohort" in caplog.text + assert "secret_criterion" not in caplog.text + assert "test-internal-key" not in caplog.text + assert "c2VjcmV0X2NyaXRlcmlvbg" not in caplog.text + + +@pytest.mark.asyncio +@patch("trust_api.utils.http.httpx.AsyncClient") +async def test_make_request_transport_error_log_omits_query_string(mock_client, caplog): + """Transport-error logs render host + path only — the merged query string is dropped (logging policy).""" + req = httpx.Request("GET", "http://example.com/import_status?encoded_query=c2VjcmV0X2NyaXRlcmlvbg") + mock_client.return_value.__aenter__.return_value.request.side_effect = httpx.ConnectError( + "connect failed for url http://example.com/import_status?encoded_query=c2VjcmV0X2NyaXRlcmlvbg", request=req + ) + + with caplog.at_level("ERROR"), pytest.raises(HTTPException) as exc_info: + await make_request("GET", "http://example.com/import_status") + + assert exc_info.value.status_code == 502 + assert "example.com/import_status" in caplog.text + assert "c2VjcmV0X2NyaXRlcmlvbg" not in caplog.text + assert "c2VjcmV0X2NyaXRlcmlvbg" not in str(exc_info.value.detail) diff --git a/trust/trust-api/trust_api/utils/http.py b/trust/trust-api/trust_api/utils/http.py index c3e417167..f348fa6ba 100644 --- a/trust/trust-api/trust_api/utils/http.py +++ b/trust/trust-api/trust_api/utils/http.py @@ -49,7 +49,11 @@ async def make_request( params = params or {} headers = dict(headers or {}) # copy so we don't mutate callers - logger.debug(f"Making {method} request to {url} with json_body={json_body}, params={params}, headers={headers}") + # Method + URL only (the url argument carries no query string — params are + # passed separately). Never log headers (they carry the trust-internal + # service key and XNAT credentials), the body (cohort SQL rides in task + # payloads), or params (``encoded_query`` is base64-wrapped SQL) — logging policy. + logger.debug(f"Making {method} request to {url}") try: async with httpx.AsyncClient( @@ -79,11 +83,13 @@ async def make_request( except httpx.RequestError as e: # This covers DNS errors, connect timeouts, connection refused, TLS errors, etc. + # Render the target as host + path only: e.request.url carries the merged + # query string (``encoded_query`` is base64-wrapped cohort SQL), and str(e) + # can interpolate the same URL — logging policy. cause = repr(getattr(e, "__cause__", None)) - msg = ( - f"{e.__class__.__name__} when calling {method} {getattr(e, 'request', None) and e.request.url}: {e}. " - f"Cause={cause}" - ) + request = getattr(e, "request", None) + target = f"{request.url.host}{request.url.path}" if request is not None else "" + msg = f"{e.__class__.__name__} when calling {method} {target}. Cause={cause}" logger.error(msg) # Map transport layer failures to 502 for upstream callers. - raise HTTPException(status_code=502, detail=f"Failed to connect to remote service: {e}") + raise HTTPException(status_code=502, detail=f"Failed to connect to remote service: {e.__class__.__name__}")