-v raises the CLI's log level per repeat; -q prints only fatal errors (closes #212)

Every line quak prints on stderr now goes through one log, in src/cli-log.ts, at one of six levels. The default, info, prints what quak printed before. -v adds each retry and the start and end of each refresh and ML data fetch; -vv adds each request with its result. -q prints only fatal lines, and is refused with -v; both are program options. Every non-zero exit logs one fatal line, so a run that exits 1 because files failed says how many and where to look. Every line reporting a failure is at error. --json changes stdout only, so backup and --json runs log their progress on stderr. withRetry and ApiClient report retries and requests through new callbacks.

Model: opus-5-5

test/cli/log.test.ts

@@ -0,0 +1,357 @@
+/**
+ * Tests for the CLI's log levels, set with `-v`/`--verbose` and `-q`/`--quiet`
+ * (`src/cli-log.ts`, issue #212).
+ *
+ * Every line quak prints on stderr is a log line at one of six levels, from
+ * the quietest: fatal, error, warning, info, debug, trace. A run prints the
+ * lines at its own level and at every quieter one. The level is info unless
+ * asked otherwise: `-v` raises it to debug, `-vv` to trace, and more repeats
+ * stay at trace. `-q` lowers it to fatal, so a run prints only the line a
+ * command prints as it fails with a non-zero exit code. stdout holds the
+ * command's output at every level.
+ *
+ * Most tests run `bin/quak.ts`, as the smoke test does, against an account of
+ * one album holding one photo: the saved session is in a temporary directory,
+ * and `fetch` is a fake of the Ente server that serves the album and the photo
+ * encrypted as Ente's clients encrypt them. Each run has a cache directory of
+ * its own, so its refresh fetches the album's files, as on a first run.
+ */
+
+import { mkdtempSync, rmSync } from "node:fs";
+import { tmpdir } from "node:os";
+import { join } from "node:path";
+import sodium from "libsodium-wrappers-sumo";
+import {
+    afterAll,
+    afterEach,
+    beforeAll,
+    describe,
+    expect,
+    it,
+    vi,
+} from "vitest";
+
+import { ApiClient } from "../../src/api/client.js";
+import { saveSession } from "../../src/cli-commands.js";
+import { logRefresh, logRequests, type Log } from "../../src/cli-log.js";
+import { init, toBase64 } from "../../src/crypto/index.js";
+import { encryptSecretbox, encryptStreamBlob } from "../ente-server.js";
+
+// `bin/quak.ts` reads the saved session from the data directory env-paths
+// gives it, which here is a temporary directory made before the first run.
+const paths = vi.hoisted(() => ({ data: "" }));
+vi.mock("env-paths", () => ({ default: () => paths }));
+
+const USER_ID = 42;
+const root = mkdtempSync(join(tmpdir(), "quak-log-test-"));
+const argv = process.argv;
+
+class ExitCalled extends Error {}
+
+// Run `quak <args>` to its exit, with a cache of its own, and return its exit
+// code and what it wrote on stdout and on stderr, which are kept off the
+// terminal. `process.exit` is stubbed to throw, so nothing runs after it, as
+// nothing does after a real exit.
+const quak = async (
+    ...args: string[]
+): Promise<{ code: number; stdout: string; stderr: string }> => {
+    let stdout = "";
+    let stderr = "";
+    let code = NaN;
+    vi.spyOn(process.stdout, "write").mockImplementation((text) => {
+        stdout += String(text);
+        return true;
+    });
+    vi.spyOn(process.stderr, "write").mockImplementation((text) => {
+        stderr += String(text);
+        return true;
+    });
+    vi.spyOn(process, "exit").mockImplementation((exitCode) => {
+        code = Number(exitCode ?? 0);
+        throw new ExitCalled();
+    });
+    const cache = mkdtempSync(join(root, "cache-"));
+    process.argv = ["node", "quak", "--cache-dir", cache, ...args];
+    vi.resetModules();
+    await expect(import("../../bin/quak.js")).rejects.toBeInstanceOf(
+        ExitCalled,
+    );
+    return { code, stdout, stderr };
+};
+
+// Album 1, "Trips", of user 42, holding photo 100, "beach.jpg". The album's
+// key is encrypted with the account's master key, the photo's key with the
+// album's, and the photo's metadata with its own key. Only the session and
+// these two records are needed: the tests never log in.
+beforeAll(async () => {
+    await init();
+    await sodium.ready;
+    const masterKey = sodium.crypto_secretbox_keygen();
+    const keyPair = sodium.crypto_box_keypair();
+    paths.data = join(root, "session");
+    saveSession(paths.data, {
+        email: "log@example.com",
+        userID: USER_ID,
+        token: "token",
+        masterKey: toBase64(masterKey),
+        secretKey: toBase64(keyPair.privateKey),
+        publicKey: toBase64(keyPair.publicKey),
+    });
+
+    const albumKey = sodium.crypto_secretbox_keygen();
+    const albumKeyBox = encryptSecretbox(albumKey, masterKey);
+    const name = encryptSecretbox(new TextEncoder().encode("Trips"), albumKey);
+    const album = {
+        id: 1,
+        owner: { id: USER_ID },
+        encryptedKey: toBase64(albumKeyBox.ciphertext),
+        keyDecryptionNonce: toBase64(albumKeyBox.nonce),
+        encryptedName: toBase64(name.ciphertext),
+        nameDecryptionNonce: toBase64(name.nonce),
+        type: "album",
+        updationTime: 1,
+    };
+    const photoKey = sodium.crypto_secretstream_xchacha20poly1305_keygen();
+    const photoKeyBox = encryptSecretbox(photoKey, albumKey);
+    const metadata = encryptStreamBlob(
+        new TextEncoder().encode(
+            JSON.stringify({
+                title: "beach.jpg",
+                fileType: 0,
+                creationTime: 1000,
+                modificationTime: 1000,
+            }),
+        ),
+        photoKey,
+    );
+    const photo = {
+        id: 100,
+        collectionID: 1,
+        ownerID: USER_ID,
+        encryptedKey: toBase64(photoKeyBox.ciphertext),
+        keyDecryptionNonce: toBase64(photoKeyBox.nonce),
+        metadata: {
+            encryptedData: toBase64(metadata.ciphertext),
+            decryptionHeader: toBase64(metadata.header),
+        },
+        // These tests fetch no original and no thumbnail.
+        file: { decryptionHeader: "" },
+        thumbnail: { decryptionHeader: "" },
+        updationTime: 1,
+    };
+
+    const json = (body: unknown): Response =>
+        new Response(JSON.stringify(body), {
+            headers: { "content-type": "application/json" },
+        });
+    vi.stubGlobal("fetch", async (input: string) => {
+        const { pathname } = new URL(input);
+        if (pathname === "/collections/v2") {
+            return json({ collections: [album] });
+        }
+        if (pathname === "/collections/v2/diff") {
+            return json({ diff: [photo], hasMore: false });
+        }
+        return new Response("not found", { status: 404 });
+    });
+});
+
+afterEach(() => {
+    process.argv = argv;
+    vi.restoreAllMocks();
+});
+
+afterAll(() => {
+    vi.unstubAllGlobals();
+    rmSync(root, { recursive: true, force: true });
+});
+
+// What `quak files` writes on stdout at every level.
+const FILES = "100\timage\tbeach.jpg\n";
+
+// What it writes on stderr at each level. Info is the refresh's progress, one
+// line for the one album whose files it fetched. Debug adds the start and end
+// of the refresh, and trace each request with the status of its answer.
+const INFO = "Fetched the files of 1 of 1 collections\n";
+const DEBUG = "Refresh started\n" + INFO + "Refresh done\n";
+const TRACE =
+    "Refresh started\n" +
+    "GET https://api.ente.io/collections/v2?sinceTime=0: HTTP 200\n" +
+    "GET https://api.ente.io/collections/v2/diff?collectionID=1&sinceTime=0: HTTP 200\n" +
+    INFO +
+    "Refresh done\n";
+
+describe("the log level", () => {
+    it("is info by default", async () => {
+        expect(await quak("files")).toEqual({
+            code: 0,
+            stdout: FILES,
+            stderr: INFO,
+        });
+    });
+
+    it("is debug with -v", async () => {
+        expect(await quak("-v", "files")).toEqual({
+            code: 0,
+            stdout: FILES,
+            stderr: DEBUG,
+        });
+    });
+
+    it("is trace with -vv", async () => {
+        expect(await quak("-vv", "files")).toEqual({
+            code: 0,
+            stdout: FILES,
+            stderr: TRACE,
+        });
+    });
+
+    it("stays at trace with -vvv", async () => {
+        expect((await quak("-vvv", "files")).stderr).toBe(TRACE);
+    });
+
+    it("counts --verbose --verbose as -vv", async () => {
+        expect((await quak("--verbose", "--verbose", "files")).stderr).toBe(
+            TRACE,
+        );
+    });
+
+    // Both are options of the program, taken before or after the command's
+    // name, as `--cache-dir` is.
+    it("is set by an option after the command's name too", async () => {
+        expect((await quak("files", "-v")).stderr).toBe(DEBUG);
+        expect((await quak("files", "--json", "-vv")).stderr).toBe(TRACE);
+        expect((await quak("files", "-q")).stderr).toBe("");
+    });
+});
+
+describe("-q", () => {
+    it("prints nothing on stderr when the command works", async () => {
+        expect(await quak("-q", "files")).toEqual({
+            code: 0,
+            stdout: FILES,
+            stderr: "",
+        });
+    });
+
+    // The refresh's progress is left out; the line saying why the command
+    // failed is the fatal one, and it is printed.
+    it("prints only the line a failing command exits with", async () => {
+        expect(await quak("-q", "files", "9")).toEqual({
+            code: 1,
+            stdout: "",
+            stderr: "Collection 9 not found\n",
+        });
+    });
+
+    it("is refused with -v, in one line, before the command runs", async () => {
+        for (const args of [
+            ["-q", "-v", "files"],
+            ["files", "--verbose", "--quiet"],
+        ]) {
+            const { code, stdout, stderr } = await quak(...args);
+            expect(code).toBe(1);
+            expect(stdout).toBe("");
+            expect(stderr).toBe(
+                "error: option '-q, --quiet' cannot be used with option '-v, --verbose'\n",
+            );
+        }
+    });
+});
+
+// `--help` lists both options, and each command's help lists them too, since
+// each command takes them.
+describe("--help", () => {
+    it("lists -v and -q for the program and for each command", async () => {
+        for (const args of [["--help"], ["files", "--help"]]) {
+            const { stdout } = await quak(...args);
+            expect(stdout).toContain("-v, --verbose");
+            expect(stdout).toContain("-q, --quiet");
+        }
+    });
+});
+
+// The library writes no lines itself. Its layers report through callbacks,
+// and the CLI logs what they report.
+describe("what the library reports", () => {
+    const collect = (): { log: Log; lines: string[] } => {
+        const lines: string[] = [];
+        return { log: (level, line) => lines.push(`${level}: ${line}`), lines };
+    };
+
+    // A request answered 503 and retried: each attempt is a request, logged
+    // at trace with its status, and the retry is logged at debug with how
+    // long it waits and why.
+    it("logs each request at trace and each retry at debug", async () => {
+        const { log, lines } = collect();
+        const answers = [
+            new Response("unavailable", { status: 503 }),
+            new Response("{}", {
+                headers: { "content-type": "application/json" },
+            }),
+        ];
+        const client = new ApiClient({
+            ...logRequests(log, {
+                sleep: async () => {},
+                random: () => 0.5,
+            }),
+            fetch: async () => answers.shift()!,
+        });
+
+        await client.getJSON("/collections/v2", { sinceTime: 0 });
+
+        const url = "https://api.ente.io/collections/v2?sinceTime=0";
+        expect(lines).toEqual([
+            `trace: GET ${url}: HTTP 503`,
+            "debug: Attempt 1 failed, retrying in 250 ms: HTTP 503",
+            `trace: GET ${url}: HTTP 200`,
+        ]);
+    });
+
+    it("logs a request that failed with its error", async () => {
+        const { log, lines } = collect();
+        const client = new ApiClient({
+            ...logRequests(log, { attempts: 1 }),
+            fetch: async () => {
+                throw new TypeError("fetch failed", {
+                    cause: new Error("connect ECONNREFUSED 1.2.3.4:443"),
+                });
+            },
+        });
+
+        await expect(client.getJSON("/collections/v2")).rejects.toThrow();
+
+        expect(lines).toEqual([
+            "trace: GET https://api.ente.io/collections/v2: fetch failed: connect ECONNREFUSED 1.2.3.4:443",
+        ]);
+    });
+
+    // Each operation is named in plain words, as the README names it.
+    it("logs a refresh's progress at info, and its start and end at debug", () => {
+        const { log, lines } = collect();
+        const onProgress = logRefresh(log);
+
+        onProgress({ operation: "refresh", status: "started" });
+        onProgress({
+            operation: "refresh",
+            status: "progress",
+            fetched: 1,
+            total: 2,
+        });
+        onProgress({
+            operation: "refresh",
+            status: "failed",
+            error: "HTTP 503",
+        });
+        onProgress({ operation: "fetchMLData", status: "started" });
+        onProgress({ operation: "fetchMLData", status: "done", fetched: 3 });
+
+        expect(lines).toEqual([
+            "debug: Refresh started",
+            "info: Fetched the files of 1 of 2 collections",
+            "debug: Refresh failed: HTTP 503",
+            "debug: ML data fetch started",
+            "debug: ML data fetch done",
+        ]);
+    });
+});