Skip to content

Commit

Permalink
oidc logging added
Browse files Browse the repository at this point in the history
  • Loading branch information
@akiioto
akiioto committed Oct 25, 2024
1 parent c768a0d commit 9fec555
Show file tree
Hide file tree
Showing 2 changed files with 50 additions and 37 deletions.
64 changes: 38 additions & 26 deletions pkg/oidc/oidc.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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"}
Expand Down Expand Up @@ -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.
Expand Down Expand Up @@ -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 {
Expand All @@ -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
}
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -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")
Expand All @@ -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 {
Expand All @@ -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
}

Expand Down Expand Up @@ -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
Expand All @@ -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
}

Expand All @@ -410,23 +417,28 @@ 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)
}

newVerifier := provider.NewVerifier(logger, newVerifierConfig)
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)
}
}
23 changes: 12 additions & 11 deletions pkg/oidc/oidc_test.go
View file
Original file line number Diff line number Diff line change
Expand Up @@ -3,10 +3,6 @@ package oidc_test
import (
"errors"
"fmt"

// "time"

// "fmt"
"os"

"github.com/coreos/go-oidc/v3/oidc"
Expand All @@ -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
Expand All @@ -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"
})

Expand Down Expand Up @@ -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"))
Expand Down

0 comments on commit 9fec555

Please sign in to comment.