diff --git a/apps/cli/lib/daemon-client.ts b/apps/cli/lib/daemon-client.ts index 0c4a5055c7..de3517d324 100644 --- a/apps/cli/lib/daemon-client.ts +++ b/apps/cli/lib/daemon-client.ts @@ -246,12 +246,13 @@ const daemonListProcessesSuccessResponseSchema = z.object( { // Cache the process list returned from the process manager for a very short time to make multiple // calls in quick succession more efficient -const listProcesses = cacheFunctionTTL( async () => { +async function listProcesses() { + await connectToDaemon(); const response = await sendDaemonRequest( { type: 'list-processes', } ); return daemonListProcessesSuccessResponseSchema.parse( response ).processes; -} ); +} export async function getDaemonBus(): Promise< DaemonBus > { if ( ! daemonBus ) { @@ -289,10 +290,6 @@ export async function isProcessRunning( processName: string ): Promise< ProcessDescription | undefined > { try { - if ( ! isConnected ) { - return undefined; - } - const processes = await listProcesses(); return processes.find( ( p ) => p.name === processName && p.status === 'online' ); } catch ( error ) { @@ -322,6 +319,12 @@ export async function startProcess( } export async function stopProcess( processName: string ): Promise< void > { + const runningProcess = await isProcessRunning( processName ); + + if ( ! runningProcess ) { + return; + } + await connectToDaemon(); await sendDaemonRequest( { type: 'stop-process', diff --git a/apps/cli/lib/tests/wordpress-server-manager.test.ts b/apps/cli/lib/tests/wordpress-server-manager.test.ts index 8264441009..442d642c33 100644 --- a/apps/cli/lib/tests/wordpress-server-manager.test.ts +++ b/apps/cli/lib/tests/wordpress-server-manager.test.ts @@ -46,6 +46,7 @@ describe( 'WordPress Server Manager', () => { vi.mocked( daemonClient.startProcess ).mockResolvedValue( mockProcessDescription ); vi.mocked( daemonClient.stopProcess ).mockResolvedValue( undefined ); vi.mocked( daemonClient.getDaemonBus ).mockResolvedValue( mockBus as DaemonBus ); + vi.mocked( daemonClient.sendMessageToProcess ).mockReturnValue( Promise.resolve() ); } ); afterEach( () => { @@ -133,14 +134,51 @@ describe( 'WordPress Server Manager', () => { describe( 'stopWordPressServer', () => { it( 'should stop WordPress server with correct process name', async () => { - await stopWordPressServer( 'test-site-id' ); + vi.mocked( daemonClient.isProcessRunning ).mockResolvedValue( { + name: 'studio-site-test-site-id', + pmId: 1, + status: 'online', + pid: 1234, + } ); - expect( vi.mocked( daemonClient.stopProcess ) ).toHaveBeenCalledWith( - 'studio-site-test-site-id' - ); + vi.mocked( daemonClient.sendMessageToProcess ).mockImplementation( ( processId, message ) => { + setImmediate( () => { + mockBus.emit( 'process-message', { + process: { name: 'studio-site-test-site-id', pm_id: 1 }, + raw: { + topic: 'result', + originalMessageId: message.messageId, + }, + } ); + } ); + + return Promise.resolve(); + } ); + + const promise = stopWordPressServer( 'test-site-id' ); + + setTimeout( () => { + mockBus.emit( 'process-event', { + process: { name: 'studio-site-test-site-id', pm_id: 1 }, + event: 'exit', + } ); + }, 500 ); + + await promise; + + expect( vi.mocked( daemonClient.stopProcess ) ).not.toHaveBeenCalled(); } ); - it( 'should propagate stopProcess errors', async () => { + it( 'should propagate errors from fallback `stopProcess` call', async () => { + vi.mocked( daemonClient.isProcessRunning ).mockResolvedValue( { + name: 'studio-site-test-site-id', + pmId: 1, + status: 'online', + pid: 1234, + } ); + vi.mocked( daemonClient.sendMessageToProcess ).mockRejectedValue( + new Error( 'Failed to send stop message' ) + ); vi.mocked( daemonClient.stopProcess ).mockRejectedValue( new Error( 'Failed to stop process' ) ); diff --git a/apps/cli/lib/wordpress-server-manager.ts b/apps/cli/lib/wordpress-server-manager.ts index e74249d887..5df3dfd8bc 100644 --- a/apps/cli/lib/wordpress-server-manager.ts +++ b/apps/cli/lib/wordpress-server-manager.ts @@ -209,7 +209,9 @@ export async function sendMessage( ? `Maximum timeout of ${ maxTotalElapsedTime / 1000 }s exceeded` : `No activity for ${ PLAYGROUND_CLI_INACTIVITY_TIMEOUT / 1000 }s`; reject( - new Error( `Timeout waiting for response to message ${ messageId }: ${ timeoutReason }` ) + new Error( + `Timeout waiting for response to message ${ message.topic }: ${ timeoutReason }` + ) ); } }, PLAYGROUND_CLI_ACTIVITY_CHECK_INTERVAL ); @@ -279,20 +281,42 @@ export async function stopWordPressServer( siteId: string ): Promise< void > { const processName = getProcessName( siteId ); const runningProcess = await isProcessRunning( processName ); - if ( runningProcess ) { - try { - await sendMessage( - runningProcess.pmId, - processName, - { topic: 'stop-server', data: {} }, - { maxTotalElapsedTime: GRACEFUL_STOP_TIMEOUT } - ); - } catch { - // Graceful shutdown failed, `stopProcess()` will handle it - } + if ( ! runningProcess ) { + return; } - return stopProcess( processName ); + try { + const bus = await getDaemonBus(); + let busExitEventListener: ( event: DaemonBusEventMap[ 'process-event' ] ) => void; + + const exitPromise = new Promise< void >( ( resolve ) => { + busExitEventListener = ( event: DaemonBusEventMap[ 'process-event' ] ) => { + if ( event.process.name === processName && event.event === 'exit' ) { + resolve(); + } + }; + + bus.on( 'process-event', busExitEventListener ); + } ).finally( () => { + bus.off( 'process-event', busExitEventListener ); + } ); + + await sendMessage( + runningProcess.pmId, + processName, + { topic: 'stop-server', data: {} }, + { maxTotalElapsedTime: GRACEFUL_STOP_TIMEOUT } + ); + + // Allow 5 seconds (arbitrary number) of cleanup time for the child process before throwing an + // exception and telling the process manager to send a SIGKILL signal. + await Promise.race( [ + exitPromise, + new Promise( ( resolve, reject ) => setTimeout( reject, 5000 ) ), + ] ); + } catch { + return stopProcess( processName ); + } } export interface RunBlueprintOptions { diff --git a/apps/cli/process-manager-daemon.ts b/apps/cli/process-manager-daemon.ts index 95290a7e44..e54e248958 100644 --- a/apps/cli/process-manager-daemon.ts +++ b/apps/cli/process-manager-daemon.ts @@ -2,6 +2,7 @@ import { ChildProcess, spawn } from 'child_process'; import fs, { createWriteStream, WriteStream } from 'fs'; import net from 'net'; import path from 'path'; +import readline from 'readline'; import semver from 'semver'; import { PROCESS_MANAGER_LOGS_DIR, @@ -51,6 +52,19 @@ function getProcessLogPaths( processName: string ) { }; } +function timestampLogLine( line: string ): string { + return `${ new Date().toISOString() } ${ line }\n`; +} + +function writeTimestampedLines( target: WriteStream, content: string ) { + const normalizedContent = content.split( '\r\n' ).join( '\n' ); + const lines = normalizedContent.trimEnd().split( '\n' ); + + lines.forEach( ( line ) => { + target.write( timestampLogLine( line ) ); + } ); +} + export class ProcessManagerDaemon { private readonly controlServer = new SocketServer( PROCESS_MANAGER_CONTROL_SOCKET_PATH, @@ -210,8 +224,8 @@ export class ProcessManagerDaemon { this.managedProcesses.set( pmId, managedProcess ); - child.stdout?.pipe( stdoutStream ); - child.stderr?.pipe( stderrStream ); + this.pipeOutputWithTimestamp( child.stdout, stdoutStream ); + this.pipeOutputWithTimestamp( child.stderr, stderrStream ); child.on( 'message', ( raw ) => { const event = daemonEventSchema.safeParse( { @@ -228,7 +242,7 @@ export class ProcessManagerDaemon { } ); child.on( 'error', ( error ) => { - void stderrStream.write( `${ error.stack ?? error.message }\n` ); + writeTimestampedLines( stderrStream, error.stack ?? error.message ); void this.handleProcessExit( managedProcess ); } ); @@ -320,6 +334,24 @@ export class ProcessManagerDaemon { this.eventsServer.broadcast( event ); } + private pipeOutputWithTimestamp( + input: NodeJS.ReadableStream | null, + target: WriteStream + ): void { + if ( ! input ) { + return; + } + + const lineReader = readline.createInterface( { + input, + crlfDelay: Infinity, + } ); + + lineReader.on( 'line', ( line ) => { + void target.write( timestampLogLine( line ) ); + } ); + } + private toProcessDescription( managedProcess: ManagedProcess ): ProcessDescription { if ( managedProcess.status === 'stopped' ) { return { diff --git a/apps/cli/wordpress-server-child.ts b/apps/cli/wordpress-server-child.ts index fda5a5821c..92ca09bcd4 100644 --- a/apps/cli/wordpress-server-child.ts +++ b/apps/cli/wordpress-server-child.ts @@ -38,7 +38,6 @@ import { } from 'cli/lib/types/wordpress-server-ipc'; let server: RunCLIServer | null = null; -let startingPromise: Promise< void > | null = null; let lastCliArgs: Record< string, unknown > | null = null; // Intercept and prefix all console output from playground-cli @@ -80,11 +79,11 @@ process.stderr.write = function ( ...args: Parameters< typeof originalStderrWrit } as typeof process.stderr.write; function logToConsole( ...args: Parameters< typeof console.log > ) { - originalConsoleLog( new Date().toISOString(), `[WordPress Server Child]`, ...args ); + originalConsoleLog( `[WordPress Server Child]`, ...args ); } function errorToConsole( ...args: Parameters< typeof console.error > ) { - originalConsoleError( new Date().toISOString(), `[WordPress Server Child]`, ...args ); + originalConsoleError( `[WordPress Server Child]`, ...args ); } function escapePhpString( str: string ): string { @@ -260,13 +259,23 @@ async function getBaseRunCLIArgs( args.xdebug = true; } + lastCliArgs = sanitizeRunCLIArgs( args ); return args; } +let startupAbortController: AbortController | null = null; +let startingPromise: Promise< void > | null = null; + +// We allow a single `startServer` call per process. If that call throws, we expect +// `ipcMessageHandler` to kill the process. function wrapWithStartingPromise< Args extends unknown[], Return extends void >( callback: ( ...args: Args ) => Promise< Return > ) { return async ( ...args: Args ) => { + if ( startingPromise ) { + return startingPromise; + } + startingPromise = callback( ...args ); return startingPromise; }; @@ -279,19 +288,17 @@ const startServer = wrapWithStartingPromise( return; } + startupAbortController = new AbortController(); + const stopSignal = AbortSignal.any( [ signal, startupAbortController.signal ] ); + try { - signal.addEventListener( - 'abort', - () => { - throw new Error( 'Operation aborted' ); - }, - { once: true } - ); + stopSignal.throwIfAborted(); const args = await getBaseRunCLIArgs( 'server', config ); - lastCliArgs = sanitizeRunCLIArgs( args ); server = await runCLI( args ); + stopSignal.throwIfAborted(); + if ( config.adminPassword || config.adminUsername || config.adminEmail ) { await setAdminCredentials( server, @@ -300,51 +307,79 @@ const startServer = wrapWithStartingPromise( config.adminEmail ); } + + stopSignal.throwIfAborted(); } catch ( error ) { - server = null; - errorToConsole( `Failed to start server:`, error ); + if ( server ) { + await server[ Symbol.asyncDispose ](); + server = null; + } + + if ( error instanceof Error && error.name === 'AbortError' ) { + logToConsole( `Aborted start server operation:`, error ); + } else { + errorToConsole( `Failed to start server:`, error ); + } + + // Rethrowing the error so that `ipcMessageHandler` returns an error IPC response and kills the process throw error; + } finally { + startupAbortController = null; } } ); const STOP_SERVER_TIMEOUT = 5000; -async function stopServer(): Promise< void > { +enum StopServerResult { + ABORTED_STARTUP = 'ABORTED_STARTUP', + OK = 'OK', +} + +async function stopServer(): Promise< StopServerResult > { + // If there's a startup in progress, abort and return gracefully. The `startServer` function will + // throw because of the aborted signal, leading `ipcMessageHandler` to return an error IPC + // response and killing the process. + if ( startupAbortController ) { + logToConsole( 'Startup operation in progress. Aborting it to stop the server…' ); + startupAbortController.abort(); + return StopServerResult.ABORTED_STARTUP; + } + + // If there's no `startupAbortController` and no `server` instance, then it's likely the client + // never sent a `start-server` message. Return gracefully so `ipcMessageHandler` can disconnect + // IPC and allow the process to (hopefully) exit cleanly. if ( ! server ) { logToConsole( 'No server running, nothing to stop' ); - return; + return StopServerResult.OK; } - const serverToDispose = server; - server = null; - try { const disposalTimeout = new Promise< void >( ( _, reject ) => setTimeout( () => reject( new Error( 'Server disposal timeout' ) ), STOP_SERVER_TIMEOUT ) ); - await Promise.race( [ serverToDispose[ Symbol.asyncDispose ](), disposalTimeout ] ); + await Promise.race( [ server[ Symbol.asyncDispose ](), disposalTimeout ] ); logToConsole( 'Server stopped gracefully' ); + return StopServerResult.OK; } catch ( error ) { errorToConsole( 'Error during server disposal:', error ); + // Rethrowing the error so that `ipcMessageHandler` returns an error IPC response and kills the process + throw error; + } finally { + server = null; } } async function runBlueprint( config: ServerConfig, signal: AbortSignal ): Promise< void > { try { - signal.addEventListener( - 'abort', - () => { - throw new Error( 'Operation aborted' ); - }, - { once: true } - ); + signal.throwIfAborted(); const args = await getBaseRunCLIArgs( 'run-blueprint', config ); - lastCliArgs = sanitizeRunCLIArgs( args ); await runCLI( args ); + signal.throwIfAborted(); + logToConsole( `Blueprint applied successfully for site ${ config.siteId }` ); } catch ( error ) { errorToConsole( `Failed to run Blueprint:`, error ); @@ -363,6 +398,8 @@ const runWpCliCommand = sequential( throw new Error( `Failed to run WP CLI command because server is not running` ); } + logToConsole( `Running WP-CLI command:`, args ); + signal.addEventListener( 'abort', () => { @@ -424,15 +461,19 @@ function parsePhpError( error: unknown ): string { return message; } -function sendErrorMessage( messageId: string, error: unknown ) { - const errorResponse: ChildMessageRaw = { - originalMessageId: messageId, - topic: 'error', - errorMessage: parsePhpError( error ), - errorStack: error instanceof Error ? error.stack : undefined, - cliArgs: lastCliArgs ?? undefined, - }; - process.send!( errorResponse ); +function sendErrorMessage( messageId: string, error: unknown ): Promise< void > { + return new Promise( ( resolve ) => { + const errorResponse: ChildMessageRaw = { + originalMessageId: messageId, + topic: 'error', + errorMessage: parsePhpError( error ), + errorStack: error instanceof Error ? error.stack : undefined, + cliArgs: lastCliArgs ?? undefined, + }; + process.send!( errorResponse, () => { + resolve(); + } ); + } ); } const abortControllers: Record< string, AbortController > = {}; @@ -446,7 +487,7 @@ async function ipcMessageHandler( packet: unknown ) { const minimalMessageSchema = z.object( { id: z.string() } ); const minimalMessage = minimalMessageSchema.safeParse( packet ); if ( minimalMessage.success ) { - sendErrorMessage( minimalMessage.data.id, messageResult.error ); + await sendErrorMessage( minimalMessage.data.id, messageResult.error ); } return; } @@ -457,13 +498,14 @@ async function ipcMessageHandler( packet: unknown ) { } const abortController = abortControllers[ validMessage.messageId ]; + logToConsole( `Received ${ validMessage.topic } message` ); + try { let result: unknown; switch ( validMessage.topic ) { case 'abort': abortController?.abort(); - delete abortControllers[ validMessage.messageId ]; return; case 'start-server': result = await startServer( validMessage.data.config, abortController.signal ); @@ -479,7 +521,7 @@ async function ipcMessageHandler( packet: unknown ) { result = await runWpCliCommand( validMessage.data.args, abortController.signal ); } catch ( wpCliError ) { errorToConsole( `WP-CLI error:`, wpCliError ); - sendErrorMessage( validMessage.messageId, wpCliError ); + await sendErrorMessage( validMessage.messageId, wpCliError ); return; // Don't crash, just return error to caller } break; @@ -493,10 +535,19 @@ async function ipcMessageHandler( packet: unknown ) { result, }; process.send!( response ); + + // If the `stopServer` function ran successfully, the last open handle should be the IPC channel. + // Disconnect so that the process can exit cleanly. + if ( validMessage.topic === 'stop-server' && result === StopServerResult.OK ) { + process.disconnect(); + } } catch ( error ) { errorToConsole( `Error handling message ${ validMessage.topic }:`, error ); - sendErrorMessage( validMessage.messageId, error ); + await sendErrorMessage( validMessage.messageId, error ); + originalConsoleLog( 'Killing process because of', error ); process.exit( 1 ); + } finally { + delete abortControllers[ validMessage.messageId ]; } } diff --git a/apps/studio/src/modules/cli/lib/execute-command.ts b/apps/studio/src/modules/cli/lib/execute-command.ts index 9e4ad4c68a..950aba44ff 100644 --- a/apps/studio/src/modules/cli/lib/execute-command.ts +++ b/apps/studio/src/modules/cli/lib/execute-command.ts @@ -29,6 +29,9 @@ class CliCommandError extends Error { this.exitCode = options.exitCode; this.signal = options.signal; this.name = 'CliCommandError'; + // The stack trace for this error is misleading, because it's not actually thrown where the error + // happened - it's just a representation of an error that happened in a different process. + this.stack = undefined; } get message(): string {