diff --git a/app/test_engine/models/manual_test_case.py b/app/test_engine/models/manual_test_case.py index 6b4c1413..00693f8d 100644 --- a/app/test_engine/models/manual_test_case.py +++ b/app/test_engine/models/manual_test_case.py @@ -35,6 +35,13 @@ OUTCOME_TIMEOUT_S = 60 * 10 # Seconds LOG_UPLOAD_TIMEOUT_S = 60 * 10 # Seconds +# Number of lines from an uploaded manual log to combine into a single log entry. +# Uploaded logs can have hundreds of thousands of lines; logging (and therefore +# broadcasting to the UI websocket and persisting to the DB) one entry per line +# stalls the event loop for long enough that the websocket's keepalive ping/pong +# times out and the connection is dropped (see GitHub issue #1062). +MANUAL_LOG_CHUNK_LINES = 500 + class TestError(Exception): """Raised when an error occurs during execution.""" @@ -197,16 +204,28 @@ def handle_uploaded_file(self, file: UploadFile) -> None: logger.info(f"Uploading manual log: {file.filename}") logger.info("---- Start of Manual Log ----") + had_invalid_utf8 = False with file.file as f: + chunk: list[str] = [] for line in f: try: - logger.info(line.decode("utf-8").strip()) + chunk.append(line.decode("utf-8").rstrip("\r\n")) except UnicodeDecodeError: - logger.warning( - "WARNING: The following line contained invalid UTF-8." - " Some content was replaced with: �" - ) - logger.info(line.decode("utf-8", errors="replace").strip()) + had_invalid_utf8 = True + chunk.append(line.decode("utf-8", errors="replace").rstrip("\r\n")) + + if len(chunk) >= MANUAL_LOG_CHUNK_LINES: + logger.info("\n".join(chunk)) + chunk = [] + + if chunk: + logger.info("\n".join(chunk)) + + if had_invalid_utf8: + logger.warning( + "WARNING: The uploaded log contained lines with invalid UTF-8." + " Some content was replaced with: �" + ) logger.info("---- End of Manual Log ----") diff --git a/app/tests/test_engine/test_manual_test_case.py b/app/tests/test_engine/test_manual_test_case.py new file mode 100644 index 00000000..fc377586 --- /dev/null +++ b/app/tests/test_engine/test_manual_test_case.py @@ -0,0 +1,121 @@ +# +# Copyright (c) 2026 Project CHIP Authors +# +# 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. +# +from io import BytesIO +from typing import BinaryIO, Optional +from unittest import mock + +from app.test_engine.models.manual_test_case import ( + MANUAL_LOG_CHUNK_LINES, + ManualLogUploadStep, +) + + +class FakeUploadFile: + """Minimal stand-in for FastAPI's UploadFile used by handle_uploaded_file.""" + + def __init__(self, content: bytes, content_type: str = "text/plain") -> None: + self.file: BinaryIO = BytesIO(content) + self.filename: Optional[str] = "manual_log.txt" + self.content_type = content_type + + +@mock.patch("app.test_engine.models.manual_test_case.logger") +def test_handle_uploaded_file_rejects_unsupported_content_type( + mock_logger: mock.Mock, +) -> None: + step = ManualLogUploadStep("Prompt Manual Log Upload") + step.append_failure = mock.Mock() # type: ignore[method-assign] + + step.handle_uploaded_file(FakeUploadFile(b"irrelevant", content_type="image/png")) + + step.append_failure.assert_called_once() + mock_logger.info.assert_not_called() + + +@mock.patch("app.test_engine.models.manual_test_case.logger") +def test_handle_uploaded_file_batches_lines_into_chunks(mock_logger: mock.Mock) -> None: + """A large uploaded log must not result in one logger.info() call per line. + + Regression test for GitHub issue #1062: logging one entry per line floods + the same channel used to broadcast updates over the websocket and to + persist to the DB, stalling the event loop long enough that the + websocket's ping/pong keepalive times out mid-upload. + """ + line_count = MANUAL_LOG_CHUNK_LINES * 2 + 3 + content = "\n".join(f"line-{i}" for i in range(line_count)).encode("utf-8") + + step = ManualLogUploadStep("Prompt Manual Log Upload") + step.append_failure = mock.Mock() # type: ignore[method-assign] + + step.handle_uploaded_file(FakeUploadFile(content)) + + step.append_failure.assert_not_called() + + # "Uploading manual log: ...", "---- Start ----", N chunk(s), "---- End ----" + info_calls = [call.args[0] for call in mock_logger.info.call_args_list] + assert info_calls[0].startswith("Uploading manual log:") + assert info_calls[1] == "---- Start of Manual Log ----" + assert info_calls[-1] == "---- End of Manual Log ----" + + chunk_calls = info_calls[2:-1] + # 2 full chunks + 1 partial chunk, never one call per line. + assert len(chunk_calls) == 3 + assert chunk_calls[0].count("\n") == MANUAL_LOG_CHUNK_LINES - 1 + assert chunk_calls[-1].count("\n") == 2 # trailing partial chunk of 3 lines + + # All lines are still present, in order, across the batched calls. + reconstructed = "\n".join(chunk_calls).splitlines() + assert reconstructed == [f"line-{i}" for i in range(line_count)] + + +@mock.patch("app.test_engine.models.manual_test_case.logger") +def test_handle_uploaded_file_replaces_invalid_utf8_and_warns_once( + mock_logger: mock.Mock, +) -> None: + content = b"good line\n\xff\xfe bad line\ngood line 2\n" + + step = ManualLogUploadStep("Prompt Manual Log Upload") + step.append_failure = mock.Mock() # type: ignore[method-assign] + + step.handle_uploaded_file(FakeUploadFile(content)) + + mock_logger.warning.assert_called_once() + info_calls = [call.args[0] for call in mock_logger.info.call_args_list] + body = "\n".join(info_calls[2:-1]) + assert "�" in body + + +@mock.patch("app.test_engine.models.manual_test_case.logger") +def test_handle_uploaded_file_strips_windows_line_endings( + mock_logger: mock.Mock, +) -> None: + """Windows-style CRLF line endings must not leave a stray \\r in each line. + + Regression test: an earlier version of this fix used .rstrip("\\n"), which + left a trailing \\r on every line of a CRLF-terminated file, corrupting the + joined chunk with embedded carriage returns. + """ + content = b"line one\r\nline two\r\nline three\r\n" + + step = ManualLogUploadStep("Prompt Manual Log Upload") + step.append_failure = mock.Mock() # type: ignore[method-assign] + + step.handle_uploaded_file(FakeUploadFile(content)) + + info_calls = [call.args[0] for call in mock_logger.info.call_args_list] + body = "\n".join(info_calls[2:-1]) + assert "\r" not in body + assert body.splitlines() == ["line one", "line two", "line three"] diff --git a/app/uvicorn_worker.py b/app/uvicorn_worker.py new file mode 100644 index 00000000..f65c512a --- /dev/null +++ b/app/uvicorn_worker.py @@ -0,0 +1,38 @@ +# +# Copyright (c) 2026 Project CHIP Authors +# +# 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. +# +"""Gunicorn worker class with a longer websocket ping timeout. + +Uploading a large manual test log (see GitHub issue #1062) can keep the event +loop busy for an extended period (each uploaded line is turned into a log +entry that gets broadcast over the same main websocket and persisted to the +DB). With uvicorn's default ``ws_ping_timeout`` (20s), the websocket's +keepalive ping/pong can't be serviced in time, causing the connection to be +dropped mid-upload with `ConnectionClosedError: no close frame received or +sent`. + +This mirrors the ``--ws-ping-timeout 60`` flag already used by the dev-only +``gunicorn/start-reload.sh`` script, so production gets the same tolerance. +""" +from uvicorn.workers import UvicornWorker + +WS_PING_TIMEOUT_S = 60 + + +class ExtendedTimeoutUvicornWorker(UvicornWorker): + CONFIG_KWARGS = { + **UvicornWorker.CONFIG_KWARGS, + "ws_ping_timeout": WS_PING_TIMEOUT_S, + } diff --git a/gunicorn/start.sh b/gunicorn/start.sh index 6de8d8d7..cf987e2f 100644 --- a/gunicorn/start.sh +++ b/gunicorn/start.sh @@ -40,7 +40,10 @@ else DEFAULT_GUNICORN_CONF=/gunicorn_conf.py fi export GUNICORN_CONF=${GUNICORN_CONF:-$DEFAULT_GUNICORN_CONF} -export WORKER_CLASS=${WORKER_CLASS:-"uvicorn.workers.UvicornWorker"} +# ExtendedTimeoutUvicornWorker raises ws_ping_timeout (default UvicornWorker: 20s). +# Uploading a large manual test log can keep the event loop busy long enough for +# the default timeout to drop the websocket mid-upload (issue #1062). +export WORKER_CLASS=${WORKER_CLASS:-"app.uvicorn_worker.ExtendedTimeoutUvicornWorker"} # If there's a prestart.sh script in the /app directory or other path specified, run it before starting DEFAULT_PRE_START_PATH="/app/prestart.sh"