Merge pull request #92 from telia-oss/improve-logging

Improve sidecred logging

backend/file/file.go

@@ -2,6 +2,7 @@
 package file
 
 import (
+	"context"
 	"encoding/json"
 	"fmt"
 	"os"
@@ -17,7 +18,7 @@ func New() sidecred.StateBackend {
 type fileStateBackend struct{}
 
 // Load implements sidecred.StateBackend.
-func (b *fileStateBackend) Load(file string) (*sidecred.State, error) {
+func (b *fileStateBackend) Load(ctx context.Context, file string) (*sidecred.State, error) {
 	if err := b.createFileIfNotExists(file); err != nil {
 		return nil, err
 	}
@@ -36,7 +37,7 @@ func (b *fileStateBackend) Load(file string) (*sidecred.State, error) {
 }
 
 // Save implements sidecred.StateBackend.
-func (b *fileStateBackend) Save(file string, state *sidecred.State) error {
+func (b *fileStateBackend) Save(ctx context.Context, file string, state *sidecred.State) error {
 	if err := b.createFileIfNotExists(file); err != nil {
 		return err
 	}

backend/s3/s3.go

@@ -4,6 +4,7 @@ package s3
 //go:generate go run github.com/maxbrunsfeld/counterfeiter/v6 -generate
 import (
 	"bytes"
+	"context"
 	"encoding/json"
 	"errors"
 	"io"
@@ -36,7 +37,7 @@ type backend struct {
 }
 
 // Load implements sidecred.StateBackend.
-func (b *backend) Load(key string) (*sidecred.State, error) {
+func (b *backend) Load(ctx context.Context, key string) (*sidecred.State, error) {
 	var state sidecred.State
 	obj, err := b.client.GetObject(&s3.GetObjectInput{
 		Bucket: aws.String(b.bucket),
@@ -64,7 +65,7 @@ func (b *backend) Load(key string) (*sidecred.State, error) {
 }
 
 // Save implements sidecred.StateBackend.
-func (b *backend) Save(key string, state *sidecred.State) error {
+func (b *backend) Save(ctx context.Context, key string, state *sidecred.State) error {
 	o, err := json.Marshal(state)
 	if err != nil {
 		return err

backend/s3/s3_test.go

@@ -1,6 +1,7 @@
 package s3_test
 
 import (
+	"context"
 	"io"
 	"strings"
 	"testing"
@@ -29,7 +30,7 @@ func TestS3Backend(t *testing.T) {
 			fakeS3.GetObjectReturns(&s3.GetObjectOutput{Body: io.NopCloser(strings.NewReader("{}"))}, nil)
 
 			b := backend.New(fakeS3, "bucket")
-			state, err := b.Load("key")
+			state, err := b.Load(context.TODO(), "key")
 			require.NoError(t, err)
 			assert.Equal(t, &sidecred.State{}, state)
 		})

cmd/sidecred-lambda/main.go

@@ -2,19 +2,24 @@ package main
 
 import (
 	"bytes"
+	"context"
 	"fmt"
 	"io"
+	"math/rand"
 	"os"
+	"time"
 
 	"github.com/alecthomas/kingpin"
 	"github.com/aws/aws-lambda-go/lambda"
 	"github.com/aws/aws-sdk-go/aws"
 	"github.com/aws/aws-sdk-go/aws/session"
 	"github.com/aws/aws-sdk-go/service/s3"
 	environment "github.com/telia-oss/aws-env"
+	"go.uber.org/zap"
 
 	"github.com/telia-oss/sidecred"
 	"github.com/telia-oss/sidecred/config"
+	"github.com/telia-oss/sidecred/eventctx"
 	"github.com/telia-oss/sidecred/internal/cli"
 )
 
@@ -26,6 +31,9 @@ func main() {
 		bucket = app.Flag("config-bucket", "Name of the S3 bucket where the config is stored.").Required().String()
 	)
 
+	// Make span, and trace id random
+	rand.Seed(time.Now().Unix())
+
 	sess, err := session.NewSession()
 	if err != nil {
 		panic(fmt.Errorf("failed to create a new session: %s", err))
@@ -51,30 +59,64 @@ type Event struct {
 	StatePath  string `json:"state_path"`
 }
 
-func runFunc(configBucket *string) func(*sidecred.Sidecred, sidecred.StateBackend) error {
-	return func(s *sidecred.Sidecred, backend sidecred.StateBackend) error {
+func runFunc(configBucket *string) func(*sidecred.Sidecred, sidecred.StateBackend, sidecred.RunConfig) error {
+	return func(s *sidecred.Sidecred, backend sidecred.StateBackend, runConfig sidecred.RunConfig) error {
 		lambda.Start(func(event Event) error {
-			cfg, err := loadConfig(*configBucket, event.ConfigPath)
+			ctx := context.Background() // NOTE: change to function arg later.
+
+			uid := rand.Uint64() //nolint:gosec // Only need random enough for unique id
+			ctx = eventctx.SetLogger(ctx, runConfig.Logger.With(
+				zap.Uint64("dd.trace_id", uid),
+				zap.Uint64("dd.span_id", uid),
+			))
+
+			ctx = eventctx.SetStats(ctx, &eventctx.Stats{
+				CallsToGithub: 0,
+			})
+
+			cfg, err := loadConfig(ctx, *configBucket, event.ConfigPath)
 			if err != nil {
-				return fmt.Errorf("failed to load config: %s", err)
+				return failure(ctx, cfg.Namespace(), fmt.Errorf("failed to load config: %s", err))
 			}
-			state, err := backend.Load(event.StatePath)
+
+			ctx = eventctx.SetLogger(ctx, eventctx.GetLogger(ctx).With(
+				zap.String("namespace", cfg.Namespace()),
+			))
+
+			state, err := backend.Load(ctx, event.StatePath)
 			if err != nil {
-				return fmt.Errorf("failed to load state: %s", err)
+				return failure(ctx, cfg.Namespace(), fmt.Errorf("failed to load state: %s", err))
 			}
-			if err := s.Process(cfg, state); err != nil {
-				return err
+
+			if err := s.Process(ctx, cfg, state); err != nil {
+				return failure(ctx, cfg.Namespace(), err)
 			}
-			if err := backend.Save(event.StatePath, state); err != nil {
-				return fmt.Errorf("failed to save state: %s", err)
+
+			if err := backend.Save(ctx, event.StatePath, state); err != nil {
+				return failure(ctx, cfg.Namespace(), fmt.Errorf("failed to save state: %s", err))
 			}
+
+			stats := eventctx.GetStats(ctx)
+			eventctx.GetLogger(ctx).Info(fmt.Sprintf("processing '%s' done", cfg.Namespace()),
+				zap.Int("calls_to_github", stats.CallsToGithub),
+			)
+
 			return nil
 		})
 		return nil
 	}
 }
 
-func loadConfig(bucket, key string) (sidecred.Config, error) {
+func failure(ctx context.Context, namespace string, err error) error {
+	stats := eventctx.GetStats(ctx)
+	eventctx.GetLogger(ctx).Info(fmt.Sprintf("processing '%s' failed", namespace),
+		zap.Int("calls_to_github", stats.CallsToGithub),
+	)
+
+	return err
+}
+
+func loadConfig(ctx context.Context, bucket, key string) (sidecred.Config, error) {
 	sess, err := session.NewSession()
 	if err != nil {
 		return nil, err

cmd/sidecred/main.go

@@ -1,13 +1,16 @@
 package main
 
 import (
+	"context"
 	"fmt"
 	"os"
 
 	"github.com/alecthomas/kingpin"
+	"go.uber.org/zap"
 
 	"github.com/telia-oss/sidecred"
 	"github.com/telia-oss/sidecred/config"
+	"github.com/telia-oss/sidecred/eventctx"
 	"github.com/telia-oss/sidecred/internal/cli"
 )
 
@@ -40,26 +43,42 @@ func main() {
 	kingpin.MustParse(app.Parse(os.Args[1:]))
 }
 
-func runFunc(cfg, statePath *string) func(*sidecred.Sidecred, sidecred.StateBackend) error {
-	return func(s *sidecred.Sidecred, backend sidecred.StateBackend) error {
+func runFunc(cfg, statePath *string) func(*sidecred.Sidecred, sidecred.StateBackend, sidecred.RunConfig) error {
+	return func(s *sidecred.Sidecred, backend sidecred.StateBackend, runConfig sidecred.RunConfig) error {
+		ctx := context.Background()
+
+		ctx = eventctx.SetStats(ctx, &eventctx.Stats{
+			CallsToGithub: 0,
+		})
+
 		b, err := os.ReadFile(*cfg)
 		if err != nil {
 			return fmt.Errorf("failed to read config: %s", err)
 		}
+
 		cfg, err := config.Parse(b)
 		if err != nil {
 			return fmt.Errorf("failed to parse config: %s", err)
 		}
-		state, err := backend.Load(*statePath)
+
+		state, err := backend.Load(ctx, *statePath)
 		if err != nil {
 			return fmt.Errorf("failed to load state: %s", err)
 		}
-		if err := s.Process(cfg, state); err != nil {
+
+		if err := s.Process(ctx, cfg, state); err != nil {
 			return err
 		}
-		if err := backend.Save(*statePath, state); err != nil {
+
+		if err := backend.Save(ctx, *statePath, state); err != nil {
 			return fmt.Errorf("failed to save state: %s", err)
 		}
+
+		stats := eventctx.GetStats(ctx)
+		eventctx.GetLogger(ctx).Info(fmt.Sprintf("processing '%s' done", cfg.Namespace()),
+			zap.Int("calls_to_github", stats.CallsToGithub),
+		)
+
 		return nil
 	}
 }

eventctx/context.go

@@ -0,0 +1,52 @@
+package eventctx
+
+import (
+	"context"
+	"testing"
+
+	"go.uber.org/zap"
+	"go.uber.org/zap/zaptest"
+)
+
+var (
+	loggerKey = struct{}{}
+	statsKey  = struct{}{}
+)
+
+type Stats struct {
+	CallsToGithub int
+}
+
+func (s *Stats) IncGithubCalls() {
+	s.CallsToGithub++
+}
+
+func GetLogger(ctx context.Context) *zap.Logger {
+	logger, ok := ctx.Value(loggerKey).(*zap.Logger)
+	if !ok {
+		return zap.NewNop()
+	}
+
+	return logger
+}
+
+func SetLogger(ctx context.Context, logger *zap.Logger) context.Context {
+	return context.WithValue(ctx, loggerKey, logger)
+}
+
+func TestContext(t *testing.T) context.Context {
+	return SetLogger(context.TODO(), zaptest.NewLogger(t))
+}
+
+func GetStats(ctx context.Context) *Stats {
+	stats, ok := ctx.Value(statsKey).(*Stats)
+	if !ok {
+		return &Stats{}
+	}
+
+	return stats
+}
+
+func SetStats(ctx context.Context, stats *Stats) context.Context {
+	return context.WithValue(ctx, statsKey, stats)
+}

githubrotator/rotator.go

@@ -10,6 +10,8 @@ import (
 	"github.com/google/go-github/v45/github"
 	"github.com/telia-oss/githubapp"
 	"go.uber.org/zap"
+
+	"github.com/telia-oss/sidecred/eventctx"
 )
 
 const (
@@ -45,13 +47,13 @@ type Rotator struct {
 	rateLimitClient RateLimits
 }
 
-func (r *Rotator) CreateInstallationToken(owner string, repositories []string, permissions *githubapp.Permissions) (*githubapp.Token, error) {
+func (r *Rotator) CreateInstallationToken(ctx context.Context, owner string, repositories []string, permissions *githubapp.Permissions) (*githubapp.Token, error) {
 	if r.apps[0].hasValidToken() {
 		r.logger.Debug("retrieving rate limits for token",
 			zap.String("token_expires_at", r.apps[0].token.ExpiresAt.String()),
 			zap.String("app", r.apps[0].integrationID))
 
-		rateLimits, _, err := r.rateLimitClient.GetTokenRateLimits(context.TODO(), r.apps[0].token.GetToken())
+		rateLimits, _, err := r.rateLimitClient.GetTokenRateLimits(ctx, r.apps[0].token.GetToken())
 		switch {
 		case err != nil:
 			r.logger.Debug("unexpected error when retrieving rate limits",
@@ -77,14 +79,14 @@ func (r *Rotator) CreateInstallationToken(owner string, repositories []string, p
 		}
 	}
 
-	return r.createInstallationToken(owner, repositories, permissions)
+	return r.createInstallationToken(ctx, owner, repositories, permissions)
 }
 
 func hasTokenExpired(token *githubapp.Token) bool {
 	return token.ExpiresAt.Sub(time.Now()).Seconds() <= 5 //nolint:gosimple,gocritic
 }
 
-func (r *Rotator) createInstallationToken(owner string, repositories []string, permissions *githubapp.Permissions) (*githubapp.Token, error) {
+func (r *Rotator) createInstallationToken(ctx context.Context, owner string, repositories []string, permissions *githubapp.Permissions) (*githubapp.Token, error) {
 	r.logger.Debug("createInstallationToken called",
 		zap.String("app", r.apps[0].integrationID),
 		zap.Int("number_of_apps", len(r.apps)))
@@ -102,6 +104,7 @@ func (r *Rotator) createInstallationToken(owner string, repositories []string, p
 		r.logger.Debug("create installation token",
 			zap.String("app", r.apps[0].integrationID))
 
+		eventctx.GetStats(ctx).IncGithubCalls()
 		var rateLimitError *github.RateLimitError
 		token, err := r.apps[0].app.CreateInstallationToken(owner, repositories, permissions)
 		switch {

githubrotator/rotator_test.go

@@ -11,6 +11,7 @@ import (
 	"github.com/telia-oss/githubapp"
 	"go.uber.org/zap"
 
+	"github.com/telia-oss/sidecred/eventctx"
 	"github.com/telia-oss/sidecred/githubrotator"
 	"github.com/telia-oss/sidecred/githubrotator/fakes"
 )
@@ -69,24 +70,24 @@ func TestRotator_CreateInstallationToken(t *testing.T) {
 	})
 
 	// App 0 called, returns RateLimitError, rotates, App 1 called, returns Error, rotates, App 2 called, returns tokenA
-	token, err := rotator.CreateInstallationToken("telia-oss", []string{"sidecred"}, nil)
+	token, err := rotator.CreateInstallationToken(eventctx.TestContext(t), "telia-oss", []string{"sidecred"}, nil)
 	fmt.Println("TOKEN", token)
 	fmt.Println("ERROR", err)
 	assert.Expect(token.GetToken()).To(Equal("a"))
 	assert.Expect(err).To(BeNil())
 
 	// tokenA GetTokenRateLimits called, returns low rate limit, rotate, App 0 by passed, App 1 called, returns tokenB
-	token, err = rotator.CreateInstallationToken("telia-oss", []string{"sidecred"}, nil)
+	token, err = rotator.CreateInstallationToken(eventctx.TestContext(t), "telia-oss", []string{"sidecred"}, nil)
 	assert.Expect(token.GetToken()).To(Equal("b"))
 	assert.Expect(err).To(BeNil())
 
 	// tokenB GetTokenRateLimits called, returns Error
-	token, err = rotator.CreateInstallationToken("telia-oss", []string{"sidecred"}, nil)
+	token, err = rotator.CreateInstallationToken(eventctx.TestContext(t), "telia-oss", []string{"sidecred"}, nil)
 	assert.Expect(token).To(BeNil())
 	assert.Expect(err).To(HaveOccurred())
 
 	// tokenB GetTokenRateLimits called, returns rate limit above cutoff, returns tokenC
-	token, err = rotator.CreateInstallationToken("telia-oss", []string{"sidecred"}, nil)
+	token, err = rotator.CreateInstallationToken(eventctx.TestContext(t), "telia-oss", []string{"sidecred"}, nil)
 	assert.Expect(token).To(Equal(tokenC))
 	assert.Expect(err).To(BeNil())
 }