Merge #55279

55279: grpcutil,log: avoid log spam related to TCP probes r=tbg a=knz

Fixes #32102

See individual commits for details.

Co-authored-by: Raphael 'kena' Poss <[email protected]>

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{}
 

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,40 +143,59 @@ 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
 }{
 	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
 				}

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")
 		}
 	})
 }

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 {

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 {