Skip to content

Commit 5a1e8e8

Browse files
authored
feat: add support for structured logs (GoogleCloudPlatform#66)
This is a port of GoogleCloudPlatform/cloud-sql-proxy#1246
1 parent 13c0c93 commit 5a1e8e8

File tree

9 files changed

+225
-71
lines changed

9 files changed

+225
-71
lines changed

alloydb/alloydb.go

+10
Original file line numberDiff line numberDiff line change
@@ -29,3 +29,13 @@ type Dialer interface {
2929

3030
io.Closer
3131
}
32+
33+
// Logger is the interface used throughout the project for logging.
34+
type Logger interface {
35+
// Debugf is for reporting additional information about internal operations.
36+
Debugf(format string, args ...interface{})
37+
// Infof is for reporting informational messages.
38+
Infof(format string, args ...interface{})
39+
// Errorf is for reporting errors.
40+
Errorf(format string, args ...interface{})
41+
}

cmd/root.go

+61-36
Original file line numberDiff line numberDiff line change
@@ -32,6 +32,7 @@ import (
3232
"contrib.go.opencensus.io/exporter/prometheus"
3333
"contrib.go.opencensus.io/exporter/stackdriver"
3434
"github.com/GoogleCloudPlatform/alloydb-auth-proxy/alloydb"
35+
"github.com/GoogleCloudPlatform/alloydb-auth-proxy/internal/log"
3536
"github.com/GoogleCloudPlatform/alloydb-auth-proxy/internal/proxy"
3637
"github.com/spf13/cobra"
3738
"go.opencensus.io/trace"
@@ -76,8 +77,11 @@ func Execute() {
7677
// Command represents an invocation of the AlloyDB Auth Proxy.
7778
type Command struct {
7879
*cobra.Command
79-
conf *proxy.Config
80+
conf *proxy.Config
81+
logger alloydb.Logger
82+
dialer alloydb.Dialer
8083

84+
cleanup func() error
8185
disableTraces bool
8286
telemetryTracingSampleRate int
8387
disableMetrics bool
@@ -88,25 +92,25 @@ type Command struct {
8892
}
8993

9094
// Option is a function that configures a Command.
91-
type Option func(*proxy.Config)
95+
type Option func(*Command)
96+
97+
// WithLogger overrides the default logger.
98+
func WithLogger(l alloydb.Logger) Option {
99+
return func(c *Command) {
100+
c.logger = l
101+
}
102+
}
92103

93104
// WithDialer configures the Command to use the provided dialer to connect to
94105
// AlloyDB instances.
95106
func WithDialer(d alloydb.Dialer) Option {
96-
return func(c *proxy.Config) {
97-
c.Dialer = d
107+
return func(c *Command) {
108+
c.dialer = d
98109
}
99110
}
100111

101112
// NewCommand returns a Command object representing an invocation of the proxy.
102113
func NewCommand(opts ...Option) *Command {
103-
c := &Command{
104-
conf: &proxy.Config{},
105-
}
106-
for _, o := range opts {
107-
o(c.conf)
108-
}
109-
110114
cmd := &cobra.Command{
111115
Use: "alloydb-auth-proxy instance_uri...",
112116
Version: versionString,
@@ -115,19 +119,38 @@ func NewCommand(opts ...Option) *Command {
115119
connecting to AlloyDB instances. It listens on a local port and forwards
116120
connections to your instance's IP address, providing a secure connection
117121
without having to manage any client SSL certificates.`,
118-
Args: func(cmd *cobra.Command, args []string) error {
119-
err := parseConfig(cmd, c.conf, args)
120-
if err != nil {
121-
return err
122-
}
123-
// The arguments are parsed. Usage is no longer needed.
124-
cmd.SilenceUsage = true
125-
return nil
126-
},
127-
RunE: func(*cobra.Command, []string) error {
128-
return runSignalWrapper(c)
122+
}
123+
124+
logger := log.NewStdLogger(os.Stdout, os.Stderr)
125+
c := &Command{
126+
Command: cmd,
127+
logger: logger,
128+
cleanup: func() error { return nil },
129+
conf: &proxy.Config{
130+
UserAgent: userAgent,
129131
},
130132
}
133+
for _, o := range opts {
134+
o(c)
135+
}
136+
137+
cmd.Args = func(cmd *cobra.Command, args []string) error {
138+
// Handle logger separately from config
139+
if c.conf.StructuredLogs {
140+
c.logger, c.cleanup = log.NewStructuredLogger()
141+
}
142+
err := parseConfig(c, c.conf, args)
143+
if err != nil {
144+
return err
145+
}
146+
// The arguments are parsed. Usage is no longer needed.
147+
cmd.SilenceUsage = true
148+
// Errors will be handled by logging from here on.
149+
cmd.SilenceErrors = true
150+
return nil
151+
}
152+
153+
cmd.RunE = func(*cobra.Command, []string) error { return runSignalWrapper(c) }
131154

132155
// Global-only flags
133156
cmd.PersistentFlags().StringVarP(&c.conf.Token, "token", "t", "",
@@ -136,6 +159,8 @@ without having to manage any client SSL certificates.`,
136159
"Path to a service account key to use for authentication.")
137160
cmd.PersistentFlags().BoolVarP(&c.conf.GcloudAuth, "gcloud-auth", "g", false,
138161
"Use gcloud's user configuration to retrieve a token for authentication.")
162+
cmd.PersistentFlags().BoolVarP(&c.conf.StructuredLogs, "structured-logs", "l", false,
163+
"Enable structured logs using the LogEntry format")
139164
cmd.PersistentFlags().Uint64Var(&c.conf.MaxConnections, "max-connections", 0,
140165
`Limits the number of connections by refusing any additional connections.
141166
When this flag is not set, there is no limit.`)
@@ -168,18 +193,15 @@ the maximum time has passed. Defaults to 0s.`)
168193
cmd.PersistentFlags().StringVarP(&c.conf.UnixSocket, "unix-socket", "u", "",
169194
`Enables Unix sockets for all listeners using the provided directory.`)
170195

171-
c.Command = cmd
172196
return c
173197
}
174198

175-
func parseConfig(cmd *cobra.Command, conf *proxy.Config, args []string) error {
199+
func parseConfig(cmd *Command, conf *proxy.Config, args []string) error {
176200
// If no instance connection names were provided, error.
177201
if len(args) == 0 {
178202
return newBadCommandError("missing instance uri (e.g., /projects/$PROJECTS/locations/$LOCTION/clusters/$CLUSTER/instances/$INSTANCES)")
179203
}
180204

181-
conf.UserAgent = userAgent
182-
183205
userHasSet := func(f string) bool {
184206
return cmd.PersistentFlags().Lookup(f).Changed
185207
}
@@ -210,13 +232,13 @@ func parseConfig(cmd *cobra.Command, conf *proxy.Config, args []string) error {
210232
}
211233

212234
if !userHasSet("telemetry-project") && userHasSet("telemetry-prefix") {
213-
cmd.Println("Ignoring telementry-prefix as telemetry-project was not set")
235+
cmd.logger.Infof("Ignoring telementry-prefix as telemetry-project was not set")
214236
}
215237
if !userHasSet("telemetry-project") && userHasSet("disable-metrics") {
216-
cmd.Println("Ignoring disable-metrics as telemetry-project was not set")
238+
cmd.logger.Infof("Ignoring disable-metrics as telemetry-project was not set")
217239
}
218240
if !userHasSet("telemetry-project") && userHasSet("disable-traces") {
219-
cmd.Println("Ignoring disable-traces as telemetry-project was not set")
241+
cmd.logger.Infof("Ignoring disable-traces as telemetry-project was not set")
220242
}
221243

222244
var ics []proxy.InstanceConnConfig
@@ -288,6 +310,7 @@ func parseConfig(cmd *cobra.Command, conf *proxy.Config, args []string) error {
288310

289311
// runSignalWrapper watches for SIGTERM and SIGINT and interupts execution if necessary.
290312
func runSignalWrapper(cmd *Command) error {
313+
defer cmd.cleanup()
291314
ctx, cancel := context.WithCancel(cmd.Context())
292315
defer cancel()
293316

@@ -340,7 +363,7 @@ func runSignalWrapper(cmd *Command) error {
340363
// Give the HTTP server a second to shutdown cleanly.
341364
ctx2, _ := context.WithTimeout(context.Background(), time.Second)
342365
if err := server.Shutdown(ctx2); err != nil {
343-
cmd.Printf("failed to shutdown Prometheus HTTP server: %v\n", err)
366+
cmd.logger.Errorf("failed to shutdown Prometheus HTTP server: %v\n", err)
344367
}
345368
}
346369
}()
@@ -378,7 +401,7 @@ func runSignalWrapper(cmd *Command) error {
378401
startCh := make(chan *proxy.Client)
379402
go func() {
380403
defer close(startCh)
381-
p, err := proxy.NewClient(ctx, cmd.Command, cmd.conf)
404+
p, err := proxy.NewClient(ctx, cmd.dialer, cmd.logger, cmd.conf)
382405
if err != nil {
383406
shutdownCh <- fmt.Errorf("unable to start: %v", err)
384407
return
@@ -389,13 +412,15 @@ func runSignalWrapper(cmd *Command) error {
389412
var p *proxy.Client
390413
select {
391414
case err := <-shutdownCh:
415+
cmd.logger.Errorf("The proxy has encountered a terminal error: %v", err)
392416
return err
393417
case p = <-startCh:
394418
}
395-
cmd.Println("The proxy has started successfully and is ready for new connections!")
419+
cmd.logger.Infof("The proxy has started successfully and is ready for new connections!")
420+
defer p.Close()
396421
defer func() {
397422
if cErr := p.Close(); cErr != nil {
398-
cmd.PrintErrf("The proxy failed to close cleanly: %v\n", cErr)
423+
cmd.logger.Errorf("error during shutdown: %v", cErr)
399424
}
400425
}()
401426

@@ -406,11 +431,11 @@ func runSignalWrapper(cmd *Command) error {
406431
err := <-shutdownCh
407432
switch {
408433
case errors.Is(err, errSigInt):
409-
cmd.PrintErrln("SIGINT signal received. Shutting down...")
434+
cmd.logger.Errorf("SIGINT signal received. Shutting down...")
410435
case errors.Is(err, errSigTerm):
411-
cmd.PrintErrln("SIGTERM signal received. Shutting down...")
436+
cmd.logger.Errorf("SIGTERM signal received. Shutting down...")
412437
default:
413-
cmd.PrintErrf("The proxy has encountered a terminal error: %v\n", err)
438+
cmd.logger.Errorf("The proxy has encountered a terminal error: %v", err)
414439
}
415440
return err
416441
}

cmd/root_test.go

+7
Original file line numberDiff line numberDiff line change
@@ -177,6 +177,13 @@ func TestNewCommandArguments(t *testing.T) {
177177
WaitOnClose: 10 * time.Second,
178178
}),
179179
},
180+
{
181+
desc: "enabling structured logging",
182+
args: []string{"--structured-logs", "/projects/proj/locations/region/clusters/clust/instances/inst"},
183+
want: withDefaults(&proxy.Config{
184+
StructuredLogs: true,
185+
}),
186+
},
180187
}
181188

182189
for _, tc := range tcs {

go.mod

+1
Original file line numberDiff line numberDiff line change
@@ -10,6 +10,7 @@ require (
1010
github.com/lib/pq v1.10.5 // indirect
1111
github.com/spf13/cobra v1.5.0
1212
go.opencensus.io v0.23.0
13+
go.uber.org/zap v1.21.0
1314
golang.org/x/net v0.0.0-20220517181318-183a9ca12b87 // indirect
1415
golang.org/x/oauth2 v0.0.0-20220622183110-fd043fe589d2
1516
golang.org/x/sys v0.0.0-20220712014510-0a85c31ab51e

go.sum

+8
Original file line numberDiff line numberDiff line change
@@ -148,6 +148,8 @@ github.com/aws/aws-sdk-go v1.43.11/go.mod h1:y4AeaBuwd2Lk+GepC1E9v0qOiTws0MIWAX4
148148
github.com/aws/aws-sdk-go v1.43.31 h1:yJZIr8nMV1hXjAvvOLUFqZRJcHV7udPQBfhJqawDzI0=
149149
github.com/aws/aws-sdk-go v1.43.31/go.mod h1:y4AeaBuwd2Lk+GepC1E9v0qOiTws0MIWAX4oIKwKHZo=
150150
github.com/benbjohnson/clock v1.0.3/go.mod h1:bGMdMPoPVvcYyt1gHDf4J2KE153Yf9BuiUKYMaxlTDM=
151+
github.com/benbjohnson/clock v1.1.0 h1:Q92kusRqC1XV2MjkWETPvjJVqKetz1OzxZB7mHJLju8=
152+
github.com/benbjohnson/clock v1.1.0/go.mod h1:J11/hYXuz8f4ySSvYwY0FKfm+ezbsZBKZxNJlLklBHA=
151153
github.com/beorn7/perks v0.0.0-20160804104726-4c0e84591b9a/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
152154
github.com/beorn7/perks v0.0.0-20180321164747-3a771d992973/go.mod h1:Dwedo/Wpr24TaqPxmxbtue+5NUziq4I4S80YR8gNf3Q=
153155
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=
11831185
go.uber.org/atomic v1.5.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
11841186
go.uber.org/atomic v1.6.0/go.mod h1:sABNBOSYdrvTF6hTgEIbc7YasKWGhgEQZyfxyTvoXHQ=
11851187
go.uber.org/atomic v1.7.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
1188+
go.uber.org/atomic v1.9.0 h1:ECmE8Bn/WFTYwEW/bpKD3M8VtR/zQVbavAoalC1PYyE=
11861189
go.uber.org/atomic v1.9.0/go.mod h1:fEN4uk6kAWBTFdckzkM89CLk9XfWZrxpCo0nPH17wJc=
11871190
go.uber.org/automaxprocs v1.5.1/go.mod h1:BF4eumQw0P9GtnuxxovUd06vwm1o18oMzFtK66vU6XU=
11881191
go.uber.org/goleak v1.1.10/go.mod h1:8a7PlsEVH3e/a/GLqe5IIrQx6GzcnRmZEufDUTk4A7A=
1192+
go.uber.org/goleak v1.1.11/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
1193+
go.uber.org/goleak v1.1.12 h1:gZAh5/EyT/HQwlpkCy6wTpqfH9H8Lz8zbm3dZh+OyzA=
11891194
go.uber.org/goleak v1.1.12/go.mod h1:cwTWslyiVhfpKIDGSZEM2HlOvcqm+tG4zioyIeLoqMQ=
11901195
go.uber.org/multierr v1.1.0/go.mod h1:wR5kodmAFQ0UK8QlbwjlSNy0Z68gJhDJUG5sjR94q/0=
11911196
go.uber.org/multierr v1.3.0/go.mod h1:VgVr7evmIr6uPjLBxg28wmKNXyqE9akIJ5XnfpiKl+4=
11921197
go.uber.org/multierr v1.5.0/go.mod h1:FeouvMocqHpRaaGuG9EjoKcStLC43Zu/fmqdUMPcKYU=
1198+
go.uber.org/multierr v1.6.0 h1:y6IPFStTAIT5Ytl7/XYmHvzXQ7S3g/IeZW9hyZ5thw4=
11931199
go.uber.org/multierr v1.6.0/go.mod h1:cdWPpRnG4AhwMwsgIHip0KRBQjJy5kYEpYjJxpXp9iU=
11941200
go.uber.org/tools v0.0.0-20190618225709-2cfd321de3ee/go.mod h1:vJERXedbb3MVM5f9Ejo0C68/HhF8uaILCdgjnY+goOA=
11951201
go.uber.org/zap v1.9.1/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
11961202
go.uber.org/zap v1.10.0/go.mod h1:vwi/ZaCAaUcBkycHslxD9B2zi4UTXhF60s6SWpuDF0Q=
11971203
go.uber.org/zap v1.13.0/go.mod h1:zwrFLgMcdUuIBviXEYEH1YKNaOBnKXsx2IPda5bBwHM=
11981204
go.uber.org/zap v1.17.0/go.mod h1:MXVU+bhUf/A7Xi2HNOnopQOrmycQ5Ih87HtOu4q5SSo=
1205+
go.uber.org/zap v1.21.0 h1:WefMeulhovoZ2sYXz7st6K0sLj7bBhpiFaud4r4zST8=
1206+
go.uber.org/zap v1.21.0/go.mod h1:wjWOCqI0f2ZZrJF/UufIOkiC8ii6tm1iqIsLo76RfJw=
11991207
golang.org/x/crypto v0.0.0-20171113213409-9f005a07e0d3/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
12001208
golang.org/x/crypto v0.0.0-20180904163835-0709b304e793/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=
12011209
golang.org/x/crypto v0.0.0-20181009213950-7c1a557ab941/go.mod h1:6SG95UA2DQfeDnfUPMdvaQW0Q7yPrPDi9nlGo2tz2b4=

internal/log/log.go

+98
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,98 @@
1+
// Copyright 2022 Google LLC
2+
//
3+
// Licensed under the Apache License, Version 2.0 (the "License");
4+
// you may not use this file except in compliance with the License.
5+
// You may obtain a copy of the License at
6+
//
7+
// http://www.apache.org/licenses/LICENSE-2.0
8+
//
9+
// Unless required by applicable law or agreed to in writing, software
10+
// distributed under the License is distributed on an "AS IS" BASIS,
11+
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
12+
// See the License for the specific language governing permissions and
13+
// limitations under the License.
14+
15+
package log
16+
17+
import (
18+
"io"
19+
llog "log"
20+
"os"
21+
22+
"github.com/GoogleCloudPlatform/alloydb-auth-proxy/alloydb"
23+
"go.uber.org/zap"
24+
"go.uber.org/zap/zapcore"
25+
)
26+
27+
// StdLogger is the standard logger that distinguishes between info and error
28+
// logs.
29+
type StdLogger struct {
30+
infoLog *llog.Logger
31+
errLog *llog.Logger
32+
}
33+
34+
// NewStdLogger create a Logger that uses out and err for informational and
35+
// error messages.
36+
func NewStdLogger(out, err io.Writer) alloydb.Logger {
37+
return &StdLogger{
38+
infoLog: llog.New(out, "", llog.LstdFlags),
39+
errLog: llog.New(err, "", llog.LstdFlags),
40+
}
41+
}
42+
43+
func (l *StdLogger) Infof(format string, v ...interface{}) {
44+
l.infoLog.Printf(format, v...)
45+
}
46+
47+
func (l *StdLogger) Errorf(format string, v ...interface{}) {
48+
l.errLog.Printf(format, v...)
49+
}
50+
51+
func (l *StdLogger) Debugf(format string, v ...interface{}) {
52+
l.infoLog.Printf(format, v...)
53+
}
54+
55+
// StructuredLogger writes log messages in JSON.
56+
type StructuredLogger struct {
57+
logger *zap.SugaredLogger
58+
}
59+
60+
func (l *StructuredLogger) Infof(format string, v ...interface{}) {
61+
l.logger.Infof(format, v...)
62+
}
63+
64+
func (l *StructuredLogger) Errorf(format string, v ...interface{}) {
65+
l.logger.Errorf(format, v...)
66+
}
67+
68+
func (l *StructuredLogger) Debugf(format string, v ...interface{}) {
69+
l.logger.Infof(format, v...)
70+
}
71+
72+
// NewStructuredLogger creates a Logger that logs messages using JSON.
73+
func NewStructuredLogger() (alloydb.Logger, func() error) {
74+
// Configure structured logs to adhere to LogEntry format
75+
// https://cloud.google.com/logging/docs/reference/v2/rest/v2/LogEntry
76+
c := zap.NewProductionEncoderConfig()
77+
c.LevelKey = "severity"
78+
c.MessageKey = "message"
79+
c.TimeKey = "timestamp"
80+
c.EncodeLevel = zapcore.CapitalLevelEncoder
81+
c.EncodeTime = zapcore.ISO8601TimeEncoder
82+
83+
enc := zapcore.NewJSONEncoder(c)
84+
core := zapcore.NewTee(
85+
zapcore.NewCore(enc, zapcore.Lock(os.Stdout), zap.LevelEnablerFunc(func(l zapcore.Level) bool {
86+
// Anything below error, goes to the info log.
87+
return l < zapcore.ErrorLevel
88+
})),
89+
zapcore.NewCore(enc, zapcore.Lock(os.Stderr), zap.LevelEnablerFunc(func(l zapcore.Level) bool {
90+
// Anything at error or higher goes to the error log.
91+
return l >= zapcore.ErrorLevel
92+
})),
93+
)
94+
l := &StructuredLogger{
95+
logger: zap.New(core).Sugar(),
96+
}
97+
return l, l.logger.Sync
98+
}

0 commit comments

Comments
 (0)