Files
PaperClipAI/server/src/services/skill-version-cache.ts
T
3cd3af5d75 Trace native preparation and OpenCode execution phases (#17918)
## Thinking Path

> - Paperclip is the open source app people use to manage AI agents for
work.
> - Each native run prepares its workspace and skills, then starts its
provider.
> - A long preparation span does not show whether inventory refresh, a
cache lock, repository reads, or file checks caused the delay.
> - One hosted run spent 81 seconds in this phase. The same deployed
service and pinned files took 2.55 seconds in a separate diagnostic
process.
> - Another hosted turn spent 69 seconds before its first output. A
matched public-workspace local model replay took 7.64 seconds.
> - We need skill preparation and provider-internal measurements before
choosing another fix.
> - This pull request adds skill spans, a real-service benchmark, and
opt-in filtered provider timing.
> - The benefit is a faster and more precise diagnosis loop.

## Linked Issues or Issue Description

Refs #17620. That PR owns the batched read optimization. This PR adds
diagnostics and does not change its read policy.
Refs #17907. That PR protects long cache lock transactions from the
database idle timeout.

**What happened?**

Native skill configuration can take much longer than matched standalone
resolution. Provider execution also has long gaps with no internal
timings. Existing spans cannot separate inventory refresh, cache
acquisition, repository reads, context loading, Git snapshots, or model
streaming.

**Expected behavior**

An operator-configured trace shows these phases under the existing run
context. Without an OTLP endpoint, the new spans stay off. A local
benchmark can reproduce the service path with real PostgreSQL, files, an
agent actor, and a responsible user.

**Steps to reproduce**

1. Run `pnpm --filter @paperclipai/server exec tsx
scripts/benchmark-native-skill-preparation.ts --actor=agent
--staging-shape=true`.
2. Inspect cold and warm phase timings, SQL counts, and file
verification results.
3. Set the existing operator OTLP configuration and add
`--export-otlp=true` to inspect the same hierarchy in the collector.

## What Changed

- Add bounded skill inventory, refresh wait, cache acquisition, row,
version, repository, file check, and consumer spans.
- Keep the existing endpoint gate, attribute allowlist, cache locks,
authorization, file validation, and durable pin boundary.
- Add a standalone benchmark with a full repository fixture, immutable
snapshot input, calibrated local transport delay, and optional OTLP
export.
- Verify every delivered file and executable bit outside the timed
section. Create its fixture agent through the lifecycle API.
- Add an opt-in authenticated loopback sink for OpenCode. Discard raw
attributes, logs and content. Retain only closed phase names and
timestamps.
- Carry one bounded diagnostic batch through the real proxy, Rust
normalization, durable journal and server trace projection. Group
provider phases under their execution parent.
- Freeze the Date clock in an existing delegated Slack rate-limit test.
This fixes a CI failure when consecutive requests cross a rate-window
boundary. It does not change rate-limit behavior.
- Document phase boundaries and the difference between SDK startup and
confirmed ingestion.

## Verification

- Skill service, runtime selection, concurrency, cache and timing
suites: 122 tests passed with real PostgreSQL and migrations.
Enabled-span integration tests also passed. They verify parent
relationships and a real advisory-lock timeout.
- A captured 208-file repository produced 209 verified runtime files.
The benchmark uses real agent and responsible-user authorization. The
lifecycle fixture correction passed with the staging-shaped inventory.
- Affected OpenCode driver, collector and transport tests: 72 passed.
The tests cover authentication, content removal, size/count bounds,
disabled behavior and the rebuilt native Runner boundary. One Rust
projection test and 18 server trace tests also passed. A held run-log
sink proves that a full 128-span diagnostic batch adds no duplicate
database writes before terminal consumption.
- The two CI-failing delegated Slack rate-limit cases passed against
real PostgreSQL with only the Date clock frozen.
- Runner TypeScript and server TypeScript checks passed. Rust formatting
and module-boundary checks passed.
- Real Honeycomb readback confirmed the 14-span skill waterfall and a
40-span provider waterfall. Provider phases have the correct execution
parent. The provider export uses synthetic model replies and is
instrumentation proof only.
- Earlier full local checks failed on missing package-local executables,
then on the default Node heap and a missing generated service worker.
The dependency links were repaired. The server check passed with a
larger heap. The full local test attempt could not start embedded
PostgreSQL on this host and was stopped after retaining its failures;
real database coverage uses an isolated database on an existing local
server. These attempts do not count as a full local pass.
- CI on the prior revision passed typecheck, build, Runner and all E2E
shards. It failed the benchmark lifecycle boundary and one existing
rate-window test. Those fixes passed CI. A later Runner assertion
exposed the Copilot source identity pin on the shared transport file.
The diagnostic flag now uses the existing configured-environment
projection, preserving that file byte-for-byte. All 66 selected
installation and native transport tests passed. New-head CI and review
remain required.
- The under-15-second hosted response target remains unmet. This PR adds
diagnostics and does not claim a hosted latency fix.

## Risks

- Skill spans and Honeycomb export retain the operator endpoint gate.
OpenCode phase collection requires a separate explicit diagnostic flag.
Without an endpoint, its closed measurements stay in the instance run
log.
- Raw OpenCode OTLP can contain prompts and authorization attributes.
The new sink rejects unauthenticated requests and discards all
attributes before any measurement reaches PRP or the operator collector.
Request, event and per-phase limits bound memory and journal growth.
- Collection does not wait for a provider flush. Late or oversized
exports can be absent; these measurements are not a complete profiling
guarantee.
- The benchmark's inventory contents and transport delay are explicit
fixtures. They do not reproduce server contention or prove hosted
response time.
- The one durable diagnostic batch remains the local evidence. Its child
span export does not add per-phase run-log rows.
- No database migration, authorization policy, model selection or
inference transport changes. The Rust Runner and OpenCode proxy must be
shipped together for the new opt-in diagnostic.

## Model Used

OpenAI GPT-6 through Codex, with repository inspection, shell execution,
browser tools, and Honeycomb queries. The session does not expose a
verifiable backend deployment ID or context-window size.

## Checklist

- [x] I have included a thinking path that traces from project context
to this change
- [x] I have specified the model used (with version and capability
details)
- [x] I have checked ROADMAP.md and confirmed this PR does not duplicate
planned core work
- [x] I have searched GitHub for duplicate or related PRs and linked
them above
- [x] I have either (a) linked existing issues with `Fixes: #` / `Closes
#` / `Refs #` OR (b) described the issue in-PR following the relevant
issue template
- [x] I have not referenced internal/instance-local Paperclip issues or
links (only public GitHub `#NNN` / `github.com/paperclipai/paperclip`
URLs)
- [x] My branch name describes the change (e.g. `docs/...`, `fix/...`)
and contains no internal Paperclip ticket id or instance-derived details
- [x] I have run tests locally and they pass
- [x] I have added or updated tests where applicable
- [x] I have updated relevant documentation to reflect my changes
- [x] I have considered and documented any risks above
- [ ] All Paperclip CI gates are green
- [ ] Greptile is 5/5 with no open P2s, recommendations, or follow-ups
- [x] I will address all Greptile and reviewer comments before
requesting merge

---------

Co-authored-by: Paperclip <noreply@paperclip.ing>
Co-authored-by: Paperclip <paperclip@paperclip.ing>
2026-10-27 14:53:32 -05:00

201 lines
11 KiB
TypeScript

import { AsyncLocalStorage } from "node:async_hooks";
import { randomUUID } from "node:crypto";
import { constants, promises as fs } from "node:fs";
import path from "node:path";
import { and, eq, sql } from "drizzle-orm";
import { companySkillVersions, companySkillRepositorySnapshots, heartbeatRuns,
nativeRunFinalizations, environmentLeases, withDedicatedDbConnection, type Db } from "@paperclipai/db";
import { resolvePaperclipInstanceRoot } from "../home-paths.js";
import { assertSkillSnapshotPath } from "./skill-snapshot.js";
import { repositorySkillFrontmatter } from "./skill-repository-package.js";
import type { CompanySkillVersionFileInventoryEntry } from "@paperclipai/shared";
import { parseNativeExecutionInput } from "../vendor/paperclip-runner/index.js";
import { beginRunPhase } from "./execution-preparation-timing.js";
export const SKILL_VERSION_CACHE_IDLE_MS = 60 * 60 * 1000;
const locks = new AsyncLocalStorage<Array<{ db: Db; companyId: string }>>();
const uuid = /^[a-f0-9]{8}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{4}-[a-f0-9]{12}$/i;
export class SkillCacheBusy extends Error {}
// Repository snapshots are immutable and referenced with restrictive foreign
// keys. Cache only validated entrypoint names, never large file contents, so an
// hourly sweep does not transfer the same repository for each skill/version.
const verifiedSnapshots = new WeakMap<Db, Map<string, ReadonlySet<string>>>();
/** Hold through publication AND durable run pinning, not just file creation. */
export async function withSkillVersionCacheLock<T>(db: Db, companyId: string, action: () => Promise<T>, tryOnly = false): Promise<T> {
const held = locks.getStore() ?? [];
if (held.some(lock => lock.db === db && lock.companyId === companyId)) return action();
// Preparation uses the ordinary pool for version/pin writes. Borrowing a pool
// connection for this lock would deadlock installations with a one-slot pool.
const acquired = beginRunPhase("skills.cache.acquire");
return withDedicatedDbConnection(db, connection => connection.transaction(async tx => {
const key = `skill_version_cache:${companyId}`;
if (tryOnly) {
const rows = await tx.execute<{ acquired: boolean }>(sql`select pg_try_advisory_xact_lock(hashtextextended(${key}, 0)) as acquired`);
if (!rows[0]?.acquired) throw new SkillCacheBusy();
} else await tx.execute(sql`select pg_advisory_xact_lock(hashtextextended(${key}, 0))`);
acquired();
return locks.run([...held, { db, companyId }], action);
})).catch(error => {
acquired(true);
throw error;
});
}
export function skillVersionCachePaths(companyId: string, skillId: string, versionId: string) {
if (![companyId, skillId, versionId].every(value => uuid.test(value))) throw new Error("Invalid skill cache identity");
const root = path.join(resolvePaperclipInstanceRoot(), "skills", companyId);
return {
root,
directory: path.join(root, "__versions__", skillId, versionId),
access: path.join(root, "__version_access__", skillId, `${versionId}.json`),
};
}
/** Never traverse a symlink below the configured instance root. */
export async function ensureSkillCacheDirectory(directory: string, create = false) {
const root = path.resolve(resolvePaperclipInstanceRoot());
const relative = path.relative(root, directory);
if (!relative || relative.startsWith("..") || path.isAbsolute(relative)) throw new Error("Skill cache escaped instance root");
if (create) await fs.mkdir(root, { recursive: true });
let cursor = root;
for (const part of relative.split(path.sep)) {
cursor = path.join(cursor, part);
if (create) await fs.mkdir(cursor).catch((error: NodeJS.ErrnoException) => {
if (error.code !== "EEXIST") throw error;
});
const stat = await fs.lstat(cursor);
if (!stat.isDirectory() || stat.isSymbolicLink()) throw new Error("Unsafe skill cache directory");
}
}
export async function touchSkillVersionCache(companyId: string, skillId: string, versionId: string, now = Date.now()) {
const { access } = skillVersionCachePaths(companyId, skillId, versionId);
await ensureSkillCacheDirectory(path.dirname(access), true);
const temporary = `${access}.${randomUUID()}.tmp`;
try {
await fs.writeFile(temporary, JSON.stringify({ version: 1, lastUsedAt: now }), { flag: "wx", mode: 0o600 });
await fs.rename(temporary, access);
} finally { await fs.rm(temporary, { force: true }); }
}
export async function lastUsedAt(filename: string): Promise<number | null> {
try {
await ensureSkillCacheDirectory(path.dirname(filename));
const file = await fs.open(filename, constants.O_RDONLY | constants.O_NOFOLLOW);
try {
const stat = await file.stat();
if (!stat.isFile() || stat.size > 256) return null;
const value = JSON.parse(await file.readFile("utf8"));
return value.version === 1 && Number.isSafeInteger(value.lastUsedAt) && value.lastUsedAt > 0 ? value.lastUsedAt : null;
} finally { await file.close(); }
} catch (error) {
if (error instanceof SyntaxError || ["ENOENT", "ELOOP"].includes((error as NodeJS.ErrnoException).code ?? "")) return null;
throw error;
}
}
// A terminal run can still own provider execution or recovery. Only fully settled
// runs release their pins; resume preparation reacquires the same cache lock.
export async function protectedVersions(db: Db, companyId: string): Promise<Set<string> | null> {
const rows = await db.select({
id: heartbeatRuns.id, agentId: heartbeatRuns.agentId, nativeIssueId: heartbeatRuns.nativeIssueId,
pins: sql<unknown>`${heartbeatRuns.contextSnapshot}->'skillVersions'`,
// Avoid loading large execution inputs for runs with the modern pin map.
legacyInput: sql<unknown>`case when ${heartbeatRuns.runtimeMode} = 'native'
and not coalesce(${heartbeatRuns.contextSnapshot} ? 'skillVersions', false)
then ${heartbeatRuns.runnerProfileJson}->'nativeExecutionInput' end`,
})
.from(heartbeatRuns).where(and(eq(heartbeatRuns.companyId, companyId), sql`(
${heartbeatRuns.status} not in ('succeeded', 'failed', 'timed_out', 'cancelled', 'interrupted')
or ${heartbeatRuns.finishedAt} is null
or ${heartbeatRuns.controllerLeaseExpiresAt} > now()
or exists (select 1 from ${nativeRunFinalizations} f
where f.company_id = ${heartbeatRuns.companyId} and f.run_id = ${heartbeatRuns.id}
and (f.phase <> 'committed' or f.lease_owner is not null or f.recovery_state is not null))
or exists (select 1 from ${environmentLeases} l
where l.company_id = ${heartbeatRuns.companyId} and l.heartbeat_run_id = ${heartbeatRuns.id}
and (l.status = 'pending_cleanup' or l.cleanup_status = 'failed'
or l.metadata ? 'nativeWorkspaceExportResume'
or (l.released_at is null and not coalesce(l.status = 'retained'
and l.lease_policy = 'reuse_by_environment' and l.cleanup_status = 'success', false))))
)`));
const versions = new Set<string>();
for (const { pins, legacyInput, id, agentId, nativeIssueId } of rows) {
if (legacyInput != null) {
// Older native runs captured the complete selection in their immutable
// execution input before contextSnapshot.skillVersions was introduced.
// Use the recovery parser (including digest validation) and the exact run
// binding. Never repair a malformed modern pin map with a different source.
try {
const input = parseNativeExecutionInput(legacyInput);
if (!("runtimeContext" in input) || input.binding.companyId !== companyId
|| input.binding.runId !== id || input.binding.agentId !== agentId
|| input.binding.issueId !== nativeIssueId) return null;
for (const skill of input.runtimeContext.skills) {
// Unversioned skills have their own captured asset bundle; they do
// not reference a directory under __versions__.
if (skill.versionId === null) continue;
if (!uuid.test(skill.versionId)) return null;
versions.add(skill.versionId);
}
continue;
} catch { return null; }
}
// Legacy/incomplete preparation is not proof that no skill is in use.
if (!pins || typeof pins !== "object" || Array.isArray(pins)) return null;
for (const version of Object.values(pins)) {
if (typeof version !== "string" || !uuid.test(version)) return null;
versions.add(version);
}
}
return versions;
}
function validateInventory(inventory: CompanySkillVersionFileInventoryEntry[]) {
const seen = new Set<string>();
for (const file of inventory) {
assertSkillSnapshotPath(file.path);
if (seen.has(file.path) || typeof file.content !== "string") return false;
seen.add(file.path);
}
return true;
}
export async function hasRestorableSnapshot(db: Db, companyId: string, versionId: string) {
const [version] = await db.select().from(companySkillVersions).where(and(
eq(companySkillVersions.companyId, companyId), eq(companySkillVersions.id, versionId)));
if (!version) return false;
if (version.repositorySnapshotId) {
if (!version.repositorySkillPath) return false;
let cache = verifiedSnapshots.get(db);
if (!cache) { cache = new Map(); verifiedSnapshots.set(db, cache); }
const key = `${companyId}:${version.repositorySnapshotId}`;
const verified = cache.get(key);
if (verified) return verified.has(version.repositorySkillPath);
const [snapshot] = await db.select({ inventory: companySkillRepositorySnapshots.fileInventory })
.from(companySkillRepositorySnapshots).where(and(eq(companySkillRepositorySnapshots.companyId, companyId),
eq(companySkillRepositorySnapshots.id, version.repositorySnapshotId)));
if (!snapshot || !validateInventory(snapshot.inventory)) return false;
const entrypoints = new Set(snapshot.inventory.filter(file => file.encoding !== "base64"
&& repositorySkillFrontmatter(file.content)).map(file => file.path));
if (cache.size >= 128) cache.delete(cache.keys().next().value!);
cache.set(key, entrypoints);
return entrypoints.has(version.repositorySkillPath);
}
return validateInventory(version.fileInventory) && version.fileInventory.some(file => file.path === "SKILL.md");
}
// Counts allocated bytes without following links, matching what df can reclaim.
export async function allocatedBytes(directory: string, shouldContinue: () => boolean = () => true): Promise<number> {
if (!shouldContinue()) throw new Error("Skill cache scan stopped");
const stat = await fs.lstat(directory);
if (stat.isSymbolicLink() || (!stat.isDirectory() && !stat.isFile())) throw new Error("Unsafe skill cache entry");
let bytes = stat.blocks * 512;
if (stat.isDirectory()) {
for (const entry of await fs.readdir(directory)) bytes += await allocatedBytes(path.join(directory, entry), shouldContinue);
}
return bytes;
}