fix(log): refactor some logs

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

.github/workflows/golangci-lint.yaml

@@ -45,3 +45,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

errors/errors.go

@@ -89,8 +89,8 @@ var (
 	ErrImgStoreNotFound               = errors.New("routes: image store not found corresponding to given route")
 	ErrEmptyValue                     = errors.New("cache: empty value")
 	ErrEmptyRepoList                  = errors.New("search: no repository found")
-	ErrCVESearchDisabled              = errors.New("search: CVE search is disabled")
-	ErrCVEDBNotFound                  = errors.New("cve: CVE DB is not present")
+	ErrCVESearchDisabled              = errors.New("search: cve search is disabled")
+	ErrCVEDBNotFound                  = errors.New("cve: cve-db is not present")
 	ErrInvalidRepositoryName          = errors.New("repository: not a valid repository name")
 	ErrSyncMissingCatalog             = errors.New("sync: couldn't fetch upstream registry's catalog")
 	ErrMethodNotSupported             = errors.New("storage: method not supported")

pkg/api/authn.go

@@ -419,7 +419,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

@@ -549,7 +549,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)
@@ -607,7 +607,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)
 		}
 
@@ -616,7 +616,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
@@ -1223,8 +1223,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)
@@ -1496,8 +1494,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)
@@ -1920,7 +1916,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")
 		}
 	}
 
@@ -1941,7 +1937,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)
@@ -2011,7 +2007,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)
 		}
 
@@ -2041,7 +2037,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
@@ -2057,7 +2053,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)
 
@@ -2085,7 +2081,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
@@ -2141,7 +2137,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
@@ -2159,7 +2155,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)
 
@@ -2194,7 +2190,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/client/cve_cmd_test.go

@@ -181,7 +181,8 @@ func TestNegativeServerResponse(t *testing.T) {
 
 		test.WaitTillServerReady(url)
 
-		_, err = test.ReadLogFileAndSearchString(logPath, "DB update completed, next update scheduled", 90*time.Second)
+		_, err = test.ReadLogFileAndSearchString(logPath, "cve-db update completed, next update scheduled after interval",
+			90*time.Second)
 		if err != nil {
 			panic(err)
 		}
@@ -263,7 +264,8 @@ func TestServerCVEResponse(t *testing.T) {
 		panic(err)
 	}
 
-	_, err = test.ReadLogFileAndSearchString(logPath, "DB update completed, next update scheduled", 90*time.Second)
+	_, err = test.ReadLogFileAndSearchString(logPath, "cve-db update completed, next update scheduled after interval",
+		90*time.Second)
 	if err != nil {
 		panic(err)
 	}

pkg/cli/server/config_reloader.go

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

pkg/cli/server/config_reloader_test.go

@@ -491,7 +491,7 @@ func TestConfigReloader(t *testing.T) {
 		time.Sleep(5 * time.Second)
 
 		found, err := test.ReadLogFileAndSearchString(logFile.Name(),
-			"Error downloading Trivy DB to destination dir", 30*time.Second)
+			"failed to download trivy-db to destination dir", 30*time.Second)
 		So(err, ShouldBeNil)
 		So(found, ShouldBeTrue)
 

pkg/cli/server/extensions_test.go

@@ -805,7 +805,7 @@ func TestServeScrubExtension(t *testing.T) {
 		So(dataStr, ShouldContainSubstring,
 			"\"Extensions\":{\"Search\":null,\"Sync\":null,\"Metrics\":null,\"Scrub\":{\"Enable\":true,\"Interval\":86400000000000},\"Lint\":null") //nolint:lll // gofumpt conflicts with lll
 		So(dataStr, ShouldNotContainSubstring,
-			"Scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
+			"scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
 	})
 
 	Convey("scrub implicitly enabled, but with scrub interval param set", t, func(c C) {
@@ -837,7 +837,7 @@ func TestServeScrubExtension(t *testing.T) {
 		dataStr := string(data)
 		So(dataStr, ShouldContainSubstring, "\"Scrub\":{\"Enable\":true,\"Interval\":3600000000000}")
 		So(dataStr, ShouldContainSubstring,
-			"Scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
+			"scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
 	})
 
 	Convey("scrub explicitly enabled, but without scrub interval param set", t, func(c C) {
@@ -869,7 +869,7 @@ func TestServeScrubExtension(t *testing.T) {
 		So(dataStr, ShouldContainSubstring,
 			"\"Extensions\":{\"Search\":null,\"Sync\":null,\"Metrics\":null,\"Scrub\":{\"Enable\":true,\"Interval\":86400000000000},\"Lint\":null") //nolint:lll // gofumpt conflicts with lll
 		So(dataStr, ShouldNotContainSubstring,
-			"Scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
+			"scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
 	})
 
 	Convey("scrub explicitly disabled", t, func(c C) {
@@ -899,9 +899,9 @@ func TestServeScrubExtension(t *testing.T) {
 		defer os.Remove(logPath) // clean up
 		dataStr := string(data)
 		So(dataStr, ShouldContainSubstring, "\"Scrub\":{\"Enable\":false,\"Interval\":86400000000000}")
-		So(dataStr, ShouldContainSubstring, "Scrub config not provided, skipping scrub")
+		So(dataStr, ShouldContainSubstring, "scrub config not provided, skipping scrub")
 		So(dataStr, ShouldNotContainSubstring,
-			"Scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
+			"scrub interval set to too-short interval < 2h, changing scrub duration to 2 hours and continuing.")
 	})
 }
 
@@ -1066,7 +1066,7 @@ func TestServeSearchEnabledCVE(t *testing.T) {
 		So(found, ShouldBeTrue)
 		So(err, ShouldBeNil)
 
-		found, err = ReadLogFileAndSearchString(logPath, "updating the CVE database", readLogFileTimeout)
+		found, err = ReadLogFileAndSearchString(logPath, "updating cve-db", readLogFileTimeout)
 		So(found, ShouldBeTrue)
 		So(err, ShouldBeNil)
 	})
@@ -1151,8 +1151,8 @@ func TestServeSearchDisabled(t *testing.T) {
 		defer os.Remove(logPath) // clean up
 		dataStr := string(data)
 		So(dataStr, ShouldContainSubstring,
-			"\"Search\":{\"Enable\":false,\"CVE\":{\"UpdateInterval\":10800000000000,\"Trivy\":null}")
-		So(dataStr, ShouldContainSubstring, "CVE config not provided, skipping CVE update")
+			`"Search":{"Enable":false,"CVE":{"UpdateInterval":10800000000000,"Trivy":null}`)
+		So(dataStr, ShouldContainSubstring, "cve config not provided, skipping cve-db update")
 		So(dataStr, ShouldNotContainSubstring,
 			"CVE update interval set to too-short interval < 2h, changing update duration to 2 hours and continuing.")
 	})