grpclog: add GRPC_GO_COMPONENT_LOG_LEVEL for controling component logs#8885
grpclog: add GRPC_GO_COMPONENT_LOG_LEVEL for controling component logs#8885110y wants to merge 11 commits intogrpc:masterfrom
Conversation
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## master #8885 +/- ##
==========================================
- Coverage 83.06% 82.88% -0.18%
==========================================
Files 410 410
Lines 32598 32702 +104
==========================================
+ Hits 27076 27105 +29
- Misses 4053 4088 +35
- Partials 1469 1509 +40
🚀 New features to boost your workflow:
|
|
@easwars Please take a look, thanks 🙏 |
eshitachandwani
left a comment
eshitachandwani
left a comment
There was a problem hiding this comment.
Apologies for the delay , I am still in process of reviewing the PR , but posting a few quick comments I had.
| // 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. |
There was a problem hiding this comment.
Can you please make sure the comments are wrapped at 80 cols
| } | ||
| level := kv[1] | ||
| switch level { | ||
| case "INFO", "info": |
There was a problem hiding this comment.
Here , instead of just checking for all uppercase and all lower case , can we instead convert the input to all lowercase and then just check for info. This is similar to what we do for balancer and resolver registries. But I also see that this is how log levels are checked earlier so maybe @easwars knows if there is a particular reason for that.
There was a problem hiding this comment.
As you mentioned, and as I mentioned in the issue regarding component logging: #3937 (comment),
this code follows what the existing GRPC_GO_LOG_SEVERITY_LEVEL does for case-insensitive level matching.
I also thought it might be better to use strings.ToLower for matching, but I would say we should make two environment variables have the same logic for case-insensitivity.
@easwars What do you think about this? 👀
There was a problem hiding this comment.
Let me notify in case of you missed this comment 🙏
| case "ERROR", "error": | ||
| logLevels[component] = severityError | ||
| default: | ||
| logLevels[component] = severityFatal |
There was a problem hiding this comment.
If the log level does not match any, we might want to let the global default take over for the specific component instead of level being Fatal.
There was a problem hiding this comment.
I also thought it would be better to let the global default logger take over if the log level for a component does not match any know level.
However, I found that the existing GRPC_GO_LOG_SEVERITY_LEVEL implicitly behaves like the "FATAL" level if an unknown level string is passed:
Lines 109 to 124 in ef6044e
So, I made the new GRPC_GO_COMPONENT_LOG_LEVEL behave similarly.
I think it would be fine to make the new GRPC_GO_COMPONENT_LOG_LEVEL behave differently from the existing GRPC_GO_LOG_SEVERITY_LEVEL and let the global default logger take over if the log level for a component does not match any as @eshitachandwani mentioned.
@easwars What do you think about this? 👀
There was a problem hiding this comment.
Why do you say that it implicitly behaves like fatal if an unknown string is passed? My reading of it is that passing an unknown string should just lead to nothing being logged because all three writers would be set to io.Discard.
There was a problem hiding this comment.
Ah, sorry I missed that internal.NewLoggerV2 uses the error writer also for the fatal writer:
grpc-go/grpclog/internal/loggerv2.go
Line 258 in d723006
I made it to use global default logger when it gets an unrecognized string for a component by this commit: d723006
| severityFatal | ||
| ) | ||
|
|
||
| func parseComponentLogLevel(logLevel string) map[string]severityLevel { |
There was a problem hiding this comment.
| func parseComponentLogLevel(logLevel string) map[string]severityLevel { | |
| func parseComponentLogLevels(logLevels string) map[string]severityLevel { |
There was a problem hiding this comment.
Updated: c0d5868
Because the variable logLevel is already used in subsequent processing and the name of environment variable is GRPC_GO_COMPONENT_LOG_LEVEL (does not have s), I leave the argument as it was.
|
|
||
| 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) |
There was a problem hiding this comment.
Correct me if my understanding is wrong but if we pass io.Discard in error and warning writer, it is never going to print the error or warning logs?
There was a problem hiding this comment.
Because combineLoggers:
grpc-go/grpclog/internal/loggerv2.go
Lines 255 to 256 in ef6044e
This is also the same behavior as the existing newLoggerV2:
Lines 109 to 124 in 324a394
|
/gemini review |
![gemini-code-assist[bot]](https://avatars.githubusercontent.com/in/956858?s=60&v=4){kind=small}
There was a problem hiding this comment.
Code Review
The pull request introduces a valuable feature for per-component log severity control in gRPC-Go. The implementation correctly handles the precedence of component-specific settings over global settings and provides a separate component logger to allow more verbose logging for specific components. However, there are a few critical issues regarding Go version compatibility and thread safety that need to be addressed before merging.
| if cData, ok := cache[componentName]; ok { | ||
| return cData | ||
| } | ||
| c := &componentData{componentName} | ||
| c := &componentData{ | ||
| name: 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...) | ||
| } | ||
| case severityFatal: | ||
| c.infoDepth = noopDepth | ||
| c.warningDepth = noopDepth | ||
| c.errorDepth = noopDepth | ||
| } | ||
| } | ||
|
|
||
| cache[componentName] = c |
There was a problem hiding this comment.
Access to the global cache map is not synchronized. Since Component is a public function that can be called concurrently from multiple goroutines (e.g., during lazy initialization of different gRPC components), this can lead to a concurrent map write panic. Although the original code had this issue, the PR significantly increases the logic within the critical section, making the race more likely. A sync.Mutex or sync.RWMutex should be used to protect the cache.
There was a problem hiding this comment.
As gemini mentioned, my implementation does not use a mutex because the original implementation does not use a mutex to protect cache.
@eshitachandwani @easwars What do you think about this? 👀
There was a problem hiding this comment.
Using a mutex would mean every component trying to initialize the logger would have to acquire the mutex and it will significantly increase the latency, so I dont think using mutex is a good idea.
There was a problem hiding this comment.
The mutex is only going to be used when the component is created and not everytime the component is used to log a message. So, I don't think it is going to significantly increase the latency. I think we can go ahead with having the mutex.
| 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: | ||
|
|
||
| ```console | ||
| $ 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: | ||
|
|
||
| ```console | ||
| $ 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 |
There was a problem hiding this comment.
I think we should consolidate all this information in the godoc for the grpclog package (including the existing paragraph in this section) and simply point to the godoc from here.
| case "ERROR", "error": | ||
| logLevels[component] = severityError | ||
| default: | ||
| logLevels[component] = severityFatal |
There was a problem hiding this comment.
Why do you say that it implicitly behaves like fatal if an unknown string is passed? My reading of it is that passing an unknown string should just lead to nothing being logged because all three writers would be set to io.Discard.
| logLevels[component] = severityInfo | ||
| case "WARNING", "warning": | ||
| logLevels[component] = severityWarning | ||
| case "ERROR", "error": |
There was a problem hiding this comment.
Currently, we consider an empty string to mean log at ERROR as well.
There was a problem hiding this comment.
@easwars
So, do you men if we have GRPC_GO_COMPONENT_LOG_LEVEL as dns:INFO,xds:,authz:ERROR, the log level for xds component should be ERROR instead of make it use the global default logger, right?
| return V(l) | ||
| } | ||
|
|
||
| func noopDepth(_ int, _ ...any) { |
There was a problem hiding this comment.
Nit: You could ignore the blank identifiers in the parameter list because all of them are blank.
| "strings" | ||
| ) | ||
|
|
||
| type severityLevel int |
There was a problem hiding this comment.
I think this whole logic of parsing the newly added env var should be in grpclog/grpclog.go and not here. This file should only contain the implementation of the component logger.
|
|
||
| func init() { | ||
| SetLoggerV2(newLoggerV2()) | ||
| initLogger( |
There was a problem hiding this comment.
init --> initLogger --> setLoggerV2 etc. So many levels of function calls just makes this code very hard to read and understand and keep things in your mental model. Can we flatten this please. We can continue to have parseComponentLogLevels as a separate function since it deserves to be one. But the rest can all be inlined here into init.
There was a problem hiding this comment.
OK, now I also think it should be flattened.
Before tidying up it, let me clarify about initLogger.
Its purpose is to make us to be able to replace the io.Writer easily for tests like this:
grpc-go/grpclog/component_test.go
Line 257 in c0d5868
Do you think we should flatten initLogger too?
|
|
||
| func componentInfoDepth(depth int, args ...any) { | ||
| if internal.ComponentDepthLoggerV2Impl != nil { | ||
| internal.ComponentDepthLoggerV2Impl.InfoDepth(depth, args...) |
There was a problem hiding this comment.
Don't we have to do depth+1 here?
There was a problem hiding this comment.
This behaves like what the current InfoDepth does:
Lines 213 to 219 in 619a19e
I checked that componentInfoDepth preserves the same behavior that the current InfoDepth does by following script and command:
package main
import (
"flag"
"google.golang.org/grpc/grpclog"
_ "google.golang.org/grpc/grpclog/glogger"
)
var dnsLogger = grpclog.Component("dns")
func main() {
flag.Parse()
foo()
}
func foo() {
bar()
}
func bar() {
baz()
}
func baz() {
dnsLogger.InfoDepth(1, "This is an info message from baz")
}$ GRPC_GO_LOG_SEVERITY_LEVEL="INFO" go run main.go -logtostderr
... main.go:23] [dns]This is an info message from baz$ GRPC_GO_COMPONENT_LOG_LEVEL="dns:INFO" go run main.go -logtostderr
... main.go:23] [dns]This is an info message from baz| 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) | ||
| } |
There was a problem hiding this comment.
Since these functions are only called from the component logger, I think these should move to component.go unless you had a good reason to have them here, in which case, I would like to hear that.
| infoDepth func(depth int, args ...any) | ||
| warningDepth func(depth int, args ...any) | ||
| errorDepth func(depth int, args ...any) | ||
| fatalDepth func(depth int, args ...any) |
There was a problem hiding this comment.
Do we really need these function pointers? Can't we instead store the severityLevel for this component, and handle it directly in each of its methods?
func (c *componentData) InfoDepth(depth int, args ...any) {
if c.level > severityInfo { return } // Fast-path exit
// ... rest of logic
}As an improvement, we could even store the computed prefix in the componentData struct. I'm talking about [" + string(c.name) + "] and not have to compute that for every log message.
There was a problem hiding this comment.
@easwars
The reason why I use function pointers is to avoid checking severity every time a log function is called, by replacing loggers with the noopDepth function according to their levels.
I also think it's OK to handle it directly in each methods.
What do you think about this?
There was a problem hiding this comment.
In the meantime, I updated the prefix computation logic: 619a19e
easwars
added
Status: Requires Reporter Clarification
and removed
Status: Requires Reporter Clarification
labels
|
I saw that CI seems to fail randomly: https://github.com/grpc/grpc-go/actions/runs/22563149237/job/65353773787?pr=8885, https://github.com/grpc/grpc-go/actions/runs/22572272694/job/65382832623?pr=8885 Is this just a flaky test or do you think this might be caused by changes introduced in this PR...? |
|
Thank you for your review! Please take another look, thanks 🙏 |
|
I apologize for the delay in the review process. I'm currently dealing with a few higher priority things and will get back to this asap. Thanks for your patience. |
|
No problem! |
5 participants
Fixes #3937
Add support for the
GRPC_GO_COMPONENT_LOG_LEVELenvironment variable, which allows users to configure log severity levels on a per-component basis.The format is a comma-separated list of
component:LEVELpairs (e.g.,dns:ERROR,xds:WARNING,authz:INFO).When both
GRPC_GO_LOG_SEVERITY_LEVELandGRPC_GO_COMPONENT_LOG_LEVELare set,component-specific settings take precedence for the specified components.
Components without an explicit override continue to use the existing global severity level logger.
A separate component logger (
ComponentLoggerV2Impl) is introduced so that components configured with a less restrictive severity than the global logger (e.g., component=INFO while global=ERROR) can still produce output.RELEASE NOTES:
GRPC_GO_COMPONENT_LOG_LEVELenvironment variable for per-component log severity configuration. Users can now set different severity levels for individual gRPC components (e.g.,GRPC_GO_COMPONENT_LOG_LEVEL=dns:ERROR,xds:WARNING).