diff --git a/gopls/doc/daemon.md b/gopls/doc/daemon.md index d9d23d6e1e..d65a021097 100644 --- a/gopls/doc/daemon.md +++ b/gopls/doc/daemon.md @@ -116,11 +116,15 @@ servers and clients. ### 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-.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 15a4363ce5..e49bc6beaa 100644 --- a/internal/lsp/cmd/cmd.go +++ b/internal/lsp/cmd/cmd.go @@ -92,7 +92,6 @@ func New(name, wd string, env []string, options func(*source.Options)) *Applicat 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 00157bd40e..92b9e4e539 100644 --- a/internal/lsp/cmd/serve.go +++ b/internal/lsp/cmd/serve.go @@ -8,6 +8,7 @@ import ( "context" "flag" "fmt" + "log" "os" "strings" "time" @@ -62,8 +63,9 @@ func (s *Serve) Run(ctx context.Context, args ...string) error { } 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 @@ func (s *Serve) Run(ctx context.Context, args ...string) error { 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 5adcc1cd2c..01f3951810 100644 --- a/internal/lsp/cmd/test/cmdtest.go +++ b/internal/lsp/cmd/test/cmdtest.go @@ -68,7 +68,7 @@ func TestCommandLine(testdata string, options func(*source.Options)) func(*testi 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 ea5a544b05..03d5c66b44 100644 --- a/internal/lsp/debug/serve.go +++ b/internal/lsp/debug/serve.go @@ -323,14 +323,18 @@ func WithInstance(ctx context.Context, workdir, agent string) context.Context { } // 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 b43e6e31a2..dca983455f 100644 --- a/internal/lsp/lsprpc/lsprpc.go +++ b/internal/lsp/lsprpc/lsprpc.go @@ -38,6 +38,8 @@ var serverIndex int64 // 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 @@ type StreamServer struct { // 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 @@ func (s *StreamServer) ServeStream(ctx context.Context, conn jsonrpc2.Conn) erro 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 @@ func NewForwarder(network, addr string, opts ...ForwarderOption) *Forwarder { goplsPath: gp, dialTimeout: 1 * time.Second, retries: 5, - remoteLogfile: "auto", remoteListenTimeout: 1 * time.Minute, } for _, opt := range opts { @@ -295,7 +300,9 @@ func (f *Forwarder) connectToRemote(ctx context.Context) (net.Conn, error) { 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 @@ func handshaker(session *cache.Session, goplsPath string, handler jsonrpc2.Handl 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 1f0c626419..324f85b6b1 100644 --- a/internal/lsp/lsprpc/lsprpc_test.go +++ b/internal/lsp/lsprpc/lsprpc_test.go @@ -56,7 +56,7 @@ func TestClientLogging(t *testing.T) { 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 checkClose(t *testing.T, closer func() error) { 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 @@ func TestDebugInfoLifecycle(t *testing.T) { 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 7c6b8fd0fa..7a1021b786 100644 --- a/internal/lsp/regtest/runner.go +++ b/internal/lsp/regtest/runner.go @@ -237,7 +237,7 @@ func (s *loggingFramer) printBuffers(testname string, w io.Writer) { } 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 @@ func (r *Runner) forwardedServer(ctx context.Context, t *testing.T) jsonrpc2.Str 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