feat: add support for structured logs

alloydb/alloydb.go

@@ -29,3 +29,13 @@ type Dialer interface {
 
 	io.Closer
 }
+
+// Logger is the interface used throughout the project for logging.
+type Logger interface {
+	// Debugf is for reporting additional information about internal operations.
+	Debugf(format string, args ...interface{})
+	// Infof is for reporting informational messages.
+	Infof(format string, args ...interface{})
+	// Errorf is for reporting errors.
+	Errorf(format string, args ...interface{})
+}

cmd/root.go

@@ -32,6 +32,7 @@ import (
 	"contrib.go.opencensus.io/exporter/prometheus"
 	"contrib.go.opencensus.io/exporter/stackdriver"
 	"github.com/GoogleCloudPlatform/alloydb-auth-proxy/alloydb"
+	"github.com/GoogleCloudPlatform/alloydb-auth-proxy/internal/log"
 	"github.com/GoogleCloudPlatform/alloydb-auth-proxy/internal/proxy"
 	"github.com/spf13/cobra"
 	"go.opencensus.io/trace"
@@ -76,8 +77,11 @@ func Execute() {
 // Command represents an invocation of the AlloyDB Auth Proxy.
 type Command struct {
 	*cobra.Command
-	conf *proxy.Config
+	conf   *proxy.Config
+	logger alloydb.Logger
+	dialer alloydb.Dialer
 
+	cleanup                    func() error
 	disableTraces              bool
 	telemetryTracingSampleRate int
 	disableMetrics             bool
@@ -88,25 +92,25 @@ type Command struct {
 }
 
 // Option is a function that configures a Command.
-type Option func(*proxy.Config)
+type Option func(*Command)
+
+// WithLogger overrides the default logger.
+func WithLogger(l alloydb.Logger) Option {
+	return func(c *Command) {
+		c.logger = l
+	}
+}
 
 // WithDialer configures the Command to use the provided dialer to connect to
 // AlloyDB instances.
 func WithDialer(d alloydb.Dialer) Option {
-	return func(c *proxy.Config) {
-		c.Dialer = d
+	return func(c *Command) {
+		c.dialer = d
 	}
 }
 
 // NewCommand returns a Command object representing an invocation of the proxy.
 func NewCommand(opts ...Option) *Command {
-	c := &Command{
-		conf: &proxy.Config{},
-	}
-	for _, o := range opts {
-		o(c.conf)
-	}
-
 	cmd := &cobra.Command{
 		Use:     "alloydb-auth-proxy instance_uri...",
 		Version: versionString,
@@ -115,19 +119,38 @@ func NewCommand(opts ...Option) *Command {
 connecting to AlloyDB instances. It listens on a local port and forwards
 connections to your instance's IP address, providing a secure connection
 without having to manage any client SSL certificates.`,
-		Args: func(cmd *cobra.Command, args []string) error {
-			err := parseConfig(cmd, c.conf, args)
-			if err != nil {
-				return err
-			}
-			// The arguments are parsed. Usage is no longer needed.
-			cmd.SilenceUsage = true
-			return nil
-		},
-		RunE: func(*cobra.Command, []string) error {
-			return runSignalWrapper(c)
+	}
+
+	logger := log.NewStdLogger(os.Stdout, os.Stderr)
+	c := &Command{
+		Command: cmd,
+		logger:  logger,
+		cleanup: func() error { return nil },
+		conf: &proxy.Config{
+			UserAgent: userAgent,
 		},
 	}
+	for _, o := range opts {
+		o(c)
+	}
+
+	cmd.Args = func(cmd *cobra.Command, args []string) error {
+		// Handle logger separately from config
+		if c.conf.StructuredLogs {
+			c.logger, c.cleanup = log.NewStructuredLogger()
+		}
+		err := parseConfig(c, c.conf, args)
+		if err != nil {
+			return err
+		}
+		// The arguments are parsed. Usage is no longer needed.
+		cmd.SilenceUsage = true
+		// Errors will be handled by logging from here on.
+		cmd.SilenceErrors = true
+		return nil
+	}
+
+	cmd.RunE = func(*cobra.Command, []string) error { return runSignalWrapper(c) }
 
 	// Global-only flags
 	cmd.PersistentFlags().StringVarP(&c.conf.Token, "token", "t", "",
@@ -136,6 +159,8 @@ without having to manage any client SSL certificates.`,
 		"Path to a service account key to use for authentication.")
 	cmd.PersistentFlags().BoolVarP(&c.conf.GcloudAuth, "gcloud-auth", "g", false,
 		"Use gcloud's user configuration to retrieve a token for authentication.")
+	cmd.PersistentFlags().BoolVarP(&c.conf.StructuredLogs, "structured-logs", "l", false,
+		"Enable structured logs using the LogEntry format")
 	cmd.PersistentFlags().Uint64Var(&c.conf.MaxConnections, "max-connections", 0,
 		`Limits the number of connections by refusing any additional connections.
 When this flag is not set, there is no limit.`)
@@ -168,18 +193,15 @@ the maximum time has passed. Defaults to 0s.`)
 	cmd.PersistentFlags().StringVarP(&c.conf.UnixSocket, "unix-socket", "u", "",
 		`Enables Unix sockets for all listeners using the provided directory.`)
 
-	c.Command = cmd
 	return c
 }
 
-func parseConfig(cmd *cobra.Command, conf *proxy.Config, args []string) error {
+func parseConfig(cmd *Command, conf *proxy.Config, args []string) error {
 	// If no instance connection names were provided, error.
 	if len(args) == 0 {
 		return newBadCommandError("missing instance uri (e.g., /projects/$PROJECTS/locations/$LOCTION/clusters/$CLUSTER/instances/$INSTANCES)")
 	}
 
-	conf.UserAgent = userAgent
-
 	userHasSet := func(f string) bool {
 		return cmd.PersistentFlags().Lookup(f).Changed
 	}
@@ -210,13 +232,13 @@ func parseConfig(cmd *cobra.Command, conf *proxy.Config, args []string) error {
 	}
 
 	if !userHasSet("telemetry-project") && userHasSet("telemetry-prefix") {
-		cmd.Println("Ignoring telementry-prefix as telemetry-project was not set")
+		cmd.logger.Infof("Ignoring telementry-prefix as telemetry-project was not set")
 	}
 	if !userHasSet("telemetry-project") && userHasSet("disable-metrics") {
-		cmd.Println("Ignoring disable-metrics as telemetry-project was not set")
+		cmd.logger.Infof("Ignoring disable-metrics as telemetry-project was not set")
 	}
 	if !userHasSet("telemetry-project") && userHasSet("disable-traces") {
-		cmd.Println("Ignoring disable-traces as telemetry-project was not set")
+		cmd.logger.Infof("Ignoring disable-traces as telemetry-project was not set")
 	}
 
 	var ics []proxy.InstanceConnConfig
@@ -288,6 +310,7 @@ func parseConfig(cmd *cobra.Command, conf *proxy.Config, args []string) error {
 
 // runSignalWrapper watches for SIGTERM and SIGINT and interupts execution if necessary.
 func runSignalWrapper(cmd *Command) error {
+	defer cmd.cleanup()
 	ctx, cancel := context.WithCancel(cmd.Context())
 	defer cancel()
 
@@ -340,7 +363,7 @@ func runSignalWrapper(cmd *Command) error {
 				// Give the HTTP server a second to shutdown cleanly.
 				ctx2, _ := context.WithTimeout(context.Background(), time.Second)
 				if err := server.Shutdown(ctx2); err != nil {
-					cmd.Printf("failed to shutdown Prometheus HTTP server: %v\n", err)
+					cmd.logger.Errorf("failed to shutdown Prometheus HTTP server: %v\n", err)
 				}
 			}
 		}()
@@ -378,7 +401,7 @@ func runSignalWrapper(cmd *Command) error {
 	startCh := make(chan *proxy.Client)
 	go func() {
 		defer close(startCh)
-		p, err := proxy.NewClient(ctx, cmd.Command, cmd.conf)
+		p, err := proxy.NewClient(ctx, cmd.dialer, cmd.logger, cmd.conf)
 		if err != nil {
 			shutdownCh <- fmt.Errorf("unable to start: %v", err)
 			return
@@ -389,13 +412,15 @@ func runSignalWrapper(cmd *Command) error {
 	var p *proxy.Client
 	select {
 	case err := <-shutdownCh:
+		cmd.logger.Errorf("The proxy has encountered a terminal error: %v", err)
 		return err
 	case p = <-startCh:
 	}
-	cmd.Println("The proxy has started successfully and is ready for new connections!")
+	cmd.logger.Infof("The proxy has started successfully and is ready for new connections!")
+	defer p.Close()
 	defer func() {
 		if cErr := p.Close(); cErr != nil {
-			cmd.PrintErrf("The proxy failed to close cleanly: %v\n", cErr)
+			cmd.logger.Errorf("error during shutdown: %v", cErr)
 		}
 	}()
 
@@ -406,11 +431,11 @@ func runSignalWrapper(cmd *Command) error {
 	err := <-shutdownCh
 	switch {
 	case errors.Is(err, errSigInt):
-		cmd.PrintErrln("SIGINT signal received. Shutting down...")
+		cmd.logger.Errorf("SIGINT signal received. Shutting down...")
 	case errors.Is(err, errSigTerm):
-		cmd.PrintErrln("SIGTERM signal received. Shutting down...")
+		cmd.logger.Errorf("SIGTERM signal received. Shutting down...")
 	default:
-		cmd.PrintErrf("The proxy has encountered a terminal error: %v\n", err)
+		cmd.logger.Errorf("The proxy has encountered a terminal error: %v", err)
 	}
 	return err
 }

cmd/root_test.go

@@ -177,6 +177,13 @@ func TestNewCommandArguments(t *testing.T) {
 				WaitOnClose: 10 * time.Second,
 			}),
 		},
+		{
+			desc: "enabling structured logging",
+			args: []string{"--structured-logs", "/projects/proj/locations/region/clusters/clust/instances/inst"},
+			want: withDefaults(&proxy.Config{
+				StructuredLogs: true,
+			}),
+		},
 	}
 
 	for _, tc := range tcs {

go.mod

@@ -10,6 +10,7 @@ require (
 	github.com/lib/pq v1.10.5 // indirect
 	github.com/spf13/cobra v1.5.0
 	go.opencensus.io v0.23.0
+	go.uber.org/zap v1.21.0
 	golang.org/x/net v0.0.0-20220517181318-183a9ca12b87 // indirect
 	golang.org/x/oauth2 v0.0.0-20220622183110-fd043fe589d2
 	golang.org/x/sys v0.0.0-20220712014510-0a85c31ab51e

go.sum

@@ -148,6 +148,8 @@ github.com/aws/aws-sdk-go v1.43.11/go.mod h1:y4AeaBuwd2Lk+GepC1E9v0qOiTws0MIWAX4
 github.com/aws/aws-sdk-go v1.43.31 h1:yJZIr8nMV1hXjAvvOLUFqZRJcHV7udPQBfhJqawDzI0=
 github.com/aws/aws-sdk-go v1.43.31/go.mod h1:y4AeaBuwd2Lk+GepC1E9v0qOiTws0MIWAX4oIKwKHZo=
 github.com/benbjohnson/clock v1.0.3/go.mod h1:bGMdMPoPVvcYyt1gHDf4J2KE153Yf9BuiUKYMaxlTDM=
+github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
+github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
 github.com/beorn7/perks v0.0.0-20160804104726-4c0e84591b9a/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
 github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
 github.com/beorn7/perks v1.0.0/go.mod h1:KWe93zE9D1o94FZ5RNwFwVgaQK1VOXiVxmqh+CedLV8=
@@ -1183,19 +1185,25 @@ go.uber.org/atomic v1.4.0/go.mod h1:gD2HeocX3+yG+ygLZcrzQJaqmWj9AIm7n08wl/qW/PE=
 go.uber.org/atomic v1.5.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
 go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
 go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
+go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE=
 go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
 go.uber.org/automaxprocs v1.5.1/go.mod h1:BF4eumQw0P9GtnuxxovUd06vwm1o18oMzFtK66vU6XU=
 go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
+go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
+go.uber.org/goleak v1.1.12 h1:gZAh5/EyT/HQwlpkCy6wTpqfH9H8Lz8zbm3dZh+OyzA=
 go.uber.org/goleak v1.1.12/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
 go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
 go.uber.org/multierr v1.3.0/go.mod h1:VgVr7evmIr6uPjLBxg28wmKNXyqE9akIJ5XnfpiKl+4=
 go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU=
+go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
 go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
 go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
 go.uber.org/zap v1.9.1/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
 go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
 go.uber.org/zap v1.13.0/go.mod h1:zwrFLgMcdUuIBviXEYEH1YKNaOBnKXsx2IPda5bBwHM=
 go.uber.org/zap v1.17.0/go.mod h1:MXVU+bhUf/A7Xi2HNOnopQOrmycQ5Ih87HtOu4q5SSo=
+go.uber.org/zap v1.21.0 h1:WefMeulhovoZ2sYXz7st6K0sLj7bBhpiFaud4r4zST8=
+go.uber.org/zap v1.21.0/go.mod h1:wjWOCqI0f2ZZrJF/UufIOkiC8ii6tm1iqIsLo76RfJw=
 golang.org/x/crypto v0.0.0-20171113213409-9f005a07e0d3/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
 golang.org/x/crypto v0.0.0-20181009213950-7c1a557ab941/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=

internal/log/log.go

@@ -0,0 +1,98 @@
+// Copyright 2022 Google LLC
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//      http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package log
+
+import (
+	"io"
+	llog "log"
+	"os"
+
+	"github.com/GoogleCloudPlatform/alloydb-auth-proxy/alloydb"
+	"go.uber.org/zap"
+	"go.uber.org/zap/zapcore"
+)
+
+// StdLogger is the standard logger that distinguishes between info and error
+// logs.
+type StdLogger struct {
+	infoLog *llog.Logger
+	errLog  *llog.Logger
+}
+
+// NewStdLogger create a Logger that uses out and err for informational and
+// error messages.
+func NewStdLogger(out, err io.Writer) alloydb.Logger {
+	return &StdLogger{
+		infoLog: llog.New(out, "", llog.LstdFlags),
+		errLog:  llog.New(err, "", llog.LstdFlags),
+	}
+}
+
+func (l *StdLogger) Infof(format string, v ...interface{}) {
+	l.infoLog.Printf(format, v...)
+}
+
+func (l *StdLogger) Errorf(format string, v ...interface{}) {
+	l.errLog.Printf(format, v...)
+}
+
+func (l *StdLogger) Debugf(format string, v ...interface{}) {
+	l.infoLog.Printf(format, v...)
+}
+
+// StructuredLogger writes log messages in JSON.
+type StructuredLogger struct {
+	logger *zap.SugaredLogger
+}
+
+func (l *StructuredLogger) Infof(format string, v ...interface{}) {
+	l.logger.Infof(format, v...)
+}
+
+func (l *StructuredLogger) Errorf(format string, v ...interface{}) {
+	l.logger.Errorf(format, v...)
+}
+
+func (l *StructuredLogger) Debugf(format string, v ...interface{}) {
+	l.logger.Infof(format, v...)
+}
+
+// NewStructuredLogger creates a Logger that logs messages using JSON.
+func NewStructuredLogger() (alloydb.Logger, func() error) {
+	// Configure structured logs to adhere to LogEntry format
+	// https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry
+	c := zap.NewProductionEncoderConfig()
+	c.LevelKey = "severity"
+	c.MessageKey = "message"
+	c.TimeKey = "timestamp"
+	c.EncodeLevel = zapcore.CapitalLevelEncoder
+	c.EncodeTime = zapcore.ISO8601TimeEncoder
+
+	enc := zapcore.NewJSONEncoder(c)
+	core := zapcore.NewTee(
+		zapcore.NewCore(enc, zapcore.Lock(os.Stdout), zap.LevelEnablerFunc(func(l zapcore.Level) bool {
+			// Anything below error, goes to the info log.
+			return l < zapcore.ErrorLevel
+		})),
+		zapcore.NewCore(enc, zapcore.Lock(os.Stderr), zap.LevelEnablerFunc(func(l zapcore.Level) bool {
+			// Anything at error or higher goes to the error log.
+			return l >= zapcore.ErrorLevel
+		})),
+	)
+	l := &StructuredLogger{
+		logger: zap.New(core).Sugar(),
+	}
+	return l, l.logger.Sync
+}