internal/lsp/lsprpc: improvements to daemon logging
The gopls daemon had different default logging behavior than the sidecar
gopls: by default, the daemon was started with -logfile=auto.
Additionally, because most logs are reflected back to the forwarder, the
actual daemon logs have very little (if any) information.
This means that if you simply start gopls with -remote=auto, you'll get
a single logfile named /tmp/gopls-<pid>.log, which is mostly empty. This
is not a delightful experience.
Fix this via several improvements:
+ Log lifecycle events in the Daemon, to give the log a purpose.
+ Give the daemon a new default log location:
/tmp/gopls-daemon-<pid>.log.
+ Don't pass -logfile=auto to the daemon by default.
Fixes golang/go#40105
Change-Id: I5e91ea98b4968c512bce76a596bbae441f461a66
Reviewed-on: https://go-review.googlesource.com/c/tools/+/241440
Run-TryBot: Robert Findley <rfindley@google.com>
TryBot-Result: Gobot Gobot <gobot@golang.org>
Reviewed-by: Rebecca Stambler <rstambler@golang.org>
diff --git a/gopls/doc/daemon.md b/gopls/doc/daemon.md
index d9d23d6..d65a021 100644
--- a/gopls/doc/daemon.md
+++ b/gopls/doc/daemon.md
@@ -116,11 +116,15 @@
### Using logfiles
-The gopls daemon is started with `-logfile=auto` by default. To customize this,
-pass `-remote.logfile` to the gopls forwarder.
+The gopls daemon is started with logging disabled by default. To customize
+this, pass `-remote.logfile` to the gopls forwarder. Using
+`-remote.logfile=auto`, the daemon will log to a default location (on posix
+systems: `/tmp/gopls-daemon-<pid>.log`).
-By default, the gopls daemon is not started with the `-rpc.trace` flag, so its
-logfile will only contain actual debug logs from the gopls process.
+The gopls daemon does not log session-scoped messages: those are instead
+reflected back to the forwarder so that they can be accessed by the editor.
+Daemon logs will only contain global messages, for example logs when sessions
+connect and disconnect.
It is recommended to start the forwarder gopls process with `-rpc.trace`, so
that its logfile will contain rpc trace logs specific to the LSP session.
diff --git a/internal/lsp/cmd/cmd.go b/internal/lsp/cmd/cmd.go
index 15a4363..e49bc6b 100644
--- a/internal/lsp/cmd/cmd.go
+++ b/internal/lsp/cmd/cmd.go
@@ -92,7 +92,6 @@
Serve: Serve{
RemoteListenTimeout: 1 * time.Minute,
- RemoteLogfile: "auto",
},
}
return app
diff --git a/internal/lsp/cmd/serve.go b/internal/lsp/cmd/serve.go
index 00157bd..92b9e4e 100644
--- a/internal/lsp/cmd/serve.go
+++ b/internal/lsp/cmd/serve.go
@@ -8,6 +8,7 @@
"context"
"flag"
"fmt"
+ "log"
"os"
"strings"
"time"
@@ -62,8 +63,9 @@
}
di := debug.GetInstance(ctx)
+ isDaemon := s.Address != "" || s.Port != 0
if di != nil {
- closeLog, err := di.SetLogFile(s.Logfile)
+ closeLog, err := di.SetLogFile(s.Logfile, isDaemon)
if err != nil {
return err
}
@@ -82,16 +84,21 @@
lsprpc.RemoteLogfile(s.RemoteLogfile),
)
} else {
- ss = lsprpc.NewStreamServer(cache.New(ctx, s.app.options))
+ ss = lsprpc.NewStreamServer(cache.New(ctx, s.app.options), isDaemon)
}
+ var network, addr string
if s.Address != "" {
- network, addr := parseAddr(s.Address)
- return jsonrpc2.ListenAndServe(ctx, network, addr, ss, s.IdleTimeout)
+ network, addr = parseAddr(s.Address)
}
if s.Port != 0 {
- addr := fmt.Sprintf(":%v", s.Port)
- return jsonrpc2.ListenAndServe(ctx, "tcp", addr, ss, s.IdleTimeout)
+ network = "tcp"
+ addr = fmt.Sprintf(":%v", s.Port)
+ }
+ if addr != "" {
+ log.Printf("Gopls daemon: listening on %s network, address %s...", network, addr)
+ defer log.Printf("Gopls daemon: exiting")
+ return jsonrpc2.ListenAndServe(ctx, network, addr, ss, s.IdleTimeout)
}
stream := jsonrpc2.NewHeaderStream(fakenet.NewConn("stdio", os.Stdin, os.Stdout))
if s.Trace && di != nil {
diff --git a/internal/lsp/cmd/test/cmdtest.go b/internal/lsp/cmd/test/cmdtest.go
index 5adcc1c..01f3951 100644
--- a/internal/lsp/cmd/test/cmdtest.go
+++ b/internal/lsp/cmd/test/cmdtest.go
@@ -68,7 +68,7 @@
func NewTestServer(ctx context.Context, options func(*source.Options)) *servertest.TCPServer {
ctx = debug.WithInstance(ctx, "", "")
cache := cache.New(ctx, options)
- ss := lsprpc.NewStreamServer(cache)
+ ss := lsprpc.NewStreamServer(cache, false)
return servertest.NewTCPServer(ctx, ss, nil)
}
diff --git a/internal/lsp/debug/serve.go b/internal/lsp/debug/serve.go
index ea5a544..03d5c66 100644
--- a/internal/lsp/debug/serve.go
+++ b/internal/lsp/debug/serve.go
@@ -323,14 +323,18 @@
}
// SetLogFile sets the logfile for use with this instance.
-func (i *Instance) SetLogFile(logfile string) (func(), error) {
+func (i *Instance) SetLogFile(logfile string, isDaemon bool) (func(), error) {
// TODO: probably a better solution for deferring closure to the caller would
// be for the debug instance to itself be closed, but this fixes the
// immediate bug of logs not being captured.
closeLog := func() {}
if logfile != "" {
if logfile == "auto" {
- logfile = filepath.Join(os.TempDir(), fmt.Sprintf("gopls-%d.log", os.Getpid()))
+ if isDaemon {
+ logfile = filepath.Join(os.TempDir(), fmt.Sprintf("gopls-daemon-%d.log", os.Getpid()))
+ } else {
+ logfile = filepath.Join(os.TempDir(), fmt.Sprintf("gopls-%d.log", os.Getpid()))
+ }
}
f, err := os.Create(logfile)
if err != nil {
diff --git a/internal/lsp/lsprpc/lsprpc.go b/internal/lsp/lsprpc/lsprpc.go
index b43e6e3..dca9834 100644
--- a/internal/lsp/lsprpc/lsprpc.go
+++ b/internal/lsp/lsprpc/lsprpc.go
@@ -38,6 +38,8 @@
// streams as a new LSP session, using a shared cache.
type StreamServer struct {
cache *cache.Cache
+ // logConnections controls whether or not to log new connections.
+ logConnections bool
// serverForTest may be set to a test fake for testing.
serverForTest protocol.Server
@@ -46,8 +48,8 @@
// NewStreamServer creates a StreamServer using the shared cache. If
// withTelemetry is true, each session is instrumented with telemetry that
// records RPC statistics.
-func NewStreamServer(cache *cache.Cache) *StreamServer {
- return &StreamServer{cache: cache}
+func NewStreamServer(cache *cache.Cache, logConnections bool) *StreamServer {
+ return &StreamServer{cache: cache, logConnections: logConnections}
}
// ServeStream implements the jsonrpc2.StreamServer interface, by handling
@@ -78,6 +80,10 @@
handshaker(session, executable,
protocol.ServerHandler(server,
jsonrpc2.MethodNotFound))))
+ if s.logConnections {
+ log.Printf("Session %s: connected", session.ID())
+ defer log.Printf("Session %s: exited", session.ID())
+ }
<-conn.Done()
return conn.Err()
}
@@ -146,7 +152,6 @@
goplsPath: gp,
dialTimeout: 1 * time.Second,
retries: 5,
- remoteLogfile: "auto",
remoteListenTimeout: 1 * time.Minute,
}
for _, opt := range opts {
@@ -295,7 +300,9 @@
args := []string{"serve",
"-listen", fmt.Sprintf(`%s;%s`, network, address),
"-listen.timeout", f.remoteListenTimeout.String(),
- "-logfile", f.remoteLogfile,
+ }
+ if f.remoteLogfile != "" {
+ args = append(args, "-logfile", f.remoteLogfile)
}
if f.remoteDebug != "" {
args = append(args, "-debug", f.remoteDebug)
@@ -466,11 +473,16 @@
return func(ctx context.Context, reply jsonrpc2.Replier, r jsonrpc2.Request) error {
switch r.Method() {
case handshakeMethod:
+ // We log.Printf in this handler, rather than event.Log when we want logs
+ // to go to the daemon log rather than being reflected back to the
+ // client.
var req handshakeRequest
if err := json.Unmarshal(r.Params(), &req); err != nil {
+ log.Printf("Error processing handshake for session %s: %v", session.ID(), err)
sendError(ctx, reply, err)
return nil
}
+ log.Printf("Session %s: got handshake. Logfile: %q, Debug addr: %q", session.ID(), req.Logfile, req.DebugAddr)
event.Log(ctx, "Handshake session update",
cache.KeyUpdateSession.Of(session),
tag.DebugAddress.Of(req.DebugAddr),
diff --git a/internal/lsp/lsprpc/lsprpc_test.go b/internal/lsp/lsprpc/lsprpc_test.go
index 1f0c626..324f85b 100644
--- a/internal/lsp/lsprpc/lsprpc_test.go
+++ b/internal/lsp/lsprpc/lsprpc_test.go
@@ -56,7 +56,7 @@
client := fakeClient{logs: make(chan string, 10)}
ctx = debug.WithInstance(ctx, "", "")
- ss := NewStreamServer(cache.New(ctx, nil))
+ ss := NewStreamServer(cache.New(ctx, nil), false)
ss.serverForTest = server
ts := servertest.NewPipeServer(ctx, ss, nil)
defer checkClose(t, ts.Close)
@@ -113,7 +113,7 @@
func setupForwarding(ctx context.Context, t *testing.T, s protocol.Server) (direct, forwarded servertest.Connector, cleanup func()) {
t.Helper()
serveCtx := debug.WithInstance(ctx, "", "")
- ss := NewStreamServer(cache.New(serveCtx, nil))
+ ss := NewStreamServer(cache.New(serveCtx, nil), false)
ss.serverForTest = s
tsDirect := servertest.NewTCPServer(serveCtx, ss, nil)
@@ -217,7 +217,7 @@
serverCtx := debug.WithInstance(baseCtx, "", "")
cache := cache.New(serverCtx, nil)
- ss := NewStreamServer(cache)
+ ss := NewStreamServer(cache, false)
tsBackend := servertest.NewTCPServer(serverCtx, ss, nil)
forwarder := NewForwarder("tcp", tsBackend.Addr)
diff --git a/internal/lsp/regtest/runner.go b/internal/lsp/regtest/runner.go
index 7c6b8fd..7a1021b 100644
--- a/internal/lsp/regtest/runner.go
+++ b/internal/lsp/regtest/runner.go
@@ -237,7 +237,7 @@
}
func singletonServer(ctx context.Context, t *testing.T) jsonrpc2.StreamServer {
- return lsprpc.NewStreamServer(cache.New(ctx, nil))
+ return lsprpc.NewStreamServer(cache.New(ctx, nil), false)
}
func (r *Runner) forwardedServer(ctx context.Context, t *testing.T) jsonrpc2.StreamServer {
@@ -245,15 +245,15 @@
return lsprpc.NewForwarder("tcp", ts.Addr)
}
-// getTestServer gets the test server instance to connect to, or creates one if
-// it doesn't exist.
+// getTestServer gets the shared test server instance to connect to, or creates
+// one if it doesn't exist.
func (r *Runner) getTestServer() *servertest.TCPServer {
r.mu.Lock()
defer r.mu.Unlock()
if r.ts == nil {
ctx := context.Background()
ctx = debug.WithInstance(ctx, "", "")
- ss := lsprpc.NewStreamServer(cache.New(ctx, nil))
+ ss := lsprpc.NewStreamServer(cache.New(ctx, nil), false)
r.ts = servertest.NewTCPServer(ctx, ss, nil)
}
return r.ts
