|
| 1 | +# Copyright Amazon.com, Inc. or its affiliates. All Rights Reserved. |
| 2 | + |
| 3 | +"""Hardening of the action-output filter: log redaction, and containment of |
| 4 | +consumer callbacks. |
| 5 | +
|
| 6 | +``ActionMonitoringFilter`` runs on the thread forwarding a subprocess's stdout, |
| 7 | +so anything that escapes it unwinds ``LoggingSubprocess.run()`` and costs us the |
| 8 | +output stream and process ownership. It is also the control that keeps secrets |
| 9 | +out of the log. |
| 10 | +""" |
| 11 | + |
| 12 | +import logging |
| 13 | +import sys |
| 14 | +from typing import Any |
| 15 | +from unittest.mock import MagicMock, patch |
| 16 | + |
| 17 | +import pytest |
| 18 | + |
| 19 | +from openjd.model.v2023_09 import ( |
| 20 | + Action as Action_2023_09, |
| 21 | + ArgString as ArgString_2023_09, |
| 22 | + CommandString as CommandString_2023_09, |
| 23 | + StepActions as StepActions_2023_09, |
| 24 | + StepScript as StepScript_2023_09, |
| 25 | +) |
| 26 | + |
| 27 | +from openjd.sessions import ActionState, Session, SessionState |
| 28 | +from openjd.sessions._action_filter import ( |
| 29 | + ActionMessageKind, |
| 30 | + ActionMonitoringFilter, |
| 31 | + envvar_set_matcher_json, |
| 32 | + envvar_set_matcher_str, |
| 33 | + envvar_unset_matcher, |
| 34 | +) |
| 35 | + |
| 36 | + |
| 37 | +def _make_record( |
| 38 | + msg: str, args: Any = None, session_id: str = "foo", level: int = logging.INFO |
| 39 | +) -> logging.LogRecord: |
| 40 | + """A LogRecord shaped the way the session logger produces them.""" |
| 41 | + record = logging.LogRecord("test", level, "path", 1, msg, args, None) |
| 42 | + record.session_id = session_id # type: ignore[attr-defined] |
| 43 | + return record |
| 44 | + |
| 45 | + |
| 46 | +class _UnrenderableError(Exception): |
| 47 | + """An exception whose rendering raises -- the shape that defeated the R5-2 |
| 48 | + containment, which interpolated the exception into an f-string.""" |
| 49 | + |
| 50 | + def __str__(self) -> str: |
| 51 | + raise RuntimeError("__str__ is hostile") |
| 52 | + |
| 53 | + def __repr__(self) -> str: |
| 54 | + raise RuntimeError("__repr__ is hostile too") |
| 55 | + |
| 56 | + |
| 57 | +class TestRedactionDoesNotLeakViaRecordArgs: |
| 58 | + """R5-1: `record.args` must be empty by the time the filter returns. |
| 59 | +
|
| 60 | + The redaction logic only ever inspects `record.msg`. A downstream handler |
| 61 | + calls `record.getMessage()`, which re-runs `msg % args` -- so any path that |
| 62 | + leaves `args` populated re-interpolates the *un-scanned* original into the |
| 63 | + emitted line. |
| 64 | + """ |
| 65 | + |
| 66 | + def _filter_with_secret(self, secret: str = "SUPERSECRET") -> ActionMonitoringFilter: |
| 67 | + f = ActionMonitoringFilter(session_id="foo", callback=MagicMock()) |
| 68 | + f._redacted_values.add(secret) |
| 69 | + return f |
| 70 | + |
| 71 | + def test_secret_in_args_is_redacted_when_formatting_succeeds(self) -> None: |
| 72 | + # GIVEN: a secret carried only in args, with a msg that matches nothing |
| 73 | + f = self._filter_with_secret() |
| 74 | + record = _make_record("value is %s", ("SUPERSECRET",)) |
| 75 | + |
| 76 | + # WHEN |
| 77 | + f.filter(record) |
| 78 | + |
| 79 | + # THEN: the emitted line -- which is what a handler actually renders -- |
| 80 | + # carries no secret, and args cannot reintroduce one. |
| 81 | + assert "SUPERSECRET" not in record.getMessage() |
| 82 | + assert not record.args |
| 83 | + |
| 84 | + def test_secret_in_args_is_redacted_when_formatting_fails(self) -> None: |
| 85 | + """The load-bearing case. `%d` against a str raises, so the old code |
| 86 | + skipped clearing args and the handler re-interpolated the secret.""" |
| 87 | + # GIVEN: a record whose own %-formatting is broken |
| 88 | + f = self._filter_with_secret() |
| 89 | + record = _make_record("value is %d", ("SUPERSECRET",)) |
| 90 | + |
| 91 | + # WHEN |
| 92 | + f.filter(record) |
| 93 | + |
| 94 | + # THEN: args are cleared, so getMessage() cannot resurrect the secret, |
| 95 | + # and the secret does not survive anywhere on the record. |
| 96 | + assert not record.args |
| 97 | + assert "SUPERSECRET" not in record.getMessage() |
| 98 | + assert "SUPERSECRET" not in str(record.msg) |
| 99 | + |
| 100 | + def test_record_stays_renderable_when_formatting_fails(self) -> None: |
| 101 | + """Folding args in must not leave a record that raises in the handler.""" |
| 102 | + # GIVEN |
| 103 | + f = self._filter_with_secret() |
| 104 | + record = _make_record("value is %d", ("SUPERSECRET",)) |
| 105 | + |
| 106 | + # WHEN |
| 107 | + f.filter(record) |
| 108 | + |
| 109 | + # THEN: getMessage() does not raise (it would if msg still held %d and |
| 110 | + # args were still a str tuple), and the redaction marker is present. |
| 111 | + assert "*" * 8 in record.getMessage() |
| 112 | + |
| 113 | + def test_whole_line_redaction_clears_args(self) -> None: |
| 114 | + # GIVEN: a message that matches a whole redacted line |
| 115 | + f = ActionMonitoringFilter(session_id="foo", callback=MagicMock()) |
| 116 | + f._redacted_lines.add("secret-line") |
| 117 | + record = _make_record("secret-line", None) |
| 118 | + |
| 119 | + # WHEN |
| 120 | + f.filter(record) |
| 121 | + |
| 122 | + # THEN |
| 123 | + assert record.getMessage() == "*" * 8 |
| 124 | + assert not record.args |
| 125 | + |
| 126 | + def test_args_are_untouched_when_no_redactions_registered(self) -> None: |
| 127 | + """Lazy %-formatting must keep working for every ordinary log line.""" |
| 128 | + # GIVEN: no registered secrets |
| 129 | + f = ActionMonitoringFilter(session_id="foo", callback=MagicMock()) |
| 130 | + record = _make_record("value is %s", ("plain",)) |
| 131 | + |
| 132 | + # WHEN |
| 133 | + f.filter(record) |
| 134 | + |
| 135 | + # THEN: the filter did not fold args in, so the handler still formats. |
| 136 | + assert record.args == ("plain",) |
| 137 | + assert record.getMessage() == "value is plain" |
| 138 | + |
| 139 | + |
| 140 | +# =========================================================================== |
| 141 | +# R5-2 -- consumer callback exceptions must not escape filter() |
| 142 | +# =========================================================================== |
| 143 | + |
| 144 | + |
| 145 | +class TestFilterContainsConsumerCallbackFailures: |
| 146 | + """R5-2: this filter runs on the thread forwarding the subprocess's stdout. |
| 147 | +
|
| 148 | + An exception escaping `filter()` unwinds `LoggingSubprocess.run()` before the |
| 149 | + child is waited on: the pump thread dies, the rest of the output is dropped, |
| 150 | + and the process is left unreaped. |
| 151 | + """ |
| 152 | + |
| 153 | + @pytest.mark.parametrize( |
| 154 | + "exc", |
| 155 | + [RuntimeError("boom"), KeyError("boom"), TypeError("boom"), AttributeError("boom")], |
| 156 | + ids=["RuntimeError", "KeyError", "TypeError", "AttributeError"], |
| 157 | + ) |
| 158 | + def test_handler_callback_exception_does_not_escape(self, exc: Exception) -> None: |
| 159 | + # GIVEN: a consumer callback that raises a non-ValueError |
| 160 | + def callback(kind: ActionMessageKind, value: Any, fail: bool) -> None: |
| 161 | + raise exc |
| 162 | + |
| 163 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 164 | + record = _make_record("openjd_progress: 50.0") |
| 165 | + |
| 166 | + # WHEN / THEN: filter() returns normally... |
| 167 | + assert f.filter(record) is True |
| 168 | + # ...and keeps the record, with the failure visible in the action's output. |
| 169 | + assert "boom" in record.getMessage() |
| 170 | + |
| 171 | + def test_malformed_env_callback_exception_does_not_escape(self) -> None: |
| 172 | + """The one callback invocation in filter() not routed through `handler`.""" |
| 173 | + |
| 174 | + # GIVEN |
| 175 | + def callback(kind: ActionMessageKind, value: Any, fail: bool) -> None: |
| 176 | + raise RuntimeError("boom") |
| 177 | + |
| 178 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 179 | + # A near-miss env command: space before the colon. |
| 180 | + record = _make_record("openjd_env : FOO=bar") |
| 181 | + |
| 182 | + # WHEN / THEN |
| 183 | + assert f.filter(record) is True |
| 184 | + |
| 185 | + def test_valueerror_still_annotates_the_record(self) -> None: |
| 186 | + """The pre-existing ValueError contract must be unchanged.""" |
| 187 | + # GIVEN: progress outside the legal range raises ValueError in the handler |
| 188 | + f = ActionMonitoringFilter(session_id="foo", callback=MagicMock()) |
| 189 | + record = _make_record("openjd_progress: 500.0") |
| 190 | + |
| 191 | + # WHEN / THEN |
| 192 | + assert f.filter(record) is True |
| 193 | + assert "ERROR" in record.getMessage() |
| 194 | + |
| 195 | + def test_redaction_failure_fails_closed(self) -> None: |
| 196 | + """If the redaction control itself breaks, emit nothing rather than an |
| 197 | + unscanned line -- and do not let it reach the pump thread.""" |
| 198 | + # GIVEN |
| 199 | + f = ActionMonitoringFilter(session_id="foo", callback=MagicMock()) |
| 200 | + record = _make_record("carries a secret") |
| 201 | + |
| 202 | + # WHEN |
| 203 | + with patch.object( |
| 204 | + ActionMonitoringFilter, |
| 205 | + "apply_message_redaction", |
| 206 | + side_effect=RuntimeError("redaction is broken"), |
| 207 | + ): |
| 208 | + result = f.filter(record) |
| 209 | + |
| 210 | + # THEN |
| 211 | + assert result is True |
| 212 | + assert record.getMessage() == "*" * 8 |
| 213 | + |
| 214 | + def test_a_live_child_is_still_reaped_when_the_callback_raises(self) -> None: |
| 215 | + """End to end: the reason R5-2 matters. A progress update from a live |
| 216 | + child must not cost us the process.""" |
| 217 | + # GIVEN: a consumer that raises on the first progress update |
| 218 | + state: dict[str, Any] = {"raised": False} |
| 219 | + |
| 220 | + def callback(session_id: str, status: Any) -> None: |
| 221 | + if status.progress is not None and not state["raised"]: |
| 222 | + state["raised"] = True |
| 223 | + raise RuntimeError("consumer blew up on a progress update") |
| 224 | + |
| 225 | + script = StepScript_2023_09( |
| 226 | + actions=StepActions_2023_09( |
| 227 | + onRun=Action_2023_09( |
| 228 | + command=CommandString_2023_09(sys.executable), |
| 229 | + args=[ |
| 230 | + ArgString_2023_09("-c"), |
| 231 | + ArgString_2023_09( |
| 232 | + "print('openjd_progress: 50.0', flush=True)\n" |
| 233 | + "print('done', flush=True)\n" |
| 234 | + ), |
| 235 | + ], |
| 236 | + ) |
| 237 | + ) |
| 238 | + ) |
| 239 | + |
| 240 | + # WHEN |
| 241 | + with Session(session_id="r5-2-e2e", job_parameter_values={}, callback=callback) as session: |
| 242 | + session.run_task(step_script=script, task_parameter_values={}) |
| 243 | + deadline = 60.0 |
| 244 | + import time |
| 245 | + |
| 246 | + start = time.monotonic() |
| 247 | + while session.state == SessionState.RUNNING and time.monotonic() - start < deadline: |
| 248 | + time.sleep(0.05) |
| 249 | + |
| 250 | + # THEN: the consumer did raise, the action still reached a terminal |
| 251 | + # state, and the subprocess was waited on -- an exit code proves the |
| 252 | + # `wait()` in LoggingSubprocess.run() was reached rather than skipped. |
| 253 | + assert state["raised"] is True |
| 254 | + assert session.state != SessionState.RUNNING |
| 255 | + assert session.action_status is not None |
| 256 | + assert session.action_status.exit_code == 0 |
| 257 | + assert session.action_status.state == ActionState.SUCCESS |
| 258 | + |
| 259 | + |
| 260 | +# =========================================================================== |
| 261 | +# SIB-1 -- env var name anchoring (sibling of R5-5, found during this round) |
| 262 | +# =========================================================================== |
| 263 | + |
| 264 | + |
| 265 | +class TestEnvVarNameAnchoring: |
| 266 | + """`$` also matches immediately before a trailing newline, so an |
| 267 | + `$`-anchored NAME pattern accepted "FOO\\n" -- a name no OS can hold. |
| 268 | +
|
| 269 | + The VALUE half stays deliberately permissive: a multi-line value delivered |
| 270 | + through the JSON form is supported, tested behaviour. |
| 271 | + """ |
| 272 | + |
| 273 | + @pytest.mark.parametrize("name", ["FOO\n", "FOO\r", "FOO\r\n"]) |
| 274 | + def test_unset_rejects_a_trailing_newline_in_the_name(self, name: str) -> None: |
| 275 | + assert envvar_unset_matcher.match(name) is None |
| 276 | + |
| 277 | + def test_unset_still_accepts_a_legal_name(self) -> None: |
| 278 | + assert envvar_unset_matcher.match("FOO_BAR9") is not None |
| 279 | + |
| 280 | + @pytest.mark.parametrize("payload", ["FOO=bar\n", "FOO\n=bar"]) |
| 281 | + def test_set_rejects_a_trailing_newline(self, payload: str) -> None: |
| 282 | + assert envvar_set_matcher_str.match(payload) is None |
| 283 | + |
| 284 | + def test_multiline_value_via_json_is_still_supported(self) -> None: |
| 285 | + """Guards the intended feature against over-correction.""" |
| 286 | + # GIVEN / WHEN |
| 287 | + raw = '"FOO=BAR\\nBAZ"' |
| 288 | + # THEN: the raw (escaped) form still validates... |
| 289 | + assert envvar_set_matcher_json.match(raw) is not None |
| 290 | + # ...and the decoded multi-line value still reaches the callback. |
| 291 | + callback = MagicMock() |
| 292 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 293 | + f.filter(_make_record('openjd_env: "FOO=BAR\\nBAZ"')) |
| 294 | + env_calls = [ |
| 295 | + c |
| 296 | + for c in callback.call_args_list |
| 297 | + if c[0][0] == ActionMessageKind.ENV and isinstance(c[0][1], dict) |
| 298 | + ] |
| 299 | + assert len(env_calls) == 1 |
| 300 | + assert env_calls[0][0][1] == {"name": "FOO", "value": "BAR\nBAZ"} |
| 301 | + |
| 302 | + @pytest.mark.parametrize( |
| 303 | + "msg", |
| 304 | + [ |
| 305 | + 'openjd_env: "FOO\\nBAR=baz"', |
| 306 | + 'openjd_env: "FOO\\u000aBAR=baz"', |
| 307 | + 'openjd_env: "FOO\\u0000BAR=baz"', |
| 308 | + ], |
| 309 | + ) |
| 310 | + def test_a_separator_cannot_reach_a_decoded_name(self, msg: str) -> None: |
| 311 | + """A name carrying a separator must be rejected outright, not passed on. |
| 312 | +
|
| 313 | + Rewritten after an audit: the previous version looped over the recorded |
| 314 | + calls asserting a property of any dict it found, and since these inputs |
| 315 | + produce no ENV dict at all, its assertion body never executed. It passed |
| 316 | + against a deliberately broken implementation. Assert the rejection |
| 317 | + directly instead. |
| 318 | + """ |
| 319 | + # GIVEN |
| 320 | + callback = MagicMock() |
| 321 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 322 | + |
| 323 | + # WHEN |
| 324 | + f.filter(_make_record(msg)) |
| 325 | + |
| 326 | + # THEN: no environment variable was defined, and the failure was reported. |
| 327 | + env_defs = [ |
| 328 | + c |
| 329 | + for c in callback.call_args_list |
| 330 | + if c[0][0] == ActionMessageKind.ENV and isinstance(c[0][1], dict) |
| 331 | + ] |
| 332 | + assert env_defs == [] |
| 333 | + assert callback.call_args_list, "the parse failure must be reported to the consumer" |
| 334 | + assert callback.call_args_list[-1][0][2] is True # cancel-and-fail |
| 335 | + |
| 336 | + |
| 337 | +# =========================================================================== |
| 338 | +# R5-3 -- the shared temporary root must be validated before use |
| 339 | +# =========================================================================== |
| 340 | + |
| 341 | + |
| 342 | +class TestContainmentDoesNotReRaise: |
| 343 | + def test_handler_path_contains_an_unrenderable_exception(self) -> None: |
| 344 | + # GIVEN: a consumer callback raising an exception that cannot be rendered |
| 345 | + def callback(kind: ActionMessageKind, value: Any, fail: bool) -> None: |
| 346 | + raise _UnrenderableError() |
| 347 | + |
| 348 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 349 | + record = _make_record("openjd_progress: 50.0") |
| 350 | + |
| 351 | + # WHEN / THEN: filter() still returns rather than letting the exception |
| 352 | + # reach the stdout pump thread. |
| 353 | + assert f.filter(record) is True |
| 354 | + assert "_UnrenderableError" in record.getMessage() |
| 355 | + |
| 356 | + def test_malformed_env_path_contains_an_unrenderable_exception(self) -> None: |
| 357 | + # GIVEN |
| 358 | + def callback(kind: ActionMessageKind, value: Any, fail: bool) -> None: |
| 359 | + raise _UnrenderableError() |
| 360 | + |
| 361 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 362 | + |
| 363 | + # WHEN / THEN |
| 364 | + assert f.filter(_make_record("openjd_env : FOO=bar")) is True |
| 365 | + |
| 366 | + def test_renderable_exceptions_still_report_their_message(self) -> None: |
| 367 | + """The defensive rendering must not degrade the ordinary case.""" |
| 368 | + |
| 369 | + # GIVEN |
| 370 | + def callback(kind: ActionMessageKind, value: Any, fail: bool) -> None: |
| 371 | + raise RuntimeError("a perfectly ordinary boom") |
| 372 | + |
| 373 | + f = ActionMonitoringFilter(session_id="foo", callback=callback) |
| 374 | + record = _make_record("openjd_progress: 50.0") |
| 375 | + |
| 376 | + # WHEN |
| 377 | + f.filter(record) |
| 378 | + |
| 379 | + # THEN |
| 380 | + assert "a perfectly ordinary boom" in record.getMessage() |
| 381 | + |
| 382 | + |
| 383 | +# =========================================================================== |
| 384 | +# REG-3 -- the R5-3 validation must not be defeatable by a symlink swap |
| 385 | +# =========================================================================== |
0 commit comments