service,logflags: log all RPC messages

We occasionally receive bug reports from users of VSCode-go and GoLand.
GoLand has its own way of capturing the packet exchange between itself
and delve but VSCode-go (supposedly) doesn't.
So far this hasn't been a problem since all bug reports were obvious
bugs on the plugin or easy to reproduce without VSCode-go, but it might
be helpful in the future to have a way to log the packet exchange
between dlv and a frontend.

This commit adds a --log-output option to enable logging of all rpc
messages and changes service/rpccommon accordingly.

Documentation/usage/dlv.md

@@ -37,6 +37,7 @@ Pass flags to the program you are debugging using `--`, for example:
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_attach.md

@@ -37,6 +37,7 @@ dlv attach pid [executable]
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_connect.md

@@ -32,6 +32,7 @@ dlv connect addr
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_core.md

@@ -36,6 +36,7 @@ dlv core <executable> <core>
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_debug.md

@@ -43,6 +43,7 @@ dlv debug [package]
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_exec.md

@@ -37,6 +37,7 @@ dlv exec <path/to/binary>
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_replay.md

@@ -36,6 +36,7 @@ dlv replay [trace directory]
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_run.md

@@ -32,6 +32,7 @@ dlv run
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_test.md

@@ -43,6 +43,7 @@ dlv test [package]
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_trace.md

@@ -45,6 +45,7 @@ dlv trace [package] regexp
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

Documentation/usage/dlv_version.md

@@ -32,6 +32,7 @@ dlv version
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.
       --wd string            Working directory for running the program. (default ".")
 ```

cmd/dlv/cmds/commands.go

@@ -94,6 +94,7 @@ func New(docCall bool) *cobra.Command {
 	gdbwire		Log connection to gdbserial backend
 	lldbout		Copy output from debugserver/lldb to standard output
 	debuglineerr	Log recoverable errors reading .debug_line
+	rpc		Log all RPC messages
 Defaults to "debugger" when logging is enabled with --log.`)
 	RootCommand.PersistentFlags().BoolVarP(&Headless, "headless", "", false, "Run debug server only, in headless mode.")
 	RootCommand.PersistentFlags().BoolVarP(&AcceptMulti, "accept-multiclient", "", false, "Allows a headless server to accept multiple client connections. Note that the server API is not reentrant and clients will have to coordinate.")
@@ -363,7 +364,7 @@ func traceCmd(cmd *cobra.Command, args []string) {
 			APIVersion:  2,
 			WorkingDir:  WorkingDir,
 			Backend:     Backend,
-		}, logflags.Debugger())
+		}, logflags.RPC())
 		if err := server.Run(); err != nil {
 			fmt.Fprintln(os.Stderr, err)
 			return 1
@@ -509,7 +510,7 @@ func execute(attachPid int, processArgs []string, conf *config.Config, coreFile
 			Foreground:  Headless,
 
 			DisconnectChan: disconnectChan,
-		}, logflags.Debugger())
+		}, logflags.RPC())
 	default:
 		fmt.Printf("Unknown API version: %d\n", APIVersion)
 		return 1

pkg/logflags/logflags.go

@@ -2,14 +2,16 @@ package logflags
 
 import (
 	"errors"
+	"io/ioutil"
+	"log"
 	"strings"
 )
 
 var debugger = false
 var gdbWire = false
 var lldbServerOutput = false
-var suppressedErrors = false
 var debugLineErrors = false
+var rpc = false
 
 // GdbWire returns true if the gdbserial package should log all the packets
 // exchanged with the stub.
@@ -34,11 +36,18 @@ func DebugLineErrors() bool {
 	return debugLineErrors
 }
 
+// RPC returns true if rpc messages should be logged.
+func RPC() bool {
+	return rpc
+}
+
 var errLogstrWithoutLog = errors.New("--log-output specified without --log")
 
 // Setup sets debugger flags based on the contents of logstr.
