grpc
/
grpc-go
mirror of https://github.com/grpc/grpc-go.git
1
0
Fork 0
Code Issues Packages Projects Releases Wiki Activity

grpctest: minor improvements to the test logger implementation (#8370)

This commit is contained in:
Ashesh Vidyut 2025-07-07 11:55:00 +05:30 committed by GitHub
parent aa57e6af6c
commit 64a6b623ba
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
11 changed files with 108 additions and 98 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
clientconn_test.go
View File

@ -702,7 +702,7 @@ func (s) TestResolverEmptyUpdateNotPanic(t *testing.T) {
}
func (s) TestClientUpdatesParamsAfterGoAway(t *testing.T) {
grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
grpctest.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
lis, err := net.Listen("tcp", "localhost:0")
if err != nil {

2
encoding/encoding_test.go
View File

@ -112,7 +112,7 @@ func (c *errProtoCodec) Name() string {
// Tests the case where encoding fails on the server. Verifies that there is
// no panic and that the encoding error is propagated to the client.
func (s) TestEncodeDoesntPanicOnServer(t *testing.T) {
grpctest.TLogger.ExpectError("grpc: server failed to encode response")
grpctest.ExpectError("grpc: server failed to encode response")
// Create a codec that errors when encoding messages.
encodingErr := errors.New("encoding failed")

4
internal/grpctest/grpctest.go
View File

@ -53,7 +53,7 @@ type Tester struct{}
// Setup updates the tlogger.
func (Tester) Setup(t *testing.T) {
TLogger.Update(t)
tLogr.update(t)
// TODO: There is one final leak around closing connections without completely
// draining the recvBuffer that has yet to be resolved. All other leaks have been
// completely addressed, and this can be turned back on as soon as this issue is
@ -75,7 +75,7 @@ func (Tester) Teardown(t *testing.T) {
if atomic.LoadUint32(&lcFailed) == 1 {
t.Log("Goroutine leak check disabled for future tests")
}
TLogger.EndTest(t)
tLogr.endTest(t)
}
// Interface defines Tester's methods for use in this package.

172
internal/grpctest/tlogger.go
View File

@ -33,9 +33,9 @@ import (
"google.golang.org/grpc/grpclog"
)
// TLogger serves as the grpclog logger and is the interface through which
// tLogr serves as the grpclog logger and is the interface through which
// expected errors are declared in tests.
var TLogger *tLogger
var tLogr *tLogger
const callingFrame = 4
@ -73,11 +73,21 @@ type tLogger struct {
}
func init() {
TLogger = &tLogger{errors: map[*regexp.Regexp]int{}}
vLevel := os.Getenv("GRPC_GO_LOG_VERBOSITY_LEVEL")
if vl, err := strconv.Atoi(vLevel); err == nil {
TLogger.v = vl
vLevel := 0 // Default verbosity level
if vLevelEnv, found := os.LookupEnv("GRPC_GO_LOG_VERBOSITY_LEVEL"); found {
// If found, attempt to convert. If conversion is successful, update vLevel.
// If conversion fails, log a warning, but vLevel remains its default of 0.
if val, err := strconv.Atoi(vLevelEnv); err == nil {
vLevel = val
} else {
// Log the error if the environment variable is not a valid integer.
fmt.Printf("Warning: GRPC_GO_LOG_VERBOSITY_LEVEL environment variable '%s' is not a valid integer. "+
"Using default verbosity level 0. Error: %v\n", vLevelEnv, err)
}
}
// Initialize tLogr with the determined verbosity level.
tLogr = &tLogger{errors: make(map[*regexp.Regexp]int), v: vLevel}
}
// getCallingPrefix returns the <file:line> at the given depth from the stack.
@ -90,61 +100,61 @@ func getCallingPrefix(depth int) (string, error) {
}
// log logs the message with the specified parameters to the tLogger.
func (g *tLogger) log(ltype logType, depth int, format string, args ...any) {
g.mu.Lock()
defer g.mu.Unlock()
func (tl *tLogger) log(ltype logType, depth int, format string, args ...any) {
tl.mu.Lock()
defer tl.mu.Unlock()
prefix, err := getCallingPrefix(callingFrame + depth)
if err != nil {
g.t.Error(err)
tl.t.Error(err)
return
}
args = append([]any{ltype.String() + " " + prefix}, args...)
args = append(args, fmt.Sprintf(" (t=+%s)", time.Since(g.start)))
args = append(args, fmt.Sprintf(" (t=+%s)", time.Since(tl.start)))
if format == "" {
switch ltype {
case errorLog:
// fmt.Sprintln is used rather than fmt.Sprint because t.Log uses fmt.Sprintln behavior.
if g.expected(fmt.Sprintln(args...)) {
g.t.Log(args...)
// fmt.Sprintln is used rather than fmt.Sprint because tl.Log uses fmt.Sprintln behavior.
if tl.expected(fmt.Sprintln(args...)) {
tl.t.Log(args...)
} else {
g.t.Error(args...)
tl.t.Error(args...)
}
case fatalLog:
panic(fmt.Sprint(args...))
default:
g.t.Log(args...)
tl.t.Log(args...)
}
} else {
// Add formatting directives for the callingPrefix and timeSuffix.
format = "%v " + format + "%s"
switch ltype {
case errorLog:
if g.expected(fmt.Sprintf(format, args...)) {
g.t.Logf(format, args...)
if tl.expected(fmt.Sprintf(format, args...)) {
tl.t.Logf(format, args...)
} else {
g.t.Errorf(format, args...)
tl.t.Errorf(format, args...)
}
case fatalLog:
panic(fmt.Sprintf(format, args...))
default:
g.t.Logf(format, args...)
tl.t.Logf(format, args...)
}
}
}
// Update updates the testing.T that the testing logger logs to. Should be done
// update updates the testing.T that the testing logger logs to. Should be done
// before every test. It also initializes the tLogger if it has not already.
func (g *tLogger) Update(t *testing.T) {
g.mu.Lock()
defer g.mu.Unlock()
if !g.initialized {
grpclog.SetLoggerV2(TLogger)
g.initialized = true
func (tl *tLogger) update(t *testing.T) {
tl.mu.Lock()
defer tl.mu.Unlock()
if !tl.initialized {
grpclog.SetLoggerV2(tl)
tl.initialized = true
}
g.t = t
g.start = time.Now()
g.errors = map[*regexp.Regexp]int{}
tl.t = t
tl.start = time.Now()
tl.errors = map[*regexp.Regexp]int{}
}
// ExpectError declares an error to be expected. For the next test, the first
@ -152,41 +162,41 @@ func (g *tLogger) Update(t *testing.T) {
// to fail. "For the next test" includes all the time until the next call to
// Update(). Note that if an expected error is not encountered, this will cause
// the test to fail.
func (g *tLogger) ExpectError(expr string) {
g.ExpectErrorN(expr, 1)
func ExpectError(expr string) {
ExpectErrorN(expr, 1)
}
// ExpectErrorN declares an error to be expected n times.
func (g *tLogger) ExpectErrorN(expr string, n int) {
g.mu.Lock()
defer g.mu.Unlock()
func ExpectErrorN(expr string, n int) {
tLogr.mu.Lock()
defer tLogr.mu.Unlock()
re, err := regexp.Compile(expr)
if err != nil {
g.t.Error(err)
tLogr.t.Error(err)
return
}
g.errors[re] += n
tLogr.errors[re] += n
}
// EndTest checks if expected errors were not encountered.
func (g *tLogger) EndTest(t *testing.T) {
g.mu.Lock()
defer g.mu.Unlock()
for re, count := range g.errors {
// endTest checks if expected errors were not encountered.
func (tl *tLogger) endTest(t *testing.T) {
tl.mu.Lock()
defer tl.mu.Unlock()
for re, count := range tl.errors {
if count > 0 {
t.Errorf("Expected error '%v' not encountered", re.String())
}
}
g.errors = map[*regexp.Regexp]int{}
tl.errors = map[*regexp.Regexp]int{}
}
// expected determines if the error string is protected or not.
func (g *tLogger) expected(s string) bool {
for re, count := range g.errors {
func (tl *tLogger) expected(s string) bool {
for re, count := range tl.errors {
if re.FindStringIndex(s) != nil {
g.errors[re]--
tl.errors[re]--
if count <= 1 {
delete(g.errors, re)
delete(tl.errors, re)
}
return true
}
@ -194,70 +204,70 @@ func (g *tLogger) expected(s string) bool {
return false
}
func (g *tLogger) Info(args ...any) {
g.log(infoLog, 0, "", args...)
func (tl *tLogger) Info(args ...any) {
tl.log(infoLog, 0, "", args...)
}
func (g *tLogger) Infoln(args ...any) {
g.log(infoLog, 0, "", args...)
func (tl *tLogger) Infoln(args ...any) {
tl.log(infoLog, 0, "", args...)
}
func (g *tLogger) Infof(format string, args ...any) {
g.log(infoLog, 0, format, args...)
func (tl *tLogger) Infof(format string, args ...any) {
tl.log(infoLog, 0, format, args...)
}
func (g *tLogger) InfoDepth(depth int, args ...any) {
g.log(infoLog, depth, "", args...)
func (tl *tLogger) InfoDepth(depth int, args ...any) {
tl.log(infoLog, depth, "", args...)
}
func (g *tLogger) Warning(args ...any) {
g.log(warningLog, 0, "", args...)
func (tl *tLogger) Warning(args ...any) {
tl.log(warningLog, 0, "", args...)
}
func (g *tLogger) Warningln(args ...any) {
g.log(warningLog, 0, "", args...)
func (tl *tLogger) Warningln(args ...any) {
tl.log(warningLog, 0, "", args...)
}
func (g *tLogger) Warningf(format string, args ...any) {
g.log(warningLog, 0, format, args...)
func (tl *tLogger) Warningf(format string, args ...any) {
tl.log(warningLog, 0, format, args...)
}
func (g *tLogger) WarningDepth(depth int, args ...any) {
g.log(warningLog, depth, "", args...)
func (tl *tLogger) WarningDepth(depth int, args ...any) {
tl.log(warningLog, depth, "", args...)
}
func (g *tLogger) Error(args ...any) {
g.log(errorLog, 0, "", args...)
func (tl *tLogger) Error(args ...any) {
tl.log(errorLog, 0, "", args...)
}
func (g *tLogger) Errorln(args ...any) {
g.log(errorLog, 0, "", args...)
func (tl *tLogger) Errorln(args ...any) {
tl.log(errorLog, 0, "", args...)
}
func (g *tLogger) Errorf(format string, args ...any) {
g.log(errorLog, 0, format, args...)
func (tl *tLogger) Errorf(format string, args ...any) {
tl.log(errorLog, 0, format, args...)
}
func (g *tLogger) ErrorDepth(depth int, args ...any) {
g.log(errorLog, depth, "", args...)
func (tl *tLogger) ErrorDepth(depth int, args ...any) {
tl.log(errorLog, depth, "", args...)
}
func (g *tLogger) Fatal(args ...any) {
g.log(fatalLog, 0, "", args...)
func (tl *tLogger) Fatal(args ...any) {
tl.log(fatalLog, 0, "", args...)
}
func (g *tLogger) Fatalln(args ...any) {
g.log(fatalLog, 0, "", args...)
func (tl *tLogger) Fatalln(args ...any) {
tl.log(fatalLog, 0, "", args...)
}
func (g *tLogger) Fatalf(format string, args ...any) {
g.log(fatalLog, 0, format, args...)
func (tl *tLogger) Fatalf(format string, args ...any) {
tl.log(fatalLog, 0, format, args...)
}
func (g *tLogger) FatalDepth(depth int, args ...any) {
g.log(fatalLog, depth, "", args...)
func (tl *tLogger) FatalDepth(depth int, args ...any) {
tl.log(fatalLog, depth, "", args...)
}
func (g *tLogger) V(l int) bool {
return l <= g.v
func (tl *tLogger) V(l int) bool {
return l <= tl.v
}

8
internal/grpctest/tlogger_test.go
View File

@ -66,10 +66,10 @@ func (s) TestWarningDepth(*testing.T) {
func (s) TestError(*testing.T) {
const numErrors = 10
TLogger.ExpectError("Expected error")
TLogger.ExpectError("Expected ln error")
TLogger.ExpectError("Expected formatted error")
TLogger.ExpectErrorN("Expected repeated error", numErrors)
ExpectError("Expected error")
ExpectError("Expected ln error")
ExpectError("Expected formatted error")
ExpectErrorN("Expected repeated error", numErrors)
grpclog.Error("Expected", "error")
grpclog.Errorln("Expected", "ln", "error")
grpclog.Errorf("%v %v %v", "Expected", "formatted", "error")

6
internal/transport/keepalive_test.go
View File

@ -398,7 +398,7 @@ func (s) TestKeepaliveClientStaysHealthyWithResponsiveServer(t *testing.T) {
// explicitly makes sure the fix works and the client sends a ping every [Time]
// period.
func (s) TestKeepaliveClientFrequency(t *testing.T) {
grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
grpctest.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
serverConfig := &ServerConfig{
KeepalivePolicy: keepalive.EnforcementPolicy{
@ -430,7 +430,7 @@ func (s) TestKeepaliveClientFrequency(t *testing.T) {
// (when there are no active streams), based on the configured
// EnforcementPolicy.
func (s) TestKeepaliveServerEnforcementWithAbusiveClientNoRPC(t *testing.T) {
grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
grpctest.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
serverConfig := &ServerConfig{
KeepalivePolicy: keepalive.EnforcementPolicy{
@ -461,7 +461,7 @@ func (s) TestKeepaliveServerEnforcementWithAbusiveClientNoRPC(t *testing.T) {
// (even when there is an active stream), based on the configured
// EnforcementPolicy.
func (s) TestKeepaliveServerEnforcementWithAbusiveClientWithRPC(t *testing.T) {
grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
grpctest.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
serverConfig := &ServerConfig{
KeepalivePolicy: keepalive.EnforcementPolicy{

2
orca/producer_test.go
View File

@ -266,7 +266,7 @@ func (f *fakeORCAService) StreamCoreMetrics(req *v3orcaservicepb.OrcaLoadReportR
// TestProducerBackoff verifies that the ORCA producer applies the proper
// backoff after stream failures.
func (s) TestProducerBackoff(t *testing.T) {
grpctest.TLogger.ExpectErrorN("injected error", 4)
grpctest.ExpectErrorN("injected error", 4)
ctx, cancel := context.WithTimeout(context.Background(), defaultTestTimeout)
defer cancel()

4
test/end2end_test.go
View File

@ -5312,7 +5312,7 @@ func (s) TestStatusInvalidUTF8Message(t *testing.T) {
// will fail to marshal the status because of the invalid utf8 message. Details
// will be dropped when sending.
func (s) TestStatusInvalidUTF8Details(t *testing.T) {
grpctest.TLogger.ExpectError("Failed to marshal rpc status")
grpctest.ExpectError("Failed to marshal rpc status")
var (
origMsg = string([]byte{0xff, 0xfe, 0xfd})
@ -6323,7 +6323,7 @@ func (s) TestServerClosesConn(t *testing.T) {
// TestNilStatsHandler ensures we do not panic as a result of a nil stats
// handler.
func (s) TestNilStatsHandler(t *testing.T) {
grpctest.TLogger.ExpectErrorN("ignoring nil parameter", 2)
grpctest.ExpectErrorN("ignoring nil parameter", 2)
ss := &stubserver.StubServer{
UnaryCallF: func(context.Context, *testpb.SimpleRequest) (*testpb.SimpleResponse, error) {
return &testpb.SimpleResponse{}, nil

2
test/goaway_test.go
View File

@ -121,7 +121,7 @@ func (s) TestDetailedGoAwayErrorOnGracefulClosePropagatesToRPCError(t *testing.T
}
func (s) TestDetailedGoAwayErrorOnAbruptClosePropagatesToRPCError(t *testing.T) {
grpctest.TLogger.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
grpctest.ExpectError("Client received GoAway with error code ENHANCE_YOUR_CALM and debug data equal to ASCII \"too_many_pings\"")
// set the min keepalive time very low so that this test can take
// a reasonable amount of time
prev := internal.KeepaliveMinPingTime

2
test/healthcheck_test.go
View File

@ -254,7 +254,7 @@ func (s) TestHealthCheckWatchStateChange(t *testing.T) {
// If Watch returns Unimplemented, then the ClientConn should go into READY state.
func (s) TestHealthCheckHealthServerNotRegistered(t *testing.T) {
grpctest.TLogger.ExpectError("Subchannel health check is unimplemented at server side, thus health check is disabled")
grpctest.ExpectError("Subchannel health check is unimplemented at server side, thus health check is disabled")
s := grpc.NewServer()
lis, err := net.Listen("tcp", "localhost:0")
if err != nil {

2
test/metadata_test.go
View File

@ -37,7 +37,7 @@ import (
)
func (s) TestInvalidMetadata(t *testing.T) {
grpctest.TLogger.ExpectErrorN("stream: failed to validate md when setting trailer", 5)
grpctest.ExpectErrorN("stream: failed to validate md when setting trailer", 5)
tests := []struct {
name string