Skip to content

Commit

Permalink
Add a logger to log the calls to the Identity Provider (#250)
Browse files Browse the repository at this point in the history 
* Add a logger to log the calls to the Identity Provider

Signed-off-by: Ignasi Barrera <ignasi@tetrate.io>

* Reuse the http logging roundtripper in the OIDC test client

Signed-off-by: Ignasi Barrera <ignasi@tetrate.io>

---------

Signed-off-by: Ignasi Barrera <ignasi@tetrate.io>
  • Loading branch information
@nacx
nacx authored Apr 17, 2024
1 parent 2cbc8be commit 706f4e7
Show file tree
Hide file tree
Showing 15 changed files with 311 additions and 88 deletions.
2 changes: 1 addition & 1 deletion e2e/istio/istio_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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{
Expand Down
8 changes: 4 additions & 4 deletions e2e/keycloak/keycloak_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand All @@ -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)
Expand Down Expand Up @@ -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),
)
Expand Down
6 changes: 3 additions & 3 deletions e2e/legacy/legacy_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand All @@ -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)
Expand Down Expand Up @@ -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),
)
Expand Down
44 changes: 12 additions & 32 deletions e2e/testclient.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 {
Expand Down Expand Up @@ -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.
Expand All @@ -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
}
}
Expand Down Expand Up @@ -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}}
)
Expand All @@ -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 {
Expand Down
53 changes: 22 additions & 31 deletions internal/authz/oidc.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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
}
Expand All @@ -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)
Expand Down Expand Up @@ -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())
Expand All @@ -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
}
Expand Down Expand Up @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand All @@ -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
}
Expand Down Expand Up @@ -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}
Expand Down Expand Up @@ -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
}
Expand Down
2 changes: 1 addition & 1 deletion internal/authz/oidc_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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)
})
Expand Down
37 changes: 37 additions & 0 deletions internal/http/http.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand Down Expand Up @@ -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
}
Loading

0 comments on commit 706f4e7

Please sign in to comment.