Add a logger to log the calls to the Identity Provider

internal/authz/oidc.go

@@ -70,7 +70,7 @@ type oidcHandler struct {
 func NewOIDCHandler(cfg *oidcv1.OIDCConfig, tlsPool internal.TLSConfigPool, jwks oidc.JWKSProvider,
 	sessions oidc.SessionStoreFactory, clock oidc.Clock, sessionGen oidc.SessionGenerator) (Handler, error) {
 
-	client, err := getHTTPClient(cfg, tlsPool)
+	client, err := inthttp.NewHTTPClient(cfg, tlsPool, internal.Logger(internal.IDP))
 	if err != nil {
 		return nil, err
 	}
@@ -91,23 +91,6 @@ func NewOIDCHandler(cfg *oidcv1.OIDCConfig, tlsPool internal.TLSConfigPool, jwks
 	}, nil
 }
 
-func getHTTPClient(cfg *oidcv1.OIDCConfig, tlsPool internal.TLSConfigPool) (*http.Client, error) {
-	transport := http.DefaultTransport.(*http.Transport).Clone()
-
-	var err error
-	if transport.TLSClientConfig, err = tlsPool.LoadTLSConfig(cfg); err != nil {
-		return nil, err
-	}
-
-	if cfg.ProxyUri != "" {
-		// config validation ensures that the proxy uri is valid
-		proxyURL, _ := url.Parse(cfg.ProxyUri)
-		transport.Proxy = http.ProxyURL(proxyURL)
-	}
-
-	return &http.Client{Transport: transport}, nil
-}
-
 // Process a CheckRequest and populate a CheckResponse according to the mockHandler configuration.
 func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp *envoy.CheckResponse) error {
 	log := o.log.Context(ctx)
@@ -143,7 +126,8 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 				return nil
 			}
 		}
-		log.Info("logout complete. Redirecting to logout redirect uri")
+		log.Info("logout complete. Redirecting to logout redirect uri",
+			"uri", o.config.GetLogout().GetRedirectUri())
 		deny := newDenyResponse()
 		// add IDP logout location
 		setRedirect(deny, o.config.GetLogout().GetRedirectUri())
@@ -156,7 +140,7 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 	// If the request does not have a session_id cookie,
 	// then generate a session id, put it in a header, and redirect for login.
 	if sessionID == "" {
-		log.Info("no session cookie detected. Generating new session and sending user to re-authenticate.")
+		log.Info("no session cookie detected. Generating new session and sending user to re-authenticate")
 		o.redirectToIDP(ctx, log, resp, req.GetAttributes().GetRequest().GetHttp(), "")
 		return nil
 	}
@@ -185,22 +169,22 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 	// If the user has a session_id cookie but there are no required tokens in the
 	// session store associated with it, then redirect for login.
 	if tokenResponse == nil {
-		log.Info("required tokens are not present. Sending user to re-authenticate.")
+		log.Info("required tokens are not present. Sending user to re-authenticate")
 		o.redirectToIDP(ctx, log, resp, req.GetAttributes().GetRequest().GetHttp(), sessionID)
 		return nil
 	}
 
 	// If both ID & Access token are still unexpired,
 	// then allow the request to proceed (no need to intervene).
 	log.Debug("checking tokens expiration")
-	expired, err := o.areRequiredTokensExpired(tokenResponse)
+	expired, err := o.areRequiredTokensExpired(log, tokenResponse)
 	if err != nil {
 		log.Error("error checking token expiration", err)
 		setDenyResponse(resp, newDenyResponse(), codes.Internal)
 		return nil
 	}
 	if !expired {
-		log.Info("tokens not expired. Allowing request to proceed.")
+		log.Info("tokens not expired. Allowing request to proceed")
 		o.allowResponse(resp, tokenResponse)
 		return nil
 	}
@@ -210,7 +194,7 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 	// If there is no refresh token,
 	// then direct the request to the identity provider for authentication
 	if tokenResponse.RefreshToken == "" {
-		log.Info("a token was expired, but session did not contain a refresh token. Sending user to re-authenticate.")
+		log.Info("a token was expired, but session did not contain a refresh token. Sending user to re-authenticate")
 		o.redirectToIDP(ctx, log, resp, req.GetAttributes().GetRequest().GetHttp(), sessionID)
 		return nil
 	}
@@ -221,7 +205,7 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 	log.Debug("attempting token refresh")
 	refreshedTokens := o.refreshToken(ctx, log, tokenResponse, tokenResponse.RefreshToken, sessionID)
 	if refreshedTokens == nil {
-		log.Info("token refresh failed. Sending user to re-authenticate.")
+		log.Info("token refresh failed. Sending user to re-authenticate")
 		o.redirectToIDP(ctx, log, resp, req.GetAttributes().GetRequest().GetHttp(), sessionID)
 		return nil
 	}
