From 9fec555151f86e0ced15b1917f2200b61715ed6a Mon Sep 17 00:00:00 2001 From: Patryk Dobrowolski Date: Fri, 25 Oct 2024 09:19:41 +0200 Subject: [PATCH] oidc logging added --- pkg/oidc/oidc.go | 64 +++++++++++++++++++++++++------------------ pkg/oidc/oidc_test.go | 23 ++++++++-------- 2 files changed, 50 insertions(+), 37 deletions(-) diff --git a/pkg/oidc/oidc.go b/pkg/oidc/oidc.go index 5657fa72c98d..d42c5d33fec5 100644 --- a/pkg/oidc/oidc.go +++ b/pkg/oidc/oidc.go @@ -5,17 +5,24 @@ package oidc import ( + "context" "errors" "fmt" + "strconv" "time" "github.com/coreos/go-oidc/v3/oidc" "github.com/go-jose/go-jose/v4" "github.com/go-jose/go-jose/v4/jwt" - "github.com/kyma-project/test-infra/pkg/logging" - "golang.org/x/net/context" ) +type LoggerInterface interface { + Debugw(msg string, keysAndValues ...string) + Infow(msg string, keysAndValues ...string) + Errorw(msg string, keysAndValues ...string) + Errorf(msg string, args ...interface{}) +} + var ( // SupportedSigningAlgorithms is a list of supported oidc token signing algorithms. SupportedSigningAlgorithms = []string{"RS256"} @@ -68,11 +75,6 @@ type ClaimsInterface interface { ValidateExpectations(Issuer) error } -type LoggerInterface interface { - logging.StructuredLoggerInterface - logging.WithLoggerInterface -} - // Issuer is the OIDC issuer. // Name is the human-readable name of the issuer. // IssuerURL is the OIDC discovery issuer endpoint. @@ -172,11 +174,11 @@ func NewVerifierConfig(logger LoggerInterface, clientID string, options ...Verif logger.Debugw("Created Verifier config with default values", "clientID", clientID, - "SkipClientIDCheck", verifierConfig.SkipClientIDCheck, - "SkipExpiryCheck", verifierConfig.SkipExpiryCheck, - "SkipIssuerCheck", verifierConfig.SkipIssuerCheck, - "InsecureSkipSignatureCheck", verifierConfig.InsecureSkipSignatureCheck, - "SupportedSigningAlgs", verifierConfig.SupportedSigningAlgs, + "SkipClientIDCheck", strconv.FormatBool(verifierConfig.SkipClientIDCheck), + "SkipExpiryCheck", strconv.FormatBool(verifierConfig.SkipExpiryCheck), + "SkipIssuerCheck", strconv.FormatBool(verifierConfig.SkipIssuerCheck), + "InsecureSkipSignatureCheck", strconv.FormatBool(verifierConfig.InsecureSkipSignatureCheck), + "SupportedSigningAlgs", fmt.Sprintf("%v", verifierConfig.SupportedSigningAlgs), ) logger.Debugw("Applying VerifierConfigOptions") for _, option := range options { @@ -187,11 +189,11 @@ func NewVerifierConfig(logger LoggerInterface, clientID string, options ...Verif } logger.Debugw("Applied all VerifierConfigOptions", "clientID", clientID, - "SkipClientIDCheck", verifierConfig.SkipClientIDCheck, - "SkipExpiryCheck", verifierConfig.SkipExpiryCheck, - "SkipIssuerCheck", verifierConfig.SkipIssuerCheck, - "InsecureSkipSignatureCheck", verifierConfig.InsecureSkipSignatureCheck, - "SupportedSigningAlgs", verifierConfig.SupportedSigningAlgs, + "SkipClientIDCheck", strconv.FormatBool(verifierConfig.SkipClientIDCheck), + "SkipExpiryCheck", strconv.FormatBool(verifierConfig.SkipExpiryCheck), + "SkipIssuerCheck", strconv.FormatBool(verifierConfig.SkipIssuerCheck), + "InsecureSkipSignatureCheck", strconv.FormatBool(verifierConfig.InsecureSkipSignatureCheck), + "SupportedSigningAlgs", fmt.Sprintf("%v", verifierConfig.SupportedSigningAlgs), ) return verifierConfig, nil } @@ -232,7 +234,8 @@ func (claims *Claims) ValidateExpectations(issuer Issuer) error { logger := claims.LoggerInterface logger.Debugw("Validating job_workflow_ref claim against expected value", "job_workflow_ref", claims.JobWorkflowRef, "expected", issuer.ExpectedJobWorkflowRef) if claims.JobWorkflowRef != issuer.ExpectedJobWorkflowRef { - return fmt.Errorf("job_workflow_ref claim expected value validation failed, expected: %s, provided: %s", claims.JobWorkflowRef, issuer.ExpectedJobWorkflowRef) + logger.Errorw("Job workflow ref validation failed", "expected", issuer.ExpectedJobWorkflowRef, "provided", claims.JobWorkflowRef) + return fmt.Errorf("job_workflow_ref claim expected value validation failed, expected: %s, provided: %s", issuer.ExpectedJobWorkflowRef, claims.JobWorkflowRef) } logger.Debugw("Claims validated successfully") return nil @@ -290,11 +293,11 @@ func NewTokenProcessor( tokenProcessor.verifierConfig = config logger.Debugw("Added Verifier config to token processor", "clientID", config.ClientID, - "SkipClientIDCheck", config.SkipClientIDCheck, - "SkipExpiryCheck", config.SkipExpiryCheck, - "SkipIssuerCheck", config.SkipIssuerCheck, - "InsecureSkipSignatureCheck", config.InsecureSkipSignatureCheck, - "SupportedSigningAlgs", config.SupportedSigningAlgs, + "SkipClientIDCheck", strconv.FormatBool(config.SkipClientIDCheck), + "SkipExpiryCheck", strconv.FormatBool(config.SkipExpiryCheck), + "SkipIssuerCheck", strconv.FormatBool(config.SkipIssuerCheck), + "InsecureSkipSignatureCheck", strconv.FormatBool(config.InsecureSkipSignatureCheck), + "SupportedSigningAlgs", fmt.Sprintf("%v", config.SupportedSigningAlgs), ) if tokenProcessor.verifierConfig.ClientID == "" { return TokenProcessor{}, errors.New("verifierConfig clientID is empty") @@ -311,7 +314,7 @@ func NewTokenProcessor( return TokenProcessor{}, err } tokenProcessor.issuer = trustedIssuer - logger.Debugw("Added trusted issuer to TokenProcessor", "issuer", tokenProcessor.issuer) + logger.Debugw("Added trusted issuer to TokenProcessor", "issuer", fmt.Sprintf("%+v", tokenProcessor.issuer)) logger.Debugw("Applying TokenProcessorOptions") for _, option := range options { @@ -322,7 +325,7 @@ func NewTokenProcessor( } logger.Debugw("Applied all TokenProcessorOptions") - logger.Debugw("Created token processor", "issuer", tokenProcessor.issuer) + logger.Debugw("Created token processor", "issuer", fmt.Sprintf("%+v", tokenProcessor.issuer)) return tokenProcessor, nil } @@ -361,7 +364,7 @@ func (tokenProcessor *TokenProcessor) tokenIssuer(signAlgorithm []string) (strin func (tokenProcessor *TokenProcessor) isTrustedIssuer(issuer string, trustedIssuers map[string]Issuer) (Issuer, error) { logger := tokenProcessor.logger logger.Debugw("Checking if issuer is trusted", "issuer", issuer) - logger.Debugw("Trusted issuers", "trustedIssuers", trustedIssuers) + logger.Debugw("Trusted issuers", "trustedIssuers", fmt.Sprintf("%+v", trustedIssuers)) if trustedIssuer, exists := trustedIssuers[issuer]; exists { logger.Debugw("Issuer is trusted", "issuer", issuer) return trustedIssuer, nil @@ -388,19 +391,23 @@ func (tokenProcessor *TokenProcessor) VerifyAndExtractClaims(ctx context.Context token, err = tokenProcessor.handleExpiredToken(ctx, tokenExpiryError, logger, err) } if err != nil { + logger.Errorf("Failed to verify token", "error", err) return fmt.Errorf("failed to verify token: %w", err) } logger.Debugw("Getting claims from token") err = token.Claims(claims) if err != nil { + logger.Errorf("Failed to get claims from token", "error", err) return fmt.Errorf("failed to get claims from token: %w", err) } logger.Debugw("Got claims from token", "claims", fmt.Sprintf("%+v", claims)) err = claims.ValidateExpectations(tokenProcessor.issuer) if err != nil { + logger.Errorf("Failed to validate claims", "error", err) return fmt.Errorf("failed to validate claims: %w", err) } + logger.Infow("Token verified and claims extracted successfully") return nil } @@ -410,11 +417,13 @@ func (tokenProcessor *TokenProcessor) handleExpiredToken(ctx context.Context, to elapsed := now.Sub(expiryTime) gracePeriod := 10 * time.Minute if elapsed <= gracePeriod { + logger.Infow("Token expired recently, attempting to verify without expiry check", "elapsed", elapsed.String()) newVerifierConfig := tokenProcessor.verifierConfig newVerifierConfig.SkipExpiryCheck = true provider, err := NewProviderFromDiscovery(ctx, logger, tokenProcessor.issuer.IssuerURL) if err != nil { + logger.Errorw("Failed to create provider", "error", err.Error()) return Token{}, fmt.Errorf("failed to create provider: %w", err) } @@ -422,11 +431,14 @@ func (tokenProcessor *TokenProcessor) handleExpiredToken(ctx context.Context, to token, err := newVerifier.Verify(ctx, tokenProcessor.rawToken) if err != nil { + logger.Errorw("Failed to verify token after skipping expiry check", "error", err.Error()) return Token{}, fmt.Errorf("failed to verify token after skipping expiry check: %w", err) } + logger.Debugw("Token verified successfully after skipping expiry check") return token, nil } else { + logger.Errorw("Token expired too long ago", "elapsed", elapsed.String(), "gracePeriod", gracePeriod.String()) return Token{}, fmt.Errorf("token expired more than %v ago: %w", gracePeriod, err) } } diff --git a/pkg/oidc/oidc_test.go b/pkg/oidc/oidc_test.go index 643e4589fae8..85d5da587224 100644 --- a/pkg/oidc/oidc_test.go +++ b/pkg/oidc/oidc_test.go @@ -3,10 +3,6 @@ package oidc_test import ( "errors" "fmt" - - // "time" - - // "fmt" "os" "github.com/coreos/go-oidc/v3/oidc" @@ -16,15 +12,22 @@ import ( . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" "github.com/stretchr/testify/mock" - "go.uber.org/zap" "golang.org/x/net/context" ) +// MockLogger implements the LoggerInterface for testing purposes +type MockLogger struct{} + +func (l *MockLogger) Debugw(msg string, keysAndValues ...string) {} +func (l *MockLogger) Infow(msg string, keysAndValues ...string) {} +func (l *MockLogger) Errorw(msg string, keysAndValues ...string) {} +func (l *MockLogger) Errorf(msg string, keysAndValues ...interface{}) {} + var _ = Describe("OIDC", func() { var ( err error ctx context.Context - logger *zap.SugaredLogger + logger tioidc.LoggerInterface trustedIssuers map[string]tioidc.Issuer rawToken []byte verifierConfig tioidc.VerifierConfig @@ -33,10 +36,7 @@ var _ = Describe("OIDC", func() { ) BeforeEach(func() { - l, err := zap.NewDevelopment() - Expect(err).NotTo(HaveOccurred()) - - logger = l.Sugar() + logger = &MockLogger{} clientID = "testClientID" }) @@ -243,7 +243,8 @@ var _ = Describe("OIDC", func() { // Verify Expect(err).To(HaveOccurred()) - Expect(err).To(MatchError("failed to validate claims: job_workflow_ref claim expected value validation failed, expected: kyma-project/test-infra/.github/workflows/unexpected.yml@refs/heads/main, provided: kyma-project/test-infra/.github/workflows/verify-oidc-token.yml@refs/heads/main")) + Expect(err).To(MatchError("failed to validate claims: job_workflow_ref claim expected value validation failed, expected: kyma-project/test-infra/.github/workflows/verify-oidc-token.yml@refs/heads/main, provided: kyma-project/test-infra/.github/workflows/unexpected.yml@refs/heads/main")) + }) It("should return an error when token was not verified", func() { verifier.On("Verify", mock.AnythingOfType("backgroundCtx"), string(rawToken)).Return(token, fmt.Errorf("token validation failed"))