fix(log): refactor some logs

Signed-off-by: Ramkumar Chinchani <[email protected]>

.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

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)

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).

pkg/cli/server/root.go

@@ -71,7 +71,7 @@ func newServeCmd(conf *config.Config) *cobra.Command {
 			}
 
 			if err := ctlr.Run(reloaderCtx); err != nil {
-				ctlr.Log.Fatal().Err(err).Msg("unable to start controller, exiting")
+				ctlr.Log.Fatal().Err(err).Msg("failed to start controller, exiting")
 			}
 		},
 	}
@@ -105,15 +105,15 @@ func newScrubCmd(conf *config.Config) *cobra.Command {
 				fmt.Sprintf("http://%s/v2", net.JoinHostPort(conf.HTTP.Address, conf.HTTP.Port)),
 				nil)
 			if err != nil {
-				log.Error().Err(err).Msg("unable to create a new http request")
+				log.Error().Err(err).Msg("failed to create a new http request")
 				panic(err)
 			}
 
 			response, err := http.DefaultClient.Do(req)
 			if err == nil {
 				response.Body.Close()
-				log.Warn().Msg("The server is running, in order to perform the scrub command the server should be shut down")
-				panic("Error: server is running")
+				log.Warn().Msg("server is running, in order to perform the scrub command the server should be shut down")
+				panic("server is running")
 			} else {
 				// server is down
 				ctlr := api.NewController(conf)
@@ -146,11 +146,11 @@ func newVerifyCmd(conf *config.Config) *cobra.Command {
 		Run: func(cmd *cobra.Command, args []string) {
 			if len(args) > 0 {
 				if err := LoadConfiguration(conf, args[0]); err != nil {
-					log.Error().Str("config", args[0]).Msg("Config file is invalid")
+					log.Error().Str("config", args[0]).Msg("config file is invalid")
 					panic(err)
 				}
 
-				log.Info().Str("config", args[0]).Msg("Config file is valid")
+				log.Info().Str("config", args[0]).Msg("config file is valid")
 			}
 		},
 	}
@@ -291,19 +291,19 @@ func validateCacheConfig(cfg *config.Config, log zlog.Logger) error {
 
 func validateExtensionsConfig(cfg *config.Config, log zlog.Logger) error {
 	if cfg.Extensions != nil && cfg.Extensions.Mgmt != nil {
-		log.Warn().Msg("The mgmt extensions configuration option has been made redundant and will be ignored.")
+		log.Warn().Msg("mgmt extensions configuration option has been made redundant and will be ignored.")
 	}
 
 	if cfg.Extensions != nil && cfg.Extensions.APIKey != nil {
-		log.Warn().Msg("The apikey extension configuration will be ignored as API keys " +
+		log.Warn().Msg("apikey extension configuration will be ignored as API keys " +
 			"are now configurable in the HTTP settings.")
 	}
 
 	if cfg.Extensions != nil && cfg.Extensions.UI != nil && cfg.Extensions.UI.Enable != nil && *cfg.Extensions.UI.Enable {
 		// it would make sense to also check for mgmt and user prefs to be enabled,
 		// but those are both enabled by having the search and ui extensions enabled
 		if cfg.Extensions.Search == nil || !*cfg.Extensions.Search.Enable {
-			log.Error().Err(zerr.ErrBadConfig).Msg("UI functionality can't be used without search extension.")
+			log.Error().Err(zerr.ErrBadConfig).Msg("ui functionality can't be used without search extension.")
 
 			return zerr.ErrBadConfig
 		}
@@ -312,7 +312,7 @@ func validateExtensionsConfig(cfg *config.Config, log zlog.Logger) error {
 	//nolint:lll
 	if cfg.Storage.StorageDriver != nil && cfg.Extensions != nil && cfg.Extensions.Search != nil &&
 		cfg.Extensions.Search.Enable != nil && *cfg.Extensions.Search.Enable && cfg.Extensions.Search.CVE != nil {
-		log.Error().Err(zerr.ErrBadConfig).Msg("CVE functionality can't be used with remote storage. Please disable CVE")
+		log.Error().Err(zerr.ErrBadConfig).Msg("cve functionality can't be used with remote storage. Please disable cve")
 
 		return zerr.ErrBadConfig
 	}
@@ -321,7 +321,7 @@ func validateExtensionsConfig(cfg *config.Config, log zlog.Logger) error {
 		//nolint:lll
 		if subPath.StorageDriver != nil && cfg.Extensions != nil && cfg.Extensions.Search != nil &&
 			cfg.Extensions.Search.Enable != nil && *cfg.Extensions.Search.Enable && cfg.Extensions.Search.CVE != nil {
-			log.Error().Err(zerr.ErrBadConfig).Msg("CVE functionality can't be used with remote storage. Please disable CVE")
+			log.Error().Err(zerr.ErrBadConfig).Msg("cveCVE functionality can't be used with remote storage. Please disable cve")
 
 			return zerr.ErrBadConfig
 		}

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 found")
 	}
 }
 
@@ -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")
 }

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("failed 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("failed 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)
 	}
 }

pkg/extensions/extension_metrics.go

@@ -18,10 +18,10 @@ func EnableMetricsExtension(config *config.Config, log log.Logger, rootDir strin
 		if config.Extensions.Metrics.Prometheus.Path == "" {
 			config.Extensions.Metrics.Prometheus.Path = "/metrics"
 
-			log.Warn().Msg("Prometheus instrumentation Path not set, changing to '/metrics'.")
+			log.Warn().Msg("prometheus instrumentation path not set, changing to '/metrics'.")
 		}
 	} else {
-		log.Info().Msg("Metrics config not provided, skipping Metrics config update")
+		log.Info().Msg("metrics config not provided, skipping metrics config update")
 	}
 }
 

pkg/extensions/extension_scrub.go

@@ -25,7 +25,7 @@ func EnableScrubExtension(config *config.Config, log log.Logger, storeController
 		if config.Extensions.Scrub.Interval < minScrubInterval {
 			config.Extensions.Scrub.Interval = minScrubInterval
 
-			log.Warn().Msg("Scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.") //nolint:lll // gofumpt conflicts with lll
+			log.Warn().Msg("scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.") //nolint:lll // gofumpt conflicts with lll
 		}
 
 		generator := &taskGenerator{

pkg/extensions/extension_search.go

@@ -59,7 +59,7 @@ func EnableSearchExtension(conf *config.Config, storeController storage.StoreCon
 func downloadTrivyDB(interval time.Duration, sch *scheduler.Scheduler, cveScanner CveScanner, log log.Logger) {
 	generator := cveinfo.NewDBUpdateTaskGenerator(interval, cveScanner, log)
 
-	log.Info().Msg("Submitting CVE DB update scheduler")
+	log.Info().Msg("submitting CVE DB update scheduler")
 	sch.SubmitGenerator(generator, interval, scheduler.HighPriority)
 }
 
@@ -68,7 +68,7 @@ func startScanner(interval time.Duration, metaDB mTypes.MetaDB, sch *scheduler.S
 ) {
 	generator := cveinfo.NewScanTaskGenerator(metaDB, cveScanner, log)
 
-	log.Info().Msg("Submitting CVE scan scheduler")
+	log.Info().Msg("submitting CVE scan scheduler")
 	sch.SubmitGenerator(generator, interval, scheduler.MediumPriority)
 }
 

pkg/extensions/extension_sync.go

@@ -64,7 +64,7 @@ func EnableSyncExtension(config *config.Config, metaDB mTypes.MetaDB,
 		return onDemand, nil
 	}
 
-	log.Info().Msg("Sync registries config not provided or disabled, skipping sync")
+	log.Info().Msg("sync config not provided or disabled, so not enabling sync")
 
 	return nil, nil //nolint: nilnil
 }

pkg/extensions/monitoring/minimal.go

@@ -314,7 +314,7 @@ func (ms *metricServer) CounterInc(cv *CounterValue) {
 	if err != nil {
 		// The last thing we want is to panic/stop the server due to instrumentation
 		// thus log a message (should be detected during development of new metrics)
-		ms.log.Error().Err(err).Msg("Instrumentation error")
+		ms.log.Error().Err(err).Msg("failed due to instrumentation error")
 
 		return
 	}
@@ -334,7 +334,7 @@ func (ms *metricServer) GaugeSet(gv *GaugeValue) {
 
 	err := sanityChecks(gv.Name, labels, ok, gv.LabelNames, gv.LabelValues)
 	if err != nil {
-		ms.log.Error().Err(err).Msg("Instrumentation error")
+		ms.log.Error().Err(err).Msg("failed due to instrumentation error")
 
 		return
 	}
@@ -353,7 +353,7 @@ func (ms *metricServer) SummaryObserve(sv *SummaryValue) {
 
 	err := sanityChecks(sv.Name, labels, ok, sv.LabelNames, sv.LabelValues)
 	if err != nil {
-		ms.log.Error().Err(err).Msg("Instrumentation error")
+		ms.log.Error().Err(err).Msg("failed due to instrumentation error")
 
 		return
 	}
@@ -374,7 +374,7 @@ func (ms *metricServer) HistogramObserve(hv *HistogramValue) {
 
 	err := sanityChecks(hv.Name, labels, ok, hv.LabelNames, hv.LabelValues)
 	if err != nil {
-		ms.log.Error().Err(err).Msg("Instrumentation error")
+		ms.log.Error().Err(err).Msg("failed due to instrumentation error")
 
 		return
 	}

pkg/extensions/search/cve/cve.go

@@ -199,10 +199,10 @@ func (cveinfo BaseCveInfo) GetImageListWithCVEFixed(repo, cveID string) ([]cvemo
 
 	if len(vulnerableTags) != 0 {
 		cveinfo.Log.Info().Str("repository", repo).Str("cve-id", cveID).
-			Interface("vulnerableTags", vulnerableTags).Msg("Vulnerable tags")
+			Interface("tags", vulnerableTags).Msg("vulnerable tags")
 		fixedTags = GetFixedTags(allTags, vulnerableTags)
 		cveinfo.Log.Info().Str("repository", repo).Str("cve-id", cveID).
-			Interface("fixedTags", fixedTags).Msg("Fixed tags")
+			Interface("tags", fixedTags).Msg("fixed tags")
 	} else {
 		cveinfo.Log.Info().Str("repository", repo).Str("cve-id", cveID).
 			Msg("image does not contain any tag that have given cve")

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{},
@@ -127,13 +129,13 @@ func (gen *scanTaskGenerator) Next() (scheduler.Task, error) {
 	if err != nil {
 		// Do not crash the generator for potential repodb inconistencies
 		// as there may be scannable images not yet scanned
-		gen.log.Warn().Err(err).Msg("Scheduled CVE scan: error while obtaining repo metadata")
+		gen.log.Warn().Err(err).Msg("failed to obtain repo metadata during scheduled CVE scan")
 	}
 
 	// no reposMeta are returned, all results are in already in cache
 	// or manifests cannot be scanned
 	if len(reposMeta) == 0 {
-		gen.log.Info().Msg("Scheduled CVE scan: finished for available images")
+		gen.log.Info().Msg("finished scanning available images during scheduled CVE scan")
 
 		gen.done = true
 
@@ -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
 }

pkg/extensions/search/cve/trivy/scanner.go

@@ -249,7 +249,7 @@ func (scanner Scanner) isManifestScanable(digestStr string) (bool, error) {
 
 	err = json.Unmarshal(manifestData.ManifestBlob, &manifestContent)
 	if err != nil {
-		scanner.log.Error().Err(err).Msg("unable to unmashal manifest blob")
+		scanner.log.Error().Err(err).Msg("failed to unmashal manifest blob")
 
 		return false, zerr.ErrScanNotSupported
 	}
@@ -352,7 +352,7 @@ func (scanner Scanner) ScanImage(image string) (map[string]cvemodel.CVE, error)
 	}
 
 	if err != nil {
-		scanner.log.Error().Err(err).Str("image", originalImageInput).Msg("unable to scan image")
+		scanner.log.Error().Err(err).Str("image", originalImageInput).Msg("failed to scan image")
 
 		return map[string]cvemodel.CVE{}, err
 	}
@@ -507,18 +507,16 @@ func (scanner Scanner) UpdateDB() error {
 }
 
 func (scanner Scanner) updateDB(dbDir string) error {
-	scanner.log.Debug().Str("dbDir", dbDir).Msg("Download Trivy DB to destination dir")
-
 	ctx := context.Background()
 
 	registryOpts := fanalTypes.RegistryOptions{Insecure: false}
 
-	scanner.log.Debug().Str("dbDir", dbDir).Msg("Started downloading Trivy DB to destination dir")
+	scanner.log.Debug().Str("dbDir", dbDir).Msg("started downloading trivy-db to destination dir")
 
 	err := operation.DownloadDB(ctx, "dev", dbDir, scanner.dbRepository, false, false, registryOpts)
 	if err != nil {
 		scanner.log.Error().Err(err).Str("dbDir", dbDir).
-			Str("dbRepository", scanner.dbRepository).Msg("Error downloading Trivy DB to destination dir")
+			Str("dbRepository", scanner.dbRepository).Msg("failed to download trivy-db to destination dir")
 
 		return err
 	}
@@ -528,13 +526,13 @@ func (scanner Scanner) updateDB(dbDir string) error {
 
 		if err := javadb.Update(); err != nil {
 			scanner.log.Error().Err(err).Str("dbDir", dbDir).
-				Str("javaDBRepository", scanner.javaDBRepository).Msg("Error downloading Trivy Java DB to destination dir")
+				Str("javaDBRepository", scanner.javaDBRepository).Msg("failed to download trivy-java-db to destination dir")
 
 			return err
 		}
 	}
 
-	scanner.log.Debug().Str("dbDir", dbDir).Msg("Finished downloading Trivy DB to destination dir")
+	scanner.log.Debug().Str("dbDir", dbDir).Msg("finished downloading trivy-db to destination dir")
 
 	return nil
 }