-func Setup(log bool, logstr string) error {
-	if !log {
+func Setup(logFlag bool, logstr string) error {
+	log.SetFlags(log.Ldate | log.Ltime | log.Lshortfile)
+	if !logFlag {
+		log.SetOutput(ioutil.Discard)
 		if logstr != "" {
 			return errLogstrWithoutLog
 		}
@@ -58,6 +67,8 @@ func Setup(log bool, logstr string) error {
 			lldbServerOutput = true
 		case "debuglineerr":
 			debugLineErrors = true
+		case "rpc":
+			rpc = true
 		}
 	}
 	return nil

service/debugger/debugger.go

@@ -12,6 +12,7 @@ import (
 	"sync"
 	"time"
 
+	"github.com/derekparker/delve/pkg/logflags"
 	"github.com/derekparker/delve/pkg/proc"
 	"github.com/derekparker/delve/pkg/proc/core"
 	"github.com/derekparker/delve/pkg/proc/gdbserial"
@@ -70,7 +71,9 @@ func New(config *Config, processArgs []string) (*Debugger, error) {
 	// Create the process by either attaching or launching.
 	switch {
 	case d.config.AttachPid > 0:
+		if logflags.Debugger() {
 			log.Printf("attaching to pid %d", d.config.AttachPid)
+		}
 		path := ""
 		if len(d.processArgs) > 0 {
 			path = d.processArgs[0]
@@ -86,10 +89,14 @@ func New(config *Config, processArgs []string) (*Debugger, error) {
 		var err error
 		switch d.config.Backend {
 		case "rr":
+			if logflags.Debugger() {
 				log.Printf("opening trace %s", d.config.CoreFile)
+			}
 			p, err = gdbserial.Replay(d.config.CoreFile, false)
 		default:
+			if logflags.Debugger() {
 				log.Printf("opening core file %s (executable %s)", d.config.CoreFile, d.processArgs[0])
+			}
 			p, err = core.OpenCore(d.config.CoreFile, d.processArgs[0])
 		}
 		if err != nil {
@@ -98,7 +105,9 @@ func New(config *Config, processArgs []string) (*Debugger, error) {
 		d.target = p
 
 	default:
+		if logflags.Debugger() {
 			log.Printf("launching process with args: %v", d.processArgs)
+		}
 		p, err := d.Launch(d.processArgs, d.config.WorkingDir)
 		if err != nil {
 			if err != proc.NotExecutableErr && err != proc.UnsupportedLinuxArchErr && err != proc.UnsupportedWindowsArchErr && err != proc.UnsupportedDarwinArchErr {
@@ -358,7 +367,9 @@ func (d *Debugger) CreateBreakpoint(requestedBp *api.Breakpoint) (*api.Breakpoin
 		return nil, err
 	}
 	createdBp = api.ConvertBreakpoint(bp)
+	if logflags.Debugger() {
 		log.Printf("created breakpoint: %#v", createdBp)
+	}
 	return createdBp, nil
 }
 
@@ -406,7 +417,9 @@ func (d *Debugger) ClearBreakpoint(requestedBp *api.Breakpoint) (*api.Breakpoint
 		return nil, fmt.Errorf("Can't clear breakpoint @%x: %s", requestedBp.Addr, err)
 	}
 	clearedBp = api.ConvertBreakpoint(bp)
+	if logflags.Debugger() {
 		log.Printf("cleared breakpoint: %#v", clearedBp)
+	}
 	return clearedBp, err
 }
 
@@ -504,7 +517,9 @@ func (d *Debugger) Command(command *api.DebuggerCommand) (*api.DebuggerState, er
 	if command.Name == api.Halt {
 		// RequestManualStop does not invoke any ptrace syscalls, so it's safe to
 		// access the process directly.
+		if logflags.Debugger() {
 			log.Print("halting")
+		}
 		err = d.target.RequestManualStop()
 	}
 
@@ -515,10 +530,14 @@ func (d *Debugger) Command(command *api.DebuggerCommand) (*api.DebuggerState, er
 
 	switch command.Name {
 	case api.Continue:
+		if logflags.Debugger() {
 			log.Print("continuing")
+		}
 		err = proc.Continue(d.target)
 	case api.Rewind:
+		if logflags.Debugger() {
 			log.Print("rewinding")
+		}
 		if err := d.target.Direction(proc.Backward); err != nil {
 			return nil, err
 		}
@@ -527,23 +546,35 @@ func (d *Debugger) Command(command *api.DebuggerCommand) (*api.DebuggerState, er
 		}()
 		err = proc.Continue(d.target)
 	case api.Next:
+		if logflags.Debugger() {
 			log.Print("nexting")
+		}
 		err = proc.Next(d.target)
 	case api.Step:
+		if logflags.Debugger() {
 			log.Print("stepping")
+		}
 		err = proc.Step(d.target)
 	case api.StepInstruction:
+		if logflags.Debugger() {
 			log.Print("single stepping")
+		}
 		err = d.target.StepInstruction()
 	case api.StepOut:
+		if logflags.Debugger() {
 			log.Print("step out")
+		}
 		err = proc.StepOut(d.target)
 	case api.SwitchThread:
+		if logflags.Debugger() {
 			log.Printf("switching to thread %d", command.ThreadID)
+		}
 		err = d.target.SwitchThread(command.ThreadID)
 		withBreakpointInfo = false
 	case api.SwitchGoroutine:
+		if logflags.Debugger() {
 			log.Printf("switching to goroutine %d", command.GoroutineID)
+		}
 		err = d.target.SwitchGoroutine(command.GoroutineID)
 		withBreakpointInfo = false
 	case api.Halt:

service/rpccommon/server.go

@@ -2,10 +2,10 @@ package rpccommon
 
 import (
 	"bytes"
+	"encoding/json"
 	"errors"
 	"fmt"
 	"io"
-	"io/ioutil"
 	"log"
 	"net"
 	"net/rpc"
@@ -41,6 +41,7 @@ type ServerImpl struct {
 	s2 *rpc2.RPCServer
 	// maps of served methods, one for each supported API.
 	methodMaps []map[string]*methodType
+	log        bool
 }
 
 type RPCCallback struct {
@@ -65,17 +66,16 @@ type methodType struct {
 
 // NewServer creates a new RPCServer.
 func NewServer(config *service.Config, logEnabled bool) *ServerImpl {
-	log.SetFlags(log.Ldate | log.Ltime | log.Lshortfile)
-	if !logEnabled {
-		log.SetOutput(ioutil.Discard)
-	}
 	if config.APIVersion < 2 {
+		if logEnabled {
 			log.Printf("Using API v1")
 		}
+	}
 	return &ServerImpl{
 		config:   config,
 		listener: config.Listener,
 		stopChan: make(chan struct{}),
+		log:      logEnabled,
 	}
 }
 
@@ -130,10 +130,10 @@ func (s *ServerImpl) Run() error {
 
 	s.methodMaps[0] = map[string]*methodType{}
 	s.methodMaps[1] = map[string]*methodType{}
-	suitableMethods(s.s1, s.methodMaps[0])
-	suitableMethods(rpcServer, s.methodMaps[0])
-	suitableMethods(s.s2, s.methodMaps[1])
-	suitableMethods(rpcServer, s.methodMaps[1])
+	suitableMethods(s.s1, s.methodMaps[0], s.log)
+	suitableMethods(rpcServer, s.methodMaps[0], s.log)
+	suitableMethods(s.s2, s.methodMaps[1], s.log)
+	suitableMethods(rpcServer, s.methodMaps[1], s.log)
 
 	go func() {
 		defer s.listener.Close()
@@ -183,12 +183,14 @@ func isExportedOrBuiltinType(t reflect.Type) bool {
 // two signatures:
 //  func (rcvr ReceiverType) Method(in InputType, out *ReplyType) error
 //  func (rcvr ReceiverType) Method(in InputType, cb service.RPCCallback)
-func suitableMethods(rcvr interface{}, methods map[string]*methodType) {
+func suitableMethods(rcvr interface{}, methods map[string]*methodType, logEnabled bool) {
 	typ := reflect.TypeOf(rcvr)
 	rcvrv := reflect.ValueOf(rcvr)
 	sname := reflect.Indirect(rcvrv).Type().Name()
 	if sname == "" {
+		if logEnabled {
 			log.Printf("rpc.Register: no service name for type %s", typ)
+		}
 		return
 	}
 	for m := 0; m < typ.NumMethod(); m++ {
@@ -201,13 +203,17 @@ func suitableMethods(rcvr interface{}, methods map[string]*methodType) {
 		}
 		// Method needs three ins: (receive, *args, *reply) or (receiver, *args, *RPCCallback)
 		if mtype.NumIn() != 3 {
+			if logEnabled {
 				log.Println("method", mname, "has wrong number of ins:", mtype.NumIn())
+			}
 			continue
 		}
 		// First arg need not be a pointer.
 		argType := mtype.In(1)
 		if !isExportedOrBuiltinType(argType) {
+			if logEnabled {
 				log.Println(mname, "argument type not exported:", argType)
+			}
 			continue
 		}
 
@@ -217,29 +223,39 @@ func suitableMethods(rcvr interface{}, methods map[string]*methodType) {
 		if synchronous {
 			// Second arg must be a pointer.
 			if replyType.Kind() != reflect.Ptr {
+				if logEnabled {
 					log.Println("method", mname, "reply type not a pointer:", replyType)
+				}
 				continue
 			}
 			// Reply type must be exported.
 			if !isExportedOrBuiltinType(replyType) {
+				if logEnabled {
 					log.Println("method", mname, "reply type not exported:", replyType)
+				}
 				continue
 			}
 
 			// Method needs one out.
 			if mtype.NumOut() != 1 {
+				if logEnabled {
 					log.Println("method", mname, "has wrong number of outs:", mtype.NumOut())
+				}
 				continue
 			}
 			// The return type of the method must be error.
 			if returnType := mtype.Out(0); returnType != typeOfError {
+				if logEnabled {
 					log.Println("method", mname, "returns", returnType.String(), "not error")
+				}
 				continue
 			}
 		} else {
 			// Method needs zero outs.
 			if mtype.NumOut() != 0 {
+				if logEnabled {
 					log.Println("method", mname, "has wrong number of outs:", mtype.NumOut())
+				}
 				continue
 			}
 		}
@@ -257,14 +273,18 @@ func (s *ServerImpl) serveJSONCodec(conn io.ReadWriteCloser) {
 		err := codec.ReadRequestHeader(&req)
 		if err != nil {
 			if err != io.EOF {
+				if s.log {
 					log.Println("rpc:", err)
 				}
+			}
 			break
 		}
 
 		mtype, ok := s.methodMaps[s.config.APIVersion-1][req.ServiceMethod]
 		if !ok {
+			if s.log {
 				log.Printf("rpc: can't find method %s", req.ServiceMethod)
+			}
 			continue
 		}
 
@@ -287,6 +307,10 @@ func (s *ServerImpl) serveJSONCodec(conn io.ReadWriteCloser) {
 		}
 
 		if mtype.Synchronous {
+			if s.log {
+				argvbytes, _ := json.Marshal(argv.Interface())
+				log.Printf("-> %s(%T%s)\n", req.ServiceMethod, argv.Interface(), argvbytes)
+			}
 			replyv = reflect.New(mtype.ReplyType.Elem())
 			function := mtype.method.Func
 			var returnValues []reflect.Value
@@ -306,8 +330,16 @@ func (s *ServerImpl) serveJSONCodec(conn io.ReadWriteCloser) {
 				errmsg = errInter.(error).Error()
 			}
 			resp = rpc.Response{}
+			if s.log {
+				replyvbytes, _ := json.Marshal(replyv.Interface())
+				log.Printf("<- %T%s error: %q\n", replyv.Interface(), replyvbytes, errmsg)
+			}
 			s.sendResponse(sending, &req, &resp, replyv.Interface(), codec, errmsg)
 		} else {
+			if s.log {
+				argvbytes, _ := json.Marshal(argv.Interface())
+				log.Printf("(async %d) -> %s(%T%s)\n", req.Seq, req.ServiceMethod, argv.Interface(), argvbytes)
+			}
 			function := mtype.method.Func
 			ctl := &RPCCallback{s, sending, codec, req}
 			go func() {
@@ -342,9 +374,11 @@ func (s *ServerImpl) sendResponse(sending *sync.Mutex, req *rpc.Request, resp *r
 	defer sending.Unlock()
 	err := codec.WriteResponse(resp, reply)
 	if err != nil {
+		if s.log {
 			log.Println("rpc: writing response:", err)
 		}
 	}
+}
 
 func (cb *RPCCallback) Return(out interface{}, err error) {
 	errmsg := ""
@@ -352,6 +386,10 @@ func (cb *RPCCallback) Return(out interface{}, err error) {
 		errmsg = err.Error()
 	}
 	var resp rpc.Response
+	if cb.s.log {
+		outbytes, _ := json.Marshal(out)
+		log.Printf("(async %d) <- %T%s error: %q", cb.req.Seq, out, outbytes, errmsg)
+	}
 	cb.s.sendResponse(cb.sending, &cb.req, &resp, out, cb.codec, errmsg)
 }