From 9306e9936817b8b2624033fede6a0d7d9c2593a1 Mon Sep 17 00:00:00 2001 From: Sida Chen Date: Thu, 4 May 2017 13:21:25 -0400 Subject: [PATCH] converted to structured logging by using logrus changed from capnslog to logrus for logging JSON structured message. finished issue #383 --- api/api.go | 14 +++---- api/router.go | 3 +- api/v1/models.go | 3 -- api/v1/router.go | 3 +- api/v1/routes.go | 3 +- cmd/clair/main.go | 21 +++++----- database/pgsql/keyvalue.go | 2 + database/pgsql/layer.go | 7 ++-- database/pgsql/lock.go | 2 + database/pgsql/notification.go | 8 ++-- database/pgsql/pgsql.go | 6 +-- database/pgsql/vulnerability.go | 4 +- ext/featurefmt/apk/apk.go | 6 +-- ext/featurefmt/dpkg/dpkg.go | 8 ++-- ext/featurefmt/rpm/rpm.go | 12 +++--- ext/featurens/driver.go | 8 ++-- ext/imagefmt/driver.go | 9 ++-- ext/notification/driver.go | 4 -- ext/versionfmt/driver.go | 4 -- ext/vulnmdsrc/nvd/nvd.go | 16 +++---- ext/vulnmdsrc/nvd/xml.go | 4 +- ext/vulnsrc/alpine/alpine.go | 13 +++--- ext/vulnsrc/debian/debian.go | 16 ++++--- ext/vulnsrc/oracle/oracle.go | 25 ++++++----- ext/vulnsrc/rhel/rhel.go | 22 +++++----- ext/vulnsrc/ubuntu/ubuntu.go | 25 +++++------ notifier.go | 24 ++++++----- pkg/formatter/formatter.go | 74 +++++++++++++++++++++++++++++++++ updater.go | 26 ++++++------ worker.go | 28 ++++++------- 30 files changed, 227 insertions(+), 173 deletions(-) create mode 100644 pkg/formatter/formatter.go diff --git a/api/api.go b/api/api.go index 9da5073a..b2cb028d 100644 --- 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 index 74658814..bd81d93e 100644 --- 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 index 93d048b9..866d71a5 100644 --- 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 index 44608949..faeed9a5 100644 --- 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 index eab3115c..f44dde67 100644 --- 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 index 11f0de4c..efed24ba 100644 --- 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 index 14730d51..ab599588 100644 --- 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 index 32f1cc29..095e6307 100644 --- 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 index f677232e..d3521b75 100644 --- 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 index 6d079753..f8c6960d 100644 --- 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 index 3353ddcc..34504a9a 100644 --- a/database/pgsql/pgsql.go +++ b/database/pgsql/pgsql.go @@ -25,11 +25,11 @@ 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" @@ -37,8 +37,6 @@ import ( ) 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 index f7a88199..efb57392 100644 --- 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 index f8357ba4..2729a52b 100644 --- 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 index e2ebc428..3a77ce4f 100644 --- 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[^\s]*)( \((?P.*)\))?`) 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 } diff --git a/ext/featurefmt/rpm/rpm.go b/ext/featurefmt/rpm/rpm.go index b1e9b6e8..a54d69bc 100644 --- a/ext/featurefmt/rpm/rpm.go +++ b/ext/featurefmt/rpm/rpm.go @@ -22,7 +22,7 @@ import ( "os/exec" "strings" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/featurefmt" @@ -32,8 +32,6 @@ import ( "github.com/coreos/clair/pkg/tarutil" ) -var log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/featurefmt/rpm") - type lister struct{} func init() { @@ -53,20 +51,20 @@ func (l lister) ListFeatures(files tarutil.FilesMap) ([]database.FeatureVersion, tmpDir, err := ioutil.TempDir(os.TempDir(), "rpm") defer os.RemoveAll(tmpDir) if err != nil { - log.Errorf("could not create temporary folder for RPM detection: %s", err) + log.WithError(err).Error("could not create temporary folder for RPM detection") return []database.FeatureVersion{}, commonerr.ErrFilesystem } err = ioutil.WriteFile(tmpDir+"/Packages", f, 0700) if err != nil { - log.Errorf("could not create temporary file for RPM detection: %s", err) + log.WithError(err).Error("could not create temporary file for RPM detection") return []database.FeatureVersion{}, commonerr.ErrFilesystem } // Extract binary package names because RHSA refers to binary package names. out, err := exec.Command("rpm", "--dbpath", tmpDir, "-qa", "--qf", "%{NAME} %{EPOCH}:%{VERSION}-%{RELEASE}\n").CombinedOutput() if err != nil { - log.Errorf("could not query RPM: %s. output: %s", err, string(out)) + log.WithError(err).WithField("output", string(out)).Error("could not query RPM") // Do not bubble up because we probably won't be able to fix it, // the database must be corrupted return []database.FeatureVersion{}, nil @@ -90,7 +88,7 @@ func (l lister) ListFeatures(files tarutil.FilesMap) ([]database.FeatureVersion, version := strings.Replace(line[1], "(none):", "", -1) err := versionfmt.Valid(rpm.ParserName, version) if err != nil { - log.Warningf("could not parse package version '%s': %s. skipping", line[1], err.Error()) + log.WithError(err).WithField("version", line[1]).Warning("could not parse package version. skipping") continue } diff --git a/ext/featurens/driver.go b/ext/featurens/driver.go index db066cbb..c0d221bd 100644 --- a/ext/featurens/driver.go +++ b/ext/featurens/driver.go @@ -20,7 +20,7 @@ import ( "sync" "testing" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" "github.com/stretchr/testify/assert" "github.com/coreos/clair/database" @@ -28,8 +28,6 @@ import ( ) var ( - log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/featurens") - detectorsM sync.RWMutex detectors = make(map[string]Detector) ) @@ -79,12 +77,12 @@ func Detect(files tarutil.FilesMap) (*database.Namespace, error) { for name, detector := range detectors { namespace, err := detector.Detect(files) if err != nil { - log.Warningf("failed while attempting to detect namespace %s: %s", name, err) + log.WithError(err).WithField("name", name).Warning("failed while attempting to detect namespace") return nil, err } if namespace != nil { - log.Debugf("detected namespace %s: %#v", name, namespace) + log.WithFields(log.Fields{"name": name, "namespace": namespace.Name}).Debug("detected namespace") return namespace, nil } } diff --git a/ext/imagefmt/driver.go b/ext/imagefmt/driver.go index 97f3bf79..6997e93b 100644 --- a/ext/imagefmt/driver.go +++ b/ext/imagefmt/driver.go @@ -30,9 +30,10 @@ import ( "strings" "sync" + log "github.com/sirupsen/logrus" + "github.com/coreos/clair/pkg/commonerr" "github.com/coreos/clair/pkg/tarutil" - "github.com/coreos/pkg/capnslog" ) var ( @@ -43,8 +44,6 @@ var ( // when pulling layers, verified in default. insecureTLS = false - log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/imagefmt") - extractorsM sync.RWMutex extractors = make(map[string]Extractor) ) @@ -127,13 +126,13 @@ func Extract(format, path string, headers map[string]string, toExtract []string) client := &http.Client{Transport: tr} r, err := client.Do(request) if err != nil { - log.Warningf("could not download layer: %s", err) + log.WithError(err).Warning("could not download layer") return nil, ErrCouldNotFindLayer } // Fail if we don't receive a 2xx HTTP status code. if math.Floor(float64(r.StatusCode/100)) != 2 { - log.Warningf("could not download layer: got status code %d, expected 2XX", r.StatusCode) + log.WithField("status code", r.StatusCode).Warning("could not download layer: expected 2XX") return nil, ErrCouldNotFindLayer } diff --git a/ext/notification/driver.go b/ext/notification/driver.go index ad1dcc1e..8b961ae8 100644 --- a/ext/notification/driver.go +++ b/ext/notification/driver.go @@ -24,14 +24,10 @@ import ( "sync" "time" - "github.com/coreos/pkg/capnslog" - "github.com/coreos/clair/database" ) var ( - log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/notification") - sendersM sync.RWMutex senders = make(map[string]Sender) ) diff --git a/ext/versionfmt/driver.go b/ext/versionfmt/driver.go index 3d38469f..42f6c5b8 100644 --- a/ext/versionfmt/driver.go +++ b/ext/versionfmt/driver.go @@ -19,8 +19,6 @@ package versionfmt import ( "errors" "sync" - - "github.com/coreos/pkg/capnslog" ) const ( @@ -40,8 +38,6 @@ var ( // but should return an error in the case where the version is invalid. ErrInvalidVersion = errors.New("invalid version") - nlog = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/versionfmt") - parsersM sync.Mutex parsers = make(map[string]Parser) ) diff --git a/ext/vulnmdsrc/nvd/nvd.go b/ext/vulnmdsrc/nvd/nvd.go index c8b7698e..5be08b97 100644 --- a/ext/vulnmdsrc/nvd/nvd.go +++ b/ext/vulnmdsrc/nvd/nvd.go @@ -30,7 +30,7 @@ import ( "strings" "time" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/vulnmdsrc" @@ -42,9 +42,9 @@ const ( dataFeedMetaURL string = "http://static.nvd.nist.gov/feeds/xml/cve/nvdcve-2.0-%s.meta" appenderName string = "NVD" -) -var log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/vulnmdsrc/nvd") + logDataFeedName string = "data feed name" +) type appender struct { localPath string @@ -90,7 +90,7 @@ func (a *appender) BuildCache(datastore database.Datastore) error { for dataFeedName, dataFeedReader := range dataFeedReaders { var nvd nvd if err = xml.NewDecoder(dataFeedReader).Decode(&nvd); err != nil { - log.Errorf("could not decode NVD data feed '%s': %s", dataFeedName, err) + log.WithError(err).WithField(logDataFeedName, dataFeedName).Error("could not decode NVD data feed") return commonerr.ErrCouldNotParse } @@ -134,7 +134,7 @@ func getDataFeeds(dataFeedHashes map[string]string, localPath string) (map[strin for _, dataFeedName := range dataFeedNames { hash, err := getHashFromMetaURL(fmt.Sprintf(dataFeedMetaURL, dataFeedName)) if err != nil { - log.Warningf("could get get NVD data feed hash '%s': %s", dataFeedName, err) + log.WithError(err).WithField(logDataFeedName, dataFeedName).Warning("could not get NVD data feed hash") // It's not a big deal, no need interrupt, we're just going to download it again then. continue @@ -163,14 +163,14 @@ func getDataFeeds(dataFeedHashes map[string]string, localPath string) (map[strin // Download data feed. r, err := http.Get(fmt.Sprintf(dataFeedURL, dataFeedName)) if err != nil { - log.Errorf("could not download NVD data feed file '%s': %s", dataFeedName, err) + log.WithError(err).WithField(logDataFeedName, dataFeedName).Error("could not download NVD data feed") return dataFeedReaders, dataFeedHashes, commonerr.ErrCouldNotDownload } // Un-gzip it. gr, err := gzip.NewReader(r.Body) if err != nil { - log.Errorf("could not read NVD data feed file '%s': %s", dataFeedName, err) + log.WithError(err).WithField(logDataFeedName, dataFeedName).Error("could not read NVD data feed") return dataFeedReaders, dataFeedHashes, commonerr.ErrCouldNotDownload } @@ -188,7 +188,7 @@ func getDataFeeds(dataFeedHashes map[string]string, localPath string) (map[strin } dataFeedReaders[dataFeedName] = nrc - log.Warningf("could not store NVD data feed to filesystem: %s", err) + log.WithError(err).Warning("could not store NVD data feed to filesystem") } } } diff --git a/ext/vulnmdsrc/nvd/xml.go b/ext/vulnmdsrc/nvd/xml.go index d7649ce6..9c6ffd98 100644 --- a/ext/vulnmdsrc/nvd/xml.go +++ b/ext/vulnmdsrc/nvd/xml.go @@ -17,6 +17,8 @@ package nvd import ( "fmt" "strings" + + log "github.com/sirupsen/logrus" ) type nvd struct { @@ -90,7 +92,7 @@ func addVec(str *string, vec, val string) { if let, ok := vectorValuesToLetters[val]; ok { *str = fmt.Sprintf("%s%s:%s/", *str, vec, let) } else { - log.Warningf("unknown value '%v' for CVSSv2 vector '%s'", val, vec) + log.WithFields(log.Fields{"value": val, "vector": vec}).Warning("unknown value for CVSSv2 vector") } } } diff --git a/ext/vulnsrc/alpine/alpine.go b/ext/vulnsrc/alpine/alpine.go index e99926ba..10af67c3 100644 --- a/ext/vulnsrc/alpine/alpine.go +++ b/ext/vulnsrc/alpine/alpine.go @@ -24,10 +24,9 @@ import ( "path/filepath" "strings" + log "github.com/sirupsen/logrus" "gopkg.in/yaml.v2" - "github.com/coreos/pkg/capnslog" - "github.com/coreos/clair/database" "github.com/coreos/clair/ext/versionfmt" "github.com/coreos/clair/ext/versionfmt/dpkg" @@ -42,8 +41,6 @@ const ( nvdURLPrefix = "https://cve.mitre.org/cgi-bin/cvename.cgi?name=" ) -var log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/vulnsrc/alpine") - func init() { vulnsrc.RegisterUpdater("alpine", &updater{}) } @@ -53,7 +50,7 @@ type updater struct { } func (u *updater) Update(db database.Datastore) (resp vulnsrc.UpdateResponse, err error) { - log.Info("fetching Alpine vulnerabilities") + log.WithField("package", "Alpine").Info("Start fetching vulnerabilities") // Pull the master branch. var commit string @@ -75,7 +72,7 @@ func (u *updater) Update(db database.Datastore) (resp vulnsrc.UpdateResponse, er // Short-circuit if there have been no updates. if commit == dbCommit { - log.Debug("no alpine update") + log.WithField("package", "alpine").Debug("no update") return } @@ -187,7 +184,7 @@ func (u *updater) pullRepository() (commit string, err error) { cmd.Dir = u.repositoryLocalPath if out, err := cmd.CombinedOutput(); err != nil { u.Clean() - log.Errorf("could not pull alpine-secdb repository: %s. output: %s", err, out) + log.WithError(err).WithField("output", string(out)).Error("could not pull alpine-secdb repository") return "", commonerr.ErrCouldNotDownload } } else { @@ -238,7 +235,7 @@ func parseYAML(r io.Reader) (vulns []database.Vulnerability, err error) { for version, vulnStrs := range pkg.Fixes { 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") continue } diff --git a/ext/vulnsrc/debian/debian.go b/ext/vulnsrc/debian/debian.go index ec917fe3..3288e46b 100644 --- a/ext/vulnsrc/debian/debian.go +++ b/ext/vulnsrc/debian/debian.go @@ -25,7 +25,7 @@ import ( "net/http" "strings" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/versionfmt" @@ -40,8 +40,6 @@ const ( updaterFlag = "debianUpdater" ) -var log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/vulnsrc/debian") - type jsonData map[string]map[string]jsonVuln type jsonVuln struct { @@ -62,12 +60,12 @@ func init() { } func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateResponse, err error) { - log.Info("fetching Debian vulnerabilities") + log.WithField("package", "Debian").Info("Start fetching vulnerabilities") // Download JSON. r, err := http.Get(url) if err != nil { - log.Errorf("could not download Debian's update: %s", err) + log.WithError(err).Error("could not download Debian's update") return resp, commonerr.ErrCouldNotDownload } @@ -108,14 +106,14 @@ func buildResponse(jsonReader io.Reader, latestKnownHash string) (resp vulnsrc.U var data jsonData err = json.NewDecoder(teedJSONReader).Decode(&data) if err != nil { - log.Errorf("could not unmarshal Debian's JSON: %s", err) + log.WithError(err).Error("could not unmarshal Debian's JSON") return resp, commonerr.ErrCouldNotParse } // Calculate the hash and skip updating if the hash has been seen before. hash = hex.EncodeToString(jsonSHA.Sum(nil)) if latestKnownHash == hash { - log.Debug("no Debian update") + log.WithField("package", "Debian").Debug("no update") return resp, nil } @@ -185,7 +183,7 @@ func parseDebianJSON(data *jsonData) (vulnerabilities []database.Vulnerability, // "fixed_version" (if affected). err = versionfmt.Valid(dpkg.ParserName, releaseNode.FixedVersion) if err != nil { - log.Warningf("could not parse package version '%s': %s. skipping", releaseNode.FixedVersion, err.Error()) + log.WithError(err).WithField("version", version).Warning("could not parse package version. skipping") continue } version = releaseNode.FixedVersion @@ -252,7 +250,7 @@ func SeverityFromUrgency(urgency string) database.Severity { return database.HighSeverity default: - log.Warningf("could not determine vulnerability severity from: %s", urgency) + log.WithField("urgency", urgency).Warning("could not determine vulnerability severity from urgency") return database.UnknownSeverity } } diff --git a/ext/vulnsrc/oracle/oracle.go b/ext/vulnsrc/oracle/oracle.go index bc112865..ee6a8343 100644 --- a/ext/vulnsrc/oracle/oracle.go +++ b/ext/vulnsrc/oracle/oracle.go @@ -25,7 +25,9 @@ import ( "strconv" "strings" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" + + "fmt" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/versionfmt" @@ -48,8 +50,6 @@ var ( } elsaRegexp = regexp.MustCompile(`com.oracle.elsa-(\d+).xml`) - - log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/vulnsrc/oracle") ) type oval struct { @@ -116,8 +116,7 @@ func compareELSA(left, right int) int { } func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateResponse, err error) { - log.Info("fetching Oracle Linux vulnerabilities") - + log.WithField("package", "Oracle Linux").Info("Start fetching vulnerabilities") // Get the first ELSA we have to manage. flagValue, err := datastore.GetKeyValue(updaterFlag) if err != nil { @@ -132,7 +131,7 @@ func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateRespo // Fetch the update list. r, err := http.Get(ovalURI) if err != nil { - log.Errorf("could not download Oracle's update list: %s", err) + log.WithError(err).Error("could not download Oracle's update list") return resp, commonerr.ErrCouldNotDownload } defer r.Body.Close() @@ -155,7 +154,7 @@ func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateRespo // Download the ELSA's XML file. r, err := http.Get(ovalURI + elsaFilePrefix + strconv.Itoa(elsa) + ".xml") if err != nil { - log.Errorf("could not download Oracle's update file: %s", err) + log.WithError(err).Error("could not download Oracle's update list") return resp, commonerr.ErrCouldNotDownload } @@ -176,7 +175,7 @@ func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateRespo resp.FlagName = updaterFlag resp.FlagValue = strconv.Itoa(largest(elsaList)) } else { - log.Debug("no Oracle Linux update.") + log.WithField("package", "Oracle Linux").Debug("no update") } return resp, nil @@ -198,7 +197,7 @@ func parseELSA(ovalReader io.Reader) (vulnerabilities []database.Vulnerability, var ov oval err = xml.NewDecoder(ovalReader).Decode(&ov) if err != nil { - log.Errorf("could not decode Oracle's XML: %s", err) + log.WithError(err).Error("could not decode Oracle's XML") err = commonerr.ErrCouldNotParse return } @@ -318,7 +317,7 @@ func toFeatureVersions(criteria criteria) []database.FeatureVersion { const prefixLen = len("Oracle Linux ") osVersion, err = strconv.Atoi(strings.TrimSpace(c.Comment[prefixLen : prefixLen+strings.Index(c.Comment[prefixLen:], " ")])) if err != nil { - log.Warningf("could not parse Oracle Linux release version from: '%s'.", c.Comment) + log.WithError(err).WithField("comment", c.Comment).Warning("could not parse Oracle Linux release version from comment") } } else if strings.Contains(c.Comment, " is earlier than ") { const prefixLen = len(" is earlier than ") @@ -326,7 +325,7 @@ func toFeatureVersions(criteria criteria) []database.FeatureVersion { version := c.Comment[strings.Index(c.Comment, " is earlier than ")+prefixLen:] err := versionfmt.Valid(rpm.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 { featureVersion.Version = version } @@ -339,7 +338,7 @@ func toFeatureVersions(criteria criteria) []database.FeatureVersion { if featureVersion.Feature.Namespace.Name != "" && featureVersion.Feature.Name != "" && featureVersion.Version != "" { featureVersionParameters[featureVersion.Feature.Namespace.Name+":"+featureVersion.Feature.Name] = featureVersion } else { - log.Warningf("could not determine a valid package from criterions: %v", criterions) + log.WithField("criterions", fmt.Sprintf("%v", criterions)).Warning("could not determine a valid package from criterions") } } @@ -388,7 +387,7 @@ func severity(def definition) database.Severity { case "critical": return database.CriticalSeverity default: - log.Warningf("could not determine vulnerability severity from: %s.", def.Severity) + log.WithField("severity", def.Severity).Warning("could not determine vulnerability severity") return database.UnknownSeverity } } diff --git a/ext/vulnsrc/rhel/rhel.go b/ext/vulnsrc/rhel/rhel.go index ea1e9c3d..bbd48c15 100644 --- a/ext/vulnsrc/rhel/rhel.go +++ b/ext/vulnsrc/rhel/rhel.go @@ -19,13 +19,14 @@ package rhel import ( "bufio" "encoding/xml" + "fmt" "io" "net/http" "regexp" "strconv" "strings" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/versionfmt" @@ -53,8 +54,6 @@ var ( } rhsaRegexp = regexp.MustCompile(`com.redhat.rhsa-(\d+).xml`) - - log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/vulnsrc/rhel") ) type oval struct { @@ -90,8 +89,7 @@ func init() { } func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateResponse, err error) { - log.Info("fetching RHEL vulnerabilities") - + log.WithField("package", "RHEL").Info("Start fetching vulnerabilities") // Get the first RHSA we have to manage. flagValue, err := datastore.GetKeyValue(updaterFlag) if err != nil { @@ -105,7 +103,7 @@ func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateRespo // Fetch the update list. r, err := http.Get(ovalURI) if err != nil { - log.Errorf("could not download RHEL's update list: %s", err) + log.WithError(err).Error("could not download RHEL's update list") return resp, commonerr.ErrCouldNotDownload } @@ -127,7 +125,7 @@ func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateRespo // Download the RHSA's XML file. r, err := http.Get(ovalURI + rhsaFilePrefix + strconv.Itoa(rhsa) + ".xml") if err != nil { - log.Errorf("could not download RHEL's update file: %s", err) + log.WithError(err).Error("could not download RHEL's update list") return resp, commonerr.ErrCouldNotDownload } @@ -148,7 +146,7 @@ func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateRespo resp.FlagName = updaterFlag resp.FlagValue = strconv.Itoa(rhsaList[len(rhsaList)-1]) } else { - log.Debug("no Red Hat update.") + log.WithField("package", "Red Hat").Debug("no update") } return resp, nil @@ -161,7 +159,7 @@ func parseRHSA(ovalReader io.Reader) (vulnerabilities []database.Vulnerability, var ov oval err = xml.NewDecoder(ovalReader).Decode(&ov) if err != nil { - log.Errorf("could not decode RHEL's XML: %s", err) + log.WithError(err).Error("could not decode RHEL's XML") err = commonerr.ErrCouldNotParse return } @@ -281,7 +279,7 @@ func toFeatureVersions(criteria criteria) []database.FeatureVersion { const prefixLen = len("Red Hat Enterprise Linux ") osVersion, err = strconv.Atoi(strings.TrimSpace(c.Comment[prefixLen : prefixLen+strings.Index(c.Comment[prefixLen:], " ")])) if err != nil { - log.Warningf("could not parse Red Hat release version from: '%s'.", c.Comment) + log.WithField("criterion comment", c.Comment).Warning("could not parse Red Hat release version from criterion comment") } } else if strings.Contains(c.Comment, " is earlier than ") { const prefixLen = len(" is earlier than ") @@ -289,7 +287,7 @@ func toFeatureVersions(criteria criteria) []database.FeatureVersion { version := c.Comment[strings.Index(c.Comment, " is earlier than ")+prefixLen:] err := versionfmt.Valid(rpm.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 { featureVersion.Version = version featureVersion.Feature.Namespace.VersionFormat = rpm.ParserName @@ -307,7 +305,7 @@ func toFeatureVersions(criteria criteria) []database.FeatureVersion { if featureVersion.Feature.Namespace.Name != "" && featureVersion.Feature.Name != "" && featureVersion.Version != "" { featureVersionParameters[featureVersion.Feature.Namespace.Name+":"+featureVersion.Feature.Name] = featureVersion } else { - log.Warningf("could not determine a valid package from criterions: %v", criterions) + log.WithField("criterions", fmt.Sprintf("%v", criterions)).Warning("could not determine a valid package from criterions") } } diff --git a/ext/vulnsrc/ubuntu/ubuntu.go b/ext/vulnsrc/ubuntu/ubuntu.go index 6ef3633a..c328ae31 100644 --- a/ext/vulnsrc/ubuntu/ubuntu.go +++ b/ext/vulnsrc/ubuntu/ubuntu.go @@ -28,7 +28,7 @@ import ( "strconv" "strings" - "github.com/coreos/pkg/capnslog" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/versionfmt" @@ -74,8 +74,6 @@ var ( affectsCaptureRegexp = regexp.MustCompile(`(?P.*)_(?P.*): (?P[^\s]*)( \(+(?P[^()]*)\)+)?`) affectsCaptureRegexpNames = affectsCaptureRegexp.SubexpNames() - - log = capnslog.NewPackageLogger("github.com/coreos/clair", "ext/vulnsrc/ubuntu") ) type updater struct { @@ -87,7 +85,7 @@ func init() { } func (u *updater) Update(datastore database.Datastore) (resp vulnsrc.UpdateResponse, err error) { - log.Info("fetching Ubuntu vulnerabilities") + log.WithField("package", "Ubuntu").Info("Start fetching vulnerabilities") // Pull the bzr repository. if err = u.pullRepository(); err != nil { @@ -176,7 +174,7 @@ func (u *updater) pullRepository() (err error) { cmd := exec.Command("bzr", "branch", "--use-existing-dir", trackerRepository, ".") cmd.Dir = u.repositoryLocalPath if out, err := cmd.CombinedOutput(); err != nil { - log.Errorf("could not branch Ubuntu repository: %s. output: %s", err, out) + log.WithError(err).WithField("output", string(out)).Error("could not branch Ubuntu repository") return commonerr.ErrCouldNotDownload } @@ -188,8 +186,7 @@ func (u *updater) pullRepository() (err error) { cmd.Dir = u.repositoryLocalPath if out, err := cmd.CombinedOutput(); err != nil { os.RemoveAll(u.repositoryLocalPath) - - log.Errorf("could not pull Ubuntu repository: %s. output: %s", err, out) + log.WithError(err).WithField("output", string(out)).Error("could not pull Ubuntu repository") return commonerr.ErrCouldNotDownload } @@ -201,13 +198,13 @@ func getRevisionNumber(pathToRepo string) (int, error) { cmd.Dir = pathToRepo out, err := cmd.CombinedOutput() if err != nil { - log.Errorf("could not get Ubuntu repository's revision number: %s. output: %s", err, out) + log.WithError(err).WithField("output", string(out)).Error("could not get Ubuntu repository's revision number") return 0, commonerr.ErrCouldNotDownload } revno, err := strconv.Atoi(strings.TrimSpace(string(out))) if err != nil { - log.Errorf("could not parse Ubuntu repository's revision number: %s. output: %s", err, out) + log.WithError(err).WithField("output", string(out)).Error("could not parse Ubuntu repository's revision number") return 0, commonerr.ErrCouldNotDownload } @@ -222,14 +219,14 @@ func collectModifiedVulnerabilities(revision int, dbRevision, repositoryLocalPat for _, folder := range []string{"active", "retired"} { d, err := os.Open(repositoryLocalPath + "/" + folder) if err != nil { - log.Errorf("could not open Ubuntu vulnerabilities repository's folder: %s", err) + log.WithError(err).Error("could not open Ubuntu vulnerabilities repository's folder") return nil, vulnsrc.ErrFilesystem } // Get the FileInfo of all the files in the directory. names, err := d.Readdirnames(-1) if err != nil { - log.Errorf("could not read Ubuntu vulnerabilities repository's folder:: %s.", err) + log.WithError(err).Error("could not read Ubuntu vulnerabilities repository's folder") return nil, vulnsrc.ErrFilesystem } @@ -254,7 +251,7 @@ func collectModifiedVulnerabilities(revision int, dbRevision, repositoryLocalPat // Handle an up to date database. dbRevisionInt, _ := strconv.Atoi(dbRevision) if revision == dbRevisionInt { - log.Debug("no Ubuntu update") + log.WithField("package", "Ubuntu").Debug("no update") return modifiedCVE, nil } @@ -263,7 +260,7 @@ func collectModifiedVulnerabilities(revision int, dbRevision, repositoryLocalPat cmd.Dir = repositoryLocalPath out, err := cmd.CombinedOutput() if err != nil { - log.Errorf("could not get Ubuntu vulnerabilities repository logs: %s. output: %s", err, out) + log.WithError(err).WithField("output", string(out)).Error("could not get Ubuntu vulnerabilities repository logs") return nil, commonerr.ErrCouldNotDownload } @@ -361,7 +358,7 @@ func parseUbuntuCVE(fileContent io.Reader) (vulnerability database.Vulnerability var err error err = versionfmt.Valid(dpkg.ParserName, md["note"]) if err != nil { - log.Warningf("could not parse package version '%s': %s. skipping", md["note"], err) + log.WithError(err).WithField("version", md["note"]).Warning("could not parse package version. skipping") } version = md["note"] } diff --git a/notifier.go b/notifier.go index 0586f019..ad3e947c 100644 --- a/notifier.go +++ b/notifier.go @@ -20,6 +20,7 @@ import ( "github.com/coreos/pkg/timeutil" "github.com/pborman/uuid" "github.com/prometheus/client_golang/prometheus" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/notification" @@ -32,6 +33,9 @@ const ( notifierMaxBackOff = 15 * time.Minute notifierLockRefreshDuration = time.Minute * 2 notifierLockDuration = time.Minute*8 + notifierLockRefreshDuration + + logSenderName = "sender name" + logNotiName = "notification name" ) var ( @@ -59,23 +63,23 @@ func RunNotifier(config *notification.Config, datastore database.Datastore, stop // Configure registered notifiers. for senderName, sender := range notification.Senders() { if configured, err := sender.Configure(config); configured { - log.Infof("sender '%s' configured\n", senderName) + log.WithField(logSenderName, senderName).Info("sender configured") } else { notification.UnregisterSender(senderName) if err != nil { - log.Errorf("could not configure notifier '%s': %s", senderName, err) + log.WithError(err).WithField(logSenderName, senderName).Error("could not configure notifier") } } } // Do not run the updater if there is no notifier enabled. if len(notification.Senders()) == 0 { - log.Infof("notifier service is disabled") + log.Info("notifier service is disabled") return } whoAmI := uuid.New() - log.Infof("notifier service started. lock identifier: %s\n", whoAmI) + log.WithField("lock identifier", whoAmI).Info("notifier service started") for running := true; running; { // Find task. @@ -123,7 +127,7 @@ func findTask(datastore database.Datastore, renotifyInterval time.Duration, whoA if err != nil { // There is no notification or an error occurred. if err != commonerr.ErrNotFound { - log.Warningf("could not get notification to send: %s", err) + log.WithError(err).Warning("could not get notification to send") } // Wait. @@ -136,7 +140,7 @@ func findTask(datastore database.Datastore, renotifyInterval time.Duration, whoA // Lock the notification. if hasLock, _ := datastore.Lock(notification.Name, whoAmI, notifierLockDuration, false); hasLock { - log.Infof("found and locked a notification: %s", notification.Name) + log.WithField(logNotiName, notification.Name).Info("found and locked a notification") return ¬ification } } @@ -150,13 +154,13 @@ func handleTask(n database.VulnerabilityNotification, st *stopper.Stopper, maxAt for { // Max attempts exceeded. if attempts >= maxAttempts { - log.Infof("giving up on sending notification '%s' via sender '%s': max attempts exceeded (%d)\n", n.Name, senderName, maxAttempts) + log.WithFields(log.Fields{logNotiName: n.Name, logSenderName: senderName, "max attempts": maxAttempts}).Info("giving up on sending notification : max attempts exceeded") return false, false } // Backoff. if backOff > 0 { - log.Infof("waiting %v before retrying to send notification '%s' via sender '%s' (Attempt %d / %d)\n", backOff, n.Name, senderName, attempts+1, maxAttempts) + log.WithFields(log.Fields{"duration": backOff, logNotiName: n.Name, logSenderName: senderName, "attempts": attempts + 1, "max attempts": maxAttempts}).Info("waiting before retrying to send notification") if !st.Sleep(backOff) { return false, true } @@ -166,7 +170,7 @@ func handleTask(n database.VulnerabilityNotification, st *stopper.Stopper, maxAt if err := sender.Send(n); err != nil { // Send failed; increase attempts/backoff and retry. promNotifierBackendErrorsTotal.WithLabelValues(senderName).Inc() - log.Errorf("could not send notification '%s' via notifier '%s': %v", n.Name, senderName, err) + log.WithError(err).WithFields(log.Fields{logSenderName: senderName, logNotiName: n.Name}).Error("could not send notification via notifier") backOff = timeutil.ExpBackoff(backOff, notifierMaxBackOff) attempts++ continue @@ -177,6 +181,6 @@ func handleTask(n database.VulnerabilityNotification, st *stopper.Stopper, maxAt } } - log.Infof("successfully sent notification '%s'\n", n.Name) + log.WithField(logNotiName, n.Name).Info("successfully sent notification") return true, false } diff --git a/pkg/formatter/formatter.go b/pkg/formatter/formatter.go new file mode 100644 index 00000000..021ffb46 --- /dev/null +++ b/pkg/formatter/formatter.go @@ -0,0 +1,74 @@ +package formatter + +import ( + "encoding/json" + "fmt" + "runtime" + "strings" + + "github.com/sirupsen/logrus" +) + +// JSONExtendedFormatter formats log information to JSON format with time and line number in file +type JSONExtendedFormatter struct { + ShowLn bool +} + +func (f *JSONExtendedFormatter) Format(entry *logrus.Entry) ([]byte, error) { + // Because entry.Data is not concurrent write safe, we need to copy the dictionary + data := make(logrus.Fields, len(entry.Data)+4) + + for k, v := range entry.Data { + switch v := v.(type) { + case error: + // Otherwise errors are ignored by `encoding/json` + // https://github.com/Sirupsen/logrus/issues/137 + data[k] = v.Error() + default: + data[k] = v + } + } + + if f.ShowLn { + var ( + filename = "???" + filepath string + line int + ok = true + ) + // worst case is O(call stack size) + for depth := 3; ok; depth++ { + _, filepath, line, ok = runtime.Caller(depth) + if !ok { + line = 0 + filename = "???" + break + } else if !strings.Contains(filepath, "logrus") { + if line < 0 { + line = 0 + } + slash := strings.LastIndex(filepath, "/") + if slash >= 0 { + filename = filepath[slash+1:] + } else { + filename = filepath + } + break + } + } + data["Location"] = fmt.Sprintf("%s:%d", filename, line) + } + now := entry.Time + ts := now.Format("2006-01-02 15:04:05") + ms := now.Nanosecond() / 1000 + + data["Time"] = fmt.Sprintf("%s.%06d", ts, ms) + data["Event"] = entry.Message + data["Level"] = entry.Level.String() + + serialized, err := json.Marshal(data) + if err != nil { + return nil, fmt.Errorf("Failed to marshal fields to JSON, %v", err) + } + return append(serialized, '\n'), nil +} diff --git a/updater.go b/updater.go index 523bad13..71ac147d 100644 --- a/updater.go +++ b/updater.go @@ -20,9 +20,9 @@ import ( "sync" "time" - "github.com/coreos/pkg/capnslog" "github.com/pborman/uuid" "github.com/prometheus/client_golang/prometheus" + log "github.com/sirupsen/logrus" "github.com/coreos/clair/database" "github.com/coreos/clair/ext/vulnmdsrc" @@ -38,8 +38,6 @@ const ( ) var ( - log = capnslog.NewPackageLogger("github.com/coreos/clair", "clair") - promUpdaterErrorsTotal = prometheus.NewCounter(prometheus.CounterOpts{ Name: "clair_updater_errors_total", Help: "Numbers of errors that the updater generated.", @@ -74,12 +72,12 @@ func RunUpdater(config *UpdaterConfig, datastore database.Datastore, st *stopper // Do not run the updater if there is no config or if the interval is 0. if config == nil || config.Interval == 0 { - log.Infof("updater service is disabled.") + log.Info("updater service is disabled.") return } whoAmI := uuid.New() - log.Infof("updater service started. lock identifier: %s", whoAmI) + log.WithField("lock identifier", whoAmI).Info("updater service started") for { var stop bool @@ -89,7 +87,7 @@ func RunUpdater(config *UpdaterConfig, datastore database.Datastore, st *stopper nextUpdate := time.Now().UTC() lastUpdate, firstUpdate, err := getLastUpdate(datastore) if err != nil { - log.Errorf("an error occured while getting the last update time") + log.WithError(err).Error("an error occured while getting the last update time") nextUpdate = nextUpdate.Add(config.Interval) } else if firstUpdate == false { nextUpdate = lastUpdate.Add(config.Interval) @@ -133,7 +131,7 @@ func RunUpdater(config *UpdaterConfig, datastore database.Datastore, st *stopper log.Debug("update lock is already taken") nextUpdate = hasLockUntil } else { - log.Debugf("update lock is already taken by %s until %v", lockOwner, lockExpiration) + log.WithFields(log.Fields{"lock owner": lockOwner, "lock expiration": lockExpiration}).Debug("update lock is already taken") nextUpdate = lockExpiration } } @@ -142,7 +140,7 @@ func RunUpdater(config *UpdaterConfig, datastore database.Datastore, st *stopper // Sleep, but remain stoppable until approximately the next update time. now := time.Now().UTC() waitUntil := nextUpdate.Add(time.Duration(rand.ExpFloat64()/0.5) * time.Second) - log.Debugf("next update attempt scheduled for %v.", waitUntil) + log.WithField("scheduled time", waitUntil).Debug("next update attempt scheduled") if !waitUntil.Before(now) { if !st.Sleep(waitUntil.Sub(time.Now())) { break @@ -172,11 +170,11 @@ func update(datastore database.Datastore, firstUpdate bool) { status, vulnerabilities, flags, notes := fetch(datastore) // Insert vulnerabilities. - log.Tracef("inserting %d vulnerabilities for update", len(vulnerabilities)) + log.WithField("count", len(vulnerabilities)).Debug("inserting vulnerabilities for update") err := datastore.InsertVulnerabilities(vulnerabilities, !firstUpdate) if err != nil { promUpdaterErrorsTotal.Inc() - log.Errorf("an error occured when inserting vulnerabilities for update: %s", err) + log.WithError(err).Error("an error occured when inserting vulnerabilities for update") return } vulnerabilities = nil @@ -188,7 +186,7 @@ func update(datastore database.Datastore, firstUpdate bool) { // Log notes. for _, note := range notes { - log.Warningf("fetcher note: %s", note) + log.WithField("note", note).Warning("fetcher note") } promUpdaterNotesTotal.Set(float64(len(notes))) @@ -219,14 +217,14 @@ func fetch(datastore database.Datastore) (bool, []database.Vulnerability, map[st response, err := u.Update(datastore) if err != nil { promUpdaterErrorsTotal.Inc() - log.Errorf("an error occured when fetching update '%s': %s.", name, err) + log.WithError(err).WithField("updater name", name).Error("an error occured when fetching update") status = false responseC <- nil return } responseC <- &response - log.Infof("finished fetching %s", name) + log.WithField("updater name", name).Info("finished fetching") }(n, u) } @@ -273,7 +271,7 @@ func addMetadata(datastore database.Datastore, vulnerabilities []database.Vulner // Build up a metadata cache. if err := appender.BuildCache(datastore); err != nil { promUpdaterErrorsTotal.Inc() - log.Errorf("an error occured when loading metadata fetcher '%s': %s.", name, err) + log.WithError(err).WithField("appender name", name).Error("an error occured when loading metadata fetcher") return } diff --git a/worker.go b/worker.go index 9856f851..76e2605c 100644 --- a/worker.go +++ b/worker.go @@ -17,6 +17,8 @@ package clair import ( "regexp" + log "github.com/sirupsen/logrus" + "github.com/coreos/clair/database" "github.com/coreos/clair/ext/featurefmt" "github.com/coreos/clair/ext/featurens" @@ -28,7 +30,8 @@ import ( const ( // Version (integer) represents the worker version. // Increased each time the engine changes. - Version = 3 + Version = 3 + logLayerName = "layer" ) var ( @@ -67,8 +70,7 @@ func ProcessLayer(datastore database.Datastore, imageFormat, name, parentName, p return commonerr.NewBadRequestError("could not process a layer which does not have a format") } - log.Debugf("layer %s: processing (Location: %s, Engine version: %d, Parent: %s, Format: %s)", - name, cleanURL(path), Version, parentName, imageFormat) + log.WithFields(log.Fields{logLayerName: name, "path": cleanURL(path), "engine version": Version, "parent layer": parentName, "format": imageFormat}).Debug("processing layer") // Check to see if the layer is already in the database. layer, err := datastore.FindLayer(name, false, false) @@ -88,8 +90,7 @@ func ProcessLayer(datastore database.Datastore, imageFormat, name, parentName, p return err } if err == commonerr.ErrNotFound { - log.Warningf("layer %s: the parent layer (%s) is unknown. it must be processed first", name, - parentName) + log.WithFields(log.Fields{logLayerName: name, "parent layer": parentName}).Warning("the parent layer is unknown. it must be processed first") return ErrParentUnknown } layer.Parent = &parent @@ -97,13 +98,10 @@ func ProcessLayer(datastore database.Datastore, imageFormat, name, parentName, p } else { // The layer is already in the database, check if we need to update it. if layer.EngineVersion >= Version { - log.Debugf(`layer %s: layer content has already been processed in the past with engine %d. - Current engine is %d. skipping analysis`, name, layer.EngineVersion, Version) + log.WithFields(log.Fields{logLayerName: name, "past engine version": layer.EngineVersion, "current engine version": Version}).Debug("layer content has already been processed in the past with older engine. skipping analysis") return nil } - - log.Debugf(`layer %s: layer content has been analyzed in the past with engine %d. Current - engine is %d. analyzing again`, name, layer.EngineVersion, Version) + log.WithFields(log.Fields{logLayerName: name, "past engine version": layer.EngineVersion, "current engine version": Version}).Debug("layer content has already been processed in the past with older engine. analyzing again") } // Analyze the content. @@ -121,7 +119,7 @@ func detectContent(imageFormat, name, path string, headers map[string]string, pa totalRequiredFiles := append(featurefmt.RequiredFilenames(), featurens.RequiredFilenames()...) files, err := imagefmt.Extract(imageFormat, path, headers, totalRequiredFiles) if err != nil { - log.Errorf("layer %s: failed to extract data from %s: %s", name, cleanURL(path), err) + log.WithError(err).WithFields(log.Fields{logLayerName: name, "path": cleanURL(path)}).Error("failed to extract data from path") return } @@ -136,7 +134,7 @@ func detectContent(imageFormat, name, path string, headers map[string]string, pa return } if len(featureVersions) > 0 { - log.Debugf("layer %s: detected %d features", name, len(featureVersions)) + log.WithFields(log.Fields{logLayerName: name, "feature count": len(featureVersions)}).Debug("detected features") } return @@ -148,7 +146,7 @@ func detectNamespace(name string, files tarutil.FilesMap, parent *database.Layer return } if namespace != nil { - log.Debugf("layer %s: detected namespace %q", name, namespace.Name) + log.WithFields(log.Fields{logLayerName: name, "detected namespace": namespace.Name}).Debug("detected namespace") return } @@ -156,7 +154,7 @@ func detectNamespace(name string, files tarutil.FilesMap, parent *database.Layer if parent != nil { namespace = parent.Namespace if namespace != nil { - log.Debugf("layer %s: detected namespace %q (from parent)", name, namespace.Name) + log.WithFields(log.Fields{logLayerName: name, "detected namespace": namespace.Name}).Debug("detected namespace (from parent)") return } } @@ -210,7 +208,7 @@ func detectFeatureVersions(name string, files tarutil.FilesMap, namespace *datab continue } - log.Warningf("Namespace unknown for feature %s %s, in layer %s", feature.Feature.Name, feature.Version, name) + log.WithFields(log.Fields{"feature name": feature.Feature.Name, "feature version": feature.Version, logLayerName: name}).Warning("Namespace unknown") err = ErrUnsupported return }