directory: add logging http client to help with debugging outbound http requests (#2385)

internal/databroker/server.go

@@ -226,7 +226,7 @@ func (srv *Server) ReleaseLease(ctx context.Context, req *databroker.ReleaseLeas
 func (srv *Server) RenewLease(ctx context.Context, req *databroker.RenewLeaseRequest) (*emptypb.Empty, error) {
 	_, span := trace.StartSpan(ctx, "databroker.grpc.RenewLease")
 	defer span.End()
-	log.Info(ctx).
+	log.Debug(ctx).
 		Str("peer", grpcutil.GetPeerAddr(ctx)).
 		Str("name", req.GetName()).
 		Str("id", req.GetId()).

internal/directory/azure/azure.go

@@ -12,8 +12,10 @@ import (
 	"strings"
 	"sync"
 
+	"github.com/rs/zerolog"
 	"golang.org/x/oauth2"
 
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/pkg/grpc/directory"
 )
 
@@ -55,7 +57,10 @@ func WithLoginURL(loginURL *url.URL) Option {
 // WithHTTPClient sets the http client to use for requests to the Azure APIs.
 func WithHTTPClient(httpClient *http.Client) Option {
 	return func(cfg *config) {
-		cfg.httpClient = httpClient
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "azure")
+			})
 	}
 }
 

internal/directory/github/github.go

@@ -16,6 +16,7 @@ import (
 	"github.com/rs/zerolog"
 	"github.com/tomnomnom/linkheader"
 
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/pkg/grpc/directory"
 )
@@ -47,7 +48,10 @@ func WithServiceAccount(serviceAccount *ServiceAccount) Option {
 // WithHTTPClient sets the http client option.
 func WithHTTPClient(httpClient *http.Client) Option {
 	return func(cfg *config) {
-		cfg.httpClient = httpClient
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "github")
+			})
 	}
 }
 

internal/directory/gitlab/gitlab.go

@@ -14,6 +14,7 @@ import (
 	"github.com/rs/zerolog"
 	"github.com/tomnomnom/linkheader"
 
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/pkg/grpc/directory"
 )
@@ -45,7 +46,10 @@ func WithServiceAccount(serviceAccount *ServiceAccount) Option {
 // WithHTTPClient sets the http client option.
 func WithHTTPClient(httpClient *http.Client) Option {
 	return func(cfg *config) {
-		cfg.httpClient = httpClient
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "azure")
+			})
 	}
 }
 

internal/directory/google/google.go

@@ -17,6 +17,7 @@ import (
 	"google.golang.org/api/googleapi"
 	"google.golang.org/api/option"
 
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/pkg/grpc/directory"
 )
@@ -33,6 +34,7 @@ const (
 )
 
 type config struct {
+	httpClient     *http.Client
 	serviceAccount *ServiceAccount
 	url            string
 }
