*: Use structured logging

Implements structured logging via Logrus. This gives us a logger per
boundry that we care about, allowing for easier parsing of logs if users
have more than one log option enabled. Also, cleans up a lot of
conditionals in the code by simply silencing the logger at creation as
opposed to conditionally logging everywhere.

cmd/dlv/cmds/commands.go

@@ -364,7 +364,7 @@ func traceCmd(cmd *cobra.Command, args []string) {
 			APIVersion:  2,
 			WorkingDir:  WorkingDir,
 			Backend:     Backend,
-		}, logflags.RPC())
+		})
 		if err := server.Run(); err != nil {
 			fmt.Fprintln(os.Stderr, err)
 			return 1
@@ -510,7 +510,7 @@ func execute(attachPid int, processArgs []string, conf *config.Config, coreFile
 			Foreground:  Headless,
 
 			DisconnectChan: disconnectChan,
-		}, logflags.RPC())
+		})
 	default:
 		fmt.Printf("Unknown API version: %d\n", APIVersion)
 		return 1
@@ -535,8 +535,6 @@ func execute(attachPid int, processArgs []string, conf *config.Config, coreFile
 
 	var status int
 	if Headless {
-		// Print listener address
-		fmt.Printf("API server listening at: %s\n", listener.Addr())
 		ch := make(chan os.Signal, 1)
 		signal.Notify(ch, syscall.SIGINT)
 		select {

cmd/dlv/dlv_test.go

@@ -80,13 +80,13 @@ func TestBuild(t *testing.T) {
 
 	buildtestdir := filepath.Join(fixtures, "buildtest")
 
-	cmd := exec.Command(dlvbin, "debug", "--headless=true", "--listen="+listenAddr, "--api-version=2", "--backend="+testBackend)
+	cmd := exec.Command(dlvbin, "debug", "--headless=true", "--listen="+listenAddr, "--api-version=2", "--backend="+testBackend, "--log", "--log-output=debugger,rpc")
 	cmd.Dir = buildtestdir
-	stdout, err := cmd.StdoutPipe()
+	stderr, err := cmd.StderrPipe()
-	assertNoError(err, t, "stdout pipe")
+	assertNoError(err, t, "stderr pipe")
 	cmd.Start()
 
-	scan := bufio.NewScanner(stdout)
+	scan := bufio.NewScanner(stderr)
 	// wait for the debugger to start
 	scan.Scan()
 	go func() {

pkg/dwarf/line/line_parser.go

@@ -27,14 +27,13 @@ type DebugLineInfo struct {
 	Instructions []byte
 	Lookup       map[string]*FileEntry
 
+	Logf func(string, ...interface{})
+
 	// stateMachineCache[pc] is a state machine stopped at pc
 	stateMachineCache map[uint64]*StateMachine
 
 	// lastMachineCache[pc] is a state machine stopped at an address after pc
 	lastMachineCache map[uint64]*StateMachine
-
-	// logSuppressedErrors enables logging of otherwise suppressed errors
-	logSuppressedErrors bool
 }
 
 type FileEntry struct {
@@ -47,7 +46,7 @@ type FileEntry struct {
 type DebugLines []*DebugLineInfo
 
 // ParseAll parses all debug_line segments found in data
-func ParseAll(data []byte) DebugLines {
+func ParseAll(data []byte, logfn func(string, ...interface{})) DebugLines {
 	var (
 		lines = make(DebugLines, 0)
 		buf   = bytes.NewBuffer(data)
@@ -55,7 +54,7 @@ func ParseAll(data []byte) DebugLines {
 
 	// We have to parse multiple file name tables here.
 	for buf.Len() > 0 {
-		lines = append(lines, Parse("", buf))
+		lines = append(lines, Parse("", buf, logfn))
 	}
 
 	return lines
@@ -63,8 +62,9 @@ func ParseAll(data []byte) DebugLines {
 
 // Parse parses a single debug_line segment from buf. Compdir is the
 // DW_AT_comp_dir attribute of the associated compile unit.
-func Parse(compdir string, buf *bytes.Buffer) *DebugLineInfo {
+func Parse(compdir string, buf *bytes.Buffer, logfn func(string, ...interface{})) *DebugLineInfo {
 	dbl := new(DebugLineInfo)
+	dbl.Logf = logfn
 	dbl.Lookup = make(map[string]*FileEntry)
 	if compdir != "" {
 		dbl.IncludeDirs = append(dbl.IncludeDirs, compdir)
@@ -146,8 +146,3 @@ func readFileEntry(info *DebugLineInfo, buf *bytes.Buffer, exitOnEmptyPath bool)
 
 	return entry
 }
-
-// LogSuppressedErrors enables or disables logging of suppressed errors
-func (dbl *DebugLineInfo) LogSuppressedErrors(v bool) {
-	dbl.logSuppressedErrors = v
-}

pkg/dwarf/line/line_parser_test.go

@@ -67,7 +67,7 @@ const (
 
 func testDebugLinePrologueParser(p string, t *testing.T) {
 	data := grabDebugLineSection(p, t)
-	debugLines := ParseAll(data)
+	debugLines := ParseAll(data, nil)
 
 	mainFileFound := false
 
@@ -164,7 +164,7 @@ func BenchmarkLineParser(b *testing.B) {
 
 	b.ResetTimer()
 	for i := 0; i < b.N; i++ {
-		_ = ParseAll(data)
+		_ = ParseAll(data, nil)
 	}
 }
 
@@ -179,7 +179,7 @@ func loadBenchmarkData(tb testing.TB) DebugLines {
 		tb.Fatal("Could not read test data", err)
 	}
 
-	return ParseAll(data)
+	return ParseAll(data, nil)
 }
 
 func BenchmarkStateMachine(b *testing.B) {

pkg/dwarf/line/state_machine.go

@@ -5,7 +5,6 @@ import (
 	"encoding/binary"
 	"errors"
 	"fmt"
-	"log"
 
 	"github.com/derekparker/delve/pkg/dwarf/util"
 )
@@ -125,8 +124,8 @@ func (lineInfo *DebugLineInfo) AllPCsForFileLine(f string, l int) (pcs []uint64)
 
 	for {
 		if err := sm.next(); err != nil {
-			if lineInfo.logSuppressedErrors {
+			if lineInfo.Logf != nil {
-				log.Printf("AllPCsForFileLine error: %v", err)
+				lineInfo.Logf("AllPCsForFileLine error: %v", err)
 			}
 			break
 		}
@@ -154,8 +153,8 @@ func (lineInfo *DebugLineInfo) AllPCsBetween(begin, end uint64, excludeFile stri
 
 	for {
 		if err := sm.next(); err != nil {
-			if lineInfo.logSuppressedErrors {
+			if lineInfo.Logf != nil {
-				log.Printf("AllPCsBetween error: %v", err)
+				lineInfo.Logf("AllPCsBetween error: %v", err)
 			}
 			break
 		}
@@ -228,8 +227,8 @@ func (lineInfo *DebugLineInfo) PCToLine(basePC, pc uint64) (string, int) {
 func (sm *StateMachine) PCToLine(pc uint64) (string, int, bool) {
 	if !sm.started {
 		if err := sm.next(); err != nil {
-			if sm.dbl.logSuppressedErrors {
+			if sm.dbl.Logf != nil {
-				log.Printf("PCToLine error: %v", err)
+				sm.dbl.Logf("PCToLine error: %v", err)
 			}
 			return "", 0, false
 		}
@@ -247,8 +246,8 @@ func (sm *StateMachine) PCToLine(pc uint64) (string, int, bool) {
 			}
 		}
 		if err := sm.next(); err != nil {
-			if sm.dbl.logSuppressedErrors {
+			if sm.dbl.Logf != nil {
-				log.Printf("PCToLine error: %v", err)
+				sm.dbl.Logf("PCToLine error: %v", err)
 			}
 			break
 		}
@@ -276,8 +275,8 @@ func (lineInfo *DebugLineInfo) LineToPC(filename string, lineno int) uint64 {
 
 	for {
 		if err := sm.next(); err != nil {
-			if lineInfo.logSuppressedErrors {
+			if lineInfo.Logf != nil {
-				log.Printf("LineToPC error: %v", err)
+				lineInfo.Logf("LineToPC error: %v", err)
 			}
 			break
 		}
@@ -311,8 +310,8 @@ func (lineInfo *DebugLineInfo) PrologueEndPC(start, end uint64) (pc uint64, file
 			}
 		}
 		if err := sm.next(); err != nil {
-			if lineInfo.logSuppressedErrors {
+			if lineInfo.Logf != nil {
-				log.Printf("PrologueEnd error: %v", err)
+				lineInfo.Logf("PrologueEnd error: %v", err)
 			}
 			return 0, "", 0, false
 		}

pkg/proc/gdbserial/gdbserver.go

@@ -68,6 +68,7 @@ import (
 	"errors"
 	"fmt"
 	"go/ast"
+	"io/ioutil"
 	"net"
 	"os"
 	"os/exec"
@@ -81,6 +82,7 @@ import (
 
 	"github.com/derekparker/delve/pkg/logflags"
 	"github.com/derekparker/delve/pkg/proc"
+	"github.com/sirupsen/logrus"
 )
 
 const (
@@ -166,11 +168,17 @@ type gdbRegister struct {
 // Detach.
 // Use Listen, Dial or Connect to complete connection.
 func New(process *os.Process) *Process {
+	logger := logrus.New().WithFields(logrus.Fields{"layer": "gdbconn"})
+	logger.Level = logrus.DebugLevel
+	if !logflags.GdbWire() {
+		logger.Logger.Out = ioutil.Discard
+	}
 	p := &Process{
 		conn: gdbConn{
 			maxTransmitAttempts: maxTransmitAttempts,
 			inbuf:               make([]byte, 0, initialInputBufferSize),
 			direction:           proc.Forward,
+			log:                 logger,
 		},
 		threads:        make(map[int]*Thread),
 		bi:             proc.NewBinaryInfo(runtime.GOOS, runtime.GOARCH),

pkg/proc/gdbserial/gdbserver_conn.go

@@ -18,6 +18,7 @@ import (
 
 	"github.com/derekparker/delve/pkg/logflags"
 	"github.com/derekparker/delve/pkg/proc"
+	"github.com/sirupsen/logrus"
 )
 
 type gdbConn struct {
@@ -43,6 +44,8 @@ type gdbConn struct {
 	maxTransmitAttempts   int  // maximum number of transmit or receive attempts when bad checksums are read
 	threadSuffixSupported bool // thread suffix supported by stub
 	isDebugserver         bool // true if the stub is debugserver
+
+	log *logrus.Entry
 }
 
 const (
@@ -634,7 +637,7 @@ func (conn *gdbConn) parseStopPacket(resp []byte, threadID string, tu *threadUpd
 		sp.sig = uint8(sig)
 
 		if logflags.GdbWire() && gdbWireFullStopPacket {
-			fmt.Fprintf(os.Stderr, "full stop packet: %s\n", string(resp))
+			conn.log.Debug("full stop packet: %s\n", string(resp))
 		}
 
 		buf := resp[3:]
@@ -705,9 +708,7 @@ const ctrlC = 0x03 // the ASCII character for ^C
 
 // executes a ctrl-C on the line
 func (conn *gdbConn) sendCtrlC() error {
-	if logflags.GdbWire() {
+	conn.log.Debug("<- interrupt")
-		fmt.Println("<- interrupt")
-	}
 	_, err := conn.conn.Write([]byte{ctrlC})
 	return err
 }
@@ -994,9 +995,9 @@ func (conn *gdbConn) send(cmd []byte) error {
 	for {
 		if logflags.GdbWire() {
 			if len(cmd) > gdbWireMaxLen {
-				fmt.Printf("<- %s...\n", string(cmd[:gdbWireMaxLen]))
+				conn.log.Debugf("<- %s...\n", string(cmd[:gdbWireMaxLen]))
 			} else {
-				fmt.Printf("<- %s\n", string(cmd))
+				conn.log.Debugf("<- %s\n", string(cmd))
 			}
 		}
 		_, err := conn.conn.Write(cmd)
@@ -1045,9 +1046,9 @@ func (conn *gdbConn) recv(cmd []byte, context string, binary bool) (resp []byte,
 				partial = true
 			}
 			if !partial {
-				fmt.Printf("-> %s%s\n", string(resp), string(conn.inbuf[:2]))
+				conn.log.Debugf("-> %s%s\n", string(resp), string(conn.inbuf[:2]))
 			} else {
-				fmt.Printf("-> %s...\n", string(out))
+				conn.log.Debugf("-> %s...\n", string(out))
 			}
 		}
 
@@ -1098,9 +1099,7 @@ func (conn *gdbConn) readack() bool {
 	if err != nil {
 		return false
 	}
-	if logflags.GdbWire() {
+	conn.log.Debugf("-> %s\n", string(b))
-		fmt.Printf("-> %s\n", string(b))
-	}
 	return b == '+'
 }
 
@@ -1110,9 +1109,7 @@ func (conn *gdbConn) sendack(c byte) {
 		panic(fmt.Errorf("sendack(%c)", c))
 	}
 	conn.conn.Write([]byte{c})
-	if logflags.GdbWire() {
+	conn.log.Debugf("<- %s\n", string(c))
-		fmt.Printf("<- %s\n", string(c))
-	}
 }
 
 // escapeXor is the value mandated by the specification to escape characters

pkg/proc/types.go

@@ -24,6 +24,7 @@ import (
 	"github.com/derekparker/delve/pkg/dwarf/reader"
 	"github.com/derekparker/delve/pkg/goversion"
 	"github.com/derekparker/delve/pkg/logflags"
+	"github.com/sirupsen/logrus"
 )
 
 // The kind field in runtime._type is a reflect.Kind value plus
@@ -220,8 +221,15 @@ func (bi *BinaryInfo) loadDebugInfoMaps(debugLineBytes []byte, wg *sync.WaitGrou
 			}
 			lineInfoOffset, _ := entry.Val(dwarf.AttrStmtList).(int64)
 			if lineInfoOffset >= 0 && lineInfoOffset < int64(len(debugLineBytes)) {
-				cu.lineInfo = line.Parse(compdir, bytes.NewBuffer(debugLineBytes[lineInfoOffset:]))
+				var logfn func(string, ...interface{})
-				cu.lineInfo.LogSuppressedErrors(logflags.DebugLineErrors())
+				if logflags.DebugLineErrors() {
+					logger := logrus.New().WithFields(logrus.Fields{"layer": "dwarf-line"})
+					logger.Level = logrus.DebugLevel
+					logfn = func(fmt string, args ...interface{}) {
+						logger.Printf(fmt, args)
+					}
+				}
+				cu.lineInfo = line.Parse(compdir, bytes.NewBuffer(debugLineBytes[lineInfoOffset:]), logfn)
 			}
 			cu.producer, _ = entry.Val(dwarf.AttrProducer).(string)
 			if cu.isgo && cu.producer != "" {

pkg/terminal/command_test.go

@@ -113,7 +113,7 @@ func withTestTerminalBuildFlags(name string, t testing.TB, buildFlags test.Build
 		Listener:    listener,
 		ProcessArgs: []string{test.BuildFixture(name, buildFlags).Path},
 		Backend:     testBackend,
-	}, false)
+	})
 	if err := server.Run(); err != nil {
 		t.Fatal(err)
 	}

service/debugger/debugger.go

@@ -4,7 +4,7 @@ import (
 	"errors"
 	"fmt"
 	"go/parser"
-	"log"
+	"io/ioutil"
 	"path/filepath"
 	"regexp"
 	"runtime"
@@ -18,6 +18,7 @@ import (
 	"github.com/derekparker/delve/pkg/proc/gdbserial"
 	"github.com/derekparker/delve/pkg/proc/native"
 	"github.com/derekparker/delve/service/api"
+	"github.com/sirupsen/logrus"
 )
 
 // Debugger service.
@@ -35,6 +36,7 @@ type Debugger struct {
 	// TODO(DO NOT MERGE WITHOUT) rename to targetMutex
 	processMutex sync.Mutex
 	target       proc.Process
+	log          *logrus.Entry
 }
 
 // Config provides the configuration to start a Debugger.
@@ -63,17 +65,21 @@ type Config struct {
 // New creates a new Debugger. ProcessArgs specify the commandline arguments for the
 // new process.
 func New(config *Config, processArgs []string) (*Debugger, error) {
+	logger := logrus.New().WithFields(logrus.Fields{"layer": "debugger"})
+	logger.Level = logrus.DebugLevel
+	if !logflags.Debugger() {
+		logger.Logger.Out = ioutil.Discard
+	}
 	d := &Debugger{
 		config:      config,
 		processArgs: processArgs,
+		log:         logger,
 	}
 
 	// Create the process by either attaching or launching.
 	switch {
 	case d.config.AttachPid > 0:
-		if logflags.Debugger() {
+		d.log.Infof("attaching to pid %d", d.config.AttachPid)
-			log.Printf("attaching to pid %d", d.config.AttachPid)
-		}
 		path := ""
 		if len(d.processArgs) > 0 {
 			path = d.processArgs[0]
@@ -89,14 +95,10 @@ func New(config *Config, processArgs []string) (*Debugger, error) {
 		var err error
 		switch d.config.Backend {
 		case "rr":
-			if logflags.Debugger() {
+			d.log.Infof("opening trace %s", d.config.CoreFile)
-				log.Printf("opening trace %s", d.config.CoreFile)
-			}
 			p, err = gdbserial.Replay(d.config.CoreFile, false)
 		default:
-			if logflags.Debugger() {
+			d.log.Infof("opening core file %s (executable %s)", d.config.CoreFile, d.processArgs[0])
-				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 {
@@ -105,9 +107,7 @@ func New(config *Config, processArgs []string) (*Debugger, error) {
 		d.target = p
 
 	default:
-		if logflags.Debugger() {
+		d.log.Infof("launching process with args: %v", d.processArgs)
-			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 {
@@ -367,9 +367,7 @@ func (d *Debugger) CreateBreakpoint(requestedBp *api.Breakpoint) (*api.Breakpoin
 		return nil, err
 	}
 	createdBp = api.ConvertBreakpoint(bp)
-	if logflags.Debugger() {
+	d.log.Infof("created breakpoint: %#v", createdBp)
-		log.Printf("created breakpoint: %#v", createdBp)
-	}
 	return createdBp, nil
 }
 
@@ -417,9 +415,7 @@ 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() {
+	d.log.Infof("cleared breakpoint: %#v", clearedBp)
-		log.Printf("cleared breakpoint: %#v", clearedBp)
-	}
 	return clearedBp, err
 }
 
@@ -517,9 +513,7 @@ 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() {
+		d.log.Debug("halting")
-			log.Print("halting")
-		}
 		err = d.target.RequestManualStop()
 	}
 
@@ -530,14 +524,10 @@ func (d *Debugger) Command(command *api.DebuggerCommand) (*api.DebuggerState, er
 
 	switch command.Name {
 	case api.Continue:
-		if logflags.Debugger() {
+		d.log.Debug("continuing")
-			log.Print("continuing")
-		}
 		err = proc.Continue(d.target)
 	case api.Rewind:
-		if logflags.Debugger() {
+		d.log.Debug("rewinding")
-			log.Print("rewinding")
-		}
 		if err := d.target.Direction(proc.Backward); err != nil {
 			return nil, err
 		}
@@ -546,35 +536,23 @@ func (d *Debugger) Command(command *api.DebuggerCommand) (*api.DebuggerState, er
 		}()
 		err = proc.Continue(d.target)
 	case api.Next:
-		if logflags.Debugger() {
+		d.log.Debug("nexting")
-			log.Print("nexting")
-		}
 		err = proc.Next(d.target)
 	case api.Step:
-		if logflags.Debugger() {
+		d.log.Debug("stepping")
-			log.Print("stepping")
-		}
 		err = proc.Step(d.target)
 	case api.StepInstruction:
-		if logflags.Debugger() {
+		d.log.Debug("single stepping")
-			log.Print("single stepping")
-		}
 		err = d.target.StepInstruction()
 	case api.StepOut:
-		if logflags.Debugger() {
+		d.log.Debug("step out")
-			log.Print("step out")
-		}
 		err = proc.StepOut(d.target)
 	case api.SwitchThread:
-		if logflags.Debugger() {
+		d.log.Debugf("switching to thread %d", command.ThreadID)
-			log.Printf("switching to thread %d", command.ThreadID)
-		}
 		err = d.target.SwitchThread(command.ThreadID)
 		withBreakpointInfo = false
 	case api.SwitchGoroutine:
-		if logflags.Debugger() {
+		d.log.Debugf("switching to goroutine %d", command.GoroutineID)
-			log.Printf("switching to goroutine %d", command.GoroutineID)
-		}
 		err = d.target.SwitchGoroutine(command.GoroutineID)
 		withBreakpointInfo = false
 	case api.Halt:

service/rpccommon/server.go

@@ -6,7 +6,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
+	"io/ioutil"
 	"net"
 	"net/rpc"
 	"net/rpc/jsonrpc"
@@ -16,12 +16,14 @@ import (
 	"unicode"
 	"unicode/utf8"
 
+	"github.com/derekparker/delve/pkg/logflags"
 	"github.com/derekparker/delve/pkg/version"
 	"github.com/derekparker/delve/service"
 	"github.com/derekparker/delve/service/api"
 	"github.com/derekparker/delve/service/debugger"
 	"github.com/derekparker/delve/service/rpc1"
 	"github.com/derekparker/delve/service/rpc2"
+	"github.com/sirupsen/logrus"
 )
 
 // ServerImpl implements a JSON-RPC server that can switch between two
@@ -41,7 +43,7 @@ type ServerImpl struct {
 	s2 *rpc2.RPCServer
 	// maps of served methods, one for each supported API.
 	methodMaps []map[string]*methodType
-	log        bool
+	log        *logrus.Entry
 }
 
 type RPCCallback struct {
@@ -65,17 +67,24 @@ type methodType struct {
 }
 
 // NewServer creates a new RPCServer.
-func NewServer(config *service.Config, logEnabled bool) *ServerImpl {
+func NewServer(config *service.Config) *ServerImpl {
+	logger := logrus.New().WithFields(logrus.Fields{"layer": "rpc"})
+	logger.Level = logrus.DebugLevel
+	if !logflags.RPC() {
+		logger.Logger.Out = ioutil.Discard
+	}
 	if config.APIVersion < 2 {
-		if logEnabled {
+		logger.Info("Using API v1")
-			log.Printf("Using API v1")
+	}
-		}
+	if config.Foreground {
+		// Print listener address
+		logger.Infof("API server listening at: %s", config.Listener.Addr())
 	}
 	return &ServerImpl{
 		config:   config,
 		listener: config.Listener,
 		stopChan: make(chan struct{}),
-		log:      logEnabled,
+		log:      logger,
 	}
 }
 
@@ -183,14 +192,12 @@ 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, logEnabled bool) {
+func suitableMethods(rcvr interface{}, methods map[string]*methodType, log *logrus.Entry) {
 	typ := reflect.TypeOf(rcvr)
 	rcvrv := reflect.ValueOf(rcvr)
 	sname := reflect.Indirect(rcvrv).Type().Name()
 	if sname == "" {
-		if logEnabled {
+		log.Debugf("rpc.Register: no service name for type %s", typ)
-			log.Printf("rpc.Register: no service name for type %s", typ)
-		}
 		return
 	}
 	for m := 0; m < typ.NumMethod(); m++ {
@@ -203,17 +210,13 @@ func suitableMethods(rcvr interface{}, methods map[string]*methodType, logEnable
 		}
 		// Method needs three ins: (receive, *args, *reply) or (receiver, *args, *RPCCallback)
 		if mtype.NumIn() != 3 {
-			if logEnabled {
+			log.Warn("method", mname, "has wrong number of ins:", mtype.NumIn())
-				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.Warn(mname, "argument type not exported:", argType)
-				log.Println(mname, "argument type not exported:", argType)
-			}
 			continue
 		}
 
@@ -223,39 +226,29 @@ func suitableMethods(rcvr interface{}, methods map[string]*methodType, logEnable
 		if synchronous {
 			// Second arg must be a pointer.
 			if replyType.Kind() != reflect.Ptr {
-				if logEnabled {
+				log.Warn("method", mname, "reply type not a pointer:", replyType)
-					log.Println("method", mname, "reply type not a pointer:", replyType)
-				}
 				continue
 			}
 			// Reply type must be exported.
 			if !isExportedOrBuiltinType(replyType) {
-				if logEnabled {
+				log.Warn("method", mname, "reply type not exported:", replyType)
-					log.Println("method", mname, "reply type not exported:", replyType)
-				}
 				continue
 			}
 
 			// Method needs one out.
 			if mtype.NumOut() != 1 {
-				if logEnabled {
+				log.Warn("method", mname, "has wrong number of outs:", mtype.NumOut())
-					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.Warn("method", mname, "returns", returnType.String(), "not error")
-					log.Println("method", mname, "returns", returnType.String(), "not error")
-				}
 				continue
 			}
 		} else {
 			// Method needs zero outs.
 			if mtype.NumOut() != 0 {
-				if logEnabled {
+				log.Warn("method", mname, "has wrong number of outs:", mtype.NumOut())
-					log.Println("method", mname, "has wrong number of outs:", mtype.NumOut())
-				}
 				continue
 			}
 		}
@@ -273,18 +266,14 @@ func (s *ServerImpl) serveJSONCodec(conn io.ReadWriteCloser) {
 		err := codec.ReadRequestHeader(&req)
 		if err != nil {
 			if err != io.EOF {
-				if s.log {
+				s.log.Error("rpc:", err)
-					log.Println("rpc:", err)
-				}
 			}
 			break
 		}
 
 		mtype, ok := s.methodMaps[s.config.APIVersion-1][req.ServiceMethod]
 		if !ok {
-			if s.log {
+			s.log.Errorf("rpc: can't find method %s", req.ServiceMethod)
-				log.Printf("rpc: can't find method %s", req.ServiceMethod)
-			}
 			continue
 		}
 
@@ -307,9 +296,9 @@ func (s *ServerImpl) serveJSONCodec(conn io.ReadWriteCloser) {
 		}
 
 		if mtype.Synchronous {
-			if s.log {
+			if logflags.RPC() {
 				argvbytes, _ := json.Marshal(argv.Interface())
-				log.Printf("-> %s(%T%s)\n", req.ServiceMethod, argv.Interface(), argvbytes)
+				s.log.Debugf("-> %s(%T%s)\n", req.ServiceMethod, argv.Interface(), argvbytes)
 			}
 			replyv = reflect.New(mtype.ReplyType.Elem())
 			function := mtype.method.Func
@@ -330,15 +319,15 @@ func (s *ServerImpl) serveJSONCodec(conn io.ReadWriteCloser) {
 				errmsg = errInter.(error).Error()
 			}
 			resp = rpc.Response{}
-			if s.log {
+			if logflags.RPC() {
 				replyvbytes, _ := json.Marshal(replyv.Interface())
-				log.Printf("<- %T%s error: %q\n", replyv.Interface(), replyvbytes, errmsg)
+				s.log.Debugf("<- %T%s error: %q\n", replyv.Interface(), replyvbytes, errmsg)
 			}
 			s.sendResponse(sending, &req, &resp, replyv.Interface(), codec, errmsg)
 		} else {
-			if s.log {
+			if logflags.RPC() {
 				argvbytes, _ := json.Marshal(argv.Interface())
-				log.Printf("(async %d) -> %s(%T%s)\n", req.Seq, req.ServiceMethod, argv.Interface(), argvbytes)
+				s.log.Debugf("(async %d) -> %s(%T%s)\n", req.Seq, req.ServiceMethod, argv.Interface(), argvbytes)
 			}
 			function := mtype.method.Func
 			ctl := &RPCCallback{s, sending, codec, req}
@@ -374,9 +363,7 @@ 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 {
+		s.log.Error("writing response:", err)
-			log.Println("rpc: writing response:", err)
-		}
 	}
 }
 
@@ -386,9 +373,9 @@ func (cb *RPCCallback) Return(out interface{}, err error) {
 		errmsg = err.Error()
 	}
 	var resp rpc.Response
-	if cb.s.log {
+	if logflags.RPC() {
 		outbytes, _ := json.Marshal(out)
-		log.Printf("(async %d) <- %T%s error: %q", cb.req.Seq, out, outbytes, errmsg)
+		cb.s.log.Debugf("(async %d) <- %T%s error: %q", cb.req.Seq, out, outbytes, errmsg)
 	}
 	cb.s.sendResponse(cb.sending, &cb.req, &resp, out, cb.codec, errmsg)
 }

service/test/integration1_test.go

@@ -33,7 +33,7 @@ func withTestClient1(name string, t *testing.T, fn func(c *rpc1.RPCClient)) {
 		Listener:    listener,
 		ProcessArgs: []string{protest.BuildFixture(name, 0).Path},
 		Backend:     testBackend,
-	}, false)
+	})
 	if err := server.Run(); err != nil {
 		t.Fatal(err)
 	}
@@ -61,7 +61,7 @@ func Test1RunWithInvalidPath(t *testing.T) {
 		Listener:    listener,
 		ProcessArgs: []string{"invalid_path"},
 		Backend:     testBackend,
-	}, false)
+	})
 	if err := server.Run(); err == nil {
 		t.Fatal("Expected Run to return error for invalid program path")
 	}
@@ -150,7 +150,7 @@ func Test1Restart_attachPid(t *testing.T) {
 		Listener:  nil,
 		AttachPid: 999,
 		Backend:   testBackend,
-	}, false)
+	})
 	if err := server.Restart(); err == nil {
 		t.Fatal("expected error on restart after attaching to pid but got none")
 	}

service/test/integration2_test.go

@@ -51,7 +51,7 @@ func withTestClient2(name string, t *testing.T, fn func(c service.Client)) {
 		Listener:    listener,
 		ProcessArgs: []string{protest.BuildFixture(name, 0).Path},
 		Backend:     testBackend,
-	}, false)
+	})
 	if err := server.Run(); err != nil {
 		t.Fatal(err)
 	}
@@ -84,7 +84,7 @@ func TestRunWithInvalidPath(t *testing.T) {
 		ProcessArgs: []string{"invalid_path"},
 		APIVersion:  2,
 		Backend:     testBackend,
-	}, false)
+	})
 	if err := server.Run(); err == nil {
 		t.Fatal("Expected Run to return error for invalid program path")
 	}
@@ -175,7 +175,7 @@ func TestRestart_attachPid(t *testing.T) {
 		AttachPid:  999,
 		APIVersion: 2,
 		Backend:    testBackend,
-	}, false)
+	})
 	if err := server.Restart(); err == nil {
 		t.Fatal("expected error on restart after attaching to pid but got none")
 	}