feat: report lockfile verification progress (#11712)

* feat: report lockfile verification progress

The lockfile resolution verifier introduced in #11705 runs an unbounded
registry round-trip on cache miss and was previously silent — on a cold
registry cache users saw nothing for several seconds. Emit pnpm:lockfile-verification
log events (started/done) around the actual verification pass and render
them in the default reporter as a transient progress line that collapses
into a final "verified" summary with entry count and elapsed time. The
cached short-circuit stays silent.

* feat: include lockfile path in verification log and render when non-standard

Add `lockfilePath` to the `pnpm:lockfile-verification` event payload so
consumers always know which lockfile a `started`/`done` pair refers to.
In the default reporter, render the path in the message only when the
lockfile lives outside the workspace root (or, for non-workspace
installs, outside cwd) — the common case stays uncluttered, while
custom `lockfileDir` setups now surface in the verification line.

* feat: name what the lockfile verification actually checks in the rendered message

"Verifying lockfile" was opaque about *what* was being verified. Reword
the rendered messages to explicitly name the check ("supply-chain
policies"), so users on a cold-cache pause understand what's happening
instead of just seeing the pause.

* fix: skip lockfile verification emission for empty candidate set

A non-empty lockfile.packages whose snapshots all fail name/version
extraction would still emit a "Verifying lockfile (0 entries)" line even
though no verifier work runs. Bail before emission when the candidate
map is empty so the no-op branch stays silent, matching the contract
for the other no-op branches (empty verifiers, no lockfile.packages).

* fix(reporter): always close out the verifying-lockfile frame

Address two Copilot review points on #11712:

1. The verifier emitted `started` but no terminal event when violations
   were found or when the registry fan-out threw, leaving "Verifying
   lockfile…" as the last frame for that block in ansi-diff mode (and
   an unmatched line in CI logs). Add a `failed` status to the logger,
   wrap the fan-out in try/finally so a terminal event is emitted on
   every exit path that emitted `started`, and render a brief failure
   line so the spinner-style frame is replaced before the PnpmError
   block prints.

2. The path-suppression heuristic used strict `===` between
   path.dirname(lockfilePath) and expectedDir, which broke on trailing
   separators and slash-direction differences. Switch to a
   path.relative-based check so a workspaceDir like `/repo/` or a
   Windows path with mixed slashes still correctly suppresses the
   redundant "at <path>" suffix.

* docs: update lockfile verification logging behavior

The lockfile verifier now emits log events during the registry round-trip pass, improving user visibility into the process.
This commit is contained in:
Zoltan Kochan
2026-05-18 11:38:47 +02:00
committed by GitHub
parent a671dda173
commit 4a79336473
9 changed files with 383 additions and 23 deletions

View File

@@ -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).

View File

@@ -127,6 +127,7 @@ export function toOutput$ (
const deprecationPushStream = new Rx.Subject<logs.DeprecationLog>()
const summaryPushStream = new Rx.Subject<logs.SummaryLog>()
const lifecyclePushStream = new Rx.Subject<logs.LifecycleLog>()
const lockfileVerificationPushStream = new Rx.Subject<logs.LockfileVerificationLog>()
const statsPushStream = new Rx.Subject<logs.StatsLog>()
const packageImportMethodPushStream = new Rx.Subject<logs.PackageImportMethodLog>()
const installCheckPushStream = new Rx.Subject<logs.InstallCheckLog>()
@@ -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),

View File

@@ -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<logs.DeprecationLog>
summary: Rx.Observable<logs.SummaryLog>
lifecycle: Rx.Observable<logs.LifecycleLog>
lockfileVerification: Rx.Observable<logs.LockfileVerificationLog>
stats: Rx.Observable<logs.StatsLog>
installCheck: Rx.Observable<logs.InstallCheckLog>
installingConfigDeps: Rx.Observable<logs.InstallingConfigDepsLog>
@@ -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 }),

View File

@@ -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<LockfileVerificationLog>,
opts: ReportLockfileVerificationOptions
): Rx.Observable<Rx.Observable<{ msg: string }>> {
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 <path>` 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))}`
}

View File

@@ -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)')
})

View File

@@ -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'

View File

@@ -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

View File

@@ -0,0 +1,56 @@
import {
type LogBase,
logger,
} from '@pnpm/logger'
export const lockfileVerificationLogger = logger<LockfileVerificationMessage>('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

View File

@@ -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<ResolutionPolicyViolation[]> {
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<ResolutionPolicyViolation[]> {
// 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<string, { name: string, version: string, resolution: Resolution }>()
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<string, Candidate> {
const candidates = new Map<string, Candidate>()
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<string, Candidate>,
verifiers: readonly ResolutionVerifier[],
concurrency: number | undefined
): Promise<ResolutionPolicyViolation[]> {
const violations: ResolutionPolicyViolation[] = []
const limit = pLimit(concurrency ?? DEFAULT_CONCURRENCY)
await Promise.all(