Pick any line to see why it is the way it is: the commit, the pull request and issue it came from, and what the agent was thinking.
| Merge Actions runs: summaries, attempts and re-runs, graceful cancel, log downloads, badges (actions 0009) | 1 | import assert from "node:assert/strict"; |
| 2 | import { test } from "node:test"; | |
| 3 | ||
| 4 | import type { JobLogText } from "@g1t/contracts"; | |
| 5 | ||
| A very long step log stays fast. Each chunk of a job's log is read once, into its step's log, as it arrives (`appendLog` in lib/log-lines.ts), where before every chunk joined the step's text again and read all of it from the start: a group a chunk leaves open holds the next chunk's lines, a line still being written shows until it ends, and a search reads the lines already read, once a change. A step of more than 2,000 rows draws only those on screen and 800 pixels either side (lib/log-window.ts), each row one line high until it is drawn and measured, so the space kept above and below is right however lines wrap; groups fold in the page's state rather than in a `details`, and search, following the newest line and Jump to latest work as on a short log. Each line's number links to it as GitHub's do (`#step:3:12`), opening its step and its group, scrolling to it and marking it. With a synthetic 50,000-line log in 500 chunks of 100 lines, reading it took 24.6 s in all and 105 ms for the last chunk before, and 0.5 s and 1.3 ms now; in Chromium the page drew the whole log in 2.2 s and each new chunk in 213 ms (157,000 elements), and now in 51 ms and 17 ms (385 elements). The Actions guide says so. | 6 | import { |
| 7 | type StepLog, | |
| 8 | appendLog, | |
| 9 | archiveFiles, | |
| 10 | blocks, | |
| 11 | classify, | |
| 12 | emptyLog, | |
| 13 | fileName, | |
| 14 | groupOf, | |
| 15 | highlight, | |
| 16 | lastStamp, | |
| 17 | logRows, | |
| 18 | readLog, | |
| 19 | rowKey, | |
| 20 | searchLog, | |
| 21 | searchStepLog, | |
| 22 | splitStamp, | |
| 23 | } from "./log-lines.ts"; | |
| 24 | ||
| 25 | /** `text` read as chunks cut at `cuts` (offsets into it), one at a time. */ | |
| 26 | function readInChunks(text: string, cuts: number[]): StepLog { | |
| 27 | let log = emptyLog(); | |
| 28 | let at = 0; | |
| 29 | for (const cut of [...cuts, text.length]) { | |
| 30 | log = appendLog(log, text.slice(at, cut)); | |
| 31 | at = cut; | |
| 32 | } | |
| 33 | return log; | |
| 34 | } | |
| 35 | ||
| 36 | /** What a log holds, for comparing two ways of reading it. */ | |
| 37 | function shape(log: StepLog) { | |
| 38 | return { blocks: log.blocks, lines: log.lines, blockOf: log.blockOf, group: log.group, lastAt: log.lastAt, hasText: log.hasText }; | |
| 39 | } | |
| 40 | ||
| 41 | test("a log read chunk by chunk is the log read at once, wherever the chunks fall", () => { | |
| 42 | const text = [ | |
| 43 | "2026-10-12T09:41:07.1000000Z Job: test", | |
| 44 | "2026-10-12T09:41:07.2000000Z ##[group]Run cargo test", | |
| 45 | "2026-10-12T09:41:07.3000000Z cargo test --locked", | |
| 46 | "2026-10-12T09:41:07.4000000Z \u001b[32mok\u001b[0m", | |
| 47 | "2026-10-12T09:41:08.0000000Z ##[endgroup]", | |
| 48 | "2026-10-12T09:41:09.0000000Z ##[error]Process completed with exit code 101.", | |
| 49 | "", | |
| 50 | ].join("\n"); | |
| 51 | const whole = readLog(text); | |
| 52 | // Every cut, and many cuts, including inside a line and inside an escape code. | |
| 53 | for (let cut = 0; cut <= text.length; cut++) assert.deepEqual(shape(readInChunks(text, [cut])), shape(whole), `cut at ${cut}`); | |
| 54 | assert.deepEqual(shape(readInChunks(text, Array.from({ length: text.length }, (_, i) => i))), shape(whole)); | |
| 55 | assert.equal(whole.lastAt, "2026-10-12T09:41:09.0000000Z"); | |
| 56 | assert.deepEqual(whole.blocks, blocks(text)); | |
| 57 | }); | |
| 58 | ||
| 59 | test("a group a chunk leaves open holds the next chunk's lines", () => { | |
| 60 | let log = appendLog(emptyLog(), "before\n##[group]Install\none\n"); | |
| 61 | assert.equal(log.group, 1); | |
| 62 | log = appendLog(log, "two\n##[endgroup]\nafter\n"); | |
| 63 | assert.deepEqual( | |
| 64 | log.blocks.map((block) => (block.kind === "line" ? block.line.text : `${block.title}: ${block.lines.map((entry) => entry.line.text).join(",")}`)), | |
| 65 | ["before", "Install: one,two", "after"], | |
| 66 | ); | |
| 67 | assert.equal(log.group, null); | |
| 68 | assert.equal(groupOf(log, 3), 1); | |
| 69 | assert.equal(groupOf(log, 4), null); | |
| 70 | }); | |
| 71 | ||
| 72 | test("a line still being written shows, and is read once it ends", () => { | |
| 73 | let log = appendLog(emptyLog(), "one\ntw"); | |
| 74 | assert.equal(log.lines.length, 1); | |
| 75 | assert.deepEqual(log.tail, { line: { kind: "text", text: "tw" }, number: 2 }); | |
| 76 | assert.deepEqual(searchStepLog(log, "TW").map((found) => found.number), [2]); | |
| 77 | log = appendLog(log, "o\n"); | |
| 78 | assert.equal(log.tail, undefined); | |
| 79 | assert.deepEqual(log.lines.map((entry) => entry.line.text), ["one", "two"]); | |
| 80 | // A group's marker cut in two opens the group once it is whole. | |
| 81 | log = appendLog(log, "##[gro"); | |
| 82 | assert.equal(log.tail, undefined, "half a marker is not a line"); | |
| 83 | log = appendLog(log, "up]Later\nthree\n"); | |
| 84 | assert.equal(groupOf(log, 3), 2); | |
| 85 | assert.equal(readLog(" \n\n").hasText, false); | |
| 86 | }); | |
| 87 | ||
| 88 | test("reading a long log chunk by chunk reads each line once", () => { | |
| 89 | const line = (n: number) => `2026-10-12T09:41:07.0000000Z ${n % 500 === 0 ? "##[group]Batch" : n % 500 === 20 ? "##[endgroup]" : `test case_${n} ... ok`}\n`; | |
| 90 | let log = emptyLog(); | |
| 91 | const started = performance.now(); | |
| 92 | for (let chunk = 0; chunk < 500; chunk++) { | |
| 93 | let text = ""; | |
| 94 | for (let n = chunk * 100; n < chunk * 100 + 100; n++) text += line(n); | |
| 95 | log = appendLog(log, text); | |
| 96 | } | |
| 97 | const took = performance.now() - started; | |
| 98 | assert.equal(log.lines.length, 50_000 - 200); | |
| 99 | // Reading the whole text again for every chunk took about 25 s here. | |
| 100 | assert.ok(took < 2000, `50,000 lines in 500 chunks took ${Math.round(took)} ms`); | |
| 101 | }); | |
| 102 | ||
| 103 | test("a log's rows are its lines and groups' titles, open groups' lines under them", () => { | |
| 104 | const log = readLog("a\n##[group]G\nb\nc\n##[endgroup]\nd\n"); | |
| 105 | const keys = (open: number[]) => logRows(log, new Set(open)).map(rowKey); | |
| 106 | assert.deepEqual(keys([]), ["L1", "G1", "L4"]); | |
| 107 | assert.deepEqual(keys([1]), ["L1", "G1", "L2", "L3", "L4"]); | |
| 108 | assert.deepEqual(logRows(log, new Set())[1], { kind: "group", block: 1, title: "G", at: undefined, open: false, size: 2 }); | |
| 109 | // A search reads a log once a change. | |
| 110 | assert.equal(searchStepLog(log, "b"), searchStepLog(log, " B ")); | |
| 111 | }); | |
| Merge Actions runs: summaries, attempts and re-runs, graceful cancel, log downloads, badges (actions 0009) | 112 | |
| 113 | const LOG = ["Job: test", "##[group]Run cargo test", "cargo test --locked", "##[endgroup]", "test greet ... FAILED", "##[error]Process completed with exit code 101."].join("\n"); | |
| 114 | ||
| 115 | test("a log reads as lines and folded groups, numbered past the group markers", () => { | |
| 116 | const parsed = blocks(LOG); | |
| 117 | assert.equal(parsed.length, 4); | |
| 118 | assert.deepEqual(parsed[1], { kind: "group", title: "Run cargo test", lines: [{ line: { kind: "text", text: "cargo test --locked" }, number: 2 }] }); | |
| 119 | assert.deepEqual(parsed[3], { kind: "line", line: { kind: "error", text: "Process completed with exit code 101." }, number: 4 }); | |
| 120 | }); | |
| 121 | ||
| 122 | test("search finds lines in any case, inside folded groups too", () => { | |
| 123 | assert.deepEqual( | |
| 124 | searchLog(LOG, "CARGO TEST").map((found) => found.number), | |
| 125 | [2], | |
| 126 | ); | |
| 127 | assert.deepEqual( | |
| 128 | searchLog(LOG, "test").map((found) => found.number), | |
| 129 | [1, 2, 3], | |
| 130 | ); | |
| 131 | assert.deepEqual(searchLog(LOG, " "), []); | |
| 132 | // The group's title is not a line of its own. | |
| 133 | assert.deepEqual(searchLog(LOG, "Run cargo"), []); | |
| 134 | }); | |
| 135 | ||
| 136 | test("matches are marked where they fall", () => { | |
| 137 | assert.deepEqual(highlight("Test a test", "test"), [ | |
| 138 | { text: "Test", match: true }, | |
| 139 | { text: " a ", match: false }, | |
| 140 | { text: "test", match: true }, | |
| 141 | ]); | |
| 142 | assert.deepEqual(highlight("plain", ""), [{ text: "plain", match: false }]); | |
| 143 | }); | |
| 144 | ||
| 145 | test("a run's archive has each job whole and a file per step, named as the API names them", () => { | |
| 146 | const job = (name: string, chunks: [number, string][], omitted = false): JobLogText => ({ | |
| 147 | jobId: "job_1", | |
| 148 | name, | |
| 149 | steps: [{ number: 1, name: "Run cargo test", status: "completed", conclusion: "success", startedAt: null, finishedAt: null }], | |
| 150 | chunks: chunks.map(([step, text], index) => ({ seq: index + 1, step, text })), | |
| 151 | done: true, | |
| 152 | omitted, | |
| 153 | }); | |
| 154 | const files = archiveFiles([job("test", [[0, "set up\n"], [1, "running\n"], [1, "ok\n"]]), job("deploy/x", [], true)]); | |
| 155 | assert.deepEqual( | |
| 156 | files.map((file) => file.path), | |
| 157 | ["1_test.txt", "test/0_Set up job.txt", "test/1_Run cargo test.txt", "2_deploy_x.txt"], | |
| 158 | ); | |
| 159 | assert.equal(files[0]!.text, "set up\nrunning\nok\n"); | |
| 160 | assert.equal(files[2]!.text, "running\nok\n"); | |
| 161 | assert.match(files[3]!.text, /left out/); | |
| 162 | assert.equal(fileName("build / a:b"), "build _ a_b"); | |
| 163 | assert.equal(fileName(".."), "job"); | |
| 164 | }); | |
| A running job's log is live, as on GitHub. A step's output reaches its run's page within about two seconds: the runner sends what is printed every second, and the page asks every second while a step runs, every three while none does; an answer that fails (a 429, a 5xx, the network) is asked again after a wait that doubles to half a minute, or as long as Retry-After says, where before one such answer stopped the log for good and the step said "No output yet." until the page was reloaded, and a signed-out viewer's run page, refreshing beside its log, ran into the 30-a-minute limit within a minute; the live log now counts as a page, and only log downloads as costly. A hidden tab stops asking and catches up when shown, and the page says when it is reconnecting. The running step opens by itself, its timer counts, its log follows the newest line while its end is on screen and offers Jump to latest once the viewer scrolls up, a step that has printed nothing for a while says "Running · no output for 2m 10s", and the job's header names the step it is on. Colour that tools print (bold, dim, italic, underline, the 16 colours as theme tokens for light and dark, 256 colours and 24-bit colour, text and background) is drawn as printed, other escape codes are dropped and links keep their text, and search reads the plain text and keeps the colours around what it marks. Every line is stamped with the time it was printed, as GitHub's raw logs are, so log.txt and the run's zip have a time at the start of each line, and a clock button beside Search logs shows the times, remembered by the browser. Set up job now gives the runner's version and name, the operating system, the runner image, the machine's architecture, CPUs and memory, the token's permissions under G1T_TOKEN Permissions, the secret source and the actions it downloads; each run step opens with GitHub's folded Run group, the script in cyan, the shell's whole path and the step's env, each uses step with its with inputs (an action's defaults among them) and env; cache and artifact transfers say how far they have got every five seconds; and a last Complete job step sets the job's outputs and stops what the steps left running, found by RUNNER_TRACKING_ID as GitHub's runner finds it. Two batches of a job's log written at once can no longer reach for the same seq and lose one. The Actions guide and the rate limits page say so. | 165 | |
| 166 | test("each line's time comes off the front, as GitHub's logs stamp it, and colours stay beside the plain text", () => { | |
| 167 | const stamped = [ | |
| 168 | "2026-10-12T09:41:07.1234567Z ##[group]Run cargo build", | |
| 169 | "2026-10-12T09:41:07.2000000Z \u001b[36;1mcargo build\u001b[0m", | |
| 170 | "2026-10-12T09:41:07.3000000Z ##[endgroup]", | |
| 171 | "2026-10-12T09:41:09.0000000Z \u001b[1m\u001b[32m Compiling\u001b[0m g1t v0.2.0", | |
| 172 | "2026-10-12T09:41:10.0000000Z ##[error]Process completed with exit code 1.", | |
| 173 | "a line from before lines were stamped", | |
| 174 | "", | |
| 175 | ].join("\n"); | |
| 176 | const parsed = blocks(stamped); | |
| 177 | assert.equal(parsed.length, 4, "a log's last newline adds no line"); | |
| 178 | assert.deepEqual(parsed[0], { | |
| 179 | kind: "group", | |
| 180 | title: "Run cargo build", | |
| 181 | at: "2026-10-12T09:41:07.1234567Z", | |
| 182 | lines: [{ line: { kind: "text", text: "cargo build", at: "2026-10-12T09:41:07.2000000Z", ansi: "\u001b[36;1mcargo build\u001b[0m" }, number: 1 }], | |
| 183 | }); | |
| 184 | assert.deepEqual(parsed[1], { | |
| 185 | kind: "line", | |
| 186 | line: { kind: "text", text: " Compiling g1t v0.2.0", at: "2026-10-12T09:41:09.0000000Z", ansi: "\u001b[1m\u001b[32m Compiling\u001b[0m g1t v0.2.0" }, | |
| 187 | number: 2, | |
| 188 | }); | |
| 189 | assert.deepEqual(parsed[2], { kind: "line", line: { kind: "error", text: "Process completed with exit code 1.", at: "2026-10-12T09:41:10.0000000Z" }, number: 3 }); | |
| 190 | assert.deepEqual(parsed[3], { kind: "line", line: { kind: "text", text: "a line from before lines were stamped" }, number: 4 }); | |
| 191 | // Search reads the plain text, never the time or the codes. | |
| 192 | assert.deepEqual( | |
| 193 | searchLog(stamped, "compiling g1t").map((found) => found.number), | |
| 194 | [2], | |
| 195 | ); | |
| 196 | assert.deepEqual(searchLog(stamped, "2026-10-12"), []); | |
| 197 | assert.deepEqual(searchLog(stamped, "32m"), []); | |
| 198 | assert.deepEqual(splitStamp("2026-10-12T09:41:07Z text"), { at: "2026-10-12T09:41:07Z", rest: "text" }); | |
| 199 | assert.deepEqual(splitStamp("2026-10-12 not a stamp"), { rest: "2026-10-12 not a stamp" }); | |
| 200 | assert.deepEqual(classify("##[warning]plain"), { kind: "warning", text: "plain" }); | |
| 201 | assert.equal(lastStamp(stamped), "2026-10-12T09:41:10.0000000Z"); | |
| 202 | assert.equal(lastStamp("no stamps\n"), undefined); | |
| 203 | }); |
This file's history is long; its oldest lines are credited to the oldest commit read.