Skip to content

Commit

Permalink
feat: add support for structured logs
Browse files Browse the repository at this point in the history
  • Loading branch information
enocom committed Jul 12, 2022
1 parent 2c9864d commit 188f268
Show file tree
Hide file tree
Showing 8 changed files with 220 additions and 69 deletions.
10 changes: 10 additions & 0 deletions alloydb/alloydb.go
Original file line number Diff line number Diff line change
Expand Up @@ -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{})
}
97 changes: 61 additions & 36 deletions cmd/root.go
Original file line number Diff line number Diff line change
Expand Up @@ -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"
Expand Down Expand Up @@ -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
Expand All @@ -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,
Expand All @@ -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", "",
Expand All @@ -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.`)
Expand Down Expand Up @@ -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
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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()

Expand Down Expand Up @@ -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)
}
}
}()
Expand Down Expand Up @@ -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
Expand All @@ -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)
}
}()

Expand All @@ -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
}
7 changes: 7 additions & 0 deletions cmd/root_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down
1 change: 1 addition & 0 deletions go.mod
Original file line number Diff line number Diff line change
Expand Up @@ -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 // indirect
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-20220708085239-5a0f0661e09d
Expand Down
6 changes: 6 additions & 0 deletions go.sum
Original file line number Diff line number Diff line change
Expand Up @@ -148,6 +148,7 @@ 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/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=
Expand Down Expand Up @@ -1183,19 +1184,24 @@ 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/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=
Expand Down
98 changes: 98 additions & 0 deletions internal/log/log.go
Original file line number Diff line number Diff line change
@@ -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
}
Loading

0 comments on commit 188f268

Please sign in to comment.