From 14a1606a343e46f58fb8a86fb8b575f492e09020 Mon Sep 17 00:00:00 2001 From: Kevin Malachowski Date: Fri, 16 Jun 2017 15:34:34 -0700 Subject: [PATCH 1/2] Add a -verbose flag to allow users to turn off verbose log messages. Users of the library version of the proxy can swap in their own log implementations (or suppress logs in their own way). The binary distribution allows you to just turn off verbose flags. --- cmd/cloud_sql_proxy/cloud_sql_proxy.go | 22 +++++++++++------ cmd/cloud_sql_proxy/proxy.go | 22 ++++++++--------- logging/logging.go | 31 +++++++++++++++++++++++ proxy/certs/certs.go | 8 +++--- proxy/fuse/fuse.go | 34 +++++++++++++------------- proxy/proxy/client.go | 19 +++++++------- proxy/proxy/common.go | 15 ++++++------ 7 files changed, 95 insertions(+), 56 deletions(-) create mode 100644 logging/logging.go diff --git a/cmd/cloud_sql_proxy/cloud_sql_proxy.go b/cmd/cloud_sql_proxy/cloud_sql_proxy.go index e82d736dc..34266c6c6 100644 --- a/cmd/cloud_sql_proxy/cloud_sql_proxy.go +++ b/cmd/cloud_sql_proxy/cloud_sql_proxy.go @@ -35,6 +35,7 @@ import ( "sync" "time" + "github.com/GoogleCloudPlatform/cloudsql-proxy/logging" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/certs" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/fuse" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/proxy" @@ -51,6 +52,7 @@ var ( checkRegion = flag.Bool("check_region", false, `If specified, the 'region' portion of the connection string is required for UNIX socket-based connections.`) + verbose = flag.Bool("verbose", true, "If false, verbose output such as information about when connections are created/closed without error are suppressed") // Settings for how to choose which instance to connect to. dir = flag.String("dir", "", "Directory to use for placing UNIX sockets representing database instances") @@ -214,7 +216,7 @@ func authenticatedClient(ctx context.Context) (*http.Client, error) { if err != nil { return nil, fmt.Errorf("invalid json file %q: %v", f, err) } - log.Printf("using credential file for authentication; email=%s", cfg.Email) + logging.Infof("using credential file for authentication; email=%s", cfg.Email) return cfg.Client(ctx), nil } else if tok := *token; tok != "" { src := oauth2.StaticTokenSource(&oauth2.Token{AccessToken: tok}) @@ -259,7 +261,7 @@ func listInstances(ctx context.Context, cl *http.Client, projects []string) ([]s return nil }) if err != nil { - log.Printf("Error listing instances in %v: %v", proj, err) + logging.Errorf("Error listing instances in %v: %v", proj, err) } wg.Done() }() @@ -288,7 +290,7 @@ func gcloudProject() []string { // gcloud not installed; ignore the error return nil } - log.Printf("Error detecting gcloud project: %v", err) + logging.Errorf("Error detecting gcloud project: %v", err) return nil } @@ -299,12 +301,12 @@ func gcloudProject() []string { } if err := json.Unmarshal(buf.Bytes(), &data); err != nil { - log.Printf("Failed to unmarshal bytes from gcloud: %v", err) - log.Printf(" gcloud returned:\n%s", buf) + logging.Errorf("Failed to unmarshal bytes from gcloud: %v", err) + logging.Errorf(" gcloud returned:\n%s", buf) return nil } - log.Printf("Using gcloud's active project: %v", data.Core.Project) + logging.Infof("Using gcloud's active project: %v", data.Core.Project) return []string{data.Core.Project} } @@ -333,6 +335,10 @@ func main() { return } + if *verbose { + logging.Verbosef = func(string, ...interface{}) {} + } + instList := stringList(*instances) projList := stringList(*projects) // TODO: it'd be really great to consolidate flag verification in one place. @@ -386,7 +392,7 @@ func main() { return nil }) if err != nil { - log.Print(err) + logging.Errorf("Error on receiving new instances from metadata: %v", err) } time.Sleep(5 * time.Second) } @@ -400,7 +406,7 @@ func main() { connSrc = c } - log.Print("Ready for new connections") + logging.Infof("Ready for new connections") (&proxy.Client{ Port: port, diff --git a/cmd/cloud_sql_proxy/proxy.go b/cmd/cloud_sql_proxy/proxy.go index 8e0541283..94af0dfb5 100644 --- a/cmd/cloud_sql_proxy/proxy.go +++ b/cmd/cloud_sql_proxy/proxy.go @@ -20,7 +20,6 @@ import ( "bytes" "errors" "fmt" - "log" "net" "net/http" "os" @@ -28,6 +27,7 @@ import ( "runtime" "strings" + "github.com/GoogleCloudPlatform/cloudsql-proxy/logging" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/fuse" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/proxy" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/util" @@ -64,7 +64,7 @@ func watchInstancesLoop(dir string, dst chan<- proxy.Conn, updates <-chan string for instances := range updates { list, err := parseInstanceConfigs(dir, strings.Split(instances, ","), cl) if err != nil { - log.Print(err) + logging.Errorf("%v", err) } stillOpen := make(map[string]net.Listener) @@ -85,7 +85,7 @@ func watchInstancesLoop(dir string, dst chan<- proxy.Conn, updates <-chan string l, err := listenInstance(dst, cfg) if err != nil { - log.Printf("Couldn't open socket for %q: %v", instance, err) + logging.Errorf("Couldn't open socket for %q: %v", instance, err) continue } stillOpen[instance] = l @@ -95,7 +95,7 @@ func watchInstancesLoop(dir string, dst chan<- proxy.Conn, updates <-chan string // update. Clean up those instances' sockets by closing them; note that // this does not affect any existing connections instance. for instance, listener := range dynamicInstances { - log.Printf("Closing socket for instance %v", instance) + logging.Infof("Closing socket for instance %v", instance) listener.Close() } @@ -104,19 +104,19 @@ func watchInstancesLoop(dir string, dst chan<- proxy.Conn, updates <-chan string for _, v := range static { if err := v.Close(); err != nil { - log.Printf("Error closing %q: %v", v.Addr(), err) + logging.Errorf("Error closing %q: %v", v.Addr(), err) } } for _, v := range dynamicInstances { if err := v.Close(); err != nil { - log.Printf("Error closing %q: %v", v.Addr(), err) + logging.Errorf("Error closing %q: %v", v.Addr(), err) } } } func remove(path string) { if err := os.Remove(path); err != nil && !os.IsNotExist(err) { - log.Printf("Remove(%q) error: %v", path, err) + logging.Infof("Remove(%q) error: %v", path, err) } } @@ -133,7 +133,7 @@ func listenInstance(dst chan<- proxy.Conn, cfg instanceConfig) (net.Listener, er } if unix { if err := os.Chmod(cfg.Address, 0777|os.ModeSocket); err != nil { - log.Printf("couldn't update permissions for socket file %q: %v; other users may not be unable to connect", cfg.Address, err) + logging.Errorf("couldn't update permissions for socket file %q: %v; other users may not be unable to connect", cfg.Address, err) } } @@ -141,16 +141,16 @@ func listenInstance(dst chan<- proxy.Conn, cfg instanceConfig) (net.Listener, er for { c, err := l.Accept() if err != nil { - log.Printf("Error in accept for %q on %v: %v", cfg, cfg.Address, err) + logging.Errorf("Error in accept for %q on %v: %v", cfg, cfg.Address, err) l.Close() return } - log.Printf("New connection for %q", cfg.Instance) + logging.Verbosef("New connection for %q", cfg.Instance) dst <- proxy.Conn{cfg.Instance, c} } }() - log.Printf("Listening on %s for %s", cfg.Address, cfg.Instance) + logging.Infof("Listening on %s for %s", cfg.Address, cfg.Instance) return l, nil } diff --git a/logging/logging.go b/logging/logging.go new file mode 100644 index 000000000..21c17d69e --- /dev/null +++ b/logging/logging.go @@ -0,0 +1,31 @@ +// Copyright 2015 Google Inc. All Rights Reserved. +// +// 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 logging contains helpers to support log messages. If you are using +// the Cloud SQL Proxy as a Go library, you can override these variables to +// control where log messages end up. +package logging + +import "log" + +// Verbosef is called to write verbose logs, such as when a new connection is +// established correctly. +var Verbosef = log.Printf + +// Infof is called to write informational logs, such as when startup has +// completed. +var Infof = log.Printf + +// Errorf is called to write an error log, such as when a new connection fails. +var Errorf = log.Printf diff --git a/proxy/certs/certs.go b/proxy/certs/certs.go index 9bad1b163..d6228ae1d 100644 --- a/proxy/certs/certs.go +++ b/proxy/certs/certs.go @@ -23,12 +23,12 @@ import ( "encoding/pem" "errors" "fmt" - "log" "math" mrand "math/rand" "net/http" "time" + "github.com/GoogleCloudPlatform/cloudsql-proxy/logging" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/util" "google.golang.org/api/googleapi" sqladmin "google.golang.org/api/sqladmin/v1beta4" @@ -96,7 +96,7 @@ func backoffAPIRetry(desc, instance string, do func() error) error { // sleep = baseBackoff * backoffMult^(retries + randomFactor) exp := float64(i+1) + mrand.Float64() sleep := time.Duration(baseBackoff * math.Pow(backoffMult, exp)) - log.Printf("Error in %s %s: %v; retrying in %v", desc, instance, err, sleep) + logging.Errorf("Error in %s %s: %v; retrying in %v", desc, instance, err, sleep) time.Sleep(sleep) } return err @@ -172,8 +172,8 @@ func (s *RemoteCertSource) Remote(instance string) (cert *x509.Certificate, addr if s.checkRegion { return nil, "", "", err } - log.Print(err) - log.Print("WARNING: specifying the correct region in an instance string will become required in a future version!") + logging.Errorf("%v", err) + logging.Errorf("WARNING: specifying the correct region in an instance string will become required in a future version!") } if len(data.IpAddresses) == 0 || data.IpAddresses[0].IpAddress == "" { return nil, "", "", fmt.Errorf("no IP address found for %v", instance) diff --git a/proxy/fuse/fuse.go b/proxy/fuse/fuse.go index 557807442..b73d606a0 100644 --- a/proxy/fuse/fuse.go +++ b/proxy/fuse/fuse.go @@ -38,7 +38,6 @@ import ( "errors" "fmt" "io" - "log" "net" "os" "path/filepath" @@ -46,6 +45,7 @@ import ( "bazil.org/fuse" "bazil.org/fuse/fs" + "github.com/GoogleCloudPlatform/cloudsql-proxy/logging" "github.com/GoogleCloudPlatform/cloudsql-proxy/proxy/proxy" "golang.org/x/net/context" ) @@ -71,12 +71,12 @@ func NewConnSrc(mountdir, tmpdir string, connset *proxy.ConnSet) (<-chan proxy.C if err := fuse.Unmount(mountdir); err != nil { // The error is too verbose to be useful to print out } - log.Printf("Mounting %v...", mountdir) + logging.Verbosef("Mounting %v...", mountdir) c, err := fuse.Mount(mountdir, fuse.AllowOther()) if err != nil { return nil, nil, fmt.Errorf("cannot mount %q: %v", mountdir, err) } - log.Printf("Mounted %v", mountdir) + logging.Infof("Mounted %v", mountdir) if connset == nil { // Make a dummy one. @@ -95,23 +95,23 @@ func NewConnSrc(mountdir, tmpdir string, connset *proxy.ConnSet) (<-chan proxy.C server := fs.New(c, &fs.Config{ Debug: func(msg interface{}) { if false { - log.Print(msg) + logging.Verbosef("%s", msg) } }, }) go func() { if err := server.Serve(root); err != nil { - log.Printf("serve %q exited due to error: %v", mountdir, err) + logging.Errorf("serve %q exited due to error: %v", mountdir, err) } // The server exited but we don't know whether this is because of a // graceful reason (via root.Close) or via an external force unmounting. // Closing the root will ensure the 'dst' chan is closed correctly to // signify that no new connections are possible. if err := root.Close(); err != nil { - log.Printf("root.Close() error: %v", err) + logging.Errorf("root.Close() error: %v", err) } - log.Printf("FUSE exited") + logging.Infof("FUSE exited") }() return conns, root, nil @@ -168,17 +168,17 @@ func (r *fsRoot) newConn(instance string, c net.Conn) { if ch := r.dst; ch != nil { ch <- proxy.Conn{instance, c} } else { - log.Printf("Ignored new conn request to %q: system has been closed", instance) + logging.Errorf("Ignored new conn request to %q: system has been closed", instance) } r.RUnlock() } func (r *fsRoot) Forget() { - log.Printf("Forget called on %q", r.linkDir) + logging.Verbosef("Forget called on %q", r.linkDir) } func (r *fsRoot) Destroy() { - log.Printf("Destroy called on %q", r.linkDir) + logging.Verbosef("Destroy called on %q", r.linkDir) } func (r *fsRoot) Close() error { @@ -193,7 +193,7 @@ func (r *fsRoot) Close() error { } r.Unlock() - log.Printf("unmount %q", r.linkDir) + logging.Infof("unmount %q", r.linkDir) if err := fuse.Unmount(r.linkDir); err != nil { return err } @@ -210,7 +210,7 @@ func (r *fsRoot) Close() error { if errs.Len() == 0 { return nil } - log.Printf("Close %q: %v", r.linkDir, errs.String()) + logging.Errorf("Close %q: %v", r.linkDir, errs.String()) return errors.New(errs.String()) } @@ -247,11 +247,11 @@ func (r *fsRoot) Lookup(_ context.Context, req *fuse.LookupRequest, resp *fuse.L os.Remove(path) // Best effort; the following will fail if this does. sock, err := net.Listen("unix", path) if err != nil { - log.Printf("couldn't listen at %q: %v", path, err) + logging.Errorf("couldn't listen at %q: %v", path, err) return nil, fuse.EEXIST } if err := os.Chmod(path, 0777|os.ModeSocket); err != nil { - log.Printf("couldn't update permissions for socket file %q: %v; other users may be unable to connect", path, err) + logging.Errorf("couldn't update permissions for socket file %q: %v; other users may be unable to connect", path, err) } go r.listenerLifecycle(sock, instance, path) @@ -272,7 +272,7 @@ func (r *fsRoot) removeListener(instance, path string) { if ok && string(v) == path { delete(r.links, instance) } else { - log.Printf("Removing a listener for %q at %q which was already replaced", instance, path) + logging.Errorf("Removing a listener for %q at %q which was already replaced", instance, path) } r.sockLock.Unlock() } @@ -283,7 +283,7 @@ func (r *fsRoot) listenerLifecycle(l net.Listener, instance, path string) { for { c, err := l.Accept() if err != nil { - log.Printf("error in Accept for %q: %v", instance, err) + logging.Errorf("error in Accept for %q: %v", instance, err) break } r.newConn(instance, c) @@ -291,7 +291,7 @@ func (r *fsRoot) listenerLifecycle(l net.Listener, instance, path string) { r.removeListener(instance, path) l.Close() if err := os.Remove(path); err != nil { - log.Printf("couldn't remove %q: %v", path, err) + logging.Errorf("couldn't remove %q: %v", path, err) } } diff --git a/proxy/proxy/client.go b/proxy/proxy/client.go index b2b937e55..06b6f6086 100644 --- a/proxy/proxy/client.go +++ b/proxy/proxy/client.go @@ -19,10 +19,11 @@ import ( "crypto/x509" "errors" "fmt" - "log" "net" "sync" "time" + + "github.com/GoogleCloudPlatform/cloudsql-proxy/logging" ) const ( @@ -94,14 +95,14 @@ func (c *Client) Run(connSrc <-chan Conn) { } if err := c.Conns.Close(); err != nil { - log.Printf("closing client had error: %v", err) + logging.Errorf("closing client had error: %v", err) } } func (c *Client) handleConn(conn Conn) { server, err := c.Dial(conn.Instance) if err != nil { - log.Printf("couldn't connect to %q: %v", conn.Instance, err) + logging.Errorf("couldn't connect to %q: %v", conn.Instance, err) conn.Conn.Close() return } @@ -115,7 +116,7 @@ func (c *Client) handleConn(conn Conn) { c.Conns.Add(conn.Instance, conn.Conn) copyThenClose(server, conn.Conn, conn.Instance, "local connection on "+conn.Conn.LocalAddr().String()) if err := c.Conns.Remove(conn.Instance, conn.Conn); err != nil { - log.Print(err) + logging.Errorf("%s", err) } } @@ -132,7 +133,7 @@ func (c *Client) refreshCfg(instance string) (addr string, cfg *tls.Config, err } if old := c.cfgCache[instance]; time.Since(old.lastRefreshed) < throttle { - log.Printf("Throttling refreshCfg(%s): it was only called %v ago", instance, time.Since(old.lastRefreshed)) + logging.Errorf("Throttling refreshCfg(%s): it was only called %v ago", instance, time.Since(old.lastRefreshed)) // Refresh was called too recently, just reuse the result. return old.addr, old.cfg, old.err } @@ -217,12 +218,12 @@ func (c *Client) tryConnect(addr string, cfg *tls.Config) (net.Conn, error) { if s, ok := conn.(setKeepAliver); ok { if err := s.SetKeepAlive(true); err != nil { - log.Printf("Couldn't set KeepAlive to true: %v", err) + logging.Verbosef("Couldn't set KeepAlive to true: %v", err) } else if err := s.SetKeepAlivePeriod(keepAlivePeriod); err != nil { - log.Printf("Couldn't set KeepAlivePeriod to %v", keepAlivePeriod) + logging.Verbosef("Couldn't set KeepAlivePeriod to %v", keepAlivePeriod) } } else { - log.Printf("KeepAlive not supported: long-running tcp connections may be killed by the OS.") + logging.Verbosef("KeepAlive not supported: long-running tcp connections may be killed by the OS.") } ret := tls.Client(conn, cfg) @@ -243,7 +244,7 @@ func NewConnSrc(instance string, l net.Listener) <-chan Conn { for { c, err := l.Accept() if err != nil { - log.Printf("listener (%#v) had error: %v", l, err) + logging.Errorf("listener (%#v) had error: %v", l, err) l.Close() close(ch) return diff --git a/proxy/proxy/common.go b/proxy/proxy/common.go index 73ebe425b..bb5cc9cbc 100644 --- a/proxy/proxy/common.go +++ b/proxy/proxy/common.go @@ -20,9 +20,10 @@ import ( "errors" "fmt" "io" - "log" "net" "sync" + + "github.com/GoogleCloudPlatform/cloudsql-proxy/logging" ) type dbgConn struct { @@ -31,19 +32,19 @@ type dbgConn struct { func (d dbgConn) Write(b []byte) (int, error) { x, y := d.Conn.Write(b) - log.Printf("write(%q) => (%v, %v)", b, x, y) + logging.Verbosef("write(%q) => (%v, %v)", b, x, y) return x, y } func (d dbgConn) Read(b []byte) (int, error) { x, y := d.Conn.Read(b) - log.Printf("read: (%v, %v) => %q", x, y, b[:x]) + logging.Verbosef("read: (%v, %v) => %q", x, y, b[:x]) return x, y } func (d dbgConn) Close() error { err := d.Conn.Close() - log.Printf("close: %v", err) + logging.Verbosef("close: %v", err) return err } @@ -75,7 +76,7 @@ func copyError(readDesc, writeDesc string, readErr bool, err error) { } else { desc = "Writing data to " + writeDesc } - log.Printf("%v had error: %v", desc, err) + logging.Errorf("%v had error: %v", desc, err) } func copyThenClose(remote, local io.ReadWriteCloser, remoteDesc, localDesc string) { @@ -86,7 +87,7 @@ func copyThenClose(remote, local io.ReadWriteCloser, remoteDesc, localDesc strin select { case firstErr <- err: if readErr && err == io.EOF { - log.Printf("Client closed %v", localDesc) + logging.Verbosef("Client closed %v", localDesc) } else { copyError(localDesc, remoteDesc, readErr, err) } @@ -100,7 +101,7 @@ func copyThenClose(remote, local io.ReadWriteCloser, remoteDesc, localDesc strin select { case firstErr <- err: if readErr && err == io.EOF { - log.Printf("Instance %v closed connection", remoteDesc) + logging.Verbosef("Instance %v closed connection", remoteDesc) } else { copyError(remoteDesc, localDesc, readErr, err) } From 8bc072073f48ba31edd2e5c3496d1c078a80b4f3 Mon Sep 17 00:00:00 2001 From: Kevin Malachowski Date: Fri, 16 Jun 2017 15:44:27 -0700 Subject: [PATCH 2/2] move the verbose flag to be next to the quiet flag --- cmd/cloud_sql_proxy/cloud_sql_proxy.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/cmd/cloud_sql_proxy/cloud_sql_proxy.go b/cmd/cloud_sql_proxy/cloud_sql_proxy.go index 48fbcf7f6..9ca206aaf 100644 --- a/cmd/cloud_sql_proxy/cloud_sql_proxy.go +++ b/cmd/cloud_sql_proxy/cloud_sql_proxy.go @@ -49,11 +49,11 @@ import ( var ( version = flag.Bool("version", false, "Print the version of the proxy and exit") + verbose = flag.Bool("verbose", true, "If false, verbose output such as information about when connections are created/closed without error are suppressed") quiet = flag.Bool("quiet", false, "Disable log messages") checkRegion = flag.Bool("check_region", false, `If specified, the 'region' portion of the connection string is required for UNIX socket-based connections.`) - verbose = flag.Bool("verbose", true, "If false, verbose output such as information about when connections are created/closed without error are suppressed") // Settings for how to choose which instance to connect to. dir = flag.String("dir", "", "Directory to use for placing UNIX sockets representing database instances")