Skip to content

Commit

Permalink
feat: add support for structured logs (#1246)
Browse files Browse the repository at this point in the history
  • Loading branch information
enocom committed Jul 27, 2022
1 parent 2d05608 commit f11355f
Show file tree
Hide file tree
Showing 7 changed files with 231 additions and 76 deletions.
10 changes: 10 additions & 0 deletions cloudsql/cloudsql.go
Original file line number Diff line number Diff line change
Expand Up @@ -32,3 +32,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/cloudsql-proxy/v2/cloudsql"
"github.com/GoogleCloudPlatform/cloudsql-proxy/v2/internal/log"
"github.com/GoogleCloudPlatform/cloudsql-proxy/v2/internal/proxy"
"github.com/spf13/cobra"
"go.opencensus.io/trace"
Expand Down Expand Up @@ -64,8 +65,11 @@ func Execute() {
// Command represents an invocation of the Cloud SQL Auth Proxy.
type Command struct {
*cobra.Command
conf *proxy.Config
conf *proxy.Config
logger cloudsql.Logger
dialer cloudsql.Dialer

cleanup func() error
disableTraces bool
telemetryTracingSampleRate int
disableMetrics bool
Expand All @@ -76,25 +80,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 cloudsql.Logger) Option {
return func(c *Command) {
c.logger = l
}
}

// WithDialer configures the Command to use the provided dialer to connect to
// Cloud SQL instances.
func WithDialer(d cloudsql.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: "cloud_sql_proxy instance_connection_name...",
Version: versionString,
Expand All @@ -103,19 +107,38 @@ func NewCommand(opts ...Option) *Command {
connecting to Cloud SQL 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 @@ -124,6 +147,8 @@ 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 @@ -162,18 +187,15 @@ the maximum time has passed. Defaults to 0s.`)
cmd.PersistentFlags().BoolVar(&c.conf.PrivateIP, "private-ip", false,
"Connect to the private ip address for all instances")

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_connection_name (e.g., project:region:instance)")
}

conf.UserAgent = userAgent

userHasSet := func(f string) bool {
return cmd.PersistentFlags().Lookup(f).Changed
}
Expand Down Expand Up @@ -203,13 +225,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")
}

if userHasSet("sqladmin-api-endpoint") && conf.ApiEndpointUrl != "" {
Expand Down Expand Up @@ -333,6 +355,7 @@ func parseBoolOpt(q url.Values, name string) (*bool, 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 @@ -385,7 +408,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 @@ -423,7 +446,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 @@ -434,13 +457,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 @@ -451,11 +476,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 @@ -214,6 +214,13 @@ func TestNewCommandArguments(t *testing.T) {
}},
}),
},
{
desc: "enabling structured logging",
args: []string{"--structured-logs", "proj:region:inst"},
want: withDefaults(&proxy.Config{
StructuredLogs: true,
}),
},
{
desc: "using the max connections flag",
args: []string{"--max-connections", "1", "proj:region:inst"},
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/cloudsql-proxy/v2/cloudsql"
"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) cloudsql.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() (cloudsql.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 f11355f

Please sign in to comment.