diff --git a/.changeset/lockfile-verification-progress-logs.md b/.changeset/lockfile-verification-progress-logs.md new file mode 100644 index 0000000000..647a14c68e --- /dev/null +++ b/.changeset/lockfile-verification-progress-logs.md @@ -0,0 +1,10 @@ +--- +"@pnpm/core-loggers": minor +"@pnpm/installing.deps-installer": patch +"@pnpm/cli.default-reporter": minor +"pnpm": patch +--- + +The lockfile verifier added in #11705 now emits `pnpm:lockfile-verification` log events (`status: 'started' | 'done'`) around the registry round-trip pass, and the default reporter renders them as a transient progress line so users can see that pnpm is doing work — on a cold registry cache the round-trip can take a noticeable beat, and the previous behavior was complete silence followed by either a long pause or an error. The cached short-circuit stays silent (no logs when no work happens), and the `done` line carries the number of distinct entries that were checked plus the elapsed time. + +Pacquet parity: not ported — pacquet doesn't carry the lockfile verifier yet (see the parity note on #11705). diff --git a/cli/default-reporter/src/index.ts b/cli/default-reporter/src/index.ts index 65d13ba3a5..94015efea5 100644 --- a/cli/default-reporter/src/index.ts +++ b/cli/default-reporter/src/index.ts @@ -127,6 +127,7 @@ export function toOutput$ ( const deprecationPushStream = new Rx.Subject() const summaryPushStream = new Rx.Subject() const lifecyclePushStream = new Rx.Subject() + const lockfileVerificationPushStream = new Rx.Subject() const statsPushStream = new Rx.Subject() const packageImportMethodPushStream = new Rx.Subject() const installCheckPushStream = new Rx.Subject() @@ -170,6 +171,9 @@ export function toOutput$ ( case 'pnpm:lifecycle': lifecyclePushStream.next(log) break + case 'pnpm:lockfile-verification': + lockfileVerificationPushStream.next(log) + break case 'pnpm:stats': statsPushStream.next(log) break @@ -243,6 +247,7 @@ export function toOutput$ ( ignoredScripts: Rx.from(ignoredScriptsPushStream), lifecycle: Rx.from(lifecyclePushStream), link: Rx.from(linkPushStream), + lockfileVerification: Rx.from(lockfileVerificationPushStream), other, packageImportMethod: Rx.from(packageImportMethodPushStream), packageManifest: Rx.from(packageManifestPushStream), diff --git a/cli/default-reporter/src/reporterForClient/index.ts b/cli/default-reporter/src/reporterForClient/index.ts index ae4c79b2f5..8e3af0bd18 100644 --- a/cli/default-reporter/src/reporterForClient/index.ts +++ b/cli/default-reporter/src/reporterForClient/index.ts @@ -13,6 +13,7 @@ import { reportIgnoredBuilds } from './reportIgnoredBuilds.js' import { reportInstallChecks } from './reportInstallChecks.js' import { reportInstallingConfigDeps } from './reportInstallingConfigDeps.js' import { reportLifecycleScripts } from './reportLifecycleScripts.js' +import { reportLockfileVerification } from './reportLockfileVerification.js' import { LOG_LEVEL_NUMBER, reportMisc } from './reportMisc.js' import { reportPeerDependencyIssues } from './reportPeerDependencyIssues.js' import { reportProgress } from './reportProgress.js' @@ -41,6 +42,7 @@ export function reporterForClient ( deprecation: Rx.Observable summary: Rx.Observable lifecycle: Rx.Observable + lockfileVerification: Rx.Observable stats: Rx.Observable installCheck: Rx.Observable installingConfigDeps: Rx.Observable @@ -130,6 +132,10 @@ export function reporterForClient ( }), reportInstallChecks(log$.installCheck, { cwd }), reportInstallingConfigDeps(log$.installingConfigDeps), + reportLockfileVerification(log$.lockfileVerification, { + cwd, + workspaceDir: opts.pnpmConfig?.workspaceDir, + }), reportScope(log$.scope, { isRecursive: opts.isRecursive, cmd: opts.cmd }), reportSkippedOptionalDependencies(log$.skippedOptionalDependency, { cwd }), reportHooks(log$.hook, { cwd, isRecursive: opts.isRecursive }), diff --git a/cli/default-reporter/src/reporterForClient/reportLockfileVerification.ts b/cli/default-reporter/src/reporterForClient/reportLockfileVerification.ts new file mode 100644 index 0000000000..c6d771032d --- /dev/null +++ b/cli/default-reporter/src/reporterForClient/reportLockfileVerification.ts @@ -0,0 +1,77 @@ +import path from 'node:path' + +import type { LockfileVerificationLog } from '@pnpm/core-loggers' +import chalk from 'chalk' +import normalize from 'normalize-path' +import prettyMs from 'pretty-ms' +import * as Rx from 'rxjs' +import { map } from 'rxjs/operators' + +export interface ReportLockfileVerificationOptions { + cwd: string + /** + * The workspace root, when one exists. Used as the "expected" + * location for the lockfile — when the lockfile lives there, the + * path is implied and we don't repeat it in the rendered message. + * Falls back to `cwd` for single-project installs. + */ + workspaceDir?: string +} + +export function reportLockfileVerification ( + lockfileVerification$: Rx.Observable, + opts: ReportLockfileVerificationOptions +): Rx.Observable> { + const expectedDir = opts.workspaceDir ?? opts.cwd + // A single inner observable so the `done` message overwrites the + // transient `started` message in ansi-diff mode. In appendOnly mode + // both lines are printed. + return Rx.of(lockfileVerification$.pipe( + map((log) => { + const path_ = formatLockfilePath(log.lockfilePath, opts.cwd, expectedDir) + const entries = `${log.entries} ${log.entries === 1 ? 'entry' : 'entries'}` + switch (log.status) { + case 'started': + return { + msg: `${chalk.cyan('?')} Verifying lockfile${path_} against supply-chain policies (${entries})...`, + } + case 'done': + return { + msg: `${chalk.green('✓')} Lockfile${path_} passes supply-chain policies (${entries} in ${prettyMs(log.elapsedMs)})`, + } + case 'failed': + // Brief one-liner so the transient `started` frame doesn't + // stay on screen above the detailed PnpmError block that the + // error reporter prints next. + return { + msg: `${chalk.red('✗')} Lockfile${path_} failed supply-chain policy check (${entries} in ${prettyMs(log.elapsedMs)})`, + } + } + }) + )) +} + +// Returns a leading-space-prefixed `at ` suffix only when the +// lockfile sits outside the obvious project/workspace root — otherwise +// the path is implied and printing it would just add noise to every +// install. Empty string when the path is omitted or matches the +// expected location. +// +// Uses `path.relative` rather than a strict `===` between +// `path.dirname(lockfilePath)` and `expectedDir`: relative path +// computation normalizes slash direction and trailing separators, so +// a workspaceDir like `C:/repo/` correctly matches a lockfilePath at +// `C:\repo\pnpm-lock.yaml` on Windows. The lockfile is considered +// "inside the expected dir" when the relative path is a bare file +// name (no separator) that doesn't escape upward. +function formatLockfilePath ( + lockfilePath: string | undefined, + cwd: string, + expectedDir: string +): string { + if (lockfilePath == null) return '' + const fromExpected = path.relative(expectedDir, lockfilePath) + const isDirectChild = !fromExpected.includes(path.sep) && !fromExpected.startsWith('..') + if (isDirectChild) return '' + return ` at ${normalize(path.relative(cwd, lockfilePath))}` +} diff --git a/cli/default-reporter/test/reportingLockfileVerification.ts b/cli/default-reporter/test/reportingLockfileVerification.ts new file mode 100644 index 0000000000..60d1339bd9 --- /dev/null +++ b/cli/default-reporter/test/reportingLockfileVerification.ts @@ -0,0 +1,150 @@ +import path from 'node:path' +import { stripVTControlCharacters as stripAnsi } from 'node:util' + +import { expect, test } from '@jest/globals' +import { toOutput$ } from '@pnpm/cli.default-reporter' +import type { Config, ConfigContext } from '@pnpm/config.reader' +import { lockfileVerificationLogger } from '@pnpm/core-loggers' +import { createStreamParser } from '@pnpm/logger' +import { firstValueFrom, take, toArray } from 'rxjs' + +test('prints lockfile verification in-progress and completion messages', async () => { + const cwd = '/repo' + const output$ = toOutput$({ + context: { + argv: ['install'], + config: { dir: cwd } as Config & ConfigContext, + }, + streamParser: createStreamParser(), + }) + + // Subscribe before emitting so we capture both the started and the + // done frame in ansi-diff mode. + const frames = firstValueFrom(output$.pipe(take(2), toArray())) + + const lockfilePath = path.join(cwd, 'pnpm-lock.yaml') + lockfileVerificationLogger.debug({ status: 'started', entries: 234, lockfilePath }) + lockfileVerificationLogger.debug({ + status: 'done', + entries: 234, + elapsedMs: 1234, + lockfilePath, + }) + + const [started, done] = await frames + expect(stripAnsi(started)).toBe('? Verifying lockfile against supply-chain policies (234 entries)...') + expect(stripAnsi(done)).toBe('✓ Lockfile passes supply-chain policies (234 entries in 1.2s)') +}) + +test('uses singular noun for one entry', async () => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + streamParser: createStreamParser(), + }) + + const frames = firstValueFrom(output$.pipe(take(2), toArray())) + + lockfileVerificationLogger.debug({ status: 'started', entries: 1 }) + lockfileVerificationLogger.debug({ + status: 'done', + entries: 1, + elapsedMs: 42, + }) + + const [started, done] = await frames + expect(stripAnsi(started)).toBe('? Verifying lockfile against supply-chain policies (1 entry)...') + expect(stripAnsi(done)).toBe('✓ Lockfile passes supply-chain policies (1 entry in 42ms)') +}) + +test('prints relative path when lockfile lives outside the workspace root', async () => { + const cwd = '/repo/packages/app' + const workspaceDir = '/repo' + const output$ = toOutput$({ + context: { + argv: ['install'], + config: { dir: cwd, workspaceDir } as Config & ConfigContext, + }, + streamParser: createStreamParser(), + }) + + const frames = firstValueFrom(output$.pipe(take(2), toArray())) + + // Lockfile lives in a sibling dir, not at the workspace root. + const lockfilePath = '/repo/locks/pnpm-lock.yaml' + lockfileVerificationLogger.debug({ status: 'started', entries: 5, lockfilePath }) + lockfileVerificationLogger.debug({ + status: 'done', + entries: 5, + elapsedMs: 200, + lockfilePath, + }) + + const [started, done] = await frames + expect(stripAnsi(started)).toBe('? Verifying lockfile at ../../locks/pnpm-lock.yaml against supply-chain policies (5 entries)...') + expect(stripAnsi(done)).toBe('✓ Lockfile at ../../locks/pnpm-lock.yaml passes supply-chain policies (5 entries in 200ms)') +}) + +test('does not print path when running from workspace subdir and lockfile is at workspace root', async () => { + const cwd = '/repo/packages/app' + const workspaceDir = '/repo' + const output$ = toOutput$({ + context: { + argv: ['install'], + config: { dir: cwd, workspaceDir } as Config & ConfigContext, + }, + streamParser: createStreamParser(), + }) + + const frames = firstValueFrom(output$.pipe(take(1), toArray())) + + const lockfilePath = path.join(workspaceDir, 'pnpm-lock.yaml') + lockfileVerificationLogger.debug({ status: 'started', entries: 10, lockfilePath }) + + const [started] = await frames + expect(stripAnsi(started)).toBe('? Verifying lockfile against supply-chain policies (10 entries)...') +}) + +test('suppresses path when workspaceDir has a trailing separator', async () => { + const cwd = '/repo' + // Workspace dir with a trailing slash — strict === against + // path.dirname(lockfilePath) would mismatch; path.relative normalizes. + const workspaceDir = '/repo/' + const output$ = toOutput$({ + context: { + argv: ['install'], + config: { dir: cwd, workspaceDir } as Config & ConfigContext, + }, + streamParser: createStreamParser(), + }) + + const frames = firstValueFrom(output$.pipe(take(1), toArray())) + + lockfileVerificationLogger.debug({ + status: 'started', + entries: 3, + lockfilePath: '/repo/pnpm-lock.yaml', + }) + + const [started] = await frames + expect(stripAnsi(started)).toBe('? Verifying lockfile against supply-chain policies (3 entries)...') +}) + +test('emits a brief failure line on failed status', async () => { + const output$ = toOutput$({ + context: { argv: ['install'] }, + streamParser: createStreamParser(), + }) + + const frames = firstValueFrom(output$.pipe(take(2), toArray())) + + lockfileVerificationLogger.debug({ status: 'started', entries: 12 }) + lockfileVerificationLogger.debug({ + status: 'failed', + entries: 12, + elapsedMs: 800, + }) + + const [started, failed] = await frames + expect(stripAnsi(started)).toBe('? Verifying lockfile against supply-chain policies (12 entries)...') + expect(stripAnsi(failed)).toBe('✗ Lockfile failed supply-chain policy check (12 entries in 800ms)') +}) diff --git a/core/core-loggers/src/all.ts b/core/core-loggers/src/all.ts index dcd5f8d646..55ed5b730c 100644 --- a/core/core-loggers/src/all.ts +++ b/core/core-loggers/src/all.ts @@ -8,6 +8,7 @@ export * from './installCheckLogger.js' export * from './installingConfigDeps.js' export * from './lifecycleLogger.js' export * from './linkLogger.js' +export * from './lockfileVerificationLogger.js' export * from './packageImportMethodLogger.js' export * from './packageManifestLogger.js' export * from './peerDependencyIssues.js' diff --git a/core/core-loggers/src/index.ts b/core/core-loggers/src/index.ts index 9dfce3ff69..2a544ebb5f 100644 --- a/core/core-loggers/src/index.ts +++ b/core/core-loggers/src/index.ts @@ -9,6 +9,7 @@ import type { InstallingConfigDepsLog, LifecycleLog, LinkLog, + LockfileVerificationLog, PackageImportMethodLog, PackageManifestLog, PeerDependencyIssuesLog, @@ -37,6 +38,7 @@ export type Log = | IgnoredScriptsLog | LifecycleLog | LinkLog + | LockfileVerificationLog | PackageManifestLog | PackageImportMethodLog | PeerDependencyIssuesLog diff --git a/core/core-loggers/src/lockfileVerificationLogger.ts b/core/core-loggers/src/lockfileVerificationLogger.ts new file mode 100644 index 0000000000..3383771e56 --- /dev/null +++ b/core/core-loggers/src/lockfileVerificationLogger.ts @@ -0,0 +1,56 @@ +import { + type LogBase, + logger, +} from '@pnpm/logger' + +export const lockfileVerificationLogger = logger('lockfile-verification') + +export interface LockfileVerificationMessageBase { + status: 'started' | 'done' | 'failed' + /** + * Absolute path of the lockfile being verified. Omitted only when + * the verifier is invoked without a path (today only in unit tests + * that skip the cache wiring); production code paths always pass it. + */ + lockfilePath?: string +} + +export interface LockfileVerificationStartedMessage extends LockfileVerificationMessageBase { + status: 'started' + /** Number of distinct (name, version, resolution) entries about to be verified. */ + entries: number +} + +export interface LockfileVerificationDoneMessage extends LockfileVerificationMessageBase { + status: 'done' + /** Number of distinct (name, version, resolution) entries that were verified. */ + entries: number + /** Milliseconds elapsed between the matching `started` event and `done`. */ + elapsedMs: number +} + +/** + * Terminal event emitted on every exit path that emitted `started` but + * didn't succeed — both policy violations (a `PnpmError` is about to be + * thrown with the breakdown) and unexpected throws from the registry + * fan-out. Lets the reporter close out the transient `started` frame + * in ansi-diff mode so it isn't left looking like a hung spinner above + * the failure output. + */ +export interface LockfileVerificationFailedMessage extends LockfileVerificationMessageBase { + status: 'failed' + /** Number of distinct (name, version, resolution) entries that were checked before the failure. */ + entries: number + /** Milliseconds elapsed between the matching `started` event and `failed`. */ + elapsedMs: number +} + +export type LockfileVerificationMessage = + | LockfileVerificationStartedMessage + | LockfileVerificationDoneMessage + | LockfileVerificationFailedMessage + +export type LockfileVerificationLog = + & { name: 'pnpm:lockfile-verification' } + & LogBase + & LockfileVerificationMessage diff --git a/installing/deps-installer/src/install/verifyLockfileResolutions.ts b/installing/deps-installer/src/install/verifyLockfileResolutions.ts index 39cb347022..a10afe6158 100644 --- a/installing/deps-installer/src/install/verifyLockfileResolutions.ts +++ b/installing/deps-installer/src/install/verifyLockfileResolutions.ts @@ -1,3 +1,4 @@ +import { lockfileVerificationLogger } from '@pnpm/core-loggers' import { hashObject } from '@pnpm/crypto.object-hasher' import { PnpmError } from '@pnpm/error' import type { LockfileObject } from '@pnpm/lockfile.fs' @@ -113,10 +114,15 @@ export async function verifyLockfileResolutions ( cachePrecomputed = result.precomputed } - const violations = await iterateLockfileViolations(lockfile, verifiers, options?.concurrency) - - if (violations.length === 0) { - // Persist the success so the next install can stat-only the lockfile. + // Emit started/done around the actual verification pass — the + // round-trip can be slow on a cold registry cache, and the cached + // short-circuit above doesn't reach this branch, so a user only + // sees these messages on installs that are doing real work. + // A degenerate lockfile where every snapshot fails the + // name/version extraction (so candidates is empty) skips emission + // entirely — no work, no noise. + const candidates = collectCandidates(lockfile) + if (candidates.size === 0) { if (cache) { recordVerification(cache.cacheDir, { lockfilePath: cache.lockfilePath, @@ -126,7 +132,45 @@ export async function verifyLockfileResolutions ( } return } + const startedAt = Date.now() + lockfileVerificationLogger.debug({ + status: 'started', + entries: candidates.size, + lockfilePath: options?.lockfilePath, + }) + // Guarantee a terminal `done` or `failed` event on every exit path + // that emitted `started`. Without this, an unexpected throw from the + // registry fan-out (or the policy-violation throw below) would leave + // the transient "Verifying lockfile…" line as the last frame the + // reporter rendered for this block, hanging spinner-style above the + // failure output. + let terminalStatus: 'done' | 'failed' = 'failed' + try { + const violations = await iterateLockfileViolations(candidates, verifiers, options?.concurrency) + if (violations.length === 0) { + terminalStatus = 'done' + // Persist the success so the next install can stat-only the lockfile. + if (cache) { + recordVerification(cache.cacheDir, { + lockfilePath: cache.lockfilePath, + verifiers, + hashLockfile, + }, cachePrecomputed) + } + return + } + throw buildVerificationError(violations) + } finally { + lockfileVerificationLogger.debug({ + status: terminalStatus, + entries: candidates.size, + elapsedMs: Date.now() - startedAt, + lockfilePath: options?.lockfilePath, + }) + } +} +function buildVerificationError (violations: ResolutionPolicyViolation[]): PnpmError { // Stable order so the error output is deterministic. violations.sort((a, b) => `${a.name}@${a.version}`.localeCompare(`${b.name}@${b.version}`)) // Pick the throw code: a single-code batch keeps the per-policy code @@ -147,7 +191,7 @@ export async function verifyLockfileResolutions ( const details = omitted > 0 ? `${breakdown}\n …and ${omitted} more` : breakdown - throw new PnpmError( + return new PnpmError( errorCode, `${violations.length} lockfile entries failed verification:\n${details}`, { @@ -182,26 +226,28 @@ export async function collectResolutionPolicyViolations ( ): Promise { if (verifiers.length === 0) return [] if (!lockfile.packages) return [] - return iterateLockfileViolations(lockfile, verifiers, options?.concurrency) + return iterateLockfileViolations(collectCandidates(lockfile), verifiers, options?.concurrency) } -async function iterateLockfileViolations ( - lockfile: LockfileObject, - verifiers: readonly ResolutionVerifier[], - concurrency: number | undefined -): Promise { - // depPath can include peer-dependency and patch_hash suffixes (e.g. - // `react@18.0.0(peer)(patch_hash=…)`); the same (name, version) pair may - // therefore appear multiple times. Dedupe so we issue at most one - // verification per package version. - // - // Include a serialization of `resolution` in the key so two entries that - // share a (name, version) but differ in *what* was resolved (e.g. one - // pinned via npm, another via a git URL under the same alias) don't - // collapse: if the wrong shape wins the dedup, a protocol-scoped - // verifier short-circuits on the surviving entry and the real one is - // never checked. - const candidates = new Map() +interface Candidate { + name: string + version: string + resolution: Resolution +} + +// depPath can include peer-dependency and patch_hash suffixes (e.g. +// `react@18.0.0(peer)(patch_hash=…)`); the same (name, version) pair may +// therefore appear multiple times. Dedupe so we issue at most one +// verification per package version. +// +// Include a serialization of `resolution` in the key so two entries that +// share a (name, version) but differ in *what* was resolved (e.g. one +// pinned via npm, another via a git URL under the same alias) don't +// collapse: if the wrong shape wins the dedup, a protocol-scoped +// verifier short-circuits on the surviving entry and the real one is +// never checked. +function collectCandidates (lockfile: LockfileObject): Map { + const candidates = new Map() for (const [depPath, snapshot] of Object.entries(lockfile.packages ?? {})) { const { name, version } = nameVerFromPkgSnapshot(depPath as DepPath, snapshot) if (!name || !version) continue @@ -212,7 +258,14 @@ async function iterateLockfileViolations ( resolution: snapshot.resolution as Resolution, }) } + return candidates +} +async function iterateLockfileViolations ( + candidates: Map, + verifiers: readonly ResolutionVerifier[], + concurrency: number | undefined +): Promise { const violations: ResolutionPolicyViolation[] = [] const limit = pLimit(concurrency ?? DEFAULT_CONCURRENCY) await Promise.all(