@@ -231,7 +215,7 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 		return nil
 	}
 
-	log.Info("token refresh successful. Allowing request to proceed.")
+	log.Info("token refresh successful. Allowing request to proceed")
 	o.allowResponse(resp, refreshedTokens)
 	return nil
 }
@@ -327,7 +311,7 @@ func (o *oidcHandler) retrieveTokens(ctx context.Context, log telemetry.Logger,
 	}
 
 	if stateFromStore == nil {
-		log.Info("missing state, nonce, and original url requested by user in the store. Cannot redirect.")
+		log.Info("missing state, nonce, and original url requested by user in the store. Cannot redirect")
 		deny := newDenyResponse()
 		deny.Body = "Oops, your session has expired. Please try again."
 		deny.Status = &typev3.HttpStatus{Code: typev3.StatusCode_BadRequest}
@@ -760,17 +744,24 @@ func encodeHeaderValue(preamble string, value string) string {
 }
 
 // areRequiredTokensExpired checks if the required tokens are expired.
-func (o *oidcHandler) areRequiredTokensExpired(tokens *oidc.TokenResponse) (bool, error) {
+func (o *oidcHandler) areRequiredTokensExpired(log telemetry.Logger, tokens *oidc.TokenResponse) (bool, error) {
 	idToken, err := tokens.ParseIDToken()
 	if err != nil {
 		return false, fmt.Errorf("parsing id token: %w", err)
 	}
 
-	if idToken.Expiration().Before(o.clock.Now()) {
+	now := o.clock.Now()
+	if idToken.Expiration().Before(now) {
+		log.Info("id token is expired", "exp", idToken.Expiration(), "expired_for", now.Sub(idToken.Expiration()))
 		return true, nil
 	}
-	if o.config.GetAccessToken() != nil && tokens.AccessToken != "" && !tokens.AccessTokenExpiresAt.IsZero() {
-		return tokens.AccessTokenExpiresAt.Before(o.clock.Now()), nil
+	if o.config.GetAccessToken() != nil &&
+		tokens.AccessToken != "" &&
+		!tokens.AccessTokenExpiresAt.IsZero() &&
+		tokens.AccessTokenExpiresAt.Before(now) {
+		log.Info("access token is expired", "exp", tokens.AccessTokenExpiresAt,
+			"expired_for", now.Sub(tokens.AccessTokenExpiresAt))
+		return true, nil
 	}
 	return false, nil
 }

internal/authz/oidc_test.go

@@ -1370,7 +1370,7 @@ func TestAreTokensExpired(t *testing.T) {
 				tokResp.AccessTokenExpiresAt = tt.accessTokenExpiration
 			}
 
-			got, err := h.(*oidcHandler).areRequiredTokensExpired(tokResp)
+			got, err := h.(*oidcHandler).areRequiredTokensExpired(h.(*oidcHandler).log, tokResp)
 			require.NoError(t, err)
 			require.Equal(t, tt.want, got)
 		})

internal/http/http.go

@@ -16,7 +16,14 @@ package http
 
 import (
 	"encoding/base64"
+	"net/http"
+	"net/url"
 	"strings"
+
+	"github.com/tetratelabs/telemetry"
+
+	oidcv1 "github.com/istio-ecosystem/authservice/config/gen/go/v1/oidc"
+	"github.com/istio-ecosystem/authservice/internal"
 )
 
 // GetPathQueryFragment splits the given path into path, query, and fragment.
@@ -80,6 +87,36 @@ func EncodeCookieHeader(name string, value string, directives []string) string {
 	return b.String()
 }
 
+// BasicAuthHeader returns the value of the Authorization header for the given id and secret.
 func BasicAuthHeader(id string, secret string) string {
 	return "Basic " + base64.StdEncoding.EncodeToString([]byte(id+":"+secret))
 }
+
+// NewHTTPClient creates a new HTTP client with the given OIDC configuration and TLS pool.
+// If a logger is provided, it will log the requests and responses at debug level.
+func NewHTTPClient(cfg *oidcv1.OIDCConfig, tlsPool internal.TLSConfigPool, log telemetry.Logger) (*http.Client, error) {
+	transport := http.DefaultTransport.(*http.Transport).Clone()
+
+	var err error
+	if transport.TLSClientConfig, err = tlsPool.LoadTLSConfig(cfg); err != nil {
+		return nil, err
+	}
+
+	if cfg.ProxyUri != "" {
+		// config validation ensures that the proxy uri is valid
+		proxyURL, _ := url.Parse(cfg.ProxyUri)
+		transport.Proxy = http.ProxyURL(proxyURL)
+	}
+
+	if log != nil && log.Level() >= telemetry.LevelDebug {
+		return &http.Client{
+			Transport: &LoggingRoundTripper{
+				Log:      log,
+				Delegate: transport,
+			},
+		}, nil
+
+	}
+
+	return &http.Client{Transport: transport}, nil
+}

internal/http/http_test.go

@@ -15,10 +15,17 @@
 package http
 
 import (
+	"context"
 	"encoding/base64"
+	"net/http"
 	"testing"
 
 	"github.com/stretchr/testify/require"
+	"github.com/tetratelabs/telemetry"
+	"google.golang.org/protobuf/types/known/structpb"
+
+	oidcv1 "github.com/istio-ecosystem/authservice/config/gen/go/v1/oidc"
+	"github.com/istio-ecosystem/authservice/internal"
 )
 
 func TestGetPathQueryFragment(t *testing.T) {
@@ -132,3 +139,53 @@ func TestBasicAuthHeader(t *testing.T) {
 		})
 	}
 }
