Miscellaneous logging improvements (#1525)

* *: use loglevel to control what gets logged instead of output redirection

This stops logrus from doing all the formatting just to discard it
immediately afterwards.

* logflags: replace default formatter of logrus

The default formatter of logrus emits logs in two different formats
depending on whether or not the output is going to a terminal. The
output format for non-terminals is indented to be machine readable, but
we mostly read logs ourselves and the excessive quoting makes that
format unreadable.
When outputting to terminals it uses ANSI escape codes unconditionally,
without checking whether the terminal it is connected to actually
supports colors.

This commit replaces the default formatter with a much simpler
formatter that always uses a more readable format, doesn't use colors
and places the key-value pairs at the beginning of the line (which is a
better match for how we use them).

* cmd/dlv: add command line options to redirect logs

Adds two options, --log-to-file and --log-to-fd, to redirect logs to a
file or to a file descriptor.

When one of those two options is specified the "API server listening
at:" message will also be redirected to the specified file/file
descriptor.
This allows clients that want to use the "API server listening at:"
message to do so even if they want to redirect the target's stdout to
another file or device.

Implements #1179, #1523

Documentation/api/ClientHowto.md

@@ -33,6 +33,8 @@ This will, however, cause problems if you actually spawn multiple instances of t
 
 It's probably better to let Delve pick a random unused port number on its own. To do this do not specify any `--listen` option and read one line of output from dlv's stdout. If the first line emitted by dlv starts with "API server listening at: " then dlv started correctly and the rest of the line specifies the address that Delve is listening at.
 
+The `--log-to-file` and `--log-to-fd` options can be used to redirect the "API server listening at:" message to a file or to a file descriptor. If neither is specified the message will be output to stdout.
+
 ## Controlling the backend
 
 Once you have a running headless instance you can connect to it and start sending commands. Delve's protocol is built on top of the [JSON-RPC](http://json-rpc.org) specification.

Documentation/usage/dlv.md

@@ -32,6 +32,7 @@ Pass flags to the program you are debugging using `--`, for example:
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_attach.md

@@ -32,6 +32,7 @@ dlv attach pid [executable]
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_connect.md

@@ -27,6 +27,7 @@ dlv connect addr
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_core.md

@@ -33,6 +33,7 @@ dlv core <executable> <core>
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_debug.md

@@ -38,6 +38,7 @@ dlv debug [package]
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_exec.md

@@ -33,6 +33,7 @@ dlv exec <path/to/binary>
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_replay.md

@@ -31,6 +31,7 @@ dlv replay [trace directory]
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_run.md

@@ -27,6 +27,7 @@ dlv run
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_test.md

@@ -38,6 +38,7 @@ dlv test [package]
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_trace.md

@@ -42,6 +42,7 @@ dlv trace [package] regexp
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

Documentation/usage/dlv_version.md

@@ -27,6 +27,7 @@ dlv version
       --init string          Init file, executed by the terminal client.
   -l, --listen string        Debugging server listen address. (default "localhost:0")
       --log                  Enable debugging server logging.
+      --log-dest string      Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the "API listening" message in headless mode.
       --log-output string    Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
 	gdbwire		Log connection to gdbserial backend

cmd/dlv/cmds/commands.go

@@ -29,6 +29,8 @@ var (
 	Log bool
 	// LogOutput is a comma separated list of components that should produce debug output.
 	LogOutput string
+	// LogDest is the file path or file descriptor where logs should go.
+	LogDest string
 	// Headless is whether to run without terminal.
 	Headless bool
 	// APIVersion is the requested API version while running headless
@@ -90,6 +92,7 @@ func New(docCall bool) *cobra.Command {
 	}
 
 	RootCommand.PersistentFlags().StringVarP(&Addr, "listen", "l", "localhost:0", "Debugging server listen address.")
+
 	RootCommand.PersistentFlags().BoolVarP(&Log, "log", "", false, "Enable debugging server logging.")
 	RootCommand.PersistentFlags().StringVarP(&LogOutput, "log-output", "", "", `Comma separated list of components that should produce debug output, possible values:
 	debugger	Log debugger commands
@@ -100,6 +103,8 @@ func New(docCall bool) *cobra.Command {
 	fncall		Log function call protocol
 	minidump	Log minidump loading
 Defaults to "debugger" when logging is enabled with --log.`)
+	RootCommand.PersistentFlags().StringVarP(&LogDest, "log-dest", "", "", "Writes logs to the specified file or file descriptor. If the argument is a number it will be interpreted as a file descriptor, otherwise as a file path. This option will also redirect the \"API listening\" message in headless mode.")
+
 	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.")
 	RootCommand.PersistentFlags().IntVar(&APIVersion, "api-version", 1, "Selects API version when headless.")
@@ -320,7 +325,8 @@ func debugCmd(cmd *cobra.Command, args []string) {
 
 func traceCmd(cmd *cobra.Command, args []string) {
 	status := func() int {
-		err := logflags.Setup(Log, LogOutput)
+		err := logflags.Setup(Log, LogOutput, LogDest)
+		defer logflags.Close()
 		if err != nil {
 			fmt.Fprintf(os.Stderr, "%v\n", err)
 			return 1
@@ -541,10 +547,11 @@ const (
 )
 
 func execute(attachPid int, processArgs []string, conf *config.Config, coreFile string, kind executeKind) int {
-	if err := logflags.Setup(Log, LogOutput); err != nil {
+	if err := logflags.Setup(Log, LogOutput, LogDest); err != nil {
 		fmt.Fprintf(os.Stderr, "%v\n", err)
 		return 1
 	}
+	defer logflags.Close()
 
 	if Headless && (InitFile != "") {
 		fmt.Fprint(os.Stderr, "Warning: init file ignored\n")

pkg/logflags/logflags.go

@@ -1,10 +1,19 @@
 package logflags
 
 import (
+	"bytes"
 	"errors"
+	"fmt"
+	"io"
 	"io/ioutil"
 	"log"
+	"os"
+	"sort"
+	"strconv"
 	"strings"
+	"time"
+
+	"github.com/sirupsen/logrus"
 )
 
 var debugger = false
@@ -15,17 +24,42 @@ var rpc = false
 var fnCall = false
 var minidump = false
 
+var logOut io.WriteCloser
+
+func makeLogger(flag bool, fields logrus.Fields) *logrus.Entry {
+	logger := logrus.New().WithFields(fields)
+	logger.Logger.Formatter = &textFormatter{}
+	if logOut != nil {
+		logger.Logger.Out = logOut
+	}
+	logger.Logger.Level = logrus.DebugLevel
+	if !flag {
+		logger.Logger.Level = logrus.PanicLevel
+	}
+	return logger
+}
+
 // GdbWire returns true if the gdbserial package should log all the packets
 // exchanged with the stub.
 func GdbWire() bool {
 	return gdbWire
 }
 
+// GdbWireLogger returns a configured logger for the gdbserial wire protocol.
+func GdbWireLogger() *logrus.Entry {
+	return makeLogger(gdbWire, logrus.Fields{"layer": "gdbconn"})
+}
+
 // Debugger returns true if the debugger package should log.
 func Debugger() bool {
 	return debugger
 }
 
+// DebuggerLogger returns a logger for the debugger package.
+func DebuggerLogger() *logrus.Entry {
+	return makeLogger(debugger, logrus.Fields{"layer": "debugger"})
+}
+
 // LLDBServerOutput returns true if the output of the LLDB server should be
 // redirected to standard output instead of suppressed.
 func LLDBServerOutput() bool {
@@ -38,25 +72,61 @@ func DebugLineErrors() bool {
 	return debugLineErrors
 }
 
-// RPC returns true if rpc messages should be logged.
+// RPC returns true if RPC messages should be logged.
 func RPC() bool {
 	return rpc
 }
 
+// RPCLogger returns a logger for RPC messages.
+func RPCLogger() *logrus.Entry {
+	return makeLogger(rpc, logrus.Fields{"layer": "rpc"})
+}
+
 // FnCall returns true if the function call protocol should be logged.
 func FnCall() bool {
 	return fnCall
 }
 
+func FnCallLogger() *logrus.Entry {
+	return makeLogger(fnCall, logrus.Fields{"layer": "proc", "kind": "fncall"})
+}
+
 // Minidump returns true if the minidump loader should be logged.
 func Minidump() bool {
 	return minidump
 }
 
+func MinidumpLogger() *logrus.Entry {
+	return makeLogger(minidump, logrus.Fields{"layer": "core", "kind": "minidump"})
+}
+
+// WriteAPIListeningMessage writes the "API server listening" message in headless mode.
+func WriteAPIListeningMessage(addr string) {
+	if logOut != nil {
+		fmt.Fprintf(logOut, "API server listening at: %s\n", addr)
+	} else {
+		fmt.Printf("API server listening at: %s\n", addr)
+	}
+}
+
 var errLogstrWithoutLog = errors.New("--log-output specified without --log")
 
 // Setup sets debugger flags based on the contents of logstr.
-func Setup(logFlag bool, logstr string) error {
+// If logDest is not empty logs will be redirected to the file descriptor or
+// file path specified by logDest.
+func Setup(logFlag bool, logstr string, logDest string) error {
+	if logDest != "" {
+		n, err := strconv.Atoi(logDest)
+		if err == nil {
+			logOut = os.NewFile(uintptr(n), "delve-logs")
+		} else {
+			fh, err := os.Create(logDest)
+			if err != nil {
+				return fmt.Errorf("could not create log file: %v", err)
+			}
+			logOut = fh
+		}
+	}
 	log.SetFlags(log.Ldate | log.Ltime | log.Lshortfile)
 	if !logFlag {
 		log.SetOutput(ioutil.Discard)
@@ -89,3 +159,69 @@ func Setup(logFlag bool, logstr string) error {
 	}
 	return nil
 }
+
+// Close closes the logger output.
+func Close() {
+	if logOut != nil {
+		logOut.Close()
+	}
+}
+
+// textFormatter is a simplified version of logrus.TextFormatter that
+// doesn't make logs unreadable when they are output to a text file or to a
+// terminal that doesn't support colors.
+type textFormatter struct {
+}
+
+func (f *textFormatter) Format(entry *logrus.Entry) ([]byte, error) {
+	var b *bytes.Buffer
+	if entry.Buffer != nil {
+		b = entry.Buffer
+	} else {
+		b = &bytes.Buffer{}
+	}
+
+	keys := make([]string, 0, len(entry.Data))
+	for k := range entry.Data {
+		keys = append(keys, k)
+	}
+	sort.Strings(keys)
+
+	b.WriteString(entry.Time.Format(time.RFC3339))
+	b.WriteByte(' ')
+	b.WriteString(entry.Level.String())
+	b.WriteByte(' ')
+	for i, key := range keys {
+		b.WriteString(key)
+		b.WriteByte('=')
+		stringVal, ok := entry.Data[key].(string)
+		if !ok {
+			stringVal = fmt.Sprint(entry.Data[key])
+		}
+		if f.needsQuoting(stringVal) {
+			fmt.Fprintf(b, "%q", stringVal)
+		} else {
+			b.WriteString(stringVal)
+		}
+		if i != len(keys)-1 {
+			b.WriteByte(',')
+		} else {
+			b.WriteByte(' ')
+		}
+	}
+	b.WriteString(entry.Message)
+	b.WriteByte('\n')
+	return b.Bytes(), nil
+}
+
+func (f *textFormatter) needsQuoting(text string) bool {
+	for _, ch := range text {
+		if !((ch >= 'a' && ch <= 'z') ||
+			(ch >= 'A' && ch <= 'Z') ||
+			(ch >= '0' && ch <= '9') ||
+			ch == '-' || ch == '.' || ch == '_' || ch == '/' || ch == '@' || ch == '^' || ch == '+') {
+			return true
+		}
+	}
+	return false
+}

pkg/proc/core/windows_amd64_minidump.go

@@ -5,13 +5,12 @@ import (
 	"github.com/go-delve/delve/pkg/proc"
 	"github.com/go-delve/delve/pkg/proc/core/minidump"
 	"github.com/go-delve/delve/pkg/proc/winutil"
-	"github.com/sirupsen/logrus"
 )
 
 func readAMD64Minidump(minidumpPath, exePath string) (*Process, error) {
 	var logfn func(string, ...interface{})
 	if logflags.Minidump() {
-		logfn = logrus.WithFields(logrus.Fields{"layer": "core", "kind": "minidump"}).Infof
+		logfn = logflags.MinidumpLogger().Infof
 	}
 
 	mdmp, err := minidump.Open(minidumpPath, logfn)

pkg/proc/fncall.go

@@ -15,7 +15,6 @@ import (
 	"github.com/go-delve/delve/pkg/dwarf/op"
 	"github.com/go-delve/delve/pkg/dwarf/reader"
 	"github.com/go-delve/delve/pkg/logflags"
-	"github.com/sirupsen/logrus"
 	"golang.org/x/arch/x86/x86asm"
 )
 
@@ -153,10 +152,7 @@ func CallFunction(p Process, expr string, retLoadCfg *LoadConfig, checkEscape bo
 }
 
 func fncallLog(fmtstr string, args ...interface{}) {
-	if !logflags.FnCall() {
-		return
-	}
-	logrus.WithFields(logrus.Fields{"layer": "proc", "kind": "fncall"}).Infof(fmtstr, args...)
+	logflags.FnCallLogger().Infof(fmtstr, args...)
 }
 
 // writePointer writes val as an architecture pointer at addr in mem.

pkg/proc/gdbserial/gdbserver.go

@@ -68,7 +68,6 @@ import (
 	"errors"
 	"fmt"
 	"go/ast"
-	"io/ioutil"
 	"net"
 	"os"
 	"os/exec"
@@ -83,7 +82,6 @@ import (
 	"github.com/go-delve/delve/pkg/proc"
 	"github.com/go-delve/delve/pkg/proc/linutil"
 	isatty "github.com/mattn/go-isatty"
-	"github.com/sirupsen/logrus"
 )
 
 const (
@@ -170,11 +168,7 @@ 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.Logger.Level = logrus.DebugLevel
-	if !logflags.GdbWire() {
-		logger.Logger.Out = ioutil.Discard
-	}
+	logger := logflags.GdbWireLogger()
 	p := &Process{
 		conn: gdbConn{
 			maxTransmitAttempts: maxTransmitAttempts,

pkg/proc/gdbserial/rr_test.go

@@ -19,7 +19,7 @@ func TestMain(m *testing.M) {
 	var logConf string
 	flag.StringVar(&logConf, "log", "", "configures logging")
 	flag.Parse()
-	logflags.Setup(logConf != "", logConf)
+	logflags.Setup(logConf != "", logConf, "")
 	os.Exit(protest.RunTestsWithFixtures(m))
 }
 

pkg/proc/proc_test.go

@@ -47,7 +47,7 @@ func TestMain(m *testing.M) {
 		fmt.Fprintf(os.Stderr, "unknown build mode %q", buildMode)
 		os.Exit(1)
 	}
-	logflags.Setup(logConf != "", logConf)
+	logflags.Setup(logConf != "", logConf, "")
 	os.Exit(protest.RunTestsWithFixtures(m))
 }
 

service/debugger/debugger.go

@@ -5,7 +5,6 @@ import (
 	"errors"
 	"fmt"
 	"go/parser"
-	"io/ioutil"
 	"path/filepath"
 	"regexp"
 	"runtime"
@@ -74,11 +73,7 @@ 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.Logger.Level = logrus.DebugLevel
-	if !logflags.Debugger() {
-		logger.Logger.Out = ioutil.Discard
-	}
+	logger := logflags.DebuggerLogger()
 	d := &Debugger{
 		config:      config,
 		processArgs: processArgs,

service/rpccommon/server.go

@@ -6,7 +6,6 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"io/ioutil"
 	"net"
 	"net/rpc"
 	"net/rpc/jsonrpc"
@@ -68,17 +67,13 @@ type methodType struct {
 
 // NewServer creates a new RPCServer.
 func NewServer(config *service.Config) *ServerImpl {
-	logger := logrus.New().WithFields(logrus.Fields{"layer": "rpc"})
-	logger.Logger.Level = logrus.DebugLevel
-	if !logflags.RPC() {
-		logger.Logger.Out = ioutil.Discard
-	}
+	logger := logflags.RPCLogger()
 	if config.APIVersion < 2 {
 		logger.Info("Using API v1")
 	}
 	if config.Foreground {
 		// Print listener address
-		fmt.Printf("API server listening at: %s\n", config.Listener.Addr())
+		logflags.WriteAPIListeningMessage(config.Listener.Addr().String())
 	}
 	return &ServerImpl{
 		config:   config,

service/test/integration2_test.go

@@ -38,7 +38,7 @@ func TestMain(m *testing.M) {
 		fmt.Fprintf(os.Stderr, "unknown build mode %q", buildMode)
 		os.Exit(1)
 	}
-	logflags.Setup(logOutput != "", logOutput)
+	logflags.Setup(logOutput != "", logOutput, "")
 	os.Exit(protest.RunTestsWithFixtures(m))
 }