Merge pull request authzed#1864 from jzelinskie/less-verbose-logging

cmd/server: log dispatching at debug level

Author: ecordell

internal/datastore/crdb/crdb_test.go

@@ -303,7 +303,7 @@ func newCRDBWithUser(t *testing.T, pool *dockertest.Pool) (adminConn *pgx.Conn,
 	require.NoError(t, rootCertFile.Close())
 
 	resource, err := pool.RunWithOptions(&dockertest.RunOptions{
-		Repository: "cockroachdb/cockroach",
+		Repository: "mirror.gcr.io/cockroachdb/cockroach",
 		Tag:        testdatastore.CRDBTestVersionTag,
 		Cmd:        []string{"start-single-node", "--certs-dir", "/certs", "--accept-sql-without-tls"},
 		Mounts:     []string{certDir + ":/certs"},

internal/testserver/datastore/crdb.go

@@ -40,7 +40,7 @@ func RunCRDBForTesting(t testing.TB, bridgeNetworkName string) RunningEngineForT
 	name := fmt.Sprintf("crds-%s", uuid.New().String())
 	resource, err := pool.RunWithOptions(&dockertest.RunOptions{
 		Name:       name,
-		Repository: "cockroachdb/cockroach",
+		Repository: "mirror.gcr.io/cockroachdb/cockroach",
 		Tag:        CRDBTestVersionTag,
 		Cmd:        []string{"start-single-node", "--insecure", "--max-offset=50ms"},
 		NetworkID:  bridgeNetworkName,

internal/testserver/datastore/mysql.go

@@ -58,7 +58,7 @@ func RunMySQLForTestingWithOptions(t testing.TB, options MySQLTesterOptions, bri
 	name := fmt.Sprintf("mysql-%s", uuid.New().String())
 	resource, err := pool.RunWithOptions(&dockertest.RunOptions{
 		Name:       name,
-		Repository: "mysql",
+		Repository: "mirror.gcr.io/library/mysql",
 		Tag:        containerImageTag,
 		Env:        []string{"MYSQL_ROOT_PASSWORD=secret"},
 		// increase max connections (default 151) to accommodate tests using the same docker container

internal/testserver/datastore/postgres.go

@@ -69,7 +69,7 @@ func RunPostgresForTestingWithCommitTimestamps(t testing.TB, bridgeNetworkName s
 
 	postgres, err := pool.RunWithOptions(&dockertest.RunOptions{
 		Name:       postgresContainerHostname,
-		Repository: "postgres",
+		Repository: "mirror.gcr.io/library/postgres",
 		Tag:        pgVersion,
 		Env: []string{
 			"POSTGRES_USER=" + POSTGRES_TEST_USER,
@@ -173,7 +173,7 @@ func (b *postgresTester) runPgbouncerForTesting(t testing.TB, pool *dockertest.P
 
 	pgbouncer, err := pool.RunWithOptions(&dockertest.RunOptions{
 		Name:       pgbouncerContainerHostname,
-		Repository: "edoburu/pgbouncer",
+		Repository: "mirror.gcr.io/edoburu/pgbouncer",
 		Tag:        "latest",
 		Env: []string{
 			"DB_USER=" + POSTGRES_TEST_USER,

pkg/cmd/server/defaults.go

@@ -118,15 +118,26 @@ func MetricsHandler(telemetryRegistry *prometheus.Registry, c *Config) http.Hand
 	return mux
 }
 
-// the server has a deadline set, so we consider it a normal condition
-// this makes sure we don't log them as errors
 var defaultCodeToLevel = grpclog.WithLevels(func(code codes.Code) grpclog.Level {
 	if code == codes.DeadlineExceeded {
+		// The server has a deadline set, so we consider it a normal condition.
+		// This ensures that we don't log them as errors.
 		return grpclog.LevelInfo
 	}
 	return grpclog.DefaultServerCodeToLevel(code)
 })
 
+var dispatchDefaultCodeToLevel = grpclog.WithLevels(func(code codes.Code) grpclog.Level {
+	switch code {
+	case codes.OK, codes.Canceled:
+		return grpclog.LevelDebug
+	case codes.NotFound, codes.AlreadyExists, codes.InvalidArgument, codes.Unauthenticated:
+		return grpclog.LevelWarn
+	default:
+		return grpclog.DefaultServerCodeToLevel(code)
+	}
+})
+
 var durationFieldOption = grpclog.WithDurationField(func(duration time.Duration) grpclog.Fields {
 	return grpclog.Fields{"grpc.time_ms", duration.Milliseconds()}
 })
@@ -376,15 +387,15 @@ func DefaultDispatchMiddleware(logger zerolog.Logger, authFunc grpcauth.AuthFunc
 	return []grpc.UnaryServerInterceptor{
 			requestid.UnaryServerInterceptor(requestid.GenerateIfMissing(true)),
 			logmw.UnaryServerInterceptor(logmw.ExtractMetadataField(string(requestmeta.RequestIDKey), "requestID")),
-			grpclog.UnaryServerInterceptor(InterceptorLogger(logger), defaultCodeToLevel, durationFieldOption, traceIDFieldOption),
+			grpclog.UnaryServerInterceptor(InterceptorLogger(logger), dispatchDefaultCodeToLevel, durationFieldOption, traceIDFieldOption),
 			grpcMetricsUnaryInterceptor,
 			grpcauth.UnaryServerInterceptor(authFunc),
 			datastoremw.UnaryServerInterceptor(ds),
 			servicespecific.UnaryServerInterceptor,
 		}, []grpc.StreamServerInterceptor{
 			requestid.StreamServerInterceptor(requestid.GenerateIfMissing(true)),
 			logmw.StreamServerInterceptor(logmw.ExtractMetadataField(string(requestmeta.RequestIDKey), "requestID")),
-			grpclog.StreamServerInterceptor(InterceptorLogger(logger), defaultCodeToLevel, durationFieldOption, traceIDFieldOption),
+			grpclog.StreamServerInterceptor(InterceptorLogger(logger), dispatchDefaultCodeToLevel, durationFieldOption, traceIDFieldOption),
 			grpcMetricsStreamingInterceptor,
 			grpcauth.StreamServerInterceptor(authFunc),
 			datastoremw.StreamServerInterceptor(ds),