Files
Verso/services/clsi/app/js/TypstRunner.js
T
claude b8543c8bb9
Build and Deploy Verso / deploy (push) Has been cancelled
fix: capture typst diagnostics emitted after the status line
typst watch outputs the "[HH:MM:SS] compiled with errors" status line
FIRST, then the full diagnostic output (file:line:col, source snippets,
hints) AFTERWARDS. The previous code resolved the pending compile
promise as soon as COMPILE_DONE_RE fired, discarding all post-status
diagnostic lines. Those lines then got cleared by the next cycle's
COMPILE_START_RE, so output.log only ever contained the bare status
line — explaining the "zero verbosity" symptom.

Fix: introduce a two-phase buffering model. When COMPILE_DONE_RE fires,
enter "post-done" phase (storing doneResult) and keep accumulating into
currentLines. _finalizeCompile() is called either when the next
COMPILE_START_RE arrives (zero added latency) or after FLUSH_DELAY_MS
(150 ms fallback for the last compile). It concatenates pre-done and
post-done lines before resolving, so output.log now contains the full
diagnostic output.

Co-Authored-By: Claude Sonnet 4.6 <noreply@anthropic.com>
2026-06-08 12:25:43 +00:00

494 lines
17 KiB
JavaScript

import Path from 'node:path'
import { spawn } from 'node:child_process'
import { promisify } from 'node:util'
import logger from '@overleaf/logger'
import Settings from '@overleaf/settings'
import CommandRunner from './CommandRunner.js'
import fs from 'node:fs'
// ---------------------------------------------------------------------------
// Constants
// ---------------------------------------------------------------------------
// Max lines kept from the current compile cycle (prevents unbounded growth
// for documents that produce many warnings).
const MAX_LOG_LINES = 500
// How long to wait for the watcher process to emit its first output.
const WATCH_START_TIMEOUT_MS = 15_000
// Matches the start-of-compile marker typst watch emits before each cycle:
// "[HH:MM:SS] compiling ..."
// Used to reset the line buffer so stale output from a failed compile that
// didn't emit a "compiled with errors" footer cannot bleed into the next log.
const COMPILE_START_RE = /^\[\d{2}:\d{2}:\d{2}\] compiling/
// Matches the three terminal lines that typst watch emits at the end of each
// compile cycle regardless of outcome:
// "[HH:MM:SS] compiled successfully in 42ms"
// "[HH:MM:SS] compiled with warnings in 42ms"
// "[HH:MM:SS] compiled with errors"
const COMPILE_DONE_RE = /compiled (successfully|with (errors|warnings))/
// Signals FileId exhaustion in a long-lived typst process (typst issue #7434).
const FILE_ID_EXHAUSTION_RE = /ran out of file ids/i
// Proactively restart the watcher before FileId exhaustion.
// Typst uses ~65 IDs per compile; 1000 compiles ≈ 65 000 — safely under 65 535.
const MAX_COMPILES_BEFORE_RESTART = 1000
// typst watch emits the "[HH:MM:SS] compiled with errors" status line FIRST,
// then the full diagnostic output (file:line:col, code snippets) AFTERWARDS.
// We buffer post-done lines and resolve after this delay if no new compile
// cycle starts sooner. 150 ms is well above the ~1 chunk latency for typst's
// diagnostic flush and imperceptible on top of a typical compile time.
const FLUSH_DELAY_MS = 150
// ---------------------------------------------------------------------------
// State (module-level, never exported)
// ---------------------------------------------------------------------------
// Active cold-start compile jobs (Docker fallback): compileName → PID
const ProcessTable = {}
// Long-lived watcher processes: compileName → WatchEntry
// WatchEntry shape:
// proc ChildProcess
// directory compile dir (absolute path)
// mainFile root .typ filename
// environment env vars passed to the runner
// compilationCount total successful compile cycles on this watcher
// restartPending flag to restart at the next runTypst call
// accumulator incomplete trailing line from the last data chunk
// currentLines lines accumulated in the current phase (pre-done or
// post-done, see _onWatcherData for the two-phase logic)
// doneResult { preLines, compiledWithErrors } held between the
// COMPILE_DONE_RE line and the post-done diagnostic flush;
// null when not in post-done phase
// flushTimeout timeout handle that finalises doneResult when no next
// compile cycle starts within FLUSH_DELAY_MS
// pendingResolvers Array<{resolve, reject, timeoutHandle}>
// pendingResult compile result cached when typst finished before a
// resolver was registered (race-condition safety net)
const WatchTable = {}
// PIDs we have intentionally killed, so the close handler can distinguish
// an expected exit from an unexpected crash.
const _killedWatchPids = new Set()
// ---------------------------------------------------------------------------
// Public entry point
// ---------------------------------------------------------------------------
async function runTypstAsync(compileName, options) {
// Docker / sandboxed mode: fall back to a cold-start compile per request.
if (Settings.clsi?.dockerRunner) {
return _runColdStart(compileName, options)
}
const timeout = options.timeout || 60_000
const entry = WatchTable[compileName]
const needsStart =
!entry ||
entry.restartPending ||
entry.proc.exitCode !== null
if (needsStart) {
if (entry) _killWatchEntry(compileName)
// _startWatcher spawns the process, registers all handlers, then calls
// _waitForNextCompile synchronously — the resolver is in pendingResolvers
// before any I/O event can fire, eliminating the race condition.
const result = await _startWatcher(compileName, options)
await _writeLogOutputAsync(compileName, options.directory, result)
if (result.compiledWithErrors) {
throw Object.assign(new Error('typst-compile-failure'), {
typstCompileFailure: true,
})
}
return result
}
// Watcher is alive. _waitForNextCompile adds the resolver synchronously
// inside the Promise constructor, before this function yields — safe.
const result = await _waitForNextCompile(compileName, timeout)
await _writeLogOutputAsync(compileName, options.directory, result)
if (result.compiledWithErrors) {
throw Object.assign(new Error('typst-compile-failure'), {
typstCompileFailure: true,
})
}
return result
}
// ---------------------------------------------------------------------------
// Watcher lifecycle
// ---------------------------------------------------------------------------
async function _startWatcher(compileName, options) {
const { directory, mainFile, environment } = options
const timeout = options.timeout || 60_000
const absInput = Path.join(directory, mainFile)
const absOutput = Path.join(directory, 'output.pdf')
const env = { ...process.env, ...(environment || {}) }
logger.debug({ compileName, absInput }, 'starting typst watcher')
const proc = spawn(
'/bin/sh',
['-c', `typst watch "${absInput}" "${absOutput}" 2>&1`],
{
cwd: directory,
env,
stdio: ['ignore', 'pipe', 'ignore'],
detached: true,
}
)
const entry = {
proc,
directory,
mainFile,
environment,
compilationCount: 0,
restartPending: false,
accumulator: '',
currentLines: [],
doneResult: null,
flushTimeout: null,
pendingResolvers: [],
pendingResult: null,
}
WatchTable[compileName] = entry
// Register handlers synchronously — before any I/O events can fire.
proc.stdout.setEncoding('utf8')
proc.stdout.on('data', chunk => _onWatcherData(compileName, chunk))
proc.on('error', err => {
logger.error({ err, compileName }, 'typst watcher process error')
_rejectAllPending(
compileName,
Object.assign(err, { terminated: true })
)
if (WatchTable[compileName]?.proc === proc) {
delete WatchTable[compileName]
}
})
proc.on('close', (code, signal) => {
logger.warn({ code, signal, compileName }, 'typst watcher exited')
const wasKilled = _killedWatchPids.delete(proc.pid)
if (!wasKilled) {
_rejectAllPending(
compileName,
Object.assign(new Error('typst watcher exited unexpectedly'), {
terminated: true,
})
)
}
if (WatchTable[compileName]?.proc === proc) {
delete WatchTable[compileName]
}
})
// typst watch performs an initial compile immediately on startup.
// _waitForNextCompile adds the resolver synchronously here (inside the
// Promise constructor) before we yield, so it will catch that first event.
return _waitForNextCompile(compileName, timeout + WATCH_START_TIMEOUT_MS)
}
function _killWatchEntry(compileName) {
const entry = WatchTable[compileName]
if (!entry) return
clearTimeout(entry.flushTimeout)
delete WatchTable[compileName]
try {
_killedWatchPids.add(entry.proc.pid)
process.kill(-entry.proc.pid) // kill entire process group
} catch (err) {
_killedWatchPids.delete(entry.proc.pid)
logger.warn({ err, compileName }, 'error killing typst watcher process group')
}
}
// ---------------------------------------------------------------------------
// Stdout parsing
// ---------------------------------------------------------------------------
function _onWatcherData(compileName, chunk) {
const entry = WatchTable[compileName]
if (!entry) return
entry.accumulator += chunk
const lines = entry.accumulator.split('\n')
entry.accumulator = lines.pop() // keep the incomplete trailing fragment
for (const line of lines) {
if (COMPILE_START_RE.test(line)) {
// A new compile cycle is starting. If we were in the post-done phase
// (collecting diagnostic lines that typst emits AFTER the status line),
// finalise the previous result now — all diagnostics have arrived.
if (entry.doneResult) {
_finalizeCompile(compileName)
}
// Start fresh for the new cycle.
entry.currentLines = [line]
continue
}
entry.currentLines.push(line)
if (entry.currentLines.length > MAX_LOG_LINES) {
entry.currentLines.shift()
}
if (FILE_ID_EXHAUSTION_RE.test(line)) {
logger.warn({ compileName }, 'typst watcher: FileId exhaustion detected')
entry.restartPending = true
}
if (COMPILE_DONE_RE.test(line)) {
entry.compilationCount++
if (entry.compilationCount >= MAX_COMPILES_BEFORE_RESTART) {
logger.info(
{ compileName, compilationCount: entry.compilationCount },
'typst watcher: scheduling restart (FileId threshold)'
)
entry.restartPending = true
}
// typst watch outputs the "[HH:MM:SS] compiled with errors" status
// line FIRST, then the full diagnostics (file:line:col, code snippets)
// AFTERWARDS. Enter post-done phase: keep accumulating into currentLines
// and flush after FLUSH_DELAY_MS (or immediately when the next compile
// cycle's COMPILE_START_RE arrives, whichever comes first).
entry.doneResult = {
preLines: entry.currentLines,
compiledWithErrors: /compiled with errors/.test(line),
}
entry.currentLines = []
clearTimeout(entry.flushTimeout)
entry.flushTimeout = setTimeout(
() => _finalizeCompile(compileName),
FLUSH_DELAY_MS
)
}
}
}
// Combines the pre-done lines (up to/including the status line) with any
// post-done diagnostic lines and resolves all pending waiters.
function _finalizeCompile(compileName) {
const entry = WatchTable[compileName]
if (!entry || !entry.doneResult) return
clearTimeout(entry.flushTimeout)
entry.flushTimeout = null
const { preLines, compiledWithErrors } = entry.doneResult
entry.doneResult = null
// Merge: status line(s) first, then the post-done diagnostics.
const allLines = preLines.concat(entry.currentLines)
entry.currentLines = []
_resolveAllPending(compileName, {
stdout: allLines.join('\n'),
compiledWithErrors,
})
}
// ---------------------------------------------------------------------------
// Resolver helpers
// ---------------------------------------------------------------------------
function _waitForNextCompile(compileName, timeout) {
return new Promise((resolve, reject) => {
const entry = WatchTable[compileName]
if (!entry) {
return reject(new Error('no typst watcher for ' + compileName))
}
// If typst finished a compile cycle before this resolver was registered
// (race: ResourceWriter wrote files → typst compiled → runTypst called),
// consume the cached result immediately instead of waiting for a timeout.
if (entry.pendingResult) {
const result = entry.pendingResult
entry.pendingResult = null
return resolve(result)
}
// Push synchronously inside the Promise constructor — before the first
// await in the caller, so no data event can fire in the gap.
const timeoutHandle = setTimeout(() => {
entry.pendingResolvers = entry.pendingResolvers.filter(r => r !== resolver)
reject(
Object.assign(new Error('typst compile timed out'), { timedout: true })
)
}, timeout)
const resolver = { resolve, reject, timeoutHandle }
entry.pendingResolvers.push(resolver)
})
}
function _resolveAllPending(compileName, result) {
const entry = WatchTable[compileName]
if (!entry) return
const resolvers = entry.pendingResolvers.splice(0)
if (resolvers.length === 0) {
// typst compiled before a resolver was registered — cache the result so
// the next _waitForNextCompile call can consume it immediately.
entry.pendingResult = result
return
}
for (const { resolve, timeoutHandle } of resolvers) {
clearTimeout(timeoutHandle)
resolve(result)
}
}
function _rejectAllPending(compileName, err) {
const entry = WatchTable[compileName]
if (!entry) return
for (const { reject, timeoutHandle } of entry.pendingResolvers.splice(0)) {
clearTimeout(timeoutHandle)
reject(err)
}
}
// ---------------------------------------------------------------------------
// Log output
// ---------------------------------------------------------------------------
async function _writeLogOutputAsync(compileName, directory, output) {
const content = (output && output.stdout) || ''
if (!content) return
// Write to output.log so the PDF-preview log panel picks it up.
const logFile = Path.join(directory, 'output.log')
try {
await fs.promises.unlink(logFile)
} catch (err) {
if (err.code !== 'ENOENT') {
logger.error({ err, compileName, logFile }, 'error removing typst log')
}
}
try {
await fs.promises.writeFile(logFile, content, { flag: 'wx' })
} catch (err) {
if (err.code !== 'EEXIST') {
logger.error({ err, compileName, logFile }, 'error writing typst log')
}
}
}
// ---------------------------------------------------------------------------
// Cold-start fallback (Docker / sandboxed mode)
// ---------------------------------------------------------------------------
function _runColdStart(compileName, options) {
return new Promise((resolve, reject) => {
const { directory, mainFile, image, environment, compileGroup } = options
const timeout = options.timeout || 60_000
logger.debug({ directory, mainFile, compileGroup }, 'typst cold-start compile')
const inputPath = `$COMPILE_DIR/${mainFile}`
const command = ['/bin/sh', '-c', `typst compile ${inputPath} output.pdf 2>&1`]
ProcessTable[compileName] = CommandRunner.run(
compileName,
command,
directory,
image,
timeout,
environment || {},
compileGroup,
null,
function (error, output) {
delete ProcessTable[compileName]
if (error && (error.terminated || error.timedout)) {
return reject(error)
}
const combined =
output || (error ? { stdout: error.stdout || '' } : null)
_writeLogOutputAsync(compileName, directory, combined).then(
() => {
if (error && combined?.stdout) {
// Non-zero exit with output = typst compile error (not a
// system/infra error). Signal failure so the log panel opens.
reject(
Object.assign(new Error('typst-compile-failure'), {
typstCompileFailure: true,
})
)
} else if (error) {
reject(error)
} else {
resolve(combined)
}
},
reject
)
}
)
})
}
// ---------------------------------------------------------------------------
// Public interface
// ---------------------------------------------------------------------------
function isRunning(compileName) {
return (
ProcessTable[compileName] != null ||
(WatchTable[compileName]?.pendingResolvers.length > 0)
)
}
function killTypst(compileName, callback) {
logger.debug({ compileName }, 'killing typst (watcher + any active compile)')
// Cold-start fallback path
if (ProcessTable[compileName] != null) {
CommandRunner.kill(ProcessTable[compileName], () => {})
delete ProcessTable[compileName]
}
// Reject any in-flight waiters and tear down the watcher process
_rejectAllPending(
compileName,
Object.assign(new Error('terminated'), { terminated: true })
)
_killWatchEntry(compileName)
callback(null)
}
// Kill all watcher processes when the CLSI Node process exits.
process.on('exit', () => {
for (const compileName of Object.keys(WatchTable)) {
_killWatchEntry(compileName)
}
})
const runTypst = (compileName, options, callback) => {
runTypstAsync(compileName, options).then(
result => callback(null, result),
err => callback(err)
)
}
export default {
isRunning,
runTypst,
killTypst,
promises: {
runTypst: runTypstAsync,
killTypst: promisify(killTypst),
},
}