*: 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()
-	assertNoError(err, t, "stdout pipe")
+	stderr, err := cmd.StderrPipe()
+	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,24 +46,25 @@ 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)
 	)
 
 	// 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
 }
 
 // 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 {
-				log.Printf("AllPCsForFileLine error: %v", err)
+			if lineInfo.Logf != nil {
+				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 {
-				log.Printf("AllPCsBetween error: %v", err)
+			if lineInfo.Logf != nil {
+				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 {
-				log.Printf("PCToLine error: %v", err)
+			if sm.dbl.Logf != nil {
+				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 {
-				log.Printf("PCToLine error: %v", err)
+			if sm.dbl.Logf != nil {
+				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 {
-				log.Printf("LineToPC error: %v", err)
+			if lineInfo.Logf != nil {
+				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 {
-				log.Printf("PrologueEnd error: %v", err)
+			if lineInfo.Logf != nil {
+				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() {
-		fmt.Println("<- interrupt")
-	}
+	conn.log.Debug("<- 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() {
-		fmt.Printf("-> %s\n", string(b))
-	}
+	conn.log.Debugf("-> %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() {
-		fmt.Printf("<- %s\n", string(c))
-	}
+	conn.log.Debugf("<- %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:]))
-				cu.lineInfo.LogSuppressedErrors(logflags.DebugLineErrors())
+				var logfn func(string, ...interface{})
+				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)
 	}