diff --git a/cmd/csaf_aggregator/config.go b/cmd/csaf_aggregator/config.go index edb1fd9..2a2bef2 100644 --- a/cmd/csaf_aggregator/config.go +++ b/cmd/csaf_aggregator/config.go @@ -12,7 +12,6 @@ import ( "crypto/tls" "errors" "fmt" - "log" "net/http" "os" "runtime" @@ -26,6 +25,7 @@ import ( "github.com/csaf-poc/csaf_distribution/v3/internal/models" "github.com/csaf-poc/csaf_distribution/v3/internal/options" "github.com/csaf-poc/csaf_distribution/v3/util" + "golang.org/x/exp/slog" "golang.org/x/time/rate" ) @@ -178,9 +178,11 @@ func (p *provider) ageAccept(c *config) func(time.Time) bool { } if c.Verbose { - log.Printf( - "Setting up filter to accept advisories within time range %s to %s\n", - r[0].Format(time.RFC3339), r[1].Format(time.RFC3339)) + slog.Debug( + "Setting up filter to accept advisories within time range", + "from", r[0].Format(time.RFC3339), + "to", r[1].Format(time.RFC3339), + ) } return r.Contains } @@ -393,6 +395,17 @@ func (c *config) setDefaults() { } } +// prepareLogging sets up the structured logging. +func (cfg *config) prepareLogging() error { + ho := slog.HandlerOptions{ + Level: slog.LevelDebug, + } + handler := slog.NewTextHandler(os.Stdout, &ho) + logger := slog.New(handler) + slog.SetDefault(logger) + return nil +} + // compileIgnorePatterns compiles the configured patterns to be ignored. func (p *provider) compileIgnorePatterns() error { pm, err := filter.NewPatternMatcher(p.IgnorePattern) diff --git a/cmd/csaf_aggregator/full.go b/cmd/csaf_aggregator/full.go index 600c650..2165397 100644 --- a/cmd/csaf_aggregator/full.go +++ b/cmd/csaf_aggregator/full.go @@ -11,7 +11,6 @@ package main import ( "errors" "fmt" - "log" "os" "path/filepath" "strings" @@ -20,6 +19,7 @@ import ( "github.com/csaf-poc/csaf_distribution/v3/csaf" "github.com/csaf-poc/csaf_distribution/v3/util" + "golang.org/x/exp/slog" ) type fullJob struct { @@ -29,11 +29,13 @@ type fullJob struct { err error } -// setupProviderFull fetches the provider-metadate.json for a specific provider. +// setupProviderFull fetches the provider-metadata.json for a specific provider. func (w *worker) setupProviderFull(provider *provider) error { - log.Printf("worker #%d: %s (%s)\n", - w.num, provider.Name, provider.Domain) - + w.log.Info("Setting up provider", + "provider", slog.GroupValue( + slog.String("name", provider.Name), + slog.String("domain", provider.Domain), + )) w.dir = "" w.provider = provider @@ -55,7 +57,7 @@ func (w *worker) setupProviderFull(provider *provider) error { "provider-metadata.json has %d validation issues", len(errors)) } - log.Printf("provider-metadata: %s\n", w.loc) + w.log.Info("Using provider-metadata", "url", w.loc) return nil } @@ -79,7 +81,7 @@ func (w *worker) fullWork(wg *sync.WaitGroup, jobs <-chan *fullJob) { func (p *processor) full() error { if p.cfg.runAsMirror() { - log.Println("Running in aggregator mode") + p.log.Info("Running in aggregator mode") // check if we need to setup a remote validator if p.cfg.RemoteValidatorOptions != nil { @@ -96,16 +98,18 @@ func (p *processor) full() error { }() } } else { - log.Println("Running in lister mode") + p.log.Info("Running in lister mode") } queue := make(chan *fullJob) var wg sync.WaitGroup - log.Printf("Starting %d workers.\n", p.cfg.Workers) + p.log.Info("Starting workers...", "num", p.cfg.Workers) + for i := 1; i <= p.cfg.Workers; i++ { wg.Add(1) w := newWorker(i, p) + go w.fullWork(&wg, queue) } @@ -135,12 +139,22 @@ func (p *processor) full() error { for i := range jobs { j := &jobs[i] if j.err != nil { - log.Printf("error: '%s' failed: %v\n", j.provider.Name, j.err) + p.log.Error("Job execution failed", + slog.Group("job", + slog.Group("provider"), + "name", j.provider.Name, + ), + "err", j.err, + ) continue } if j.aggregatorProvider == nil { - log.Printf( - "error: '%s' does not produce any result.\n", j.provider.Name) + p.log.Error("Job did not produce any result", + slog.Group("job", + slog.Group("provider"), + "name", j.provider.Name, + ), + ) continue } diff --git a/cmd/csaf_aggregator/indices.go b/cmd/csaf_aggregator/indices.go index 69954bd..cc91b45 100644 --- a/cmd/csaf_aggregator/indices.go +++ b/cmd/csaf_aggregator/indices.go @@ -12,7 +12,6 @@ import ( "bufio" "encoding/csv" "fmt" - "log" "os" "path/filepath" "sort" @@ -377,7 +376,7 @@ func (w *worker) writeIndices() error { } for label, summaries := range w.summaries { - log.Printf("%s: %d\n", label, len(summaries)) + w.log.Debug("Writing indices", "label", label, "summaries.num", len(summaries)) if err := w.writeInterims(label, summaries); err != nil { return err } diff --git a/cmd/csaf_aggregator/interim.go b/cmd/csaf_aggregator/interim.go index bdd5ebc..cf4a937 100644 --- a/cmd/csaf_aggregator/interim.go +++ b/cmd/csaf_aggregator/interim.go @@ -17,7 +17,6 @@ import ( "errors" "fmt" "io" - "log" "net/http" "os" "path/filepath" @@ -102,12 +101,12 @@ func (w *worker) checkInterims( // XXX: Should we return an error here? for _, e := range errors { - log.Printf("validation error: %s: %v\n", url, e) + w.log.Error("validation error", "url", url, "err", e) } // We need to write the changed content. - // This will start the transcation if not already started. + // This will start the transaction if not already started. dst, err := tx.Dst() if err != nil { return nil, err @@ -159,8 +158,7 @@ func (w *worker) checkInterims( // setupProviderInterim prepares the worker for a specific provider. func (w *worker) setupProviderInterim(provider *provider) { - log.Printf("worker #%d: %s (%s)\n", - w.num, provider.Name, provider.Domain) + w.log.Info("Setting up worker", provider.Name, provider.Domain) w.dir = "" w.provider = provider @@ -262,7 +260,7 @@ func (p *processor) interim() error { queue := make(chan *interimJob) var wg sync.WaitGroup - log.Printf("Starting %d workers.\n", p.cfg.Workers) + p.log.Info("Starting workers...", "num", p.cfg.Workers) for i := 1; i <= p.cfg.Workers; i++ { wg.Add(1) w := newWorker(i, p) diff --git a/cmd/csaf_aggregator/lazytransaction.go b/cmd/csaf_aggregator/lazytransaction.go index a2b1e94..458002f 100644 --- a/cmd/csaf_aggregator/lazytransaction.go +++ b/cmd/csaf_aggregator/lazytransaction.go @@ -9,11 +9,11 @@ package main import ( - "log" "os" "path/filepath" "github.com/csaf-poc/csaf_distribution/v3/util" + "golang.org/x/exp/slog" ) type lazyTransaction struct { @@ -85,7 +85,8 @@ func (lt *lazyTransaction) commit() error { os.RemoveAll(lt.dst) return err } - log.Printf("Move %q -> %q\n", symlink, lt.src) + + slog.Debug("Moving directory", "from", symlink, "to", lt.src) if err := os.Rename(symlink, lt.src); err != nil { os.RemoveAll(lt.dst) return err diff --git a/cmd/csaf_aggregator/main.go b/cmd/csaf_aggregator/main.go index 74a9670..b738a7e 100644 --- a/cmd/csaf_aggregator/main.go +++ b/cmd/csaf_aggregator/main.go @@ -15,7 +15,9 @@ import ( "path/filepath" "github.com/csaf-poc/csaf_distribution/v3/internal/options" + "github.com/gofrs/flock" + "golang.org/x/exp/slog" ) func lock(lockFile *string, fn func() error) error { @@ -44,8 +46,9 @@ func lock(lockFile *string, fn func() error) error { func main() { _, cfg, err := parseArgsConfig() - options.ErrorCheck(err) - options.ErrorCheck(cfg.prepare()) - p := processor{cfg: cfg} - options.ErrorCheck(lock(cfg.LockFile, p.process)) + cfg.prepareLogging() + options.ErrorCheckStructured(err) + options.ErrorCheckStructured(cfg.prepare()) + p := processor{cfg: cfg, log: slog.Default()} + options.ErrorCheckStructured(lock(cfg.LockFile, p.process)) } diff --git a/cmd/csaf_aggregator/mirror.go b/cmd/csaf_aggregator/mirror.go index 3acb48e..0779a5b 100644 --- a/cmd/csaf_aggregator/mirror.go +++ b/cmd/csaf_aggregator/mirror.go @@ -16,7 +16,7 @@ import ( "encoding/json" "fmt" "io" - "log" + "log/slog" "net/http" "net/url" "os" @@ -47,7 +47,7 @@ func (w *worker) mirror() (*csaf.AggregatorCSAFProvider, error) { if err != nil && w.dir != "" { // If something goes wrong remove the debris. if err := os.RemoveAll(w.dir); err != nil { - log.Printf("error: %v\n", err) + w.log.Error("Could not remove directory", "path", w.dir, "err", err) } } return result, err @@ -166,7 +166,7 @@ func (w *worker) writeProviderMetadata() error { {Expr: `$.public_openpgp_keys`, Action: util.ReMarshalMatcher(&pm.PGPKeys)}, }, w.metadataProvider); err != nil { // only log the errors - log.Printf("extracting data from orignal provider failed: %v\n", err) + w.log.Error("Extracting data from original provider failed", "err", err) } // We are mirroring the remote public keys, too. @@ -196,11 +196,11 @@ func (w *worker) mirrorPGPKeys(pm *csaf.ProviderMetadata) error { for i := range pm.PGPKeys { pgpKey := &pm.PGPKeys[i] if pgpKey.URL == nil { - log.Printf("ignoring PGP key without URL: %s\n", pgpKey.Fingerprint) + w.log.Warn("Ignoring PGP key without URL", "fingerprint", pgpKey.Fingerprint) continue } if _, err := hex.DecodeString(string(pgpKey.Fingerprint)); err != nil { - log.Printf("ignoring PGP with invalid fingerprint: %s\n", *pgpKey.URL) + w.log.Warn("Ignoring PGP key with invalid fingerprint", "url", *pgpKey.URL) continue } @@ -344,7 +344,7 @@ func (w *worker) doMirrorTransaction() error { // Check if there is a sysmlink already. target := filepath.Join(w.processor.cfg.Folder, w.provider.Name) - log.Printf("target: '%s'\n", target) + w.log.Debug("Checking for path existance", "path", target) exists, err := util.PathExists(target) if err != nil { @@ -359,7 +359,7 @@ func (w *worker) doMirrorTransaction() error { } } - log.Printf("sym link: %s -> %s\n", w.dir, target) + w.log.Debug("Creating symbol", "from", w.dir, "to", target) // Create a new symlink if err := os.Symlink(w.dir, target); err != nil { @@ -368,7 +368,7 @@ func (w *worker) doMirrorTransaction() error { } // Move the symlink - log.Printf("Move: %s -> %s\n", target, webTarget) + w.log.Debug("Moving symbol", "from", target, "to", webTarget) if err := os.Rename(target, webTarget); err != nil { os.RemoveAll(w.dir) return err @@ -499,14 +499,14 @@ func (w *worker) mirrorFiles(tlpLabel csaf.TLPLabel, files []csaf.AdvisoryFile) u, err := url.Parse(file.URL()) if err != nil { - log.Printf("error: %s\n", err) + w.log.Error("Could not parse advisory file URL", "err", err) continue } // Should we ignore this advisory? if w.provider.ignoreURL(file.URL(), w.processor.cfg) { if w.processor.cfg.Verbose { - log.Printf("Ignoring %s: %q\n", w.provider.Name, file.URL()) + w.log.Info("Ignoring advisory", slog.Group("provider", "name", w.provider.Name), "file", file) } continue } @@ -514,7 +514,7 @@ func (w *worker) mirrorFiles(tlpLabel csaf.TLPLabel, files []csaf.AdvisoryFile) // Ignore not conforming filenames. filename := filepath.Base(u.Path) if !util.ConformingFileName(filename) { - log.Printf("Not conforming filename %q. Ignoring.\n", filename) + w.log.Warn("Ignoring advisory because of non-conforming filename", "filename", filename) continue } @@ -531,19 +531,18 @@ func (w *worker) mirrorFiles(tlpLabel csaf.TLPLabel, files []csaf.AdvisoryFile) } if err := downloadJSON(w.client, file.URL(), download); err != nil { - log.Printf("error: %v\n", err) + w.log.Error("Error while downloading JSON", "err", err) continue } // Check against CSAF schema. errors, err := csaf.ValidateCSAF(advisory) if err != nil { - log.Printf("error: %s: %v", file, err) + w.log.Error("Error while validating CSAF schema", "err", err) continue } if len(errors) > 0 { - log.Printf("CSAF file %s has %d validation errors.\n", - file, len(errors)) + w.log.Error("CSAF file has validation errors", "num.errors", len(errors), "file", file) continue } @@ -551,29 +550,27 @@ func (w *worker) mirrorFiles(tlpLabel csaf.TLPLabel, files []csaf.AdvisoryFile) if rmv := w.processor.remoteValidator; rmv != nil { rvr, err := rmv.Validate(advisory) if err != nil { - log.Printf("Calling remote validator failed: %s\n", err) + w.log.Error("Calling remote validator failed", "err", err) continue } if !rvr.Valid { - log.Printf( - "CSAF file %s does not validate remotely.\n", file) + w.log.Error("CSAF file does not validate remotely", "file", file.URL()) continue } } sum, err := csaf.NewAdvisorySummary(w.expr, advisory) if err != nil { - log.Printf("error: %s: %v\n", file, err) + w.log.Error("Error while creating new advisory", "file", file, "err", err) continue } if util.CleanFileName(sum.ID) != filename { - log.Printf("ID %q does not match filename %s", - sum.ID, filename) + w.log.Error("ID mismatch", "id", sum.ID, "filename", filename) } if err := w.extractCategories(label, advisory); err != nil { - log.Printf("error: %s: %v\n", file, err) + w.log.Error("Could not extract categories", "file", file, "err", err) continue } @@ -624,7 +621,7 @@ func (w *worker) downloadSignatureOrSign(url, fname string, data []byte) error { if err != nil { if err != errNotFound { - log.Printf("error: %s: %v\n", url, err) + w.log.Error("Could not find signature URL", "url", url, "err", err) } // Sign it our self. if sig, err = w.sign(data); err != nil { diff --git a/cmd/csaf_aggregator/processor.go b/cmd/csaf_aggregator/processor.go index ccd5062..9a71b90 100644 --- a/cmd/csaf_aggregator/processor.go +++ b/cmd/csaf_aggregator/processor.go @@ -10,14 +10,14 @@ package main import ( "fmt" - "log" "os" "path/filepath" - "github.com/ProtonMail/gopenpgp/v2/crypto" - "github.com/csaf-poc/csaf_distribution/v3/csaf" "github.com/csaf-poc/csaf_distribution/v3/util" + + "github.com/ProtonMail/gopenpgp/v2/crypto" + "golang.org/x/exp/slog" ) type processor struct { @@ -26,6 +26,9 @@ type processor struct { // remoteValidator is a globally configured remote validator. remoteValidator csaf.RemoteValidator + + // log is the structured logger for the whole processor. + log *slog.Logger } type summary struct { @@ -48,6 +51,7 @@ type worker struct { dir string // Directory to store data to. summaries map[string][]summary // the summaries of the advisories. categories map[string]util.Set[string] // the categories per label. + log *slog.Logger // the structured logger, supplied with the worker number. } func newWorker(num int, processor *processor) *worker { @@ -55,6 +59,7 @@ func newWorker(num int, processor *processor) *worker { num: num, processor: processor, expr: util.NewPathEval(), + log: processor.log.With(slog.Int("worker", num)), } } @@ -86,9 +91,10 @@ func (w *worker) locateProviderMetadata(domain string) error { if w.processor.cfg.Verbose { for i := range lpmd.Messages { - log.Printf( - "Loading provider-metadata.json of %q: %s\n", - domain, lpmd.Messages[i].Message) + w.log.Info( + "Loading provider-metadata.json", + "domain", domain, + "message", lpmd.Messages[i].Message) } } @@ -141,7 +147,7 @@ func (p *processor) removeOrphans() error { fi, err := entry.Info() if err != nil { - log.Printf("error: %v\n", err) + p.log.Error("Could not retrieve file info", "err", err) continue } @@ -153,13 +159,13 @@ func (p *processor) removeOrphans() error { d := filepath.Join(path, entry.Name()) r, err := filepath.EvalSymlinks(d) if err != nil { - log.Printf("error: %v\n", err) + p.log.Error("Could not evaluate symlink", "err", err) continue } fd, err := os.Stat(r) if err != nil { - log.Printf("error: %v\n", err) + p.log.Error("Could not retrieve file stats", "err", err) continue } @@ -169,18 +175,18 @@ func (p *processor) removeOrphans() error { } // Remove the link. - log.Printf("removing link %s -> %s\n", d, r) + p.log.Info("Removing link", "path", fmt.Sprintf("%s -> %s", d, r)) if err := os.Remove(d); err != nil { - log.Printf("error: %v\n", err) + p.log.Error("Could not remove symlink", "err", err) continue } // Only remove directories which are in our folder. if rel, err := filepath.Rel(prefix, r); err == nil && rel == filepath.Base(r) { - log.Printf("removing directory %s\n", r) + p.log.Info("Remove directory", "path", r) if err := os.RemoveAll(r); err != nil { - log.Printf("error: %v\n", err) + p.log.Error("Could not remove directory", "err", err) } } } diff --git a/csaf/advisories.go b/csaf/advisories.go index 5b85690..abd55c6 100644 --- a/csaf/advisories.go +++ b/csaf/advisories.go @@ -13,6 +13,7 @@ import ( "fmt" "io" "log" + "log/slog" "net/http" "net/url" "strings" @@ -23,6 +24,7 @@ import ( // AdvisoryFile constructs the urls of a remote file. type AdvisoryFile interface { + slog.LogValuer URL() string SHA256URL() string SHA512URL() string @@ -46,6 +48,11 @@ func (paf PlainAdvisoryFile) SHA512URL() string { return string(paf) + ".sha512" // SignURL returns the URL of signature file of this advisory. func (paf PlainAdvisoryFile) SignURL() string { return string(paf) + ".asc" } +// LogValue implements [slog.LogValuer] +func (paf PlainAdvisoryFile) LogValue() slog.Value { + return slog.GroupValue(slog.String("url", paf.URL())) +} + // HashedAdvisoryFile is a more involed version of checkFile. // Here each component can be given explicitly. // If a component is not given it is constructed by @@ -71,6 +78,11 @@ func (haf HashedAdvisoryFile) SHA512URL() string { return haf.name(2, ".sha512") // SignURL returns the URL of signature file of this advisory. func (haf HashedAdvisoryFile) SignURL() string { return haf.name(3, ".asc") } +// LogValue implements [slog.LogValuer] +func (haf HashedAdvisoryFile) LogValue() slog.Value { + return slog.GroupValue(slog.String("url", haf.URL())) +} + // AdvisoryFileProcessor implements the extraction of // advisory file names from a given provider metadata. type AdvisoryFileProcessor struct { diff --git a/go.mod b/go.mod index 469c8a3..1f6f51d 100644 --- a/go.mod +++ b/go.mod @@ -14,7 +14,7 @@ require ( github.com/santhosh-tekuri/jsonschema/v5 v5.3.1 go.etcd.io/bbolt v1.3.8 golang.org/x/crypto v0.14.0 - golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa + golang.org/x/exp v0.0.0-20240416160154-fe59bbe5cc7f golang.org/x/term v0.13.0 golang.org/x/time v0.3.0 ) diff --git a/go.sum b/go.sum index 3a101d4..cbbb382 100644 --- a/go.sum +++ b/go.sum @@ -53,6 +53,8 @@ golang.org/x/crypto v0.14.0 h1:wBqGXzWJW6m1XrIKlAH0Hs1JJ7+9KBwnIO8v66Q9cHc= golang.org/x/crypto v0.14.0/go.mod h1:MVFd36DqK4CsrnJYDkBA3VC4m2GkXAM0PvzMCn4JQf4= golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa h1:FRnLl4eNAQl8hwxVVC17teOw8kdjVDVAiFMtgUdTSRQ= golang.org/x/exp v0.0.0-20231110203233-9a3e6036ecaa/go.mod h1:zk2irFbV9DP96SEBUUAy67IdHUaZuSnrz1n472HUCLE= +golang.org/x/exp v0.0.0-20240416160154-fe59bbe5cc7f h1:99ci1mjWVBWwJiEKYY6jWa4d2nTQVIEhZIptnrVb1XY= +golang.org/x/exp v0.0.0-20240416160154-fe59bbe5cc7f/go.mod h1:/lliqkxwWAhPjf5oSOIJup2XcqJaw8RGS6k3TGEc7GI= golang.org/x/mod v0.6.0-dev.0.20220419223038-86c51ed26bb4/go.mod h1:jJ57K6gSWd91VN4djpZkiMVwK6gcyfeH4XE8wZrZaV4= golang.org/x/mod v0.8.0/go.mod h1:iBbtSCu2XBx23ZKBPSOrRkjjQPZFPuis4dIYUhu/chs= golang.org/x/net v0.0.0-20190620200207-3b0461eec859/go.mod h1:z5CRVTTTmAJ677TzLLGU+0bjPO0LkuOLi4/5GtJWs/s= diff --git a/internal/options/options.go b/internal/options/options.go index 961b4b4..ffd699b 100644 --- a/internal/options/options.go +++ b/internal/options/options.go @@ -19,6 +19,7 @@ import ( "github.com/mitchellh/go-homedir" "github.com/csaf-poc/csaf_distribution/v3/util" + "golang.org/x/exp/slog" ) // Parser helps parsing command line arguments and loading @@ -147,3 +148,12 @@ func ErrorCheck(err error) { log.Fatalf("error: %v\n", err) } } + +// ErrorCheck checks if err is not nil and terminates +// the program if so. +func ErrorCheckStructured(err error) { + if err != nil { + slog.Error("Error while executing program", "err", err) + os.Exit(1) + } +}