diff --git a/docs/cs-rg-qualification.md b/docs/cs-rg-qualification.md index 6468a2d..f5fee44 100644 --- a/docs/cs-rg-qualification.md +++ b/docs/cs-rg-qualification.md @@ -71,6 +71,8 @@ env -i HOME="$HOME" TMPDIR="$TMPDIR" PATH="/bin:/usr/bin:/bin:/usr/ `--modes` limits a suite to `in-process` or `uds`; both run by default. The installed-service suites default to the service's socket, journal, log, `host.toml` and the consumer's credential file, whose path is handed to the gateway and never read by the harness. Exit status: 0 passed or qualified, 1 failed, 2 incomplete or inconclusive, 3 the harness failed, 130 interrupted; `verify` exits 0 when the run checks out and 1 when it does not. +**Terminal output.** Each scenario, phase, interval, repetition and run prints one `qualify:` line with its verdict. On a terminal the verdict is in color: green when it passed or qualified, red when it failed or the harness failed, yellow when it is inconclusive, incomplete or not run, and magenta when it was interrupted. A status line under the output shows what runs and for how long: in a measurement interval, the time into its planned length and the load's runs, and in the recovery measurement also the gateway that serves. `--color auto`, the default, colors a terminal unless `NO_COLOR` is set, and `always` or `never` overrides it. `--console-log ` keeps a copy of everything the run prints, without color or the status line. A pipe to `tee` makes the output a pipe, which turns both off, so a run started from a terminal keeps its console log this way. The evidence, `verify`'s JSON and the console log never hold color, and output to a file or a pipe is exactly what it was before. + The harness talks to `codespace-mcp` over standard input and output as any MCP client does (protocol `2025-11-25`), with its own small client, so a timing is the tool call's local round trip from the harness and includes no network. It reads DevGuard's journal read-only, as DevGuard's own measurement does, and takes a governed launch's attempt ID and scope root from the gateway's log. diff --git a/docs/ko/cs-rg-qualification.md b/docs/ko/cs-rg-qualification.md index 6811b23..7a02f66 100644 --- a/docs/ko/cs-rg-qualification.md +++ b/docs/ko/cs-rg-qualification.md @@ -71,6 +71,8 @@ env -i HOME="$HOME" TMPDIR="$TMPDIR" PATH="/bin:/usr/bin:/bin:/usr/ `--modes`로 스위트를 `in-process`나 `uds` 하나로 줄일 수 있으며, 기본은 둘 다입니다. 설치된 서비스를 쓰는 스위트는 기본으로 서비스의 socket, journal, 로그, `host.toml`, 소비자 credential 파일을 씁니다. credential 파일은 경로만 gateway에 넘기고 하네스는 읽지 않습니다. 종료 상태는 0 통과 또는 qualification, 1 실패, 2 미완료 또는 판정 불가, 3 하네스 실패, 130 중단입니다. `verify`는 실행 기록이 맞으면 0, 아니면 1로 끝납니다. +**터미널 출력.** 시나리오, 단계, 구간, 반복, 실행마다 판정을 담은 `qualify:` 줄이 하나씩 나옵니다. 터미널에서는 판정에 색이 들어갑니다. 통과하거나 qualification을 마치면 초록, 실패하거나 하네스가 실패하면 빨강, 판정 불가, 미완료, 실행 안 함이면 노랑, 중단되면 자홍색입니다. 출력 아래의 상태 줄은 무엇이 얼마나 오래 실행 중인지 보여 줍니다. 측정 구간에서는 계획한 길이 가운데 지난 시간과 부하의 실행 수를, 복구 측정에서는 서비스 중인 gateway도 보여 줍니다. 기본값 `--color auto`는 `NO_COLOR`가 설정되지 않은 터미널에만 색을 넣고, `always`나 `never`로 이를 바꿀 수 있습니다. `--console-log <새 파일>`은 실행이 출력하는 모든 내용을 색과 상태 줄 없이 복사해 둡니다. `tee`로 파이프를 연결하면 출력이 파이프가 되어 색과 상태 줄이 모두 꺼지므로, 터미널에서 시작한 실행은 이 방법으로 콘솔 로그를 남깁니다. 증거, `verify`의 JSON, 콘솔 로그에는 색이 들어가지 않으며, 파일이나 파이프로 보낸 출력은 이전과 똑같습니다. + 하네스는 다른 MCP client와 마찬가지로 표준 입출력으로 `codespace-mcp`와 통신하며(protocol `2025-11-25`), 자체의 작은 client를 씁니다. 따라서 시간 값은 하네스에서 잰 도구 호출의 로컬 왕복 시간이고 네트워크 시간은 들어가지 않습니다. DevGuard의 journal은 DevGuard 자신의 측정처럼 읽기 전용으로 읽고, 관리 대상 실행의 attempt ID와 scope root는 gateway 로그에서 가져옵니다. diff --git a/docs/ko/recovery-qualification.md b/docs/ko/recovery-qualification.md index e793b3a..47a604a 100644 --- a/docs/ko/recovery-qualification.md +++ b/docs/ko/recovery-qualification.md @@ -6,7 +6,7 @@ 이 문서는 Gateway 복구(P1-RECOVERY)의 opt-in 모드인 [독립 Runner](runner-isolation.md#independent-runner)를 qualification하는 절차입니다. 어떤 조합을 지원한다고 주장하는지, 각 주장을 어떻게 시험하고 측정하는지, 무엇이 통과인지, 실행이 어떤 증거를 남기는지를 정합니다. [CS-RG qualification 절차](cs-rg-qualification.md)를 따르며, 그 후보 조합, 증거, 확인 방식을 그대로 쓰고, 하네스도 같은 [`scripts/qualify-devguard.py`](../../scripts/qualify-devguard.py)입니다. 이 절차는 첫 qualification 실행 전에 하네스와 함께 고정합니다. 첫 실행 뒤에 둘 중 하나라도 바꾸면 새 절차가 되며, 다른 변경처럼 검토하고 영향받는 실행은 다시 합니다. 각 단위가 무엇을 만들었는지는 [결합 로드맵](devguard-integration.md#resource-gateway-recovery)에 있고, 이 문서는 그 결과가 qualification을 통과하는지를 판단합니다. -**현재 상태:** 첫 qualification 실행 전에 하네스와 함께 고정했습니다([#112](https://github.com/novelKR/CodeSpace/pull/112)). 통과한 실행이 나오기 전에 하네스 결함 세 개를 고쳤고([#113](https://github.com/novelKR/CodeSpace/pull/113), [#114](https://github.com/novelKR/CodeSpace/pull/114), [#115](https://github.com/novelKR/CodeSpace/pull/115)), 고칠 때마다 새 절차와 새 후보가 되어 실행을 다시 했습니다. 후보 `1c0eadd`의 실행이 통과해, 독립 Runner는 그 조합으로 qualification을 마쳤습니다. 결과와 증거는 [qualification 보고서](recovery-qualification-report.md)에 있고, 수정 내용은 그 [수정 기록](recovery-qualification-report.md#recovery-report-amendments)에 있습니다. +**현재 상태:** 첫 qualification 실행 전에 하네스와 함께 고정했습니다([#112](https://github.com/novelKR/CodeSpace/pull/112)). 통과한 실행이 나오기 전에 하네스 결함 세 개를 고쳤고([#113](https://github.com/novelKR/CodeSpace/pull/113), [#114](https://github.com/novelKR/CodeSpace/pull/114), [#115](https://github.com/novelKR/CodeSpace/pull/115)), 고칠 때마다 새 절차와 새 후보가 되어 실행을 다시 했습니다. 후보 `1c0eadd`의 실행이 통과해, 독립 Runner는 그 조합으로 qualification을 마쳤습니다. 결과와 증거는 [qualification 보고서](recovery-qualification-report.md)에 있고, 수정 내용은 그 [수정 기록](recovery-qualification-report.md#recovery-report-amendments)에 있습니다. 그 뒤로는 하네스와 검사 스크립트가 터미널에 출력하는 방식만 바뀌었습니다([하네스 실행](cs-rg-qualification.md#running)). 이 변경으로 이후 main commit은 code tree가 달라지므로, qualification을 마친 빌드는 계속 `1c0eadd` 자체이며 다음 qualification은 바뀐 하네스로 실행합니다. diff --git a/docs/ko/upstream-update.md b/docs/ko/upstream-update.md index 933dadc..25084a2 100644 --- a/docs/ko/upstream-update.md +++ b/docs/ko/upstream-update.md @@ -50,6 +50,9 @@ CI도 같은 이름의 단계를 병렬 실행하며 목록은 `--help`로 확 실패한 테스트와 panic 위치, 테스트 수, 실패한 cargo나 unittest 대상도 출력하므로 CI job 로그에서 바로 확인할 수 있습니다. 테스트 자체의 출력은 자식 프로세스의 환경을 담을 수 있어 로그에만 남깁니다. +터미널에서는 실행 중인 단계와 걸린 시간을 상태 줄에 보여 주고 실패를 색으로 +강조합니다. `--color never`를 주면 색을 넣지 않으며, 파일이나 파이프로 보낸 +출력에는 색이 없습니다. 시도마다 `--output`으로 다른 Git 무시 디렉터리를 지정하거나 이전 결과를 보관합니다. 보고서에는 소스 HEAD, Codex SHA, Rust 호스트, 소스와 lockfile 해시가 기록되며 실행 중 입력이 바뀌면 실패합니다. `passed`는 기록된 단계만의 통과를 뜻합니다. diff --git a/docs/recovery-qualification.md b/docs/recovery-qualification.md index 74640b3..5bd1541 100644 --- a/docs/recovery-qualification.md +++ b/docs/recovery-qualification.md @@ -6,7 +6,7 @@ This page is the protocol for qualifying the [independent Runner](runner-isolation.md#independent-runner), the opt-in mode of Gateway recovery (P1-RECOVERY): which combinations are claimed, how each claim is tested and measured, what makes a run pass, and what evidence a run leaves. It follows the [CS-RG qualification protocol](cs-rg-qualification.md), whose candidate, evidence and verification it reuses, and its harness is the same [`scripts/qualify-devguard.py`](../scripts/qualify-devguard.py). It is frozen together with the harness before any qualification run; a change to either after the first run is a new protocol, reviewed like any other change, and the runs it affects are repeated. The [integration roadmap](devguard-integration.md#resource-gateway-recovery) describes what each unit built; this page decides whether the result qualifies. -**Status:** frozen with its harness ([#112](https://github.com/novelKR/CodeSpace/pull/112)) before the first qualification run. Before any run qualified, three harness defects were corrected ([#113](https://github.com/novelKR/CodeSpace/pull/113), [#114](https://github.com/novelKR/CodeSpace/pull/114), [#115](https://github.com/novelKR/CodeSpace/pull/115)); each correction made a new protocol and a new candidate, and the runs were repeated on it. The runs on the candidate `1c0eadd` passed, and the independent Runner is qualified for that combination; the [qualification report](recovery-qualification-report.md) has the results and the evidence, and its [amendments](recovery-qualification-report.md#recovery-report-amendments) record the corrections. +**Status:** frozen with its harness ([#112](https://github.com/novelKR/CodeSpace/pull/112)) before the first qualification run. Before any run qualified, three harness defects were corrected ([#113](https://github.com/novelKR/CodeSpace/pull/113), [#114](https://github.com/novelKR/CodeSpace/pull/114), [#115](https://github.com/novelKR/CodeSpace/pull/115)); each correction made a new protocol and a new candidate, and the runs were repeated on it. The runs on the candidate `1c0eadd` passed, and the independent Runner is qualified for that combination; the [qualification report](recovery-qualification-report.md) has the results and the evidence, and its [amendments](recovery-qualification-report.md#recovery-report-amendments) record the corrections. Since then only what the harness and the checks print on a terminal has changed ([running the harness](cs-rg-qualification.md#running)). That gives later commits of main another code tree, so the qualified build stays `1c0eadd` itself, and the next qualification runs on the changed harness. diff --git a/docs/translations.json b/docs/translations.json index cb6e531..f284bde 100644 --- a/docs/translations.json +++ b/docs/translations.json @@ -133,8 +133,8 @@ "회귀와-동등성", "후보-조합" ], - "source_sha256": "dc0a5ce31fcd3fc4ac9b27b53ed04e04cb448b14f13c8f0fe26f1bf0edc5d283", - "translation_sha256": "6396e29330c89d2b231cfef742ec7dc7927c2297ecefec52a93a67bf210497fb" + "source_sha256": "6bc422fd2b3212dc89055655b0fe25c6bce10ca8e93f6761e2488e6476d17de2", + "translation_sha256": "11f66274ae7e0ab09a88121a99274d68b2b7db78fe3b9114659fca397dbc3792" }, { "id": "cs-rg-qualification-report", @@ -249,8 +249,8 @@ "회귀", "후보-조합" ], - "source_sha256": "a85f4cb3fef6228e77ab7613e796bfd211732b66a88a639dc986c2a10292fad5", - "translation_sha256": "a249e22d93e288e16c88f4605c63b9faa2b722819049f3a619edac8508eaf415" + "source_sha256": "e857af544c09ab653a7c703b44978be3c7545b3056e89f898e047bcb6d7f2f6e", + "translation_sha256": "01c3f33207f7b678b8e5e40d1f971ac2d7d4c7aa59bbab98b17646995dba63c7" }, { "id": "recovery-qualification-report", @@ -917,8 +917,8 @@ "향후-crate와-백엔드의-경계", "후보-검토" ], - "source_sha256": "f0846a7de343b43410f0df86873ea3773b863baabc2379c27eb2f69d9bcd7409", - "translation_sha256": "9a99fb130cbd1099f3b58134ba0907f9edcd11f917bd1e3445209509bfc5098b" + "source_sha256": "7099124f690fb9a59ca6a9d3734405a8d1445bda46786e28bb89dd933c85699b", + "translation_sha256": "1f4148815546388e68621c1510b015ad82977b43710283e5a616fabdbf0ae11d" }, { "id": "upstream-patches", diff --git a/docs/upstream-update.md b/docs/upstream-update.md index d8c108d..65c8cba 100644 --- a/docs/upstream-update.md +++ b/docs/upstream-update.md @@ -46,6 +46,9 @@ When a stage fails, the script also prints the lines of that stage's log that name what failed: the failed tests and where they panicked, the test counts, and the failed cargo or unittest target, so a CI job log names them. A test's own output stays in the log, since its messages can carry a child's environment. +On a terminal the script also shows the running stage and its time on a status +line, and failures in color; `--color never` leaves the color out, and output to +a file or a pipe is plain. Choose a different ignored directory with `--output` for each attempt; preserve previous reports before repeating a run. Reports record the source HEAD, Codex SHA, Rust host, and source/lockfile hashes. A changed input invalidates the run. diff --git a/scripts/check-no-model-deps.sh b/scripts/check-no-model-deps.sh index 7fe3824..ae8b166 100755 --- a/scripts/check-no-model-deps.sh +++ b/scripts/check-no-model-deps.sh @@ -17,6 +17,12 @@ # Never skip the tree because the range could not be computed. set -euo pipefail +# Outcomes in color on a terminal, unless NO_COLOR is set or TERM is dumb, as scripts/console.py +# chooses; redirected, every line is as before. +colors() { [[ -t "$1" && -z "${NO_COLOR:-}" && "${TERM:-}" != dumb ]]; } +if colors 1; then OK=$'\e[1;32mok\e[0m'; else OK=ok; fi +if colors 2; then FORBIDDEN=$'\e[1;31mforbidden\e[0m'; else FORBIDDEN=forbidden; fi + ROOT="$(git rev-parse --show-toplevel)" cd "$ROOT" @@ -237,7 +243,7 @@ scan_manifest() { out="$(grep -nE '^[[:space:]]*codex-[A-Za-z0-9_-]+[[:space:]]*=' "$file" || true)" if [[ -n "$out" ]]; then { - echo "forbidden (codex- cargo dep) in $file:" + echo "$FORBIDDEN (codex- cargo dep) in $file:" echo "$out" } >"$outfile" fi @@ -286,7 +292,7 @@ scan_adapter_manifest() { done < <(grep -nE '^[[:space:]]*codex-[A-Za-z0-9_-]+[[:space:]]*=' "$file" || true) if [[ -n "$bad" ]]; then { - echo "forbidden (codex- key not on $kind allowlist) in $file:" + echo "$FORBIDDEN (codex- key not on $kind allowlist) in $file:" printf '%s' "$bad" } >"$outfile" fi @@ -302,7 +308,7 @@ scan_source() { out="$(grep -R -n -E --exclude-dir=target --exclude-dir=.git -e "$pattern" "$dir" || true)" if [[ -n "$out" ]]; then { - echo "forbidden ($label) in $dir:" + echo "$FORBIDDEN ($label) in $dir:" echo "$out" } >"$outfile" fi @@ -318,7 +324,7 @@ scan_no_helper_lib() { out="$(grep -nE '^[[:space:]]*codespace-linux-sandbox[[:space:]]*=' "$file" || true)" if [[ -n "$out" ]]; then { - echo "forbidden (codespace-linux-sandbox library path dep) in $file:" + echo "$FORBIDDEN (codespace-linux-sandbox library path dep) in $file:" echo "$out" } >"$outfile" fi @@ -327,7 +333,7 @@ scan_no_helper_lib() { scan_helper_binary_only() { local outfile="$1" if [[ -f crates/linux-sandbox/src/lib.rs ]]; then - echo "forbidden: crates/linux-sandbox must be binary-only (src/lib.rs present)" >"$outfile" + echo "$FORBIDDEN: crates/linux-sandbox must be binary-only (src/lib.rs present)" >"$outfile" fi } @@ -420,4 +426,4 @@ if [[ "$hits" -ne 0 ]]; then exit 1 fi -echo "no-model-deps ok" +echo "no-model-deps $OK" diff --git a/scripts/check-upstream-pin.sh b/scripts/check-upstream-pin.sh index 96cd68b..3838fb8 100755 --- a/scripts/check-upstream-pin.sh +++ b/scripts/check-upstream-pin.sh @@ -4,12 +4,20 @@ # patch adapter tests fail. Never treat a red parity run as success. set -euo pipefail +# Outcomes in color on a terminal, unless NO_COLOR is set or TERM is dumb, as scripts/console.py +# chooses; redirected, every line is as before. +colors() { [[ -t "$1" && -z "${NO_COLOR:-}" && "${TERM:-}" != dumb ]]; } +if colors 1; then OK=$'\e[1;32mok\e[0m'; else OK=ok; fi +fail() { + if colors 2; then printf '\e[1;31m%s\e[0m\n' "$1" >&2; else printf '%s\n' "$1" >&2; fi +} + ROOT="$(git rev-parse --show-toplevel)" cd "$ROOT" LOCK_FILE="docs/upstream-lock.md" if [[ ! -f "$LOCK_FILE" ]]; then - echo "missing $LOCK_FILE" >&2 + fail "missing $LOCK_FILE" exit 1 fi @@ -23,18 +31,18 @@ expected="$(awk -F'|' ' ' "$LOCK_FILE")" if [[ ! "$expected" =~ ^[0-9a-f]{40}$ ]]; then - echo "could not parse 40-char commit from $LOCK_FILE (got: ${expected:-empty})" >&2 + fail "could not parse 40-char commit from $LOCK_FILE (got: ${expected:-empty})" exit 1 fi if [[ ! -e third_party/codex ]]; then - echo "third_party/codex is missing; init the submodule" >&2 + fail "third_party/codex is missing; init the submodule" exit 1 fi actual="$(git -C third_party/codex rev-parse HEAD)" if [[ "$actual" != "$expected" ]]; then - echo "Codex submodule $actual does not match lock $expected" >&2 + fail "Codex submodule $actual does not match lock $expected" echo "Do not git submodule update --remote onto Codex main. See docs/upstream-update.md." >&2 exit 1 fi @@ -42,7 +50,7 @@ fi # The recorded downstream patches must be applied, and nothing else changed. python3 scripts/codex_patch.py check -echo "upstream pin ok $actual" +echo "upstream pin $OK $actual" if [[ "${PIN_ONLY:-}" == "1" ]]; then exit 0 diff --git a/scripts/check_docs.py b/scripts/check_docs.py index b2ff44c..2e6f99a 100644 --- a/scripts/check_docs.py +++ b/scripts/check_docs.py @@ -9,6 +9,10 @@ import sys from pathlib import Path +# Loaded by its path too (docs-site's tests), so its own directory is made importable. +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import console # noqa: E402 + ROOT = Path(__file__).resolve().parents[1] REGISTRY = ROOT / 'docs' / 'translations.json' SCHEMA = 'codespace-documentation/v1' @@ -16,10 +20,12 @@ 'id', 'section', 'order', 'route', 'source', 'translation', 'anchors', 'source_sha256', 'translation_sha256', } +# The outcome in color on a terminal (scripts/console.py); redirected, the text as before. +CONSOLE = console.Console('check_docs') def fail(message): - print('Documentation check failed: ' + message, file=sys.stderr) + CONSOLE.line('Documentation check ' + CONSOLE.err_style.verdict('failed') + ': ' + message, err=True) return 1 @@ -89,7 +95,8 @@ def check(): missing_anchors = [item for item in document['anchors'] if item not in available] if missing_anchors: return fail('Missing anchors for ' + ident + ': ' + ', '.join(missing_anchors)) - print('Documentation registry verified: ' + str(len(registry['documents'])) + ' paired documents') + CONSOLE.line('Documentation registry ' + CONSOLE.style.verdict('verified') + ': ' + + str(len(registry['documents'])) + ' paired documents') return 0 @@ -106,7 +113,7 @@ def record(ident=None): document['anchors'] = sorted(set(headings(source.read_text(encoding='utf-8'))) | set(headings(translation.read_text(encoding='utf-8')))) REGISTRY.write_text(json.dumps(registry, ensure_ascii=False, indent=2) + '\n', encoding='utf-8') - print('Recorded ' + ', '.join(document['id'] for document in selected)) + CONSOLE.line(CONSOLE.style('Recorded', 'bold', 'green') + ' ' + ', '.join(document['id'] for document in selected)) return 0 @@ -114,15 +121,17 @@ def main(): parser = argparse.ArgumentParser(description=__doc__) parser.add_argument('command', nargs='?', default='check', choices=['check', 'record']) parser.add_argument('--id') + console.add_option(parser) args = parser.parse_args() - try: - if args.command == 'record': - return record(args.id) - if args.id: - return fail('check does not take --id') - return check() - except (OSError, ValueError, KeyError, json.JSONDecodeError) as error: - return fail(str(error)) + with CONSOLE.session(args.color, live=False): + try: + if args.command == 'record': + return record(args.id) + if args.id: + return fail('check does not take --id') + return check() + except (OSError, ValueError, KeyError, json.JSONDecodeError) as error: + return fail(str(error)) if __name__ == '__main__': diff --git a/scripts/codex_patch.py b/scripts/codex_patch.py index cf1406f..77b7ff1 100644 --- a/scripts/codex_patch.py +++ b/scripts/codex_patch.py @@ -20,11 +20,16 @@ import sys import tempfile +sys.path.insert(0, str(Path(__file__).resolve().parent)) +import console # noqa: E402 + ROOT = Path(__file__).resolve().parents[1] LOCK = ROOT / 'docs' / 'upstream-lock.md' CHECKOUT = ROOT / 'third_party' / 'codex' PIN_SECTION = 'Deployment pin' PATCH_SECTION = 'Downstream patch' +# The outcome in color on a terminal (scripts/console.py); redirected, the text as before. +CONSOLE = console.Console('codex_patch') class PatchStateError(RuntimeError): @@ -149,12 +154,15 @@ def revert(record: Record, checkout: Path = CHECKOUT) -> str: def main(): parser = argparse.ArgumentParser(description=__doc__) parser.add_argument('command', choices=['apply', 'check', 'revert']) + console.add_option(parser) args = parser.parse_args() - try: - print({'apply': apply, 'check': check, 'revert': revert}[args.command](read_record())) - except (OSError, PatchStateError) as error: - print(f'codex_patch {args.command} failed: {error}', file=sys.stderr) - return 1 + with CONSOLE.session(args.color, live=False): + try: + message = {'apply': apply, 'check': check, 'revert': revert}[args.command](read_record()) + except (OSError, PatchStateError) as error: + CONSOLE.line(f'codex_patch {args.command} {CONSOLE.err_style.verdict("failed")}: {error}', err=True) + return 1 + CONSOLE.line(CONSOLE.style(message, 'green')) return 0 diff --git a/scripts/console.py b/scripts/console.py new file mode 100644 index 0000000..f1e2dde --- /dev/null +++ b/scripts/console.py @@ -0,0 +1,299 @@ +"""Terminal output for people: verdict words in color, a live status line while a long step runs, +and a plain copy of the output for a console log (docs/cs-rg-qualification.md#running). + +Only what a person reads goes through here. Evidence, JSON, MCP messages, logs that a program +reads and anything a parent process captures are never styled. Redirected to a file or a pipe, +or with color off, every line is exactly the text a plain print writes; and without a terminal +and without a console log, nothing replaces stdout or stderr at all. + +Color is chosen for each stream: `--color always` or `never`, or for `auto`, a terminal while +NO_COLOR is unset or empty (https://no-color.org) and TERM is not `dumb`. No environment +variable turns color on, so a child whose output is captured never inherits it. + +Standard library only; Python 3.9 or later, as the qualification host's system Python.""" +import contextlib +import os +import re +import sys +import threading +import time +import traceback + +MODES = ('auto', 'always', 'never') +# Select Graphic Rendition parameters. +CODES = {'bold': '1', 'dim': '2', 'red': '31', 'green': '32', 'yellow': '33', 'magenta': '35', 'cyan': '36'} +ANSI = re.compile(r'\x1b\[[0-9;]*m') +# Each verdict word in the color of what its reader has to do: nothing (green), look at what failed +# (red), look at what could not be shown (yellow), or note that the run was stopped (magenta). +VERDICT_COLORS = { + **dict.fromkeys(('pass', 'passed', 'qualified', 'verified', 'ok'), 'green'), + **dict.fromkeys(('fail', 'failed', 'harness_failed'), 'red'), + **dict.fromkeys(('inconclusive', 'incomplete', 'not_run'), 'yellow'), + 'interrupted': 'magenta'} +# How often the status line is redrawn. +TICK_S = 1.0 + + +def add_option(parser): + """`--color` for a script's command line.""" + parser.add_argument('--color', choices=MODES, default='auto', + help='color for people: auto (on a terminal, unless NO_COLOR is set), always or never') + + +def is_terminal(stream): + try: + return bool(stream.isatty()) + except (AttributeError, OSError, ValueError): + return False + + +def wants_color(stream, mode='auto', environ=None): + """Whether output to `stream` is colored under `mode`.""" + if mode not in MODES: + raise ValueError(f'color is one of {", ".join(MODES)}, not {mode!r}') + if mode != 'auto': + return mode == 'always' + environ = os.environ if environ is None else environ + return not environ.get('NO_COLOR') and environ.get('TERM') != 'dumb' and is_terminal(stream) + + +def clock(seconds): + """`seconds` as m:ss, or as h:mm:ss from an hour on.""" + seconds = max(0, int(seconds)) + hours, rest = divmod(seconds, 3600) + minutes, seconds = divmod(rest, 60) + return f'{hours}:{minutes:02d}:{seconds:02d}' if hours else f'{minutes}:{seconds:02d}' + + +class Style: + """Text in SGR styles when on, and the text itself when off.""" + + def __init__(self, on=False): + self.on = bool(on) + + @classmethod + def of(cls, stream, mode='auto', environ=None): + return cls(wants_color(stream, mode, environ)) + + def __call__(self, text, *names): + text = str(text) + if not (self.on and names and text): + return text + return '\x1b[' + ';'.join(CODES[name] for name in names) + 'm' + text + '\x1b[0m' + + def verdict(self, word): + """A verdict word: bold, in the color of what its reader has to do.""" + color = VERDICT_COLORS.get(str(word)) + return self(word, 'bold', *((color,) if color else ())) + + def reasons(self, word, reasons): + """A verdict's reasons as the harness prints them, a Python list: dim when there are + none, and otherwise in the verdict's color.""" + color = VERDICT_COLORS.get(str(word)) + return self(reasons, 'dim') if not reasons else self(reasons, *((color,) if color else ())) + + +class Progress: + """The status line of one step: its subject and how long it has run; with `planned_s`, + `starting` until `begin` marks the start of the planned part, the time into it, and + `concluding` once it is over; `detail`, a function, adds counts after a comma.""" + + def __init__(self, subject, planned_s=None, detail=None): + self.subject, self.planned_s, self.detail = subject, planned_s, detail + self.created = time.monotonic() + self.began = None + + def begin(self, at=None): + """Mark the start of the planned part, now or at the monotonic time `at`.""" + self.began = time.monotonic() if at is None else at + + def __call__(self): + now = time.monotonic() + if self.planned_s is None: + text = f'{self.subject} {clock(now - self.created)}' + elif self.began is None or now < self.began: + text = f'{self.subject} starting' + elif now - self.began < self.planned_s: + text = f'{self.subject} {clock(now - self.began)} of {clock(self.planned_s)}' + else: + text = f'{self.subject} concluding' + extra = self.detail() if self.detail is not None else '' + return f'{text}, {extra}' if extra else text + + +class Stream: + """stdout or stderr during a session: what is written goes to the stream, after the status + line is taken away, and a copy without colors goes to the console log.""" + + def __init__(self, console, stream): + self._console, self._stream = console, stream + self._terminal = is_terminal(stream) + + def write(self, text): + return self._console.write(self._stream, self._terminal, text) + + def writelines(self, lines): + for line in lines: + self.write(line) + + def flush(self): + self._stream.flush() + + def __getattr__(self, name): + return getattr(self._stream, name) + + +class Console: + """A process's output for people. + + `line` prints one line, styled with `style` (for stdout; `err_style` is for stderr). In a + `session` on a terminal, `status` shows a live line under the output while a step runs, + redrawn every second: every write to stdout or stderr takes it away first, and it comes back + once the output is at a line start. A session's console log gets everything written to + stdout and stderr, without colors and without the status line. Outside a session, or in one + with neither a terminal nor a log, `line` is a plain print and nothing is replaced.""" + + def __init__(self, name): + self.name = name + self.style = self.err_style = Style(False) + self.lock = threading.RLock() + self.terminal = self.log = self.ticker = None + self.steps = [] + self.shown, self.drawn = 0, '' + self.at_start = True + self.stopped = threading.Event() + + def line(self, text='', err=False): + with self.lock: + print(text, file=sys.stderr if err else sys.stdout, flush=True) + + @contextlib.contextmanager + def session(self, color='auto', log_path=None, live=True, environ=None): + """For the block: color for stdout and stderr as `color` says, with `live` the status line + when stdout is a terminal, and a new console log at `log_path`. An exception that leaves the + block is copied to the log as the interpreter will print it.""" + environ = os.environ if environ is None else environ + stdout, stderr = sys.stdout, sys.stderr + self.style, self.err_style = Style.of(stdout, color, environ), Style.of(stderr, color, environ) + terminal = stdout if live and is_terminal(stdout) and environ.get('TERM') != 'dumb' else None + try: + log = self.open_log(log_path) if log_path is not None else None + if terminal is None and log is None: + yield self + return + with self.lock: + self.terminal, self.log, self.steps, self.at_start = terminal, log, [], True + self.shown, self.drawn = 0, '' + # Each session's status line has its own ticker, which ends with the session. + self.stopped = threading.Event() + sys.stdout, sys.stderr = Stream(self, stdout), Stream(self, stderr) + try: + yield self + except BaseException as error: + self.keep(error) + raise + finally: + self.stopped.set() + if self.ticker is not None: + self.ticker.join(timeout=5) + with self.lock: + self.erase() + sys.stdout, sys.stderr = stdout, stderr + self.terminal = self.log = self.ticker = None + self.steps = [] + if log is not None: + log.close() + finally: + self.style = self.err_style = Style(False) + + def open_log(self, path): + """A new console log; an existing file is never written over.""" + try: + descriptor = os.open(path, os.O_WRONLY | os.O_CREAT | os.O_EXCL, 0o600) + except FileExistsError: + raise SystemExit(f'{self.name}: {path} already exists') from None + except OSError as error: + raise SystemExit(f'{self.name}: the console log {path} cannot be created: {error}') from None + return os.fdopen(descriptor, 'w', encoding='utf-8', errors='backslashreplace', newline='') + + def keep(self, error): + """Copy to the log what the interpreter prints for an exception that ends the program.""" + if self.log is None: + return + if isinstance(error, SystemExit): + text = '' if error.code is None or isinstance(error.code, int) else f'{error.code}\n' + else: + text = ''.join(traceback.format_exception(type(error), error, error.__traceback__)) + with self.lock: + self.log.write(text) + self.log.flush() + + @contextlib.contextmanager + def status(self, text): + """While the block runs, a terminal's status line shows `text`: a function, such as a + Progress, or a subject that a Progress then times.""" + if self.terminal is None: + yield + return + step = [text if callable(text) else Progress(text)] + with self.lock: + self.steps.append(step) + if self.ticker is None: + self.ticker = threading.Thread(target=self.tick, args=(self.stopped,), name='console-status', + daemon=True) + self.ticker.start() + try: + yield + finally: + with self.lock: + self.steps = [entry for entry in self.steps if entry is not step] + if not self.steps: + self.erase() + + def tick(self, stopped): + while not stopped.wait(TICK_S): + with self.lock: + if not stopped.is_set() and self.terminal is not None and self.steps and self.at_start: + self.draw(self.steps[-1][0]) + + def draw(self, text): + try: + text = str(text()) + except Exception: # noqa: BLE001 - a status line never stops the work it shows + return + try: + width = os.get_terminal_size(self.terminal.fileno()).columns + except (AttributeError, OSError, ValueError): + width = 0 + # A terminal whose size is unknown reports 0 columns. + text = text[:(width or 80) - 1] + if not text or (self.shown and text == self.drawn): + return + try: + self.terminal.write('\r' + ' ' * self.shown + '\r' + self.style(text, 'dim')) + self.terminal.flush() + except (OSError, ValueError): + return + self.shown, self.drawn = len(text), text + + def erase(self): + if self.shown and self.terminal is not None: + try: + self.terminal.write('\r' + ' ' * self.shown + '\r') + self.terminal.flush() + except (OSError, ValueError): + pass + self.shown, self.drawn = 0, '' + + def write(self, stream, terminal, text): + with self.lock: + if terminal: + self.erase() + count = stream.write(text) + if text and terminal: + self.at_start = text.endswith('\n') + if self.log is not None and text: + self.log.write(ANSI.sub('', text)) + if '\n' in text: + self.log.flush() + return count diff --git a/scripts/qualify-devguard.py b/scripts/qualify-devguard.py index 8be5d67..d6e41c2 100644 --- a/scripts/qualify-devguard.py +++ b/scripts/qualify-devguard.py @@ -29,6 +29,11 @@ own scratch directories. Exit status: 0 passed or qualified, 1 failed, 2 incomplete or inconclusive, 3 the harness failed, 130 interrupted; verify exits 0 when the sealed run checks out and 1 when it does not. + +On a terminal, each verdict is in color and a status line shows what runs and for how long; +--color chooses otherwise, and --console-log keeps a plain copy of the output. The evidence, +verify's JSON and the console log never hold color, and output to a file or a pipe is exactly what +it was before. """ import argparse import hashlib @@ -57,11 +62,14 @@ from qualify_analysis import check # noqa: E402 import qualify_host as host # noqa: E402 from qualify_host import ToolError # noqa: E402 +import console # noqa: E402 ROOT = Path(__file__).resolve().parents[1] PINNED_RUST = '1.95.0' EXIT = {'passed': 0, 'qualified': 0, 'failed': 1, 'incomplete': 2, 'inconclusive': 2} EXIT_CRASH = 3 +# What the run prints for people (scripts/console.py): plain unless a suite's session colors it. +CONSOLE = console.Console('qualify') IO = (False, True) MODES = ('in-process', 'uds') # What a matrix execution asks for; it runs one process at a time, never a descendant. @@ -383,12 +391,15 @@ def run_scenario(results, evidence, mode, io, name, function, *args, suite=None, began = time.time() checks, detail = [], {} if not not_run: - try: - checks, detail = function(*args) - except Exception as error: # noqa: BLE001 - every broken scenario is evidence - checks = [check('the scenario completed', False, error=f'{type(error).__name__}: {error}', - trace=traceback.format_exc()[-3000:])] - detail = {} + label = scenario_label({'suite': suite, 'mode': mode, 'participation': participation, 'io': io, + 'scenario': name}) + with CONSOLE.status(f'qualify: {label}: running'): + try: + checks, detail = function(*args) + except Exception as error: # noqa: BLE001 - every broken scenario is evidence + checks = [check('the scenario completed', False, error=f'{type(error).__name__}: {error}', + trace=traceback.format_exc()[-3000:])] + detail = {} entry = {'scenario': name, 'mode': mode, 'io': io, 'verdict': analysis.scenario_verdict(checks, not_run), 'checks': checks, 'detail': detail, 'started_unix': began, 'ended_unix': time.time()} for key, value in (('suite', suite), ('participation', participation), ('not_run', not_run)): @@ -396,10 +407,20 @@ def run_scenario(results, evidence, mode, io, name, function, *args, suite=None, entry[key] = value results.append(entry) evidence.append('scenarios.jsonl', entry) - print(f"qualify: {scenario_label(entry)}: {entry['verdict']}", flush=True) + verdict_line(f'{scenario_label(entry)}:', entry['verdict']) return entry +def verdict_line(subject, verdict, reasons=None): + """One line for people: `qualify:`, the subject, its verdict and, when given, its reasons. + With color off it is the plain text, as the console log keeps it.""" + style = CONSOLE.style + parts = [style('qualify:', 'dim'), subject, style.verdict(verdict)] + if reasons is not None: + parts.append(style.reasons(verdict, reasons)) + CONSOLE.line(' '.join(parts)) + + def scenario_label(entry): return ' '.join(str(part) for part in (entry.get('suite'), entry['mode'], entry.get('participation'), entry['io'] or '-', entry['scenario']) if part) @@ -818,8 +839,8 @@ def matrix(args, live, evidence): run_scenario(results, evidence, mode, None, 'runner-socket', scenario_runner_socket, bench) entry = run_scenario(results, evidence, mode, None, 'settled', lambda: (settled_checks(bench, mode), {})) if entry['verdict'] != 'pass': - print('qualify: work stayed charged or an instance stayed active; the matrix stops here', - flush=True) + CONSOLE.line(CONSOLE.style('qualify:', 'dim') + ' ' + CONSOLE.style( + 'work stayed charged or an instance stayed active; the matrix stops here', 'bold', 'red')) break finally: if bench is not None: @@ -1696,7 +1717,7 @@ def authority_phase(bench, gateway, evidence, mode, targets, echo, phase, fault, 'read_errors': watcher.read_errors, 'evidence_writer': written, 'raw': raw_hashes(raw)} record['verdict'], record['reasons'], record['metrics'] = phase_verdict(record, rows) evidence.write_json(f'{mode}/authority/{phase}/phase.json', record) - print(f"qualify: {mode} authority {phase}: {record['verdict']} {record['reasons']}", flush=True) + verdict_line(f'{mode} authority {phase}:', record['verdict'], record['reasons']) return record @@ -1832,6 +1853,13 @@ def interval_metrics(record, rows, sampled, runs, release_id, service_pid, reser def control_interval(context, mode, kind, seconds, key, service_pid): + """One interval, with a status line on a terminal: the time into it and the load's runs.""" + progress = console.Progress(f'qualify: {key} {kind}:', seconds) + with CONSOLE.status(progress): + return measured_control_interval(context, mode, kind, seconds, key, service_pid, progress) + + +def measured_control_interval(context, mode, kind, seconds, key, service_pid, progress): args, live, evidence, measure, release, dg_release, work, reservation = ( context[name] for name in ('args', 'live', 'evidence', 'measure', 'release', 'dg_release', 'work', 'reservation')) prefix = f'{key}/{kind}' @@ -1882,6 +1910,7 @@ def control_interval(context, mode, kind, seconds, key, service_pid): 'service': host.Sampler(writer, raw / 'service.jsonl', SERVICE_PERIOD_S, release.state), 'footprint': host.Sampler(writer, raw / 'footprint.jsonl', FOOTPRINT_PERIOD_S, footprint(bench.owner_pid, gateway, mode))} + progress.begin(begin) until(begin) record['started_unix'] = time.time() for thread in list(schedules.values()) + list(samplers.values()): @@ -1890,6 +1919,7 @@ def control_interval(context, mode, kind, seconds, key, service_pid): (raw / 'runs').mkdir() load = measure.consumers(SimpleNamespace(qualify_bin=Path(args.qualify_bin)), dg_release, args.load, work, raw / 'runs', begin + seconds, key, args.rehearsal) + progress.detail = lambda: load_runs(load) for consumer in load: consumer.start() limit = begin + seconds + measure.LOAD_COMPLETION_LIMIT_S @@ -1940,10 +1970,15 @@ def control_interval(context, mode, kind, seconds, key, service_pid): record['verdict'], record['reasons'] = analysis.interval_verdict(kind, invalid, metrics) record['metrics'] = metrics evidence.write_json(prefix + '/interval.json', record) - print(f"qualify: {key} {kind}: {record['verdict']} {record['reasons']}", flush=True) + verdict_line(f'{key} {kind}:', record['verdict'], record['reasons']) return record +def load_runs(load): + """The load's runs so far, for a status line.""" + return f'{sum(len(consumer.runs) for consumer in load)} load runs' + + def early_outcome(report): """The verdict of a repetition that could not begin its intervals, or None.""" if not report['service_before']['runs_release']: @@ -1976,7 +2011,7 @@ def control_repetition(context, plan, mode, repetition): def conclude(outcome): report['verdict'], report['reasons'] = outcome evidence.write_json(f'{key}/report.json', report) - print(f"qualify: {key} {report['verdict']} {report['reasons']}", flush=True) + verdict_line(key, report['verdict'], report['reasons']) return report if report['service_before']['runs_release'] and args.load == 'warm': @@ -4133,6 +4168,8 @@ def __init__(self, context, kind, seconds, key): self.pending_timeouts, self.pending_approval = [], None self.number = 0 self.store_id = None + self.load = [] + self.progress = console.Progress(f'qualify: {key} {kind}:', seconds, self.status_counts) # ---------------------------------------------------------- the interval @@ -4161,10 +4198,11 @@ def run(self): if watcher is not None: watcher.start() begin = time.monotonic() + 0.5 + self.progress.begin(begin) schedules = self.schedules(watcher, begin) samplers = self.samplers() if self.kind == 'load' and self.context.get('measure') is not None: - load = self.start_load(begin) + load = self.load = self.start_load(begin) until(begin) self.serving.serve(self.gateway) record['started_unix'] = time.time() @@ -4230,9 +4268,16 @@ def run(self): else: record['verdict'], record['reasons'] = 'inconclusive', list(invalid) or ['the interval did not begin'] self.evidence.write_json(self.prefix + '/interval.json', record) - print(f"qualify: {self.key} {self.kind}: {record['verdict']} {record['reasons']}", flush=True) + verdict_line(f'{self.key} {self.kind}:', record['verdict'], record['reasons']) return record + def status_counts(self): + """The counts on the interval's status line: the serving gateway and the load's runs.""" + parts = [f'gateway {self.number}'] if self.number else [] + if self.load: + parts.append(load_runs(self.load)) + return ', '.join(parts) + def journal_before(self): if not self.governed: return None @@ -4662,7 +4707,9 @@ def recovery_interval_metrics(record, rows, sampled, records, found, runs, relea def recovery_interval(context, kind, seconds, key): - return RecoveryInterval(context, kind, seconds, key).run() + interval = RecoveryInterval(context, kind, seconds, key) + with CONSOLE.status(interval.progress): + return interval.run() def recovery_repetition_outcome(report, idle, load): @@ -4686,7 +4733,7 @@ def recovery_repetition(context, plan, repetition): def conclude(outcome): report['verdict'], report['reasons'] = outcome evidence.write_json(f'{key}/report.json', report) - print(f"qualify: {key} {report['verdict']} {report['reasons']}", flush=True) + verdict_line(key, report['verdict'], report['reasons']) return report if governed: @@ -4987,7 +5034,7 @@ def verify_recovery(directory, problems): VERIFIERS = {'candidate': verify_candidate, 'matrix': verify_scenarios, 'faults': verify_scenarios, 'authority': verify_authority, 'control': verify_control, 'recovery': verify_recovery, **{unit: verify_scenarios for unit in RECOVERY_UNITS}} -HARNESS = ('qualify-devguard.py', 'qualify_analysis.py', 'qualify_host.py') +HARNESS = ('qualify-devguard.py', 'qualify_analysis.py', 'qualify_host.py', 'console.py') def harness(): @@ -5093,6 +5140,10 @@ def arguments(argv=None): base.add_argument('--runtime-bin', type=Path, required=True, help='codespace-codex-runtime built with --features devguard (the uds worker, or the ' 'independent Runner)') + console.add_option(base) + base.add_argument('--console-log', type=Path, + help='a new file for a plain copy of what the run prints, without color or the status ' + 'line; unlike a pipe to tee, it leaves the terminal a terminal') common = argparse.ArgumentParser(add_help=False, parents=[base]) common.add_argument('--modes', type=modes, default=list(MODES), help='in-process, uds or both (default both)') installed = installed_options(True) @@ -5150,6 +5201,11 @@ def main(argv=None): result = verify(args.directory) print(json.dumps(result, indent=2)) return 0 if result['verdict'] == 'verified' else 1 + with CONSOLE.session(args.color, args.console_log): + return run_suite(args, argv) + + +def run_suite(args, argv): evidence = host.Evidence(args.out) live = Live() for number in (signal.SIGTERM, signal.SIGHUP): @@ -5159,7 +5215,8 @@ def main(argv=None): 'harness': harness()} status = EXIT_CRASH try: - result = SUITES[args.suite](args, live, evidence) + with CONSOLE.status(f'qualify: {args.suite}'): + result = SUITES[args.suite](args, live, evidence) report.update(result=result, verdict=result['verdict']) status = EXIT[result['verdict']] except KeyboardInterrupt: @@ -5173,8 +5230,9 @@ def main(argv=None): report['ended_unix'] = time.time() evidence.write_json('report.json', report) manifest = evidence.seal() - print(f"qualify: {args.suite}: {report['verdict']}; evidence {evidence.path}, MANIFEST.json SHA-256 {manifest}", - flush=True) + style = CONSOLE.style + CONSOLE.line(f"{style('qualify:', 'dim')} {style(args.suite, 'bold')}: {style.verdict(report['verdict'])}; " + f"evidence {evidence.path}, MANIFEST.json SHA-256 {manifest}") return status diff --git a/scripts/tests/test_console.py b/scripts/tests/test_console.py new file mode 100644 index 0000000..8d09ad1 --- /dev/null +++ b/scripts/tests/test_console.py @@ -0,0 +1,226 @@ +"""Terminal output for people (scripts/console.py): color only where it is asked for or a terminal +shows it, a status line only on a terminal, and a console log that is the plain text.""" +import contextlib +import io +from pathlib import Path +import sys +import tempfile +import time +import unittest +from unittest import mock + +sys.path.insert(0, str(Path(__file__).resolve().parents[1])) +import console # noqa: E402 + +PLAIN = {'PATH': '/usr/bin'} + + +class Terminal(io.StringIO): + """A stream that says it is a terminal and has no descriptor, so the width is the fallback.""" + + def isatty(self): + return True + + +def until(condition, limit=5.0): + deadline = time.monotonic() + limit + while not condition(): + if time.monotonic() > deadline: + raise AssertionError('the condition did not hold in time') + time.sleep(0.01) + + +class ColorTests(unittest.TestCase): + def test_auto_colors_only_a_terminal(self): + self.assertTrue(console.wants_color(Terminal(), 'auto', PLAIN)) + self.assertFalse(console.wants_color(io.StringIO(), 'auto', PLAIN)) + self.assertFalse(console.wants_color(Terminal(), 'auto', dict(PLAIN, NO_COLOR='1'))) + self.assertTrue(console.wants_color(Terminal(), 'auto', dict(PLAIN, NO_COLOR=''))) + self.assertFalse(console.wants_color(Terminal(), 'auto', dict(PLAIN, TERM='dumb'))) + self.assertTrue(console.wants_color(io.StringIO(), 'always', dict(PLAIN, NO_COLOR='1'))) + self.assertFalse(console.wants_color(Terminal(), 'never', PLAIN)) + with self.assertRaises(ValueError): + console.wants_color(Terminal(), 'sometimes', PLAIN) + + def test_a_style_that_is_off_is_the_text(self): + style = console.Style(False) + self.assertEqual(style('qualify:', 'dim'), 'qualify:') + self.assertEqual(style.verdict('qualified'), 'qualified') + self.assertEqual(style.reasons('inconclusive', ['a reason']), "['a reason']") + self.assertEqual(style.reasons('pass', []), '[]') + + def test_verdict_colors(self): + style = console.Style(True) + self.assertEqual(style.verdict('pass'), '\x1b[1;32mpass\x1b[0m') + self.assertEqual(style.verdict('qualified'), '\x1b[1;32mqualified\x1b[0m') + self.assertEqual(style.verdict('harness_failed'), '\x1b[1;31mharness_failed\x1b[0m') + self.assertEqual(style.verdict('not_run'), '\x1b[1;33mnot_run\x1b[0m') + self.assertEqual(style.verdict('interrupted'), '\x1b[1;35minterrupted\x1b[0m') + self.assertEqual(style.verdict('unknown'), '\x1b[1munknown\x1b[0m') + self.assertEqual(style.reasons('pass', []), '\x1b[2m[]\x1b[0m') + self.assertEqual(style.reasons('fail', ['x']), "\x1b[31m['x']\x1b[0m") + self.assertEqual(style('', 'bold'), '') + self.assertEqual(console.ANSI.sub('', style.verdict('fail') + ' ' + style('x', 'dim')), 'fail x') + + +class ProgressTests(unittest.TestCase): + def test_clock(self): + self.assertEqual([console.clock(s) for s in (-1, 0, 59.9, 61, 3599, 3600, 36061)], + ['0:00', '0:00', '0:59', '1:01', '59:59', '1:00:00', '10:01:01']) + + def test_progress_text(self): + now = [100.0] + with mock.patch.object(console.time, 'monotonic', lambda: now[0]): + plain = console.Progress('qualify: matrix') + interval = console.Progress('qualify: uds-1 load:', 1800, lambda: '29 load runs') + now[0] = 165.0 + self.assertEqual(plain(), 'qualify: matrix 1:05') + self.assertEqual(interval(), 'qualify: uds-1 load: starting, 29 load runs') + interval.begin(170.0) + self.assertEqual(interval(), 'qualify: uds-1 load: starting, 29 load runs') + now[0] = 893.0 + self.assertEqual(interval(), 'qualify: uds-1 load: 12:03 of 30:00, 29 load runs') + now[0] = 1970.0 + interval.detail = lambda: '' + self.assertEqual(interval(), 'qualify: uds-1 load: concluding') + + +class SessionTests(unittest.TestCase): + def setUp(self): + self.scratch = tempfile.TemporaryDirectory() + self.dir = Path(self.scratch.name) + self.console = console.Console('test') + + def tearDown(self): + self.scratch.cleanup() + + def test_without_a_terminal_or_a_log_nothing_is_replaced(self): + with contextlib.redirect_stdout(io.StringIO()) as out, contextlib.redirect_stderr(io.StringIO()): + with self.console.session('auto', environ=PLAIN): + self.assertIs(sys.stdout, out) + with self.console.status('a step'): + self.console.line(self.console.style.verdict('passed')) + self.assertIs(sys.stdout, out) + self.assertEqual(out.getvalue(), 'passed\n') + self.assertFalse(self.console.style.on) + + def test_the_console_log_is_the_plain_output(self): + log = self.dir / 'run.console.log' + with contextlib.redirect_stdout(io.StringIO()) as out, contextlib.redirect_stderr(io.StringIO()) as err: + with self.console.session('always', log, environ=PLAIN): + self.console.line(f"{self.console.style('qualify:', 'dim')} uds-1 load: " + f"{self.console.style.verdict('pass')}") + print('measure: a line of its own', flush=True) + print('a warning', file=sys.stderr) + self.assertIs(sys.stdout, out) + self.assertIn('\x1b[1;32mpass\x1b[0m', out.getvalue()) + self.assertEqual(console.ANSI.sub('', out.getvalue()), 'qualify: uds-1 load: pass\nmeasure: a line of its own\n') + self.assertEqual(err.getvalue(), 'a warning\n') + self.assertEqual(log.read_text(), 'qualify: uds-1 load: pass\nmeasure: a line of its own\na warning\n') + self.assertEqual(log.stat().st_mode & 0o777, 0o600) + + def test_a_console_log_is_never_written_over(self): + log = self.dir / 'run.console.log' + log.write_text('an earlier run\n') + with self.assertRaises(SystemExit) as raised: + with self.console.session('never', log, environ=PLAIN): + self.fail('the session began') + self.assertEqual(str(raised.exception.code), f'test: {log} already exists') + self.assertEqual(log.read_text(), 'an earlier run\n') + with self.assertRaises(SystemExit) as raised: + with self.console.session('never', self.dir / 'missing' / 'run.console.log', environ=PLAIN): + self.fail('the session began') + self.assertIn('cannot be created', str(raised.exception.code)) + + def test_what_ends_the_program_is_kept_in_the_log(self): + log = self.dir / 'exit.console.log' + with contextlib.redirect_stdout(io.StringIO()), self.assertRaises(SystemExit): + with self.console.session('never', log, environ=PLAIN): + raise SystemExit('test: the evidence directory already exists') + self.assertEqual(log.read_text(), 'test: the evidence directory already exists\n') + log = self.dir / 'trace.console.log' + with contextlib.redirect_stdout(io.StringIO()), self.assertRaises(KeyError): + with self.console.session('never', log, environ=PLAIN): + raise KeyError('missing') + text = log.read_text() + self.assertTrue(text.startswith('Traceback (most recent call last):\n'), text) + self.assertTrue(text.endswith("KeyError: 'missing'\n"), text) + log = self.dir / 'status.console.log' + with contextlib.redirect_stdout(io.StringIO()), self.assertRaises(SystemExit): + with self.console.session('never', log, environ=PLAIN): + raise SystemExit(2) + self.assertEqual(log.read_text(), '') + + def test_a_terminal_shows_the_status_line_and_the_log_does_not(self): + screen, log = Terminal(), self.dir / 'live.console.log' + with mock.patch.object(console, 'TICK_S', 0.01), contextlib.redirect_stdout(screen): + with self.console.session('never', log, environ=PLAIN): + with self.console.status(console.Progress('qualify: uds-1 idle:', 600)): + until(lambda: self.console.shown) + self.console.line('qualify: uds pipe exits: pass') + until(lambda: self.console.shown) + self.assertEqual(self.console.shown, 0) + with self.console.status('qualify: recovery'): + until(lambda: self.console.shown) + print('qualify: a partial', end='', flush=True) + self.assertEqual(self.console.shown, 0) + time.sleep(0.05) + self.assertEqual(self.console.shown, 0) + print(' line', flush=True) + until(lambda: self.console.shown) + self.assertIs(sys.stdout, screen) + text = screen.getvalue() + status = 'qualify: uds-1 idle: starting' + self.assertTrue(text.startswith('\r\r' + status), repr(text[:80])) + self.assertIn('\r' + ' ' * len(status) + '\rqualify: uds pipe exits: pass\n', text) + self.assertIn('qualify: a partial line\n', text) + self.assertIn('\rqualify: recovery 0:00', text) + self.assertTrue(text.endswith('\r' + ' ' * len('qualify: recovery 0:00') + '\r'), repr(text[-80:])) + self.assertEqual(log.read_text(), 'qualify: uds pipe exits: pass\nqualify: a partial line\n') + + def test_a_status_line_fits_the_terminal_and_is_dim_in_color(self): + screen = Terminal() + with mock.patch.object(console, 'TICK_S', 0.01), contextlib.redirect_stdout(screen): + with self.console.session('always', environ=PLAIN): + with self.console.status(lambda: 'x' * 200): + until(lambda: self.console.shown) + self.assertIn('\r\x1b[2m' + 'x' * 79 + '\x1b[0m', screen.getvalue()) + self.assertNotIn('x' * 80, screen.getvalue()) + + def test_an_unchanged_status_is_drawn_once(self): + screen = Terminal() + with mock.patch.object(console, 'TICK_S', 0.01), contextlib.redirect_stdout(screen): + with self.console.session('never', environ=PLAIN): + with self.console.status(lambda: 'qualify: uds-1 load: concluding'): + until(lambda: self.console.shown) + time.sleep(0.1) + status = 'qualify: uds-1 load: concluding' + self.assertEqual(screen.getvalue(), '\r\r' + status + '\r' + ' ' * len(status) + '\r') + + def test_a_broken_status_never_stops_the_work(self): + screen = Terminal() + + def broken(): + raise RuntimeError('no counts yet') + + with mock.patch.object(console, 'TICK_S', 0.01), contextlib.redirect_stdout(screen): + with self.console.session('never', environ=PLAIN): + with self.console.status(broken): + time.sleep(0.05) + self.console.line('qualify: still running') + self.assertEqual(screen.getvalue(), 'qualify: still running\n') + + def test_a_dumb_terminal_or_no_live_output_has_no_status_line(self): + for environ, live in ((dict(PLAIN, TERM='dumb'), True), (PLAIN, False)): + screen = Terminal() + with mock.patch.object(console, 'TICK_S', 0.01), contextlib.redirect_stdout(screen): + with self.console.session('auto', live=live, environ=environ): + self.assertIs(sys.stdout, screen) + with self.console.status('qualify: matrix'): + time.sleep(0.05) + self.console.line(self.console.style.verdict('passed')) + self.assertEqual(screen.getvalue(), 'passed\n' if environ.get('TERM') else '\x1b[1;32mpassed\x1b[0m\n') + + +if __name__ == '__main__': + unittest.main() diff --git a/scripts/tests/test_qualify_devguard.py b/scripts/tests/test_qualify_devguard.py index bf8a15f..0c3ff96 100644 --- a/scripts/tests/test_qualify_devguard.py +++ b/scripts/tests/test_qualify_devguard.py @@ -24,6 +24,7 @@ SCRIPTS = Path(__file__).resolve().parents[1] sys.path.insert(0, str(SCRIPTS)) +import console # noqa: E402 import qualify_analysis as analysis # noqa: E402 import qualify_host as host # noqa: E402 spec = importlib.util.spec_from_file_location('qualify', SCRIPTS / 'qualify-devguard.py') @@ -803,6 +804,75 @@ def test_repetition_outcomes(self): cold = dict(report, prewarm=[{'result': 'completed', 'exit_code': 1}]) self.assertEqual(qualify.early_outcome(cold)[1], ['the warm target directory could not be built']) + # ------------------------------------------------------------ terminal output + + def test_lines_without_color_read_as_before(self): + with contextlib.redirect_stdout(io.StringIO()) as printed: + qualify.verdict_line('uds pipe exits:', 'pass') + qualify.verdict_line('uds-1 load:', 'inconclusive', ['rehearsal durations are below the protocol']) + qualify.verdict_line('uds-1', 'pass', []) + self.assertEqual(printed.getvalue(), 'qualify: uds pipe exits: pass\n' + "qualify: uds-1 load: inconclusive ['rehearsal durations are below the protocol']\n" + 'qualify: uds-1 pass []\n') + + def test_lines_in_color(self): + with contextlib.redirect_stdout(io.StringIO()) as printed: + with qualify.CONSOLE.session('always'): + qualify.verdict_line('uds-1 load:', 'fail', ['status: p99']) + qualify.verdict_line('uds-1', 'pass', []) + self.assertEqual(printed.getvalue(), + "\x1b[2mqualify:\x1b[0m uds-1 load: \x1b[1;31mfail\x1b[0m \x1b[31m['status: p99']\x1b[0m\n" + '\x1b[2mqualify:\x1b[0m uds-1 \x1b[1;32mpass\x1b[0m \x1b[2m[]\x1b[0m\n') + + def test_a_run_keeps_a_plain_console_log(self): + def suite(args, live, evidence): + qualify.verdict_line('uds pipe exits:', 'pass') + return {'verdict': 'passed'} + + def argv(name, *extra): + return ['matrix', '--out', str(self.dir / name), '--mcp-bin', 'm', '--runtime-bin', 'r', '--release', 'v', + *extra] + + log = self.dir / 'run.console.log' + with mock.patch.dict(qualify.SUITES, {'matrix': suite}): + with contextlib.redirect_stdout(io.StringIO()) as printed: + self.assertEqual(qualify.main(argv('run', '--color', 'always', '--console-log', str(log))), 0) + out = (self.dir / 'run').resolve() + plain = ('qualify: uds pipe exits: pass\n' + f'qualify: matrix: passed; evidence {out}, MANIFEST.json SHA-256 {host.sha256(out / "MANIFEST.json")}\n') + self.assertIn('\x1b[1;32mpassed\x1b[0m', printed.getvalue()) + self.assertEqual(console.ANSI.sub('', printed.getvalue()), plain) + self.assertEqual(log.read_text(), plain) + self.assertIs(sys.stdout, sys.__stdout__) + report = json.loads((out / 'report.json').read_text()) + self.assertIn('console.py', report['harness']['files']) + self.assertIn('--console-log', report['argv']) + # Without a terminal and without a log, the output is what it was before. + with contextlib.redirect_stdout(io.StringIO()) as printed: + self.assertEqual(qualify.main(argv('plain')), 0) + self.assertNotIn('\x1b', printed.getvalue()) + self.assertTrue(printed.getvalue().startswith('qualify: uds pipe exits: pass\nqualify: matrix: passed;')) + # A console log is never written over, and the run does not start. + with contextlib.redirect_stdout(io.StringIO()), self.assertRaises(SystemExit) as refused: + qualify.main(argv('again', '--console-log', str(log))) + self.assertEqual(str(refused.exception.code), f'qualify: {log} already exists') + self.assertFalse((self.dir / 'again').exists()) + self.assertEqual(log.read_text(), plain) + with contextlib.redirect_stderr(io.StringIO()), self.assertRaises(SystemExit): + qualify.arguments(argv('x', '--color', 'sometimes')) + + def test_interval_status_lines(self): + now = [10.0] + with mock.patch.object(console.time, 'monotonic', lambda: now[0]): + interval = qualify.RecoveryInterval({'args': SimpleNamespace(), 'live': None, 'evidence': host.Evidence( + self.dir / 'status'), 'governed': False, 'combination': 'independent'}, 'load', 1800, 'independent-1') + self.assertEqual(interval.progress(), 'qualify: independent-1 load: starting') + interval.progress.begin(12.0) + interval.number = 29 + interval.load = [SimpleNamespace(runs=[{}] * 3), SimpleNamespace(runs=[{}])] + now[0] = 735.0 + self.assertEqual(interval.progress(), 'qualify: independent-1 load: 12:03 of 30:00, gateway 29, 4 load runs') + def test_modes(self): self.assertEqual(qualify.modes('uds'), ['uds']) self.assertEqual(qualify.modes('in-process, uds'), ['in-process', 'uds']) diff --git a/scripts/validate-upstream.py b/scripts/validate-upstream.py index 6bf37d8..1e2dc39 100644 --- a/scripts/validate-upstream.py +++ b/scripts/validate-upstream.py @@ -13,8 +13,13 @@ import time import codex_patch +import console from upstream_dependencies import ADAPTERS, DEVGUARD_SOURCE, ROOT +# What the run prints for people: on a terminal, a status line with the running stage's time, and +# failures in color (scripts/console.py). The stage logs and the report are never styled. +CONSOLE = console.Console('validate-upstream') + def capture(*cmd): return subprocess.check_output(cmd, cwd=ROOT).decode().strip() @@ -170,7 +175,7 @@ def devguard_binaries(): def execute(commands, env, log): for command in commands: - print('+ ' + ' '.join(command), flush=True) + CONSOLE.line(CONSOLE.style('+ ' + ' '.join(command), 'dim')) log.write('+ ' + ' '.join(command) + '\n') log.flush() status = subprocess.run(command, cwd=ROOT, env=env, stdout=log, stderr=subprocess.STDOUT).returncode @@ -209,16 +214,18 @@ def failure_lines(path): def print_failures(stage, path): """Print what a failed stage's log names as failed. A log that cannot be read changes nothing but this summary.""" + style = CONSOLE.style try: lines = failure_lines(path) except OSError as error: - print(f'{stage} failed; its log could not be read: {error}', flush=True) + CONSOLE.line(f'{stage} {style.verdict("failed")}; its log could not be read: {error}') return - print(f'{stage} failed; ' + (f'from {path.name}:' if lines else f'{path.name} names no failed test'), flush=True) + CONSOLE.line(f'{stage} {style.verdict("failed")}; ' + + (f'from {path.name}:' if lines else f'{path.name} names no failed test')) for line in lines[:FAILURES_SHOWN]: - print(' ' + line, flush=True) + CONSOLE.line(' ' + style(line, 'red')) if len(lines) > FAILURES_SHOWN: - print(f' and {len(lines) - FAILURES_SHOWN} more lines in {path.name}', flush=True) + CONSOLE.line(style(f' and {len(lines) - FAILURES_SHOWN} more lines in {path.name}', 'dim')) def run(selected, output): @@ -267,7 +274,7 @@ def run(selected, output): if stage == 'macos-fork-race': # The harness's summary, trial lines and crash reports go to the report. stage_env['CODESPACE_FORK_RACE_OUT'] = str(output / 'fork-race') - with (output / (stage + '.log')).open('w') as log: + with (output / (stage + '.log')).open('w') as log, CONSOLE.status(f'{stage}:'): execute(commands, stage_env, log) entry['status'] = 'passed' except (OSError, RuntimeError) as error: @@ -278,7 +285,7 @@ def run(selected, output): fork_race = output / 'fork-race' / 'summary.json' if stage == 'macos-fork-race' and fork_race.is_file(): # The stage's counts for readers of the job log; the report keeps the details. - print('fork_race summary: ' + fork_race.read_text().strip(), flush=True) + CONSOLE.line(CONSOLE.style('fork_race summary:', 'bold') + ' ' + fork_race.read_text().strip()) if fingerprint() != before: raise RuntimeError('source or validation inputs changed during execution') report['status'] = 'failed' if failed else ('incomplete' if any(s['status'] == 'not_run' for s in report['stages']) else 'passed') @@ -301,13 +308,15 @@ def main(): parser = argparse.ArgumentParser(description=__doc__) parser.add_argument('stage', nargs='+', choices=['all'] + list(stages())) parser.add_argument('--output', type=Path, default=ROOT / 'target/upstream-reports/local') + console.add_option(parser) args = parser.parse_args() selected = all_stages() if 'all' in args.stage else list(dict.fromkeys(args.stage)) # Reports must be ignored; otherwise they would invalidate the source snapshot themselves. output = args.output.resolve() if subprocess.run(['git', 'check-ignore', '-q', str(output / 'report.json')], cwd=ROOT).returncode != 0: parser.error('--output must be inside a git-ignored directory (e.g. target/upstream-reports)') - return run(selected, output) + with CONSOLE.session(args.color): + return run(selected, output) if __name__ == '__main__':