agent, server: add option to log source location (spiffe#4246)

Add an option to both agent and server to enable logging of the source
location (file name, line number, function name).

This new option is available both via the configuration file and as a
command-line flag.

Signed-off-by: Carlo Teubner <carlo@cteubner.net>

cmd/spire-agent/cli/run/run.go

@@ -74,6 +74,7 @@ type agentConfig struct {
 	LogFile                       string    `hcl:"log_file"`
 	LogFormat                     string    `hcl:"log_format"`
 	LogLevel                      string    `hcl:"log_level"`
+	LogSourceLocation             bool      `hcl:"log_source_location"`
 	SDS                           sdsConfig `hcl:"sds"`
 	ServerAddress                 string    `hcl:"server_address"`
 	ServerPort                    int       `hcl:"server_port"`
@@ -309,6 +310,7 @@ func parseFlags(name string, args []string, output io.Writer) (*agentConfig, err
 	flags.StringVar(&c.LogFile, "logFile", "", "File to write logs to")
 	flags.StringVar(&c.LogFormat, "logFormat", "", "'text' or 'json'")
 	flags.StringVar(&c.LogLevel, "logLevel", "", "'debug', 'info', 'warn', or 'error'")
+	flags.BoolVar(&c.LogSourceLocation, "logSourceLocation", false, "Include source file, line number and function name in log lines")
 	flags.StringVar(&c.ServerAddress, "serverAddress", "", "IP address or DNS name of the SPIRE server")
 	flags.IntVar(&c.ServerPort, "serverPort", 0, "Port number of the SPIRE server")
 	flags.StringVar(&c.TrustDomain, "trustDomain", "", "The trust domain that this agent belongs to")
@@ -459,6 +461,9 @@ func NewAgentConfig(c *Config, logOptions []log.Option, allowUnknownConfig bool)
 		log.WithLevel(c.Agent.LogLevel),
 		log.WithFormat(c.Agent.LogFormat),
 	)
+	if c.Agent.LogSourceLocation {
+		logOptions = append(logOptions, log.WithSourceLocation())
+	}
 	var reopenableFile *log.ReopenableFile
 	if c.Agent.LogFile != "" {
 		reopenableFile, err := log.NewReopenableFile(c.Agent.LogFile)

cmd/spire-agent/cli/run/run_test.go

@@ -430,6 +430,46 @@ func TestMergeInput(t *testing.T) {
 				require.Equal(t, "DEBUG", c.Agent.LogLevel)
 			},
 		},
+		{
+			msg:       "log_source_location should default to false if not set",
+			fileInput: func(c *Config) {},
+			cliInput:  func(c *agentConfig) {},
+			test: func(t *testing.T, c *Config) {
+				require.False(t, c.Agent.LogSourceLocation)
+			},
+		},
+		{
+			msg: "log_source_location should be configurable by file",
+			fileInput: func(c *Config) {
+				c.Agent.LogSourceLocation = true
+			},
+			cliInput: func(c *agentConfig) {},
+			test: func(t *testing.T, c *Config) {
+				require.True(t, c.Agent.LogSourceLocation)
+			},
+		},
+		{
+			msg:       "log_source_location should be configurable by CLI flag",
+			fileInput: func(c *Config) {},
+			cliInput: func(c *agentConfig) {
+				c.LogSourceLocation = true
+			},
+			test: func(t *testing.T, c *Config) {
+				require.True(t, c.Agent.LogSourceLocation)
+			},
+		},
+		{
+			msg: "log_source_location specified by CLI flag should take precedence over file",
+			fileInput: func(c *Config) {
+				c.Agent.LogSourceLocation = false
+			},
+			cliInput: func(c *agentConfig) {
+				c.LogSourceLocation = true
+			},
+			test: func(t *testing.T, c *Config) {
+				require.True(t, c.Agent.LogSourceLocation)
+			},
+		},
 		{
 			msg:       "server_address should not have a default value",
 			fileInput: func(c *Config) {},

cmd/spire-server/cli/run/run.go

@@ -79,6 +79,7 @@ type serverConfig struct {
 	LogFile            string             `hcl:"log_file"`
 	LogLevel           string             `hcl:"log_level"`
 	LogFormat          string             `hcl:"log_format"`
+	LogSourceLocation  bool               `hcl:"log_source_location"`
 	RateLimit          rateLimitConfig    `hcl:"ratelimit"`
 	SocketPath         string             `hcl:"socket_path"`
 	TrustDomain        string             `hcl:"trust_domain"`
@@ -303,6 +304,7 @@ func parseFlags(name string, args []string, output io.Writer) (*serverConfig, er
 	flags.StringVar(&c.DataDir, "dataDir", "", "Directory to store runtime data to")
 	flags.StringVar(&c.LogFile, "logFile", "", "File to write logs to")
 	flags.StringVar(&c.LogFormat, "logFormat", "", "'text' or 'json'")
+	flags.BoolVar(&c.LogSourceLocation, "logSourceLocation", false, "Include source file, line number and function name in log lines")
 	flags.StringVar(&c.LogLevel, "logLevel", "", "'debug', 'info', 'warn', or 'error'")
 	flags.StringVar(&c.TrustDomain, "trustDomain", "", "The trust domain that this server belongs to")
 	flags.BoolVar(&c.ExpandEnv, "expandEnv", false, "Expand environment variables in SPIRE config file")
@@ -349,6 +351,9 @@ func NewServerConfig(c *Config, logOptions []log.Option, allowUnknownConfig bool
 		log.WithLevel(c.Server.LogLevel),
 		log.WithFormat(c.Server.LogFormat),
 	)
+	if c.Server.LogSourceLocation {
+		logOptions = append(logOptions, log.WithSourceLocation())
+	}
 	var reopenableFile *log.ReopenableFile
 	if c.Server.LogFile != "" {
 		reopenableFile, err := log.NewReopenableFile(c.Server.LogFile)

cmd/spire-server/cli/run/run_test.go

@@ -351,6 +351,42 @@ func TestMergeInput(t *testing.T) {
 				require.Equal(t, "DEBUG", c.Server.LogLevel)
 			},
 		},
+		{
+			msg:       "log_source_location should default to false if not set",
+			fileInput: func(c *Config) {},
+			cliFlags:  []string{},
+			test: func(t *testing.T, c *Config) {
+				require.False(t, c.Server.LogSourceLocation)
+			},
+		},
+		{
+			msg: "log_source_location should be configurable by file",
+			fileInput: func(c *Config) {
+				c.Server.LogSourceLocation = true
+			},
+			cliFlags: []string{},
+			test: func(t *testing.T, c *Config) {
+				require.True(t, c.Server.LogSourceLocation)
+			},
+		},
+		{
+			msg:       "log_source_location should be configurable by CLI flag",
+			fileInput: func(c *Config) {},
+			cliFlags:  []string{"-logSourceLocation"},
+			test: func(t *testing.T, c *Config) {
+				require.True(t, c.Server.LogSourceLocation)
+			},
+		},
+		{
+			msg: "log_source_location specified by CLI flag should take precedence over file",
+			fileInput: func(c *Config) {
+				c.Server.LogSourceLocation = false
+			},
+			cliFlags: []string{"-logSourceLocation"},
+			test: func(t *testing.T, c *Config) {
+				require.True(t, c.Server.LogSourceLocation)
+			},
+		},
 		{
 			msg: "default_x509_svid_ttl should be configurable by file",
 			fileInput: func(c *Config) {

conf/agent/agent_full.conf

@@ -34,6 +34,10 @@ agent {
     # log_format: Format of logs, <text|json>. Default: text.
     # log_format = "text"
 
+    # log_source_location: whether to include source file, line number, and
+    # function name in each log line. Default: false.
+    # log_source_location = true
+
     # log_level: Sets the logging level <DEBUG|INFO|WARN|ERROR>. Default: INFO
     log_level = "DEBUG"
 

conf/server/server_full.conf

@@ -123,6 +123,10 @@ server {
     # Format of logs, <text|json>. Default: text.
     # log_format = "text"
 
+    # log_source_location: whether to include source file, line number, and
+    # function name in each log line. Default: false.
+    # log_source_location = true
+
     # ratelimit: Holds rate limiting configurations.
     # ratelimit = {
     #     # Controls whether or not node attestation is rate limited to one

doc/spire_agent.md

@@ -54,6 +54,7 @@ This may be useful for templating configuration files, for example across differ
 | `log_file`                        | File to write logs to                                                                                                          |                                  |
 | `log_level`                       | Sets the logging level <DEBUG|INFO|WARN|ERROR>                                                            | INFO                             |
 | `log_format`                      | Format of logs, <text|json>                                                                                         | Text                             |
+| `log_source_location`             | If true, logs include source file, line number, and method name fields (adds a bit of runtime cost)                            | false                                          |
 | `profiling_enabled`               | If true, enables a [net/http/pprof](https://pkg.go.dev/net/http/pprof) endpoint                                                | false                            |
 | `profiling_freq`                  | Frequency of dumping profiling data to disk. Only enabled when `profiling_enabled` is `true` and `profiling_freq` > 0.         |                                  |
 | `profiling_names`                 | List of profile names that will be dumped to disk on each profiling tick, see [Profiling Names](#profiling-names)              |                                  |

doc/spire_server.md

@@ -68,6 +68,7 @@ This may be useful for templating configuration files, for example across differ
 | `log_file`              | File to write logs to                                                                                                                                                                                                                               |                                                                |
 | `log_level`             | Sets the logging level <DEBUG|INFO|WARN|ERROR>                                                                                                                                                                                 | INFO                                                           |
 | `log_format`            | Format of logs, <text|json>                                                                                                                                                                                                              | text                                                           |
+| `log_source_location`   | If true, logs include source file, line number, and method name fields (adds a bit of runtime cost)                                                                                                                                                 | false                                                          |
 | `profiling_enabled`     | If true, enables a [net/http/pprof](https://pkg.go.dev/net/http/pprof) endpoint                                                                                                                                                                     | false                                                          |
 | `profiling_freq`        | Frequency of dumping profiling data to disk. Only enabled when `profiling_enabled` is `true` and `profiling_freq` > 0.                                                                                                                              |                                                                |
 | `profiling_names`       | List of profile names that will be dumped to disk on each profiling tick, see [Profiling Names](#profiling-names)                                                                                                                                   |                                                                |

pkg/common/log/log_test.go

@@ -1,6 +1,7 @@
 package log
 
 import (
+	"bytes"
 	"encoding/json"
 	"fmt"
 	"io"
@@ -63,6 +64,49 @@ func TestLocalTimeHook(t *testing.T) {
 	}
 }
 
+func TestTextFormat(t *testing.T) {
+	logger, err := NewLogger()
+	require.NoError(t, err)
+	var buffer bytes.Buffer
+	logger.SetOutput(&buffer)
+	require.NoError(t, err)
+
+	logger.Info("Testing")
+
+	require.Regexp(t, `^time=.+ level=info msg=Testing\n$`, buffer.String())
+}
+
+func TestSourceLocation(t *testing.T) {
+	logger, err := NewLogger(WithSourceLocation())
+	require.NoError(t, err)
+	var buffer bytes.Buffer
+	logger.SetOutput(&buffer)
+	require.NoError(t, err)
+
+	logger.Info("Hello world")
+
+	require.Regexp(t,
+		`^time=.+ level=info msg="Hello world" file="log_test\.go:\d+" func=github\.com/spiffe/spire/pkg/common/log\.TestSourceLocation\n$`,
+		buffer.String())
+}
+
+// Test HCLogAdapter separately to verify that the correct frame in the call
+// stack gets reported.
+func TestSourceLocationHCLog(t *testing.T) {
+	logger, err := NewLogger(WithSourceLocation())
+	require.NoError(t, err)
+	var buffer bytes.Buffer
+	logger.SetOutput(&buffer)
+	require.NoError(t, err)
+
+	hcLogger := NewHCLogAdapter(*logger, "test-logger")
+	hcLogger.Info("Hello world")
+
+	require.Regexp(t,
+		`^time=.+ level=info msg="Hello world" file="log_test\.go:\d+" func=github\.com/spiffe/spire/pkg/common/log\.TestSourceLocationHCLog\n$`,
+		buffer.String())
+}
+
 // Basic smoketest: set up a logger, make sure options work
 func TestLogger(t *testing.T) {
 	testHook := test.Hook{}

pkg/common/log/options.go

@@ -3,6 +3,9 @@ package log
 import (
 	"fmt"
 	"os"
+	"path/filepath"
+	"regexp"
+	"runtime"
 	"strings"
 
 	"github.com/sirupsen/logrus"
@@ -86,3 +89,62 @@ func WithLevel(logLevel string) Option {
 		return nil
 	}
 }
+
+func WithSourceLocation() Option {
+	return func(logger *Logger) error {
+		// logrus provides a built-in feature that is very close to what we
+		// want (logger.SetReportCaller). Unfortunately, it always reports the
+		// immediate caller; but in certain cases, we want to skip over some
+		// more frames; in particular, this applies to the HCLogAdapter.
+		logger.AddHook(sourceLocHook{})
+		return nil
+	}
+}
+
+type sourceLocHook struct{}
+
+func (sourceLocHook) Levels() []logrus.Level {
+	return logrus.AllLevels
+}
+
+func (sourceLocHook) Fire(e *logrus.Entry) error {
+	frame := getCaller()
+	if frame != nil {
+		e.Data[logrus.FieldKeyFile] = fmt.Sprintf("%s:%d", filepath.Base(frame.File), frame.Line)
+		e.Data[logrus.FieldKeyFunc] = frame.Function
+	}
+	return nil
+}
+
+func getCaller() *runtime.Frame {
+	pcs := make([]uintptr, 10)
+	skip := 3 // skip 'runtime.Callers', this function, and its caller
+	numPcs := runtime.Callers(skip, pcs)
+	if numPcs == 0 {
+		return nil
+	}
+	frames := runtime.CallersFrames(pcs[:numPcs])
+
+	for {
+		f, more := frames.Next()
+
+		// skip over frames within the logging infrastructure
+		if !isLoggingFunc(f.Function) {
+			return &f
+		}
+
+		if !more {
+			break
+		}
+	}
+
+	return nil
+}
+
+var loggingFuncRegexp = regexp.MustCompile(
+	`^github\.com/(?:sirupsen/logrus|spiffe/spire/pkg/common/log)[./]`)
+
+func isLoggingFunc(funcName string) bool {
+	return loggingFuncRegexp.MatchString(funcName) &&
+		!strings.HasPrefix(funcName, "github.com/spiffe/spire/pkg/common/log.Test")
+}