fix: recover panics from validation code

execution/dispatcher/dispatcher.go

@@ -1,7 +1,6 @@
 package dispatcher
 
 import (
-	"errors"
 	"fmt"
 	"log"
 	"runtime"
@@ -50,7 +49,32 @@ func (d *Dispatcher) Handle(command ucan.Command, fn execution.HandlerFunc) {
 	d.handlers[command] = fn
 }
 
-func (d *Dispatcher) Execute(req execution.Request) (execution.Response, error) {
+// Execute validates the invocation and runs the handler registered for its
+// command. A panic anywhere along the way, in the handler or in validation
+// code such as a DID resolver or verifier factory, fails that task with a
+// short-lived [execution.ExecutionFailureErrorName] receipt instead of
+// escaping to the caller, so one misbehaving invocation cannot take down a
+// server that executes many at once. The receipt does not say that the
+// failure was a panic; the panic value goes to the configured [PanicLogger].
+func (d *Dispatcher) Execute(req execution.Request) (res execution.Response, err error) {
+	// recover() alone cannot tell a normal return from panic(nil), which is
+	// recovered as nil under GODEBUG=panicnil=1, so the flag is what says
+	// whether execute returned.
+	returned := false
+	defer func() {
+		if returned {
+			return
+		}
+		d.panicLogger(req, recover())
+		res, err = d.transientFailure(req, execution.NewExecutionFailureError(req.Invocation().Command()))
+	}()
+	res, err = d.execute(req)
+	returned = true
+	return res, err
+}
+
+// execute is [Dispatcher.Execute] without the recovery boundary.
+func (d *Dispatcher) execute(req execution.Request) (execution.Response, error) {
 	aud := req.Invocation().Audience()
 	if !aud.Defined() {
 		aud = req.Invocation().Subject()
@@ -104,50 +128,30 @@ func (d *Dispatcher) Execute(req execution.Request) (execution.Response, error)
 		return nil, fmt.Errorf("failed to create response: %w", err)
 	}
 
-	err = d.runHandler(req, res, handler)
+	err = handler(req, res)
 	if err != nil {
-		respOpts := []execution.ResponseOption{
-			execution.WithIssuer(d.authority),
-			execution.WithReceiptTimestamp(d.receiptTimestamps),
-		}
-		// Errors returned from handlers and panics recovered from them are
-		// unexpected and likely transient, so the receipt asserting the
-		// failure is short-lived. Permanent errors are set as error results
-		// on the response by the handler.
-		if d.handlerErrorReceiptTTL > 0 {
-			exp := ucan.Now() + ucan.UnixTimestamp(d.handlerErrorReceiptTTL.Seconds())
-			respOpts = append(respOpts, execution.WithReceiptExpiration(exp))
-		}
-		respOpts = append(respOpts, execution.WithFailure(execution.NewHandlerExecutionError(cmd, err)))
-		return execution.NewResponse(req.Invocation().Task().Link(), respOpts...)
+		return d.transientFailure(req, execution.NewHandlerExecutionError(cmd, err))
 	}
 	return res, nil
 }
 
-// runHandler calls the handler and turns a panic into a returned error, so a
-// misbehaving handler fails its own task instead of taking down the process.
-// The panic value goes to the configured [PanicLogger]. The receipt tells the
-// client that the handler panicked and nothing more.
-func (d *Dispatcher) runHandler(req execution.Request, res execution.Response, handler execution.HandlerFunc) (err error) {
-	// recover() alone cannot tell a normal return from panic(nil), which is
-	// recovered as nil under GODEBUG=panicnil=1, so the flag is what says
-	// whether the handler returned.
-	returned := false
-	defer func() {
-		if returned {
-			return
-		}
-		value := recover()
-		d.panicLogger(req, value)
-		err = errHandlerPanicked
-	}()
-	err = handler(req, res)
-	returned = true
-	return err
+// transientFailure builds the response for a failure that is unexpected and
+// likely transient: an error returned from a handler or a recovered panic. The
+// receipt asserting it is short-lived, so clients retry rather than cache it.
+// Permanent errors are set as error results on the response by the handler.
+func (d *Dispatcher) transientFailure(req execution.Request, failure error) (execution.Response, error) {
+	respOpts := []execution.ResponseOption{
+		execution.WithIssuer(d.authority),
+		execution.WithReceiptTimestamp(d.receiptTimestamps),
+	}
+	if d.handlerErrorReceiptTTL > 0 {
+		exp := ucan.Now() + ucan.UnixTimestamp(d.handlerErrorReceiptTTL.Seconds())
+		respOpts = append(respOpts, execution.WithReceiptExpiration(exp))
+	}
+	respOpts = append(respOpts, execution.WithFailure(failure))
+	return execution.NewResponse(req.Invocation().Task().Link(), respOpts...)
 }
 
-var errHandlerPanicked = errors.New("handler panicked")
-
 // logPanic is the default [PanicLogger]. It prints the panic and the stack
 // through the standard log package, the way net/http reports the panics it
 // recovers, so it adds no dependency to a binary that serves HTTP.

execution/dispatcher/options.go

@@ -48,15 +48,17 @@ func WithHandlerErrorReceiptTTL(ttl time.Duration) Option {
 	}
 }
 
-// PanicLogger is called with the request and the recovered value when a
-// handler panics. The dispatcher has already decided the outcome by then: the
-// task fails with the receipt [execution.NewHandlerExecutionError] builds,
-// whose message says only that the handler panicked. The logger runs on the panicking
-// goroutine inside the deferred recover, so [runtime.Stack] or
-// [runtime/debug.Stack] called from it returns the stack of the panic.
+// PanicLogger is called with the request and the recovered value when
+// executing an invocation panics, whether in the handler or in validation code
+// such as a DID resolver or verifier factory. The dispatcher has already
+// decided the outcome by then: the task fails with the receipt
+// [execution.NewExecutionFailureError] builds, which does not reveal the panic.
+// The logger runs on the panicking goroutine inside the deferred recover, so
+// [runtime.Stack] or [runtime/debug.Stack] called from it returns the stack of
+// the panic.
 type PanicLogger func(req execution.Request, value any)
 
-// WithPanicLogger sets the function that reports recovered handler panics.
+// WithPanicLogger sets the function that records recovered panics.
 // The default prints the command, task, panic value and stack through the
 // standard log package. Set it to route panics to another logger or an error
 // tracker. A nil logger panics.

execution/dispatcher/panic_test.go

@@ -32,7 +32,7 @@ func TestDispatcherHandlerPanic(t *testing.T) {
 	}
 
 	for desc, value := range panicValues {
-		t.Run("issues a handler execution error receipt when the handler panics with "+desc, func(t *testing.T) {
+		t.Run("issues an execution failure receipt when the handler panics with "+desc, func(t *testing.T) {
 			executor := dispatcher.New(service, dispatcher.WithPanicLogger(discardPanics))
 			executor.Handle(testutil.ConsoleLogCommand, func(req execution.Request, res execution.Response) error {
 				panic(value)
@@ -43,8 +43,8 @@ func TestDispatcherHandlerPanic(t *testing.T) {
 
 			_, x := resp.Receipt().Out().Unpack()
 			require.Equal(t, map[string]any{
-				"name":    execution.HandlerExecutionErrorName,
-				"message": `"/console/log" handler execution error: handler panicked`,
+				"name":    execution.ExecutionFailureErrorName,
+				"message": `"/console/log" execution failed`,
 			}, testutil.ResultMap(t, x))
 		})
 	}
@@ -70,8 +70,8 @@ func TestDispatcherHandlerPanic(t *testing.T) {
 
 		_, x := resp.Receipt().Out().Unpack()
 		require.Equal(t, map[string]any{
-			"name":    execution.HandlerExecutionErrorName,
-			"message": `"/console/log" handler execution error: handler panicked`,
+			"name":    execution.ExecutionFailureErrorName,
+			"message": `"/console/log" execution failed`,
 		}, testutil.ResultMap(t, x))
 	})
 

execution/dispatcher/validation_panic_test.go

@@ -0,0 +1,90 @@
+package dispatcher_test
+
+import (
+	"context"
+	"testing"
+
+	"github.com/fil-forge/ucantone/did"
+	"github.com/fil-forge/ucantone/execution"
+	"github.com/fil-forge/ucantone/execution/dispatcher"
+	"github.com/fil-forge/ucantone/ipld/datamodel"
+	"github.com/fil-forge/ucantone/testutil"
+	"github.com/fil-forge/ucantone/ucan"
+	"github.com/fil-forge/ucantone/ucan/invocation"
+	"github.com/fil-forge/ucantone/validator"
+	"github.com/stretchr/testify/require"
+)
+
+// A DID resolver is the validation extension point most likely to be supplied
+// by an application, so it stands in for every piece of validation code that
+// can panic outside the handler.
+func TestDispatcherValidationPanic(t *testing.T) {
+	service := testutil.RandomIssuer(t)
+	alice := testutil.RandomIssuer(t)
+
+	inv, err := invocation.Invoke(
+		alice,
+		alice.DID(),
+		testutil.ConsoleLogCommand,
+		datamodel.Map{"message": "Hello, World!"},
+		invocation.WithAudience(service.DID()),
+	)
+	require.NoError(t, err)
+
+	panickingResolver := validator.WithDIDResolver(did.ResolverFunc(func(context.Context, did.DID) (did.Document, error) {
+		panic("boom")
+	}))
+
+	newExecutor := func(t *testing.T, options ...dispatcher.Option) *dispatcher.Dispatcher {
+		options = append(options, dispatcher.WithValidationOptions(panickingResolver))
+		executor := dispatcher.New(service, options...)
+		executor.Handle(testutil.ConsoleLogCommand, func(req execution.Request, res execution.Response) error {
+			t.Error("handler must not run when validation panics")
+			return nil
+		})
+		return executor
+	}
+
+	t.Run("issues an execution failure receipt", func(t *testing.T) {
+		executor := newExecutor(t, dispatcher.WithPanicLogger(discardPanics))
+
+		resp, err := executor.Execute(execution.NewRequest(t.Context(), inv))
+		require.NoError(t, err)
+
+		_, x := resp.Receipt().Out().Unpack()
+		require.Equal(t, map[string]any{
+			"name":    execution.ExecutionFailureErrorName,
+			"message": `"/console/log" execution failed`,
+		}, testutil.ResultMap(t, x))
+	})
+
+	t.Run("the receipt expires like one for a handler error", func(t *testing.T) {
+		executor := newExecutor(t, dispatcher.WithPanicLogger(discardPanics))
+
+		before := ucan.Now()
+		resp, err := executor.Execute(execution.NewRequest(t.Context(), inv))
+		require.NoError(t, err)
+
+		ttl := ucan.UnixTimestamp(dispatcher.DefaultHandlerErrorReceiptTTL.Seconds())
+		exp := resp.Receipt().Expiration()
+		require.NotNil(t, exp)
+		require.GreaterOrEqual(t, *exp, before+ttl)
+		require.LessOrEqual(t, *exp, ucan.Now()+ttl)
+	})
+
+	t.Run("calls the panic logger with the request and the panic value", func(t *testing.T) {
+		type call struct {
+			task  string
+			value any
+		}
+		var calls []call
+		executor := newExecutor(t, dispatcher.WithPanicLogger(func(req execution.Request, value any) {
+			calls = append(calls, call{req.Invocation().Task().Link().String(), value})
+		}))
+
+		_, err := executor.Execute(execution.NewRequest(t.Context(), inv))
+		require.NoError(t, err)
+
+		require.Equal(t, []call{{inv.Task().Link().String(), "boom"}}, calls)
+	})
+}

execution/errors.go

@@ -17,6 +17,19 @@ func NewHandlerExecutionError(cmd ucan.Command, cause error) error {
 	}
 }
 
+const ExecutionFailureErrorName = "ExecutionFailure"
+
+// NewExecutionFailureError is the failure a receipt carries when executing the
+// invocation panicked, in the handler or in validation code such as a DID
+// resolver or verifier factory. The receipt says only that execution failed;
+// the panic value and the fact that it was a panic stay on the server.
+func NewExecutionFailureError(cmd ucan.Command) error {
+	return edm.ErrorModel{
+		ErrorName: ExecutionFailureErrorName,
+		Message:   fmt.Sprintf("%q execution failed", cmd),
+	}
+}
+
 const InvalidAudienceErrorName = "InvalidAudience"
 
 func NewInvalidAudienceError(expected did.DID, actual did.DID) error {

notes.md

@@ -22,4 +22,4 @@
     * Ed25519 signer byte representation is now just the multiformats tagged private key bytes. Go internally uses 64 bytes for the private key which redundantly includes the public key.
 * Containers hold at most `container.MaxTokens` (8192) tokens. The container spec sets no limit; this is the cbor-gen/dag-json-gen array limit, pinned with a `maxlen` struct tag on `ContainerModel.Ctn1` so a generator upgrade cannot move it silently. The exported constant lets callers budget before encoding.
 * Server is a HTTP `RoundTripper`
-* A handler that panics fails its own task: the dispatcher recovers the panic and issues the same short-lived `HandlerExecutionError` receipt a returned error gets, with the fixed message `handler panicked`. The panic value never reaches the client, since it was not written for one and can carry internals. The value goes to a `PanicLogger` callback (`WithPanicLogger` on the dispatcher and the server); the default prints it with the stack through the standard `log` package and `runtime.Stack`, as net/http does, so the library links neither `log/slog` nor `runtime/debug` into a consumer binary. Before this, a panic escaped to net/http, which dropped the connection with no receipt; with invocations executing on their own goroutines it would have crashed the process.
+* A panic while executing an invocation fails its own task: `Dispatcher.Execute` recovers it and issues a short-lived `ExecutionFailure` receipt, with the same TTL a returned handler error gets. The boundary is the whole of `Execute` because validation runs application code too (a `WithDIDResolver`, a `WithVerifierFactories` factory, a nonstandard-signature verifier), and a panic there would otherwise escape the worker goroutine the server runs each invocation on. There is one receipt for every panic, and it does not say that a panic happened, let alone where: a client cannot act on the distinction, and a developer debugging it needs the log line anyway, since the panic value never reaches the client (it was not written for one and can carry internals). The value goes to a `PanicLogger` callback (`WithPanicLogger` on the dispatcher and the server); the default prints it with the stack through the standard `log` package and `runtime.Stack`, as net/http does, so the library links neither `log/slog` nor `runtime/debug` into a consumer binary. Before this, a panic escaped to net/http, which dropped the connection with no receipt; with invocations executing on their own goroutines it would have crashed the process.

server/http_test.go

@@ -1,11 +1,14 @@
 package server_test
 
 import (
+	"context"
 	"io"
 	"net/http"
 	"testing"
 	"time"
 
+	"github.com/fil-forge/ucantone/did"
+	"github.com/fil-forge/ucantone/did/key"
 	"github.com/fil-forge/ucantone/execution"
 	"github.com/fil-forge/ucantone/execution/batch"
 	"github.com/fil-forge/ucantone/ipld"
@@ -16,6 +19,7 @@ import (
 	"github.com/fil-forge/ucantone/ucan"
 	"github.com/fil-forge/ucantone/ucan/container"
 	"github.com/fil-forge/ucantone/ucan/invocation"
+	"github.com/fil-forge/ucantone/validator"
 	"github.com/stretchr/testify/require"
 )
 
@@ -212,10 +216,46 @@ func TestHTTPServerBatch(t *testing.T) {
 		rcpt, ok := res.Receipt(inv.Task().Link())
 		require.True(t, ok)
 		_, x := rcpt.Out().Unpack()
-		require.Equal(t, execution.HandlerExecutionErrorName, testutil.ResultMap(t, x)["name"])
+		require.Equal(t, execution.ExecutionFailureErrorName, testutil.ResultMap(t, x)["name"])
 		require.Equal(t, []any{"boom"}, logged)
 	})
 
+	t.Run("a panic in validation fails its own task only", func(t *testing.T) {
+		bob := testutil.RandomIssuer(t)
+		// Resolves every DID the usual way except Alice's, so validation of
+		// her invocation panics and Bob's goes through.
+		resolver := did.ResolverFunc(func(ctx context.Context, d did.DID) (did.Document, error) {
+			if d == alice.DID() {
+				panic("boom")
+			}
+			return key.Resolver.Resolve(ctx, d)
+		})
+		server := server.NewHTTP(service,
+			server.WithPanicLogger(func(execution.Request, any) {}),
+			server.WithValidationOptions(validator.WithDIDResolver(resolver)),
+		)
+		server.Handle(testutil.TestEchoCommand, func(req execution.Request, res execution.Response) error {
+			return res.SetSuccess(testutil.ArgsMap(t, req.Invocation()))
+		})
+		fromAlice, err := invocation.Invoke(alice, alice.DID(), testutil.TestEchoCommand, datamodel.Map{"message": "alice"}, invocation.WithAudience(service.DID()))
+		require.NoError(t, err)
+		fromBob, err := invocation.Invoke(bob, bob.DID(), testutil.TestEchoCommand, datamodel.Map{"message": "bob"}, invocation.WithAudience(service.DID()))
+		require.NoError(t, err)
+
+		res, err := server.ExecuteBatch(batch.NewRequest(t.Context(), []ucan.Invocation{fromAlice, fromBob}))
+		require.NoError(t, err)
+
+		aliceRcpt, ok := res.Receipt(fromAlice.Task().Link())
+		require.True(t, ok)
+		_, x := aliceRcpt.Out().Unpack()
+		require.Equal(t, execution.ExecutionFailureErrorName, testutil.ResultMap(t, x)["name"])
+
+		bobRcpt, ok := res.Receipt(fromBob.Task().Link())
+		require.True(t, ok)
+		o, _ := bobRcpt.Out().Unpack()
+		require.Equal(t, "bob", testutil.ResultMap(t, o)["message"])
+	})
+
 	t.Run("WithPanicLogger(nil) panics", func(t *testing.T) {
 		require.PanicsWithValue(t, "server.WithPanicLogger: logger must not be nil", func() {
 			server.WithPanicLogger(nil)

server/options.go

@@ -39,9 +39,10 @@ func WithReceiptTimestamps(enabled bool) HTTPOption {
 	}
 }
 
-// WithPanicLogger sets the function the server's dispatcher reports recovered
-// handler panics to. See [dispatcher.WithPanicLogger] for the default and the
-// contract. A nil logger panics.
+// WithPanicLogger sets the function the server's dispatcher records recovered
+// panics with, from handlers and from validation code alike. See
+// [dispatcher.WithPanicLogger] for the default and the contract. A nil logger
+// panics.
 func WithPanicLogger(logger dispatcher.PanicLogger) HTTPOption {
 	if logger == nil {
 		panic("server.WithPanicLogger: logger must not be nil")