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") } }) } diff --git a/pkg/util/log/log_bridge.go b/pkg/util/log/log_bridge.go index 09ae9c253cc1..c32be57c36c3 100644 --- a/pkg/util/log/log_bridge.go +++ b/pkg/util/log/log_bridge.go @@ -15,14 +15,21 @@ import ( "context" "fmt" stdLog "log" + "regexp" "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) } @@ -52,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 @@ -67,7 +84,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 {