Add log statements when auth is found, and pkg to all statements (#60)

.env.template

@@ -8,3 +8,4 @@ RVS_APP_NAME_EXCLUDE_LIST=
 RVS_WORKERS=
 RVS_DB_SERVER=
 RVS_DB_DATABASE=
+RVS_WORKLOAD_IDENTITY_REGISTRIES=radixdev.azurecr.io

charts/radix-vulnerability-scanner/Chart.yaml

@@ -1,5 +1,5 @@
 apiVersion: v1
-appVersion: 1.1.0
-version: 1.1.0
+appVersion: 1.1.1
+version: 1.1.1
 description: Scan images in RadixDeployments for vulnerabilities
 name: radix-vulnerability-scanner

pkg/dockercfg/config.go

@@ -8,6 +8,7 @@ import (
 
 	"github.com/containerd/containerd/reference/docker"
 	"github.com/equinor/radix-vulnerability-scanner/pkg/registry"
+	"github.com/rs/zerolog/log"
 )
 
 type Config struct {
@@ -42,7 +43,7 @@ func NewFromBytes(contents []byte) (*Config, error) {
 	return &cfgJSON, nil
 }
 
-func (c Config) GetAuth(_ context.Context, image string) (*registry.Auth, error) {
+func (c Config) GetAuth(ctx context.Context, image string) (*registry.Auth, error) {
 	named, err := docker.ParseDockerRef(image)
 	if err != nil {
 		return nil, err
@@ -51,6 +52,7 @@ func (c Config) GetAuth(_ context.Context, image string) (*registry.Auth, error)
 
 	if len(c.Auths) > 0 {
 		if auth, found := c.Auths[registryName]; found {
+			log.Ctx(ctx).Debug().Str("pkg", "dockercfg").Str("registry", registryName).Msg("found auth")
 			return &registry.Auth{Username: auth.Username, Password: auth.Password}, nil
 		}
 	}

pkg/handler/handler.go

@@ -75,16 +75,16 @@ func (s *imageVulnerabilityScanner) Handle(ctx context.Context, imageName string
 	if skipScan, err := s.isLastScanWithinRescanThreshold(ctx, imageName); err != nil {
 		return err
 	} else if skipScan {
-		log.Info().Str("image", imageName).Msgf("skipping scan of image, recently scanned")
+		log.Info().Str("pkg", "handler").Str("image", imageName).Msgf("skipping scan of image, recently scanned")
 		return nil
 	}
 
-	log.Info().Str("image", imageName).Msgf("scanning image")
+	log.Info().Str("pkg", "handler").Str("image", imageName).Msgf("scanning image")
 	scanCtx, cancel := context.WithTimeout(ctx, s.scanTimeout)
 	defer cancel()
 	scanResult, err := s.scanner.Scan(scanCtx, imageName, dockerConfig)
 	if err != nil {
-		log.Warn().Str("image", imageName).Err(err).Msgf("error scanning image")
+		log.Warn().Str("pkg", "handler").Str("image", imageName).Err(err).Msgf("error scanning image")
 	}
 	scanSuccess := err == nil
 	vulnerabilitiesBulk := []db.VulnerabilityBulkDto{}
@@ -133,7 +133,7 @@ func (s *imageVulnerabilityScanner) Handle(ctx context.Context, imageName string
 
 	dbCtx, cancel := context.WithTimeout(ctx, 30*time.Second)
 	defer cancel()
-	log.Info().Str("image", imageName).Msgf("storing scan results for image")
+	log.Info().Str("pkg", "handler").Str("image", imageName).Msgf("storing scan results for image")
 	return s.repository.RegisterImageScan(dbCtx, imageName, baseImage, time.Now(), scanSuccess, vulnerabilitiesBulk, identifiersBulk, referencesBulk)
 }
 

pkg/imageworker/worker.go

@@ -43,7 +43,7 @@ func New(handler handler.Handler) *Worker {
 
 // Receive implementation of Observer
 func (w *Worker) Receive(obj observe.ImageInfo) {
-	log.Info().Str("image", obj.ImageName).Msg("enqueuing image")
+	log.Info().Str("pkg", "imageworker").Str("image", obj.ImageName).Msg("enqueuing image")
 	w.queue.Add(&obj)
 }
 
@@ -93,16 +93,16 @@ func (w *Worker) processItem(ctx context.Context, item any) {
 	defer w.queue.Done(item)
 
 	if image, ok := item.(*observe.ImageInfo); ok {
-		log.Info().Str("image", image.ImageName).Msg("processing image")
+		log.Info().Str("pkg", "imageworker").Str("image", image.ImageName).Msg("processing image")
 		if err := w.handler.Handle(ctx, image.ImageName, image.DockerConfig); err != nil {
 			requeues := w.queue.NumRequeues(image)
 			if requeues < maxNumberOfRequeues {
-				log.Info().Str("image", image.ImageName).Err(err).Msgf("requeuing scan of image (attempt %d of %d) due to error", requeues+1, maxNumberOfRequeues)
+				log.Info().Str("pkg", "imageworker").Str("image", image.ImageName).Err(err).Msgf("requeuing scan of image (attempt %d of %d) due to error", requeues+1, maxNumberOfRequeues)
 				w.queue.AddRateLimited(item)
 				return
 			} else {
 				w.queue.Forget(item)
-				log.Error().Str("image", image.ImageName).Err(err).Msgf("scan failed for image after %d retries", requeues)
+				log.Error().Str("pkg", "imageworker").Str("image", image.ImageName).Err(err).Msgf("scan failed for image after %d retries", requeues)
 				return
 			}
 		}

pkg/scan/snyk.go

@@ -64,13 +64,14 @@ func (s *SnykScanner) Scan(ctx context.Context, image string, dockerConfig docke
 		return nil
 	}
 
+	log.Ctx(ctx).Debug().Str("pkg", "scan").Str("image", image).Msg("scanning image")
 	testArgs := []string{"container", "test", "--json", image}
 	var testArgsWithCreds []string
 	testArgsWithCreds = append(testArgsWithCreds, testArgs...)
 	testArgsWithCreds = append(testArgsWithCreds, credArgs...)
 	buf := &bytes.Buffer{}
 	err := scanFn(ctx, testArgsWithCreds, buf)
-	log.Trace().Stringer("result", buf).Strs("args", testArgsWithCreds).Err(err).Msg("scan completed")
+	log.Trace().Str("pkg", "scan").Stringer("result", buf).Strs("args", testArgsWithCreds).Err(err).Msg("scan completed")
 
 	if err != nil {
 		if len(credArgs) == 0 {
@@ -84,9 +85,10 @@ func (s *SnykScanner) Scan(ctx context.Context, image string, dockerConfig docke
 		// parameter contains invalid credentials for docker.io. Even if redis:latest is public, the invalid credentials
 		// from the `auths` parameter causes the scan to fail. We'll therefore try to do a second scan
 		// without supplying credential arguments
+		log.Ctx(ctx).Debug().Str("pkg", "scan").Str("image", image).Msg("scanning image again without creds")
 		buf = &bytes.Buffer{}
 		err = scanFn(ctx, testArgs, buf)
-		log.Trace().Stringer("result", buf).Strs("args", testArgsWithCreds).Err(err).Msg("retry scan completed")
+		log.Trace().Str("pkg", "scan").Stringer("result", buf).Strs("args", testArgsWithCreds).Err(err).Msg("retry scan completed")
 		if err != nil {
 			return nil, err
 		}

pkg/tokenstore/token_store.go

@@ -2,18 +2,13 @@ package tokenstore
 
 import (
 	"context"
-	"errors"
 
 	"github.com/containerd/containerd/reference/docker"
 	"github.com/equinor/radix-vulnerability-scanner/pkg/registry"
 	"github.com/rs/zerolog/log"
 	"golang.org/x/oauth2"
 )
 
-var (
-	ErrRegistryNotFound = errors.New("registry is not found")
-)
-
 type TokenStore struct {
 	tokens map[string]oauth2.TokenSource
 }
@@ -50,8 +45,6 @@ func (t *TokenStore) GetAuth(ctx context.Context, image string) (*registry.Auth,
 	}
 	registryName := docker.Domain(named)
 
-	log.Ctx(ctx).Debug().Str("Registry", registryName).Msg("Get token from Source")
-
 	_, ok := t.tokens[registryName]
 	if !ok {
 		return nil, nil
@@ -61,5 +54,6 @@ func (t *TokenStore) GetAuth(ctx context.Context, image string) (*registry.Auth,
 	if err != nil {
 		return nil, err
 	}
+	log.Ctx(ctx).Debug().Str("pkg", "tokenstore").Str("registry", registryName).Msg("found auth")
 	return &registry.Auth{Username: "00000000-0000-0000-0000-000000000000", Password: token.AccessToken}, nil
 }

pkg/tokenstore/tokensource/acr.go

@@ -67,7 +67,7 @@ func NewACRTokenSource(ctx context.Context, registryName string, options ...AcrO
 }
 
 func (s *AcrTokenSource) Token() (*oauth2.Token, error) {
-	s.logger.Debug().Str("registry", s.registry).Msg("Fetching new ACR token")
+	s.logger.Debug().Str("pkg", "tokensource").Str("registry", s.registry).Msg("fetching new ACR token")
 	s.mutex.Lock()
 	defer s.mutex.Unlock()