feat(transport): Log DirectPath misconfiguration (#2225)

We met issues where customers wanted to use DirectPath, but DirectPath was misconfigured and it took 2 weeks for debugging. So we want to add WARNING logs if DirectPath flag/option is set but DirectPath is not used. Issue: https://github.com/googleapis/sdk-platform-java/issues/2164.

Java PR: https://github.com/googleapis/sdk-platform-java/pull/2105.

Note that the log is added when a channel is created because we need to check the OAuth token, which means it will be logged every channel. This is a bad behavior if customer has a large channel pool size. Ideally I want to use something like LOG_EVERY_N_SEC, and I found `rate.Sometimes` can do this. Cody, do you have suggestions here?

@codyoss @frankyn

Author: mohanli-ml

go.mod

@@ -26,6 +26,7 @@ require (
 	golang.org/x/crypto v0.14.0 // indirect
 	golang.org/x/sys v0.13.0 // indirect
 	golang.org/x/text v0.13.0 // indirect
+	golang.org/x/time v0.3.0 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
 	google.golang.org/genproto v0.0.0-20231016165738-49dd2c1f3d0b // indirect
 	google.golang.org/genproto/googleapis/api v0.0.0-20231016165738-49dd2c1f3d0b // indirect

go.sum

@@ -95,6 +95,8 @@ golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk=
 golang.org/x/text v0.3.3/go.mod h1:5Zoc/QRtKVWzQhOtBMvqHzDpF6irO9z98xDceosuGiQ=
 golang.org/x/text v0.13.0 h1:ablQoSUd0tRdKxZewP80B+BaqeKJuVhuRxj/dkrun3k=
 golang.org/x/text v0.13.0/go.mod h1:TvPlkZtksWOMsz7fbANvkp4WM8x/WCo/om8BMLbz+aE=
+golang.org/x/time v0.3.0 h1:rg5rLMjNzMS1RkNLzCG38eapWhnYLFYXDXj2gOlr8j4=
+golang.org/x/time v0.3.0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20190114222345-bf090417da8b/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20190226205152-f727befe758c/go.mod h1:9Yl7xja0Znq3iFh3HoIrodX9oNMXvdceNzlUR8zjMvY=

transport/grpc/dial.go

@@ -14,10 +14,12 @@ import (
 	"net"
 	"os"
 	"strings"
+	"time"
 
 	"cloud.google.com/go/compute/metadata"
 	"go.opencensus.io/plugin/ocgrpc"
 	"golang.org/x/oauth2"
+	"golang.org/x/time/rate"
 	"google.golang.org/api/internal"
 	"google.golang.org/api/option"
 	"google.golang.org/grpc"
@@ -38,6 +40,9 @@ const enableDirectPathXds = "GOOGLE_CLOUD_ENABLE_DIRECT_PATH_XDS"
 // Set at init time by dial_socketopt.go. If nil, socketopt is not supported.
 var timeoutDialerOption grpc.DialOption
 
+// Log rate limiter
+var logRateLimiter = rate.Sometimes{Interval: 1 * time.Second}
+
 // Dial returns a GRPC connection for use communicating with a Google cloud
 // service, configured with the given ClientOptions.
 func Dial(ctx context.Context, opts ...option.ClientOption) (*grpc.ClientConn, error) {
@@ -153,6 +158,9 @@ func dial(ctx context.Context, insecure bool, o *internal.DialSettings) (*grpc.C
 		)
 
 		// Attempt Direct Path:
+		logRateLimiter.Do(func() {
+			logDirectPathMisconfig(endpoint, creds.TokenSource, o)
+		})
 		if isDirectPathEnabled(endpoint, o) && isTokenSourceDirectPathCompatible(creds.TokenSource, o) && metadata.OnGCE() {
 			// Overwrite all of the previously specific DialOptions, DirectPath uses its own set of credentials and certificates.
 			grpcOpts = []grpc.DialOption{
@@ -296,6 +304,24 @@ func checkDirectPathEndPoint(endpoint string) bool {
 	return true
 }
 
+func logDirectPathMisconfig(endpoint string, ts oauth2.TokenSource, o *internal.DialSettings) {
+	if isDirectPathXdsUsed(o) {
+		// Case 1: does not enable DirectPath
+		if !isDirectPathEnabled(endpoint, o) {
+			log.Println("WARNING: DirectPath is misconfigured. Please set the EnableDirectPath option along with the EnableDirectPathXds option.")
+		} else {
+			// Case 2: credential is not correctly set
+			if !isTokenSourceDirectPathCompatible(ts, o) {
+				log.Println("WARNING: DirectPath is misconfigured. Please make sure the token source is fetched from GCE metadata server and the default service account is used.")
+			}
+			// Case 3: not running on GCE
+			if !metadata.OnGCE() {
+				log.Println("WARNING: DirectPath is misconfigured. DirectPath is only available in a GCE environment.")
+			}
+		}
+	}
+}
+
 func processAndValidateOpts(opts []option.ClientOption) (*internal.DialSettings, error) {
 	var o internal.DialSettings
 	for _, opt := range opts {

transport/grpc/dial_test.go

@@ -5,7 +5,15 @@
 package grpc
 
 import (
+	"bytes"
+	"context"
+	"log"
+	"strings"
 	"testing"
+
+	"cloud.google.com/go/compute/metadata"
+	"golang.org/x/oauth2/google"
+	"google.golang.org/api/internal"
 )
 
 func TestCheckDirectPathEndPoint(t *testing.T) {
@@ -47,3 +55,73 @@ func TestCheckDirectPathEndPoint(t *testing.T) {
 		})
 	}
 }
+
+func TestLogDirectPathMisconfigAttrempDirectPathNotSet(t *testing.T) {
+	o := &internal.DialSettings{}
+	o.EnableDirectPathXds = true
+
+	endpoint := "abc.googleapis.com"
+
+	creds, err := internal.Creds(context.Context(context.Background()), o)
+	if err != nil {
+		t.Fatalf("failed to create creds")
+	}
+
+	buf := bytes.Buffer{}
+	log.SetOutput(&buf)
+
+	logDirectPathMisconfig(endpoint, creds.TokenSource, o)
+
+	wantedLog := "WARNING: DirectPath is misconfigured. Please set the EnableDirectPath option along with the EnableDirectPathXds option."
+	if !strings.Contains(buf.String(), wantedLog) {
+		t.Fatalf("got: %v, want: %v", buf.String(), wantedLog)
+	}
+
+}
+
+func TestLogDirectPathMisconfigWrongCredential(t *testing.T) {
+	o := &internal.DialSettings{}
+	o.EnableDirectPath = true
+	o.EnableDirectPathXds = true
+
+	endpoint := "abc.googleapis.com"
+
+	creds := &google.Credentials{}
+
+	buf := bytes.Buffer{}
+	log.SetOutput(&buf)
+
+	logDirectPathMisconfig(endpoint, creds.TokenSource, o)
+
+	wantedLog := "WARNING: DirectPath is misconfigured. Please make sure the token source is fetched from GCE metadata server and the default service account is used."
+	if !strings.Contains(buf.String(), wantedLog) {
+		t.Fatalf("got: %v, want: %v", buf.String(), wantedLog)
+	}
+
+}
+
+func TestLogDirectPathMisconfigNotOnGCE(t *testing.T) {
+	o := &internal.DialSettings{}
+	o.EnableDirectPath = true
+	o.EnableDirectPathXds = true
+
+	endpoint := "abc.googleapis.com"
+
+	creds, err := internal.Creds(context.Context(context.Background()), o)
+	if err != nil {
+		t.Fatalf("failed to create creds")
+	}
+
+	buf := bytes.Buffer{}
+	log.SetOutput(&buf)
+
+	logDirectPathMisconfig(endpoint, creds.TokenSource, o)
+
+	if !metadata.OnGCE() {
+		wantedLog := "WARNING: DirectPath is misconfigured. DirectPath is only available in a GCE environment.."
+		if !strings.Contains(buf.String(), wantedLog) {
+			t.Fatalf("got: %v, want: %v", buf.String(), wantedLog)
+		}
+	}
+
+}