lsp: enable levelled logging (#1188)

* lsp: Extend server logging with levels

Levels can be used to control how verbose the server logging is.

Signed-off-by: Charlie Egan <charlie@styra.com>

* lsp: add more debug log statements

Signed-off-by: Charlie Egan <charlie@styra.com>

---------

Signed-off-by: Charlie Egan <charlie@styra.com>

cmd/languageserver.go

@@ -10,6 +10,7 @@ import (
 	"github.com/spf13/cobra"
 
 	"github.com/styrainc/regal/internal/lsp"
+	"github.com/styrainc/regal/internal/lsp/log"
 )
 
 func init() {
@@ -25,7 +26,8 @@ func init() {
 			defer cancel()
 
 			opts := &lsp.LanguageServerOptions{
-				ErrorLog: os.Stderr,
+				LogWriter: os.Stderr,
+				LogLevel:  log.LevelMessage,
 			}
 
 			ls := lsp.NewLanguageServer(ctx, opts)

internal/lsp/config/watcher.go

@@ -3,16 +3,17 @@ package config
 import (
 	"context"
 	"fmt"
-	"io"
 	"sync"
 
 	"github.com/fsnotify/fsnotify"
+
+	"github.com/styrainc/regal/internal/lsp/log"
 )
 
 type Watcher struct {
-	errorWriter io.Writer
-	Reload      chan string
-	Drop        chan struct{}
+	logFunc func(log.Level, string, ...any)
+	Reload  chan string
+	Drop    chan struct{}
 
 	pathUpdates chan string
 
@@ -23,8 +24,8 @@ type Watcher struct {
 }
 
 type WatcherOpts struct {
-	ErrorWriter io.Writer
-	Path        string
+	LogFunc func(log.Level, string, ...any)
+	Path    string
 }
 
 func NewWatcher(opts *WatcherOpts) *Watcher {
@@ -35,7 +36,7 @@ func NewWatcher(opts *WatcherOpts) *Watcher {
 	}
 
 	if opts != nil {
-		w.errorWriter = opts.ErrorWriter
+		w.logFunc = opts.LogFunc
 		w.path = opts.Path
 	}
 
@@ -70,12 +71,12 @@ func (w *Watcher) loop(ctx context.Context) {
 			if w.path != "" {
 				err := w.fsWatcher.Remove(w.path)
 				if err != nil {
-					fmt.Fprintf(w.errorWriter, "failed to remove existing watch: %v\n", err)
+					w.logFunc(log.LevelMessage, "failed to remove existing watch: %v\n", err)
 				}
 			}
 
 			if err := w.fsWatcher.Add(path); err != nil {
-				fmt.Fprintf(w.errorWriter, "failed to add watch: %v\n", err)
+				w.logFunc(log.LevelDebug, "failed to add watch: %v\n", err)
 			}
 
 			w.path = path
@@ -84,7 +85,7 @@ func (w *Watcher) loop(ctx context.Context) {
 			w.Reload <- path
 		case event, ok := <-w.fsWatcher.Events:
 			if !ok {
-				fmt.Fprintf(w.errorWriter, "config watcher event channel closed\n")
+				w.logFunc(log.LevelMessage, "config watcher event channel closed\n")
 
 				return
 			}
@@ -98,10 +99,10 @@ func (w *Watcher) loop(ctx context.Context) {
 				w.Drop <- struct{}{}
 			}
 		case err := <-w.fsWatcher.Errors:
-			fmt.Fprintf(w.errorWriter, "config watcher error: %v\n", err)
+			w.logFunc(log.LevelMessage, "config watcher error: %v\n", err)
 		case <-ctx.Done():
 			if err := w.Stop(); err != nil {
-				fmt.Fprintf(w.errorWriter, "failed to stop watcher: %v\n", err)
+				w.logFunc(log.LevelMessage, "failed to stop watcher: %v\n", err)
 			}
 
 			return

internal/lsp/config/watcher_test.go

@@ -5,6 +5,8 @@ import (
 	"os"
 	"testing"
 	"time"
+
+	"github.com/styrainc/regal/internal/lsp/log"
 )
 
 func TestWatcher(t *testing.T) {
@@ -22,7 +24,9 @@ foo: bar
 		t.Fatal(err)
 	}
 
-	watcher := NewWatcher(&WatcherOpts{ErrorWriter: os.Stderr})
+	watcher := NewWatcher(&WatcherOpts{LogFunc: func(l log.Level, s string, a ...any) {
+		t.Logf(l.String()+": "+s, a...)
+	}})
 
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()

internal/lsp/eval.go

@@ -15,6 +15,7 @@ import (
 	"github.com/open-policy-agent/opa/topdown/print"
 
 	rbundle "github.com/styrainc/regal/bundle"
+	"github.com/styrainc/regal/internal/lsp/log"
 	"github.com/styrainc/regal/internal/lsp/uri"
 	"github.com/styrainc/regal/pkg/builtins"
 )
@@ -47,7 +48,7 @@ func (l *LanguageServer) Eval(
 
 	for k, v := range dataBundles {
 		if v.Manifest.Roots == nil {
-			l.logError(fmt.Errorf("bundle %s has no roots and will be skipped", k))
+			l.logf(log.LevelMessage, "bundle %s has no roots and will be skipped", k)
 
 			continue
 		}

internal/lsp/eval_test.go

@@ -8,13 +8,19 @@ import (
 	"testing"
 
 	rio "github.com/styrainc/regal/internal/io"
+	"github.com/styrainc/regal/internal/lsp/log"
 	"github.com/styrainc/regal/internal/parse"
 )
 
 func TestEvalWorkspacePath(t *testing.T) {
 	t.Parallel()
 
-	ls := NewLanguageServer(context.Background(), &LanguageServerOptions{ErrorLog: os.Stderr})
+	logger := newTestLogger(t)
+
+	ls := NewLanguageServer(
+		context.Background(),
+		&LanguageServerOptions{LogWriter: logger, LogLevel: log.LevelDebug},
+	)
 
 	policy1 := `package policy1
 

internal/lsp/log/level.go

@@ -0,0 +1,33 @@
+package log
+
+// Level controls the level of server logging and corresponds to TraceValue in
+// the LSP spec:
+// https://microsoft.github.io/language-server-protocol/specifications/lsp/3.17/specification/#traceValue.
+type Level int
+
+const (
+	// LevelOff is used to disable logging completely.
+	LevelOff Level = iota
+	// LogLevelMessage are intended to contain errors and other messages that
+	// should be shown in normal operation.
+	LevelMessage
+	// LogLevelDebug is includes LogLevelMessage, but also information that is
+	// not expected to be useful unless debugging the server.
+	LevelDebug
+)
+
+func (l Level) String() string {
+	return [...]string{"Off", "Messages", "Debug"}[l]
+}
+
+func (l Level) ShouldLog(incoming Level) bool {
+	if l == LevelOff {
+		return false
+	}
+
+	if l == LevelDebug {
+		return true
+	}
+
+	return l == LevelMessage && incoming == LevelMessage
+}

internal/lsp/log/level_test.go

@@ -0,0 +1,49 @@
+package log
+
+import "testing"
+
+func TestShouldLog(t *testing.T) {
+	t.Parallel()
+
+	testCases := map[string]struct {
+		Level                Level
+		IncomingMessageLevel Level
+		ExpectLog            bool
+	}{
+		"Off, no logs": {
+			Level:                LevelOff,
+			IncomingMessageLevel: LevelMessage,
+			ExpectLog:            false,
+		},
+		"Off, no logs from debug": {
+			Level:                LevelOff,
+			IncomingMessageLevel: LevelDebug,
+			ExpectLog:            false,
+		},
+		"Message, no logs from debug": {
+			Level:                LevelMessage,
+			IncomingMessageLevel: LevelDebug,
+			ExpectLog:            false,
+		},
+		"Debug, logs from Message": {
+			Level:                LevelDebug,
+			IncomingMessageLevel: LevelMessage,
+			ExpectLog:            true,
+		},
+		"Debug, all logs": {
+			Level:                LevelDebug,
+			IncomingMessageLevel: LevelDebug,
+			ExpectLog:            true,
+		},
+	}
+
+	for label, tc := range testCases {
+		t.Run(label, func(t *testing.T) {
+			t.Parallel()
+
+			if got := tc.Level.ShouldLog(tc.IncomingMessageLevel); got != tc.ExpectLog {
+				t.Errorf("expected %v, got %v", tc.ExpectLog, got)
+			}
+		})
+	}
+}