quak/test/cli/log.test.ts

/**
 * 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: "",
        });
    });

    // No album holds file 999, so fixing it fails. The refresh's progress and
    // the list of failed files are 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 () => {
        const fix = ["helper", "fix-missing-thumbnails", "--file", "999"];
        expect(await quak("-q", ...fix)).toEqual({
            code: 1,
            stdout: "",
            stderr: `quak: 1 file(s) failed; see the "Failed files:" list, or the JSON with --json\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",
        ]);
    });
});