diff --git a/README.md b/README.md index d7b0b85..eb0726a 100644 --- a/README.md +++ b/README.md @@ -378,6 +378,8 @@ quak/ thumbnails.ts detect + regenerate missing thumbnails client.ts high-level Client class assembled from the above cli-commands.ts the CLI's commands as functions returning exit codes + cli-log.ts the CLI's log level, and the one function the + commands write stderr lines through cli-output.ts how the CLI prints a file's title and time cli-read.ts fresh reads for the CLI's read commands cli-run.ts run a command, print its error, exit with its code @@ -456,6 +458,12 @@ A custom API endpoint is configurable for self-hosted servers via the constructor option `apiOrigin`. When set, file downloads route through `/files/download/` instead of the dedicated CDN host. +The constructor option `onRequest` is called once for each request sent, a +retried request once for each attempt, with its method, its URL and the status +of the answer or the error the request failed with. The URL of a presigned +upload is given without its query, which holds the upload's signature. The CLI +logs each request with `-vv` (see "CLI surface"). + Required request headers on every authenticated call: - `X-Auth-Token`: the decrypted auth token from login. @@ -532,7 +540,9 @@ each wait is drawn at random below its ceiling. Every other command uses the defaults. A library user gets the same budget by passing `UNATTENDED_RETRY_OPTIONS` as `ApiClientOptions.retry`. `sleep` and `random` are injectable through the same option, which is how the test suite exercises the -whole policy without waiting. +whole policy without waiting. `onRetry`, given there too, is called before each +wait with the error the attempt failed with, the attempt's number and the wait; +the CLI logs it with `-v` (see "CLI surface"). Two deadlines, renewed for each attempt: @@ -646,6 +656,7 @@ thumbnails), for the user to delete if they want it gone. ``` quak [--cache-dir ] global: local metadata/content cache location +quak [-v | -vv | -q] global: log more on stderr, or only fatal errors quak login interactive or QUAK_EMAIL/QUAK_PASSWORD quak whoami print logged-in account as JSON quak logout end the session, delete it @@ -669,16 +680,46 @@ request, and neither fetches any collection's files nor changes the cache. The others wait for a refresh. With an empty cache, as on a first run, that refresh fetches the files of every collection, one collection after another, and stores nothing until it has them all, which on a large account takes a while. Meanwhile -the command prints a line on stderr for each collection whose files it has -fetched, such as `Fetched the files of 3 of 120 collections`; with `--json`, -`files` and the two helpers print no such line. stdout holds only the command's -output. If that round-trip fails, the command prints the error on one line and -exits 1, or 3 when the server no longer accepts the saved session (see "Session -handling"). An album or file quak cannot decrypt does not fail it; the command -answers from what did decrypt (see "Default reads vs. fresh reads"). +the command logs a line on stderr for each collection whose files it has +fetched, such as `Fetched the files of 3 of 120 collections`, with `--json` too; +`backup` does the same while the refresh it starts with runs. stdout holds only +the command's output. If that round-trip fails, the command prints the error on +one line and exits 1, or 3 when the server no longer accepts the saved session +(see "Session handling"). An album or file quak cannot decrypt does not fail it; +the command answers from what did decrypt (see "Default reads vs. fresh reads"). `--cache-dir` overrides where the cache lives; without it each account gets its own directory under the per-user cache path. +`-v` (`--verbose`) and `-q` (`--quiet`) set how much quak logs on stderr. Like +`--cache-dir`, they go before or after any command's name. Every line quak +prints on stderr is a log line at one of six levels, from the quietest: fatal, +error, warning, info, debug and trace. A run prints the lines at its own level +and at every quieter one. stdout holds only the command's output, at every +level, and `--json` changes stdout only, so a run with `--json` logs the same +lines on stderr as one without it. + +- With neither option the level is info: the lines quak prints as it works, such + as a refresh's progress, the files a backup fetches, its summary and the files + that failed. +- `-v` raises the level to debug, which adds each retry of a request, with why + the attempt failed and how long quak waits before the next, and the start and + end of each refresh and each ML data fetch, with the error of one that failed. +- `-vv` raises it to trace, which adds each request quak sends: its method, its + URL and the status of the answer, or the error the request failed with. The + URL of an upload of a thumbnail is logged without its query, which holds the + upload's signature. More repeats stay at trace, and `--verbose --verbose` is + `-vv`. +- `-q` lowers it to fatal: quak prints only the line a command prints as it + fails and exits non-zero, such as `quak: `, `Not logged in`, an + invalid ID or a collection that does not exist. A file that fails inside + `backup` is not fatal: it is in `failures.json` and in the exit code, and + nothing is printed for it. The prompts of `login` are not log lines, and `-q` + leaves them as they are. + +`-q` with `-v` is refused with one line, +`error: option '-q, --quiet' cannot be used with option '-v, --verbose'`, and +exit status 1. + `files ` lists the files in that collection. `files` with no argument lists every file in the account, collection by collection, each file once: a file in several collections is listed with the first of them, which is @@ -828,8 +869,8 @@ reads vs. fresh reads") goes into `failures.json` with an error that starts `could not be decrypted:` and gives the reason. If a copy of it in another album decrypted, it does not: its original is stored from that copy, and the album where it does not decrypt neither links nor lists it. An album the library could -not decrypt has no name quak can read and no files it can list. A run without -`--json` prints one line for it, +not decrypt has no name quak can read and no files it can list. `quak backup` +prints one line for it on stderr, `FAILED album : could not be decrypted: `, and `--json` and the `BackupResult` list its ID in `undecryptableAlbums`. Such a file in `failures.json`, or such an album, keeps the exit code at 1, run after run, @@ -883,7 +924,7 @@ appears or goes away. A collection whose directory or JSON cannot be written, such as one whose directory name is taken by a file you put in `collections/`, does not stop the -run. A run without `--json` prints `FAILED album : ` for it, +run. `quak backup` prints `FAILED album : ` for it on stderr, `--json` and the `BackupResult` list its ID in `failedAlbums`, and the exit code is 1. The other collections and `failures.json` are still written. diff --git a/TODO.md b/TODO.md index 47a8bc9..d97ae62 100644 --- a/TODO.md +++ b/TODO.md @@ -17,16 +17,27 @@ pre-1.0 # Next Step -No bug is open. One change sneak asked for is open: -https://git.eeqj.de/sneak/quak/issues/212. The check of quak against a live Ente -account, https://git.eeqj.de/sneak/quak/issues/187, needs an account only sneak -has, so it waits on him. +No bug is open, and no change sneak asked for is open. The check of quak against +a live Ente account, https://git.eeqj.de/sneak/quak/issues/187, needs an account +only sneak has, so it waits on him. Tagging and releases are decided by sneak alone, and happen only when he declares one. # Completed Steps +- 2026-10-18: `-v`/`--verbose` raises the CLI's log level once for each repeat, + and `-q`/`--quiet` prints only fatal errors + (https://git.eeqj.de/sneak/quak/issues/212). The levels are fatal, error, + warning, info, debug and trace; the default is info, everything quak printed + on stderr before, `-v` gives debug and `-vv` trace. `src/cli-log.ts` holds the + level and the log the commands write stderr lines through. Debug adds each + retry, which `withRetry` reports through the new `onRetry`, and the start and + end of each refresh and ML data fetch; trace adds each request, which + `ApiClient` reports through the new `onRequest`. `--json` no longer keeps the + progress lines off stderr, so `backup` and `--json` runs log a refresh's + progress too. + - 2026-10-18: `quak files` takes the collection ID as an optional argument instead of the `--collection` option, which is gone (https://git.eeqj.de/sneak/quak/issues/211). With no argument it lists every diff --git a/bin/quak.ts b/bin/quak.ts index 9c31fb5..be3cd53 100644 --- a/bin/quak.ts +++ b/bin/quak.ts @@ -2,8 +2,9 @@ import { stdout, stderr } from "node:process"; import { input, password } from "@inquirer/prompts"; -import { Command } from "commander"; +import { Command, Option } from "commander"; import envPaths from "env-paths"; +import { logLevel, logRequests, stderrLog, type Log } from "../src/cli-log.js"; import { init } from "../src/crypto/index.js"; import { type CliContext, @@ -29,6 +30,9 @@ const paths = envPaths("quak", { suffix: "" }); const program = new Command(); +// Program options, so they are taken before or after any command's name. +// `-v` counts its repeats, the way commander's documentation counts a repeated +// option. program .name("quak") .description("CLI for the Ente end-to-end encrypted photo service") @@ -37,21 +41,46 @@ program "--cache-dir ", "Directory for the local metadata/content cache " + "(default: the per-user cache directory)", - ); + ) + .option( + "-v, --verbose", + "Log more on stderr: debug lines with -v, trace lines too with -vv", + (_value: string, previous: number) => previous + 1, + 0, + ) + .addOption( + new Option( + "-q, --quiet", + "Print nothing on stderr but the error a failing command exits with", + ).conflicts("verbose"), + ) + .configureHelp({ showGlobalOptions: true }); + +interface ProgramOptions { + cacheDir?: string; + verbose: number; + quiet?: boolean; +} + +// The log for this run, at the level `-v` and `-q` ask for. +const log = (): Log => { + const { verbose, quiet } = program.opts(); + return stderrLog(stderr, logLevel(verbose, quiet ?? false)); +}; const context = (): CliContext => ({ stdout, - stderr, + log: log(), sessionDir: paths.data, - cacheDir: program.opts<{ cacheDir?: string }>().cacheDir, - loadSession, - login: (opts) => Client.login(opts), + cacheDir: program.opts().cacheDir, + loadSession: (path) => loadSession(path, logRequests(log())), + login: (opts) => Client.login({ ...opts, apiOptions: logRequests(log()) }), prompt: (message) => input({ message }), promptSecret: (message) => password({ message, mask: true }), }); const run = (command: Promise): Promise => - runCommand(command, stdout, stderr, (code) => process.exit(code)); + runCommand(command, stdout, stderr, log(), (code) => process.exit(code)); program .command("login") @@ -143,7 +172,10 @@ program { ...context(), loadSession: (path) => - loadSession(path, { retry: UNATTENDED_RETRY_OPTIONS }), + loadSession( + path, + logRequests(log(), UNATTENDED_RETRY_OPTIONS), + ), }, dir, opts, diff --git a/src/api/client.ts b/src/api/client.ts index 316f9cc..483090e 100644 --- a/src/api/client.ts +++ b/src/api/client.ts @@ -36,6 +36,15 @@ export interface ApiClientOptions { retry?: RetryOptions; requestTimeoutMs?: number; downloadTimeoutMs?: number; + // Called once for each request sent, with the status of its response or + // the error it failed with, for a caller that logs requests. A request + // that is retried is reported once for each attempt. + onRequest?: (request: { + method: string; + url: string; + status?: number; + error?: unknown; + }) => void; } export interface StreamOptions { @@ -159,6 +168,7 @@ export class ApiClient { private readonly retry: ResolvedRetryOptions; private readonly requestTimeoutMs: number; private readonly downloadTimeoutMs: number; + private readonly onRequest: NonNullable; private token: string | undefined; constructor(opts?: ApiClientOptions) { @@ -180,6 +190,7 @@ export class ApiClient { opts?.requestTimeoutMs ?? DEFAULT_REQUEST_TIMEOUT_MS; this.downloadTimeoutMs = opts?.downloadTimeoutMs ?? DEFAULT_DOWNLOAD_TIMEOUT_MS; + this.onRequest = opts?.onRequest ?? (() => {}); this.token = opts?.authToken; } @@ -214,6 +225,33 @@ export class ApiClient { return h; } + // Send one request and report it to `onRequest`, with the status of its + // response or the error it failed with. `reportedURL` is the URL given to + // `onRequest`, when that must not be the one sent. + private async send( + url: string, + init: RequestInit & { method: string }, + reportedURL = url, + ): Promise { + let resp: Response; + try { + resp = await this._fetch(url, init); + } catch (err) { + this.onRequest({ + method: init.method, + url: reportedURL, + error: err, + }); + throw err; + } + this.onRequest({ + method: init.method, + url: reportedURL, + status: resp.status, + }); + return resp; + } + private async throwIfError(resp: Response): Promise { if (resp.ok) return; const requestID = resp.headers.get("x-request-id") ?? undefined; @@ -257,7 +295,7 @@ export class ApiClient { const url = buildURL(this.apiOrigin, path, query); // A GET changes nothing, so it is retried under the full policy. return withRetry(async () => { - const resp = await this._fetch(url, { + const resp = await this.send(url, { method: "GET", headers: this.headers(), signal: AbortSignal.timeout(this.requestTimeoutMs), @@ -280,7 +318,7 @@ export class ApiClient { // 3xx status, which is not retried. return withRetry( async () => { - const resp = await this._fetch(url, { + const resp = await this.send(url, { method: "POST", headers: this.headers({ "Content-Type": "application/json", @@ -321,16 +359,23 @@ export class ApiClient { // object at one key in one request, so replaying it either overwrites // the same bytes or lands them for the first time. There is no partial // state to protect, hence the full policy rather than the POST rule. + // It is reported without its query, which holds the upload's + // signature: a log keeps what it is given. + const { origin, pathname } = new URL(presignedURL); await withRetry(async () => { - const resp = await this._fetch(presignedURL, { - method: "PUT", - headers: { - "Content-Type": "application/octet-stream", - "Content-Length": String(data.length), + const resp = await this.send( + presignedURL, + { + method: "PUT", + headers: { + "Content-Type": "application/octet-stream", + "Content-Length": String(data.length), + }, + body: data, + signal: AbortSignal.timeout(this.requestTimeoutMs), }, - body: data, - signal: AbortSignal.timeout(this.requestTimeoutMs), - }); + origin + pathname, + ); if (!resp.ok) { // An ApiError, not a bare Error: without the status on the // error the upload path cannot be classified at all, and a @@ -348,7 +393,7 @@ export class ApiClient { // Same replay and redirect rules as `postJSON`, for the same reasons. return withRetry( async () => { - const resp = await this._fetch(url, { + const resp = await this.send(url, { method: "PUT", headers: this.headers({ "Content-Type": "application/json", @@ -394,7 +439,7 @@ export class ApiClient { // headers, when no bytes have arrived either. const deadline = idleDeadline(this.downloadTimeoutMs); try { - const resp = await this._fetch(url, { + const resp = await this.send(url, { method: "GET", headers: this.headers(), signal: deadline.signal, diff --git a/src/cli-commands.ts b/src/cli-commands.ts index 119912a..4af92a6 100644 --- a/src/cli-commands.ts +++ b/src/cli-commands.ts @@ -4,7 +4,9 @@ // code; a thrown error is left to the caller. Nothing here calls // `process.exit`: `bin/quak.ts` wires these to the command line, and `run` in // `cli-run.ts` prints a thrown error as one line and exits once output has -// drained. Output must stay byte-identical (see `cli-output.ts`). +// drained. Output must stay byte-identical (see `cli-output.ts`). Each line on +// stderr goes through `ctx.log` at its level (see `cli-log.ts`); a line a +// command prints as it fails with a non-zero exit code is fatal. import { copyFileSync, @@ -33,6 +35,7 @@ import { originalName, thumbnailName, } from "./cli-output.js"; +import { type Log, logRefresh } from "./cli-log.js"; import { freshCollections, freshFiles, freshFile } from "./cli-read.js"; import { withExtension } from "./filename.js"; import { runMetadataBackup } from "./metadata-backup.js"; @@ -40,7 +43,8 @@ import { listMissingThumbnails, fixMissingThumbnails } from "./thumbnails.js"; export interface CliContext { stdout: { write(text: string): unknown }; - stderr: { write(text: string): unknown }; + // Writes a line on stderr at a log level, if the run's level prints it. + log: Log; // Directory holding `session.json`. sessionDir: string; // The `--cache-dir` global, or undefined to let the library pick its @@ -82,16 +86,16 @@ const requireSession = (ctx: CliContext): Client | undefined => { try { client = ctx.loadSession(sessionPath(ctx)); } catch (err) { - ctx.stderr.write( - `${err instanceof Error ? err.message : err}\n` + - `Run "quak logout" and then "quak login" to replace it.\n`, + ctx.log("fatal", err instanceof Error ? err.message : String(err)); + ctx.log( + "fatal", + `Run "quak logout" and then "quak login" to replace it.`, ); return undefined; } if (!client) { - ctx.stderr.write( - `Not logged in. Run "quak login" first.\nSession file: ${sessionPath(ctx)}\n`, - ); + ctx.log("fatal", `Not logged in. Run "quak login" first.`); + ctx.log("fatal", `Session file: ${sessionPath(ctx)}`); return undefined; } return client; @@ -107,7 +111,7 @@ const parseID = ( ): number | undefined => { const id = Number(text); if (/^[0-9]+$/.test(text) && Number.isSafeInteger(id)) return id; - ctx.stderr.write(`Invalid ${kind} ID: ${text}\n`); + ctx.log("fatal", `Invalid ${kind} ID: ${text}`); return undefined; }; @@ -128,13 +132,8 @@ const readLibraryClient = (client: Client): LibraryClient => ({ // downloading the whole account — and no refresh starts as it opens or on a // timer: each command asks for the one it needs, and `collections` needs none // (issue #210). While a refresh runs, each collection whose files it has -// fetched is counted on stderr, unless `json` is set, so a large account shows -// progress rather than nothing. -const openReadLibrary = ( - ctx: CliContext, - client: Client, - opts: { json?: boolean } = {}, -): Promise => +// fetched is logged, so a large account shows progress rather than nothing. +const openReadLibrary = (ctx: CliContext, client: Client): Promise => Library.open({ client: readLibraryClient(client), cacheDirectory: ctx.cacheDir, @@ -142,12 +141,7 @@ const openReadLibrary = ( refreshIntervalSeconds: Infinity, precacheThumbnails: false, precacheOriginals: false, - onProgress: (event) => { - if (opts.json || event.status !== "progress") return; - ctx.stderr.write( - `Fetched the files of ${event.fetched} of ${event.total} collections\n`, - ); - }, + onProgress: logRefresh(ctx.log), }); export const loginCommand = async (ctx: CliContext): Promise => { @@ -156,7 +150,7 @@ export const loginCommand = async (ctx: CliContext): Promise => { const password = process.env.QUAK_PASSWORD ?? (await ctx.promptSecret("Password")); - ctx.stderr.write("Authenticating...\n"); + ctx.log("info", "Authenticating..."); try { const client = await ctx.login({ email, @@ -167,11 +161,12 @@ export const loginCommand = async (ctx: CliContext): Promise => { saveSession(ctx.sessionDir, client.toJSON()); const info = client.whoami(); - ctx.stderr.write(`Logged in as ${info.email} (user ${info.userID})\n`); - ctx.stderr.write(`Session saved to ${sessionPath(ctx)}\n`); + ctx.log("info", `Logged in as ${info.email} (user ${info.userID})`); + ctx.log("info", `Session saved to ${sessionPath(ctx)}`); } catch (err) { - ctx.stderr.write( - `Login failed: ${err instanceof Error ? err.message : err}\n`, + ctx.log( + "fatal", + `Login failed: ${err instanceof Error ? err.message : err}`, ); return 1; } @@ -193,7 +188,7 @@ export const whoamiCommand = async (ctx: CliContext): Promise => { export const logoutCommand = async (ctx: CliContext): Promise => { const path = sessionPath(ctx); if (!existsSync(path)) { - ctx.stderr.write("No session found.\n"); + ctx.log("info", "No session found."); return 0; } await init(); @@ -211,16 +206,15 @@ export const logoutCommand = async (ctx: CliContext): Promise => { } unlinkSync(path); if (failure === undefined) { - ctx.stderr.write("Session ended on the server.\n"); + ctx.log("info", "Session ended on the server."); } else { - ctx.stderr.write( - `Could not end the session on the server: ${failure}\n`, - ); + ctx.log("fatal", `Could not end the session on the server: ${failure}`); } - ctx.stderr.write("Session deleted.\n"); + ctx.log("info", "Session deleted."); if (cacheDir !== undefined) { - ctx.stderr.write( - `Cache directory ${cacheDir} still holds decrypted data; delete it to remove that data.\n`, + ctx.log( + "warning", + `Cache directory ${cacheDir} still holds decrypted data; delete it to remove that data.`, ); } return failure === undefined ? 0 : 1; @@ -285,7 +279,7 @@ export const filesCommand = async ( : parseID(ctx, "collection", collectionIDStr); if (collectionIDStr !== undefined && collectionID === undefined) return 1; - const lib = await openReadLibrary(ctx, client, opts); + const lib = await openReadLibrary(ctx, client); try { // Force a server round-trip and list in enumeration order (issue #36 // amendment, issue #52). Each file prints from its own decrypted @@ -294,7 +288,7 @@ export const filesCommand = async ( // newest-first order. const files = await freshFiles(lib, collectionID); if (!files) { - ctx.stderr.write(`Collection ${collectionID} not found\n`); + ctx.log("fatal", `Collection ${collectionID} not found`); return 1; } @@ -330,7 +324,7 @@ export const getCommand = async ( // (issue #36 amendment, issue #52). const resolved = await freshFile(lib, fileID); if (!resolved) { - ctx.stderr.write(`File ${fileID} not found\n`); + ctx.log("fatal", `File ${fileID} not found`); return 1; } const { photo, file } = resolved; @@ -341,7 +335,7 @@ export const getCommand = async ( if (result.videoPath === undefined) { const outPath = opts.out ?? originalName(file); copyFileSync(result.path, outPath); - ctx.stderr.write(`${result.bytes} bytes -> ${outPath}\n`); + ctx.log("info", `${result.bytes} bytes -> ${outPath}`); return 0; } // A live photo is written as its image and its video, each named after @@ -355,17 +349,16 @@ export const getCommand = async ( ? originalName(file, videoExt) : withExtension(opts.out, videoExt); if (imageOut.toLowerCase() === videoOut.toLowerCase()) { - ctx.stderr.write( - `File ${fileID} is a live photo, and its video would also be written to ${imageOut}\n`, + ctx.log( + "fatal", + `File ${fileID} is a live photo, and its video would also be written to ${imageOut}`, ); return 1; } copyFileSync(result.path, imageOut); copyFileSync(result.videoPath, videoOut); - ctx.stderr.write( - `${result.bytes} bytes -> ${imageOut}\n` + - `${statSync(videoOut).size} bytes -> ${videoOut}\n`, - ); + ctx.log("info", `${result.bytes} bytes -> ${imageOut}`); + ctx.log("info", `${statSync(videoOut).size} bytes -> ${videoOut}`); return 0; } finally { await lib.close(); @@ -389,7 +382,7 @@ export const getThumbCommand = async ( // (issue #36 amendment, issue #52). const resolved = await freshFile(lib, fileID); if (!resolved) { - ctx.stderr.write(`File ${fileID} not found\n`); + ctx.log("fatal", `File ${fileID} not found`); return 1; } const { photo, file } = resolved; @@ -399,7 +392,7 @@ export const getThumbCommand = async ( // used (not the projection title) (issue #52). const outPath = opts.out ?? thumbnailName(file); copyFileSync(result.path, outPath); - ctx.stderr.write(`${result.bytes} bytes -> ${outPath}\n`); + ctx.log("info", `${result.bytes} bytes -> ${outPath}`); return 0; } finally { await lib.close(); @@ -421,7 +414,7 @@ export const backupMetadataCommand = async ( await lib.fresh(); const result = await runMetadataBackup(lib, client, dir, { exif: opts.exif || opts.all, - onProgress: (msg) => ctx.stderr.write(msg + "\n"), + onProgress: (msg) => ctx.log("info", msg), }); return result.filesWithMLDataError > 0 ? 1 : 0; } finally { @@ -438,7 +431,7 @@ export const backupCommand = async ( const client = requireSession(ctx); if (!client) return 3; - ctx.stderr.write("Starting backup...\n"); + ctx.log("info", "Starting backup..."); // The lock is taken before the library opens and starts its refresh, so a // run refused while another backup of `dir` runs sends no request. let lock: BackupLock; @@ -446,7 +439,7 @@ export const backupCommand = async ( lock = await lockBackupDirectory(dir); } catch (err) { if ((err as NodeJS.ErrnoException).code !== "ELOCKED") throw err; - ctx.stderr.write(`quak: ${(err as Error).message}\n`); + ctx.log("fatal", `quak: ${(err as Error).message}`); return 2; } try { @@ -461,35 +454,35 @@ export const backupCommand = async ( refreshIntervalSeconds: Infinity, precacheThumbnails: false, precacheOriginals: false, + onProgress: logRefresh(ctx.log), }); try { const result = await lib.backup({ downloadDirectory: dir, lock, verify: opts.verify, - onProgress: (msg) => { - if (!opts.json) ctx.stderr.write(msg + "\n"); - }, + onProgress: (msg) => ctx.log("info", msg), }); if (opts.json) { ctx.stdout.write(JSON.stringify(result, null, 2) + "\n"); } else { - ctx.stderr.write("\n--- Backup complete ---\n"); - ctx.stderr.write(` Total files: ${result.totalFiles}\n`); - ctx.stderr.write(` Downloaded: ${result.downloaded}\n`); - ctx.stderr.write(` Skipped: ${result.skipped}\n`); + ctx.log("info", "\n--- Backup complete ---"); + ctx.log("info", ` Total files: ${result.totalFiles}`); + ctx.log("info", ` Downloaded: ${result.downloaded}`); + ctx.log("info", ` Skipped: ${result.skipped}`); if (opts.verify) { - ctx.stderr.write(` Verified: ${result.verified}\n`); - ctx.stderr.write(` Mismatched: ${result.mismatched}\n`); - ctx.stderr.write(` Unchecked: ${result.unchecked}\n`); + ctx.log("info", ` Verified: ${result.verified}`); + ctx.log("info", ` Mismatched: ${result.mismatched}`); + ctx.log("info", ` Unchecked: ${result.unchecked}`); } - ctx.stderr.write(` Failed: ${result.failed}\n`); + ctx.log("info", ` Failed: ${result.failed}`); if (result.errors.length > 0) { - ctx.stderr.write("\nFailed files:\n"); + ctx.log("error", "\nFailed files:"); for (const e of result.errors) { - ctx.stderr.write( - ` [${e.collection}] ${e.title} (id ${e.fileID}): ${e.error}\n`, + ctx.log( + "error", + ` [${e.collection}] ${e.title} (id ${e.fileID}): ${e.error}`, ); } } @@ -515,23 +508,24 @@ export const listMissingThumbnailsCommand = async ( await init(); const client = requireSession(ctx); if (!client) return 3; - const lib = await openReadLibrary(ctx, client, opts); + const lib = await openReadLibrary(ctx, client); try { // Refresh first so files added since the cache was written are // checked; a failed refresh throws. await lib.fresh(); - const missing = await listMissingThumbnails(lib, client, (msg) => { - if (!opts.json) ctx.stderr.write(msg + "\n"); - }); + const missing = await listMissingThumbnails(lib, client, (msg) => + ctx.log("info", msg), + ); if (opts.json) { ctx.stdout.write(JSON.stringify(missing, null, 2) + "\n"); } else { if (missing.length === 0) { - ctx.stderr.write("No missing thumbnails found.\n"); + ctx.log("info", "No missing thumbnails found."); } else { - ctx.stderr.write( - `\n${missing.length} file(s) with missing thumbnails:\n`, + ctx.log( + "info", + `\n${missing.length} file(s) with missing thumbnails:`, ); for (const m of missing) { ctx.stdout.write( @@ -560,31 +554,29 @@ export const fixMissingThumbnailsCommand = async ( if (fileID === undefined) return 1; fileIDs.push(fileID); } - const lib = await openReadLibrary(ctx, client, opts); + const lib = await openReadLibrary(ctx, client); try { // Refresh first so files added since the cache was written are found; // a failed refresh throws. await lib.fresh(); if (fileIDs.length === 0) { - ctx.stderr.write("Scanning for missing thumbnails...\n"); - const missing = await listMissingThumbnails(lib, client, (msg) => { - if (!opts.json) ctx.stderr.write(msg + "\n"); - }); + ctx.log("info", "Scanning for missing thumbnails..."); + const missing = await listMissingThumbnails(lib, client, (msg) => + ctx.log("info", msg), + ); fileIDs = missing.map((m) => m.fileID); if (fileIDs.length === 0) { - ctx.stderr.write("No missing thumbnails found.\n"); + ctx.log("info", "No missing thumbnails found."); return 0; } - ctx.stderr.write(`Found ${fileIDs.length} file(s) to fix.\n`); + ctx.log("info", `Found ${fileIDs.length} file(s) to fix.`); } const results = await fixMissingThumbnails( lib, client, fileIDs, - (msg) => { - if (!opts.json) ctx.stderr.write(msg + "\n"); - }, + (msg) => ctx.log("info", msg), ); if (opts.json) { @@ -595,24 +587,20 @@ export const fixMissingThumbnailsCommand = async ( (r) => r.status === "skipped", ).length; const failed = results.filter((r) => r.status === "failed").length; - ctx.stderr.write(`\n--- Done ---\n`); - ctx.stderr.write(` Fixed: ${fixed}\n`); - ctx.stderr.write(` Skipped: ${skipped}\n`); - ctx.stderr.write(` Failed: ${failed}\n`); + ctx.log("info", `\n--- Done ---`); + ctx.log("info", ` Fixed: ${fixed}`); + ctx.log("info", ` Skipped: ${skipped}`); + ctx.log("info", ` Failed: ${failed}`); if (skipped > 0) { - ctx.stderr.write("\nSkipped:\n"); + ctx.log("info", "\nSkipped:"); for (const r of results.filter((r) => r.status === "skipped")) { - ctx.stderr.write( - ` ${r.fileID}\t${r.title}\t${r.reason}\n`, - ); + ctx.log("info", ` ${r.fileID}\t${r.title}\t${r.reason}`); } } if (failed > 0) { - ctx.stderr.write("\nFailed files:\n"); + ctx.log("error", "\nFailed files:"); for (const r of results.filter((r) => r.status === "failed")) { - ctx.stderr.write( - ` ${r.fileID}\t${r.title}\t${r.reason}\n`, - ); + ctx.log("error", ` ${r.fileID}\t${r.title}\t${r.reason}`); } } } diff --git a/src/cli-log.ts b/src/cli-log.ts new file mode 100644 index 0000000..9f13296 --- /dev/null +++ b/src/cli-log.ts @@ -0,0 +1,84 @@ +// The CLI's log level, and the one function the commands write stderr lines +// through. +// +// 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. Its level is info unless +// `-v` or `-q` asks for another (see "CLI surface" in the README). A fatal line +// is the one a command prints when it fails and exits non-zero, so even `-q` +// prints it. stdout carries only a command's output and is not a log. +// +// The library itself writes no lines: its layers report through callbacks, and +// the CLI logs what they report. `logRequests` gives the API client options +// that log each request and each retry, and `logRefresh` the library's +// `onProgress` that logs what a refresh and an ML data fetch report. + +import type { ApiClientOptions } from "./api/client.js"; +import { describeError } from "./errors.js"; +import type { RefreshEvent } from "./library/index.js"; +import type { RetryOptions } from "./retry.js"; + +const LEVELS = ["fatal", "error", "warning", "info", "debug", "trace"] as const; + +export type LogLevel = (typeof LEVELS)[number]; + +// Writes `line` on stderr when the run's level prints lines at `level`. +export type Log = (level: LogLevel, line: string) => void; + +// The level asked for by `-v` given `verbose` times, or by `-q`: info without +// either, debug for `-v`, trace for `-vv` and more, fatal for `-q`. +// `bin/quak.ts` refuses `-q` and `-v` together. +export const logLevel = (verbose: number, quiet: boolean): LogLevel => { + if (quiet) return "fatal"; + if (verbose === 0) return "info"; + return verbose === 1 ? "debug" : "trace"; +}; + +// The log that writes each line at `level` or quieter to `stderr`, ending it +// with a newline. +export const stderrLog = + (stderr: { write(text: string): unknown }, level: LogLevel): Log => + (lineLevel, line) => { + if (LEVELS.indexOf(lineLevel) <= LEVELS.indexOf(level)) { + stderr.write(line + "\n"); + } + }; + +// API client options that log each request at trace, with the status of its +// response or the error it failed with, and each retry at debug, with why and +// how long it waits. `retry` is the retry policy, the default when not given. +export const logRequests = ( + log: Log, + retry?: RetryOptions, +): ApiClientOptions => ({ + retry: { + ...retry, + onRetry: (err, attempt, delayMs) => + log( + "debug", + `Attempt ${attempt} failed, retrying in ${Math.round(delayMs)} ms: ${describeError(err)}`, + ), + }, + onRequest: ({ method, url, status, error }) => + log( + "trace", + `${method} ${url}: ${error === undefined ? `HTTP ${status}` : describeError(error)}`, + ), +}); + +// A library `onProgress` that logs, at info, each collection whose files a +// refresh has fetched, and at debug the start and end of each refresh and ML +// data fetch, with the error of one that failed. +export const logRefresh = + (log: Log) => + (event: RefreshEvent): void => { + if (event.status === "progress") { + log( + "info", + `Fetched the files of ${event.fetched} of ${event.total} collections`, + ); + return; + } + const error = event.error === undefined ? "" : `: ${event.error}`; + log("debug", `${event.operation} ${event.status}${error}`); + }; diff --git a/src/cli-run.ts b/src/cli-run.ts index 50bf822..dbc77b3 100644 --- a/src/cli-run.ts +++ b/src/cli-run.ts @@ -2,21 +2,23 @@ import type { Writable } from "node:stream"; import { ApiError } from "./api/client.js"; +import type { Log } from "./cli-log.js"; import { describeError } from "./errors.js"; // Run a command and exit with its code once stdout/stderr have drained. // Exiting before the drain can truncate piped output, and the library can keep // the event loop alive after a command returns, so a plain return could hang. -// An error the command throws is printed as one `quak: MESSAGE` line, without -// the stack trace, and exits 1. MESSAGE is the error as `describeError` gives -// it, so it carries the reason Node's `fetch` puts on `cause`. A 401 from the -// server means it no longer accepts the saved session: that prints one line -// saying to log in again and exits 3, as a missing or corrupt session file -// does. +// An error the command throws is logged as one fatal `quak: MESSAGE` line, +// without the stack trace, and exits 1. MESSAGE is the error as +// `describeError` gives it, so it carries the reason Node's `fetch` puts on +// `cause`. A 401 from the server means it no longer accepts the saved session: +// that logs one fatal line saying to log in again and exits 3, as a missing or +// corrupt session file does. export const run = async ( command: Promise, stdout: Writable, stderr: Writable, + log: Log, exit: (code: number) => void, ): Promise => { let code: number; @@ -24,12 +26,13 @@ export const run = async ( code = await command; } catch (err) { if (err instanceof ApiError && err.status === 401) { - stderr.write( - `quak: the saved session is no longer valid; run "quak login"\n`, + log( + "fatal", + `quak: the saved session is no longer valid; run "quak login"`, ); code = 3; } else { - stderr.write(`quak: ${describeError(err)}\n`); + log("fatal", `quak: ${describeError(err)}`); code = 1; } } diff --git a/src/retry.ts b/src/retry.ts index c210bf7..ba5dbcc 100644 --- a/src/retry.ts +++ b/src/retry.ts @@ -24,6 +24,9 @@ export interface RetryOptions { sleep?: (ms: number) => Promise; // Injected so the jitter is reproducible under test. random?: () => number; + // Called before each wait with the error that failed attempt number + // `attempt` and how long the wait is, for a caller that logs retries. + onRetry?: (err: unknown, attempt: number, delayMs: number) => void; } export type ResolvedRetryOptions = Required; @@ -35,6 +38,7 @@ export const DEFAULT_RETRY_OPTIONS: ResolvedRetryOptions = { sleep: (ms: number): Promise => new Promise((resolve) => setTimeout(resolve, ms)), random: Math.random, + onRetry: () => {}, }; // For a run nobody is watching, such as `quak backup` from cron. A request that @@ -55,6 +59,7 @@ export const resolveRetryOptions = ( maxDelayMs: opts?.maxDelayMs ?? DEFAULT_RETRY_OPTIONS.maxDelayMs, sleep: opts?.sleep ?? DEFAULT_RETRY_OPTIONS.sleep, random: opts?.random ?? DEFAULT_RETRY_OPTIONS.random, + onRetry: opts?.onRetry ?? DEFAULT_RETRY_OPTIONS.onRetry, }); // Transport failures: the request did not complete, for reasons below HTTP. @@ -234,7 +239,9 @@ export const withRetry = async ( // and its status intact. throw err; } - await policy.sleep(backoffMs(attempt, policy)); + const delayMs = backoffMs(attempt, policy); + policy.onRetry(err, attempt, delayMs); + await policy.sleep(delayMs); } } }; diff --git a/test/api/client.test.ts b/test/api/client.test.ts index 68ab7cf..a708d31 100644 --- a/test/api/client.test.ts +++ b/test/api/client.test.ts @@ -1222,3 +1222,65 @@ describe("ApiClient non-idempotent requests", () => { } }); }); + +// `onRequest` hears of each request the client sends, as its response arrives +// or as it fails. The CLI logs these with `-vv`. A retried request is reported +// once for each attempt. +describe("ApiClient onRequest", () => { + it("reports each request with its status, or with the error it failed with", async () => { + const refused = new TypeError("fetch failed"); + const { fetch } = scriptedFetch( + refused, + textResponse("unavailable", 503), + jsonResponse({ collections: [] }), + jsonResponse({}), + streamResponse(new Uint8Array([1, 2, 3])), + ); + const requests: unknown[] = []; + const client = new ApiClient({ + fetch, + retry: noWait, + onRequest: (request) => requests.push(request), + }); + + await client.getJSON("/collections/v2", { sinceTime: 0 }); + await client.postJSON("/users/logout", {}); + await readAll(await client.getFileStream(7)); + + const collections = "https://api.ente.io/collections/v2?sinceTime=0"; + expect(requests).toEqual([ + { method: "GET", url: collections, error: refused }, + { method: "GET", url: collections, status: 503 }, + { method: "GET", url: collections, status: 200 }, + { + method: "POST", + url: "https://api.ente.io/users/logout", + status: 200, + }, + { + method: "GET", + url: "https://files.ente.io/?fileID=7", + status: 200, + }, + ]); + }); + + it("reports a presigned upload without its query, which holds the upload's signature", async () => { + const { fetch } = scriptedFetch(new Response(null, { status: 200 })); + const requests: unknown[] = []; + const client = new ApiClient({ + fetch, + retry: noWait, + onRequest: (request) => requests.push(request), + }); + + await client.putFile( + "https://s3.example/obj?X-Amz-Signature=abc", + new Uint8Array([1, 2]), + ); + + expect(requests).toEqual([ + { method: "PUT", url: "https://s3.example/obj", status: 200 }, + ]); + }); +}); diff --git a/test/cli/backup-end-to-end.test.ts b/test/cli/backup-end-to-end.test.ts index 80714ae..46895e3 100644 --- a/test/cli/backup-end-to-end.test.ts +++ b/test/cli/backup-end-to-end.test.ts @@ -54,6 +54,7 @@ import { saveSession, type CliContext, } from "../../src/cli-commands.js"; +import { stderrLog } from "../../src/cli-log.js"; import { run } from "../../src/cli-run.js"; import { loadSession } from "../../src/cli-session.js"; import { Client } from "../../src/client.js"; @@ -303,9 +304,10 @@ const backup = async ( const prompted = async (): Promise => { throw new Error("quak backup prompted"); }; + const log = stderrLog(stderr, "info"); const ctx: CliContext = { stdout, - stderr, + log, sessionDir, cacheDir: `${dir}-cache`, loadSession: (path) => @@ -319,7 +321,7 @@ const backup = async ( promptSecret: prompted, }; const code = await new Promise((resolve) => { - void run(backupCommand(ctx, dir, opts), stdout, stderr, resolve); + void run(backupCommand(ctx, dir, opts), stdout, stderr, log, resolve); }); return { code, stderr: printed, stdout: output }; }; @@ -1104,6 +1106,9 @@ describe("a backup whose lock is lost", () => { expect(code).toBe(1); expect(stderr).toBe( "Starting backup...\n" + + "Fetched the files of 1 of 3 collections\n" + + "Fetched the files of 2 of 3 collections\n" + + "Fetched the files of 3 of 3 collections\n" + "Refreshing library...\n" + "Fetching original beach.jpg (100)...\n" + "Fetching original IMG_0002.HEIC (300)...\n" + diff --git a/test/cli/backup-undecryptable.test.ts b/test/cli/backup-undecryptable.test.ts index bcd507c..26f48dc 100644 --- a/test/cli/backup-undecryptable.test.ts +++ b/test/cli/backup-undecryptable.test.ts @@ -42,6 +42,7 @@ import { saveSession, type CliContext, } from "../../src/cli-commands.js"; +import { stderrLog } from "../../src/cli-log.js"; import { loadSession } from "../../src/cli-session.js"; import { Client, type ClientSnapshot } from "../../src/client.js"; import { encryptBlob, init, toBase64 } from "../../src/crypto/index.js"; @@ -304,7 +305,7 @@ const context = (ente: FakeEnte): CliContext => { saveSession(join(root, "session"), ente.snapshot()); return { stdout, - stderr, + log: stderrLog(stderr, "info"), sessionDir: join(root, "session"), cacheDir: join(root, "cache"), loadSession: (path) => diff --git a/test/cli/bin.test.ts b/test/cli/bin.test.ts index 18b55ab..c24726c 100644 --- a/test/cli/bin.test.ts +++ b/test/cli/bin.test.ts @@ -1,7 +1,8 @@ /** * Tests for the retry options `bin/quak.ts` loads the saved session with * (`quak backup` gets the unattended ones, every other command the default), - * and for `quak files` taking its collection ID as an optional argument. + * each with the callbacks that log its requests and retries, and for + * `quak files` taking its collection ID as an optional argument. * * Each test runs `bin/quak.ts`, as the smoke test does, with its session loader * replaced by one that records the options it is given and reports no session, @@ -65,14 +66,21 @@ describe("bin/quak.ts session loading", () => { attempts, baseDelayMs, maxDelayMs, + onRetry: expect.any(Function), }), + onRequest: expect.any(Function), }, ]); }); - it("loads the session for another command with the default options", async () => { + it("loads the session for another command with the default retry options", async () => { await quak("collections"); - expect(loaded).toEqual([undefined]); + expect(loaded).toEqual([ + { + retry: { onRetry: expect.any(Function) }, + onRequest: expect.any(Function), + }, + ]); }); }); diff --git a/test/cli/commands.test.ts b/test/cli/commands.test.ts index a1c6773..53ee755 100644 --- a/test/cli/commands.test.ts +++ b/test/cli/commands.test.ts @@ -51,6 +51,7 @@ import { listMissingThumbnailsCommand, fixMissingThumbnailsCommand, } from "../../src/cli-commands.js"; +import { stderrLog } from "../../src/cli-log.js"; import { run } from "../../src/cli-run.js"; import { loadSession } from "../../src/cli-session.js"; import { @@ -208,9 +209,11 @@ let root: string; let stdout: Output; let stderr: Output; +// The commands log at the default level, info, as `quak` without `-v` or `-q` +// does; the levels have their own tests, in `log.test.ts`. const context = (client: Client | null = fakeClient()): CliContext => ({ stdout, - stderr, + log: stderrLog(stderr, "info"), sessionDir: join(root, "session"), cacheDir: join(root, "cache"), loadSession: () => client, @@ -566,7 +569,7 @@ describe("files", () => { [101, 1], [200, 2], ]); - expect(stderr.text).toBe(""); + expect(stderr.text).toBe(FETCHED_BOTH_ALBUMS); }); }); @@ -910,6 +913,8 @@ describe("backup", () => { ); }); + // `--json` shapes stdout only: the log lines stay on stderr, and the JSON + // takes the place of the summary. it("prints the result as JSON with --json, still exiting 1 on a failure", async () => { const ctx = context(fakeClient({ failID: 101 })); const code = await backupCommand(ctx, join(root, "backup"), { @@ -924,7 +929,31 @@ describe("backup", () => { failed: 1, }); expect(result.errors[0].fileID).toBe(101); - expect(stderr.text).toBe("Starting backup...\n"); + expect(stderr.text).toContain( + "Fetching original sunset.jpg (101)...\n", + ); + expect(stderr.text).not.toContain("Backup complete"); + }); + + // On an empty cache the library's first refresh fetches the files of + // every album before the backup can start, which on a large account takes + // a while; each album it has fetched the files of is counted on stderr, + // with `--json` too. + it("counts on stderr each album whose files its first refresh fetched, with --json too", async () => { + const start = + "Starting backup...\n" + + FETCHED_BOTH_ALBUMS + + "Refreshing library...\n"; + for (const json of [false, true]) { + stderr.text = ""; + const dir = mkdtempSync(join(root, "backup-")); + const ctx = { + ...context(), + cacheDir: mkdtempSync(join(root, "cache-")), + }; + expect(await backupCommand(ctx, dir, { json })).toBe(0); + expect(stderr.text.slice(0, start.length)).toBe(start); + } }); it("--verify downloads again an original that does not match its hash, prints the counts, and exits 0", async () => { @@ -1014,6 +1043,7 @@ describe("backup", () => { backupCommand(ctx, dir, {}), new PassThrough(), runStderr, + stderrLog(runStderr, "info"), resolve, ); }); @@ -1254,7 +1284,9 @@ describe("helper list-missing-thumbnails", () => { expect(stderr.text).toContain("No missing thumbnails found.\n"); }); - it("prints a JSON array with --json and no progress", async () => { + // `--json` shapes stdout only: the progress stays on stderr, and the JSON + // takes the place of the count and the list. + it("prints a JSON array with --json, and its progress on stderr", async () => { const ctx = context(fakeClient({ emptyThumbID: 200 })); expect(await listMissingThumbnailsCommand(ctx, { json: true })).toBe(0); expect(JSON.parse(stdout.text)).toEqual([ @@ -1265,7 +1297,9 @@ describe("helper list-missing-thumbnails", () => { reason: "empty thumbnail (0 bytes)", }, ]); - expect(stderr.text).toBe(""); + expect(stderr.text).toContain(FETCHED_BOTH_ALBUMS); + expect(stderr.text).toContain("[Work] Checking thumbnails...\n"); + expect(stderr.text).not.toContain("with missing thumbnails"); }); }); @@ -1624,9 +1658,9 @@ describe("an account with many albums", () => { expect(stderr.text).toBe(progress); }); - // With `--json` the refresh's progress is not printed, as `backup` and - // the thumbnail helpers print none of theirs. - it("files --json prints no progress", async () => { + // `--json` shapes stdout only, so the refresh's progress is still counted + // on stderr. + it("files --json counts on stderr each album whose files its refresh fetched", async () => { expect(await filesCommand(accountContext(), "7", { json: true })).toBe( 0, ); @@ -1640,6 +1674,10 @@ describe("an account with many albums", () => { collectionID: 7, }, ]); - expect(stderr.text).toBe(""); + let progress = ""; + for (let n = 1; n <= ALBUMS; n++) { + progress += `Fetched the files of ${n} of ${ALBUMS} collections\n`; + } + expect(stderr.text).toBe(progress); }); }); diff --git a/test/cli/log.test.ts b/test/cli/log.test.ts new file mode 100644 index 0000000..ac33504 --- /dev/null +++ b/test/cli/log.test.ts @@ -0,0 +1,354 @@ +/** + * 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", + ]); + }); +}); diff --git a/test/cli/metadata-backup.test.ts b/test/cli/metadata-backup.test.ts index 0902e44..f81491f 100644 --- a/test/cli/metadata-backup.test.ts +++ b/test/cli/metadata-backup.test.ts @@ -47,6 +47,7 @@ import { type MetadataBackupOptions, } from "../../src/metadata-backup.js"; import { backupMetadataCommand } from "../../src/cli-commands.js"; +import { stderrLog } from "../../src/cli-log.js"; import { buildAccount, buildMetaFetch, @@ -506,7 +507,10 @@ describe("quak backup-metadata when a file's ML data cannot be read", () => { const code = await backupMetadataCommand( { stdout: { write: () => true }, - stderr: { write: (text: string) => (stderr += text) }, + log: stderrLog( + { write: (text: string) => (stderr += text) }, + "info", + ), sessionDir: testDir, cacheDir: mkdtempSync(join(testDir, "cache-")), loadSession: () => client, diff --git a/test/cli/run.test.ts b/test/cli/run.test.ts index 27db619..e070d2c 100644 --- a/test/cli/run.test.ts +++ b/test/cli/run.test.ts @@ -6,6 +6,7 @@ import { PassThrough } from "node:stream"; import { describe, it, expect } from "vitest"; import { ApiError } from "../../src/api/client.js"; +import { stderrLog } from "../../src/cli-log.js"; import { run } from "../../src/cli-run.js"; // A stream whose written text is kept in `text`; writes finish at once, so @@ -23,7 +24,13 @@ const runToExit = async ( const stdout = collector(); const stderr = collector(); const code = await new Promise((resolve) => { - void run(command, stdout.stream, stderr.stream, resolve); + void run( + command, + stdout.stream, + stderr.stream, + stderrLog(stderr.stream, "info"), + resolve, + ); }); return { code, stdout: stdout.text(), stderr: stderr.text() }; }; diff --git a/test/retry/retry.test.ts b/test/retry/retry.test.ts index b943985..e0c4348 100644 --- a/test/retry/retry.test.ts +++ b/test/retry/retry.test.ts @@ -555,6 +555,36 @@ describe("withRetry", () => { expect(delays).toHaveLength(2); }); + it("tells `onRetry` of each attempt it retries, before the wait", async () => { + // A caller that logs retries, as the CLI does with `-v`, learns why + // each attempt failed and how long the next one is put off. The last + // attempt is not retried, so it is not reported. + const { sleep, delays } = recordingSleep(); + const retries: [string, number, number][] = []; + let calls = 0; + const failure = withRetry( + () => { + calls++; + return Promise.reject(new ApiError(`attempt ${calls}`, 503)); + }, + { + attempts: 3, + sleep, + random: () => 0.5, + onRetry: (err, attempt, delayMs) => { + retries.push([(err as Error).message, attempt, delayMs]); + }, + }, + ); + + await expect(failure).rejects.toThrow("attempt 3"); + expect(retries).toEqual([ + ["attempt 1", 1, 250], + ["attempt 2", 2, 500], + ]); + expect(delays).toEqual([250, 500]); + }); + it("does not retry at all when attempts is 1", async () => { const { sleep, delays } = recordingSleep(); let calls = 0; @@ -708,6 +738,7 @@ describe("retry defaults", () => { expect(resolved.maxDelayMs).toBe(DEFAULT_RETRY_OPTIONS.maxDelayMs); expect(typeof resolved.sleep).toBe("function"); expect(typeof resolved.random).toBe("function"); + expect(typeof resolved.onRetry).toBe("function"); }); it("resolves to the defaults when given nothing", () => {