From e156a44624b1a4bdf558af011f0d6ba30fd69d6e Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Alex=20-=20=E3=82=A2=E3=83=AC=E3=83=83=E3=82=AF=E3=82=B9?= Date: Sat, 20 Jun 2026 21:42:13 +0200 Subject: [PATCH] feat: log per-request method, latency, and errors MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The server had no per-request observability — only a startup line and error/panic logs — so there was no way to see which LSP methods are called or how long they take. Add ObserveHandler, a jsonrpc2 middleware (mirroring RecoverHandler) wrapping the server handler. It logs method, duration_ms (request body to reply — server processing time), and any error for every request, at Debug level so it is silent unless RIDL_LSP_LOG_LEVEL=debug. Output goes to the server logger (stderr / the editor's output channel), never stdout. Placed outermost so even recovered-panic requests are timed and logged. --- cmd/ridl-lsp/main.go | 7 ++- internal/lsp/observe.go | 37 +++++++++++++++ internal/lsp/observe_test.go | 87 ++++++++++++++++++++++++++++++++++++ 3 files changed, 129 insertions(+), 2 deletions(-) create mode 100644 internal/lsp/observe.go create mode 100644 internal/lsp/observe_test.go diff --git a/cmd/ridl-lsp/main.go b/cmd/ridl-lsp/main.go index f6eeefe..1a2686a 100644 --- a/cmd/ridl-lsp/main.go +++ b/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) diff --git a/internal/lsp/observe.go b/internal/lsp/observe.go new file mode 100644 index 0000000..db3f49a --- /dev/null +++ b/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) + } +} diff --git a/internal/lsp/observe_test.go b/internal/lsp/observe_test.go new file mode 100644 index 0000000..8090e8d --- /dev/null +++ b/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()) + } +}