xDS server spams mode "switches"

[ejona86]

When trying to debug a (non-Go) problem, I was looking at logs and discovered that Go xDS server is very spammy.

Per A36 xDS for Servers:

If the application does not register the callback, XdsServer should log any errors and each serving resumption after an error, all at a default-visible log level.

Go appears to be broken in multiple ways:

1. The logs occur even if the application provides a callback
2. The logs occur even for transitions from SERVING to SERVING. The only time the default logger should log in SERVING state is if immediately previously there was an error state

grpc-go/xds/internal/server/listener_wrapper.go

Lines 432 to 442 in e469f0d

	func (l *listenerWrapper) switchMode(fcs *xdsclient.FilterChainManager, newMode connectivity.ServingMode, err error) {
	l.mu.Lock()
	defer l.mu.Unlock()
	l.filterChains = fcs
	l.mode = newMode
	if l.modeCallback != nil {
	l.modeCallback(l.Listener.Addr(), newMode, err)
	}
	l.logger.Warningf("Listener %q entering mode: %q due to error: %v", l.Addr(), newMode, err)
	}

This is much more mild, but for a reason that I don't understand, the xds interop test server is providing its own callback. That seems unnecessary given the default behavior. But it will log up to two times per event:

grpc-go/interop/xds/server/server.go

Lines 102 to 107 in b9d7c74

	func xdsServingModeCallback(addr net.Addr, args xds.ServingModeChangeArgs) {
	logger.Infof("Serving mode for xDS server at %s changed to %s", addr.String(), args.Mode)
	if args.Err != nil {
	logger.Infof("ServingModeCallback returned error: %v", args.Err)
	}
	}

It would be more clear as a single log entry.

[ejona86]

I think the logging is even more wrong than I thought. I created a trash bootstrap (td-grpc-bootstrap --gcp-project-number 5) and ran on my local machine without any credentials.

examples/features/xds/server$ ./server
2021/11/30 16:03:34 Serving GreeterService on 0.0.0.0:50051 and HealthService on 0.0.0.0:50052

And nothing more. Minutes later, nothing more. But I know it has to be failing to start the xds server... I'd expect a message at least after 20 seconds of inability to get listener resource. In this case I'd hope it wouldn't even be delayed 20 seconds. It hasn't bound yet to the xds server port:

$ ss -ltn | grep 5005
LISTEN 0      4096         0.0.0.0:50052       0.0.0.0:*          

Running with GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info shows me the errors I expected are actually happening.

2021/11/30 15:56:26 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:56:27 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:56:30 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:56:33 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:56:40 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:56:50 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:57:10 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled
2021/11/30 15:57:36 WARNING: xds: ADS stream creation failed: rpc error: code = Unauthenticated desc = transport: context canceled

[ejona86]

#5215 (comment)

I still see no warnings by default when unable to connect.

I notice now I also don't see any useful errors (even with GRPC_GO_LOG_VERBOSITY_LEVEL=99 GRPC_GO_LOG_SEVERITY_LEVEL=info) with garbage like GRPC_XDS_BOOTSTRAP=/not/exist.