From 393b0c0f9c142570d0ae9d2bc406d147602cbc91 Mon Sep 17 00:00:00 2001 From: THOTH Date: Thu, 12 Nov 2026 08:00:16 +0900 Subject: [PATCH 1/9] Record unexpected command failures in a server log When a command ended with an unexpected exception, the server returned "internal command failure" and kept no record of it, so a beta report could only be investigated by reproducing it. The bus now writes one record per failure (method, operation id, project id, exception chain, short call path), and serve/desktop write warnings to the console and to /logs/thoth.log (1 MB, 3 old files). Request string values, token shaped strings and text past 300 characters are removed from the record. The screen shows the operation id with an internal failure so a report can be matched to the log line. Background indexing and dense scoring failures still do not block requests but are now recorded once per place. A cancel request with a non-JSON body returns 400 instead of 500. --- .github/ISSUE_TEMPLATE/beta-feedback.yml | 12 ++ SOURCE_MANIFEST.json | 89 +++++++---- apps/web/src/api/rpcClient.test.ts | 34 +++++ apps/web/src/api/rpcClient.ts | 11 +- config/complexity-budget.json | 2 +- config/module-responsibility-budget.json | 2 +- docs/BETA.md | 7 + docs/INSTALL.md | 16 ++ src/thoth/adapters/http/async_routes.py | 5 +- src/thoth/application/services/auto_index.py | 15 +- .../application/services/dense_material.py | 15 +- src/thoth/apps/log_files.py | 80 ++++++++++ src/thoth/apps/workspace_guard.py | 4 + src/thoth/domain/failure_text.py | 139 ++++++++++++++++++ src/thoth/protocol/bus.py | 82 ++++------- src/thoth/protocol/failure_log.py | 33 +++++ tests/contract/test_internal_failure_log.py | 114 ++++++++++++++ tests/contract/test_local_request_guard.py | 16 ++ tests/unit/apps/test_log_files.py | 126 ++++++++++++++++ tests/unit/domain/test_failure_text.py | 118 +++++++++++++++ .../services/test_auto_index_failure_log.py | 105 +++++++++++++ tests/unit/test_dense_material_reasons.py | 63 ++++++++ 22 files changed, 993 insertions(+), 95 deletions(-) create mode 100644 src/thoth/apps/log_files.py create mode 100644 src/thoth/domain/failure_text.py create mode 100644 src/thoth/protocol/failure_log.py create mode 100644 tests/contract/test_internal_failure_log.py create mode 100644 tests/unit/apps/test_log_files.py create mode 100644 tests/unit/domain/test_failure_text.py create mode 100644 tests/unit/services/test_auto_index_failure_log.py diff --git a/.github/ISSUE_TEMPLATE/beta-feedback.yml b/.github/ISSUE_TEMPLATE/beta-feedback.yml index b5253a56..ab2ca446 100644 --- a/.github/ISSUE_TEMPLATE/beta-feedback.yml +++ b/.github/ISSUE_TEMPLATE/beta-feedback.yml @@ -38,6 +38,18 @@ body: description: Drag an image here. Remove or blur private content first. Optional but very helpful. validations: required: false + - type: textarea + id: log + attributes: + label: Server log lines (서버 로그) + description: >- + If the screen showed "internal command failure [-32603] (operation:...)", paste the lines of + that operation id from logs\thoth.log in your workspace. Read them first; do not attach the + whole file. 화면에 operation id가 보였다면 작업 공간의 logs\thoth.log에서 그 기록의 줄만 + 붙여 주세요. + render: text + validations: + required: false - type: input id: version attributes: diff --git a/SOURCE_MANIFEST.json b/SOURCE_MANIFEST.json index 1c309475..d84bb0e6 100644 --- a/SOURCE_MANIFEST.json +++ b/SOURCE_MANIFEST.json @@ -1,6 +1,6 @@ { "schema_version": "thoth-source-preview-manifest-v1", - "created_at": "2026-11-11T16:25:32.016776+00:00", + "created_at": "2026-11-11T22:32:35.360127+00:00", "license": "MIT", "git_history_included": false, "full_suite_verified": false, @@ -18,8 +18,8 @@ }, { "path": ".github/ISSUE_TEMPLATE/beta-feedback.yml", - "sha256": "3f4e47d614207f0470636bcdaf6192739da2d7f2eaebb0322c47a5b6978008dd", - "bytes": 2610 + "sha256": "e9d8f837f0202d832fa1a0825560ceeb50e75d4f2a4f1bb590f56113a717aa7c", + "bytes": 3128 }, { "path": ".github/workflows/product-check.yml", @@ -508,13 +508,13 @@ }, { "path": "apps/web/src/api/rpcClient.test.ts", - "sha256": "0ec8a0ef2b0986ce2df8cf2e27cbbb0cfaf871b47fea87a22afed16d354f6f2c", - "bytes": 1257 + "sha256": "3b6baf07d8696dbadc95e9fae2e7e404d1e7996d625ec3a57d873875cf72b7f2", + "bytes": 2587 }, { "path": "apps/web/src/api/rpcClient.ts", - "sha256": "8c09093c82abd439f878532cae9f5d3712624aa93de85d17069219378716780c", - "bytes": 4530 + "sha256": "6e719c79ebb46bd8d3cbc653fe2819a8cbc37af124d5dedaacc7367d283d158e", + "bytes": 4974 }, { "path": "apps/web/src/api/rpcTransport.test.ts", @@ -2663,7 +2663,7 @@ }, { "path": "config/complexity-budget.json", - "sha256": "10804aa318df4b01be1476689e08c1dccdc125f56ef8405de6eb6017adb80a83", + "sha256": "55c4ebc36b0eb22d73b7109ee0b065bf7894e58e9cc1fc514d6daa3d68fc6707", "bytes": 5436 }, { @@ -2708,7 +2708,7 @@ }, { "path": "config/module-responsibility-budget.json", - "sha256": "89a3ac77485b7fe5375de20eecf34ba59c2a70fcbe95abd1dd04dd251accb4f0", + "sha256": "6e9f7bb4e27dc00c8edbe7b23ca6732df6a01c422ce0d88cff02759affba4ecd", "bytes": 8580 }, { @@ -2753,8 +2753,8 @@ }, { "path": "docs/BETA.md", - "sha256": "8412bd5199797a4a85095aa4251b78cdb2122b11b518ef8c638642b02bc584dd", - "bytes": 14781 + "sha256": "9f5981142f40d008b6126faea37ca3422e87fc5e88d95a38bbdbe43d7bd4c599", + "bytes": 15344 }, { "path": "docs/DEPENDENCY_LICENSES.json", @@ -2763,8 +2763,8 @@ }, { "path": "docs/INSTALL.md", - "sha256": "9aaa80d7087239ca6c03b524f6fc99fbc4d77fd73964172ea7a44cc0a84f8071", - "bytes": 22868 + "sha256": "f36d183a7c6f12d3dfb3541f4b25f62b2bce89fd7cd09f6f8172d8684de6e2ad", + "bytes": 23930 }, { "path": "docs/KNOWN_LIMITATIONS.ko.md", @@ -4353,8 +4353,8 @@ }, { "path": "src/thoth/adapters/http/async_routes.py", - "sha256": "da9a32e0d62c5c2d7a3cbb0acf7d0c4b9d26982098effca4325b10f84020b019", - "bytes": 8620 + "sha256": "3af46344501599e5844e458463de2b2d15c95f92084ca9dde3a3db08915caca1", + "bytes": 8740 }, { "path": "src/thoth/adapters/http/file_staging.py", @@ -5838,8 +5838,8 @@ }, { "path": "src/thoth/application/services/auto_index.py", - "sha256": "0651ddf3c46165c0f3af5cecb6037d83177d9a45b1deff7bf25ca2e82ed33a8e", - "bytes": 6502 + "sha256": "91c02eef9907b70f672a64a2fd47d856b6fc34c5ab515fb14fab55928fe4452b", + "bytes": 7150 }, { "path": "src/thoth/application/services/baseline_router.py", @@ -6018,8 +6018,8 @@ }, { "path": "src/thoth/application/services/dense_material.py", - "sha256": "19e5be103a9c40dc387f0c901a4c8a07e31bf5ebb14d813d9ea793ed05f7faa6", - "bytes": 14738 + "sha256": "241f2c6615ff0baa22c2a6ea1e51d0c274214a9d43c151544ee0e35bf38cc289", + "bytes": 15268 }, { "path": "src/thoth/application/services/dense_opt_in.py", @@ -7356,6 +7356,11 @@ "sha256": "ccf2df4ce7b50a8c7b73fc4128341ed266307067b9fe7d01b9ba3f9b4bf69df0", "bytes": 4363 }, + { + "path": "src/thoth/apps/log_files.py", + "sha256": "a3cdb42bdb0282c38b9477922f1c59ae86ebdf497f24342fb4e1cf675b9e36fc", + "bytes": 3060 + }, { "path": "src/thoth/apps/management_routes.py", "sha256": "e17ef04ae90adc48b944f0eb0529ca2a4264ba4235467f70b68ac5534f255a84", @@ -7498,8 +7503,8 @@ }, { "path": "src/thoth/apps/workspace_guard.py", - "sha256": "ae797df1136ac33b5d0f4087ae32b7cc17315bc8b497194dd1204aa28f7ce2bc", - "bytes": 2935 + "sha256": "50de9fc50db278f495eecb91ee7e774ca5770fd32d58b1741abfac2265e843c4", + "bytes": 3164 }, { "path": "src/thoth/apps/workspace_location_commands.py", @@ -7761,6 +7766,11 @@ "sha256": "9293754540245fd98767e9b3997ec8fb33ff08d8b0d6a76c254e8190c0cf333f", "bytes": 1828 }, + { + "path": "src/thoth/domain/failure_text.py", + "sha256": "9aa1f9d87fc1e054d3209287e7fd3f7aa3278b55ccbdef657af06d18c18a4406", + "bytes": 5301 + }, { "path": "src/thoth/domain/field_measurement.py", "sha256": "682e4acbe353dfa024807ab1b1cf2c2a4723b73cae7a67b7c96fbee654408ce2", @@ -8673,14 +8683,19 @@ }, { "path": "src/thoth/protocol/bus.py", - "sha256": "9015086181ac144f49617cae23b0bb3d743e1e74c192945132a3b370bada61ed", - "bytes": 31758 + "sha256": "3179cd3cd1ea3592d64bcd25ae94d14280b10e00ef8e717d64f8a34f332b51c9", + "bytes": 30445 }, { "path": "src/thoth/protocol/deferred.py", "sha256": "c4ec6f0d306c20b48ded1a7ebdee4d69f1d0e91d294792f39d0065472b40fdc1", "bytes": 927 }, + { + "path": "src/thoth/protocol/failure_log.py", + "sha256": "bc1572ddff9c684ff56e72a313bdb89607a03d56ebeac3ce683f49d68dbac9b0", + "bytes": 1226 + }, { "path": "src/thoth/protocol/journal_completion.py", "sha256": "f0d2a939b376d8f0998feaff4d52102fbafe0a9fe51da622e19242402315fbea", @@ -9126,6 +9141,11 @@ "sha256": "867366a5b68d90c8efd6bc85f834e0ce35021e9090821ac2a71ccfc7dd5bee21", "bytes": 11464 }, + { + "path": "tests/contract/test_internal_failure_log.py", + "sha256": "2c2c183d049711cda522a6cb530ea4c020935994b9b370e275ff342dce19e28c", + "bytes": 4605 + }, { "path": "tests/contract/test_jsonrpc_envelope.py", "sha256": "6132d12107ea5d020069eb6d84dd201034d10387754bcd7be2e485a760b61938", @@ -9138,8 +9158,8 @@ }, { "path": "tests/contract/test_local_request_guard.py", - "sha256": "7c24684d360a6f758182b2bb5820043e320ba2e34c9cb1fa0b1717f1a6255633", - "bytes": 4574 + "sha256": "b237c9b72ab9f78f0e37bdf71ac071546931c294d76a3aa214b278b5d272e325", + "bytes": 5262 }, { "path": "tests/contract/test_method_registry.py", @@ -11916,6 +11936,11 @@ "sha256": "a0f91e221fcc835ab3d5fc80ded9baf4f15e4b35ddd1e4d6b60f426a11ba838a", "bytes": 3193 }, + { + "path": "tests/unit/apps/test_log_files.py", + "sha256": "bff35cd20000f298456d03b0fc118142aa7f910efdf739b574f5459ae62ecbed", + "bytes": 5131 + }, { "path": "tests/unit/apps/test_source_policy_defaults.py", "sha256": "07fd08b892f5df466311f297700102bcba79fac4cd0dcaf433342d13ac7fadef", @@ -12046,6 +12071,11 @@ "sha256": "b8f455152bf36ec5d5ab4395b98ba620d0a5b06d29ee487edb3c554c4d44b4a7", "bytes": 2710 }, + { + "path": "tests/unit/domain/test_failure_text.py", + "sha256": "319b51717b2251a297e4b5fc1b222df434915426e559d7e8054c7b0114a20b88", + "bytes": 4735 + }, { "path": "tests/unit/domain/test_glossary_matcher.py", "sha256": "2f071a12c3793e3fe2b1fdaf01ef1037d0f58cdf657c36a0f3564583ab024fa9", @@ -12636,6 +12666,11 @@ "sha256": "b8e38880709329ad4fe4618305b07e7377fe03bc30659b303b333367a3b330b3", "bytes": 4869 }, + { + "path": "tests/unit/services/test_auto_index_failure_log.py", + "sha256": "84df865fc57583f09a6010e0916cbdc2cc5dc113e7f78f36e8604efd40f43fb7", + "bytes": 3864 + }, { "path": "tests/unit/services/test_browser_submission_scope.py", "sha256": "ca702d65dac6c9e84030590e17261e47a46163c284a5fb2ec8b878d6a7726f47", @@ -12968,8 +13003,8 @@ }, { "path": "tests/unit/test_dense_material_reasons.py", - "sha256": "c1408994721104e75ff8591c81b4ea2c4b9a44a41e706f36f21ff61776e8802a", - "bytes": 12102 + "sha256": "5e8229600914c19cc38349c44f89705e55877dda8d333d1231cc6cb54481c98a", + "bytes": 14549 }, { "path": "tests/unit/test_dense_material_resident.py", diff --git a/apps/web/src/api/rpcClient.test.ts b/apps/web/src/api/rpcClient.test.ts index 700eb9cf..2210f9f7 100644 --- a/apps/web/src/api/rpcClient.test.ts +++ b/apps/web/src/api/rpcClient.test.ts @@ -18,3 +18,37 @@ it("preserves the bilingual reference notice and saved-record metadata from an R name: "RpcError", code: -32030, message: `${notice} [-32030]`, details: data, }); }); + +it("shows the operation id of an unexpected server failure, because the server log is found by it", async () => { + vi.stubGlobal("fetch", vi.fn().mockResolvedValue(Response.json({ + jsonrpc: "2.0", + id: "internal", + error: { code: -32603, message: "internal command failure", data: { operation_id: "operation:42" } }, + }))); + await expect(rpc("thread/input", { project_id: "p" }, "internal-failure")).rejects.toMatchObject({ + name: "RpcError", + code: -32603, + message: "internal command failure [-32603] (operation:42)", + }); +}); + +it("adds no operation id to other errors, or when the server gave none", async () => { + const fetchMock = vi.fn() + .mockResolvedValueOnce(Response.json({ + jsonrpc: "2.0", + id: "refused", + error: { code: -32030, message: "refused", data: { operation_id: "operation:43" } }, + })) + .mockResolvedValueOnce(Response.json({ + jsonrpc: "2.0", + id: "bare", + error: { code: -32603, message: "internal command failure" }, + })); + vi.stubGlobal("fetch", fetchMock); + await expect(rpc("thread/input", { project_id: "p" }, "refused")).rejects.toMatchObject({ + message: "refused [-32030]", + }); + await expect(rpc("thread/input", { project_id: "p" }, "bare")).rejects.toMatchObject({ + message: "internal command failure [-32603]", + }); +}); diff --git a/apps/web/src/api/rpcClient.ts b/apps/web/src/api/rpcClient.ts index c89214ed..8407ef55 100644 --- a/apps/web/src/api/rpcClient.ts +++ b/apps/web/src/api/rpcClient.ts @@ -16,9 +16,18 @@ export const readQueries = new Set(["thread/read", "thread/list", "thread/activi "revision/diff/read", "revision/restore/preview", "revision/read", "revision/content/read", "revision/head/read", "revision/history/read", "trace/read", "trace/export", "trace/importPreview", "trace/history", "hypothesis/link/list", "hypothesis/test/result/list", "hypothesis/same/list", "trace/closure/list", "trace/lesson/list"]); +const INTERNAL_ERROR = -32603; + +/** The server logs an unexpected failure under its operation id; showing the id lets a report name it. */ +function internalFailureRef(code: number, details: Record | undefined): string { + const operationId = details?.operation_id; + if (code !== INTERNAL_ERROR || typeof operationId !== "string" || !operationId) return ""; + return ` (${operationId})`; +} + export class RpcError extends Error { constructor(message: string, readonly code: number, readonly details: Record) { - super(`${message} [${code}]`); + super(`${message} [${code}]${internalFailureRef(code, details)}`); this.name = "RpcError"; } } diff --git a/config/complexity-budget.json b/config/complexity-budget.json index 59e13673..fd124a9d 100644 --- a/config/complexity-budget.json +++ b/config/complexity-budget.json @@ -21,7 +21,7 @@ "src/thoth/application/services/research_gaps.py::validate_gaps": 28, "src/thoth/application/services/restore_impact.py::RestoreImpactPlanner.build": 23, "src/thoth/application/services/scoped_memory_controls.py::ScopedMemoryControls._require": 30, - "src/thoth/protocol/bus.py::CommandBus._execute": 28 + "src/thoth/protocol/bus.py::CommandBus._execute": 24 } }, "web": { diff --git a/config/module-responsibility-budget.json b/config/module-responsibility-budget.json index 76c17b1c..04e5f3ff 100644 --- a/config/module-responsibility-budget.json +++ b/config/module-responsibility-budget.json @@ -227,7 +227,7 @@ "policy": "over the 600-line limit when it was introduced; do not grow it; lower the baseline when it is split" }, "src/thoth/protocol/bus.py": { - "baseline_lines": 740, + "baseline_lines": 708, "top_level_symbols": [ "DispatchTicket", "PreClaimAuthorization", diff --git a/docs/BETA.md b/docs/BETA.md index 1f7c4bb9..e8d6dcc4 100644 --- a/docs/BETA.md +++ b/docs/BETA.md @@ -155,6 +155,10 @@ Tell us what you were doing, what you expected, what happened, and attach a scre output of `thoth.cli version` and your Windows version. Remove or blur anything private first: do not attach your documents, sign-in details or workspace files. +If the screen shows `internal command failure [-32603] (operation:...)`, open `logs\thoth.log` in +your workspace, copy the lines of the record with that operation id and paste them as text (see +[Server log](INSTALL.md#server-log)). Read them first and do not attach the whole file. + For a security problem, do not open a public issue. Use **Security → Report a vulnerability** on the repository and read the [security policy](../SECURITY.md). @@ -188,4 +192,7 @@ repository and read the [security policy](../SECURITY.md). - **신고**: [Beta feedback 이슈](https://github.com/hyperdrivebeep/thoth/issues/new/choose)에 하던 일, 기대한 결과, 실제 결과, 화면 캡처, 버전·OS를 적어 주세요. 보안 문제는 공개 이슈 대신 **Security → Report a vulnerability**로 알려 주세요. + 화면에 `internal command failure [-32603] (operation:...)`가 보이면 작업 공간의 + `logs\thoth.log`에서 그 operation id가 있는 기록의 줄만 복사해 글로 붙여 주세요. 붙이기 전에 + 내용을 읽어 보고, 파일 전체는 올리지 마세요. diff --git a/docs/INSTALL.md b/docs/INSTALL.md index 43d51a44..13fcd019 100644 --- a/docs/INSTALL.md +++ b/docs/INSTALL.md @@ -331,6 +331,22 @@ bytes or rerun the provider. An active database copy is not a consistent cold ba changes, `workspace_id` changes and browser drafts/selections stored under the old origin/root do not automatically merge; preserve browser storage separately when needed. +### Server log + +While `serve` or `desktop` runs, warnings and unexpected failures are written to the console and +to `logs\thoth.log` inside the selected workspace (about 1 MB per file; three older files are +kept). The file appears with the first record. When the screen shows +`internal command failure [-32603] (operation:...)`, the record with that operation id names the +method, the exception types and where they were raised. A failure of background indexing or of the +local retrieval scores is written once per distinct failure, not on every retry. + +The record of a failed command leaves out the string values of its request. Every record removes +token-shaped text, cuts an exception message at 300 characters and shortens file paths. +Identifiers, file names and short words can still appear, so read the lines before you share +them. Typed refusals (a rejected request, a held model call) are answers and are not logged as +failures. The other commands (`run`, `rpc`, the interactive shell) do not write the file; their +warnings go to the console as before. + ## Checks ```powershell diff --git a/src/thoth/adapters/http/async_routes.py b/src/thoth/adapters/http/async_routes.py index beea1c8b..b0f79dc2 100644 --- a/src/thoth/adapters/http/async_routes.py +++ b/src/thoth/adapters/http/async_routes.py @@ -156,7 +156,10 @@ async def cancel_async_operation( _resolve_bus_for_request: Callable[[FastAPI, Request], CommandBus], _auth_denied: Callable[[str | int | None, str], Response], ) -> Response: - body = cast(object, await request.json()) + try: + body = cast(object, await request.json()) + except ValueError as exc: + raise HTTPException(status_code=400, detail="invalid JSON") from exc mapping = cast(dict[object, object], body) if isinstance(body, dict) else {} project_id = mapping.get("project_id") if not isinstance(project_id, str) or not project_id: diff --git a/src/thoth/application/services/auto_index.py b/src/thoth/application/services/auto_index.py index 1bc13844..0aebdddb 100644 --- a/src/thoth/application/services/auto_index.py +++ b/src/thoth/application/services/auto_index.py @@ -11,10 +11,12 @@ import asyncio import contextlib +import logging from typing import TYPE_CHECKING from thoth.domain.embedding_index import EmbeddingIndexError from thoth.domain.enums import ProjectLifecycle +from thoth.domain.failure_text import BackgroundFailureLog from thoth.domain.model_asset import ModelAssetError if TYPE_CHECKING: @@ -31,6 +33,7 @@ def __init__(self, service: "LocalRetrievalService") -> None: self._task: asyncio.Task[None] | None = None self._wake: asyncio.Event | None = None self._retry_at: dict[str, float] = {} + self._failures = BackgroundFailureLog(logging.getLogger(__name__)) @property def started(self) -> bool: @@ -66,8 +69,9 @@ async def _loop(self) -> None: await self.run_pass() except asyncio.CancelledError: raise - except Exception: - pass # background work never fails a request; the next tick looks again + except Exception as exc: + # Background work never fails a request; the next tick looks again. + self._failures.note("auto-index pass", exc) with contextlib.suppress(TimeoutError): await asyncio.wait_for(wake.wait(), AUTO_INDEX_TICK_SECONDS) @@ -84,7 +88,8 @@ def projects_needing_index(self) -> list[str]: service.store.resume_interrupted(project.project_id, now_ms) if service.store.needs_indexing(project.project_id): found.append(project.project_id) - except Exception: + except Exception as exc: + self._failures.note(f"auto-index check project_id={project.project_id}", exc) continue return found @@ -118,9 +123,13 @@ async def _index_one(self, project: str) -> None: error = task.exception() if error is None: self._retry_at.pop(project, None) + self._failures.clear(f"auto-index project_id={project}") elif isinstance(error, TimeoutError): self.kick() # a long project goes on in the next pass; its finished jobs are kept elif not isinstance(error, ModelAssetError): + # Missing model files are a normal state the settings card shows; anything else is + # written down, because the retry below would otherwise hide a failure that repeats. + self._failures.note(f"auto-index project_id={project}", error) self._retry_at[project] = loop.time() + AUTO_INDEX_RETRY_SECONDS async def run_project(self, project: str) -> None: diff --git a/src/thoth/application/services/dense_material.py b/src/thoth/application/services/dense_material.py index 58e71c65..0a68e246 100644 --- a/src/thoth/application/services/dense_material.py +++ b/src/thoth/application/services/dense_material.py @@ -8,6 +8,7 @@ import asyncio import importlib +import logging import threading import time from collections.abc import Awaitable, Callable @@ -18,6 +19,7 @@ from thoth.application.services.embedding_index_service import EmbeddingIndexService from thoth.domain.embedding_index import EmbeddingIndexError from thoth.domain.evidence import EvidenceSpan, connected_retrieval_spans +from thoth.domain.failure_text import BackgroundFailureLog from thoth.domain.retrieval_embedding import ( DenseMaterial, DenseScore, @@ -101,6 +103,7 @@ def __init__( self._clock, self._build_wait = clock, build_wait self._residents: dict[str, Resident] = {} self._failed: dict[str, tuple[IndexStamp, DenseUnavailableReason]] = {} + self._failures = BackgroundFailureLog(logging.getLogger(__name__)) self._building: dict[str, tuple[IndexStamp, asyncio.Task[Resident]]] = {} self.warming: asyncio.Task[None] | None = None self._cooldown_until = 0.0 @@ -232,8 +235,9 @@ def _start_warm(self) -> None: async def _run_warm(self, warm: Callable[[], Awaitable[None]]) -> None: try: await warm() - except Exception: - pass + except Exception as exc: + # The question goes on with the lexical selection; the log says why dense was not up. + self._failures.note("local retrieval encoder warm-up", exc) finally: # A worker that is still not up is retried later, not on every request. self._cooldown_until = self._clock() + WARM_COOLDOWN_SECONDS @@ -343,7 +347,8 @@ async def material( return None # routing refuses a mixed frame itself try: stamp = self._stamp(project_id) - except Exception: + except Exception as exc: + self._failures.note(f"dense index stamp project_id={project_id}", exc) return self._unavailable(project_id, question, eligible, "EMBEDDING_FAILED") if not stamp[0]: self.invalidate(project_id) @@ -352,7 +357,9 @@ async def material( values = await self._compute(project_id, question, eligible, stamp) except _Unavailable as exc: return self._unavailable(project_id, question, eligible, exc.reason) - except Exception: + except Exception as exc: + place = f"dense scores project_id={project_id}" + self._failures.note(place, exc, redact=(question,)) return self._unavailable(project_id, question, eligible, "EMBEDDING_FAILED") return DenseMaterial.prepared( project_id=project_id, diff --git a/src/thoth/apps/log_files.py b/src/thoth/apps/log_files.py new file mode 100644 index 00000000..10d1ae7d --- /dev/null +++ b/src/thoth/apps/log_files.py @@ -0,0 +1,80 @@ +"""The workspace log of a running server: warnings and unexpected failures, kept for bug reports. + +Every logger under "thoth" writes here from WARNING up, to /logs/thoth.log (three old +files of about 1 MB are kept) and to the server's console. A record of a failed command comes from +thoth.protocol.failure_log and leaves out the request's text. An exception any other record +carries (a failed research attempt, a background check) is written the same way, by +thoth.domain.failure_text: types, cleaned and cut messages, short file paths. While the log is +installed the "thoth" loggers do not also hand their records to the root logger: a library that +configured a root console handler (the migration tool does) would print every record a second +time, with the full traceback. +""" + +from __future__ import annotations + +import logging +from logging.handlers import RotatingFileHandler +from pathlib import Path +from types import TracebackType + +from thoth.domain.failure_text import failure_text + +LOG_DIRECTORY = "logs" +LOG_FILE = "thoth.log" +LOG_BYTES = 1_000_000 +LOG_BACKUPS = 3 +_FORMAT = "%(asctime)s %(levelname)s %(name)s %(message)s" +_LOGGER = "thoth" +_OWNED = "_thoth_workspace_log" +_ExcInfo = tuple[type[BaseException], BaseException, TracebackType | None] | tuple[None, None, None] + + +class _FailureTextFormatter(logging.Formatter): + """Writes an attached exception as failure_text does, not as a full traceback.""" + + def formatException(self, ei: _ExcInfo) -> str: + return "" if ei[1] is None else failure_text(ei[1]) + + +def workspace_log_path(workspace: Path) -> Path: + return workspace / LOG_DIRECTORY / LOG_FILE + + +def install_workspace_log(workspace: Path) -> Path | None: + """Send the "thoth" loggers to the console and to the workspace log file. + + Returns the file, or None when its folder cannot be made (the console still gets the records). + Calling it again replaces the handlers of the earlier call. + """ + close_workspace_log() + logger = logging.getLogger(_LOGGER) + formatter = _FailureTextFormatter(_FORMAT) + handlers: list[logging.Handler] = [logging.StreamHandler()] + path = workspace_log_path(workspace) + installed: Path | None = path + try: + path.parent.mkdir(parents=True, exist_ok=True) + handlers.append( + RotatingFileHandler( + path, maxBytes=LOG_BYTES, backupCount=LOG_BACKUPS, encoding="utf-8", delay=True + ) + ) + except OSError: + installed = None + for handler in handlers: + handler.setLevel(logging.WARNING) + handler.setFormatter(formatter) + setattr(handler, _OWNED, True) + logger.addHandler(handler) + logger.propagate = False + return installed + + +def close_workspace_log() -> None: + """Remove and close the handlers install_workspace_log added.""" + logger = logging.getLogger(_LOGGER) + logger.propagate = True + for handler in tuple(logger.handlers): + if getattr(handler, _OWNED, False): + logger.removeHandler(handler) + handler.close() diff --git a/src/thoth/apps/workspace_guard.py b/src/thoth/apps/workspace_guard.py index 255c7576..f35b5434 100644 --- a/src/thoth/apps/workspace_guard.py +++ b/src/thoth/apps/workspace_guard.py @@ -14,6 +14,7 @@ confirm_workspace_location, ) from thoth.adapters.storage.workspace_owner import WorkspaceInUse, acquire_workspace_owner +from thoth.apps.log_files import close_workspace_log, install_workspace_log from thoth.apps.workspace_location_presentation import location_messages from thoth.domain.deployment_mode import DeploymentMode from thoth.domain.storage_context import storage_deployment_mode @@ -68,12 +69,15 @@ def owned_workspace(workspace: Path, *, command: str) -> Generator[None]: """Own the workspace for a long-running command and let go when it ends. A server opens its runtime on the first request, which is too late to refuse a second one. + While it is owned, warnings and unexpected failures go to the workspace log file. """ with workspace_guard(): if storage_deployment_mode() is DeploymentMode.LOCAL: _warn_location(check_workspace_location(workspace)) ownership = acquire_workspace_owner(workspace, command=command) + install_workspace_log(workspace) try: yield finally: + close_workspace_log() ownership.release() diff --git a/src/thoth/domain/failure_text.py b/src/thoth/domain/failure_text.py new file mode 100644 index 00000000..5648583e --- /dev/null +++ b/src/thoth/domain/failure_text.py @@ -0,0 +1,139 @@ +"""Text for a log line about an unexpected failure, without what the request carried. + +The log is the only place a maintainer can see why a command failed, and people attach it to bug +reports. So the text names every exception of the chain and where it was raised, and leaves out +the things a request or a provider put into an exception message: the string values of the request +input, token-shaped secrets, and anything past the first 300 characters of a message. +""" + +from __future__ import annotations + +import logging +import re +import traceback +from collections.abc import Iterable, Mapping, Sequence +from typing import cast + +MESSAGE_LIMIT = 300 +CHAIN_LIMIT = 5 +FRAME_LIMIT = 25 +REDACTED_INPUT = "[input]" +REDACTED_SECRET = "[secret]" +_MIN_INPUT_TEXT = 6 +# Identifiers are what a maintainer searches the log for, and they are not content. +_IDENTIFIER_KEY = re.compile(r"(_id|_ids|_digest|_ref)$") +_SECRET = re.compile( + r"sk-[A-Za-z0-9_\-]{8,}" + r"|xai-[A-Za-z0-9_\-]{8,}" + r"|Bearer\s+\S{8,}" + r"|eyJ[A-Za-z0-9_\-]{10,}\.[A-Za-z0-9_\-]{10,}\.[A-Za-z0-9_\-]*" +) + + +def input_texts(value: object) -> tuple[str, ...]: + """The string values of a request input that must not reach a log line, longest first. + + Values under identifier keys (thread_id, revision_digest, ...) are kept readable. + """ + found: set[str] = set() + + def walk(item: object, key: str) -> None: + if isinstance(item, str): + text = item.strip() + if len(text) >= _MIN_INPUT_TEXT and not _IDENTIFIER_KEY.search(key): + found.add(text) + elif isinstance(item, Mapping): + for child_key, child in cast(Mapping[object, object], item).items(): + walk(child, str(child_key)) + elif isinstance(item, Sequence) and not isinstance(item, (bytes, bytearray)): + for child in cast(Sequence[object], item): + walk(child, key) + + walk(value, "") + return tuple(sorted(found, key=lambda text: (-len(text), text))) + + +def _message(exc: BaseException, redact: tuple[str, ...]) -> str: + try: + text = str(exc) + except Exception: + return "(message unavailable)" + for hidden in redact: + text = text.replace(hidden, REDACTED_INPUT) + text = _SECRET.sub(REDACTED_SECRET, text) + text = " ".join(text.split()) + if len(text) > MESSAGE_LIMIT: + text = text[:MESSAGE_LIMIT] + "..." + return text + + +def _location(filename: str) -> str: + """A path a bug report can carry: inside the package from its root, else the last two parts.""" + parts = filename.replace("\\", "/").split("/") + if "thoth" in parts[:-1]: + index = len(parts) - 1 - parts[::-1].index("thoth") + return "/".join(parts[index:]) + return "/".join(parts[-2:]) + + +def _chain(exc: BaseException) -> list[BaseException]: + chain: list[BaseException] = [] + current: BaseException | None = exc + while current is not None and len(chain) < CHAIN_LIMIT and current not in chain: + chain.append(current) + if current.__cause__ is not None: + current = current.__cause__ + elif current.__suppress_context__: + current = None + else: + current = current.__context__ + return chain + + +def failure_headlines(exc: BaseException, *, redact: Iterable[str] = ()) -> tuple[str, ...]: + """One line per exception of the chain: its type and cleaned message, without frames.""" + hidden = tuple(redact) + lines: list[str] = [] + for position, item in enumerate(_chain(exc)): + prefix = "" if position == 0 else "caused by " + message = _message(item, hidden) + lines.append(f"{prefix}{type(item).__name__}{': ' + message if message else ''}") + return tuple(lines) + + +def failure_text(exc: BaseException, *, redact: Iterable[str] = ()) -> str: + """Every exception of the chain (type, cleaned message) with the frames it passed through.""" + lines: list[str] = [] + for item, headline in zip(_chain(exc), failure_headlines(exc, redact=redact), strict=True): + lines.append(headline) + frames = traceback.extract_tb(item.__traceback__)[-FRAME_LIMIT:] + lines.extend( + f" {_location(frame.filename)}:{frame.lineno} in {frame.name}" for frame in frames + ) + return "\n".join(lines) + + +class BackgroundFailureLog: + """Warnings for failures a background task swallows, one per distinct failure and place. + + A background task that looks again every minute would otherwise write the same failure every + minute. A place is logged again when its failure changes (the types and messages of the chain; + the frames may differ), or after clear(place). + """ + + def __init__(self, logger: logging.Logger) -> None: + self._logger = logger + self._last: dict[str, tuple[str, ...]] = {} + + def note(self, place: str, exc: BaseException, *, redact: Iterable[str] = ()) -> None: + hidden = tuple(redact) + headlines = failure_headlines(exc, redact=hidden) + if self._last.get(place) == headlines: + return + self._last[place] = headlines + self._logger.warning( + "background failure at %s\n%s", place, failure_text(exc, redact=hidden) + ) + + def clear(self, place: str) -> None: + self._last.pop(place, None) diff --git a/src/thoth/protocol/bus.py b/src/thoth/protocol/bus.py index ec3887c7..da2b841e 100644 --- a/src/thoth/protocol/bus.py +++ b/src/thoth/protocol/bus.py @@ -43,6 +43,7 @@ PendingExecution, current_operation, ) +from thoth.protocol.failure_log import log_internal_failure from thoth.protocol.journal_completion import ( JournalCompletion, journal_tail_guard, @@ -376,41 +377,14 @@ async def _execute(self, ticket: DispatchTicket) -> JsonRpcResponse: }, ) except (RpcApplicationError, ResourceScopeError) as exc: - error = self._application_error(exc) - failed = self._operations.fail( - operation.operation_id, - error.model_dump(mode="json"), - completed_at=self._clock.now(), - ) - if failed.error != error.model_dump(mode="json"): - return self._replay(request.id, failed) - self._append_event( - operation, - "operation.failed", - {"code": error.code, "message": error.message}, - ) - self._measure(request, operation.project_id, "FAILED") - return JsonRpcResponse(id=request.id, error=error) + return self._seal_failure(request, operation, self._application_error(exc)) except PermissionError as exc: error = JsonRpcError( code=RpcErrorCode.AUTHORIZATION_DENIED, message="authenticated authority identity mismatch", data={"reason_code": str(exc), "pre_io": True}, ) - failed = self._operations.fail( - operation.operation_id, - error.model_dump(mode="json"), - completed_at=self._clock.now(), - ) - if failed.error != error.model_dump(mode="json"): - return self._replay(request.id, failed) - self._append_event( - operation, - "operation.failed", - {"code": error.code, "message": error.message}, - ) - self._measure(request, operation.project_id, "FAILED") - return JsonRpcResponse(id=request.id, error=error) + return self._seal_failure(request, operation, error) except ValidationError as exc: error = JsonRpcError( code=RpcErrorCode.INVALID_PARAMS, @@ -422,21 +396,9 @@ async def _execute(self, ticket: DispatchTicket) -> JsonRpcResponse: ) }, ) - failed = self._operations.fail( - operation.operation_id, - error.model_dump(mode="json"), - completed_at=self._clock.now(), - ) - if failed.error != error.model_dump(mode="json"): - return self._replay(request.id, failed) - self._append_event( - operation, - "operation.failed", - {"code": error.code, "message": error.message}, - ) - self._measure(request, operation.project_id, "FAILED") - return JsonRpcResponse(id=request.id, error=error) + return self._seal_failure(request, operation, error) except Exception as exc: + log_internal_failure(request, operation, exc) self._persist_internal_failure( operation=operation, request=request, @@ -448,20 +410,7 @@ async def _execute(self, ticket: DispatchTicket) -> JsonRpcResponse: message="internal command failure", data={"operation_id": operation.operation_id}, ) - failed = self._operations.fail( - operation.operation_id, - error.model_dump(mode="json"), - completed_at=self._clock.now(), - ) - if failed.error != error.model_dump(mode="json"): - return self._replay(request.id, failed) - self._append_event( - operation, - "operation.failed", - {"code": error.code, "message": error.message}, - ) - self._measure(request, operation.project_id, "FAILED") - return JsonRpcResponse(id=request.id, error=error) + return self._seal_failure(request, operation, error) with journal_tail_guard(self._journal_completion, operation): completed = self._operations.complete( operation.operation_id, @@ -602,6 +551,25 @@ def _fail_abandoned_running( self._measure(request, failed.project_id, "FAILED") return JsonRpcResponse(id=request.id, error=error) + def _seal_failure( + self, request: JsonRpcRequest, operation: OperationRecord, error: JsonRpcError + ) -> JsonRpcResponse: + """Close the operation as FAILED with this error; an already sealed one is replayed.""" + failed = self._operations.fail( + operation.operation_id, + error.model_dump(mode="json"), + completed_at=self._clock.now(), + ) + if failed.error != error.model_dump(mode="json"): + return self._replay(request.id, failed) + self._append_event( + operation, + "operation.failed", + {"code": error.code, "message": error.message}, + ) + self._measure(request, operation.project_id, "FAILED") + return JsonRpcResponse(id=request.id, error=error) + def _replay(self, request_id: str | int, operation: OperationRecord) -> JsonRpcResponse: if self._resource_access is not None: self._resource_access.require_operation(operation) diff --git a/src/thoth/protocol/failure_log.py b/src/thoth/protocol/failure_log.py new file mode 100644 index 00000000..b77ffc00 --- /dev/null +++ b/src/thoth/protocol/failure_log.py @@ -0,0 +1,33 @@ +"""One log record for a command that ended in an unexpected exception. + +The caller still seals the operation and answers "internal command failure" with the operation id; +this record is what lets a maintainer find the cause from that id. Typed refusals (application +errors, validation errors, permission errors) are answers, not failures, and are not logged here. +""" + +from __future__ import annotations + +import logging + +from thoth.domain.failure_text import failure_text, input_texts +from thoth.domain.operation import OperationRecord +from thoth.protocol.jsonrpc import JsonRpcRequest + +_LOG = logging.getLogger("thoth.internal_failure") + + +def log_internal_failure( + request: JsonRpcRequest, operation: OperationRecord, exc: Exception +) -> None: + try: + detail = failure_text(exc, redact=input_texts(request.params.input)) + except Exception: + # The failure is sealed by the caller either way; a broken description must not hide it. + detail = f"{type(exc).__name__} (failure text unavailable)" + _LOG.error( + "internal command failure method=%s operation_id=%s project_id=%s\n%s", + request.method, + operation.operation_id, + operation.project_id, + detail, + ) diff --git a/tests/contract/test_internal_failure_log.py b/tests/contract/test_internal_failure_log.py new file mode 100644 index 00000000..ff6abd7e --- /dev/null +++ b/tests/contract/test_internal_failure_log.py @@ -0,0 +1,114 @@ +"""An unexpected failure of a command leaves a log record a maintainer can find by operation id.""" + +from __future__ import annotations + +import logging +from collections.abc import Iterator +from pathlib import Path + +import pytest +from pydantic import JsonValue +from tests.contract.conftest import FixedClock, SequenceIds + +from thoth.adapters.storage import SqliteLedger, SqliteOperationStore, migrate_sqlite_database +from thoth.domain.enums import OperationState +from thoth.protocol.bus import CommandBus +from thoth.protocol.jsonrpc import JsonRpcRequest, RpcApplicationError, RpcErrorCode +from thoth.protocol.registry import MethodRegistry + +LOGGER = "thoth.internal_failure" +MARK = "SECRET-MARK-123 why did LAB-42 fail" + + +async def broken(payload: dict[str, JsonValue]) -> dict[str, JsonValue]: + # The kind of message that carries what the person typed. + raise RuntimeError(f"cannot process {payload['description']}") + + +async def refused(payload: dict[str, JsonValue]) -> dict[str, JsonValue]: + del payload + raise RpcApplicationError(RpcErrorCode.DOMAIN_REJECTED, "PROJECT_NAME_TAKEN") + + +@pytest.fixture +def bus(tmp_path: Path) -> Iterator[tuple[CommandBus, SqliteOperationStore]]: + migrate_sqlite_database(tmp_path / "thoth.sqlite3") + ledger = SqliteLedger(tmp_path / "thoth.sqlite3") + ledger.initialize() + operations = SqliteOperationStore(ledger.engine) + registry = MethodRegistry() + registry.register("project/create", broken) + registry.register("project/archive", refused) + yield CommandBus(registry, operations, FixedClock(), SequenceIds()), operations + ledger.close() + + +def _request(method: str, key: str) -> JsonRpcRequest: + return JsonRpcRequest.model_validate( + { + "jsonrpc": "2.0", + "id": key, + "method": method, + "params": { + "_meta": {"idempotencyKey": key}, + "input": {"project_id": "project:lantern", "description": MARK}, + }, + } + ) + + +async def test_an_unexpected_failure_is_logged_with_its_operation_id_and_without_request_text( + bus: tuple[CommandBus, SqliteOperationStore], caplog: pytest.LogCaptureFixture +) -> None: + command_bus, operations = bus + with caplog.at_level(logging.WARNING, logger=LOGGER): + response = await command_bus.dispatch(_request("project/create", "broken-1")) + + assert response.error is not None + assert response.error.code == RpcErrorCode.INTERNAL_ERROR + assert response.error.message == "internal command failure" + operation_id = response.error.data["operation_id"] + assert isinstance(operation_id, str) + sealed = operations.read(operation_id) + assert sealed is not None and sealed.state is OperationState.FAILED + + records = [record for record in caplog.records if record.name == LOGGER] + assert len(records) == 1 + assert records[0].levelno == logging.ERROR + text = records[0].getMessage() + first, *detail = text.splitlines() + assert first == ( + "internal command failure method=project/create " + f"operation_id={operation_id} project_id=project:lantern" + ) + assert detail[0] == "RuntimeError: cannot process [input]" + assert any(line.endswith(" in broken") for line in detail) + assert any( + "thoth/protocol/bus.py:" in line and line.endswith(" in _execute") for line in detail + ) + assert "SECRET-MARK-123" not in text and "LAB-42" not in text + + +async def test_a_typed_refusal_is_an_answer_and_is_not_logged_as_a_failure( + bus: tuple[CommandBus, SqliteOperationStore], caplog: pytest.LogCaptureFixture +) -> None: + command_bus, _ = bus + with caplog.at_level(logging.DEBUG, logger=LOGGER): + response = await command_bus.dispatch(_request("project/archive", "refused-1")) + + assert response.error is not None + assert response.error.code == RpcErrorCode.DOMAIN_REJECTED + assert [record for record in caplog.records if record.name == LOGGER] == [] + + +async def test_the_same_key_sent_again_replays_the_failure_without_a_second_record( + bus: tuple[CommandBus, SqliteOperationStore], caplog: pytest.LogCaptureFixture +) -> None: + command_bus, _ = bus + with caplog.at_level(logging.WARNING, logger=LOGGER): + first = await command_bus.dispatch(_request("project/create", "broken-2")) + again = await command_bus.dispatch(_request("project/create", "broken-2")) + + assert first.error is not None and again.error is not None + assert again.error.data["operation_id"] == first.error.data["operation_id"] + assert len([record for record in caplog.records if record.name == LOGGER]) == 1 diff --git a/tests/contract/test_local_request_guard.py b/tests/contract/test_local_request_guard.py index 96861241..aef7b8fa 100644 --- a/tests/contract/test_local_request_guard.py +++ b/tests/contract/test_local_request_guard.py @@ -118,3 +118,19 @@ async def endpoint(socket: WebSocket) -> None: ): assert socket.receive_text() == "synthetic" assert not local_environment.exists() + + +async def test_a_cancel_body_that_is_not_json_is_a_client_error_not_a_server_error( + local_environment: Path, +) -> None: + transport = httpx.ASGITransport(app=create_app(), raise_app_exceptions=False) + async with httpx.AsyncClient(transport=transport, base_url="http://localhost:8765") as client: + response = await client.post( + "/operations/operation:1/cancel", + content=b"not json", + headers={"content-type": "application/json"}, + ) + assert response.status_code == 400 + assert response.json() == {"detail": "invalid JSON"} + # The body is refused before the workspace is opened. + assert not local_environment.exists() diff --git a/tests/unit/apps/test_log_files.py b/tests/unit/apps/test_log_files.py new file mode 100644 index 00000000..f8cc9799 --- /dev/null +++ b/tests/unit/apps/test_log_files.py @@ -0,0 +1,126 @@ +"""The workspace log file of a running server.""" + +import logging +from logging.handlers import RotatingFileHandler +from pathlib import Path + +import pytest + +from thoth.apps import workspace_guard +from thoth.apps.log_files import ( + LOG_BACKUPS, + LOG_BYTES, + close_workspace_log, + install_workspace_log, + workspace_log_path, +) + + +@pytest.fixture(autouse=True) +def no_leftover_handlers(): + yield + close_workspace_log() + + +def _owned_handlers() -> list[logging.Handler]: + return [ + handler + for handler in logging.getLogger("thoth").handlers + if getattr(handler, "_thoth_workspace_log", False) + ] + + +def test_warnings_of_any_thoth_logger_reach_the_workspace_file_in_utf8(tmp_path: Path) -> None: + path = install_workspace_log(tmp_path) + assert path == tmp_path / "logs" / "thoth.log" == workspace_log_path(tmp_path) + assert path is not None + logging.getLogger("thoth.internal_failure").error("internal command failure 한글 %s", "op:1") + logging.getLogger("thoth.application.services.auto_index").warning("background failure") + logging.getLogger("thoth.application.services.auto_index").info("not a problem") + logging.getLogger("another.library").error("not ours") + close_workspace_log() + + lines = path.read_text(encoding="utf-8").splitlines() + assert len(lines) == 2 + assert lines[0].endswith("ERROR thoth.internal_failure internal command failure 한글 op:1") + assert lines[1].endswith("WARNING thoth.application.services.auto_index background failure") + + +def test_the_file_is_bounded_and_installing_again_does_not_double_the_records( + tmp_path: Path, +) -> None: + install_workspace_log(tmp_path) + path = install_workspace_log(tmp_path) + assert path is not None + files = [h for h in _owned_handlers() if isinstance(h, RotatingFileHandler)] + assert len(files) == 1 and len(_owned_handlers()) == 2 # the file and the console + assert (files[0].maxBytes, files[0].backupCount) == (LOG_BYTES, LOG_BACKUPS) + logging.getLogger("thoth.x").warning("once") + close_workspace_log() + assert path.read_text(encoding="utf-8").count("once") == 1 + assert _owned_handlers() == [] + + +def test_no_file_is_made_until_something_is_logged(tmp_path: Path) -> None: + path = install_workspace_log(tmp_path) + assert path is not None and not path.exists() + + +def test_an_exception_another_record_carries_is_written_cleaned_not_as_a_full_traceback( + tmp_path: Path, +) -> None: + path = install_workspace_log(tmp_path) + assert path is not None + try: + raise RuntimeError("provider said no to sk-abcdefgh12345678 " + "x" * 1000) + except RuntimeError as exc: + # The way a failed research attempt is logged today. + logging.getLogger("thoth.application.services.research_attempt_runner").error( + "research attempt failed origin=%s", "MODEL_CALL", exc_info=exc + ) + close_workspace_log() + + text = path.read_text(encoding="utf-8") + lines = text.splitlines() + assert lines[0].endswith("research attempt failed origin=MODEL_CALL") + assert lines[1].startswith("RuntimeError: provider said no to [secret] xxx") + assert len(lines[1]) < 400 and "sk-abcdefgh12345678" not in text + assert "Traceback (most recent call last)" not in text + assert str(Path(__file__).resolve().parent) not in text + assert any(line.startswith(" ") and " in test_an_exception" in line for line in lines) + + +def test_a_record_is_printed_once_even_when_a_library_set_up_a_root_console( + tmp_path: Path, caplog: pytest.LogCaptureFixture +) -> None: + # caplog listens on the root logger, as the console handler of the migration tool does. + install_workspace_log(tmp_path) + logging.getLogger("thoth.internal_failure").error("only through the workspace handlers") + assert caplog.records == [] + close_workspace_log() + logging.getLogger("thoth.internal_failure").error("back to the usual route") + assert [record.getMessage() for record in caplog.records] == ["back to the usual route"] + + +def test_a_log_folder_that_cannot_be_made_leaves_the_console_and_does_not_stop_the_server( + tmp_path: Path, +) -> None: + (tmp_path / "logs").write_text("a file where the folder should be", encoding="utf-8") + assert install_workspace_log(tmp_path) is None + assert len(_owned_handlers()) == 1 + assert not isinstance(_owned_handlers()[0], RotatingFileHandler) + logging.getLogger("thoth.x").warning("still goes to the console") + + +def test_a_server_writes_to_the_log_of_the_workspace_it_owns_and_lets_go_of_it( + tmp_path: Path, monkeypatch: pytest.MonkeyPatch +) -> None: + workspace = tmp_path / "workspace" + monkeypatch.setenv("THOTH_DEPLOYMENT_MODE", "LOCAL") + with workspace_guard.owned_workspace(workspace, command="thoth serve"): + logging.getLogger("thoth.internal_failure").error("while the server runs") + logging.getLogger("thoth.internal_failure").error("after it stopped") + + text = workspace_log_path(workspace).read_text(encoding="utf-8") + assert "while the server runs" in text and "after it stopped" not in text + assert _owned_handlers() == [] diff --git a/tests/unit/domain/test_failure_text.py b/tests/unit/domain/test_failure_text.py new file mode 100644 index 00000000..7194d816 --- /dev/null +++ b/tests/unit/domain/test_failure_text.py @@ -0,0 +1,118 @@ +"""What a failure log line says, and what it must leave out.""" + +import logging +import re +from pathlib import Path + +import pytest + +from thoth.domain.failure_text import ( + MESSAGE_LIMIT, + REDACTED_INPUT, + REDACTED_SECRET, + BackgroundFailureLog, + failure_text, + input_texts, +) + + +def _raise_chain(detail: str) -> Exception: + def inner() -> None: + raise KeyError("portfolio") + + def outer() -> None: + try: + inner() + except KeyError as exc: + raise RuntimeError(detail) from exc + + try: + outer() + except RuntimeError as exc: + return exc + raise AssertionError("unreachable") + + +def test_every_exception_of_the_chain_is_named_with_the_frames_it_passed_through() -> None: + text = failure_text(_raise_chain("could not build the result")) + lines = text.splitlines() + assert lines[0] == "RuntimeError: could not build the result" + assert "caused by KeyError: 'portfolio'" in lines + # A frame is ": in ". + frames = [line for line in lines if line.startswith(" ")] + assert any(re.fullmatch(r" \S*test_failure_text\.py:\d+ in outer", line) for line in frames) + assert any(re.fullmatch(r" \S*test_failure_text\.py:\d+ in inner", line) for line in frames) + # The path is one a report can carry: never the full path with the folders above the checkout. + assert str(Path(__file__).resolve().parent).replace("\\", "/") not in text.replace("\\", "/") + assert lines.index("caused by KeyError: 'portfolio'") > lines.index(lines[0]) + + +def test_request_text_does_not_reach_the_log_but_identifiers_do() -> None: + request_input = { + "project_id": "project:lantern-study", + "problem": "Why did LAB-42 fail? SECRET-MARK-123", + "nested": {"api_key": "plain-key-value", "items": ["short", "another long value"]}, + "revision_digest": "a" * 64, + } + hidden = input_texts(request_input) + assert "Why did LAB-42 fail? SECRET-MARK-123" in hidden + assert "plain-key-value" in hidden and "another long value" in hidden + # Short values and identifier keys stay readable: they are what a maintainer searches for. + assert "short" not in hidden + assert "project:lantern-study" not in hidden and "a" * 64 not in hidden + assert list(hidden) == sorted(hidden, key=lambda text: (-len(text), text)) + + exc = _raise_chain( + "cannot process Why did LAB-42 fail? SECRET-MARK-123 for project:lantern-study" + ) + text = failure_text(exc, redact=hidden) + assert "SECRET-MARK-123" not in text + assert f"cannot process {REDACTED_INPUT} for project:lantern-study" in text + + +@pytest.mark.parametrize( + "secret", + [ + "sk-abcdefgh12345678", + "xai-ABCDEFGH12345678", + "Bearer abcdefghijklmnop", + "eyJhbGciOiJIUzI1NiJ9.eyJzdWIiOiIxMjM0NTY3ODkwIn0.c2lnbmF0dXJl", + ], +) +def test_token_shaped_text_is_removed_from_a_message(secret: str) -> None: + text = failure_text(ValueError(f"provider refused {secret} today")) + assert secret not in text + assert text == f"ValueError: provider refused {REDACTED_SECRET} today" + + +def test_a_long_message_is_cut_and_line_breaks_are_folded() -> None: + text = failure_text(ValueError("first line\nsecond line " + "x" * 1000)) + message = text.removeprefix("ValueError: ") + assert message.startswith("first line second line ") + assert len(message) == MESSAGE_LIMIT + len("...") + assert "\n" not in text + + +def test_an_exception_without_a_message_is_just_its_type() -> None: + assert failure_text(TimeoutError()) == "TimeoutError" + + +def test_a_repeating_background_failure_is_logged_once_per_place( + caplog: pytest.LogCaptureFixture, +) -> None: + log = BackgroundFailureLog(logging.getLogger("thoth.test.background")) + with caplog.at_level(logging.WARNING, logger="thoth.test.background"): + log.note("index project_id=p", OSError("disk")) + log.note("index project_id=p", OSError("disk")) # the next tick, the same failure + log.note("index project_id=q", OSError("disk")) # another place + log.note("index project_id=p", OSError("locked")) # the failure changed + log.clear("index project_id=p") + log.note("index project_id=p", OSError("locked")) # it worked in between, then failed again + messages = [record.getMessage() for record in caplog.records] + assert messages == [ + "background failure at index project_id=p\nOSError: disk", + "background failure at index project_id=q\nOSError: disk", + "background failure at index project_id=p\nOSError: locked", + "background failure at index project_id=p\nOSError: locked", + ] + assert {record.levelno for record in caplog.records} == {logging.WARNING} diff --git a/tests/unit/services/test_auto_index_failure_log.py b/tests/unit/services/test_auto_index_failure_log.py new file mode 100644 index 00000000..34e40a8e --- /dev/null +++ b/tests/unit/services/test_auto_index_failure_log.py @@ -0,0 +1,105 @@ +"""The background indexer swallows failures so that no request fails; the log still names them.""" + +import logging +from datetime import UTC, datetime +from types import SimpleNamespace +from typing import cast + +import pytest + +from thoth.application.services.auto_index import AutoIndexer +from thoth.application.services.local_retrieval import LocalRetrievalService +from thoth.domain.enums import ProjectLifecycle +from thoth.domain.model_asset import ModelAssetError + +LOGGER = "thoth.application.services.auto_index" + + +class Store: + def __init__(self) -> None: + self.broken: set[str] = set() + + def resume_interrupted(self, project: str, now_ms: int) -> None: + del now_ms + if project in self.broken: + raise OSError(f"cannot read the jobs of {project}") + + def needs_indexing(self, project: str) -> bool: + return project == "p-waiting" + + +def _claim(task: object, project: str, auto: bool) -> None: + del task, project, auto + + +def _release(task: object) -> None: + del task + + +def indexer(store: Store) -> AutoIndexer: + projects = [ + SimpleNamespace(project_id=name, lifecycle=ProjectLifecycle.ACTIVE) + for name in ("p-broken", "p-waiting") + ] + service = SimpleNamespace( + projects=SimpleNamespace(list=lambda: projects), + clock=SimpleNamespace(now=lambda: datetime(2026, 11, 12, tzinfo=UTC)), + store=store, + closed=False, + claim_index_slot=_claim, + release_index_slot=_release, + ) + return AutoIndexer(cast(LocalRetrievalService, service)) + + +def _warnings(caplog: pytest.LogCaptureFixture) -> list[str]: + return [r.getMessage() for r in caplog.records if r.name == LOGGER] + + +def test_a_project_whose_jobs_cannot_be_read_is_skipped_and_named_once_in_the_log( + caplog: pytest.LogCaptureFixture, +) -> None: + store = Store() + store.broken.add("p-broken") + auto = indexer(store) + with caplog.at_level(logging.WARNING, logger=LOGGER): + for _ in range(3): # three ticks + assert auto.projects_needing_index() == ["p-waiting"] + messages = _warnings(caplog) + assert len(messages) == 1 + assert messages[0].startswith( + "background failure at auto-index check project_id=p-broken\n" + "OSError: cannot read the jobs of p-broken\n" + ) + + +async def test_an_indexing_failure_is_logged_but_missing_model_files_are_not( + caplog: pytest.LogCaptureFixture, monkeypatch: pytest.MonkeyPatch +) -> None: + auto = indexer(Store()) + outcome: list[BaseException | None] = [RuntimeError("worker crashed")] + + async def run_project(project: str) -> None: + del project + if outcome[0] is not None: + raise outcome[0] + + monkeypatch.setattr(auto, "run_project", run_project) + with caplog.at_level(logging.WARNING, logger=LOGGER): + await auto._index_one("p-waiting") # pyright: ignore[reportPrivateUsage] + await auto._index_one("p-waiting") # pyright: ignore[reportPrivateUsage] + assert len(_warnings(caplog)) == 1 # the retry five minutes later fails the same way + assert _warnings(caplog)[0].startswith( + "background failure at auto-index project_id=p-waiting\nRuntimeError: worker crashed\n" + ) + + outcome[0] = None # it works once, then the same failure comes back: that is news again + await auto._index_one("p-waiting") # pyright: ignore[reportPrivateUsage] + outcome[0] = RuntimeError("worker crashed") + await auto._index_one("p-waiting") # pyright: ignore[reportPrivateUsage] + assert len(_warnings(caplog)) == 2 + + # Model files that are not installed are the normal state the settings card shows. + outcome[0] = ModelAssetError("MODEL_ASSET_MISSING") + await auto._index_one("p-waiting") # pyright: ignore[reportPrivateUsage] + assert len(_warnings(caplog)) == 2 diff --git a/tests/unit/test_dense_material_reasons.py b/tests/unit/test_dense_material_reasons.py index 0d037faf..ea830df5 100644 --- a/tests/unit/test_dense_material_reasons.py +++ b/tests/unit/test_dense_material_reasons.py @@ -1,5 +1,6 @@ """Dense material for the research path: when it is made, when it is not, why dense falls back.""" +import logging from collections.abc import Callable from types import SimpleNamespace from typing import Any, cast @@ -155,6 +156,68 @@ async def warm() -> None: assert started == [1, 1] +DENSE_LOGGER = "thoth.application.services.dense_material" + + +def _dense_warnings(caplog: pytest.LogCaptureFixture) -> list[str]: + return [r.getMessage() for r in caplog.records if r.name == DENSE_LOGGER] + + +async def test_a_failed_encoder_start_is_written_to_the_log_once( + caplog: pytest.LogCaptureFixture, +) -> None: + now = [0.0] + + async def warm() -> None: + raise RuntimeError("model folder is gone") + + p = provider(index=None, warm=warm, clock=lambda: now[0]) + with caplog.at_level(logging.WARNING, logger=DENSE_LOGGER): + for _ in range(2): # two cooldowns, the same failure + await p.material("p", "lantern", frame()) + assert p.warming is not None + await p.warming + now[0] += WARM_COOLDOWN_SECONDS + 1 + messages = _dense_warnings(caplog) + assert len(messages) == 1 + assert messages[0].startswith( + "background failure at local retrieval encoder warm-up\n" + "RuntimeError: model folder is gone\n" + ) + + +async def test_a_dense_failure_is_logged_with_its_cause_and_never_with_the_question( + caplog: pytest.LogCaptureFixture, monkeypatch: pytest.MonkeyPatch +) -> None: + unreadable = provider(stamp=OSError("db is locked")) + with caplog.at_level(logging.WARNING, logger=DENSE_LOGGER): + for _ in range(2): # two questions, the same failure + material = await unreadable.material("p", "lantern", frame()) + assert material is not None and material.unavailable_reason == "EMBEDDING_FAILED" + messages = _dense_warnings(caplog) + assert len(messages) == 1 + assert messages[0].startswith( + "background failure at dense index stamp project_id=p\nOSError: db is locked\n" + ) + + caplog.clear() + broken = provider() + + async def explode(project: str, question: str, *rest: object) -> object: + del project, rest + raise RuntimeError(f"no vector for {question}") + + monkeypatch.setattr(broken, "_compute", explode) + with caplog.at_level(logging.WARNING, logger=DENSE_LOGGER): + material = await broken.material("p", "where is the lantern kept", frame()) + assert material is not None and material.unavailable_reason == "EMBEDDING_FAILED" + (message,) = _dense_warnings(caplog) + assert message.startswith( + "background failure at dense scores project_id=p\nRuntimeError: no vector for [input]\n" + ) + assert "lantern kept" not in message + + # --- the research path ---------------------------------------------------------------------- From 39aa16e9182db5346a9247b9b7b9699bac7f4bb9 Mon Sep 17 00:00:00 2001 From: THOTH Date: Thu, 12 Nov 2026 08:21:00 +0900 Subject: [PATCH 2/9] Keep the latest answer visible in a conversation without a model With no model connected, the question area took 39-48% of the window and the latest answer showed 22 px at 1440x900 and nothing at smaller sizes; the same notice appeared twice in the page. The question area now folds the model and effort choices when there is nothing to choose, keeps one notice, opens a conversation at the start of the latest answer, names the send button "Send" with the reason it is off (title and aria-describedby), and outlines the question box on focus. --- SOURCE_MANIFEST.json | 62 +++++++------ .../src/components/ConversationTimeline.tsx | 4 +- .../LiveProjectWorkspaceConsent.test.tsx | 2 +- .../LiveProjectWorkspaceInvestigate.test.tsx | 2 +- .../LiveProjectWorkspaceRestart.test.tsx | 44 +++++++-- .../web/src/components/ModelSettings.test.tsx | 12 +++ apps/web/src/components/ModelSettings.tsx | 43 ++++++++- apps/web/src/components/ResearchComposer.tsx | 89 +++++++++++++++++-- .../components/useOpenAtLatestTurn.test.tsx | 74 +++++++++++++++ .../web/src/components/useOpenAtLatestTurn.ts | 21 +++++ apps/web/src/i18n/coreMessages.ts | 2 +- apps/web/src/i18n/ja/coreMessagesJa.ts | 2 +- apps/web/src/i18n/zh/coreMessagesZh.ts | 2 +- .../web/src/i18n/zhHant/coreMessagesZhHant.ts | 2 +- apps/web/src/workstation.css | 36 ++++++++ config/complexity-budget.json | 4 +- 16 files changed, 348 insertions(+), 53 deletions(-) create mode 100644 apps/web/src/components/useOpenAtLatestTurn.test.tsx create mode 100644 apps/web/src/components/useOpenAtLatestTurn.ts diff --git a/SOURCE_MANIFEST.json b/SOURCE_MANIFEST.json index d84bb0e6..69be5822 100644 --- a/SOURCE_MANIFEST.json +++ b/SOURCE_MANIFEST.json @@ -1,6 +1,6 @@ { "schema_version": "thoth-source-preview-manifest-v1", - "created_at": "2026-11-11T22:32:35.360127+00:00", + "created_at": "2026-11-11T23:17:41.423371+00:00", "license": "MIT", "git_history_included": false, "full_suite_verified": false, @@ -718,8 +718,8 @@ }, { "path": "apps/web/src/components/ConversationTimeline.tsx", - "sha256": "989f5a538094fbed61ec8d1b26a34d821589a8a7f82d451a14ae36ff8302836b", - "bytes": 13306 + "sha256": "fac6cb6df248655336792466ee4d4144c07f84345bc8c2fe9b57f6854b7b8b34", + "bytes": 13459 }, { "path": "apps/web/src/components/ConversationTimelineAutoRetry.test.tsx", @@ -943,13 +943,13 @@ }, { "path": "apps/web/src/components/LiveProjectWorkspaceConsent.test.tsx", - "sha256": "f4dbf9590e5109c7a5bbc989db31259444370568fa25d1b949665368e4145d5f", - "bytes": 7736 + "sha256": "1e5837f0ac55a66537e1da61918d9e9cc65062136439817430ba01586b6a5f7d", + "bytes": 7732 }, { "path": "apps/web/src/components/LiveProjectWorkspaceInvestigate.test.tsx", - "sha256": "eb9d8af3a645fffa139434dd4dadf13443ef896aacb5c6d0ff7937e4cbf4ee67", - "bytes": 11599 + "sha256": "44728f19f1c4f79f96fb94d6221614fb990963448206f09c982d4066d144a92c", + "bytes": 11595 }, { "path": "apps/web/src/components/LiveProjectWorkspaceReadiness.test.tsx", @@ -958,8 +958,8 @@ }, { "path": "apps/web/src/components/LiveProjectWorkspaceRestart.test.tsx", - "sha256": "aee0372a08b8a555d10af98fe86115e17e748a301c94e22f1270380797975e28", - "bytes": 39368 + "sha256": "6247b8c2e6b9417c95784ac65a3614bc2357b7759c9879aaa0647b62da2ec728", + "bytes": 41157 }, { "path": "apps/web/src/components/LocalRetrievalSettingsCard.test.tsx", @@ -1018,13 +1018,13 @@ }, { "path": "apps/web/src/components/ModelSettings.test.tsx", - "sha256": "767e22044c695f0d4f7a17bac455c6adc214c95ed85768f327883084c7a5f2b8", - "bytes": 23388 + "sha256": "ff8c859a516bbb4199e6c09ef7530ace180f94afe53773807762258875d7a630", + "bytes": 24703 }, { "path": "apps/web/src/components/ModelSettings.tsx", - "sha256": "3514dee00018c360671e72f6d8b66e9ab5f1372d25ac3190c216505c62464cc7", - "bytes": 9433 + "sha256": "0fc89b932bac5ec985757d707af29018682599bde1f6510c9d4ce8a7c34dd559", + "bytes": 10300 }, { "path": "apps/web/src/components/OAuthLoginFlow.tsx", @@ -1128,8 +1128,8 @@ }, { "path": "apps/web/src/components/ResearchComposer.tsx", - "sha256": "e72ce2f3905d781ef15d92e473af3b1c9a2278c708eb906ea532b9b8c285919b", - "bytes": 6947 + "sha256": "5c749076cb5f8085971cadc5cf0151c3bab23c358aa776f20b9ad7acd87cd961", + "bytes": 8716 }, { "path": "apps/web/src/components/ResearchDetailPane.tsx", @@ -1781,6 +1781,16 @@ "sha256": "460b0f47cb64f71e11923da747b77c2186ef299181ea33d3c8f86eb96f143184", "bytes": 2365 }, + { + "path": "apps/web/src/components/useOpenAtLatestTurn.test.tsx", + "sha256": "4f36af77b87d04dd960bd3512ff992c129c0ff2787fe47f4946c935bc37573d4", + "bytes": 2945 + }, + { + "path": "apps/web/src/components/useOpenAtLatestTurn.ts", + "sha256": "fe79b0898562f1e1cc02d780372cbd6789b1f4f218b2436147fd83659093081f", + "bytes": 951 + }, { "path": "apps/web/src/components/useProjectSources.ts", "sha256": "2a696821c7d8724d6f505d682332ae37c449fa3e2d5b11eddfe43b2fbfc7fef5", @@ -1863,8 +1873,8 @@ }, { "path": "apps/web/src/i18n/coreMessages.ts", - "sha256": "9c20b3222eaa2dc89d8af132f900f7dbd41a7c61410331b6b23f3124e2a03d18", - "bytes": 7912 + "sha256": "ef7da53aa98a3ab54a5303d73b2884ed5669531af5d67f23232393f7cc48ad11", + "bytes": 7898 }, { "path": "apps/web/src/i18n/countFormatMessages.ts", @@ -1948,8 +1958,8 @@ }, { "path": "apps/web/src/i18n/ja/coreMessagesJa.ts", - "sha256": "5f774398374c0c75d36b594bb44f24f306d4fcdb237f6b7f770e9c5b3c68148d", - "bytes": 5069 + "sha256": "16c258ef98efff310575d906d797c075eb42590c839035df00dbe6b45395cfe8", + "bytes": 5051 }, { "path": "apps/web/src/i18n/ja/credentialMessagesJa.ts", @@ -2303,8 +2313,8 @@ }, { "path": "apps/web/src/i18n/zh/coreMessagesZh.ts", - "sha256": "1a1ee80a58bbe888e618852d5b43da5221973d01d39ff7f494b3d12e5f42cc2f", - "bytes": 3812 + "sha256": "73c3b6bbbd0d0c4fedc156a8b4ed09daca878ace2a2a31bb7282b9de4dd22b9f", + "bytes": 3800 }, { "path": "apps/web/src/i18n/zh/credentialMessagesZh.ts", @@ -2438,8 +2448,8 @@ }, { "path": "apps/web/src/i18n/zhHant/coreMessagesZhHant.ts", - "sha256": "acd72e385607b3a9817bdaf1d0625f4be8bb28463a25443686f355c7e6f67ad1", - "bytes": 3810 + "sha256": "2a7ed43bb82465b1798d44e9b41df49488a2b9da8b44cae96615f4b6affaac09", + "bytes": 3798 }, { "path": "apps/web/src/i18n/zhHant/credentialMessagesZhHant.ts", @@ -2613,8 +2623,8 @@ }, { "path": "apps/web/src/workstation.css", - "sha256": "a5f57fa38c45c84b5df63e6899b80b70fab398e05ebf3121f3a276a499466dc8", - "bytes": 64104 + "sha256": "db0cb6c2f3c53ed4c6f6a4fb4e5206a3c56d818e6c89b2ddae52a7cd2f9b3205", + "bytes": 65044 }, { "path": "apps/web/timeline-preview.html", @@ -2663,7 +2673,7 @@ }, { "path": "config/complexity-budget.json", - "sha256": "55c4ebc36b0eb22d73b7109ee0b065bf7894e58e9cc1fc514d6daa3d68fc6707", + "sha256": "0bcaf39e7cd02f0dc39174d14b430865197b79284d6207a9e53c8e08c87404dd", "bytes": 5436 }, { diff --git a/apps/web/src/components/ConversationTimeline.tsx b/apps/web/src/components/ConversationTimeline.tsx index 38f537cb..01d16715 100644 --- a/apps/web/src/components/ConversationTimeline.tsx +++ b/apps/web/src/components/ConversationTimeline.tsx @@ -22,6 +22,7 @@ import { useAutoRetryOff } from "./useAutoRetryOff"; import { SyntheticDataNotice } from "./SyntheticDataNotice"; import { ConversationTurnView, QuestionBubble } from "./ConversationTurnView"; import { collectTurns, savedBeforeSet, turnTally } from "./timelineTurns"; +import { useOpenAtLatestTurn } from "./useOpenAtLatestTurn"; type TimelineProps = { projectId: string; threadId: string; status?: ResearchStatus; sourceUris?: string[]; queuedInstruction?: boolean; @@ -127,6 +128,7 @@ export function ConversationTimeline(props: TimelineProps) { queryFn: ({ pageParam, signal }) => readConversation(projectId, threadId, pageParam, signal, protection.block), getNextPageParam: page => page.next ?? undefined, }); + const timelineRef = useOpenAtLatestTurn(threadId, Boolean(query.data)); if (!example && threadId && (protection.blocked || query.data?.pages.some(page => page.redacted) || (query.error && !canRetainConversation(query.error)))) { return
{t("timeline.accessUnverified")} @@ -147,7 +149,7 @@ export function ConversationTimeline(props: TimelineProps) { const emptyExistingThread = Boolean(threadId && query.data && turns.length === 0 && !currentQuestion && !running); // The newest saved turn stays open unless a live block follows it; earlier turns start folded. const openIndex = currentQuestion || running ? -1 : turns.length - 1; - return
+ return
{!example && } {turns.length > 1 &&

{message("turnTally", tally.total, tally.answered, tally.interrupted)}

} {query.hasNextPage && } diff --git a/apps/web/src/components/LiveProjectWorkspaceConsent.test.tsx b/apps/web/src/components/LiveProjectWorkspaceConsent.test.tsx index 84e9df9e..9727ccd4 100644 --- a/apps/web/src/components/LiveProjectWorkspaceConsent.test.tsx +++ b/apps/web/src/components/LiveProjectWorkspaceConsent.test.tsx @@ -64,7 +64,7 @@ afterEach(async () => { it("names the empty internet consent as the reason, and the settings page lets the user choose it", async () => { await mount(); - const submit = () => container.querySelector('[aria-label="지시 추가"]') as HTMLButtonElement; + const submit = () => container.querySelector('[aria-label="보내기"]') as HTMLButtonElement; expect(container.textContent).toContain("인터넷 사용 동의를 고르세요"); expect(container.textContent).not.toContain("모델 연결과 초기 설정을 확인하세요"); expect(submit().disabled).toBe(true); diff --git a/apps/web/src/components/LiveProjectWorkspaceInvestigate.test.tsx b/apps/web/src/components/LiveProjectWorkspaceInvestigate.test.tsx index 40717f18..25b11aff 100644 --- a/apps/web/src/components/LiveProjectWorkspaceInvestigate.test.tsx +++ b/apps/web/src/components/LiveProjectWorkspaceInvestigate.test.tsx @@ -109,7 +109,7 @@ it("opens the existing conversation of the same row, with the question filled in fixture.threads = [{ thread_id: "t-other", origin: null }, { thread_id: "t-rain", origin: { subject_kind: "CRITERION", subject_id: RAIN, verdict_revision: "old-revision" } }]; await mount("t-other"); await investigate("Detection rate in rain"); - expect(button("지시 추가")).toBeTruthy(); // an existing thread + expect(button("보내기")).toBeTruthy(); // an existing thread expect(editor().value).toContain("Detection rate in rain"); expect(readDraft("p", "t-rain", scope)).toContain("Detection rate in rain"); expect(sent("thread/start")).toHaveLength(0); diff --git a/apps/web/src/components/LiveProjectWorkspaceRestart.test.tsx b/apps/web/src/components/LiveProjectWorkspaceRestart.test.tsx index 65dbef2f..266ab208 100644 --- a/apps/web/src/components/LiveProjectWorkspaceRestart.test.tsx +++ b/apps/web/src/components/LiveProjectWorkspaceRestart.test.tsx @@ -122,7 +122,7 @@ it("opens authorized stored research and draft while disconnected, but cannot su await settle(() => Boolean(container.textContent?.includes("A stored synthetic answer"))); expect((container.querySelector("#live-problem") as HTMLTextAreaElement).value).toBe("unsubmitted A draft"); expect(container.textContent).toContain("저장된 연구는 계속 볼 수 있습니다"); - expect((container.querySelector('[aria-label="지시 추가"]') as HTMLButtonElement).disabled).toBe(true); + expect((container.querySelector('[aria-label="보내기"]') as HTMLButtonElement).disabled).toBe(true); const recordsTab = [...container.querySelectorAll('[role="tab"]')].find(tab => tab.textContent === "연구 이력"); expect(recordsTab?.getAttribute("aria-disabled")).not.toBe("true"); await act(async () => container.querySelector("form.prompt-composer")!.dispatchEvent(new Event("submit", { bubbles: true, cancelable: true }))); @@ -133,13 +133,45 @@ it("opens authorized stored research and draft while disconnected, but cannot su expect(fixture.calls.some(call => call.method === "model/credential/register")).toBe(false); }); +it("says once, in the question box, why a question cannot be sent while no model is connected", async () => { + saveWorkspaceContext("p", "t", scope("A")); + await mount(); + await settle(() => Boolean(container.textContent?.includes("A stored synthetic answer"))); + const dock = container.querySelector(".composer-dock")!; + const send = dock.querySelector('[aria-label="보내기"]') as HTMLButtonElement; + const reason = "새 연구를 실행하려면 모델 연결을 확인하세요."; + // The reason is on the button itself and in the one notice the button points at. + expect(send.disabled).toBe(true); + expect(send.title).toBe(reason); + const notice = document.getElementById(send.getAttribute("aria-describedby") ?? ""); + expect(notice?.textContent).toContain(reason); + expect(dock.textContent?.split(reason)).toHaveLength(2); + // There is nothing to choose from: no model or effort box, and no second notice about a saved model. + expect(dock.querySelector("select")).toBeNull(); + expect(dock.textContent).not.toContain("저장된 모델 선택"); +}); + +it("offers the model choice and names the send button plainly once a model is connected", async () => { + fixture.executionReady = true; + saveWorkspaceContext("p", "t", scope("A")); + writeDraft("p", "t", "a follow-up question", scope("A")); + await mount(); + await settle(() => Boolean(container.querySelector('[aria-label="보내기"]:not([disabled])'))); + const dock = container.querySelector(".composer-dock")!; + const send = dock.querySelector('[aria-label="보내기"]') as HTMLButtonElement; + expect(send.title).toBe("보내기"); + expect(send.hasAttribute("aria-describedby")).toBe(false); + expect(dock.querySelectorAll("select")).toHaveLength(2); + expect(document.getElementById("composer-blocked-reason")).toBeNull(); +}); + it("keeps authorized research readable when the LOCAL setup record is corrupt", async () => { fixture.setupFailure = "CORRUPT"; saveWorkspaceContext("p", "t", scope("A")); await mount(); await settle(() => Boolean(container.textContent?.includes("A stored synthetic answer"))); expect(container.textContent).toContain("설정 파일이 손상"); - expect((container.querySelector('[aria-label="지시 추가"]') as HTMLButtonElement).disabled).toBe(true); + expect((container.querySelector('[aria-label="보내기"]') as HTMLButtonElement).disabled).toBe(true); expect(fixture.calls.some(call => call.method === "thread/read")).toBe(true); expect(fixture.calls.some(call => call.method === "workspace/setup/update" || call.method === "model/credential/register" || call.method === "thread/input")).toBe(false); }); @@ -188,7 +220,7 @@ it("keeps an existing authorized project readable when setup is unfinished, with fixture.setupComplete = false; saveWorkspaceContext("p", "t", scope("A")); await mount(); await settle(() => Boolean(container.textContent?.includes("A stored synthetic answer"))); - expect((container.querySelector('[aria-label="지시 추가"]') as HTMLButtonElement).disabled).toBe(true); + expect((container.querySelector('[aria-label="보내기"]') as HTMLButtonElement).disabled).toBe(true); expect(container.querySelector(".first-run-shell")).toBeNull(); }); @@ -281,7 +313,7 @@ it("hides cached research during a permission refetch and clears it after denial it("does not apply a late admission after project access is withdrawn", async () => { fixture.executionReady = true; saveWorkspaceContext("p", "t", scope("A")); writeDraft("p", "t", "unsent on revoke", scope("A")); - await mount(); await settle(() => Boolean(container.querySelector('[aria-label="지시 추가"]:not([disabled])'))); + await mount(); await settle(() => Boolean(container.querySelector('[aria-label="보내기"]:not([disabled])'))); let release!: () => void; fixture.admissionGate = new Promise(resolve => { release = resolve; }); try { @@ -312,7 +344,7 @@ it("keeps an editable draft through same-workspace background permission refetch editor.dispatchEvent(new Event("input", { bubbles: true })); }); expect(readDraft("p", "t", scope("A"))).toBe("edited while checking"); - expect((container.querySelector('[aria-label="지시 추가"]') as HTMLButtonElement).disabled).toBe(true); + expect((container.querySelector('[aria-label="보내기"]') as HTMLButtonElement).disabled).toBe(true); release(); await settle(() => Boolean(container.textContent?.includes("A stored synthetic answer"))); expect((container.querySelector("#live-problem") as HTMLTextAreaElement).value).toBe("edited while checking"); } finally { release(); } @@ -446,7 +478,7 @@ it("retries the persisted model choice instead of replacing it with a new draft' expect(writeLocalPending({ version: 1, workspaceId: ids.A, projectId: "p", threadId: "t", problem, selection, signature: submissionSignature("p", "t", problem, selection), key: "22222222-2222-4222-8222-222222222222", createdAt: 1 })).toBe("SAVED"); await mount(); await settle(() => Boolean(container.textContent?.includes("이전 요청이 접수됐을 수 있습니다"))); - expect((container.querySelector('[aria-label="지시 추가"]') as HTMLButtonElement).disabled).toBe(true); + expect((container.querySelector('[aria-label="보내기"]') as HTMLButtonElement).disabled).toBe(true); const retry = [...container.querySelectorAll("button")].find(button => button.textContent === "이전 요청 같은 key로 확인")!; await act(async () => retry.click()); await settle(() => fixture.calls.some(call => call.method === "thread/input")); diff --git a/apps/web/src/components/ModelSettings.test.tsx b/apps/web/src/components/ModelSettings.test.tsx index f69606f4..ed6b83fd 100644 --- a/apps/web/src/components/ModelSettings.test.tsx +++ b/apps/web/src/components/ModelSettings.test.tsx @@ -130,7 +130,19 @@ it("offers the explicit xai-oauth model without replacing an existing selection" it("keeps an unavailable saved model and effort visible until a user selects a new option", async () => { await mount(true); + // Next to the question box the notice is one short line; the reason stays in its tooltip and for a screen reader. + const brief = container.querySelector(".composer-dock .model-settings.compact p.result-notice")!; + const shown = [...brief.childNodes].filter(node => !(node instanceof HTMLElement && node.className === "visually-hidden")); + expect(shown.map(node => node.textContent).join("").replace(/\s+/g, " ").trim()) + .toBe("저장된 모델 선택을 현재 사용할 수 없습니다. 기존 선택은 유지됩니다. 변경하려면 아래에서 모델을 직접 고르세요."); + expect(brief.title).toContain("현재 모델 목록에서 저장된 모델을 찾지 못했습니다"); + expect(brief.title).toContain("저장된 선택: retired / old-model · 추론강도 high"); + expect(brief.querySelector(".visually-hidden")?.textContent).toContain("현재 모델 목록에서 저장된 모델을 찾지 못했습니다"); await openPage("설정"); + // The settings page spells the reason out in the text itself. + const full = container.querySelector(".model-settings:not(.compact) p.result-notice")!; + expect(full.querySelector(".visually-hidden")).toBeNull(); + expect(full.textContent).toContain("현재 모델 목록에서 저장된 모델을 찾지 못했습니다"); expect(container.textContent).toContain("저장된 선택: retired / old-model · 추론강도 high"); expect(container.textContent).toContain("현재 모델 목록에서 저장된 모델을 찾지 못했습니다"); const model = container.querySelector('[aria-label="연구 모델"]')!; diff --git a/apps/web/src/components/ModelSettings.tsx b/apps/web/src/components/ModelSettings.tsx index 61f037ac..2f43d7a2 100644 --- a/apps/web/src/components/ModelSettings.tsx +++ b/apps/web/src/components/ModelSettings.tsx @@ -26,6 +26,37 @@ function savedLabel(value?: SavedSelection): string | null { return `${value.provider ?? t("model.providerUnset")} / ${value.model ?? t("model.modelUnset")}${value.reasoning_effort ? message("effort", value.reasoning_effort) : ""}`; } +/** + * Says that the saved model cannot be used. Next to the question box it is one short line and the + * reason stays available to a screen reader and as the tooltip; the settings page spells it out. + */ +function UnavailableNotice({ compact, reasonCode, saved, inheritsProject }: { + compact: boolean; + reasonCode?: string | null; + saved?: SavedSelection; + inheritsProject: boolean; +}) { + const label = savedLabel(saved); + const detail = [ + unavailableReason(reasonCode), + label ? message("savedSelection", label) : "", + inheritsProject ? t("model.inheritedUnchanged") : "", + ].join(""); + if (compact) { + return ( +

+ {t("model.unavailable")} {detail} + {t("model.keepSelection")} +

+ ); + } + return ( +

+ {t("model.unavailable")} {detail} {t("model.keepSelection")} +

+ ); +} + export function ModelSettings({ projectId, threadId, selection, onSelect, onSaved, compact = false }: { projectId: string; threadId?: string; selection: ModelSelection | null; onSelect: (selection: ModelSelection) => void; onSaved: () => void; compact?: boolean; @@ -82,10 +113,14 @@ export function ModelSettings({ projectId, threadId, selection, onSelect, onSave } }); return
{t("model.settings")} - {data?.availability === "UNAVAILABLE" &&

{t("model.unavailable")} {unavailableReason(data.reason_code)} - {savedLabel(saved) ? message("savedSelection", savedLabel(saved) ?? "") : ""} - {inheritsProject ? t("model.inheritedUnchanged") : ""} - {" "}{t("model.keepSelection")}

} + {data?.availability === "UNAVAILABLE" && ( + + )} {inheritsProject && data?.availability === "UNAVAILABLE" && (inherited.isPending || inherited.isFetching ? {t("model.parentLoading")} : inherited.error ? {t("model.parentFailed")} : {message("inheritedSelection", inheritedLabel ?? t("model.noProjectModel"))})} diff --git a/apps/web/src/components/ResearchComposer.tsx b/apps/web/src/components/ResearchComposer.tsx index 96d51172..b1773ece 100644 --- a/apps/web/src/components/ResearchComposer.tsx +++ b/apps/web/src/components/ResearchComposer.tsx @@ -8,6 +8,9 @@ import { ResearchProgress, UsageSummary } from "./ResearchProgress"; import { useCitationGate } from "./SourceCitationGate"; import type { useResearchSession } from "./useResearchSession"; +/** The notice that says why a new run cannot start; the send button points at it. */ +const BLOCKED_REASON_ID = "composer-blocked-reason"; + export function ResearchComposer({session,projectId,threadId,epoch,onAttach,onOpenSettings,hosted=false,executionReady=true,readSuspended=false,consentMissing=false,modelConnected,setupNoticeShown=false}: { session:ReturnType;projectId:string;threadId:string;epoch:number;onAttach:()=>void;onOpenSettings?:(target?:"consent")=>void; hosted?:boolean;executionReady?:boolean;readSuspended?:boolean;consentMissing?:boolean;modelConnected?:boolean; @@ -18,6 +21,7 @@ export function ResearchComposer({session,projectId,threadId,epoch,onAttach,onOp const citation=useCitationGate(projectId, session.isCurrentScope); const acceptedRequest = session.research.data?.value.request; const acceptedLanguage = acceptedRequest?.response_language ?? null; + const setupNoticeHidden = readSuspended || hosted || executionReady || setupNoticeShown; const submit = async () => { if (!session.isCurrentScope() || !executionReady || readSuspended || session.pendingBlocksNewInput) return; const refs=[...session.problem.matchAll(/artifact:[A-Za-z0-9._:-]+/g)].map(item=>item[0]); @@ -36,7 +40,7 @@ export function ResearchComposer({session,projectId,threadId,epoch,onAttach,onOp {session.pendingRead.kind === "INVALID" && {t("composer.invalidPending")}} {session.pendingStorageError && {t(session.pendingStorageError)}} {readSuspended && {t("composer.accessChecking")}} -