fix(log): refactor some logs

Signed-off-by: Ramkumar Chinchani <[email protected]>
project-zot · Oct 6, 2023 · 081f230 · 081f230
1 parent 044ea85
commit 081f230
Show file tree

Hide file tree

Showing 12 changed files with 77 additions and 59 deletions.
diff --git a/.github/workflows/golangci-lint.yaml b/.github/workflows/golangci-lint.yaml
@@ -44,3 +44,13 @@ jobs:
       - name: Run linter from make target
         run: |
           make check
+      - name: Run log linter
+        run: |
+          set +e
+
+          # log messages should never start upper-cased
+          find . -name '*.go' | grep -v '_test.go' | xargs grep -n "Msg(\"[A-Z]"
+          if [ $? -eq 0 ]; then
+            exit 1
+          fi
+          exit 0
diff --git a/pkg/api/routes.go b/pkg/api/routes.go
@@ -1221,8 +1221,6 @@ func (rh *RouteHandler) CreateBlobUpload(response http.ResponseWriter, request *
 			return
 		}
 
-		rh.c.Log.Info().Int64("r.ContentLength", request.ContentLength).Msg("DEBUG")
-
 		digestStr := digests[0]
 
 		digest := godigest.Digest(digestStr)
@@ -1494,8 +1492,6 @@ func (rh *RouteHandler) UpdateBlobUpload(response http.ResponseWriter, request *
 		return
 	}
 
-	rh.c.Log.Info().Int64("r.ContentLength", request.ContentLength).Msg("DEBUG")
-
 	contentPresent := true
 
 	contentLen, err := strconv.ParseInt(request.Header.Get("Content-Length"), 10, 64)

diff --git a/pkg/api/session.go b/pkg/api/session.go
@@ -121,7 +121,8 @@ func SessionLogger(ctlr *Controller) mux.MiddlewareFunc {
 				monitoring.ObserveHTTPMethodLatency(ctlr.Metrics, method, latency) // histogram
 			}
 
-			log.Str("clientIP", clientIP).
+			log.Str("component", "session").
+				Str("clientIP", clientIP).
 				Str("method", method).
 				Str("path", path).
 				Int("statusCode", statusCode).
