feat: per-request observability (method, latency, errors)

cmd/ridl-lsp/main.go

@@ -48,8 +48,11 @@ func main() {
 	ctx = protocol.WithClient(ctx, client)
 	server.SetClient(client)
 
-	serverHandler := lsp.RecoverHandler(
-		protocol.ServerHandler(server, jsonrpc2.MethodNotFoundHandler),
+	serverHandler := lsp.ObserveHandler(
+		lsp.RecoverHandler(
+			protocol.ServerHandler(server, jsonrpc2.MethodNotFoundHandler),
+			logger,
+		),
 		logger,
 	)
 	asyncHandler := protocol.Handlers(serverHandler)

internal/lsp/observe.go

@@ -0,0 +1,37 @@
+package lsp
+
+import (
+	"context"
+	"time"
+
+	"go.lsp.dev/jsonrpc2"
+	"go.uber.org/zap"
+)
+
+// ObserveHandler wraps a jsonrpc2.Handler to log per-request observability for
+// every LSP request: the method, server processing time, and any error.
+//
+// It times from when the request body runs to when the reply is sent — server
+// processing time, not transport or queue wait. It logs at Debug so it stays
+// silent unless RIDL_LSP_LOG_LEVEL=debug, and writes only to the server logger
+// (stderr): stdout is the JSON-RPC transport and must never be logged to.
+func ObserveHandler(handler jsonrpc2.Handler, logger *zap.Logger) jsonrpc2.Handler {
+	return func(ctx context.Context, reply jsonrpc2.Replier, req jsonrpc2.Request) error {
+		start := time.Now()
+		method := req.Method()
+
+		timedReply := func(ctx context.Context, result any, replyErr error) error {
+			fields := []zap.Field{
+				zap.String("method", method),
+				zap.Float64("duration_ms", float64(time.Since(start).Microseconds())/1000),
+			}
+			if replyErr != nil {
+				fields = append(fields, zap.Error(replyErr))
+			}
+			logger.Debug("lsp request", fields...)
+			return reply(ctx, result, replyErr)
+		}
+
+		return handler(ctx, timedReply, req)
+	}
+}

internal/lsp/observe_test.go

@@ -0,0 +1,87 @@
+package lsp
+
+import (
+	"context"
+	"errors"
+	"testing"
+
+	"go.lsp.dev/jsonrpc2"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+	"go.uber.org/zap/zaptest/observer"
+)
+
+func observeTestRequest(t *testing.T) jsonrpc2.Request {
+	t.Helper()
+	req, err := jsonrpc2.NewNotification("textDocument/didChange", nil)
+	if err != nil {
+		t.Fatalf("NewNotification: %v", err)
+	}
+	return req
+}
+
+func TestObserveHandlerLogsMethodAndDuration(t *testing.T) {
+	core, logs := observer.New(zapcore.DebugLevel)
+
+	inner := jsonrpc2.Handler(func(ctx context.Context, reply jsonrpc2.Replier, req jsonrpc2.Request) error {
+		return reply(ctx, "ok", nil)
+	})
+
+	var gotResult any
+	var gotErr error
+	replyCount := 0
+	reply := func(ctx context.Context, result any, err error) error {
+		replyCount++
+		gotResult = result
+		gotErr = err
+		return nil
+	}
+
+	err := ObserveHandler(inner, zap.New(core))(context.Background(), reply, observeTestRequest(t))
+	if err != nil {
+		t.Fatalf("handler returned error: %v", err)
+	}
+
+	// The wrapped reply must forward the inner result/err unchanged.
+	if replyCount != 1 {
+		t.Fatalf("reply called %d times, want 1", replyCount)
+	}
+	if gotResult != "ok" || gotErr != nil {
+		t.Fatalf("reply forwarding: got (%v, %v), want (ok, nil)", gotResult, gotErr)
+	}
+
+	entries := logs.All()
+	if len(entries) != 1 {
+		t.Fatalf("log entries: got %d, want 1", len(entries))
+	}
+	fields := entries[0].ContextMap()
+	if fields["method"] != "textDocument/didChange" {
+		t.Fatalf("method field: got %v, want textDocument/didChange", fields["method"])
+	}
+	if _, ok := fields["duration_ms"]; !ok {
+		t.Fatalf("missing duration_ms field; got %v", fields)
+	}
+	if _, ok := fields["error"]; ok {
+		t.Fatalf("unexpected error field on a successful request: %v", fields["error"])
+	}
+}
+
+func TestObserveHandlerLogsError(t *testing.T) {
+	core, logs := observer.New(zapcore.DebugLevel)
+	wantErr := errors.New("boom")
+
+	inner := jsonrpc2.Handler(func(ctx context.Context, reply jsonrpc2.Replier, req jsonrpc2.Request) error {
+		return reply(ctx, nil, wantErr)
+	})
+	reply := func(ctx context.Context, result any, err error) error { return nil }
+
+	_ = ObserveHandler(inner, zap.New(core))(context.Background(), reply, observeTestRequest(t))
+
+	entries := logs.All()
+	if len(entries) != 1 {
+		t.Fatalf("log entries: got %d, want 1", len(entries))
+	}
+	if _, ok := entries[0].ContextMap()["error"]; !ok {
+		t.Fatalf("expected an error field on a failed request; got %v", entries[0].ContextMap())
+	}
+}