js: better error/debug reporting, especially for require()

clicommand/pipeline_eval.go

@@ -133,7 +133,7 @@ var PipelineEvalCommand = cli.Command{
 
 		pipelineYAML, err := js.EvalJS(filename, input, l)
 		if err != nil {
-			panic(err)
+			return fmt.Errorf("JavaScript evaluation: %w", err)
 		}
 
 		n, err := c.App.Writer.Write(pipelineYAML)

js/js.go

@@ -34,14 +34,21 @@ func EvalJS(name string, input []byte, log logger.Logger) ([]byte, error) {
 		return nil, err
 	}
 
-	// Run the script; we don't need to capture the return value of the script,
-	// we'll access module.exports instead.
+	// Run the script; capture the return value as a fallback in case the
+	// preferred module.exports wasn't assigned.
 	returnValue, err := runtime.RunScript(name, string(input))
 	if err != nil {
+		if exception, ok := err.(*goja.Exception); ok {
+			if exception.Value().String() == "GoError: Invalid module" {
+				log.Info("Use --debug to trace require() load attempts")
+			}
+			// log the exception and multi-line stack trace
+			log.Error("%s", exception.String())
+		}
 		return nil, err
 	}
 
-	// Get the module.exports valus assigned by the script
+	// Get the module.exports value assigned by the script
 	value := rootModule.Get(nameExports)
 	if value == nil {
 		// if module.exports wasn't assigned, try the return value of the script
@@ -63,6 +70,8 @@ func EvalJS(name string, input []byte, log logger.Logger) ([]byte, error) {
 	return pipelineYAML, nil
 }
 
+// newJavaScriptRuntime builds and configures a goja.Runtime, with various
+// modules loaded, and custom require() source loading.
 func newJavaScriptRuntime(log logger.Logger) (*goja.Runtime, *goja.Object, error) {
 	runtime := goja.New()
 
@@ -74,9 +83,9 @@ func newJavaScriptRuntime(log logger.Logger) (*goja.Runtime, *goja.Object, error
 	)
 
 	// Add basic utilities
-	registry.Enable(runtime) // require(); must be enabled before console, process
-	console.Enable(runtime)  // console.log()
-	process.Enable(runtime)  // process.env
+	enableRequireModule(runtime, registry, log) // require(); must be enabled before console, process
+	console.Enable(runtime)                     // console.log()
+	process.Enable(runtime)                     // process.env
 
 	// provide plugin() as a native module (implemented in Go)
 	// This is implemented natively as a proof-of-concept; there's no good reason
@@ -93,7 +102,8 @@ func newJavaScriptRuntime(log logger.Logger) (*goja.Runtime, *goja.Object, error
 	return runtime, rootModule, nil
 }
 
-// FS is an embedded filesystem.
+// embeddedFS embeds node_modules from the source tree into the compiled binary
+// as a virtual filesystem, which requireSourceLoader accesses.
 //
 //go:embed node_modules
 var embeddedFS embed.FS
@@ -109,27 +119,31 @@ func requireSourceLoader(log logger.Logger) require.SourceLoader {
 		if strings.HasPrefix(name, "node_modules/buildkite/") {
 			data, err := embeddedFS.ReadFile(name)
 			if errors.Is(err, fs.ErrNotExist) {
-				log.Debug("js require() embedded: %q %v", name, require.ModuleFileDoesNotExistError)
+				log.Debug("  loader=embedded %q %v", name, require.ModuleFileDoesNotExistError)
 				// continue to default loader
 			} else if err != nil {
-				log.Debug("js require() embedded: %q %v", name, err)
+				log.Debug("  loader=embedded %q %v", name, err)
 				return nil, err
 			} else {
-				log.Debug("js require() embedded: %q loaded %d bytes", name, len(data))
+				log.Debug("  loader=embedded %q loaded %d bytes", name, len(data))
 				return data, nil
 			}
 		}
 
 		data, err := require.DefaultSourceLoader(name)
 		if err != nil {
-			log.Debug("js require()  default: %q %v", name, err)
+			log.Debug("  loader=default %q %v", name, err)
 			return data, err
 		}
-		log.Debug("js require()  default: %q loaded %d bytes", name, len(data))
+		log.Debug("  loader=default %q loaded %d bytes", name, len(data))
 		return data, err
 	}
 }
 
+// pluginNativeModule implements a basic `plugin(name, ver, config)` JS function,
+// as a proof of concept of native modules. It should really be implemented as
+// an embedded JavaScript file, but this demonstrates how to implement native
+// functions that interact with Go code in more complex ways.
 func pluginNativeModule(runtime *goja.Runtime, module *goja.Object) {
 	module.Set("exports", func(call goja.FunctionCall) goja.Value {
 		name := call.Argument(0)
@@ -140,3 +154,46 @@ func pluginNativeModule(runtime *goja.Runtime, module *goja.Object) {
 		return plugin
 	})
 }
+
+// enableRequireModule adds goja_nodejs's require() function to the runtime,
+// wrapped in some custom debug logging and error reporting.
+func enableRequireModule(runtime *goja.Runtime, registry *require.Registry, log logger.Logger) {
+	// enable goja_nodejs's require()
+	registry.Enable(runtime)
+
+	// get a reference to goja_nodejs's require()
+	orig, ok := goja.AssertFunction(runtime.Get("require"))
+	if !ok {
+		panic("expected `require` to be a function")
+	}
+
+	// a stack of names being recursively loaded
+	var stack []string
+
+	// wrap require() to log/track the name being required
+	runtime.Set("require", func(call goja.FunctionCall) goja.Value {
+		name := call.Argument(0)
+
+		// track this name on our stack
+		stack = append(stack, name.String())
+		defer func() { stack = stack[:len(stack)-1] }()
+
+		log.Debug("require(%q) [%s]", name, strings.Join(stack, " → "))
+
+		// call the original goja_nodejs require()
+		res, err := orig(goja.Undefined(), name)
+		if err != nil {
+			if exception, ok := err.(*goja.Exception); ok {
+				if exception.Value().String() == "GoError: Invalid module" {
+					// report the head of the require() name stack
+					log.Error("require(%q)", stack[len(stack)-1])
+				}
+			}
+			// propagate the error to goja.Runtime
+			panic(err)
+		}
+
+		log.Debug("  require(%q) finished", name)
+		return res
+	})
+}