@@ -40,6 +42,16 @@ type config struct {
 // An Option changes the configuration for the Google directory provider.
 type Option func(cfg *config)
 
+// WithHTTPClient sets the http client option.
+func WithHTTPClient(httpClient *http.Client) Option {
+	return func(cfg *config) {
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "google")
+			})
+	}
+}
+
 // WithServiceAccount sets the service account in the Google configuration.
 func WithServiceAccount(serviceAccount *ServiceAccount) Option {
 	return func(cfg *config) {
@@ -56,6 +68,7 @@ func WithURL(url string) Option {
 
 func getConfig(options ...Option) *config {
 	cfg := new(config)
+	WithHTTPClient(http.DefaultClient)(cfg)
 	WithURL(defaultProviderURL)(cfg)
 	for _, option := range options {
 		option(cfg)
@@ -241,7 +254,10 @@ func (p *Provider) getAPIClient(ctx context.Context) (*admin.Service, error) {
 
 	ts := config.TokenSource(ctx)
 
-	p.apiClient, err = admin.NewService(ctx, option.WithTokenSource(ts), option.WithEndpoint(p.cfg.url))
+	p.apiClient, err = admin.NewService(ctx,
+		option.WithTokenSource(ts),
+		option.WithEndpoint(p.cfg.url),
+		option.WithHTTPClient(p.cfg.httpClient))
 	if err != nil {
 		return nil, fmt.Errorf("google: failed creating admin service %w", err)
 	}

internal/directory/okta/okta.go

@@ -18,6 +18,7 @@ import (
 	"github.com/rs/zerolog"
 	"github.com/tomnomnom/linkheader"
 
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/pkg/grpc/directory"
 )
@@ -61,7 +62,10 @@ func WithBatchSize(batchSize int) Option {
 // WithHTTPClient sets the http client option.
 func WithHTTPClient(httpClient *http.Client) Option {
 	return func(cfg *config) {
-		cfg.httpClient = httpClient
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "okta")
+			})
 	}
 }
 

internal/directory/onelogin/onelogin.go

@@ -16,6 +16,7 @@ import (
 	"github.com/rs/zerolog"
 	"golang.org/x/oauth2"
 
+	"github.com/pomerium/pomerium/internal/httputil"
 	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/pkg/grpc/directory"
 )
@@ -43,7 +44,10 @@ func WithBatchSize(batchSize int) Option {
 // WithHTTPClient sets the http client option.
 func WithHTTPClient(httpClient *http.Client) Option {
 	return func(cfg *config) {
-		cfg.httpClient = httpClient
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "onelogin")
+			})
 	}
 }
 

internal/directory/ping/config.go

@@ -6,7 +6,10 @@ import (
 	"net/url"
 	"strings"
 
+	"github.com/rs/zerolog"
+
 	"github.com/pomerium/pomerium/internal/encoding"
+	"github.com/pomerium/pomerium/internal/httputil"
 )
 
 type config struct {
@@ -44,7 +47,10 @@ func WithEnvironmentID(environmentID string) Option {
 // WithHTTPClient sets the http client option.
 func WithHTTPClient(httpClient *http.Client) Option {
 	return func(cfg *config) {
-		cfg.httpClient = httpClient
+		cfg.httpClient = httputil.NewLoggingClient(httpClient,
+			func(evt *zerolog.Event) *zerolog.Event {
+				return evt.Str("provider", "ping")
+			})
 	}
 }
 

internal/httputil/client.go

@@ -12,14 +12,61 @@ import (
 	"net/url"
 	"time"
 
+	"github.com/rs/zerolog"
+
+	"github.com/pomerium/pomerium/internal/log"
 	"github.com/pomerium/pomerium/internal/telemetry/metrics"
 	"github.com/pomerium/pomerium/internal/telemetry/requestid"
 	"github.com/pomerium/pomerium/internal/tripper"
 )
 
-// ErrTokenRevoked signifies a token revokation or expiration error
+// ErrTokenRevoked signifies a token revocation or expiration error
 var ErrTokenRevoked = errors.New("token expired or revoked")
 
+type loggingRoundTripper struct {
+	base      http.RoundTripper
+	customize []func(event *zerolog.Event) *zerolog.Event
+}
+
+func (l loggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
+	start := time.Now()
+	res, err := l.base.RoundTrip(req)
+	statusCode := http.StatusInternalServerError
+	if res != nil {
+		statusCode = res.StatusCode
+	}
+	evt := log.Debug(req.Context()).
+		Str("method", req.Method).
+		Str("authority", req.URL.Host).
+		Str("path", req.URL.Path).
+		Dur("duration", time.Since(start)).
+		Int("response-code", statusCode)
+	for _, f := range l.customize {
+		f(evt)
+	}
+	evt.Msg("outbound http-request")
+	return res, err
+}
+
+// NewLoggingRoundTripper creates a http.RoundTripper that will log requests.
+func NewLoggingRoundTripper(base http.RoundTripper, customize ...func(event *zerolog.Event) *zerolog.Event) http.RoundTripper {
+	if base == nil {
+		base = http.DefaultTransport
+	}
+	return loggingRoundTripper{base: base, customize: customize}
+}
+
+// NewLoggingClient creates a new http.Client that will log requests.
+func NewLoggingClient(base *http.Client, customize ...func(event *zerolog.Event) *zerolog.Event) *http.Client {
+	if base == nil {
+		base = http.DefaultClient
+	}
+	newClient := new(http.Client)
+	*newClient = *base
+	newClient.Transport = NewLoggingRoundTripper(newClient.Transport, customize...)
+	return newClient
+}
+
 type httpClient struct {
 	*http.Client
 	requestIDTripper http.RoundTripper
@@ -33,14 +80,14 @@ func (c *httpClient) Do(req *http.Request) (*http.Response, error) {
 	return c.Client.Do(req)
 }
 
-// DefaultClient avoids leaks by setting an upper limit for timeouts.
+// defaultClient avoids leaks by setting an upper limit for timeouts.
-var DefaultClient = &httpClient{
+var defaultClient = &httpClient{
 	&http.Client{Timeout: 1 * time.Minute},
 	requestid.NewRoundTripper(http.DefaultTransport),
 }
 
-// Client provides a simple helper interface to make HTTP requests
+// Do provides a simple helper interface to make HTTP requests
-func Client(ctx context.Context, method, endpoint, userAgent string, headers map[string]string, params url.Values, response interface{}) error {
+func Do(ctx context.Context, method, endpoint, userAgent string, headers map[string]string, params url.Values, response interface{}) error {
 	var body io.Reader
 	switch method {
 	case http.MethodPost:
@@ -66,7 +113,7 @@ func Client(ctx context.Context, method, endpoint, userAgent string, headers map
 		req.Header.Set(k, v)
 	}
 
-	resp, err := DefaultClient.Do(req)
+	resp, err := defaultClient.Do(req)
 	if err != nil {
 		return err
 	}

internal/httputil/client_test.go

@@ -21,5 +21,5 @@ func TestDefaultClient(t *testing.T) {
 	defer ts.Close()
 	req, _ := http.NewRequest(http.MethodGet, ts.URL, nil)
 	req = req.WithContext(requestid.WithValue(context.Background(), "foo"))
-	_, _ = DefaultClient.Do(req)
+	_, _ = defaultClient.Do(req)
 }

internal/identity/oauth/github/github.go

@@ -134,7 +134,7 @@ func (p *Provider) userEmail(ctx context.Context, t *oauth2.Token, v interface{}
 	}
 	headers := map[string]string{"Authorization": fmt.Sprintf("token %s", t.AccessToken)}
 	emailURL := githubAPIURL + emailPath
-	err := httputil.Client(ctx, http.MethodGet, emailURL, version.UserAgent(), headers, nil, &response)
+	err := httputil.Do(ctx, http.MethodGet, emailURL, version.UserAgent(), headers, nil, &response)
 	if err != nil {
 		return err
 	}
@@ -169,7 +169,7 @@ func (p *Provider) userInfo(ctx context.Context, t *oauth2.Token, v interface{})
 		"Authorization": fmt.Sprintf("token %s", t.AccessToken),
 		"Accept":        "application/vnd.github.v3+json",
 	}
-	err := httputil.Client(ctx, http.MethodGet, p.userEndpoint, version.UserAgent(), headers, nil, &response)
+	err := httputil.Do(ctx, http.MethodGet, p.userEndpoint, version.UserAgent(), headers, nil, &response)
 	if err != nil {
 		return err
 	}

internal/identity/oidc/oidc.go

@@ -251,7 +251,7 @@ func (p *Provider) Revoke(ctx context.Context, t *oauth2.Token) error {
 	params.Add("client_id", oa.ClientID)
 	params.Add("client_secret", oa.ClientSecret)
 
-	err = httputil.Client(ctx, http.MethodPost, p.RevocationURL, version.UserAgent(), nil, params, nil)
+	err = httputil.Do(ctx, http.MethodPost, p.RevocationURL, version.UserAgent(), nil, params, nil)
 	if err != nil && errors.Is(err, httputil.ErrTokenRevoked) {
 		return fmt.Errorf("internal/oidc: unexpected revoke error: %w", err)
 	}

pkg/grpc/databroker/leaser.go

@@ -97,7 +97,7 @@ func (locker *Leaser) runOnce(ctx context.Context, resetBackoff func()) error {
 	resetBackoff()
 	leaseID := res.Id
 
-	log.Info(ctx).
+	log.Debug(ctx).
 		Str("lease_name", locker.leaseName).
 		Str("lease_id", leaseID).
 		Msg("leaser: lease acquired")
@@ -136,7 +136,7 @@ func (locker *Leaser) withLease(ctx context.Context, leaseID string) error {
 				Duration: durationpb.New(locker.ttl),
 			})
 			if status.Code(err) == codes.AlreadyExists {
-				log.Info(ctx).
+				log.Debug(ctx).
 					Str("lease_name", locker.leaseName).
 					Str("lease_id", leaseID).
 					Msg("leaser: lease lost")