Add debug logging around OIDC token and GitHub action

pkg/attestation/crafter/crafter.go

@@ -211,7 +211,7 @@ func (c *Crafter) LoadCraftingState(ctx context.Context, attestationID string) e
 		return errors.New("runner type not set in the crafting state")
 	}
 
-	c.Runner = NewRunner(runnerType)
+	c.Runner = NewRunner(runnerType, c.Logger)
 	c.Logger.Debug().Str("state", c.stateManager.Info(ctx, attestationID)).Msg("loaded state")
 
 	return nil

pkg/attestation/crafter/crafter_test.go

@@ -23,6 +23,8 @@ import (
 	"testing"
 	"time"
 
+	"github.com/rs/zerolog"
+
 	schemaapi "github.com/chainloop-dev/chainloop/app/controlplane/api/workflowcontract/v1"
 	"github.com/chainloop-dev/chainloop/app/controlplane/pkg/unmarshal"
 	"github.com/chainloop-dev/chainloop/pkg/attestation/crafter"
@@ -113,7 +115,9 @@ func (s *crafterSuite) TestInit() {
 			contract, err := loadSchema(tc.contractPath)
 			require.NoError(s.T(), err)
 
-			runner := crafter.NewRunner(contract.GetRunner().GetType())
+			// Create a logger for testing
+			testLogger := zerolog.New(zerolog.Nop()).Level(zerolog.Disabled)
+			runner := crafter.NewRunner(contract.GetRunner().GetType(), &testLogger)
 			// Make sure that the tests context indicate that we are not in a CI
 			// this makes the github action runner context to fail
 			c, err := newInitializedCrafter(s.T(), tc.contractPath, tc.workflowMetadata, tc.dryRun, tc.workingDir, runner)
@@ -334,7 +338,8 @@ func (s *crafterSuite) TestResolveEnvVars() {
 				for k, v := range gitHubTestingEnvVars {
 					s.T().Setenv(k, v)
 				}
-				runner = runners.NewGithubAction(s.T().Context())
+				testLogger := zerolog.New(zerolog.Nop()).Level(zerolog.Disabled)
+				runner = runners.NewGithubAction(s.T().Context(), &testLogger)
 			} else if tc.inJenkinsEnv {
 				contract = "testdata/contracts/jenkins_with_env_vars.yaml"
 				s.T().Setenv("JOB_NAME", "some-job")

pkg/attestation/crafter/runner.go

@@ -59,19 +59,35 @@ type RunnerM map[schemaapi.CraftingSchema_Runner_RunnerType]SupportedRunner
 // timeoutCtx is a context with a 15-second timeout
 var timeoutCtx, _ = context.WithTimeout(context.Background(), 15*time.Second)
 
-var RunnersMap = map[schemaapi.CraftingSchema_Runner_RunnerType]SupportedRunner{
-	schemaapi.CraftingSchema_Runner_GITHUB_ACTION:   runners.NewGithubAction(timeoutCtx),
-	schemaapi.CraftingSchema_Runner_GITLAB_PIPELINE: runners.NewGitlabPipeline(),
-	schemaapi.CraftingSchema_Runner_AZURE_PIPELINE:  runners.NewAzurePipeline(),
-	schemaapi.CraftingSchema_Runner_JENKINS_JOB:     runners.NewJenkinsJob(),
-	schemaapi.CraftingSchema_Runner_CIRCLECI_BUILD:  runners.NewCircleCIBuild(),
-	schemaapi.CraftingSchema_Runner_DAGGER_PIPELINE: runners.NewDaggerPipeline(),
+// RunnerFactory is a function that creates a runner
+type RunnerFactory func(logger *zerolog.Logger) SupportedRunner
+
+// RunnerFactories maps runner types to factory functions that create them
+var RunnerFactories = map[schemaapi.CraftingSchema_Runner_RunnerType]RunnerFactory{
+	schemaapi.CraftingSchema_Runner_GITHUB_ACTION: func(logger *zerolog.Logger) SupportedRunner {
+		return runners.NewGithubAction(timeoutCtx, logger)
+	},
+	schemaapi.CraftingSchema_Runner_GITLAB_PIPELINE: func(_ *zerolog.Logger) SupportedRunner {
+		return runners.NewGitlabPipeline()
+	},
+	schemaapi.CraftingSchema_Runner_AZURE_PIPELINE: func(_ *zerolog.Logger) SupportedRunner {
+		return runners.NewAzurePipeline()
+	},
+	schemaapi.CraftingSchema_Runner_JENKINS_JOB: func(_ *zerolog.Logger) SupportedRunner {
+		return runners.NewJenkinsJob()
+	},
+	schemaapi.CraftingSchema_Runner_CIRCLECI_BUILD: func(_ *zerolog.Logger) SupportedRunner {
+		return runners.NewCircleCIBuild()
+	},
+	schemaapi.CraftingSchema_Runner_DAGGER_PIPELINE: func(_ *zerolog.Logger) SupportedRunner {
+		return runners.NewDaggerPipeline()
+	},
 }
 
 // Load a specific runner
-func NewRunner(t schemaapi.CraftingSchema_Runner_RunnerType) SupportedRunner {
-	if r, ok := RunnersMap[t]; ok {
-		return r
+func NewRunner(t schemaapi.CraftingSchema_Runner_RunnerType, logger *zerolog.Logger) SupportedRunner {
+	if factory, ok := RunnerFactories[t]; ok {
+		return factory(logger)
 	}
 
 	return runners.NewGeneric()
@@ -83,7 +99,10 @@ func NewRunner(t schemaapi.CraftingSchema_Runner_RunnerType) SupportedRunner {
 // If more than one runner is detected, we default to generic since its an incongruent result
 func DiscoverRunner(logger zerolog.Logger) SupportedRunner {
 	detected := []SupportedRunner{}
-	for _, r := range RunnersMap {
+
+	// Create all runners and check their environment
+	for _, factory := range RunnerFactories {
+		r := factory(&logger)
 		if r.CheckEnv() {
 			detected = append(detected, r)
 		}

pkg/attestation/crafter/runners/githubaction.go

@@ -22,34 +22,38 @@ import (
 
 	schemaapi "github.com/chainloop-dev/chainloop/app/controlplane/api/workflowcontract/v1"
 	"github.com/chainloop-dev/chainloop/pkg/attestation/crafter/runners/oidc"
+	"github.com/rs/zerolog"
 )
 
 type GitHubAction struct {
 	githubToken *oidc.Token
 }
 
-func NewGithubAction(ctx context.Context) *GitHubAction {
+func NewGithubAction(ctx context.Context, logger *zerolog.Logger) *GitHubAction {
 	// In order to ensure that we are running in a non-falsifiable environment we get the OIDC
 	// from Github. That allows us to read the workflow file path and runnner type. If that can't
 	// be done we fallback to reading the env vars directly.
 	actorPersonal := fmt.Sprintf("https://github.com/%s", os.Getenv("GITHUB_ACTOR"))
 	actorOrganization := fmt.Sprintf("https://github.com/%s", os.Getenv("GITHUB_REPOSITORY_OWNER"))
-	client, err := oidc.NewGitHubClient(oidc.WithActor(actorPersonal), oidc.WithActor(actorOrganization))
+	client, err := oidc.NewGitHubClient(logger, oidc.WithActor(actorPersonal), oidc.WithActor(actorOrganization))
 	if err != nil {
+		logger.Debug().Err(err).Msg("failed creating GitHub OIDC client")
 		return &GitHubAction{
 			githubToken: nil,
 		}
 	}
 
 	token, err := client.Token(ctx)
 	if err != nil {
+		logger.Debug().Err(err).Msg("failed to get github token")
 		return &GitHubAction{
 			githubToken: nil,
 		}
 	}
 
 	ghToken, ok := token.(*oidc.Token)
 	if !ok {
+		logger.Debug().Err(err).Msg("failed casting to OIDC token")
 		return &GitHubAction{
 			githubToken: nil,
 		}

pkg/attestation/crafter/runners/githubaction_test.go

@@ -20,6 +20,8 @@ import (
 	"os"
 	"testing"
 
+	"github.com/rs/zerolog"
+
 	"github.com/stretchr/testify/suite"
 )
 
@@ -118,7 +120,9 @@ func (s *githubActionSuite) TestRunnerName() {
 
 // Run before each test
 func (s *githubActionSuite) SetupTest() {
-	s.runner = NewGithubAction(context.Background())
+	// Create a logger for testing
+	testLogger := zerolog.New(zerolog.Nop()).Level(zerolog.Disabled)
+	s.runner = NewGithubAction(context.Background(), &testLogger)
 	t := s.T()
 	for k, v := range gitHubTestingEnvVars {
 		t.Setenv(k, v)

pkg/attestation/crafter/runners/oidc/github.go

@@ -31,6 +31,7 @@ import (
 	"io"
 
 	"github.com/coreos/go-oidc/v3/oidc"
+	"github.com/rs/zerolog"
 )
 
 // DefaultActionsProviderURL is the default URL for GitHub Actions OIDC provider
@@ -47,6 +48,7 @@ const (
 )
 
 type GitHubOIDCClient struct {
+	logger       *zerolog.Logger
 	requestURL   *url.URL
 	verifierFunc func(context.Context) (*oidc.IDTokenVerifier, error)
 	bearerToken  string
@@ -87,17 +89,19 @@ func WithActor(actor string) Option {
 }
 
 // NewGitHubClient returns new GitHub OIDC provider client.
-func NewGitHubClient(opts ...Option) (*GitHubOIDCClient, error) {
+func NewGitHubClient(logger *zerolog.Logger, opts ...Option) (*GitHubOIDCClient, error) {
 	var c GitHubOIDCClient
 
 	// Get the request URL and token from env vars
 	requestURL := os.Getenv(RequestURLEnvKey)
 	if requestURL == "" {
+		logger.Debug().Msgf("url: %s environment variable not set", RequestURLEnvKey)
 		return nil, fmt.Errorf("url: %s environment variable not set; does your workflow have `id-token: write` scope?", RequestURLEnvKey)
 	}
 
 	parsedURL, err := url.ParseRequestURI(requestURL)
 	if err != nil {
+		logger.Debug().Err(err).Msgf("invalid request URL: %q", requestURL)
 		return nil, fmt.Errorf(
 			"%w: invalid request URL %q: %w; does your workflow have `id-token: write` scope?",
 			errURLError,
@@ -107,10 +111,12 @@ func NewGitHubClient(opts ...Option) (*GitHubOIDCClient, error) {
 
 	bearerToken := os.Getenv(RequestTokenEnvKey)
 	if len(bearerToken) == 0 {
+		logger.Debug().Msgf("token: %s environment variable not set", RequestTokenEnvKey)
 		return nil, fmt.Errorf("token: %s environment variable not set; does your workflow have `id-token: write` scope?", RequestTokenEnvKey)
 	}
 
 	c = GitHubOIDCClient{
+		logger:      logger,
 		requestURL:  parsedURL,
 		bearerToken: bearerToken,
 		actor:       []string{},
@@ -144,6 +150,7 @@ func (c *GitHubOIDCClient) Token(ctx context.Context) (any, error) {
 
 	audience := c.audience
 	if len(audience) == 0 {
+		c.logger.Debug().Msgf("audience: %s environment variable not set, using default: %s", RequestTokenEnvKey, DefaultGitHubAudience)
 		audience = DefaultGitHubAudience
 	}
 
@@ -187,6 +194,7 @@ func (c *GitHubOIDCClient) newRequestURL(audience []string) string {
 }
 
 func (c *GitHubOIDCClient) requestToken(ctx context.Context, audience []string) ([]byte, error) {
+	c.logger.Debug().Msgf("requesting token with audience: %s", audience)
 	req, err := http.NewRequest("GET", c.newRequestURL(audience), nil)
 	if err != nil {
 		return nil, fmt.Errorf("%w: creating request: %w", errRequestError, err)
@@ -210,6 +218,7 @@ func (c *GitHubOIDCClient) requestToken(ctx context.Context, audience []string)
 }
 
 func (c *GitHubOIDCClient) decodePayload(b []byte) (string, error) {
+	c.logger.Debug().Msgf("decoding payload: %s", b)
 	var payload struct {
 		Value string `json:"value"`
 	}
@@ -223,6 +232,7 @@ func (c *GitHubOIDCClient) decodePayload(b []byte) (string, error) {
 // verifyToken verifies the token contents and signature.
 func (c *GitHubOIDCClient) verifyToken(ctx context.Context, audience []string, actor []string, rawIDToken string) (*oidc.IDToken, error) {
 	// Verify the token.
+	c.logger.Debug().Msgf("verifying token: %s with audience: %s and actor: %s", rawIDToken, audience, actor)
 	verifier, err := c.verifierFunc(ctx)
 	if err != nil {
 		return nil, fmt.Errorf("%w: creating verifier: %w", errVerify, err)
@@ -253,6 +263,7 @@ func (c *GitHubOIDCClient) verifyToken(ctx context.Context, audience []string, a
 }
 
 func (c *GitHubOIDCClient) decodeToken(token *oidc.IDToken) (*Token, error) {
+	c.logger.Debug().Msgf("decoding token: %s", token)
 	var t Token
 	if err := token.Claims(&t); err != nil {
 		return nil, fmt.Errorf("%w: getting claims: %w", errToken, err)
@@ -262,6 +273,7 @@ func (c *GitHubOIDCClient) decodeToken(token *oidc.IDToken) (*Token, error) {
 }
 
 func (c *GitHubOIDCClient) verifyClaims(token *Token) error {
+	c.logger.Debug().Msgf("verifying claims: %s", token)
 	if token.JobWorkflowRef == "" {
 		return fmt.Errorf("%w: job workflow ref is empty", errClaims)
 	}

pkg/attestation/crafter/runners/oidc/github_test.go

@@ -23,11 +23,13 @@ import (
 	"testing"
 
 	"github.com/chainloop-dev/chainloop/pkg/attestation/crafter/runners/oidc"
+	"github.com/rs/zerolog"
 	"github.com/stretchr/testify/assert"
 	"github.com/stretchr/testify/require"
 )
 
 func TestNewGitHubClient(t *testing.T) {
+	testLogger := zerolog.New(zerolog.Nop()).Level(zerolog.Disabled)
 	originalRequestURL := os.Getenv(oidc.RequestURLEnvKey)
 	originalRequestToken := os.Getenv(oidc.RequestTokenEnvKey)
 	defer func() {
@@ -81,7 +83,7 @@ func TestNewGitHubClient(t *testing.T) {
 	for _, tt := range tests {
 		t.Run(tt.name, func(t *testing.T) {
 			tt.setupEnv(t)
-			client, err := oidc.NewGitHubClient()
+			client, err := oidc.NewGitHubClient(&testLogger)
 
 			if tt.expectErr {
 				assert.Error(t, err)
@@ -101,8 +103,10 @@ func TestWithAudience(t *testing.T) {
 	t.Setenv(oidc.RequestURLEnvKey, "https://example.com/token")
 	t.Setenv(oidc.RequestTokenEnvKey, "test-token")
 
+	testLogger := zerolog.New(zerolog.Nop()).Level(zerolog.Disabled)
 	testAudience := []string{"test-audience"}
 	_, err := oidc.NewGitHubClient(
+		&testLogger,
 		oidc.WithAudience(testAudience),
 	)
 	require.NoError(t, err)
@@ -111,6 +115,7 @@ func TestWithAudience(t *testing.T) {
 }
 
 func TestTokenRequest(t *testing.T) {
+	testLogger := zerolog.New(zerolog.Nop()).Level(zerolog.Disabled)
 	originalRequestURL := os.Getenv(oidc.RequestURLEnvKey)
 	originalRequestToken := os.Getenv(oidc.RequestTokenEnvKey)
 	defer func() {
@@ -153,7 +158,7 @@ func TestTokenRequest(t *testing.T) {
 			t.Setenv(oidc.RequestURLEnvKey, server.URL)
 			t.Setenv(oidc.RequestTokenEnvKey, "test-token")
 
-			client, err := oidc.NewGitHubClient()
+			client, err := oidc.NewGitHubClient(&testLogger)
 			require.NoError(t, err)
 
 			_, err = client.Token(context.Background())