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/authn.go

@@ -444,7 +444,7 @@ func bearerAuthHandler(ctlr *Controller) mux.MiddlewareFunc {
 		EmptyDefaultNamespace: true,
 	})
 	if err != nil {
-		ctlr.Log.Panic().Err(err).Msg("error creating bearer authorizer")
+		ctlr.Log.Panic().Err(err).Msg("failed to create bearer authorizer")
 	}
 
 	return func(next http.Handler) http.Handler {

pkg/api/routes.go

@@ -547,7 +547,7 @@ func getReferrers(ctx context.Context, routeHandler *RouteHandler,
 			if errSync := routeHandler.c.SyncOnDemand.SyncReference(ctx, name, digest.String(),
 				syncConstants.OCI); errSync != nil {
 				routeHandler.c.Log.Err(errSync).Str("repository", name).Str("reference", digest.String()).
-					Msg("error encounter while syncing OCI reference for image")
+					Msg("failed to sync OCI reference for image")
 			}
 
 			refs, err = imgStore.GetReferrers(name, digest, artifactTypes)
@@ -605,7 +605,7 @@ func (rh *RouteHandler) GetReferrers(response http.ResponseWriter, request *http
 			rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("manifest not found")
 			response.WriteHeader(http.StatusNotFound)
 		} else {
-			rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("unable to get references")
+			rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("failed to get references")
 			response.WriteHeader(http.StatusInternalServerError)
 		}
 
@@ -614,7 +614,7 @@ func (rh *RouteHandler) GetReferrers(response http.ResponseWriter, request *http
 
 	out, err := json.Marshal(referrers)
 	if err != nil {
-		rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("unable to marshal json")
+		rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("failed to marshal json")
 		response.WriteHeader(http.StatusInternalServerError)
 
 		return
@@ -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)
@@ -1918,7 +1914,7 @@ func getImageManifest(ctx context.Context, routeHandler *RouteHandler, imgStore
 
 		if errSync := routeHandler.c.SyncOnDemand.SyncImage(ctx, name, reference); errSync != nil {
 			routeHandler.c.Log.Err(errSync).Str("repository", name).Str("reference", reference).
-				Msg("error encounter while syncing image")
+				Msg("failed to sync image")
 		}
 	}
 
@@ -1939,7 +1935,7 @@ func getOrasReferrers(ctx context.Context, routeHandler *RouteHandler,
 			if errSync := routeHandler.c.SyncOnDemand.SyncReference(ctx, name, digest.String(),
 				syncConstants.Oras); errSync != nil {
 				routeHandler.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).
-					Msg("unable to get references")
+					Msg("failed to get references")
 			}
 
 			refs, err = imgStore.GetOrasReferrers(name, digest, artifactType)
@@ -2009,7 +2005,7 @@ func (rh *RouteHandler) GetOrasReferrers(response http.ResponseWriter, request *
 			rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("manifest not found")
 			response.WriteHeader(http.StatusNotFound)
 		} else {
-			rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("unable to get references")
+			rh.c.Log.Error().Err(err).Str("name", name).Str("digest", digest.String()).Msg("failed to get references")
 			response.WriteHeader(http.StatusInternalServerError)
 		}
 
@@ -2039,7 +2035,7 @@ type APIKeyPayload struct { //nolint:revive
 func (rh *RouteHandler) GetAPIKeys(resp http.ResponseWriter, req *http.Request) {
 	apiKeys, err := rh.c.MetaDB.GetUserAPIKeys(req.Context())
 	if err != nil {
-		rh.c.Log.Error().Err(err).Msg("error getting list of API keys for user")
+		rh.c.Log.Error().Err(err).Msg("failed to get list of api keys for user")
 		resp.WriteHeader(http.StatusInternalServerError)
 
 		return
@@ -2055,7 +2051,7 @@ func (rh *RouteHandler) GetAPIKeys(resp http.ResponseWriter, req *http.Request)
 
 	data, err := json.Marshal(apiKeyResponse)
 	if err != nil {
-		rh.c.Log.Error().Err(err).Msg("unable to marshal api key response")
+		rh.c.Log.Error().Err(err).Msg("failed to marshal api key response")
 
 		resp.WriteHeader(http.StatusInternalServerError)
 
@@ -2083,7 +2079,7 @@ func (rh *RouteHandler) CreateAPIKey(resp http.ResponseWriter, req *http.Request
 
 	body, err := io.ReadAll(req.Body)
 	if err != nil {
-		rh.c.Log.Error().Msg("unable to read request body")
+		rh.c.Log.Error().Msg("failed to read request body")
 		resp.WriteHeader(http.StatusInternalServerError)
 
 		return
@@ -2138,7 +2134,7 @@ func (rh *RouteHandler) CreateAPIKey(resp http.ResponseWriter, req *http.Request
 
 	err = rh.c.MetaDB.AddUserAPIKey(req.Context(), hashedAPIKey, apiKeyDetails)
 	if err != nil {
-		rh.c.Log.Error().Err(err).Msg("error storing API key")
+		rh.c.Log.Error().Err(err).Msg("failed to store api key")
 		resp.WriteHeader(http.StatusInternalServerError)
 
 		return
@@ -2156,7 +2152,7 @@ func (rh *RouteHandler) CreateAPIKey(resp http.ResponseWriter, req *http.Request
 
 	data, err := json.Marshal(apiKeyResponse)
 	if err != nil {
-		rh.c.Log.Error().Err(err).Msg("unable to marshal api key response")
+		rh.c.Log.Error().Err(err).Msg("failed to marshal api key response")
 
 		resp.WriteHeader(http.StatusInternalServerError)
 
@@ -2191,7 +2187,7 @@ func (rh *RouteHandler) RevokeAPIKey(resp http.ResponseWriter, req *http.Request
 
 	err := rh.c.MetaDB.DeleteUserAPIKey(req.Context(), keyID)
 	if err != nil {
-		rh.c.Log.Error().Err(err).Str("keyID", keyID).Msg("error deleting API key")
+		rh.c.Log.Error().Err(err).Str("keyID", keyID).Msg("failed to delete api key")
 		resp.WriteHeader(http.StatusInternalServerError)
 
 		return

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/config_reloader.go

@@ -112,7 +112,7 @@ func (hr *HotReloader) Start() context.Context {
 		}()
 
 		if err := hr.watcher.Add(hr.filePath); err != nil {
-			log.Error().Err(err).Str("config", hr.filePath).Msg("error adding config file to FsNotify watcher")
+			log.Error().Err(err).Str("config", hr.filePath).Msg("failed to add config file to fsnotity watcher")
 			panic(err)
 		}
 

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