@@ -172,6 +173,7 @@ func SessionAuditLogger(audit *log.Logger) mux.MiddlewareFunc {
 				method == http.MethodPatch || method == http.MethodDelete) &&
 				(statusCode == http.StatusOK || statusCode == http.StatusCreated || statusCode == http.StatusAccepted) {
 				audit.Info().
+					Str("component", "session").
 					Str("clientIP", clientIP).
 					Str("subject", username).
 					Str("action", method).

diff --git a/pkg/exporter/api/exporter.go b/pkg/exporter/api/exporter.go
@@ -101,7 +101,7 @@ func (zc Collector) Collect(ch chan<- prometheus.Metric) {
 
 func panicOnDuplicateMetricName(m map[string]*prometheus.Desc, name string, log log.Logger) {
 	if _, present := m[name]; present {
-		log.Fatal().Msg("Duplicate keys: metric " + name + " already present")
+		log.Fatal().Str("metric", name).Msg("duplicate key")
 	}
 }
 
@@ -180,16 +180,16 @@ func runExporter(c *Controller) {
 
 	err := prometheus.Register(GetCollector(c))
 	if err != nil {
-		c.Log.Error().Err(err).Msg("Expected error in testing")
+		c.Log.Debug().Err(err).Msg("ignoring error")
 	}
 
 	http.Handle(c.Config.Exporter.Metrics.Path, promhttp.Handler())
-	c.Log.Info().Str("exporter addr", exporterAddr).
-		Str("exporter metrics path", c.Config.Exporter.Metrics.Path).
-		Msg("Exporter is listening on exporter addr & exposes metrics on exporter metrics path")
+	c.Log.Info().Str("addr", exporterAddr).
+		Str("path", c.Config.Exporter.Metrics.Path).
+		Msg("exporter listening")
 
 	serverAddr := fmt.Sprintf("%s://%s:%s", c.Config.Server.Protocol,
 		c.Config.Server.Host, c.Config.Server.Port)
-	c.Log.Info().Str("serverAddr", serverAddr).Msg("Scraping metrics")
-	c.Log.Fatal().Err(server.ListenAndServe()).Msg("Exporter stopped")
+	c.Log.Info().Str("serverAddr", serverAddr).Msg("scraping metrics")
+	c.Log.Fatal().Err(server.ListenAndServe()).Msg("exporter stopped")
 }
diff --git a/pkg/exporter/cli/cli.go b/pkg/exporter/cli/cli.go
@@ -60,18 +60,24 @@ func loadConfiguration(config *api.Config, configPath string) {
 	viper.SetConfigFile(configPath)
 
 	if err := viper.ReadInConfig(); err != nil {
-		log.Error().Err(err).Msg("Error while reading configuration")
+		log.Error().Err(err).Str("config", configPath).Msg("unable to read configuration")
 		panic(err)
 	}
 
 	metaData := &mapstructure.Metadata{}
 	if err := viper.Unmarshal(&config, metadataConfig(metaData)); err != nil {
-		log.Error().Err(err).Msg("Error while unmarshaling new config")
+		log.Error().Err(err).Str("config", configPath).Msg("unable to unmarshal config")
 		panic(err)
 	}
 
-	if len(metaData.Keys) == 0 || len(metaData.Unused) > 0 {
-		log.Error().Err(zerr.ErrBadConfig).Msg("Bad configuration, retry writing it")
+	if len(metaData.Keys) == 0 {
+		log.Error().Err(zerr.ErrBadConfig).Str("config", configPath).Msg("bad configuration")
+		panic(zerr.ErrBadConfig)
+	}
+
+	if len(metaData.Unused) > 0 {
+		log.Error().Err(zerr.ErrBadConfig).Interface("unknown fields", metaData.Unused).
+			Str("config", configPath).Msg("bad configuration")
 		panic(zerr.ErrBadConfig)
 	}
 }
diff --git a/pkg/extensions/search/cve/scan.go b/pkg/extensions/search/cve/scan.go
@@ -15,10 +15,12 @@ import (
 func NewScanTaskGenerator(
 	metaDB mTypes.MetaDB,
 	scanner Scanner,
-	log log.Logger,
+	logC log.Logger,
 ) scheduler.TaskGenerator {
+	sublogger := logC.With().Str("component", "search").Logger()
+
 	return &scanTaskGenerator{
-		log:        log,
+		log:        log.Logger{Logger: sublogger},
 		metaDB:     metaDB,
 		scanner:    scanner,
 		lock:       &sync.Mutex{},
@@ -195,13 +197,13 @@ func (st *scanTask) DoWork(ctx context.Context) error {
 	// We cache the results internally in the scanner
 	// so we can discard the actual results for now
 	if _, err := st.generator.scanner.ScanImage(image); err != nil {
-		st.generator.log.Error().Err(err).Str("image", image).Msg("Scheduled CVE scan errored for image")
+		st.generator.log.Error().Err(err).Str("image", image).Msg("scheduled CVE scan failed for image")
 		st.generator.addError(st.digest, err)
 
 		return err
 	}
 
-	st.generator.log.Debug().Str("image", image).Msg("Scheduled CVE scan completed successfully for image")
+	st.generator.log.Debug().Str("image", image).Msg("scheduled CVE scan completed successfully for image")
 
 	return nil
 }
diff --git a/pkg/extensions/sync/references/references.go b/pkg/extensions/sync/references/references.go
@@ -79,7 +79,7 @@ func (refs References) syncAll(ctx context.Context, localRepo, upstreamRepo,
 	for _, ref := range refs.referenceList {
 		syncedRefsDigests, err = ref.SyncReferences(ctx, localRepo, upstreamRepo, subjectDigestStr)
 		if err != nil {
-			refs.log.Error().Err(err).
+			refs.log.Warn().Err(err).
 				Str("reference type", ref.Name()).
 				Str("image", fmt.Sprintf("%s:%s", upstreamRepo, subjectDigestStr)).
 				Msg("couldn't sync image referrer")
@@ -108,7 +108,7 @@ func (refs References) SyncReference(ctx context.Context, localRepo, upstreamRep
 		if ref.Name() == referenceType {
 			syncedRefsDigests, err = ref.SyncReferences(ctx, localRepo, upstreamRepo, subjectDigestStr)
 			if err != nil {
-				refs.log.Error().Err(err).
+				refs.log.Warn().Err(err).
 					Str("reference type", ref.Name()).
 					Str("image", fmt.Sprintf("%s:%s", upstreamRepo, subjectDigestStr)).
 					Msg("couldn't sync image referrer")

diff --git a/pkg/log/guidelines.md b/pkg/log/guidelines.md
@@ -61,3 +61,5 @@ For example, lookup a cache (fast path) and it throws a not-found error, and we
 expect to handle it and perform a slow path lookup. Instead of logging the
 lookup failure at ERROR level, it may be more appropriate to log at DEBUG level
 and then handle the error.
+
+Also, instead of `Msg("error at something")` standardize on `Msg("failed at something")`.
diff --git a/pkg/meta/boltdb/boltdb.go b/pkg/meta/boltdb/boltdb.go
@@ -1118,7 +1118,7 @@ func (bdw *BoltDB) SearchRepos(ctx context.Context, searchText string,
 
 					indexDataMap[indexDigest] = indexData
 				default:
-					bdw.Log.Error().Str("mediaType", descriptor.MediaType).Msg("Unsupported media type")
+					bdw.Log.Error().Str("mediaType", descriptor.MediaType).Msg("unsupported media type")
 
 					continue
 				}
@@ -1315,7 +1315,7 @@ func (bdw *BoltDB) FilterTags(ctx context.Context, filterFunc mTypes.FilterFunc,
 						matchedTags[tag] = descriptor
 					}
 				default:
-					bdw.Log.Error().Str("mediaType", descriptor.MediaType).Msg("Unsupported media type")
+					bdw.Log.Error().Str("mediaType", descriptor.MediaType).Msg("unsupported media type")
 
 					continue
 				}

diff --git a/pkg/meta/parse.go b/pkg/meta/parse.go
@@ -20,27 +20,27 @@ import (
 // ParseStorage will sync all repos found in the rootdirectory of the oci layout that zot was deployed on with the
 // ParseStorage database.
 func ParseStorage(metaDB mTypes.MetaDB, storeController storage.StoreController, log log.Logger) error {
-	log.Info().Msg("Started parsing storage and updating MetaDB")
+	log.Info().Str("component", "metadb").Msg("parsing storage and initializing")
 
 	allRepos, err := getAllRepos(storeController)
 	if err != nil {
 		rootDir := storeController.DefaultStore.RootDir()
-		log.Error().Err(err).Str("rootDir", rootDir).
-			Msg("load-local-layout: failed to get all repo names present under rootDir")
+		log.Error().Err(err).Str("component", "metadb").Str("rootDir", rootDir).
+			Msg("failed to get all repo names present under rootDir")
 
 		return err
 	}
 
 	for _, repo := range allRepos {
 		err := ParseRepo(repo, metaDB, storeController, log)
 		if err != nil {
-			log.Error().Err(err).Str("repository", repo).Msg("load-local-layout: failed to sync repo")
+			log.Error().Err(err).Str("component", "metadb").Str("repository", repo).Msg("failed to parse repo")
 
 			return err
 		}
 	}
 
-	log.Info().Msg("Done parsing storage and updating MetaDB")
+	log.Info().Str("component", "metadb").Msg("successfully initialized")
 
 	return nil
 }
@@ -56,7 +56,7 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 
 	indexBlob, err := imageStore.GetIndexContent(repo)
 	if err != nil {
-		log.Error().Err(err).Str("repository", repo).Msg("load-repo: failed to read index.json for repo")
+		log.Error().Err(err).Str("repository", repo).Msg("failed to read index.json for repo")
 
 		return err
 	}
@@ -65,14 +65,14 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 
 	err = json.Unmarshal(indexBlob, &indexContent)
 	if err != nil {
-		log.Error().Err(err).Str("repository", repo).Msg("load-repo: failed to unmarshal index.json for repo")
+		log.Error().Err(err).Str("repository", repo).Msg("failed to unmarshal index.json for repo")
 
 		return err
 	}
 
 	err = resetRepoMeta(repo, metaDB, log)
 	if err != nil && !errors.Is(err, zerr.ErrRepoMetaNotFound) {
-		log.Error().Err(err).Str("repository", repo).Msg("load-repo: failed to reset tag field in RepoMetadata for repo")
+		log.Error().Err(err).Str("repository", repo).Msg("failed to reset tag field in RepoMetadata for repo")
 
 		return err
 	}
@@ -82,7 +82,7 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 
 		descriptorBlob, err := getCachedBlob(repo, descriptor, metaDB, imageStore, log)
 		if err != nil {
-			log.Error().Err(err).Msg("load-repo: error checking manifestMeta in MetaDB")
+			log.Error().Err(err).Msg("error checking manifestMeta in MetaDB")
 
 			return err
 		}
@@ -91,7 +91,7 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 			descriptorBlob, tag)
 		if err != nil {
 			log.Error().Err(err).Str("repository", repo).Str("tag", tag).
-				Msg("load-repo: failed checking if image is signature for specified image")
+				Msg("failed checking if image is signature for specified image")
 
 			return err
 		}
@@ -112,15 +112,15 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 			if err != nil {
 				log.Error().Err(err).Str("repository", repo).Str("tag", tag).
 					Str("manifestDigest", signedManifestDigest.String()).
-					Msg("load-repo: failed set signature meta for signed image")
+					Msg("failed set signature meta for signed image")
 
 				return err
 			}
 
 			err = metaDB.UpdateSignaturesValidity(repo, signedManifestDigest)
 			if err != nil {
 				log.Error().Err(err).Str("repository", repo).Str("reference", tag).Str("digest", signedManifestDigest.String()).Msg(
-					"load-repo: failed verify signatures validity for signed image")
+					"failed verify signatures validity for signed image")
 
 				return err
 			}
@@ -138,7 +138,7 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 			imageStore, metaDB, log)
 		if err != nil {
 			log.Error().Err(err).Str("repository", repo).Str("tag", tag).
-				Msg("load-repo: failed to set metadata for image")
+				Msg("failed to set metadata for image")
 
 			return err
 		}
@@ -152,13 +152,13 @@ func ParseRepo(repo string, metaDB mTypes.MetaDB, storeController storage.StoreC
 func resetRepoMeta(repo string, metaDB mTypes.MetaDB, log log.Logger) error {
 	repoMeta, err := metaDB.GetRepoMeta(repo)
 	if err != nil && !errors.Is(err, zerr.ErrRepoMetaNotFound) {
-		log.Error().Err(err).Str("repository", repo).Msg("load-repo: failed to get RepoMeta for repo")
+		log.Error().Err(err).Str("repository", repo).Msg("failed to get RepoMeta for repo")
 
 		return err
 	}
 
 	if errors.Is(err, zerr.ErrRepoMetaNotFound) {
-		log.Info().Str("repository", repo).Msg("load-repo: RepoMeta not found for repo, new RepoMeta will be created")
+		log.Info().Str("repository", repo).Msg("RepoMeta not found for repo, new RepoMeta will be created")
 
 		return nil
 	}
@@ -204,7 +204,7 @@ func getCachedBlob(repo string, descriptor ispec.Descriptor, metaDB mTypes.MetaD
 		descriptorBlob, _, _, err = imageStore.GetImageManifest(repo, digest.String())
 		if err != nil {
 			log.Error().Err(err).Str("repository", repo).Str("digest", digest.String()).
-				Msg("load-repo: failed to get blob for image")
+				Msg("failed to get blob for image")
 
 			return nil, err
 		}
@@ -251,7 +251,7 @@ func getCosignSignatureLayersInfo(
 	var manifestContent ispec.Manifest
 	if err := json.Unmarshal(manifestBlob, &manifestContent); err != nil {
 		log.Error().Err(err).Str("repository", repo).Str("reference", tag).Str("digest", manifestDigest).Msg(
-			"load-repo: unable to marshal blob index")
+			"unable to marshal blob index")
 
 		return layers, err
 	}
@@ -265,15 +265,15 @@ func getCosignSignatureLayersInfo(
 		layerContent, err := imageStore.GetBlobContent(repo, layer.Digest)
 		if err != nil {
 			log.Error().Err(err).Str("repository", repo).Str("reference", tag).Str("layerDigest", layer.Digest.String()).Msg(
-				"load-repo: unable to get cosign signature layer content")
+				"unable to get cosign signature layer content")
 
 			return layers, err
 		}
 
 		layerSigKey, ok := layer.Annotations[zcommon.CosignSigKey]
 		if !ok {
 			log.Error().Err(err).Str("repository", repo).Str("reference", tag).Str("layerDigest", layer.Digest.String()).Msg(
-				"load-repo: unable to get specific annotation of cosign signature")
+				"unable to get specific annotation of cosign signature")
 		}
 
 		layers = append(layers, mTypes.LayerInfo{
@@ -294,14 +294,14 @@ func getNotationSignatureLayersInfo(
 	var manifestContent ispec.Manifest
 	if err := json.Unmarshal(manifestBlob, &manifestContent); err != nil {
 		log.Error().Err(err).Str("repository", repo).Str("reference", manifestDigest).Msg(
-			"load-repo: unable to marshal blob index")
+			"unable to marshal blob index")
 
 		return layers, err
 	}
 
 	if len(manifestContent.Layers) != 1 {
 		log.Error().Err(zerr.ErrBadManifest).Str("repository", repo).Str("reference", manifestDigest).
-			Msg("load-repo: notation signature manifest requires exactly one layer but it does not")
+			Msg("notation signature manifest requires exactly one layer but it does not")
 
 		return layers, zerr.ErrBadManifest
 	}
@@ -316,7 +316,7 @@ func getNotationSignatureLayersInfo(
 	layerContent, err := imageStore.GetBlobContent(repo, layer)
 	if err != nil {
 		log.Error().Err(err).Str("repository", repo).Str("reference", manifestDigest).Str("layerDigest", layer.String()).Msg(
-			"load-repo: unable to get notation signature blob content")
+			"unable to get notation signature blob content")
 
 		return layers, err
 	}