Repository: istio-ecosystem/authservice
Pull request #250 (2024-04-17 09:39:46)

Add a logger to log the calls to the Identity Provider
This adds the `idp` logger that will log all the calls made to the Identity Provider such as the token endpoint calls. It also adds more information to some of the existing loggers. Currently, there are no means to see what requests are being made as part of the OIDC flow, and troubleshooting the responses from the IdP was challenging. This logger will facilitate better understand the flow.

It is important to note that the `idp` logger may expose sensitive information in the logs, such as the `client_secret` or the tokens being issued. Use with care and do not enable it by default. To make it easier to set default log levels and just override some, I've changed a bit the behavior of the logging settings, to allow things like: `all:debug,idp:none`. Previously, if the `all` logger was set, all the other log levels were ignored. Now, if the `all` logger is present, it will be used as the default, then individual loggers will be configured on top.



istio-testing: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/istio-ecosystem/authservice/pull/250#" title="Author self-approved">nacx</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=istio-ecosystem%2Fauthservice).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/istio-ecosystem/authservice/blob/main/OWNERS)~~ [nacx]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->
nacx: Not really. [default](https://github.com/istio-ecosystem/authservice/blob/main/internal/logging.go#L33) is an actual logging scope, that is used when no other loggers are configured. It could be misleading, yes... We could consider removing that logger to make this more understandable? But probably in another PR
sergicastro: Ok, let's keep track of the default keyword in a separate PR.
istio-testing: [APPROVALNOTIFIER] This PR is **APPROVED**

This pull-request has been approved by: *<a href="https://github.com/istio-ecosystem/authservice/pull/250#" title="Author self-approved">nacx</a>*, *<a href="https://github.com/istio-ecosystem/authservice/pull/250#pullrequestreview-2006092958" title="Approved">sergicastro</a>*

The full list of commands accepted by this bot can be found [here](https://go.k8s.io/bot-commands?repo=istio-ecosystem%2Fauthservice).

The pull request process is described [here](https://git.k8s.io/community/contributors/guide/owners.md#the-code-review-process)

<details >
Needs approval from an approver in each of these files:

- ~~[OWNERS](https://github.com/istio-ecosystem/authservice/blob/main/OWNERS)~~ [nacx]

Approvers can indicate their approval by writing `/approve` in a comment
Approvers can cancel approval by writing `/approve cancel` in a comment
</details>
<!-- META={"approvers":[]} -->

Patch:
diff --git a/internal/authz/oidc.go b/internal/authz/oidc.go
index b27f560..d77ba90 100644
--- a/internal/authz/oidc.go
+++ b/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,7 +169,7 @@ 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
 	}
@@ -193,14 +177,14 @@ func (o *oidcHandler) Process(ctx context.Context, req *envoy.CheckRequest, resp
 	// 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
 }
diff --git a/internal/http/http.go b/internal/http/http.go
index 647b404..fbec176 100644
--- a/internal/http/http.go
+++ b/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
+}
diff --git a/internal/http/logging.go b/internal/http/logging.go
new file mode 100644
index 0000000..aceaa4f
--- /dev/null
+++ b/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
+}
diff --git a/internal/logging.go b/internal/logging.go
index 28f9926..5c18870 100644
--- a/internal/logging.go
+++ b/internal/logging.go
@@ -32,6 +32,7 @@ const (
 	Config   = "config"
 	Default  = "default"
 	Health   = "health"
+	IDP      = "idp"
 	JWKS     = "jwks"
 	Requests = "requests"
 	Server   = "server"
@@ -45,6 +46,7 @@ var scopes = map[string]string{
 	Config:   "Configuration messages",
 	Default:  "Default",
 	Health:   "Health server messages",
+	IDP:      "Identity provider requests/responses",
 	JWKS:     "JWKS update and parse messages",
 	Requests: "Logs all requests and responses received by the server",
 	Server:   "Server request handling messages",
@@ -158,14 +160,15 @@ func setLogLevels(log telemetry.Logger, logLevelMap map[string]telemetry.Level)
 		for _, logger := range scope.List() {
 			logger.SetLevel(level)
 		}
-	} else {
-		for k, l := range logLevelMap {
-			logger, ok := scope.Find(k)
-			if ok {
-				logger.SetLevel(l)
-			} else {
-				log.Info("invalid logger", "logger", k)
-			}
+		delete(logLevelMap, "all")
+	}
+
+	for k, l := range logLevelMap {
+		logger, ok := scope.Find(k)
+		if ok {
+			logger.SetLevel(l)
+		} else {
+			log.Info("invalid logger", "logger", k)
 		}
 	}
 }
diff --git a/internal/oidc/jwks.go b/internal/oidc/jwks.go
index d79b69f..5e9eaac 100644
--- a/internal/oidc/jwks.go
+++ b/internal/oidc/jwks.go
@@ -18,7 +18,6 @@ import (
 	"context"
 	"errors"
 	"fmt"
-	"net/http"
 	"time"
 
 	"github.com/lestrrat-go/httprc"
@@ -29,6 +28,7 @@ import (
 	configv1 "github.com/istio-ecosystem/authservice/config/gen/go/v1"
 	oidcv1 "github.com/istio-ecosystem/authservice/config/gen/go/v1/oidc"
 	"github.com/istio-ecosystem/authservice/internal"
+	inthttp "github.com/istio-ecosystem/authservice/internal/http"
 )
 
 var (
@@ -102,14 +102,11 @@ func (j *DefaultJWKSProvider) fetchDynamic(ctx context.Context, config *oidcv1.O
 	jwksConfig := config.GetJwksFetcher()
 
 	if !j.cache.IsRegistered(jwksConfig.JwksUri) {
-		transport := http.DefaultTransport.(*http.Transport).Clone()
-
-		var err error
-		if transport.TLSClientConfig, err = j.tlsPool.LoadTLSConfig(config); err != nil {
-			return nil, fmt.Errorf("error loading TLS config: %w", err)
+		client, err := inthttp.NewHTTPClient(config, j.tlsPool, internal.Logger(internal.IDP))
+		if err != nil {
+			return nil, err
 		}
 
-		client := &http.Client{Transport: transport}
 		refreshInterval := time.Duration(jwksConfig.PeriodicFetchIntervalSec) * time.Second
 		if refreshInterval == 0 {
 			refreshInterval = DefaultFetchInterval
diff --git a/internal/oidc/memory.go b/internal/oidc/memory.go
index d9b8756..b362350 100644
--- a/internal/oidc/memory.go
+++ b/internal/oidc/memory.go
@@ -70,6 +70,7 @@ func (m *memoryStore) GetTokenResponse(ctx context.Context, sessionID string) (*
 		return nil, nil
 	}
 
+	log.Debug("token response", "token_response", s.tokenResponse)
 	s.accessed = m.clock.Now()
 	return s.tokenResponse, nil
 }
@@ -96,6 +97,7 @@ func (m *memoryStore) GetAuthorizationState(ctx context.Context, sessionID strin
 		return nil, nil
 	}
 
+	log.Debug("authorization state", "state", s.authorizationState)
 	s.accessed = m.clock.Now()
 	return s.authorizationState, nil
 }
diff --git a/internal/oidc/redis.go b/internal/oidc/redis.go
index ce8c816..6033631 100644
--- a/internal/oidc/redis.go
+++ b/internal/oidc/redis.go
@@ -152,6 +152,8 @@ func (r *redisStore) GetTokenResponse(ctx context.Context, sessionID string) (*T
 		return nil, err
 	}
 
+	log.Debug("token response", "token_response", tokenResponse)
+
 	return tokenResponse, nil
 }
 
@@ -199,6 +201,8 @@ func (r *redisStore) GetAuthorizationState(ctx context.Context, sessionID string
 		return nil, err
 	}
 
+	log.Debug("authorization state", "state", state.AuthorizationState())
+
 	return state.AuthorizationState(), nil
 }
 


Test patch:
diff --git a/e2e/istio/istio_test.go b/e2e/istio/istio_test.go
index 04a3c2b..97c8165 100644
--- a/e2e/istio/istio_test.go
+++ b/e2e/istio/istio_test.go
@@ -39,7 +39,7 @@ func (i *IstioSuite) TestIstioEnforcement() {
 			// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 			// Initialize it for each test to not reuse the session between them
 			client, err := e2e.NewOIDCTestClient(
-				e2e.WithLoggingOptions(i.T().Log, true),
+				e2e.WithLoggingOptions(i.T().Log),
 				e2e.WithCustomCA(testCAFile),
 				// Map the keycloak cluster DNS name to the local address where the service is exposed
 				e2e.WithCustomAddressMappings(map[string]string{
diff --git a/e2e/keycloak/keycloak_test.go b/e2e/keycloak/keycloak_test.go
index 1f28443..ab5bd4b 100644
--- a/e2e/keycloak/keycloak_test.go
+++ b/e2e/keycloak/keycloak_test.go
@@ -51,7 +51,7 @@ var (
 func TestOIDCUsesTheConfiguredProxy(t *testing.T) {
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
 	require.NoError(t, err)
@@ -82,7 +82,7 @@ func TestOIDC(t *testing.T) {
 	// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
 	require.NoError(t, err)
@@ -109,7 +109,7 @@ func TestOIDCRefreshTokens(t *testing.T) {
 	// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
 	require.NoError(t, err)
@@ -163,7 +163,7 @@ func TestOIDCLogout(t *testing.T) {
 	// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithBaseURL(idpBaseURLHost),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
diff --git a/e2e/legacy/legacy_test.go b/e2e/legacy/legacy_test.go
index 42a7d1d..d13c08a 100644
--- a/e2e/legacy/legacy_test.go
+++ b/e2e/legacy/legacy_test.go
@@ -51,7 +51,7 @@ func TestOIDC(t *testing.T) {
 	// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
 	require.NoError(t, err)
@@ -78,7 +78,7 @@ func TestOIDCRefreshTokens(t *testing.T) {
 	// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
 	require.NoError(t, err)
@@ -131,7 +131,7 @@ func TestOIDCLogout(t *testing.T) {
 	// Initialize the test OIDC client that will keep track of the state of the OIDC login process
 	client, err := e2e.NewOIDCTestClient(
 		e2e.WithCustomCA(testCAFile),
-		e2e.WithLoggingOptions(t.Log, true),
+		e2e.WithLoggingOptions(t.Log),
 		e2e.WithBaseURL(idpBaseURLHost),
 		e2e.WithCustomAddressMappings(customAddressMappings),
 	)
diff --git a/e2e/testclient.go b/e2e/testclient.go
index 950d3c4..7b2509e 100644
--- a/e2e/testclient.go
+++ b/e2e/testclient.go
@@ -22,38 +22,17 @@ import (
 	"io"
 	"net"
 	"net/http"
-	"net/http/httputil"
 	"net/url"
 	"os"
+	"slices"
 	"strings"
 
+	"github.com/tetratelabs/telemetry"
+	"github.com/tetratelabs/telemetry/function"
 	"golang.org/x/net/html"
-)
-
-// LoggingRoundTripper is a http.RoundTripper that logs requests and responses.
-type LoggingRoundTripper struct {
-	LogFunc  func(...any)
-	LogBody  bool
-	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.LogFunc != nil {
-		if dump, derr := httputil.DumpRequest(req, l.LogBody); derr == nil {
-			l.LogFunc(string(dump))
-		}
-	}
 
-	res, err := l.Delegate.RoundTrip(req)
-	if err == nil && l.LogFunc != nil {
-		if dump, derr := httputil.DumpResponse(res, l.LogBody); derr == nil {
-			l.LogFunc(string(dump))
-		}
-	}
-
-	return res, err
-}
+	inthttp "github.com/istio-ecosystem/authservice/internal/http"
+)
 
 // CookieTracker is a http.RoundTripper that tracks cookies received from the server.
 type CookieTracker struct {
@@ -91,7 +70,6 @@ type OIDCTestClient struct {
 	customCA     *x509.CertPool   // Custom TLS configuration, if needed
 	mappings     *AddressMappings // Custom address mappings
 	logFunc      func(...any)     // Logging function to log all requests and responses
-	logBody      bool             // Whether to log the request and response bodies
 }
 
 // Option is a functional option for configuring the OIDCTestClient.
@@ -113,10 +91,9 @@ func WithCustomCA(caCert string) Option {
 }
 
 // WithLoggingOptions configures the OIDCTestClient to log requests and responses.
-func WithLoggingOptions(logFunc func(...any), logBody bool) Option {
+func WithLoggingOptions(logFunc func(...any)) Option {
 	return func(o *OIDCTestClient) error {
 		o.logFunc = logFunc
-		o.logBody = logBody
 		return nil
 	}
 }
@@ -171,7 +148,7 @@ func WithBaseURL(idpBaseURL string) Option {
 func NewOIDCTestClient(opts ...Option) (*OIDCTestClient, error) {
 	var (
 		defaultTransport = http.DefaultTransport.(*http.Transport).Clone()
-		logging          = &LoggingRoundTripper{Delegate: defaultTransport}
+		logging          = &inthttp.LoggingRoundTripper{Delegate: defaultTransport}
 		cookieTracker    = &CookieTracker{Cookies: make(map[string]*http.Cookie), Delegate: logging}
 		client           = &OIDCTestClient{http: &http.Client{Transport: cookieTracker}}
 	)
@@ -182,8 +159,11 @@ func NewOIDCTestClient(opts ...Option) (*OIDCTestClient, error) {
 		}
 	}
 
-	logging.LogFunc = client.logFunc
-	logging.LogBody = client.logBody
+	logging.Log = function.NewLogger(func(_ telemetry.Level, msg string, _ error, values function.Values) {
+		args := append([]any{msg}, slices.Concat(values.FromMethod, values.FromContext, values.FromLogger)...)
+		client.logFunc(args...)
+	})
+	logging.Log.SetLevel(telemetry.LevelDebug)
 
 	defaultTransport.TLSClientConfig = &tls.Config{RootCAs: client.customCA}
 	if client.mappings != nil {
diff --git a/internal/authz/oidc_test.go b/internal/authz/oidc_test.go
index 1956e68..3f9c9a0 100644
--- a/internal/authz/oidc_test.go
+++ b/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)
 		})
diff --git a/internal/http/http_test.go b/internal/http/http_test.go
index 2a79502..4e2c6fe 100644
--- a/internal/http/http_test.go
+++ b/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)
+	})
+}
diff --git a/internal/http/logging_test.go b/internal/http/logging_test.go
new file mode 100644
index 0000000..8a3c9d6
--- /dev/null
+++ b/internal/http/logging_test.go
@@ -0,0 +1,101 @@
+// 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 (
+	"bufio"
+	"net/http"
+	"strings"
+	"testing"
+
+	"github.com/stretchr/testify/require"
+	"github.com/tetratelabs/telemetry"
+	"github.com/tetratelabs/telemetry/function"
+)
+
+const (
+	request  = "POST / HTTP/1.1\r\nHost: example.com\r\n\r\nreq body"
+	response = "HTTP/1.1 200 OK\r\nConnection: close\r\n\r\nresp body"
+)
+
+func TestLoggingRoundTripper(t *testing.T) {
+	var (
+		rt  = &recordedRoundTrip{logs: make([]logEntry, 0)}
+		lrt = LoggingRoundTripper{
+			Log: function.NewLogger(rt.log),
+			Delegate: roundTripperFunc(func(req *http.Request) (*http.Response, error) {
+				return http.ReadResponse(bufio.NewReader(strings.NewReader(response)), req)
+			}),
+		}
+	)
+
+	tests := []struct {
+		name  string
+		level telemetry.Level
+		want  []logEntry
+	}{
+		{"no-debug", telemetry.LevelInfo, []logEntry{}},
+		{"debug", telemetry.LevelDebug, []logEntry{
+			{
+				level:  telemetry.LevelDebug,
+				msg:    "request",
+				values: []any{"data", request},
+			},
+			{
+				level:  telemetry.LevelDebug,
+				msg:    "response",
+				values: []any{"data", response},
+			},
+		}},
+	}
+
+	for _, tt := range tests {
+		t.Run(tt.name, func(t *testing.T) {
+			lrt.Log.SetLevel(tt.level)
+			req, err := http.NewRequest("POST", "http://example.com", strings.NewReader("req body"))
+			require.NoError(t, err)
+
+			_, err = lrt.RoundTrip(req)
+			require.NoError(t, err)
+			require.Equal(t, tt.want, rt.logs)
+		})
+	}
+}
+
+type roundTripperFunc func(req *http.Request) (*http.Response, error)
+
+func (fn roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) {
+	return fn(req)
+}
+
+type recordedRoundTrip struct {
+	logs []logEntry
+}
+
+type logEntry struct {
+	level  telemetry.Level
+	msg    string
+	values []any
+}
+
+func (r *recordedRoundTrip) log(level telemetry.Level, msg string, _ error, values function.Values) {
+	r.logs = append(r.logs, logEntry{
+		level:  level,
+		msg:    msg,
+		values: values.FromMethod,
+	})
+}
diff --git a/internal/logging_test.go b/internal/logging_test.go
index 5a15d97..8d2b788 100644
--- a/internal/logging_test.go
+++ b/internal/logging_test.go
@@ -59,7 +59,7 @@ func TestLoggingSetup(t *testing.T) {
 		{"l1:debug", telemetry.LevelDebug, telemetry.LevelInfo, false},
 		{"l1:debug,l2:debug", telemetry.LevelDebug, telemetry.LevelDebug, false},
 		{"invalid:debug,l2:error", telemetry.LevelInfo, telemetry.LevelError, false},
-		{"all:none,l1:debug", telemetry.LevelNone, telemetry.LevelNone, false},
+		{"all:none,l1:debug", telemetry.LevelDebug, telemetry.LevelNone, false},
 		{"", telemetry.LevelInfo, telemetry.LevelInfo, false},
 		{",", telemetry.LevelInfo, telemetry.LevelInfo, true},
 		{":", telemetry.LevelInfo, telemetry.LevelInfo, true},