feat: capture plugin errors during ready phase (#5681)

packages/build/src/core/build.ts

@@ -481,6 +481,7 @@ const initAndRunBuild = async function ({
     timers: timersA,
     featureFlags,
     quiet,
+    systemLog,
     systemLogFile,
   })
 

packages/build/src/plugins/load.js

@@ -5,6 +5,7 @@ import { addPluginLoadErrorStatus } from '../status/load_error.js'
 import { measureDuration } from '../time/main.js'
 
 import { callChild } from './ipc.js'
+import { captureStandardError } from './system_log.js'
 
 const pSetTimeout = promisify(setTimeout)
 
@@ -79,20 +80,7 @@ const loadPlugin = async function (
 ) {
   const { childProcess } = childProcesses[index]
   const loadEvent = 'load'
-
-  // A buffer for any data piped into the child process' stderr. We'll pipe
-  // this to system logs if we fail to load the plugin.
-  const bufferedStdErr = []
-
-  let bufferedStdListener
-
-  if (featureFlags.netlify_build_plugin_system_log && childProcess.stderr) {
-    bufferedStdListener = (data) => {
-      bufferedStdErr.push(data.toString().trimEnd())
-    }
-
-    childProcess.stderr.on('data', bufferedStdListener)
-  }
+  const cleanup = captureStandardError(childProcess, systemLog, loadEvent, featureFlags)
 
   try {
     const { events } = await callChild({
@@ -115,10 +103,6 @@ const loadPlugin = async function (
     if (featureFlags.netlify_build_plugin_system_log) {
       // Wait for stderr to be flushed.
       await pSetTimeout(0)
-
-      bufferedStdErr.forEach((line) => {
-        systemLog(line)
-      })
     }
 
     addErrorInfo(error, {
@@ -128,8 +112,6 @@ const loadPlugin = async function (
     addPluginLoadErrorStatus({ error, packageName, version, debug })
     throw error
   } finally {
-    if (bufferedStdListener) {
-      childProcess.stderr.removeListener('data', bufferedStdListener)
-    }
+    cleanup()
   }
 }

packages/build/src/plugins/spawn.ts

@@ -1,10 +1,12 @@
 import { createRequire } from 'module'
 import { fileURLToPath, pathToFileURL } from 'url'
+import { promisify } from 'util'
 
 import { trace } from '@opentelemetry/api'
 import { ExecaChildProcess, execaNode } from 'execa'
 import { gte } from 'semver'
 
+import { FeatureFlags } from '../core/feature_flags.js'
 import { addErrorInfo } from '../error/info.js'
 import { NetlifyConfig } from '../index.js'
 import { BufferedLogs } from '../log/logger.js'
@@ -15,17 +17,19 @@ import {
   logOutdatedPlugins,
   logRuntime,
 } from '../log/messages/compatibility.js'
+import { SystemLogger } from '../plugins_core/types.js'
 import { isTrustedPlugin } from '../steps/plugin.js'
 import { measureDuration } from '../time/main.js'
 
 import { callChild, getEventFromChild } from './ipc.js'
 import { PluginsOptions } from './node_version.js'
 import { getSpawnInfo } from './options.js'
+import { captureStandardError } from './system_log.js'
 
 export type ChildProcess = ExecaChildProcess<string>
 
 const CHILD_MAIN_FILE = fileURLToPath(new URL('child/main.js', import.meta.url))
-
+const pSetTimeout = promisify(setTimeout)
 const require = createRequire(import.meta.url)
 
 // Start child processes used by all plugins
@@ -34,7 +38,17 @@ const require = createRequire(import.meta.url)
 //    (for both security and safety reasons)
 //  - logs can be buffered which allows manipulating them for log shipping,
 //    transforming and parallel plugins
-const tStartPlugins = async function ({ pluginsOptions, buildDir, childEnv, logs, debug, quiet, systemLogFile }) {
+const tStartPlugins = async function ({
+  pluginsOptions,
+  buildDir,
+  childEnv,
+  logs,
+  debug,
+  quiet,
+  systemLog,
+  systemLogFile,
+  featureFlags,
+}) {
   if (!quiet) {
     logRuntime(logs, pluginsOptions)
     logLoadingPlugins(logs, pluginsOptions, debug)
@@ -46,7 +60,17 @@ const tStartPlugins = async function ({ pluginsOptions, buildDir, childEnv, logs
 
   const childProcesses = await Promise.all(
     pluginsOptions.map(({ pluginDir, nodePath, nodeVersion, pluginPackageJson }) =>
-      startPlugin({ pluginDir, nodePath, nodeVersion, buildDir, childEnv, systemLogFile, pluginPackageJson }),
+      startPlugin({
+        pluginDir,
+        nodePath,
+        nodeVersion,
+        buildDir,
+        childEnv,
+        systemLog,
+        systemLogFile,
+        pluginPackageJson,
+        featureFlags,
+      }),
     ),
   )
   return { childProcesses }
@@ -60,8 +84,10 @@ const startPlugin = async function ({
   nodePath,
   buildDir,
   childEnv,
+  systemLog,
   systemLogFile,
   pluginPackageJson,
+  featureFlags,
 }: {
   nodeVersion: string
   nodePath: string
@@ -70,7 +96,9 @@ const startPlugin = async function ({
   buildDir: string
   childEnv: Record<string, string>
   pluginPackageJson: Record<string, string>
+  systemLog: SystemLogger
   systemLogFile: number
+  featureFlags: FeatureFlags
 }) {
   const ctx = trace.getActiveSpan()?.spanContext()
 
@@ -117,14 +145,23 @@ const startPlugin = async function ({
         ? ['pipe', 'pipe', 'pipe', 'ipc', systemLogFile]
         : undefined,
   })
+  const readyEvent = 'ready'
+  const cleanup = captureStandardError(childProcess, systemLog, readyEvent, featureFlags)
 
   try {
-    await getEventFromChild(childProcess, 'ready')
+    await getEventFromChild(childProcess, readyEvent)
     return { childProcess }
   } catch (error) {
+    if (featureFlags.netlify_build_plugin_system_log) {
+      // Wait for stderr to be flushed.
+      await pSetTimeout(0)
+    }
+
     const spawnInfo = getSpawnInfo()
     addErrorInfo(error, spawnInfo)
     throw error
+  } finally {
+    cleanup()
   }
 }
 

packages/build/src/plugins/system_log.ts

@@ -0,0 +1,37 @@
+import type { FeatureFlags } from '../core/feature_flags.js'
+import type { SystemLogger } from '../plugins_core/types.js'
+
+import type { ChildProcess } from './spawn.js'
+
+export const captureStandardError = (
+  childProcess: ChildProcess,
+  systemLog: SystemLogger,
+  eventName: string,
+  featureFlags: FeatureFlags,
+) => {
+  if (!featureFlags.netlify_build_plugin_system_log) {
+    return () => {
+      // no-op
+    }
+  }
+
+  let receivedChunks = false
+
+  const listener = (chunk: Buffer) => {
+    if (!receivedChunks) {
+      receivedChunks = true
+
+      systemLog(`Plugin failed to initialize during the "${eventName}" phase`)
+    }
+
+    systemLog(chunk.toString().trimEnd())
+  }
+
+  childProcess.stderr?.on('data', listener)
+
+  const cleanup = () => {
+    childProcess.stderr?.removeListener('data', listener)
+  }
+
+  return cleanup
+}

packages/build/tests/plugins/tests.js

@@ -360,8 +360,10 @@ test('Plugin errors that occur during the loading phase are piped to system logs
 
   if (platform !== 'win32') {
     const systemLog = await fs.readFile(systemLogFile.path, { encoding: 'utf8' })
+    const lines = systemLog.split('\n')
 
-    t.is(systemLog.trim(), 'An error message thrown by Node.js')
+    t.is(lines[0].trim(), 'Plugin failed to initialize during the "load" phase')
+    t.is(lines[1].trim(), 'An error message thrown by Node.js')
   }
 
   t.snapshot(normalizeOutput(output))