From cfa3c3eae7746286b9e01dcf9d4854e1f1474202 Mon Sep 17 00:00:00 2001 From: Romulo Quidute Filho Date: Wed, 22 Jul 2026 10:01:45 -0300 Subject: [PATCH 1/3] Fix WebSocket disconnect during large manual log file uploads Uploading a manual test log with hundreds of thousands of lines (e.g. TC-CADMIN-1.17) called logger.info() once per line. Each call triggered a broadcast over the same main WebSocket used by the CLI and a synchronous DB commit, stalling the event loop long enough for the WebSocket's ping/pong keepalive to time out mid-upload. The connection was dropped with ConnectionClosedError, and the next prompt-response send failed with 'Unexpected error uploading file' even though the upload itself had already succeeded (issue #1062). - Batch uploaded log lines into chunks of 500 before calling logger.info(), instead of one call per line, so a large file produces a handful of log/broadcast/DB-commit operations instead of hundreds of thousands. - Collapse the invalid-UTF-8 warning to a single message per upload instead of one per bad line. - Add app.uvicorn_worker.ExtendedTimeoutUvicornWorker, which raises ws_ping_timeout to 60s (matching the value already used by the dev-only start-reload.sh script), and wire it up as the default worker class in gunicorn/start.sh so production tolerates the same event-loop stalls as local dev. - Add unit tests covering chunked logging, invalid UTF-8 handling, and unsupported content-type rejection. --- app/test_engine/models/manual_test_case.py | 31 ++++-- .../test_engine/test_manual_test_case.py | 98 +++++++++++++++++++ app/uvicorn_worker.py | 38 +++++++ gunicorn/start.sh | 5 +- 4 files changed, 165 insertions(+), 7 deletions(-) create mode 100644 app/tests/test_engine/test_manual_test_case.py create mode 100644 app/uvicorn_worker.py diff --git a/app/test_engine/models/manual_test_case.py b/app/test_engine/models/manual_test_case.py index 6b4c1413..8be91bb2 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("\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("\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..d221f58f --- /dev/null +++ b/app/tests/test_engine/test_manual_test_case.py @@ -0,0 +1,98 @@ +# +# 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 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 = 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 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" From 9fa20ca7ce29dc97c13718ca0d9fa494dfd01656 Mon Sep 17 00:00:00 2001 From: Romulo Quidute Filho Date: Wed, 22 Jul 2026 15:02:17 -0300 Subject: [PATCH 2/3] Address review: strip CRLF instead of LF only when batching log lines .rstrip("\n") left a trailing \r on every line of a Windows-style (CRLF) uploaded log, since the file is read in binary mode and split only on \n. That stray \r would end up embedded in the joined chunk, showing up as ^M characters or unexpected double newlines wherever the chunk is logged or displayed. Use .rstrip("\r\n") so both Unix and Windows line endings are handled correctly. Add a regression test with a CRLF-terminated upload. --- app/test_engine/models/manual_test_case.py | 4 ++-- .../test_engine/test_manual_test_case.py | 23 +++++++++++++++++++ 2 files changed, 25 insertions(+), 2 deletions(-) diff --git a/app/test_engine/models/manual_test_case.py b/app/test_engine/models/manual_test_case.py index 8be91bb2..00693f8d 100644 --- a/app/test_engine/models/manual_test_case.py +++ b/app/test_engine/models/manual_test_case.py @@ -209,10 +209,10 @@ def handle_uploaded_file(self, file: UploadFile) -> None: chunk: list[str] = [] for line in f: try: - chunk.append(line.decode("utf-8").rstrip("\n")) + chunk.append(line.decode("utf-8").rstrip("\r\n")) except UnicodeDecodeError: had_invalid_utf8 = True - chunk.append(line.decode("utf-8", errors="replace").rstrip("\n")) + chunk.append(line.decode("utf-8", errors="replace").rstrip("\r\n")) if len(chunk) >= MANUAL_LOG_CHUNK_LINES: logger.info("\n".join(chunk)) diff --git a/app/tests/test_engine/test_manual_test_case.py b/app/tests/test_engine/test_manual_test_case.py index d221f58f..d8714973 100644 --- a/app/tests/test_engine/test_manual_test_case.py +++ b/app/tests/test_engine/test_manual_test_case.py @@ -96,3 +96,26 @@ def test_handle_uploaded_file_replaces_invalid_utf8_and_warns_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"] From 1553d172a2c55666caf1c099e902c05dd5962543 Mon Sep 17 00:00:00 2001 From: Romulo Quidute Filho Date: Wed, 22 Jul 2026 16:14:09 -0300 Subject: [PATCH 3/3] Fix CI mypy error: annotate FakeUploadFile.file as BinaryIO mypy's structural check against the UploadFile protocol requires file: BinaryIO exactly; a bare BytesIO() assignment left the attribute inferred as BytesIO, which mypy treats as incompatible with the protocol's BinaryIO annotation despite BytesIO satisfying it at runtime. Annotate the attribute explicitly so handle_uploaded_file(FakeUploadFile(...)) type-checks. --- app/tests/test_engine/test_manual_test_case.py | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/app/tests/test_engine/test_manual_test_case.py b/app/tests/test_engine/test_manual_test_case.py index d8714973..fc377586 100644 --- a/app/tests/test_engine/test_manual_test_case.py +++ b/app/tests/test_engine/test_manual_test_case.py @@ -14,7 +14,7 @@ # limitations under the License. # from io import BytesIO -from typing import Optional +from typing import BinaryIO, Optional from unittest import mock from app.test_engine.models.manual_test_case import ( @@ -27,7 +27,7 @@ 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 = BytesIO(content) + self.file: BinaryIO = BytesIO(content) self.filename: Optional[str] = "manual_log.txt" self.content_type = content_type