+
+func TestNewHTTPClient(t *testing.T) {
+	t.Run("proxy-skip-verify", func(t *testing.T) {
+		cfg := &oidcv1.OIDCConfig{
+			ProxyUri:           "http://localhost:8080",
+			SkipVerifyPeerCert: &structpb.Value{Kind: &structpb.Value_BoolValue{BoolValue: true}},
+		}
+		pool := internal.NewTLSConfigPool(context.Background())
+
+		client, err := NewHTTPClient(cfg, pool, nil)
+		require.NoError(t, err)
+		require.IsType(t, &http.Transport{}, client.Transport)
+		require.NotNil(t, client.Transport.(*http.Transport).Proxy)
+		require.True(t, client.Transport.(*http.Transport).TLSClientConfig.InsecureSkipVerify)
+	})
+
+	t.Run("invalid-tls", func(t *testing.T) {
+		cfg := &oidcv1.OIDCConfig{
+			TrustedCaConfig: &oidcv1.OIDCConfig_TrustedCertificateAuthorityFile{
+				TrustedCertificateAuthorityFile: "unexisting",
+			},
+		}
+		pool := internal.NewTLSConfigPool(context.Background())
+
+		_, err := NewHTTPClient(cfg, pool, nil)
+		require.Error(t, err)
+	})
+
+	t.Run("disabled-logger", func(t *testing.T) {
+		cfg := &oidcv1.OIDCConfig{}
+		pool := internal.NewTLSConfigPool(context.Background())
+		log := telemetry.NoopLogger()
+		log.SetLevel(telemetry.LevelInfo)
+
+		client, err := NewHTTPClient(cfg, pool, log)
+		require.NoError(t, err)
+		require.IsType(t, &http.Transport{}, client.Transport)
+	})
+
+	t.Run("enabled-logger", func(t *testing.T) {
+		cfg := &oidcv1.OIDCConfig{}
+		pool := internal.NewTLSConfigPool(context.Background())
+		log := telemetry.NoopLogger()
+		log.SetLevel(telemetry.LevelDebug)
+
+		client, err := NewHTTPClient(cfg, pool, log)
+		require.NoError(t, err)
+		require.IsType(t, &LoggingRoundTripper{}, client.Transport)
+	})
+}

internal/http/logging.go

@@ -0,0 +1,51 @@
+// Copyright 2024 Tetrate
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//     http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+// Copyright (c) Tetrate, Inc 2024 All Rights Reserved.
+
+package http
+
+import (
+	"net/http"
+	"net/http/httputil"
+
+	"github.com/tetratelabs/telemetry"
+)
+
+// LoggingRoundTripper is a http.RoundTripper that logs requests and responses.
+type LoggingRoundTripper struct {
+	Log      telemetry.Logger
+	Delegate http.RoundTripper
+}
+
+// RoundTrip logs all the requests and responses using the configured settings.
+func (l LoggingRoundTripper) RoundTrip(req *http.Request) (*http.Response, error) {
+	if l.Log.Level() < telemetry.LevelDebug {
+		return l.Delegate.RoundTrip(req)
+	}
+
+	if dump, derr := httputil.DumpRequest(req, true); derr == nil {
+		l.Log.Debug("request", "data", string(dump))
+	}
+
+	res, err := l.Delegate.RoundTrip(req)
+
+	if err == nil {
+		if dump, derr := httputil.DumpResponse(res, true); derr == nil {
+			l.Log.Debug("response", "data", string(dump))
+		}
+	}
+
+	return res, err
+}