diff --git a/README.md b/README.md index f9a88d597ec4..274f25d5793b 100644 --- a/README.md +++ b/README.md @@ -71,13 +71,8 @@ Please update to the latest version of gRPC-Go using ### How to turn on logging -The default logger is controlled by environment variables. Turn everything on -like this: - -```console -$ export GRPC_GO_LOG_VERBOSITY_LEVEL=99 -$ export GRPC_GO_LOG_SEVERITY_LEVEL=info -``` +See the [grpclog package documentation](https://pkg.go.dev/google.golang.org/grpc/grpclog) +for details on how to configure logging. ### The RPC failed with error `"code = Unavailable desc = transport is closing"` diff --git a/grpclog/component.go b/grpclog/component.go index f1ae080dcb81..2609becee4c7 100644 --- a/grpclog/component.go +++ b/grpclog/component.go @@ -20,33 +20,50 @@ package grpclog import ( "fmt" + "os" + "sync" + + "google.golang.org/grpc/grpclog/internal" ) // componentData records the settings for a component. type componentData struct { - name string + name string + logPrefix string + + infoDepth func(depth int, args ...any) + warningDepth func(depth int, args ...any) + errorDepth func(depth int, args ...any) + fatalDepth func(depth int, args ...any) +} + +type componentCache struct { + mu sync.Mutex + data map[string]*componentData } -var cache = map[string]*componentData{} +var cache = componentCache{ + data: map[string]*componentData{}, +} func (c *componentData) InfoDepth(depth int, args ...any) { - args = append([]any{"[" + string(c.name) + "]"}, args...) - InfoDepth(depth+1, args...) + args = append([]any{c.logPrefix}, args...) + c.infoDepth(depth+1, args...) } func (c *componentData) WarningDepth(depth int, args ...any) { - args = append([]any{"[" + string(c.name) + "]"}, args...) - WarningDepth(depth+1, args...) + args = append([]any{c.logPrefix}, args...) + c.warningDepth(depth+1, args...) } func (c *componentData) ErrorDepth(depth int, args ...any) { - args = append([]any{"[" + string(c.name) + "]"}, args...) - ErrorDepth(depth+1, args...) + args = append([]any{c.logPrefix}, args...) + c.errorDepth(depth+1, args...) } func (c *componentData) FatalDepth(depth int, args ...any) { - args = append([]any{"[" + string(c.name) + "]"}, args...) - FatalDepth(depth+1, args...) + args = append([]any{c.logPrefix}, args...) + c.fatalDepth(depth+1, args...) } func (c *componentData) Info(args ...any) { @@ -101,15 +118,93 @@ func (c *componentData) V(l int) bool { return V(l) } +func componentInfoDepth(depth int, args ...any) { + if internal.ComponentDepthLoggerV2Impl != nil { + internal.ComponentDepthLoggerV2Impl.InfoDepth(depth, args...) + } else { + internal.ComponentLoggerV2Impl.Infoln(args...) + } +} + +func componentWarningDepth(depth int, args ...any) { + if internal.ComponentDepthLoggerV2Impl != nil { + internal.ComponentDepthLoggerV2Impl.WarningDepth(depth, args...) + } else { + internal.ComponentLoggerV2Impl.Warningln(args...) + } +} + +func componentErrorDepth(depth int, args ...any) { + if internal.ComponentDepthLoggerV2Impl != nil { + internal.ComponentDepthLoggerV2Impl.ErrorDepth(depth, args...) + } else { + internal.ComponentLoggerV2Impl.Errorln(args...) + } +} + +func componentFatalDepth(depth int, args ...any) { + if internal.ComponentDepthLoggerV2Impl != nil { + internal.ComponentDepthLoggerV2Impl.FatalDepth(depth, args...) + } else { + internal.ComponentLoggerV2Impl.Fatalln(args...) + } + os.Exit(1) +} + +func noopDepth(int, ...any) { +} + // Component creates a new component and returns it for logging. If a component // with the name already exists, nothing will be created and it will be // returned. SetLoggerV2 will panic if it is called with a logger created by // Component. func Component(componentName string) DepthLoggerV2 { - if cData, ok := cache[componentName]; ok { + cache.mu.Lock() + defer cache.mu.Unlock() + if cData, ok := cache.data[componentName]; ok { return cData } - c := &componentData{componentName} - cache[componentName] = c + c := &componentData{ + name: componentName, + logPrefix: "[" + componentName + "]", + infoDepth: InfoDepth, + warningDepth: WarningDepth, + errorDepth: ErrorDepth, + fatalDepth: FatalDepth, + } + + if level, ok := componentLogLevels[componentName]; ok { + c.fatalDepth = func(depth int, args ...any) { + componentFatalDepth(depth+1, args...) + } + switch level { + case severityInfo: + c.infoDepth = func(depth int, args ...any) { + componentInfoDepth(depth+1, args...) + } + c.warningDepth = func(depth int, args ...any) { + componentWarningDepth(depth+1, args...) + } + c.errorDepth = func(depth int, args ...any) { + componentErrorDepth(depth+1, args...) + } + case severityWarning: + c.infoDepth = noopDepth + c.warningDepth = func(depth int, args ...any) { + componentWarningDepth(depth+1, args...) + } + c.errorDepth = func(depth int, args ...any) { + componentErrorDepth(depth+1, args...) + } + case severityError: + c.infoDepth = noopDepth + c.warningDepth = noopDepth + c.errorDepth = func(depth int, args ...any) { + componentErrorDepth(depth+1, args...) + } + } + } + + cache.data[componentName] = c return c } diff --git a/grpclog/component_test.go b/grpclog/component_test.go new file mode 100644 index 000000000000..f96b0c886408 --- /dev/null +++ b/grpclog/component_test.go @@ -0,0 +1,276 @@ +/* + * + * Copyright 2026 gRPC authors. + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + * + */ + +package grpclog + +import ( + "bytes" + "slices" + "strings" + "testing" + + "google.golang.org/grpc/grpclog/internal" +) + +func TestParseComponentLogLevel(t *testing.T) { + tests := []struct { + name string + input string + want map[string]severityLevel + }{ + { + name: "returns nil for empty input", + input: "", + want: nil, + }, + { + name: "parses single component with INFO level", + input: "dns:INFO", + want: map[string]severityLevel{ + "dns": severityInfo, + }, + }, + { + name: "parses single component with WARNING level", + input: "xds:WARNING", + want: map[string]severityLevel{ + "xds": severityWarning, + }, + }, + { + name: "parses single component with ERROR level", + input: "authz:ERROR", + want: map[string]severityLevel{ + "authz": severityError, + }, + }, + { + name: "all-lowercase level names are recognized", + input: "dns:error,xds:warning,authz:info", + want: map[string]severityLevel{ + "dns": severityError, + "xds": severityWarning, + "authz": severityInfo, + }, + }, + { + name: "mixed-case level names are treated as unknown and skipped", + input: "dns:Error,xds:Warning,authz:Info", + want: map[string]severityLevel{}, + }, + { + name: "parses multiple comma-separated components with different levels", + input: "dns:ERROR,xds:WARNING,authz:INFO", + want: map[string]severityLevel{ + "dns": severityError, + "xds": severityWarning, + "authz": severityInfo, + }, + }, + { + name: "entry without colon separator is skipped", + input: "dns:ERROR,invalid,xds:WARNING", + want: map[string]severityLevel{ + "dns": severityError, + "xds": severityWarning, + }, + }, + { + name: "entry with empty component name before colon is skipped", + input: ":ERROR,dns:WARNING", + want: map[string]severityLevel{ + "dns": severityWarning, + }, + }, + { + name: "unrecognized level name is skipped", + input: "dns:UNKNOWN,xds:ERROR", + want: map[string]severityLevel{ + "xds": severityError, + }, + }, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + got := parseComponentLogLevels(tt.input) + if tt.want == nil { + if got != nil { + t.Errorf("got %v for input %q, want nil", got, tt.input) + } + return + } + if len(got) != len(tt.want) { + t.Errorf("got %v for input %q, want %v", got, tt.input, tt.want) + return + } + for k, v := range tt.want { + if gv, ok := got[k]; !ok || gv != v { + t.Errorf("got %v for key %q in input %q, want %v", gv, k, tt.input, v) + } + } + }) + } +} + +func TestLogger(t *testing.T) { + tests := []struct { + name string + componentLogLevel string + logSeverityLevel string + components []string + want []string + }{ + { + name: "empty GRPC_GO_LOG_SEVERITY_LEVEL and GRPC_GO_COMPONENT_LOG_LEVEL defaults to ERROR for all logs", + componentLogLevel: "", + logSeverityLevel: "", + components: []string{"dns", "xds", "authz", "balancer"}, + want: []string{ + "ERROR: [dns] dns-error", + "ERROR: [xds] xds-error", + "ERROR: [authz] authz-error", + "ERROR: [balancer] balancer-error", + }, + }, + { + name: "INFO GRPC_GO_LOG_SEVERITY_LEVEL and empty GRPC_GO_COMPONENT_LOG_LEVEL logs all levels", + componentLogLevel: "", + logSeverityLevel: "INFO", + components: []string{"dns", "xds", "authz", "balancer"}, + want: []string{ + "INFO: [dns] dns-info", + "WARNING: [dns] dns-warning", + "ERROR: [dns] dns-error", + "INFO: [xds] xds-info", + "WARNING: [xds] xds-warning", + "ERROR: [xds] xds-error", + "INFO: [authz] authz-info", + "WARNING: [authz] authz-warning", + "ERROR: [authz] authz-error", + "INFO: [balancer] balancer-info", + "WARNING: [balancer] balancer-warning", + "ERROR: [balancer] balancer-error", + }, + }, + { + name: "GRPC_GO_COMPONENT_LOG_LEVEL overrides ERROR GRPC_GO_LOG_SEVERITY_LEVEL for configured components", + componentLogLevel: "dns:INFO,xds:WARNING,authz:ERROR", + logSeverityLevel: "ERROR", + components: []string{"dns", "xds", "authz", "balancer"}, + want: []string{ + "INFO: [dns] dns-info", + "WARNING: [dns] dns-warning", + "ERROR: [dns] dns-error", + "WARNING: [xds] xds-warning", + "ERROR: [xds] xds-error", + "ERROR: [authz] authz-error", + "ERROR: [balancer] balancer-error", + }, + }, + { + name: "GRPC_GO_COMPONENT_LOG_LEVEL overrides INFO GRPC_GO_LOG_SEVERITY_LEVEL for configured components", + componentLogLevel: "dns:INFO,xds:WARNING,authz:ERROR", + logSeverityLevel: "INFO", + components: []string{"dns", "xds", "authz", "balancer"}, + want: []string{ + "INFO: [dns] dns-info", + "WARNING: [dns] dns-warning", + "ERROR: [dns] dns-error", + "WARNING: [xds] xds-warning", + "ERROR: [xds] xds-error", + "ERROR: [authz] authz-error", + "INFO: [balancer] balancer-info", + "WARNING: [balancer] balancer-warning", + "ERROR: [balancer] balancer-error", + }, + }, + { + name: "empty GRPC_GO_LOG_SEVERITY_LEVEL with GRPC_GO_COMPONENT_LOG_LEVEL defaults to ERROR for unconfigured components", + componentLogLevel: "dns:INFO,xds:WARNING,authz:ERROR", + logSeverityLevel: "", + components: []string{"dns", "xds", "authz", "balancer"}, + want: []string{ + "INFO: [dns] dns-info", + "WARNING: [dns] dns-warning", + "ERROR: [dns] dns-error", + "WARNING: [xds] xds-warning", + "ERROR: [xds] xds-error", + "ERROR: [authz] authz-error", + "ERROR: [balancer] balancer-error", + }, + }, + { + name: "unrecognized GRPC_GO_COMPONENT_LOG_LEVEL falls back to global default", + componentLogLevel: "dns:FATAL", + logSeverityLevel: "INFO", + components: []string{"dns", "balancer"}, + want: []string{ + "INFO: [dns] dns-info", + "WARNING: [dns] dns-warning", + "ERROR: [dns] dns-error", + "INFO: [balancer] balancer-info", + "WARNING: [balancer] balancer-warning", + "ERROR: [balancer] balancer-error", + }, + }, + } + originalComponentLogLevels := componentLogLevels + originalLoggerV2 := internal.LoggerV2Impl + originalDepthLoggerV2 := internal.DepthLoggerV2Impl + originalComponentLoggerV2 := internal.ComponentLoggerV2Impl + originalComponentDepthLoggerV2 := internal.ComponentDepthLoggerV2Impl + originalCache := cache.data + + t.Cleanup(func() { + componentLogLevels = originalComponentLogLevels + internal.LoggerV2Impl = originalLoggerV2 + internal.DepthLoggerV2Impl = originalDepthLoggerV2 + internal.ComponentLoggerV2Impl = originalComponentLoggerV2 + internal.ComponentDepthLoggerV2Impl = originalComponentDepthLoggerV2 + cache.data = originalCache + }) + + const logTimestampPrefixLen = len("2006/01/02 15:04:05 ") + + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + cache.data = map[string]*componentData{} + + var buf bytes.Buffer + initLogger(&buf, tt.logSeverityLevel, "", "", tt.componentLogLevel) + + for _, name := range tt.components { + logger := Component(name) + logger.Infof("%s-info", name) + logger.Warningf("%s-warning", name) + logger.Errorf("%s-error", name) + } + + var got []string + for line := range strings.SplitSeq(buf.String(), "\n") { + if line == "" { + continue + } + got = append(got, line[logTimestampPrefixLen:]) + } + if !slices.Equal(got, tt.want) { + t.Errorf("got %v, want %v", got, tt.want) + } + }) + } +} diff --git a/grpclog/grpclog.go b/grpclog/grpclog.go index db320105e64e..09004ffaf6af 100644 --- a/grpclog/grpclog.go +++ b/grpclog/grpclog.go @@ -18,19 +18,95 @@ // Package grpclog defines logging for grpc. // -// In the default logger, severity level can be set by environment variable -// GRPC_GO_LOG_SEVERITY_LEVEL, verbosity level can be set by -// GRPC_GO_LOG_VERBOSITY_LEVEL. +// The default logger is controlled by environment variables. Turn +// everything on like this: +// +// export GRPC_GO_LOG_VERBOSITY_LEVEL=99 +// export GRPC_GO_LOG_SEVERITY_LEVEL=info +// +// Additionally, you can configure log severity levels for individual +// components using the GRPC_GO_COMPONENT_LOG_LEVEL environment +// variable. The format is a comma-separated list of component:LEVEL +// pairs like this: +// +// export GRPC_GO_COMPONENT_LOG_LEVEL=dns:ERROR,transport:WARNING +// +// When both GRPC_GO_LOG_SEVERITY_LEVEL and GRPC_GO_COMPONENT_LOG_LEVEL +// are set, component-specific settings take precedence over +// GRPC_GO_LOG_SEVERITY_LEVEL for the specified components. Components +// not listed in GRPC_GO_COMPONENT_LOG_LEVEL will use the +// GRPC_GO_LOG_SEVERITY_LEVEL setting. For example: +// +// export GRPC_GO_LOG_SEVERITY_LEVEL=ERROR +// export GRPC_GO_COMPONENT_LOG_LEVEL=dns:INFO +// +// In this case, the dns component will log at INFO level, while all +// other components will log at ERROR level. package grpclog import ( + "io" "os" + "strings" "google.golang.org/grpc/grpclog/internal" ) +type severityLevel int + +const ( + severityInfo severityLevel = iota + severityWarning + severityError +) + +func parseComponentLogLevels(logLevel string) map[string]severityLevel { + if logLevel == "" { + return nil + } + + logLevels := make(map[string]severityLevel) + for part := range strings.SplitSeq(logLevel, ",") { + kv := strings.Split(part, ":") + if len(kv) < 2 { + continue + } + component := kv[0] + if component == "" { + continue + } + level := kv[1] + switch level { + case "INFO", "info": + logLevels[component] = severityInfo + case "WARNING", "warning": + logLevels[component] = severityWarning + case "ERROR", "error": + logLevels[component] = severityError + default: + continue + } + } + return logLevels +} + +var componentLogLevels map[string]severityLevel + func init() { - SetLoggerV2(newLoggerV2()) + initLogger( + os.Stderr, + os.Getenv("GRPC_GO_LOG_SEVERITY_LEVEL"), + os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL"), + os.Getenv("GRPC_GO_LOG_FORMATTER"), + os.Getenv("GRPC_GO_COMPONENT_LOG_LEVEL"), + ) +} + +func initLogger(w io.Writer, logSeverityLevel, logVerbosityLevel, logFormatter, componentLogLevel string) { + componentLogLevels = parseComponentLogLevels(componentLogLevel) + config := loggerV2Config(logVerbosityLevel, logFormatter) + setLoggerV2(newLoggerV2(w, config, logSeverityLevel)) + setComponentLoggerV2(newComponentLoggerV2(w, config)) } // V reports whether verbosity level l is at least the requested verbose level. diff --git a/grpclog/internal/grpclog.go b/grpclog/internal/grpclog.go index 59c03bc14c2a..1c522c93f392 100644 --- a/grpclog/internal/grpclog.go +++ b/grpclog/internal/grpclog.go @@ -24,3 +24,11 @@ var LoggerV2Impl LoggerV2 // DepthLoggerV2Impl is the logger used for the depth log functions. var DepthLoggerV2Impl DepthLoggerV2 + +// ComponentLoggerV2Impl is the logger used for non-depth +// per-component log functions. +var ComponentLoggerV2Impl LoggerV2 + +// ComponentDepthLoggerV2Impl is the logger used for depth +// per-component log functions. +var ComponentDepthLoggerV2Impl DepthLoggerV2 diff --git a/grpclog/loggerv2.go b/grpclog/loggerv2.go index 892dc13d164b..5611e2f8236b 100644 --- a/grpclog/loggerv2.go +++ b/grpclog/loggerv2.go @@ -20,7 +20,6 @@ package grpclog import ( "io" - "os" "strconv" "strings" @@ -38,6 +37,8 @@ func SetLoggerV2(l LoggerV2) { } internal.LoggerV2Impl = l internal.DepthLoggerV2Impl, _ = l.(internal.DepthLoggerV2) + internal.ComponentLoggerV2Impl = l + internal.ComponentDepthLoggerV2Impl, _ = l.(internal.DepthLoggerV2) } // NewLoggerV2 creates a loggerV2 with the provided writers. @@ -55,35 +56,51 @@ func NewLoggerV2WithVerbosity(infoW, warningW, errorW io.Writer, v int) LoggerV2 return internal.NewLoggerV2(infoW, warningW, errorW, internal.LoggerV2Config{Verbosity: v}) } +func loggerV2Config(level, formatter string) internal.LoggerV2Config { + var v int + if vl, err := strconv.Atoi(level); err == nil { + v = vl + } + + jsonFormat := strings.EqualFold(formatter, "json") + + return internal.LoggerV2Config{ + Verbosity: v, + FormatJSON: jsonFormat, + } +} + // newLoggerV2 creates a loggerV2 to be used as default logger. // All logs are written to stderr. -func newLoggerV2() LoggerV2 { +func newLoggerV2(w io.Writer, config internal.LoggerV2Config, level string) LoggerV2 { errorW := io.Discard warningW := io.Discard infoW := io.Discard - logLevel := os.Getenv("GRPC_GO_LOG_SEVERITY_LEVEL") - switch logLevel { + switch level { case "", "ERROR", "error": // If env is unset, set level to ERROR. - errorW = os.Stderr + errorW = w case "WARNING", "warning": - warningW = os.Stderr + warningW = w case "INFO", "info": - infoW = os.Stderr + infoW = w } - var v int - vLevel := os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL") - if vl, err := strconv.Atoi(vLevel); err == nil { - v = vl - } + return internal.NewLoggerV2(infoW, warningW, errorW, config) +} - jsonFormat := strings.EqualFold(os.Getenv("GRPC_GO_LOG_FORMATTER"), "json") +func newComponentLoggerV2(w io.Writer, config internal.LoggerV2Config) LoggerV2 { + return internal.NewLoggerV2(w, io.Discard, io.Discard, config) +} - return internal.NewLoggerV2(infoW, warningW, errorW, internal.LoggerV2Config{ - Verbosity: v, - FormatJSON: jsonFormat, - }) +func setLoggerV2(l LoggerV2) { + internal.LoggerV2Impl = l + internal.DepthLoggerV2Impl, _ = l.(internal.DepthLoggerV2) +} + +func setComponentLoggerV2(l LoggerV2) { + internal.ComponentLoggerV2Impl = l + internal.ComponentDepthLoggerV2Impl, _ = l.(internal.DepthLoggerV2) } // DepthLoggerV2 logs at a specified call frame. If a LoggerV2 also implements