From d53d08b8cb8ae7279d19b3f62236ed4116ce3c83 Mon Sep 17 00:00:00 2001 From: bcotrim Date: Fri, 12 Jun 2026 14:24:35 +0100 Subject: [PATCH] Surface PHP startup errors when site start fails (STU-1757) --- .../export/exporters/default-exporter.ts | 2 + apps/cli/lib/read-file-tail.ts | 24 +++++++ apps/cli/lib/tests/read-file-tail.test.ts | 39 +++++++++++ .../tests/wordpress-server-manager.test.ts | 70 +++++++++++++++++++ apps/cli/lib/wordpress-server-manager.ts | 55 +++++++++++++++ apps/cli/playground-server-child.ts | 13 +++- apps/cli/process-manager-daemon.ts | 9 ++- apps/cli/tests/daemon.test.ts | 45 ++++++++++++ tools/common/lib/mu-plugins.ts | 31 ++++++++ tools/common/lib/sync/constants.ts | 4 ++ tools/common/lib/tests/mu-plugins.test.ts | 17 +++++ 11 files changed, 307 insertions(+), 2 deletions(-) create mode 100644 apps/cli/lib/read-file-tail.ts create mode 100644 apps/cli/lib/tests/read-file-tail.test.ts diff --git a/apps/cli/lib/import-export/export/exporters/default-exporter.ts b/apps/cli/lib/import-export/export/exporters/default-exporter.ts index 6260e73186..69a5d9cc97 100644 --- a/apps/cli/lib/import-export/export/exporters/default-exporter.ts +++ b/apps/cli/lib/import-export/export/exporters/default-exporter.ts @@ -7,6 +7,7 @@ import { generateBackupFilename } from '@studio/common/lib/generate-backup-filen import { createExportErrorPayload, ExportEvents } from '@studio/common/lib/import-export-events'; import { LEGACY_MU_PLUGIN_FILENAMES, + STUDIO_ERROR_LOG_FILENAME, STUDIO_LOADER_MU_PLUGIN_FILENAME, } from '@studio/common/lib/mu-plugins'; import { parseJsonFromPhpOutput } from '@studio/common/lib/php-output-parser'; @@ -45,6 +46,7 @@ export class DefaultExporter extends ImportExportEventEmitter implements Exporte 'wp-content/database', 'wp-content/db.php', 'wp-content/debug.log', + `wp-content/${ STUDIO_ERROR_LOG_FILENAME }`, ...prefixedLegacyMuPluginNames, `wp-content/mu-plugins/${ STUDIO_LOADER_MU_PLUGIN_FILENAME }`, ]; diff --git a/apps/cli/lib/read-file-tail.ts b/apps/cli/lib/read-file-tail.ts new file mode 100644 index 0000000000..332b8a397a --- /dev/null +++ b/apps/cli/lib/read-file-tail.ts @@ -0,0 +1,24 @@ +import { open } from 'fs/promises'; + +export async function readFileTail( filePath: string, maxBytes: number ): Promise< string > { + const file = await open( filePath, 'r' ); + try { + const { size } = await file.stat(); + const length = Math.min( size, maxBytes ); + if ( length === 0 ) { + return ''; + } + const { buffer } = await file.read( { + buffer: Buffer.alloc( length ), + position: size - length, + } ); + let tail = buffer.toString( 'utf8' ); + if ( length < size ) { + // Drop the first, likely partial, line of a truncated read. + tail = tail.slice( tail.indexOf( '\n' ) + 1 ); + } + return tail.trim(); + } finally { + await file.close(); + } +} diff --git a/apps/cli/lib/tests/read-file-tail.test.ts b/apps/cli/lib/tests/read-file-tail.test.ts new file mode 100644 index 0000000000..ace89d3e0d --- /dev/null +++ b/apps/cli/lib/tests/read-file-tail.test.ts @@ -0,0 +1,39 @@ +import { mkdtemp, writeFile } from 'fs/promises'; +import { tmpdir } from 'os'; +import { join } from 'path'; +import { readFileTail } from 'cli/lib/read-file-tail'; + +describe( 'readFileTail', () => { + let dir: string; + + beforeEach( async () => { + dir = await mkdtemp( join( tmpdir(), 'studio-test-tail-' ) ); + } ); + + it( 'should return the whole file when smaller than maxBytes', async () => { + const filePath = join( dir, 'small.log' ); + await writeFile( filePath, 'line one\nline two\n' ); + + expect( await readFileTail( filePath, 1024 ) ).toBe( 'line one\nline two' ); + } ); + + it( 'should return the trailing bytes and drop the partial first line when truncated', async () => { + const filePath = join( dir, 'large.log' ); + await writeFile( filePath, 'first line is long\nsecond line\nthird line\n' ); + + expect( await readFileTail( filePath, 'second line\nthird line\n'.length ) ).toBe( + 'third line' + ); + } ); + + it( 'should return an empty string for an empty file', async () => { + const filePath = join( dir, 'empty.log' ); + await writeFile( filePath, '' ); + + expect( await readFileTail( filePath, 1024 ) ).toBe( '' ); + } ); + + it( 'should reject for a missing file', async () => { + await expect( readFileTail( join( dir, 'missing.log' ), 1024 ) ).rejects.toThrow(); + } ); +} ); diff --git a/apps/cli/lib/tests/wordpress-server-manager.test.ts b/apps/cli/lib/tests/wordpress-server-manager.test.ts index 9bf423f3be..0e7436979e 100644 --- a/apps/cli/lib/tests/wordpress-server-manager.test.ts +++ b/apps/cli/lib/tests/wordpress-server-manager.test.ts @@ -1,4 +1,8 @@ import { EventEmitter } from 'events'; +import fs from 'fs'; +import os from 'os'; +import path from 'path'; +import { STUDIO_ERROR_LOG_FILENAME } from '@studio/common/lib/mu-plugins'; import { SITE_RUNTIME_NATIVE_PHP, SITE_RUNTIME_PLAYGROUND } from '@studio/common/lib/site-runtime'; import { vi } from 'vitest'; import { SiteData } from 'cli/lib/cli-config/core'; @@ -264,6 +268,72 @@ describe( 'WordPress Server Manager', () => { /early crash/ ); } ); + + it( 'should append PHP errors captured during the start attempt to the failure', async () => { + const sitePath = await fs.promises.mkdtemp( path.join( os.tmpdir(), 'studio-test-site-' ) ); + await fs.promises.mkdir( path.join( sitePath, 'wp-content' ), { recursive: true } ); + const logPath = path.join( sitePath, 'wp-content', STUDIO_ERROR_LOG_FILENAME ); + + setTimeout( () => { + fs.writeFileSync( logPath, 'PHP Fatal error: Uncaught Error: Failed opening required' ); + mockBus.emit( 'process-event', { + process: { + name: mockProcessDescription.name, + pm_id: mockProcessDescription.pmId, + }, + event: 'exit', + } ); + }, 10 ); + + await expect( + startWordPressServer( { ...mockSiteData, path: sitePath }, mockLogger ) + ).rejects.toThrow( /Recent PHP errors[\s\S]*PHP Fatal error/ ); + } ); + + it( 'should not append stale PHP errors from a previous run', async () => { + const sitePath = await fs.promises.mkdtemp( path.join( os.tmpdir(), 'studio-test-site-' ) ); + await fs.promises.mkdir( path.join( sitePath, 'wp-content' ), { recursive: true } ); + // Sites with the debug-log setting on read from debug.log, which Studio + // does not clear on start, so stale entries must be filtered by mtime. + const logPath = path.join( sitePath, 'wp-content', 'debug.log' ); + fs.writeFileSync( logPath, 'PHP Fatal error: from a previous run' ); + const past = new Date( Date.now() - 60_000 ); + fs.utimesSync( logPath, past, past ); + + setTimeout( () => { + mockBus.emit( 'process-event', { + process: { + name: mockProcessDescription.name, + pm_id: mockProcessDescription.pmId, + }, + event: 'exit', + } ); + }, 10 ); + + const error: Error = await startWordPressServer( + { ...mockSiteData, path: sitePath, enableDebugLog: true }, + mockLogger + ).then( + () => { + throw new Error( 'expected startWordPressServer to reject' ); + }, + ( e ) => e + ); + expect( error.message ).toContain( 'exited before becoming ready' ); + expect( error.message ).not.toContain( 'Recent PHP errors' ); + } ); + + it( 'should clear the studio error log from a previous run before starting', async () => { + setupIpcMocks(); + const sitePath = await fs.promises.mkdtemp( path.join( os.tmpdir(), 'studio-test-site-' ) ); + await fs.promises.mkdir( path.join( sitePath, 'wp-content' ), { recursive: true } ); + const logPath = path.join( sitePath, 'wp-content', STUDIO_ERROR_LOG_FILENAME ); + fs.writeFileSync( logPath, 'PHP Fatal error: from a previous run' ); + + await startWordPressServer( { ...mockSiteData, path: sitePath }, mockLogger ); + + expect( fs.existsSync( logPath ) ).toBe( false ); + } ); } ); describe( 'sendWpCliCommand', () => { diff --git a/apps/cli/lib/wordpress-server-manager.ts b/apps/cli/lib/wordpress-server-manager.ts index ddb74d6d4d..6f70342a20 100644 --- a/apps/cli/lib/wordpress-server-manager.ts +++ b/apps/cli/lib/wordpress-server-manager.ts @@ -11,6 +11,7 @@ import { PLAYGROUND_CLI_INACTIVITY_TIMEOUT, PLAYGROUND_CLI_MAX_TIMEOUT, } from '@studio/common/constants'; +import { STUDIO_ERROR_LOG_FILENAME } from '@studio/common/lib/mu-plugins'; import { resolveNativePhpVersion } from '@studio/common/lib/php-binary-metadata'; import { SITE_RUNTIME_NATIVE_PHP, @@ -31,6 +32,7 @@ import { } from 'cli/lib/daemon-client'; import { ensurePhpBinaryAvailable } from 'cli/lib/dependency-management/php-binary'; import { getSiteRuntime } from 'cli/lib/feature-flags'; +import { readFileTail } from 'cli/lib/read-file-tail'; import { ProcessDescription } from 'cli/lib/types/process-manager-ipc'; import { ServerConfig, ManagerMessagePayload } from 'cli/lib/types/wordpress-server-ipc'; import { Logger } from 'cli/logger'; @@ -231,6 +233,9 @@ export async function startWordPressServer( const processName = getProcessName( site.id ); const serverConfig = buildServerConfig( site, runtime, options ); + const startedAt = Date.now(); + await clearStudioErrorLog( site ); + const readyOrExit = await subscribeForReadyOrExit( processName ); try { const processDesc = await startProcess( processName, wordPressServerChildPath, { runtime } ); @@ -246,11 +251,61 @@ export async function startWordPressServer( ); return withSiteRuntime( processDesc ); + } catch ( error ) { + throw await withCapturedPhpErrors( error, site, startedAt ); } finally { readyOrExit.dispose(); } } +async function clearStudioErrorLog( site: SiteData ): Promise< void > { + const logPath = path.join( site.path, 'wp-content', STUDIO_ERROR_LOG_FILENAME ); + await fs.promises.rm( logPath, { force: true } ).catch( () => undefined ); +} + +const PHP_ERROR_TAIL_MAX_BYTES = 4096; + +/** + * Appends the PHP errors recorded during this start attempt to a startup + * failure, so users see why WordPress died (e.g. a plugin fatal) instead of + * just "process exited unexpectedly" (STU-1757). + */ +async function withCapturedPhpErrors( + error: unknown, + site: SiteData, + startedAt: number +): Promise< unknown > { + if ( + ! ( error instanceof Error ) || + error.name === 'AbortError' || + error.message === 'Operation aborted' + ) { + return error; + } + + // With the debug-log setting on, WordPress records errors to debug.log + // instead of the Studio-managed log. + const logFilename = site.enableDebugLog ? 'debug.log' : STUDIO_ERROR_LOG_FILENAME; + const logPath = path.join( site.path, 'wp-content', logFilename ); + + try { + const stats = await fs.promises.stat( logPath ); + // Only surface errors written during this start attempt; debug.log can + // hold stale entries from previous runs. + if ( stats.mtimeMs < startedAt ) { + return error; + } + const tail = await readFileTail( logPath, PHP_ERROR_TAIL_MAX_BYTES ); + if ( tail ) { + error.message += `\nRecent PHP errors (${ logPath }):\n${ tail }`; + } + } catch { + // No PHP error log to surface. + } + + return error; +} + function buildChildExitedError( processName: string, stderrTail?: string ): Error { let message = `Server child process "${ processName }" exited before becoming ready.`; if ( stderrTail?.trim() ) { diff --git a/apps/cli/playground-server-child.ts b/apps/cli/playground-server-child.ts index f9b212b40c..57d1ee8e3c 100644 --- a/apps/cli/playground-server-child.ts +++ b/apps/cli/playground-server-child.ts @@ -17,7 +17,11 @@ import { DEFAULT_PHP_VERSION } from '@studio/common/constants'; import { isWordPressDirectory } from '@studio/common/lib/fs-utils'; import { IS_JSPI_AVAILABLE } from '@studio/common/lib/jspi'; import { DEFAULT_LOCALE } from '@studio/common/lib/locale'; -import { cleanupLegacyMuPlugins, getMuPlugins } from '@studio/common/lib/mu-plugins'; +import { + cleanupLegacyMuPlugins, + getMuPlugins, + STUDIO_ERROR_LOG_FILENAME, +} from '@studio/common/lib/mu-plugins'; import { formatPlaygroundCliMessage } from '@studio/common/lib/playground-cli-messages'; import { sequential } from '@studio/common/lib/sequential'; import { isWordPressDevVersion } from '@studio/common/lib/wordpress-version-utils'; @@ -250,6 +254,13 @@ async function getBaseRunCLIArgs( const [ studioMuPluginsHostPath, loaderMuPluginHostPath ] = await getMuPlugins( { isWpAutoUpdating: config.isWpAutoUpdating, + // With the debug-log setting off nothing records PHP errors, leaving + // startup failures undiagnosable (STU-1757). Capture them to a + // Studio-managed log; `startWordPressServer` reads it back when the + // start fails. + ...( config.enableDebugLog + ? {} + : { errorLogPath: `/wordpress/wp-content/${ STUDIO_ERROR_LOG_FILENAME }` } ), } ); if ( ! useExactMountLayout ) { diff --git a/apps/cli/process-manager-daemon.ts b/apps/cli/process-manager-daemon.ts index 69725e773f..70c332b783 100644 --- a/apps/cli/process-manager-daemon.ts +++ b/apps/cli/process-manager-daemon.ts @@ -251,7 +251,14 @@ export class ProcessManagerDaemon { this.managedProcesses.set( pmId, managedProcess ); - this.pipeOutputWithTimestamp( child.stdout, stdoutStream ); + this.pipeOutputWithTimestamp( child.stdout, stdoutStream, ( line ) => { + // Playground CLI prints boot failures to stdout (with the noisy + // crash-page HTML on the following lines); keep the error line in + // the exit tail so start failures carry a reason. + if ( line.startsWith( 'Error:' ) ) { + this.recordStderrLine( managedProcess, line ); + } + } ); this.pipeOutputWithTimestamp( child.stderr, stderrStream, ( line ) => { this.recordStderrLine( managedProcess, line ); } ); diff --git a/apps/cli/tests/daemon.test.ts b/apps/cli/tests/daemon.test.ts index 06dc61e125..e232566545 100644 --- a/apps/cli/tests/daemon.test.ts +++ b/apps/cli/tests/daemon.test.ts @@ -179,6 +179,51 @@ describe( 'ProcessManagerDaemon', () => { expect( payload.stderrTail ).toContain( 'at Module._compile' ); } ); + it( 'includes stdout error lines in the exit event payload, skipping other stdout output', async () => { + const child = new MockChildProcess(); + spawnMock.mockReturnValue( child ); + const { ProcessManagerDaemon } = await import( '../process-manager-daemon' ); + + const daemon = new ProcessManagerDaemon(); + const daemonInternal = daemon as unknown as { + handleRequest: ( request: unknown ) => Promise< unknown >; + broadcastEvent: ( event: unknown ) => Promise< void >; + }; + const broadcastSpy = vi + .spyOn( daemonInternal, 'broadcastEvent' ) + .mockResolvedValue( undefined ); + + await daemonInternal.handleRequest( { + type: 'start-process', + requestId: '1', + processName: testProcessName, + scriptPath: '/tmp/test-child.js', + env: {}, + args: [], + } ); + + // Playground CLI prints boot failures to stdout, followed by the crash-page HTML. + child.stdout.write( 'WordPress Playground CLI\n' ); + child.stdout.write( 'Error: PHP.run() failed with exit code 255.\n' ); + child.stdout.write( '\n' ); + // Let readline consume the lines before triggering exit. + await new Promise( ( resolve ) => setTimeout( resolve, 25 ) ); + + child.emit( 'exit', 1 ); + await new Promise( ( resolve ) => setTimeout( resolve, 25 ) ); + + const exitCall = broadcastSpy.mock.calls.find( ( [ event ] ) => { + const payload = ( event as { type: string; payload: { event: string } } ).payload; + return payload.event === 'exit'; + } ); + + expect( exitCall ).toBeDefined(); + const payload = ( exitCall![ 0 ] as { payload: { stderrTail?: string } } ).payload; + expect( payload.stderrTail ).toContain( 'Error: PHP.run() failed with exit code 255.' ); + expect( payload.stderrTail ).not.toContain( 'DOCTYPE' ); + expect( payload.stderrTail ).not.toContain( 'WordPress Playground CLI' ); + } ); + it( 'reuses duplicate starts, forwards messages, and resolves missing stops', async () => { const child = new MockChildProcess(); spawnMock.mockReturnValue( child ); diff --git a/tools/common/lib/mu-plugins.ts b/tools/common/lib/mu-plugins.ts index dee7daf99f..8ca642d2ac 100644 --- a/tools/common/lib/mu-plugins.ts +++ b/tools/common/lib/mu-plugins.ts @@ -14,11 +14,18 @@ export interface MuPlugin { content: string; } +// Written inside the site's wp-content directory by the 0-error-capture +// mu-plugin; read back by the CLI when `site start` fails. +export const STUDIO_ERROR_LOG_FILENAME = 'studio-error.log'; + export type MuPluginRuntime = 'playground' | 'native-php'; export interface MuPluginOptions { isWpAutoUpdating?: boolean; runtime?: MuPluginRuntime; + // PHP errors are captured to this path (as seen by PHP, e.g. a VFS path + // for the Playground runtime) even when WP debug logging is off. + errorLogPath?: string; } /** @@ -165,6 +172,30 @@ function getStandardMuPlugins( options: MuPluginOptions ): MuPlugin[] { `, } ); + // Capture PHP errors while the user's debug-log setting is off, so site + // start failures (e.g. a plugin fatal during WordPress load) remain + // diagnosable. The path is baked in at write time because blueprint + // constants are not yet applied during the first boot request — exactly + // the one that fails (STU-1757). Playground's platform mu-plugins disable + // log_errors when WP_DEBUG_LOG is falsy and load after the Studio ones, + // so re-assert from a late muplugins_loaded hook in addition to setting + // immediately (the hook still fires within the current do_action pass). + if ( options.errorLogPath ) { + muPlugins.push( { + filename: '0-error-capture.php', + content: ` { expect( generatedPlugins ).not.toContain( '0-disable-auto-updates.php' ); } ); } ); + +describe( 'getMuPlugins error capture', () => { + it( 'should write the error-capture mu-plugin only when errorLogPath is set', async () => { + const [ withCapture ] = await getMuPlugins( { + errorLogPath: "/wordpress/wp-content/it's-a-log.log", + } ); + const capturePath = join( withCapture, '0-error-capture.php' ); + expect( existsSync( capturePath ) ).toBe( true ); + const content = await readFile( capturePath, 'utf8' ); + expect( content ).toContain( "ini_set( 'log_errors', '1' );" ); + expect( content ).toContain( "'/wordpress/wp-content/it\\'s-a-log.log'" ); + + const [ withoutCapture ] = await getMuPlugins(); + expect( existsSync( join( withoutCapture, '0-error-capture.php' ) ) ).toBe( false ); + } ); +} );