converted to structured logging by using logrus

changed from capnslog to logrus for logging JSON structured message. finished issue #383
quay · May 4, 2017 · 9306e99 · 9306e99
1 parent d0ca4d1
commit 9306e99
Show file tree

Hide file tree

Showing 30 changed files with 227 additions and 173 deletions.
diff --git a/api/api.go b/api/api.go
@@ -23,7 +23,7 @@ import (
 	"strconv"
 	"time"
 
-	"github.com/coreos/pkg/capnslog"
+	log "github.com/sirupsen/logrus"
 	"github.com/tylerb/graceful"
 
 	"github.com/coreos/clair/database"
@@ -32,8 +32,6 @@ import (
 
 const timeoutResponse = `{"Error":{"Message":"Clair failed to respond within the configured timeout window.","Type":"Timeout"}}`
 
-var log = capnslog.NewPackageLogger("github.com/coreos/clair", "api")
-
 // Config is the configuration for the API service.
 type Config struct {
 	Port                      int
@@ -48,14 +46,14 @@ func Run(cfg *Config, store database.Datastore, st *stopper.Stopper) {
 
 	// Do not run the API service if there is no config.
 	if cfg == nil {
-		log.Infof("main API service is disabled.")
+		log.Info("main API service is disabled.")
 		return
 	}
-	log.Infof("starting main API on port %d.", cfg.Port)
+	log.WithField("port", cfg.Port).Info("starting main API")
 
 	tlsConfig, err := tlsClientConfig(cfg.CAFile)
 	if err != nil {
-		log.Fatalf("could not initialize client cert authentication: %s\n", err)
+		log.WithError(err).Fatal("could not initialize client cert authentication")
 	}
 	if tlsConfig != nil {
 		log.Info("main API configured with client certificate authentication")
@@ -81,10 +79,10 @@ func RunHealth(cfg *Config, store database.Datastore, st *stopper.Stopper) {
 
 	// Do not run the API service if there is no config.
 	if cfg == nil {
-		log.Infof("health API service is disabled.")
+		log.Info("health API service is disabled.")
 		return
 	}
-	log.Infof("starting health API on port %d.", cfg.HealthPort)
+	log.WithField("port", cfg.HealthPort).Info("starting health API")
 
 	srv := &graceful.Server{
 		Timeout:          10 * time.Second, // Interrupt health checks when stopping

diff --git a/api/router.go b/api/router.go
@@ -19,6 +19,7 @@ import (
 	"strings"
 
 	"github.com/julienschmidt/httprouter"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair/api/v1"
 	"github.com/coreos/clair/database"
@@ -52,7 +53,7 @@ func (rtr router) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		return
 	}
 
-	log.Infof("%d %s %s %s", http.StatusNotFound, r.Method, r.RequestURI, r.RemoteAddr)
+	log.WithFields(log.Fields{"status": http.StatusNotFound, "method": r.Method, "request uri": r.RequestURI, "remote addr": r.RemoteAddr}).Info("Served HTTP request")
 	http.NotFound(w, r)
 }
 

diff --git a/api/v1/models.go b/api/v1/models.go
@@ -21,15 +21,12 @@ import (
 	"fmt"
 	"time"
 
-	"github.com/coreos/pkg/capnslog"
 	"github.com/fernet/fernet-go"
 
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/ext/versionfmt"
 )
 
-var log = capnslog.NewPackageLogger("github.com/coreos/clair", "v1")
-
 type Error struct {
 	Message string `json:"Message,omitempty"`
 }

diff --git a/api/v1/router.go b/api/v1/router.go
@@ -22,6 +22,7 @@ import (
 
 	"github.com/julienschmidt/httprouter"
 	"github.com/prometheus/client_golang/prometheus"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair/database"
 )
@@ -53,7 +54,7 @@ func httpHandler(h handler, ctx *context) httprouter.Handle {
 			WithLabelValues(route, statusStr).
 			Observe(float64(time.Since(start).Nanoseconds()) / float64(time.Millisecond))
 
-		log.Infof("%s \"%s %s\" %s (%s)", r.RemoteAddr, r.Method, r.RequestURI, statusStr, time.Since(start))
+		log.WithFields(log.Fields{"remote addr": r.RemoteAddr, "method": r.Method, "request uri": r.RequestURI, "status": statusStr, "elapsed time": time.Since(start)}).Info("Handled HTTP request")
 	}
 }
 

diff --git a/api/v1/routes.go b/api/v1/routes.go
@@ -24,6 +24,7 @@ import (
 
 	"github.com/julienschmidt/httprouter"
 	"github.com/prometheus/client_golang/prometheus"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair"
 	"github.com/coreos/clair/database"
@@ -90,7 +91,7 @@ func writeResponse(w http.ResponseWriter, r *http.Request, status int, resp inte
 		case *json.MarshalerError, *json.UnsupportedTypeError, *json.UnsupportedValueError:
 			panic("v1: failed to marshal response: " + err.Error())
 		default:
-			log.Warningf("failed to write response: %s", err.Error())
+			log.WithError(err).Warning("failed to write response")
 		}
 	}
 }

diff --git a/cmd/clair/main.go b/cmd/clair/main.go
@@ -25,12 +25,13 @@ import (
 	"syscall"
 	"time"
 
-	"github.com/coreos/pkg/capnslog"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair"
 	"github.com/coreos/clair/api"
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/ext/imagefmt"
+	"github.com/coreos/clair/pkg/formatter"
 	"github.com/coreos/clair/pkg/stopper"
 
 	// Register database driver.
@@ -56,8 +57,6 @@ import (
 	_ "github.com/coreos/clair/ext/vulnsrc/ubuntu"
 )
 
-var log = capnslog.NewPackageLogger("github.com/coreos/clair/cmd/clair", "main")
-
 func waitForSignals(signals ...os.Signal) {
 	interrupts := make(chan os.Signal, 1)
 	signal.Notify(interrupts, signals...)
@@ -67,12 +66,12 @@ func waitForSignals(signals ...os.Signal) {
 func startCPUProfiling(path string) *os.File {
 	f, err := os.Create(path)
 	if err != nil {
-		log.Fatalf("failed to create profile file: %s", err)
+		log.WithError(err).Fatal("failed to create profile file")
 	}
 
 	err = pprof.StartCPUProfile(f)
 	if err != nil {
-		log.Fatalf("failed to start CPU profiling: %s", err)
+		log.WithError(err).Fatal("failed to start CPU profiling")
 	}
 
 	log.Info("started CPU profiling")
@@ -131,20 +130,22 @@ func main() {
 	for _, bin := range []string{"git", "bzr", "rpm", "xz"} {
 		_, err := exec.LookPath(bin)
 		if err != nil {
-			log.Fatalf("failed to find dependency: %s", bin)
+			log.WithError(err).WithField("dependency", bin).Fatal("failed to find dependency")
 		}
 	}
 
 	// Load configuration
 	config, err := LoadConfig(*flagConfigPath)
 	if err != nil {
-		log.Fatalf("failed to load configuration: %s", err)
+		log.WithError(err).Fatal("failed to load configuration")
 	}
 
 	// Initialize logging system
-	logLevel, err := capnslog.ParseLevel(strings.ToUpper(*flagLogLevel))
-	capnslog.SetGlobalLogLevel(logLevel)
-	capnslog.SetFormatter(capnslog.NewPrettyFormatter(os.Stdout, false))
+
+	logLevel, err := log.ParseLevel(strings.ToUpper(*flagLogLevel))
+	log.SetLevel(logLevel)
+	log.SetOutput(os.Stdout)
+	log.SetFormatter(&formatter.JSONExtendedFormatter{ShowLn: true})
 
 	// Enable CPU Profiling if specified
 	if *flagCPUProfilePath != "" {

diff --git a/database/pgsql/keyvalue.go b/database/pgsql/keyvalue.go
@@ -18,6 +18,8 @@ import (
 	"database/sql"
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/coreos/clair/pkg/commonerr"
 )
 

diff --git a/database/pgsql/layer.go b/database/pgsql/layer.go
@@ -20,6 +20,7 @@ import (
 	"time"
 
 	"github.com/guregu/null/zero"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/pkg/commonerr"
@@ -92,11 +93,11 @@ func (pgSQL *pgSQL) FindLayer(name string, withFeatures, withVulnerabilities boo
 
 		_, err = tx.Exec(disableHashJoin)
 		if err != nil {
-			log.Warningf("FindLayer: could not disable hash join: %s", err)
+			log.WithError(err).Warningf("FindLayer: could not disable hash join")
 		}
 		_, err = tx.Exec(disableMergeJoin)
 		if err != nil {
-			log.Warningf("FindLayer: could not disable merge join: %s", err)
+			log.WithError(err).Warningf("FindLayer: could not disable merge join")
 		}
 
 		t = time.Now()
@@ -164,7 +165,7 @@ func getLayerFeatureVersions(tx *sql.Tx, layerID int) ([]database.FeatureVersion
 		case "del":
 			delete(mapFeatureVersions, fv.ID)
 		default:
-			log.Warningf("unknown Layer_diff_FeatureVersion's modification: %s", modification)
+			log.WithField("modification", modification).Warning("unknown Layer_diff_FeatureVersion's modification")
 			return featureVersions, database.ErrInconsistent
 		}
 	}

diff --git a/database/pgsql/lock.go b/database/pgsql/lock.go
@@ -17,6 +17,8 @@ package pgsql
 import (
 	"time"
 
+	log "github.com/sirupsen/logrus"
+
 	"github.com/coreos/clair/pkg/commonerr"
 )
 

diff --git a/database/pgsql/notification.go b/database/pgsql/notification.go
@@ -18,10 +18,12 @@ import (
 	"database/sql"
 	"time"
 
-	"github.com/coreos/clair/database"
-	"github.com/coreos/clair/pkg/commonerr"
 	"github.com/guregu/null/zero"
 	"github.com/pborman/uuid"
+	log "github.com/sirupsen/logrus"
+
+	"github.com/coreos/clair/database"
+	"github.com/coreos/clair/pkg/commonerr"
 )
 
 // do it in tx so we won't insert/update a vuln without notification and vice-versa.
@@ -177,7 +179,7 @@ func (pgSQL *pgSQL) loadLayerIntroducingVulnerability(vulnerability *database.Vu
 
 	_, err = tx.Exec(disableHashJoin)
 	if err != nil {
-		log.Warningf("searchNotificationLayerIntroducingVulnerability: could not disable hash join: %s", err)
+		log.WithError(err).Warning("searchNotificationLayerIntroducingVulnerability: could not disable hash join")
 	}
 
 	// We do `defer observeQueryTime` here because we don't want to observe invalid calls.

diff --git a/database/pgsql/pgsql.go b/database/pgsql/pgsql.go
@@ -25,20 +25,18 @@ import (
 
 	"gopkg.in/yaml.v2"
 
-	"github.com/coreos/pkg/capnslog"
 	"github.com/hashicorp/golang-lru"
 	"github.com/lib/pq"
 	"github.com/prometheus/client_golang/prometheus"
 	"github.com/remind101/migrate"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/database/pgsql/migrations"
 	"github.com/coreos/clair/pkg/commonerr"
 )
 
 var (
-	log = capnslog.NewPackageLogger("github.com/coreos/clair", "pgsql")
-
 	promErrorsTotal = prometheus.NewCounterVec(prometheus.CounterOpts{
 		Name: "clair_pgsql_errors_total",
 		Help: "Number of errors that PostgreSQL requests generated.",
@@ -283,7 +281,7 @@ func handleError(desc string, err error) error {
 		return commonerr.ErrNotFound
 	}
 
-	log.Errorf("%s: %v", desc, err)
+	log.WithError(err).WithField("Description", desc).Error("Handled Database Error")
 	promErrorsTotal.WithLabelValues(desc).Inc()
 
 	if _, o := err.(*pq.Error); o || err == sql.ErrTxDone || strings.HasPrefix(err.Error(), "sql:") {

diff --git a/database/pgsql/vulnerability.go b/database/pgsql/vulnerability.go
@@ -20,10 +20,12 @@ import (
 	"reflect"
 	"time"
 
+	"github.com/guregu/null/zero"
+	log "github.com/sirupsen/logrus"
+
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/ext/versionfmt"
 	"github.com/coreos/clair/pkg/commonerr"
-	"github.com/guregu/null/zero"
 )
 
 // compareStringLists returns the strings that are present in X but not in Y.

diff --git a/ext/featurefmt/apk/apk.go b/ext/featurefmt/apk/apk.go
@@ -19,7 +19,7 @@ import (
 	"bufio"
 	"bytes"
 
-	"github.com/coreos/pkg/capnslog"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/ext/featurefmt"
@@ -28,8 +28,6 @@ import (
 	"github.com/coreos/clair/pkg/tarutil"
 )
 
-var log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/featurefmt/apk")
-
 func init() {
 	featurefmt.RegisterLister("apk", &lister{})
 }
@@ -62,7 +60,7 @@ func (l lister) ListFeatures(files tarutil.FilesMap) ([]database.FeatureVersion,
 			version := string(line[2:])
 			err := versionfmt.Valid(dpkg.ParserName, version)
 			if err != nil {
-				log.Warningf("could not parse package version '%s': %s. skipping", version, err.Error())
+				log.WithError(err).WithField("version", version).Warning("could not parse package version. skipping")
 			} else {
 				ipkg.Version = version
 			}

diff --git a/ext/featurefmt/dpkg/dpkg.go b/ext/featurefmt/dpkg/dpkg.go
@@ -20,7 +20,7 @@ import (
 	"regexp"
 	"strings"
 
-	"github.com/coreos/pkg/capnslog"
+	log "github.com/sirupsen/logrus"
 
 	"github.com/coreos/clair/database"
 	"github.com/coreos/clair/ext/featurefmt"
@@ -30,8 +30,6 @@ import (
 )
 
 var (
-	log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/featurefmt/dpkg")
-
 	dpkgSrcCaptureRegexp      = regexp.MustCompile(`Source: (?P<name>[^\s]*)( \((?P<version>.*)\))?`)
 	dpkgSrcCaptureRegexpNames = dpkgSrcCaptureRegexp.SubexpNames()
 )
@@ -79,7 +77,7 @@ func (l lister) ListFeatures(files tarutil.FilesMap) ([]database.FeatureVersion,
 				version := md["version"]
 				err = versionfmt.Valid(dpkg.ParserName, version)
 				if err != nil {
-					log.Warningf("could not parse package version '%s': %s. skipping", string(line[1]), err.Error())
+					log.WithError(err).WithField("version", string(line[1])).Warning("could not parse package version. skipping")
 				} else {
 					pkg.Version = version
 				}
@@ -93,7 +91,7 @@ func (l lister) ListFeatures(files tarutil.FilesMap) ([]database.FeatureVersion,
 			version := strings.TrimPrefix(line, "Version: ")
 			err = versionfmt.Valid(dpkg.ParserName, version)
 			if err != nil {
-				log.Warningf("could not parse package version '%s': %s. skipping", string(line[1]), err.Error())
+				log.WithError(err).WithField("version", string(line[1])).Warning("could not parse package version. skipping")
 			} else {
 				pkg.Version = version
 			}