From 21ff0315d1e017607aff3e60eca4a7d2490b97b0 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Wed, 7 Oct 2020 12:39:25 +0200 Subject: [PATCH 1/3] grpcutil: avoid log spam related to TCP probes Prior to this patch, a monitoring probe that would just open and close the TCP port would cause log spam like the following: ``` grpc: Server.Serve failed to complete security handshake from "127.0.0.1:27972": EOF ``` This patch removes it. (This was tested by using netcat: `nc 127.0.0.1 26257` and then Ctrl+C to immediately close the connection.) The patch also cleans up the code around the filtering of grpc log messages. Release note: None Co-authored-by: Aaron Zinger --- pkg/util/grpcutil/grpc_util.go | 4 ++- pkg/util/grpcutil/log.go | 62 ++++++++++++++++++++++------------ pkg/util/grpcutil/log_test.go | 22 ++++-------- 3 files changed, 50 insertions(+), 38 deletions(-) diff --git a/pkg/util/grpcutil/grpc_util.go b/pkg/util/grpcutil/grpc_util.go index a20603b8c058..d5c820c4b56b 100644 --- a/pkg/util/grpcutil/grpc_util.go +++ b/pkg/util/grpcutil/grpc_util.go @@ -27,7 +27,9 @@ import ( // ErrCannotReuseClientConn is returned when a failed connection is // being reused. We require that new connections be created with // pkg/rpc.GRPCDial instead. -var ErrCannotReuseClientConn = errors.New("cannot reuse client connection") +var ErrCannotReuseClientConn = errors.New(errCannotReuseClientConnMsg) + +const errCannotReuseClientConnMsg = "cannot reuse client connection" type localRequestKey struct{} diff --git a/pkg/util/grpcutil/log.go b/pkg/util/grpcutil/log.go index 19fea0454d9d..858bed530c32 100644 --- a/pkg/util/grpcutil/log.go +++ b/pkg/util/grpcutil/log.go @@ -14,7 +14,6 @@ import ( "context" "math" "regexp" - "strings" "time" "github.com/cockroachdb/cockroach/pkg/util/log" @@ -72,7 +71,7 @@ func (severity *logger) Warning(args ...interface{}) { if log.Severity(*severity) > log.Severity_WARNING { return } - if shouldPrint(connectivitySpamRe, 30*time.Second, args...) { + if shouldPrintWarning(args...) { log.WarningfDepth(context.TODO(), 2, "", args...) } } @@ -144,25 +143,28 @@ func (severity *logger) V(i int) bool { } // https://github.com/grpc/grpc-go/blob/v1.29.1/clientconn.go#L1275 -var ( - transportFailedRe = regexp.MustCompile(`^` + regexp.QuoteMeta(`grpc: addrConn.createTransport failed to connect to`)) - connectionRefusedRe = regexp.MustCompile( - strings.Join([]string{ - // *nix - regexp.QuoteMeta("connection refused"), - // Windows - regexp.QuoteMeta("No connection could be made because the target machine actively refused it"), - // Host removed from the network and no longer resolvable: - // https://github.com/golang/go/blob/go1.8.3/src/net/net.go#L566 - regexp.QuoteMeta("no such host"), - }, "|"), - ) - clientConnReuseRe = regexp.MustCompile("cannot reuse client connection") - - connectivitySpamRe = regexp.MustCompile(transportFailedRe.String() + `.*` + - "(" + connectionRefusedRe.String() + "|" + clientConnReuseRe.String() + ")") +const ( + outgoingConnSpamReSrc = `^grpc: addrConn\.createTransport failed to connect to.*(` + + // *nix + `connection refused` + `|` + + // Windows + `No connection could be made because the target machine actively refused it` + `|` + + // Host removed from the network and no longer resolvable: + // https://github.com/golang/go/blob/go1.8.3/src/net/net.go#L566 + `no such host` + `|` + + // RPC dialer is currently failing but also retrying. + errCannotReuseClientConnMsg + + `)` + + // When a TCP probe simply opens and immediately closes the + // connection, gRPC is unhappy that the TLS handshake did not + // complete. We don't care. + incomingConnSpamReSrc = `^grpc: Server\.Serve failed to complete security handshake from "[^"]*": EOF` ) +var outgoingConnSpamRe = regexp.MustCompile(outgoingConnSpamReSrc) +var incomingConnSpamRe = regexp.MustCompile(incomingConnSpamReSrc) + var spamMu = struct { syncutil.Mutex strs map[string]time.Time @@ -170,14 +172,30 @@ var spamMu = struct { strs: make(map[string]time.Time), } -func shouldPrint(argsRe *regexp.Regexp, freq time.Duration, args ...interface{}) bool { +const minSpamLogInterval = 30 * time.Second + +// shouldPrintWarning returns true iff the gRPC warning message +// identified by args can be logged now. It returns false for outgoing +// connections errors that repeat within minSpamLogInterval of each +// other, and also for certain types of incoming connection errors. +func shouldPrintWarning(args ...interface{}) bool { for _, arg := range args { if argStr, ok := arg.(string); ok { - if argsRe.MatchString(argStr) { + // Incoming connection errors that match the criteria are blocked + // always. + if incomingConnSpamRe.MatchString(argStr) { + return false + } + + // Outgoing connection errors are only reported if performed too + // often. + // TODO(knz): Maybe the string map should be cleared periodically, + // to avoid unbounded memory growth. + if outgoingConnSpamRe.MatchString(argStr) { now := timeutil.Now() spamMu.Lock() t, ok := spamMu.strs[argStr] - doPrint := !(ok && now.Sub(t) < freq) + doPrint := !(ok && now.Sub(t) < minSpamLogInterval) if doPrint { spamMu.strs[argStr] = now } diff --git a/pkg/util/grpcutil/log_test.go b/pkg/util/grpcutil/log_test.go index 11b2188a58bd..6d2a8b244e25 100644 --- a/pkg/util/grpcutil/log_test.go +++ b/pkg/util/grpcutil/log_test.go @@ -11,7 +11,6 @@ package grpcutil import ( - "regexp" "testing" "time" @@ -20,38 +19,31 @@ import ( ) func TestShouldPrint(t *testing.T) { - const duration = 100 * time.Millisecond - - argRe, err := regexp.Compile("[a-z][0-9]") - if err != nil { - t.Fatal(err) - } - testutils.RunTrueAndFalse(t, "argsMatch", func(t *testing.T, argsMatch bool) { - msg := "baz" + msg := "blablabla" if argsMatch { - msg = "a1" + msg = "grpc: addrConn.createTransport failed to connect to 127.0.0.1:1234 (connection refused)" } args := []interface{}{msg} curriedShouldPrint := func() bool { - return shouldPrint(argRe, duration, args...) + return shouldPrintWarning(args...) } // First call should always print. if !curriedShouldPrint() { - t.Error("expected first call to print") + t.Error("1st call: should print expected true, got false") } // Should print if non-matching. alwaysPrint := !argsMatch if alwaysPrint { if !curriedShouldPrint() { - t.Error("expected second call to print") + t.Error("2nd call: should print expected true, got false") } } else { if curriedShouldPrint() { - t.Error("unexpected second call to print") + t.Error("2nd call: should print expected false, got true") } } @@ -63,7 +55,7 @@ func TestShouldPrint(t *testing.T) { spamMu.Unlock() } if !curriedShouldPrint() { - t.Error("expected third call to print") + t.Error("3rd call (after reset): should print expected true, got false") } }) } From 9b5e5a43d8e5cc4aac2d053cc808d072acef237a Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Wed, 7 Oct 2020 13:15:47 +0200 Subject: [PATCH 2/3] util/{log,netutil}: fix the log bridge Prior to this patch, log messages from the http package would look like this: ``` E201007 11:15:33.200128 878 httpLoggerserver.go:3088 http: ... ``` Notice how "httpLoggerserver.go" does not correspond to any valid file. With this patch: ``` E201007 11:15:33.200128 878 (gostd) net/http/server.go:3088 http: ... ``` Release note: None --- pkg/util/log/log_bridge.go | 12 ++++++++++-- pkg/util/netutil/net.go | 2 +- 2 files changed, 11 insertions(+), 3 deletions(-) diff --git a/pkg/util/log/log_bridge.go b/pkg/util/log/log_bridge.go index 09ae9c253cc1..fe6f299eaf54 100644 --- a/pkg/util/log/log_bridge.go +++ b/pkg/util/log/log_bridge.go @@ -16,13 +16,19 @@ import ( "fmt" stdLog "log" "strconv" + "strings" ) // NewStdLogger creates a *stdLog.Logger that forwards messages to the // CockroachDB logs with the specified severity. // -// The prefix appears at the beginning of each generated log line. +// The prefix should be the path of the package for which this logger +// is used. The prefix will be concatenated directly with the name +// of the file that triggered the logging. func NewStdLogger(severity Severity, prefix string) *stdLog.Logger { + if prefix != "" && !strings.HasSuffix(prefix, "/") { + prefix += "/" + } return stdLog.New(logBridge(severity), prefix, stdLog.Lshortfile) } @@ -67,7 +73,9 @@ func (lb logBridge) Write(b []byte) (n int, err error) { if parts := bytes.SplitN(b, []byte{':'}, 3); len(parts) != 3 || len(parts[0]) < 1 || len(parts[2]) < 1 { entry.Message = fmt.Sprintf("bad log format: %s", b) } else { - entry.File = string(parts[0]) + // We use a "(gostd)" prefix so that these log lines correctly point + // to the go standard library instead of our own source directory. + entry.File = "(gostd) " + string(parts[0]) entry.Message = string(parts[2][1 : len(parts[2])-1]) // skip leading space and trailing newline entry.Line, err = strconv.ParseInt(string(parts[1]), 10, 64) if err != nil { diff --git a/pkg/util/netutil/net.go b/pkg/util/netutil/net.go index 3a852fa064dd..aad4514fd561 100644 --- a/pkg/util/netutil/net.go +++ b/pkg/util/netutil/net.go @@ -54,7 +54,7 @@ func ListenAndServeGRPC( return ln, nil } -var httpLogger = log.NewStdLogger(log.Severity_ERROR, "httpLogger") +var httpLogger = log.NewStdLogger(log.Severity_ERROR, "net/http") // Server is a thin wrapper around http.Server. See MakeServer for more detail. type Server struct { From 0f0ad1dfcc575ed0dfd98793a55a10295ce3f620 Mon Sep 17 00:00:00 2001 From: Raphael 'kena' Poss Date: Wed, 7 Oct 2020 13:24:38 +0200 Subject: [PATCH 3/3] log: avoid log spam with monitoring probes on the HTTP port Prior to this patch, a monitoring probe that would just open and close the HTTP port would cause log spam like the following: ``` E201007 11:21:57.101735 882 (gostd) net/http/server.go:3088 http: TLS handshake error from 127.0.0.1:24059: EOF ``` This patch removes it. (This was tested by using netcat: `nc 127.0.0.1 8080` and then Ctrl+C to immediately close the connection.) Release note: None --- pkg/util/log/log_bridge.go | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/pkg/util/log/log_bridge.go b/pkg/util/log/log_bridge.go index fe6f299eaf54..c32be57c36c3 100644 --- a/pkg/util/log/log_bridge.go +++ b/pkg/util/log/log_bridge.go @@ -15,6 +15,7 @@ import ( "context" "fmt" stdLog "log" + "regexp" "strconv" "strings" ) @@ -58,9 +59,19 @@ func init() { copyStandardLogTo("INFO") } +var ignoredLogMessagesRe = regexp.MustCompile( + // The HTTP package complains when a client opens a TCP connection + // and immediately closes it. We don't care. + `^net/http.*:\d+\: http: TLS handshake error from .*: EOF\s*$`, +) + // Write parses the standard logging line and passes its components to the // logger for Severity(lb). func (lb logBridge) Write(b []byte) (n int, err error) { + if ignoredLogMessagesRe.Match(b) { + return len(b), nil + } + entry := MakeEntry(context.Background(), Severity(lb), &mainLog.logCounter, 0, /* depth */ // Note: because the caller is using the stdLog interface, they are