From f583455fdbe042015a32faca1e669bc1f74d1095 Mon Sep 17 00:00:00 2001 From: Paul Lizer Date: Thu, 1 Oct 2026 10:33:27 -0400 Subject: [PATCH 1/2] Clear the 19 py/log-injection CodeQL alerts on V2 - sanitize_log_message: add line-break replace calls after the LOG_CONTROL_CHAR_RE regex. They are no-ops at run time, so its output is unchanged, but they let CodeQL credit it as a sanitizer (alerts 2551-2554). - utils_cache.py and route_backend_workflows.py: pass request-derived IDs, scopes, keys and exception text through sanitize_log_message in the 14 flagged log calls. Ordinary values log exactly as before, and logging.exception keeps its traceback. - route_backend_plugins.py: stop logging the plugin settings request body, which can carry secrets; log its top-level field count through log_event instead (alert 1105). - Add functional tests, fix documentation and release notes, and set VERSION to 0.261.216. Refs #1543 Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- application/single_app/config.py | 2 +- .../single_app/functions_appinsights.py | 2 + .../single_app/route_backend_plugins.py | 6 +- .../single_app/route_backend_workflows.py | 16 +- application/single_app/utils_cache.py | 30 +- .../fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md | 231 ++++++ docs/explanation/release_notes.md | 10 + .../test_group_document_collaboration.py | 3 +- .../test_group_workflow_fixture_parity.py | 3 + .../test_log_injection_codeql_alerts_fix.py | 682 ++++++++++++++++++ .../test_support/log_sanitizer.py | 37 + 11 files changed, 1004 insertions(+), 18 deletions(-) create mode 100644 docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md create mode 100644 functional_tests/test_log_injection_codeql_alerts_fix.py create mode 100644 functional_tests/test_support/log_sanitizer.py diff --git a/application/single_app/config.py b/application/single_app/config.py index c5e814cb4..2584dd8ec 100644 --- a/application/single_app/config.py +++ b/application/single_app/config.py @@ -100,7 +100,7 @@ EXECUTOR_TYPE = 'thread' EXECUTOR_MAX_WORKERS = 30 SESSION_TYPE = 'filesystem' -VERSION = "0.261.213" +VERSION = "0.261.216" IS_DEVELOPMENT = is_development_env_enabled() # Opt-out for deployments where App Service Easy Auth is active but the platform diff --git a/application/single_app/functions_appinsights.py b/application/single_app/functions_appinsights.py index b5e55cd7b..7fa5d88ef 100644 --- a/application/single_app/functions_appinsights.py +++ b/application/single_app/functions_appinsights.py @@ -199,6 +199,8 @@ def sanitize_log_message(message: Any) -> str: message_text, ) message_text = LOG_CONTROL_CHAR_RE.sub(" ", message_text) + # No-ops after the regex above; they make its line-break removal visible to static analysis. + message_text = message_text.replace("\r\n", " ").replace("\n", " ").replace("\r", " ") if len(message_text) > MAX_LOG_STRING_LENGTH: return f"{message_text[:MAX_LOG_STRING_LENGTH]}... [truncated]" return message_text diff --git a/application/single_app/route_backend_plugins.py b/application/single_app/route_backend_plugins.py index 3ba48891b..ee806d00a 100644 --- a/application/single_app/route_backend_plugins.py +++ b/application/single_app/route_backend_plugins.py @@ -2211,7 +2211,11 @@ def get_core_plugin_settings(): @admin_required def update_core_plugin_settings(): data = request.get_json(force=True) - logging.info("Received plugin settings update request: %s", data) + # Plugin settings payloads can carry secrets, so only their size is logged. + log_event( + "[PLUGINS] Received plugin settings update request.", + extra={"field_count": len(data) if isinstance(data, dict) else 0}, + ) # Validate input expected_keys = [ 'enable_time_plugin', diff --git a/application/single_app/route_backend_workflows.py b/application/single_app/route_backend_workflows.py index e32e53c40..944ac7572 100644 --- a/application/single_app/route_backend_workflows.py +++ b/application/single_app/route_backend_workflows.py @@ -20,7 +20,7 @@ log_workflow_deletion, log_workflow_update, ) -from functions_appinsights import log_event +from functions_appinsights import log_event, sanitize_log_message from functions_authentication import get_current_user_id, get_current_user_info, login_required, user_required from functions_file_sync import ( FILE_SYNC_MANAGER_ROLES, @@ -1921,16 +1921,16 @@ def cancel_user_workflow_run(workflow_id, run_id): except LookupError: logging.exception( "LookupError while cancelling personal workflow run. workflow_id=%s run_id=%s user_id=%s", - workflow_id, - run_id, + sanitize_log_message(workflow_id), + sanitize_log_message(run_id), user_id, ) return jsonify({'error': 'Workflow run not found.'}), 404 except WorkflowCancellationConflictError: logging.exception( "WorkflowCancellationConflictError while cancelling personal workflow run. workflow_id=%s run_id=%s user_id=%s", - workflow_id, - run_id, + sanitize_log_message(workflow_id), + sanitize_log_message(run_id), user_id, ) return jsonify({'error': 'Workflow run cancellation conflict.'}), 409 @@ -2315,21 +2315,21 @@ def cancel_active_group_workflow_run(workflow_id): logging.exception( "Invalid group workflow request during cancellation. user_id=%s workflow_id=%s", user_id, - workflow_id, + sanitize_log_message(workflow_id), ) return jsonify({'error': 'Invalid group workflow request.'}), 400 except LookupError as exc: logging.exception( "Group workspace lookup failed during workflow cancellation. user_id=%s workflow_id=%s", user_id, - workflow_id, + sanitize_log_message(workflow_id), ) return jsonify({'error': 'Group workspace not found.'}), 404 except PermissionError as exc: logging.exception( "Unauthorized group workflow cancellation attempt. user_id=%s workflow_id=%s", user_id, - workflow_id, + sanitize_log_message(workflow_id), ) return jsonify({'error': 'Not authorized to access this group workspace.'}), 403 diff --git a/application/single_app/utils_cache.py b/application/single_app/utils_cache.py index 0dea2d7f9..f34389d21 100644 --- a/application/single_app/utils_cache.py +++ b/application/single_app/utils_cache.py @@ -29,6 +29,7 @@ cosmos_public_documents_container, cosmos_search_cache_container ) +from functions_appinsights import sanitize_log_message from azure.cosmos.exceptions import CosmosResourceNotFoundError logger = logging.getLogger(__name__) @@ -212,7 +213,10 @@ def get_group_document_fingerprint(group_id: str) -> str: return fingerprint except Exception as e: - logger.error(f"Error generating group document fingerprint for group {group_id}: {e}") + logger.error( + f"Error generating group document fingerprint for group {sanitize_log_message(group_id)}: " + f"{sanitize_log_message(e)}" + ) _debug_print(f"ERROR generating fingerprint: {e}", "FINGERPRINT", group_id=group_id[:8]) return hashlib.sha256(str(datetime.now().timestamp()).encode()).hexdigest() @@ -262,7 +266,10 @@ def get_public_workspace_document_fingerprint(public_workspace_id: str) -> str: return fingerprint except Exception as e: - logger.error(f"Error generating public workspace document fingerprint for workspace {public_workspace_id}: {e}") + logger.error( + "Error generating public workspace document fingerprint for workspace " + f"{sanitize_log_message(public_workspace_id)}: {sanitize_log_message(e)}" + ) _debug_print(f"ERROR generating fingerprint: {e}", "FINGERPRINT", workspace_id=public_workspace_id[:8]) return hashlib.sha256(str(datetime.now().timestamp()).encode()).hexdigest() @@ -498,7 +505,10 @@ def get_cached_search_results( partition_key=partition_key[:25], ttl_remaining=f"{seconds_remaining:.1f}s" ) - logger.info(f"Cache hit for key: {cache_key} (scope: {doc_scope}, partition: {partition_key[:25]})") + logger.info( + f"Cache hit for key: {sanitize_log_message(cache_key)} " + f"(scope: {sanitize_log_message(doc_scope)}, partition: {sanitize_log_message(partition_key[:25])})" + ) return results else: # Expired - delete from cache @@ -568,7 +578,11 @@ def cache_search_results(cache_key: str, results: List[Dict[str, Any]], user_id: partition_key=partition_key[:25] ) - logger.debug(f"Cached search results with key: {cache_key}, scope: {doc_scope}, partition: {partition_key[:25]}, ttl: {ttl_seconds}s, expires at: {expiry_time}") + logger.debug( + f"Cached search results with key: {sanitize_log_message(cache_key)}, " + f"scope: {sanitize_log_message(doc_scope)}, partition: {sanitize_log_message(partition_key[:25])}, " + f"ttl: {ttl_seconds}s, expires at: {expiry_time}" + ) except Exception as e: logger.error(f"Error caching search results to Cosmos DB: {e}") _debug_print(f"Cache write ERROR: {e}", "CACHE", cache_key=cache_key[:16]) @@ -632,7 +646,7 @@ def invalidate_personal_search_cache(user_id: str) -> int: "INVALIDATION", user_id=user_id[:8] ) - logger.info(f"Invalidated {count} cache entries for user {user_id}") + logger.info(f"Invalidated {count} cache entries for user {sanitize_log_message(user_id)}") return count @@ -708,7 +722,7 @@ def invalidate_group_search_cache(group_id: str, *, document_id=None, strict=Fal "INVALIDATION", group_id=group_id[:8] ) - logger.info(f"Invalidated {count} cache entries for group {group_id}") + logger.info(f"Invalidated {count} cache entries for group {sanitize_log_message(group_id)}") return count @@ -773,7 +787,9 @@ def invalidate_public_workspace_search_cache(public_workspace_id: str) -> int: "INVALIDATION", workspace_id=public_workspace_id[:8] ) - logger.info(f"Invalidated {count} cache entries for public workspace {public_workspace_id}") + logger.info( + f"Invalidated {count} cache entries for public workspace {sanitize_log_message(public_workspace_id)}" + ) return count diff --git a/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md b/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md new file mode 100644 index 000000000..a86d4568d --- /dev/null +++ b/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md @@ -0,0 +1,231 @@ +# Log Injection CodeQL Alerts Fix (v0.261.216) + +## Issue + +CodeQL's `py/log-injection` query had 19 open alerts on `paullizer-react-v2-ui`. Each one flagged +a log call that writes a value taken from the request, either Flask's `request` object or a URL +route variable such as `workflow_id`, `run_id`, `group_id`, `workspace_id` or `plugin_name`, +without a line-break sanitizer the query recognizes. All 19 are on code that predates the Chat +Orchestration Workflows roadmap, and reviews of that roadmap's pull requests kept hitting them. + +| Alerts | Location at `70c255508` | What the line logs | +|---|---|---| +| 2551, 2552, 2553, 2554 | `functions_appinsights.py` L419, L515, L531, L553 | `log_event` messages, through the `sc_message` property in the `extra` dict | +| 1110, 1111 | `utils_cache.py` L215, L265 | a group or public workspace ID and the exception, when a document fingerprint query fails | +| 1113, 1114 | `utils_cache.py` L501, L571 | the cache key, document scope and partition key, on a search cache hit or write | +| 1115, 3411, 3412 | `utils_cache.py` L635, L711, L776 | the user, group or public workspace ID, after a search cache invalidation | +| 2120, 2121, 2122, 2123 | `route_backend_workflows.py` L1924, L1925, L1932, L1933 | `workflow_id` and `run_id`, when cancelling a personal workflow run fails | +| 2124, 2125, 2126 | `route_backend_workflows.py` L2318, L2325, L2332 | `workflow_id`, when cancelling a group workflow run fails | +| 1105 | `route_backend_plugins.py` L2214 | the whole admin plugin settings request body | + +Fixed in version: **0.261.216**. Refs #1543. + +## Root cause + +The query credits one line-break sanitizer: a call to a method named `replace` whose first +argument is the string literal `"\r\n"` or `"\n"`. Anything derived from its result is treated as +clean. It does not credit `re.sub`, a `re.fullmatch` guard or a helper function, unless the value +passes through such a `replace` call inside it. + +- **The 4 `functions_appinsights.py` alerts were false positives.** `log_event` runs every message + through `sanitize_log_message`. That function masks secret assignments and authorization + values, collapses each run of `\r`, `\n` and `\t` to one space with + `LOG_CONTROL_CHAR_RE.sub(" ", ...)`, and truncates the text to `MAX_LOG_STRING_LENGTH` (8,192) + characters with a `... [truncated]` suffix. No CR or LF survives, but the query could not see + the regex remove them. All 16 reported flows pass through `sanitize_log_message` and reach the + `extra` dict as the `sc_message` property that `_build_logger_extra` builds. +- **The 14 `utils_cache.py` and `route_backend_workflows.py` alerts were real, and low severity.** + These lines put identifiers and exception text straight into a standard `logging` message. A + route variable can carry an encoded line break, so a crafted ID could start what looks like a + separate log entry. +- **The `route_backend_plugins.py` alert was also a disclosure risk.** The admin route logged the + request body before validating it. A valid body holds only booleans, but whatever was sent was + logged as sent, including a field the route then rejects, such as `api_key`, and a non-boolean + value. + +## Technical details + +### functions_appinsights.py + +`sanitize_log_message` gains one statement straight after the regex. Both of its returns, the +truncated one and the normal one, come after it: + +```python +message_text = LOG_CONTROL_CHAR_RE.sub(" ", message_text) +# No-ops after the regex above; they make its line-break removal visible to static analysis. +message_text = message_text.replace("\r\n", " ").replace("\n", " ").replace("\r", " ") +if len(message_text) > MAX_LOG_STRING_LENGTH: +``` + +- After the regex the text holds no CR or LF, so the three `replace` calls change nothing. The + function returns exactly what it returned in 0.261.213. +- The calls must not move ahead of the regex, where they would change the output: `"a\n\nb"` + would become `"a b"`, with two spaces, instead of `"a b"`. +- `_build_logger_extra`, `_normalize_extra_key` and the debug `category` value are unchanged. No + reported flow goes through the `re.fullmatch`-guarded hash and code values, the normalized keys + or the category, so they did not need the same treatment. + +### utils_cache.py + +`utils_cache.py` imports `sanitize_log_message` from `functions_appinsights` and wraps each value +the seven flagged lines write: + +| Function | Wrapped values | +|---|---| +| `get_group_document_fingerprint` | `group_id`, the exception | +| `get_public_workspace_document_fingerprint` | `public_workspace_id`, the exception | +| `get_cached_search_results` (the cache hit line) | `cache_key`, `doc_scope`, `partition_key[:25]` | +| `cache_search_results` | `cache_key`, `doc_scope`, `partition_key[:25]` | +| `invalidate_personal_search_cache` | `user_id` | +| `invalidate_group_search_cache` | `group_id` | +| `invalidate_public_workspace_search_cache` | `public_workspace_id` | + +- The messages and levels are unchanged. Some f-strings now span several lines. +- On the cache hit and write lines, the reported taint comes from `doc_scope` and the partition + key. `cache_key` is a hash, but it is wrapped too, so every value on those lines is covered. +- The import adds no cycle. `config.py` already imports `functions_appinsights`, whose only + application import is `app_settings_cache`, which in turn imports only the standard library, + Azure, Redis and `app_settings_store`. + +### route_backend_workflows.py + +The existing `from functions_appinsights import log_event` line also imports +`sanitize_log_message`. + +- In `cancel_user_workflow_run`, the `LookupError` and `WorkflowCancellationConflictError` + handlers wrap `workflow_id` and `run_id`. +- In `cancel_active_group_workflow_run`, the `ValueError`, `LookupError` and `PermissionError` + handlers wrap `workflow_id`. +- The calls stay `logging.exception` with the same format strings and argument order, so the level + and the attached traceback are unchanged. +- `user_id` comes from the signed-in session, not the request. It is not flagged and not wrapped. + +### route_backend_plugins.py + +`update_core_plugin_settings` (`POST /api/admin/plugins/settings`) no longer logs the request +body. It logs the number of top-level fields through `log_event`, with the `[PLUGINS]` tag the +module's other events use: + +```python +# Plugin settings payloads can carry secrets, so only their size is logged. +log_event( + "[PLUGINS] Received plugin settings update request.", + extra={"field_count": len(data) if isinstance(data, dict) else 0}, +) +``` + +- Field names are not logged either. In a valid request they are always the same fixed set, and + before validation they are whatever the client sent. +- The `Validated plugin settings` line after validation is unchanged. It logs only the validated + booleans, and CodeQL does not flag it. +- Validation, the saved settings, the responses and the kernel reload request are unchanged. + +### What is not changed + +These lines have the same shape as the fixed ones, but CodeQL does not flag them on the base: its +taint tracking finds no request value that reaches them. They are left for follow-up work: + +- In `utils_cache.py`, the personal document fingerprint error (`user_id`), the cache-expired and + cache-miss debug lines (`cache_key`), and the cache read and write error lines. +- The `user_id` values in the workflow cancellation lines. + +### Files modified + +- `application/single_app/functions_appinsights.py`: the `replace` chain in + `sanitize_log_message`. +- `application/single_app/utils_cache.py`: the import and the seven wrapped lines. +- `application/single_app/route_backend_workflows.py`: the import and the seven wrapped + arguments. +- `application/single_app/route_backend_plugins.py`: the field-count log. +- `application/single_app/config.py`: `VERSION` 0.261.216. +- `functional_tests/test_log_injection_codeql_alerts_fix.py` (new): the tests below. +- `functional_tests/test_support/log_sanitizer.py` (new): `real_sanitize_log_message()` runs the + real `sanitize_log_message` and the constants it reads from `functions_appinsights.py` source, + for harnesses that run application functions in a namespace they build. +- `functional_tests/test_group_document_collaboration.py` and + `functional_tests/test_group_workflow_fixture_parity.py`: the namespaces they run + `invalidate_group_search_cache` and the workflow routes in gain `sanitize_log_message`. +- `docs/explanation/release_notes.md`: the 0.261.216 entry. + +### Tests + +`functional_tests/test_log_injection_codeql_alerts_fix.py` has 44 tests, written with plain +`assert`s that pass normally and under `python -O`. It needs no Azure resources. + +- **The output is unchanged.** A frozen copy of the 0.261.213 `sanitize_log_message` is kept as + reference data. The module and the harness helper must both match it over a 33-item corpus: + plain text, `"a\n\nb"`, CRLF runs, a lone CR, tabs, mixed `\t\r\n`, `password=x`, + `api_key=...`, `Bearer` and `Basic` values, strings at, over and around the 8,192-character + limit, an exception, an int, a float, `None`, `True`, a dict, a list, bytes and unicode, + including U+2028, U+2029 and U+0085. Spot checks pin `"a\n\nb"` to `"a b"`, the masking and the + exact truncation suffix. +- **The replaces stay where CodeQL needs them.** An AST check requires a + `message_text.replace("\r\n", ...)` and `.replace("\n", ...)` chain after the + `LOG_CONTROL_CHAR_RE.sub` line and before every return. The calls change nothing at run time, + so no behavior test would notice a refactor that drops them, and dropping them would reopen four + alerts. +- **`log_event`** writes a message and `extra` values that contain CRLF and LF as single-line + `sc_*` properties. +- **utils_cache.** Each of the seven functions runs from source against a fake container. An + ordinary ID logs exactly the line 0.261.213 logged. IDs, scopes, keys and exception text that + contain `\n` or `\r\n` log on one line. +- **Workflow cancellation.** Each of the five handlers runs from source. An ordinary ID logs the + same line as before. An injected `workflow_id` and `run_id` log on one line, at ERROR, with the + exception and its traceback attached, and the response status is unchanged. +- **Plugin settings.** A request with an `api_key` field and one with a secret in a boolean field + are rejected as before, and neither the logged event, the log records nor stdout contain the + fake key. A valid request is still saved and still requests the kernel reload. +- **Fresh-process imports.** A subprocess with every socket blocked imports `functions_appinsights` + and `utils_cache` in both orders, `config` then `utils_cache`, `route_backend_workflows`, + `route_backend_plugins` and `app`, normally and under `-O`. It checks that each edited module's + `sanitize_log_message` or `log_event` is the `functions_appinsights` one. The probe imports + `functions_authentication` before `route_backend_workflows`, as `app.py` does: on the base, a + cold import of `route_backend_workflows` on its own already fails with + `NameError: enabled_required`, from an existing `functions_settings` and + `functions_authentication` import cycle. + +## Impact + +- Apart from the plugin settings line, log output is byte-identical for ordinary values, and + `log_event` output is byte-identical for every value. +- A wrapped value that contains a line break or tab is now logged on one line, with each run of + them collapsed to a space. Like `log_event` messages, a wrapped value that contains a secret + assignment or an authorization value is masked, and one longer than 8,192 characters is + truncated. +- The plugin settings line now reads `[PLUGINS] Received plugin settings update request.` with a + `field_count` property, through `log_event`, instead of the request body through the root + logger. +- No setting, route, response or stored data changes. + +## Validation + +- **Local CodeQL.** CodeQL 2.27.1 with `codeql/python-queries` 1.8.11, the versions in the base + analysis, ran `Security/CWE-117/LogInjection.ql` over the four edited modules, the two settings + cache modules they import and a synthetic Flask driver. The driver feeds request values into + every input of the flagged functions and also logs `sanitize_log_message(value)` directly. + - Base: 23 results. They are the 19 alerts, the driver's direct line, and the three + `utils_cache.py` lines listed under "What is not changed" that log `user_id` or `cache_key`. + The driver reaches those three only by passing request values where the application passes + the signed-in user's ID or a hashed cache key. + - Fix: 3 results, the same three lines. All 19 alerts cleared, and so did the driver's direct + line, which shows that `sanitize_log_message` now works as a sanitizer for its callers. +- **Mutation checks.** 25 mutations, each run normally and under `-O`, 50 runs in all, were each + caught by at least one test: + - unwrapping any one of the 20 wrapped values (13 in `utils_cache.py`, 7 in + `route_backend_workflows.py`) + - moving the replaces ahead of the regex (3 tests fail) + - dropping the replaces (the AST check fails) + - restoring the payload log (3 plugin tests fail) + - removing the new import from `utils_cache.py` (6 import tests fail) or + `route_backend_workflows.py` (2 import tests fail) + + The source files were restored byte-identical afterwards. +- **GitHub CodeQL.** The pull request's merge ref is checked once its CodeQL analysis finishes. + +## Related + +- #1543: the Chat Orchestration Workflows roadmap, whose reviews kept hitting these alerts. +- [Log Credential Key Redaction Fix](LOG_CREDENTIAL_KEY_REDACTION_FIX.md): the + `py/clear-text-logging-sensitive-data` alerts on the same logging sinks, a different rule that + this fix does not change. +- `functional_tests/test_log_injection_codeql_alerts_fix.py`. diff --git a/docs/explanation/release_notes.md b/docs/explanation/release_notes.md index 554549239..6d1e0f66a 100644 --- a/docs/explanation/release_notes.md +++ b/docs/explanation/release_notes.md @@ -2,6 +2,16 @@ For feature-focused and fix-focused drill-downs by version, see [Features by Version](https://github.com/microsoft/simplechat/tree/main/docs/explanation/features) and [Fixes by Version](https://github.com/microsoft/simplechat/tree/main/docs/explanation/fixes). +### **(v0.261.216)** + +#### Bug Fixes + +* **Log Injection CodeQL Alerts Fixed** + * Cleared the 19 open `py/log-injection` CodeQL alerts. The search cache logs and the workflow run cancellation error logs now pass identifiers and exception text through `sanitize_log_message`, so an ID containing a line break can no longer start what looks like a separate log entry. Ordinary values are logged exactly as before, and the cancellation errors keep their traceback. + * The admin plugin settings route no longer logs the request body. It was logged before validation, so a field the route then rejects, such as an API key, was written to the log as sent. The route now logs `[PLUGINS] Received plugin settings update request.` with the number of fields. + * `sanitize_log_message` already removed line breaks with a regular expression, which CodeQL doesn't recognize. It now also calls `replace` for them after the regex, which changes nothing at run time but lets CodeQL see that `log_event` output has none. Its output is unchanged. + * (Ref: #1543, `functions_appinsights.py`, `utils_cache.py`, `route_backend_workflows.py`, `route_backend_plugins.py`, [Log Injection CodeQL Alerts Fix](fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md)) + ### **(v0.261.213)** #### New Features diff --git a/functional_tests/test_group_document_collaboration.py b/functional_tests/test_group_document_collaboration.py index 47185fb2d..b432468c0 100644 --- a/functional_tests/test_group_document_collaboration.py +++ b/functional_tests/test_group_document_collaboration.py @@ -26,6 +26,7 @@ MissingRecord, document, environment, get, load_real_module, ) from test_support.agent_delegation import execute_functions, module_stub +from test_support.log_sanitizer import real_sanitize_log_message OPERATION = "group_document_collaboration_operation" @@ -188,7 +189,7 @@ def directory_query(query, parameters=None, **kwargs): env.cache = CacheStore({}) cache_helpers = { "cosmos_search_cache_container": env.cache, "logger": logging.getLogger(__name__), - "_debug_print": env.logs, + "_debug_print": env.logs, "sanitize_log_message": real_sanitize_log_message(), } execute_functions("utils_cache.py", {"invalidate_group_search_cache"}, cache_helpers) env.invalidate_cache = Mock(wraps=cache_helpers["invalidate_group_search_cache"]) diff --git a/functional_tests/test_group_workflow_fixture_parity.py b/functional_tests/test_group_workflow_fixture_parity.py index 1657be8c0..6ba97ba8b 100644 --- a/functional_tests/test_group_workflow_fixture_parity.py +++ b/functional_tests/test_group_workflow_fixture_parity.py @@ -40,6 +40,8 @@ import pytest from flask import Blueprint, Flask, jsonify, request, session +from test_support.log_sanitizer import real_sanitize_log_message + ROOT = Path(__file__).resolve().parents[1] APP_ROOT = ROOT / "application" / "single_app" @@ -417,6 +419,7 @@ def cancel_durable_workflow_run(workflow, run_id, *, actor_user_id): "queue_durable_workflow_run": queue_durable_workflow_run, "cancel_durable_workflow_run": cancel_durable_workflow_run, "log_event": lambda *args, **kwargs: self.logs.append((args, kwargs)), + "sanitize_log_message": real_sanitize_log_message(), "log_workflow_creation": lambda **kwargs: None, "log_workflow_update": lambda **kwargs: None, "log_workflow_deletion": lambda **kwargs: None, diff --git a/functional_tests/test_log_injection_codeql_alerts_fix.py b/functional_tests/test_log_injection_codeql_alerts_fix.py new file mode 100644 index 000000000..36dffbf9f --- /dev/null +++ b/functional_tests/test_log_injection_codeql_alerts_fix.py @@ -0,0 +1,682 @@ +#!/usr/bin/env python3 +# test_log_injection_codeql_alerts_fix.py +""" +Functional test for the py/log-injection CodeQL alerts fix. +Version: 0.261.216 +Implemented in: 0.261.216 + +This test ensures that the log lines CodeQL flagged for log injection keep request-derived +identifiers and exception text on one line while an ordinary identifier is logged exactly as +before, that ``sanitize_log_message`` returns exactly what it returned in 0.261.213 now that its +line-break removal is visible to static analysis, and that the admin plugin-settings route logs +the size of its payload instead of the payload. It also checks that the edited modules load in +fresh normal and optimized interpreters, in either order, with every network socket blocked. +""" + +import ast +from contextlib import redirect_stdout +from datetime import datetime, timedelta, timezone +import hashlib +import io +import logging +from pathlib import Path +import re +import subprocess +import sys +from types import SimpleNamespace +from typing import Any, Dict, List, Optional + +from azure.cosmos.exceptions import CosmosResourceNotFoundError +import pytest + +ROOT = Path(__file__).resolve().parents[1] +APP = ROOT / "application" / "single_app" +TESTS = ROOT / "functional_tests" +for search_path in (str(TESTS), str(APP)): + if search_path not in sys.path: + sys.path.insert(0, search_path) + +import functions_appinsights # noqa: E402 (path setup must precede this import) +from test_support.app_source import definitions, run_definitions # noqa: E402 +from test_support.log_sanitizer import real_sanitize_log_message # noqa: E402 +from test_support.versioning import assert_app_version_at_least # noqa: E402 + + +# sanitize_log_message exactly as released in 0.261.213, kept as reference data. +FROZEN_REDACTED_LOG_VALUE = "***REDACTED***" +FROZEN_MAX_LOG_STRING_LENGTH = 8192 +FROZEN_SECRET_ASSIGNMENT_RE = re.compile( + r"(?i)\b(api[-_]?key|access[-_]?token|client[-_]?secret|connection[-_]?string|password|secret|subscription[-_]?key|token|sig|signature)=([^&\s,;]+)" +) +FROZEN_AUTHORIZATION_VALUE_RE = re.compile(r"(?i)\b(Bearer|Basic)\s+[A-Za-z0-9._~+/=-]+") +FROZEN_LOG_CONTROL_CHAR_RE = re.compile(r"[\r\n\t]+") + + +def frozen_sanitize_log_message(message): + message_text = str(message) + message_text = FROZEN_SECRET_ASSIGNMENT_RE.sub( + lambda match: f"{match.group(1)}={FROZEN_REDACTED_LOG_VALUE}", + message_text, + ) + message_text = FROZEN_AUTHORIZATION_VALUE_RE.sub( + lambda match: f"{match.group(1)} {FROZEN_REDACTED_LOG_VALUE}", + message_text, + ) + message_text = FROZEN_LOG_CONTROL_CHAR_RE.sub(" ", message_text) + if len(message_text) > FROZEN_MAX_LOG_STRING_LENGTH: + return f"{message_text[:FROZEN_MAX_LOG_STRING_LENGTH]}... [truncated]" + return message_text + + +SANITIZE_CORPUS = ( + "plain diagnostic text", + "", + "a\n\nb", + "line one\r\nline two", + "runs\r\n\r\n\r\nof CRLF", + "lone\rcarriage return", + "\r\n", + "\n\r", + "trailing newline\n", + "tab\tseparated\t\tvalues", + "mixed\t\r\n\t\r\ncontrol characters", + "password=x", + "api_key=sk-test-0123456789&next=1", + "connection_string=AccountKey123;rest", + "Authorization: Bearer abc.def-ghi_jkl", + "Authorization: Basic dXNlcjpwYXNz", + "token=abc\r\nBearer xyz\tpassword=hunter2", + "x" * FROZEN_MAX_LOG_STRING_LENGTH, + "x" * (FROZEN_MAX_LOG_STRING_LENGTH + 1), + "y\n" * 6000, + "z" * (FROZEN_MAX_LOG_STRING_LENGTH - 2) + "\r\n\r\nqq", + ValueError("boom\r\nforged entry"), + RuntimeError(), + 42, + 3.5, + None, + True, + {"workflow_id": "wf-1\nforged", "password": "hunter2"}, + ["a\nb", 1], + b"bytes\nvalue", + "unicod\u00e9 \u2713 \u65e5\u672c\u8a9e \u2013 \U0001F680", + "line separator\u2028paragraph separator\u2029next line\u0085", + "vertical\x0btab and form\x0cfeed", +) + + +def test_version_is_at_least_the_fix_version(): + assert_app_version_at_least("0.261.216") + + +def test_sanitize_log_message_output_is_unchanged_from_0_261_213(): + sanitize = functions_appinsights.sanitize_log_message + executed_sanitize = real_sanitize_log_message() + for message in SANITIZE_CORPUS: + expected = frozen_sanitize_log_message(message) + actual = sanitize(message) + executed = executed_sanitize(message) + assert actual == expected, f"sanitize_log_message changed its output for {message!r:.80}" + assert executed == expected, f"The harness helper disagrees with the module for {message!r:.80}" + assert "\r" not in actual and "\n" not in actual + + +def test_sanitize_log_message_keeps_its_collapsing_masking_and_truncation(): + limit = functions_appinsights.MAX_LOG_STRING_LENGTH + collapsed = functions_appinsights.sanitize_log_message("a\n\nb") + crlf_runs = functions_appinsights.sanitize_log_message("a\r\n\r\nb\rc\td") + masked = functions_appinsights.sanitize_log_message("api_key=sk-test-123 Bearer abc.def") + truncated = functions_appinsights.sanitize_log_message("x" * (limit + 5)) + assert collapsed == "a b" + assert crlf_runs == "a b c d" + assert masked == "api_key=***REDACTED*** Bearer ***REDACTED***" + assert truncated == "x" * limit + "... [truncated]" + + +def _sanitize_log_message_body(): + tree = ast.parse((APP / "functions_appinsights.py").read_text(encoding="utf-8")) + function = next( + node for node in tree.body + if isinstance(node, ast.FunctionDef) and node.name == "sanitize_log_message" + ) + return function.body + + +def _assigns_message_text(statement): + return ( + isinstance(statement, ast.Assign) + and len(statement.targets) == 1 + and isinstance(statement.targets[0], ast.Name) + and statement.targets[0].id == "message_text" + ) + + +def _collapses_control_characters(statement): + value = getattr(statement, "value", None) + return ( + _assigns_message_text(statement) + and isinstance(value, ast.Call) + and isinstance(value.func, ast.Attribute) + and value.func.attr == "sub" + and isinstance(value.func.value, ast.Name) + and value.func.value.id == "LOG_CONTROL_CHAR_RE" + ) + + +def _replaced_literals(statement): + """The literal first arguments of a ``message_text.replace(...)`` chain, else an empty set.""" + if not _assigns_message_text(statement): + return set() + literals = set() + node = statement.value + while ( + isinstance(node, ast.Call) + and isinstance(node.func, ast.Attribute) + and node.func.attr == "replace" + and node.args + and isinstance(node.args[0], ast.Constant) + and isinstance(node.args[0].value, str) + ): + literals.add(node.args[0].value) + node = node.func.value + if isinstance(node, ast.Name) and node.id == "message_text": + return literals + return set() + + +def test_sanitize_log_message_keeps_the_line_break_replaces_after_the_regex(): + # CodeQL credits only a .replace("\r\n", ...) or .replace("\n", ...) call as a line-break + # sanitizer. After the regex these calls change nothing, so only this check notices if a + # refactor drops them or moves them ahead of the regex; either reopens four alerts. + body = _sanitize_log_message_body() + collapses = [index for index, statement in enumerate(body) if _collapses_control_characters(statement)] + replaces = [ + index for index, statement in enumerate(body) + if {"\r\n", "\n"} <= _replaced_literals(statement) + ] + returns = [ + index for index, statement in enumerate(body) + if any(isinstance(node, ast.Return) for node in ast.walk(statement)) + ] + assert len(collapses) == 1, "sanitize_log_message no longer collapses control characters with LOG_CONTROL_CHAR_RE" + replaces_after_regex = [index for index in replaces if index > collapses[0]] + assert replaces_after_regex, ( + 'sanitize_log_message must call message_text.replace("\\r\\n", ...).replace("\\n", ...) ' + "after LOG_CONTROL_CHAR_RE.sub" + ) + assert returns + assert min(returns) > replaces_after_regex[0], "A return comes before the line-break replaces" + + +def test_log_event_writes_single_line_properties(monkeypatch): + capture = RecordCapture() + logger = logging.getLogger(f"{__name__}.appinsights") + logger.handlers[:] = [capture] + logger.setLevel(logging.DEBUG) + logger.propagate = False + monkeypatch.setattr(functions_appinsights, "_load_logging_settings", lambda: {}) + monkeypatch.setattr(functions_appinsights, "get_appinsights_logger", lambda: logger) + try: + functions_appinsights.log_event( + "Cancelling workflow wf-1\r\nFORGED entry", + extra={"workflow_id": "wf-1\nFORGED", "error": "boom\r\nFORGED"}, + ) + finally: + logger.handlers[:] = [] + records = list(capture.records) + assert len(records) == 1 + properties = { + name: value for name, value in vars(records[0]).items() + if name.startswith("sc_") and isinstance(value, str) + } + assert properties["sc_message"] == "Cancelling workflow wf-1 FORGED entry" + assert not [name for name, value in properties.items() if "\r" in value or "\n" in value] + + +class RecordCapture(logging.Handler): + def __init__(self): + super().__init__(level=logging.DEBUG) + self.records = [] + + def emit(self, record): + self.records.append(record) + + +class FrozenDatetime(datetime): + """``datetime`` with a fixed ``now``, so the cache-write line's expiry time is known.""" + + @classmethod + def now(cls, tz=None): + return cls(2026, 1, 2, 3, 4, 5, tzinfo=tz) + + +class CacheContainer: + """The Cosmos DB container calls made on the logged utils_cache paths.""" + + def __init__(self, *, error=None, items=(), cache_item=None): + self.error = error + self.items = list(items) + self.cache_item = cache_item + self.deleted = [] + self.upserted = [] + + def query_items(self, **kwargs): + if self.error is not None: + raise self.error + return list(self.items) + + def delete_item(self, item, partition_key): + self.deleted.append((item, partition_key)) + + def read_item(self, item, partition_key): + return dict(self.cache_item) + + def upsert_item(self, body): + self.upserted.append(body) + return body + + +UTILS_CACHE_DEFINITIONS = ( + "get_group_document_fingerprint", + "get_public_workspace_document_fingerprint", + "get_cache_partition_key", + "_normalize_cache_id_list", + "get_cached_search_results", + "cache_search_results", + "invalidate_personal_search_cache", + "invalidate_group_search_cache", + "invalidate_public_workspace_search_cache", +) +CACHE_HIT = {"expiry_time": "2026-01-02T03:09:05Z", "results": [{"id": "result-1"}]} + + +def failing(message): + return lambda: CacheContainer(error=RuntimeError(message)) + + +def holding(*items): + return lambda: CacheContainer(items=items, cache_item=CACHE_HIT) + + +def run_utils_cache(function_name, *args, container, **kwargs): + """Call a utils_cache function executed from source and return its log lines.""" + capture = RecordCapture() + logger = logging.getLogger(f"{__name__}.utils_cache") + logger.handlers[:] = [capture] + logger.setLevel(logging.DEBUG) + logger.propagate = False + namespace = run_definitions("utils_cache.py", UTILS_CACHE_DEFINITIONS, { + "Any": Any, + "Dict": Dict, + "List": List, + "Optional": Optional, + "CosmosResourceNotFoundError": CosmosResourceNotFoundError, + "datetime": FrozenDatetime, + "hashlib": hashlib, + "timedelta": timedelta, + "timezone": timezone, + "logger": logger, + "sanitize_log_message": functions_appinsights.sanitize_log_message, + "_debug_print": lambda *debug_args, **debug_kwargs: None, + "get_cache_settings": lambda: (True, 300), + "cosmos_group_documents_container": container, + "cosmos_public_documents_container": container, + "cosmos_search_cache_container": container, + }) + try: + namespace[function_name](*args, **kwargs) + finally: + logger.handlers[:] = [] + return [record.getMessage() for record in capture.records] + + +# (function, args, kwargs, container, the line it logged before this fix) +ORDINARY_UTILS_CACHE_LINES = ( + ( + "get_group_document_fingerprint", ("group-1",), {}, failing("Cosmos query failed"), + "Error generating group document fingerprint for group group-1: Cosmos query failed", + ), + ( + "get_public_workspace_document_fingerprint", ("workspace-1",), {}, failing("Cosmos query failed"), + "Error generating public workspace document fingerprint for workspace workspace-1: Cosmos query failed", + ), + ( + "get_cached_search_results", ("cache-key-1", "user-1", "group"), {"active_group_ids": ["group-1"]}, + holding(), + "Cache hit for key: cache-key-1 (scope: group, partition: group:group-1)", + ), + ( + "cache_search_results", ("cache-key-1", [{"id": "result-1"}], "user-1", "public"), + {"active_public_workspace_id": "workspace-0123456789abcdef"}, holding(), + "Cached search results with key: cache-key-1, scope: public, partition: public:workspace-01234567, " + "ttl: 300s, expires at: 2026-01-02 03:09:05+00:00", + ), + ( + "invalidate_personal_search_cache", ("user-1",), {}, holding({"id": "cache-1"}), + "Invalidated 1 cache entries for user user-1", + ), + ( + "invalidate_group_search_cache", ("group-1",), {}, holding({"id": "cache-1", "user_id": "group:group-1"}), + "Invalidated 1 cache entries for group group-1", + ), + ( + "invalidate_public_workspace_search_cache", ("workspace-1",), {}, + holding({"id": "cache-1", "user_id": "public:workspace-1"}), + "Invalidated 1 cache entries for public workspace workspace-1", + ), +) + +# Every value each flagged line writes carries a line break here. +INJECTED_UTILS_CACHE_LINES = ( + ( + "get_group_document_fingerprint", ("group-1\nFORGED",), {}, failing("Cosmos query failed\r\nFORGED entry"), + "Error generating group document fingerprint for group group-1 FORGED: Cosmos query failed FORGED entry", + ), + ( + "get_public_workspace_document_fingerprint", ("workspace-1\r\nFORGED",), {}, + failing("Cosmos query failed\nFORGED entry"), + "Error generating public workspace document fingerprint for workspace workspace-1 FORGED: " + "Cosmos query failed FORGED entry", + ), + ( + "get_cached_search_results", ("cache-key-1\nFORGED", "user-1\r\nFORGED", "scope\nFORGED"), {}, holding(), + "Cache hit for key: cache-key-1 FORGED (scope: scope FORGED, partition: user-1 FORGED)", + ), + ( + "cache_search_results", ("cache-key-1\r\nFORGED", [{"id": "result-1"}], "user-1\nFORGED", "scope\r\nFORGED"), + {}, holding(), + "Cached search results with key: cache-key-1 FORGED, scope: scope FORGED, partition: user-1 FORGED, " + "ttl: 300s, expires at: 2026-01-02 03:09:05+00:00", + ), + ( + "invalidate_personal_search_cache", ("user-1\r\nFORGED",), {}, holding({"id": "cache-1"}), + "Invalidated 1 cache entries for user user-1 FORGED", + ), + ( + "invalidate_group_search_cache", ("group-1\nFORGED",), {}, + holding({"id": "cache-1", "user_id": "group:group-1"}), + "Invalidated 1 cache entries for group group-1 FORGED", + ), + ( + "invalidate_public_workspace_search_cache", ("workspace-1\r\nFORGED",), {}, + holding({"id": "cache-1", "user_id": "public:workspace-1"}), + "Invalidated 1 cache entries for public workspace workspace-1 FORGED", + ), +) + + +@pytest.mark.parametrize( + "function_name, args, kwargs, container_factory, expected", + ORDINARY_UTILS_CACHE_LINES, + ids=[case[0] for case in ORDINARY_UTILS_CACHE_LINES], +) +def test_utils_cache_logs_an_ordinary_identifier_exactly_as_before( + function_name, args, kwargs, container_factory, expected +): + messages = run_utils_cache(function_name, *args, container=container_factory(), **kwargs) + assert messages == [expected] + + +@pytest.mark.parametrize( + "function_name, args, kwargs, container_factory, expected", + INJECTED_UTILS_CACHE_LINES, + ids=[case[0] for case in INJECTED_UTILS_CACHE_LINES], +) +def test_utils_cache_keeps_an_injected_identifier_on_one_line( + function_name, args, kwargs, container_factory, expected +): + messages = run_utils_cache(function_name, *args, container=container_factory(), **kwargs) + assert messages == [expected] + assert not [message for message in messages if "\r" in message or "\n" in message] + + +WORKFLOW_CANCEL_ROUTES = ("cancel_user_workflow_run", "cancel_active_group_workflow_run") + +# (route, the failure it handles, response status, the line it logged before this fix) +WORKFLOW_CANCEL_LINES = ( + ( + "cancel_user_workflow_run", lambda namespace: LookupError("Workflow run was not found."), 404, + "LookupError while cancelling personal workflow run. workflow_id={workflow_id} run_id={run_id} user_id=user-1", + ), + ( + "cancel_user_workflow_run", + lambda namespace: namespace["WorkflowCancellationConflictError"]("This workflow run has already finished."), + 409, + "WorkflowCancellationConflictError while cancelling personal workflow run. " + "workflow_id={workflow_id} run_id={run_id} user_id=user-1", + ), + ( + "cancel_active_group_workflow_run", lambda namespace: ValueError("No active group."), 400, + "Invalid group workflow request during cancellation. user_id=user-1 workflow_id={workflow_id}", + ), + ( + "cancel_active_group_workflow_run", lambda namespace: LookupError("Group not found."), 404, + "Group workspace lookup failed during workflow cancellation. user_id=user-1 workflow_id={workflow_id}", + ), + ( + "cancel_active_group_workflow_run", lambda namespace: PermissionError("Not a group member."), 403, + "Unauthorized group workflow cancellation attempt. user_id=user-1 workflow_id={workflow_id}", + ), +) +WORKFLOW_CANCEL_IDS = [ + "personal-lookup", "personal-conflict", "group-invalid", "group-lookup", "group-permission", +] + + +def run_workflow_cancel_route(route_name, workflow_id, run_id, failure): + """Call a cancellation route executed from source, decorators removed, and capture its log records.""" + module = definitions( + "route_backend_workflows.py", + {"WorkflowCancellationConflictError"}, + register="register_route_backend_workflows", + nested=WORKFLOW_CANCEL_ROUTES, + ) + for node in module.body: + if isinstance(node, ast.FunctionDef): + node.decorator_list = [] + + def raise_failure(*args, **kwargs): + raise failure(namespace) + + namespace = { + "logging": logging, + "jsonify": lambda body: body, + "sanitize_log_message": functions_appinsights.sanitize_log_message, + "get_current_user_id": lambda: "user-1", + "get_personal_workflow": lambda user_id, requested_workflow_id: {"id": requested_workflow_id}, + "_request_workflow_run_cancellation": raise_failure, + "_resolve_group_workflow_request_group": raise_failure, + } + exec(compile(module, "route_backend_workflows.py", "exec"), namespace) + args = (workflow_id, run_id) if route_name == "cancel_user_workflow_run" else (workflow_id,) + + capture = RecordCapture() + root = logging.getLogger() + root.addHandler(capture) + try: + response = namespace[route_name](*args) + finally: + root.removeHandler(capture) + return response, [record for record in capture.records if record.name == "root"] + + +@pytest.mark.parametrize( + "route_name, failure, status, expected", WORKFLOW_CANCEL_LINES, ids=WORKFLOW_CANCEL_IDS, +) +def test_workflow_cancellation_logs_an_ordinary_identifier_exactly_as_before(route_name, failure, status, expected): + response, records = run_workflow_cancel_route(route_name, "wf-1", "run-1", failure) + messages = [record.getMessage() for record in records] + assert response[1] == status + assert messages == [expected.format(workflow_id="wf-1", run_id="run-1")] + + +@pytest.mark.parametrize( + "route_name, failure, status, expected", WORKFLOW_CANCEL_LINES, ids=WORKFLOW_CANCEL_IDS, +) +def test_workflow_cancellation_keeps_an_injected_identifier_on_one_line_with_its_traceback( + route_name, failure, status, expected +): + response, records = run_workflow_cancel_route(route_name, "wf-1\nFORGED", "run-1\r\nFORGED", failure) + messages = [record.getMessage() for record in records] + formatted = [logging.Formatter().format(record) for record in records] + assert response[1] == status + assert messages == [expected.format(workflow_id="wf-1 FORGED", run_id="run-1 FORGED")] + assert records[0].levelno == logging.ERROR + assert records[0].exc_info is not None and records[0].exc_info[1] is not None + assert "Traceback (most recent call last)" in formatted[0] + + +PLUGIN_SETTINGS_FIELDS = ( + "enable_time_plugin", + "enable_http_plugin", + "enable_wait_plugin", + "enable_math_plugin", + "enable_text_plugin", + "enable_default_embedding_model_plugin", + "allow_user_plugins", + "allow_group_plugins", +) +FAKE_API_KEY = "sk-FAKE-log-injection-0123456789abcdef" + + +def run_plugin_settings_update(payload): + """Call update_core_plugin_settings executed from source and capture everything it logs or prints.""" + module = definitions("route_backend_plugins.py", {"update_core_plugin_settings"}) + for node in module.body: + node.decorator_list = [] + events = [] + saved = [] + + def log_event(message, extra=None, **kwargs): + events.append((message, extra, kwargs)) + + def update_settings(updates): + saved.append(updates) + return True + + namespace = { + "builtins": SimpleNamespace(), + "jsonify": lambda body: body, + "log_event": log_event, + "logging": logging, + "request": SimpleNamespace(get_json=lambda force=False: payload), + "update_settings": update_settings, + } + exec(compile(module, "route_backend_plugins.py", "exec"), namespace) + + capture = RecordCapture() + root = logging.getLogger() + previous_level = root.level + root.addHandler(capture) + root.setLevel(logging.DEBUG) + stdout = io.StringIO() + try: + with redirect_stdout(stdout): + response = namespace["update_core_plugin_settings"]() + finally: + root.setLevel(previous_level) + root.removeHandler(capture) + return SimpleNamespace( + response=response, + events=events, + saved=saved, + log_lines=[record.getMessage() for record in capture.records], + stdout=stdout.getvalue(), + reload_requested=getattr(namespace["builtins"], "kernel_reload_needed", False), + ) + + +@pytest.mark.parametrize("payload, error", [ + ( + {**dict.fromkeys(PLUGIN_SETTINGS_FIELDS, True), "api_key": FAKE_API_KEY}, + "Unexpected field: api_key", + ), + ( + {**dict.fromkeys(PLUGIN_SETTINGS_FIELDS, True), "enable_http_plugin": f"api_key={FAKE_API_KEY}"}, + "Field 'enable_http_plugin' must be a boolean.", + ), +], ids=["secret-field", "secret-value"]) +def test_plugin_settings_update_logs_the_field_count_not_the_payload(payload, error): + result = run_plugin_settings_update(payload) + logged_text = repr(result.events) + "\n".join(result.log_lines) + result.stdout + assert result.response == ({"error": error}, 400) + assert result.events == [ + ("[PLUGINS] Received plugin settings update request.", {"field_count": len(payload)}, {}), + ] + assert FAKE_API_KEY not in logged_text + assert result.saved == [] + + +def test_plugin_settings_update_still_saves_a_valid_payload(): + payload = {**dict.fromkeys(PLUGIN_SETTINGS_FIELDS, False), "enable_fact_memory_plugin": True} + result = run_plugin_settings_update(payload) + expected_updates = dict.fromkeys(PLUGIN_SETTINGS_FIELDS, False) + assert result.response == ({"success": True, "updated": expected_updates}, 200) + assert result.saved == [expected_updates] + assert result.reload_requested is True + assert result.events == [ + ("[PLUGINS] Received plugin settings update request.", {"field_count": len(payload)}, {}), + ] + + +PROBE = r''' +import importlib +import sys + +sys.path[:0] = sys.argv[1:3] +from test_support.offline_bootstrap import offline_app_imports + +EDITED = { + "utils_cache": "sanitize_log_message", + "route_backend_workflows": "sanitize_log_message", + "route_backend_plugins": "log_event", +} + +with offline_app_imports() as environment: + for name in sys.argv[3:]: + importlib.import_module(name) + appinsights = importlib.import_module("functions_appinsights") + required = set(EDITED) if "app" in sys.argv[3:] else set(EDITED) & set(sys.argv[3:]) + for name, attribute in EDITED.items(): + module = sys.modules.get(name) + if module is None: + if name in required: + raise AssertionError(f"{name} was not loaded") + continue + if getattr(module, attribute) is not getattr(appinsights, attribute): + raise AssertionError(f"{name} resolved a different {attribute}") + if appinsights.sanitize_log_message("wf-1\r\nFORGED") != "wf-1 FORGED": + raise AssertionError("sanitize_log_message no longer keeps a log line on one line") + if environment.network_attempts: + raise AssertionError("A cold import swallowed a network attempt") +print("PASS: log injection modules cold imports") +''' + + +@pytest.mark.parametrize("optimized", [False, True], ids=["normal", "optimized"]) +@pytest.mark.parametrize("order", [ + ("functions_appinsights", "utils_cache"), + ("utils_cache", "functions_appinsights"), + ("config", "utils_cache"), + # app.py imports functions_authentication before any route module. Importing + # route_backend_workflows first fails on the base too: functions_settings would load first, + # and functions_authentication would copy it before enabled_required exists. + ("functions_authentication", "route_backend_workflows"), + ("route_backend_plugins",), + ("app",), +], ids="+".join) +def test_the_edited_modules_load_cold_in_either_order(order, optimized): + command = [sys.executable, "-B"] + if optimized: + command.append("-O") + process = subprocess.run( + command + ["-c", PROBE, str(APP), str(TESTS), *order], + capture_output=True, text=True, timeout=300, check=False, + ) + output = process.stdout[-8000:] + process.stderr[-8000:] + assert process.returncode == 0, output + assert "PASS:" in process.stdout, output + + +if __name__ == "__main__": + sys.exit(pytest.main([__file__, "-q"])) diff --git a/functional_tests/test_support/log_sanitizer.py b/functional_tests/test_support/log_sanitizer.py new file mode 100644 index 000000000..a5629001b --- /dev/null +++ b/functional_tests/test_support/log_sanitizer.py @@ -0,0 +1,37 @@ +# log_sanitizer.py +"""The application's ``sanitize_log_message`` for closed-namespace harnesses. + +Version: 0.261.216 +Implemented in: 0.261.216 + +Harnesses that execute route or cache functions in a namespace they build must supply +every name those functions use. ``real_sanitize_log_message`` runs +``sanitize_log_message`` and the constants it reads unchanged from +``functions_appinsights.py``, so a harness gets the real line-break removal, secret +masking and truncation without importing Azure Monitor or the settings cache. +""" + +import re +from typing import Any + +from test_support.app_source import run_definitions + + +SANITIZE_LOG_MESSAGE_DEFINITIONS = { + "REDACTED_LOG_VALUE", + "MAX_LOG_STRING_LENGTH", + "SECRET_ASSIGNMENT_RE", + "AUTHORIZATION_VALUE_RE", + "LOG_CONTROL_CHAR_RE", + "sanitize_log_message", +} + + +def real_sanitize_log_message(): + """``sanitize_log_message`` executed from ``functions_appinsights.py``.""" + namespace = run_definitions( + "functions_appinsights.py", + SANITIZE_LOG_MESSAGE_DEFINITIONS, + {"re": re, "Any": Any}, + ) + return namespace["sanitize_log_message"] From 2a38aea0aee13da549127a2c5f83913cd92ca804 Mon Sep 17 00:00:00 2001 From: Paul Lizer Date: Thu, 1 Oct 2026 11:34:11 -0400 Subject: [PATCH 2/2] Keep the group cache log line's existing CodeQL alert identity The first version wrapped group_id inside the invalidate_group_search_cache log call. That line already carries a py/clear-text-logging-sensitive-data alert (a false positive from the _get_trusted_group_upload_scope_ids name), and editing its text changed the fingerprint GitHub matches alerts by, so the PR's CodeQL check reported the existing alert as a new high-severity one. Rebind group_id through sanitize_log_message on the line before the call so the log line keeps its 0.261.213 text. Local CodeQL still clears the log-injection result there, and the clear-text result keeps its fingerprint. Update the fix doc with the GitHub and fingerprint results. Co-authored-by: Copilot App <223556219+Copilot@users.noreply.github.com> --- application/single_app/utils_cache.py | 5 +- .../fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md | 55 +++++++++++++------ 2 files changed, 43 insertions(+), 17 deletions(-) diff --git a/application/single_app/utils_cache.py b/application/single_app/utils_cache.py index f34389d21..e08cc4666 100644 --- a/application/single_app/utils_cache.py +++ b/application/single_app/utils_cache.py @@ -722,7 +722,10 @@ def invalidate_group_search_cache(group_id: str, *, document_id=None, strict=Fal "INVALIDATION", group_id=group_id[:8] ) - logger.info(f"Invalidated {count} cache entries for group {sanitize_log_message(group_id)}") + # Rebound rather than wrapped inline so the log line keeps its text, and the + # clear-text CodeQL alert already reported on it keeps its identity. + group_id = sanitize_log_message(group_id) + logger.info(f"Invalidated {count} cache entries for group {group_id}") return count diff --git a/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md b/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md index a86d4568d..6cb1e08cf 100644 --- a/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md +++ b/docs/explanation/fixes/LOG_INJECTION_CODEQL_ALERTS_FIX.md @@ -67,10 +67,10 @@ if len(message_text) > MAX_LOG_STRING_LENGTH: ### utils_cache.py -`utils_cache.py` imports `sanitize_log_message` from `functions_appinsights` and wraps each value -the seven flagged lines write: +`utils_cache.py` imports `sanitize_log_message` from `functions_appinsights` and passes each value +the seven flagged lines write through it: -| Function | Wrapped values | +| Function | Sanitized values | |---|---| | `get_group_document_fingerprint` | `group_id`, the exception | | `get_public_workspace_document_fingerprint` | `public_workspace_id`, the exception | @@ -83,6 +83,15 @@ the seven flagged lines write: - The messages and levels are unchanged. Some f-strings now span several lines. - On the cache hit and write lines, the reported taint comes from `doc_scope` and the partition key. `cache_key` is a hash, but it is wrapped too, so every value on those lines is covered. +- `invalidate_group_search_cache` rebinds `group_id = sanitize_log_message(group_id)` on the line + before its log call instead of wrapping the value inside the call, so the log line keeps its + 0.261.213 text. That line also carries an existing `py/clear-text-logging-sensitive-data` + alert. CodeQL treats the group ID as a secret because of the name of a function it comes from, + `_get_trusted_group_upload_scope_ids()` in `route_frontend_chats.py`. GitHub matches alerts + between analyses by a fingerprint of the text at and just after the alert's line, so the first + version of this fix, which wrapped `group_id` inline, made GitHub report that existing alert as + a new high-severity one. The function returns straight after the log call, so the rebinding + changes nothing else. - The import adds no cycle. `config.py` already imports `functions_appinsights`, whose only application import is `app_settings_cache`, which in turn imports only the standard library, Azure, Redis and `app_settings_store`. @@ -133,7 +142,7 @@ taint tracking finds no request value that reaches them. They are left for follo - `application/single_app/functions_appinsights.py`: the `replace` chain in `sanitize_log_message`. -- `application/single_app/utils_cache.py`: the import and the seven wrapped lines. +- `application/single_app/utils_cache.py`: the import and the seven sanitized lines. - `application/single_app/route_backend_workflows.py`: the import and the seven wrapped arguments. - `application/single_app/route_backend_plugins.py`: the field-count log. @@ -200,19 +209,25 @@ taint tracking finds no request value that reaches them. They are left for follo ## Validation - **Local CodeQL.** CodeQL 2.27.1 with `codeql/python-queries` 1.8.11, the versions in the base - analysis, ran `Security/CWE-117/LogInjection.ql` over the four edited modules, the two settings - cache modules they import and a synthetic Flask driver. The driver feeds request values into - every input of the flagged functions and also logs `sanitize_log_message(value)` directly. - - Base: 23 results. They are the 19 alerts, the driver's direct line, and the three - `utils_cache.py` lines listed under "What is not changed" that log `user_id` or `cache_key`. - The driver reaches those three only by passing request values where the application passes - the signed-in user's ID or a hashed cache key. - - Fix: 3 results, the same three lines. All 19 alerts cleared, and so did the driver's direct - line, which shows that `sanitize_log_message` now works as a sanitizer for its callers. + analysis, ran `Security/CWE-117/LogInjection.ql` and `Security/CWE-312/CleartextLogging.ql` + over the four edited modules, the two settings cache modules they import and a synthetic Flask + driver. The driver registers the workflow routes on a Flask blueprint, as `app.py` does, feeds + request values into every input of the flagged functions, passes the return value of a + function named `_get_trusted_group_upload_scope_ids` to `invalidate_group_search_cache`, and + logs `sanitize_log_message(value)` directly. + - Base: 23 log-injection results. They are the 19 alerts, the driver's direct line, and the + three `utils_cache.py` lines listed under "What is not changed" that log `user_id` or + `cache_key`. The driver reaches those three only by passing request values where the + application passes the signed-in user's ID or a hashed cache key. + - Fix: 3 log-injection results, the same three lines. All 19 alerts cleared, and so did the + driver's direct line, which shows that `sanitize_log_message` now works as a sanitizer for its + callers. + - Both runs report the same three clear-text results, with the same fingerprints, including the + one on the group invalidation log line. - **Mutation checks.** 25 mutations, each run normally and under `-O`, 50 runs in all, were each caught by at least one test: - - unwrapping any one of the 20 wrapped values (13 in `utils_cache.py`, 7 in - `route_backend_workflows.py`) + - unwrapping any one of the 20 `sanitize_log_message` calls (13 in `utils_cache.py`, one of them + the `group_id` rebinding, and 7 in `route_backend_workflows.py`) - moving the replaces ahead of the regex (3 tests fail) - dropping the replaces (the AST check fails) - restoring the payload log (3 plugin tests fail) @@ -220,7 +235,15 @@ taint tracking finds no request value that reaches them. They are left for follo `route_backend_workflows.py` (2 import tests fail) The source files were restored byte-identical afterwards. -- **GitHub CodeQL.** The pull request's merge ref is checked once its CodeQL analysis finishes. +- **GitHub CodeQL.** The pull request's first analysis reported no new `py/log-injection` alert. + Its one new alert was the existing clear-text alert on the group invalidation line, which that + version had wrapped inline. The `group_id` rebinding described under utils_cache.py fixes it. +- **Alert fingerprints.** A reimplementation of the fingerprint GitHub computes reproduces all + 1,096 fingerprints in the base analysis. On the final code, 149 of the 163 base results in the + edited files keep their fingerprints. The 14 that change are log-injection alerts on lines this + fix edits. The other five log-injection alerts, the four in `functions_appinsights.py` and the + group invalidation one, keep their fingerprints, so GitHub closes them only when CodeQL stops + reporting them, which the local run shows it does. ## Related