grpc_log.go

// Copyright 2016 The Cockroach Authors.
//
// Use of this software is governed by the Business Source License
// included in the file licenses/BSL.txt.
//
// As of the Change Date specified in that file, in accordance with
// the Business Source License, use of this software will be governed
// by the Apache License, Version 2.0, included in the file
// licenses/APL.txt.

package grpcutil

import (
	"context"
	"math"
	"os"
	"regexp"
	"strconv"
	"strings"
	"time"

	"github.com/cockroachdb/cockroach/pkg/util/log"
	"github.com/cockroachdb/cockroach/pkg/util/log/severity"
	"github.com/cockroachdb/cockroach/pkg/util/syncutil"
	"github.com/cockroachdb/cockroach/pkg/util/timeutil"
	"google.golang.org/grpc/grpclog"
)

func init() {
	LowerSeverity(severity.ERROR)
}

// LowerSeverity ensures that the severity level below which GRPC
// log messages are suppressed is at most the specified severity.
//
// Prior to the first call to this method, this cutoff is ERROR,
// or whatever is specified via the GRPC_GO_LOG_SEVERITY_LEVEL
// environment variable.
//
// Must be called before GRPC is used.
func LowerSeverity(s log.Severity) {
	logger := getGRPCLogger(
		s,
		os.Getenv("GRPC_GO_LOG_SEVERITY_LEVEL"),
		os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL"),
	)

	grpclog.SetLoggerV2(logger)
}

func getGRPCLogger(inputSeverity log.Severity, envSev, envVer string) *grpcLogger {
	{
		// If the env var specifies a lower severity than the input,
		// lower the input accordingly.
		var s log.Severity
		switch e := strings.ToLower(envSev); e {
		case "info":
			s = severity.INFO
		case "warning":
			s = severity.WARNING
		case "error":
			s = severity.ERROR
		case "":
			s = inputSeverity
		default:
			panic("unsupported GRPC_GO_LOG_SEVERITY_LEVEL: " + e)
		}
		if s < inputSeverity {
			inputSeverity = s
		}
	}

	var vl int
	if envVer != "" {
		vli, err := strconv.ParseInt(envVer, 10, 32)
		if err != nil {
			panic("invalid GRPC_GO_LOG_VERBOSITY_LEVEL " + envVer + ": " + err.Error())
		}
		if vl < 0 {
			vli = 0
		}
		if vli > math.MaxInt32 {
			vli = math.MaxInt32
		}
		vl = int(vli)
	}

	return &grpcLogger{
		sev: inputSeverity, grpcVerbosityLevel: vl,
	}
}

// NB: This interface is implemented by a pointer because using a value causes
// a synthetic stack frame to be inserted on calls to the interface methods.
// Specifically, we get a stack frame that appears as "<autogenerated>", which
// is not useful in logs.
var _ grpclog.LoggerV2 = (*grpcLogger)(nil)

// We use a depth of 2 throughout this file because all logging
// calls originate from the logging adapter file in grpc, which is
// an additional stack frame away from the actual logging site.
const depth2 = 2

type grpcLogger struct {
	sev                log.Severity
	grpcVerbosityLevel int
}

func (l *grpcLogger) vDepth(i int, depth int) bool {
	if i < 0 {
		i = 0
	}
	if i > math.MaxInt32 {
		i = math.MaxInt32
	}

	// If GRPC_GO_LOG_VERBOSITY_LEVEL is less restrictive, it prevails.
	if i <= l.grpcVerbosityLevel {
		return true
	}
	// Otherwise, our logger decides.
	return log.VDepth(log.Level(i) /* level */, depth+1)
}

func (l *grpcLogger) shouldLog(incomingSeverity log.Severity, depth int) bool {
	// If the incoming severity is at or above threshold, log.
	if l.sev <= incomingSeverity {
		return true
	}
	// If verbose logging is on at all (either for our
	// logger or via the grpc env var), log all severities.
	return l.vDepth(1, depth+1)
}

func (l *grpcLogger) Info(args ...interface{}) {
	if !l.shouldLog(severity.INFO, depth2) {
		return
	}
	log.InfofDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Infoln(args ...interface{}) {
	if !l.shouldLog(severity.INFO, depth2) {
		return
	}
	log.InfofDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Infof(format string, args ...interface{}) {
	if !l.shouldLog(severity.INFO, depth2) {
		return
	}
	log.InfofDepth(context.TODO(), depth2, format, args...)
}

func (l *grpcLogger) Warning(args ...interface{}) {
	if !l.shouldLog(severity.WARNING, depth2) {
		return
	}
	if !l.shouldPrintWarning(depth2, args...) {
		return
	}
	log.WarningfDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Warningln(args ...interface{}) {
	if !l.shouldLog(severity.WARNING, depth2) {
		return
	}
	log.WarningfDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Warningf(format string, args ...interface{}) {
	if !l.shouldLog(severity.WARNING, depth2) {
		return
	}
	log.WarningfDepth(context.TODO(), depth2, format, args...)
}

func (l *grpcLogger) Error(args ...interface{}) {
	if !l.shouldLog(severity.ERROR, depth2) {
		return
	}
	log.ErrorfDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Errorln(args ...interface{}) {
	if !l.shouldLog(severity.ERROR, depth2) {
		return
	}
	log.ErrorfDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Errorf(format string, args ...interface{}) {
	if !l.shouldLog(severity.ERROR, depth2) {
		return
	}
	log.ErrorfDepth(context.TODO(), depth2, format, args...)
}

func (l *grpcLogger) Fatal(args ...interface{}) {
	log.FatalfDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Fatalln(args ...interface{}) {
	log.FatalfDepth(context.TODO(), depth2, "", args...)
}

func (l *grpcLogger) Fatalf(format string, args ...interface{}) {
	log.FatalfDepth(context.TODO(), depth2, format, args...)
}

func (l *grpcLogger) V(i int) bool {
	return l.vDepth(i, depth2)
}

// https://github.com/grpc/grpc-go/blob/v1.29.1/clientconn.go#L1275
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),
}

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 (l *grpcLogger) shouldPrintWarning(depth int, args ...interface{}) bool {
	if l.vDepth(1, depth+1) {
		// When verbose logging is on at all, don't
		// suppress any warnings.
		return true
	}
	for _, arg := range args {
		if argStr, ok := arg.(string); ok {
			// 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) < minSpamLogInterval)
				if doPrint {
					spamMu.strs[argStr] = now
				}
				spamMu.Unlock()
				return doPrint
			}
		}
	}
	return true
}