/** * 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 ` 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", ]); }); 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: "done", fetched: 3 }); expect(lines).toEqual([ "debug: refresh started", "info: Fetched the files of 1 of 2 collections", "debug: refresh failed: HTTP 503", "debug: fetchMLData done", ]); }); });