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]" | grep -v -E "Msg\(\"HTTP|OpenID|OAuth|TLS"
+          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("cve functionality can't be used with remote storage - please disable cve")
 
 			return zerr.ErrBadConfig
 		}
@@ -534,7 +534,7 @@ func applyDefaultValues(config *config.Config, viperInstance *viper.Viper, log z
 				if config.Extensions.Search.CVE.UpdateInterval < defaultUpdateInterval {
 					config.Extensions.Search.CVE.UpdateInterval = defaultUpdateInterval
 
-					log.Warn().Msg("CVE update interval set to too-short interval < 2h, " +
+					log.Warn().Msg("cve update interval set to too-short interval < 2h, " +
 						"changing update duration to 2 hours and continuing.")
 				}
 
@@ -544,15 +544,15 @@ func applyDefaultValues(config *config.Config, viperInstance *viper.Viper, log z
 
 				if config.Extensions.Search.CVE.Trivy.DBRepository == "" {
 					defaultDBDownloadURL := "ghcr.io/aquasecurity/trivy-db"
-					log.Info().Str("trivyDownloadURL", defaultDBDownloadURL).
-						Msg("Config: using default Trivy DB download URL.")
+					log.Info().Str("url", defaultDBDownloadURL).
+						Msg("config: using default trivy-db download URL.")
 					config.Extensions.Search.CVE.Trivy.DBRepository = defaultDBDownloadURL
 				}
 
 				if config.Extensions.Search.CVE.Trivy.JavaDBRepository == "" {
 					defaultJavaDBDownloadURL := "ghcr.io/aquasecurity/trivy-java-db"
-					log.Info().Str("trivyJavaDownloadURL", defaultJavaDBDownloadURL).
-						Msg("Config: using default Trivy Java DB download URL.")
+					log.Info().Str("url", defaultJavaDBDownloadURL).
+						Msg("config: using default trivy-java-db download URL.")
 					config.Extensions.Search.CVE.Trivy.JavaDBRepository = defaultJavaDBDownloadURL
 				}
 			}
@@ -621,7 +621,7 @@ func applyDefaultValues(config *config.Config, viperInstance *viper.Viper, log z
 		cachePath := path.Join(cacheDir, storageConstants.BoltdbName+storageConstants.DBExtensionName)
 
 		if _, err := os.Stat(cachePath); err == nil {
-			log.Info().Msg("Config: dedupe set to false for s3 driver but used to be true.")
+			log.Info().Msg("config: dedupe set to false for s3 driver but used to be true.")
 			log.Info().Str("cache path", cachePath).Msg("found cache database")
 
 			config.Storage.RemoteCache = false
@@ -642,7 +642,7 @@ func applyDefaultValues(config *config.Config, viperInstance *viper.Viper, log z
 			subpathCachePath := path.Join(subpathCacheDir, storageConstants.BoltdbName+storageConstants.DBExtensionName)
 
 			if _, err := os.Stat(subpathCachePath); err == nil {
-				log.Info().Msg("Config: dedupe set to false for s3 driver but used to be true. ")
+				log.Info().Msg("config: dedupe set to false for s3 driver but used to be true. ")
 				log.Info().Str("cache path", subpathCachePath).Msg("found cache database")
 
 				storageConfig.RemoteCache = false
@@ -701,14 +701,14 @@ func LoadConfiguration(config *config.Config, configPath string) error {
 	viperInstance.SetConfigFile(configPath)
 
 	if err := viperInstance.ReadInConfig(); err != nil {
-		log.Error().Err(err).Msg("error while reading configuration")
+		log.Error().Err(err).Msg("failed to read configuration")
 
 		return err
 	}
 
 	metaData := &mapstructure.Metadata{}
 	if err := viperInstance.Unmarshal(&config, metadataConfig(metaData)); err != nil {
-		log.Error().Err(err).Msg("error while unmarshaling new config")
+		log.Error().Err(err).Msg("failed to unmarshaling new config")
 
 		return err
 	}

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{
@@ -44,7 +44,7 @@ func EnableScrubExtension(config *config.Config, log log.Logger, storeController
 			}
 		}
 	} else {
-		log.Info().Msg("Scrub config not provided, skipping scrub")
+		log.Info().Msg("scrub config not provided, skipping scrub")
 	}
 }
 

pkg/extensions/extension_search.go

@@ -52,14 +52,14 @@ func EnableSearchExtension(conf *config.Config, storeController storage.StoreCon
 		downloadTrivyDB(updateInterval, taskScheduler, cveScanner, log)
 		startScanner(scanInterval, metaDB, taskScheduler, cveScanner, log)
 	} else {
-		log.Info().Msg("CVE config not provided, skipping CVE update")
+		log.Info().Msg("cve config not provided, skipping cve-db update")
 	}
 }
 
 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 generator to 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 generator to 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")