From 5db49b6b0e7f91c55619dfa63cbd344fefc0233e Mon Sep 17 00:00:00 2001 From: mrhid6 Date: Fri, 7 Aug 2026 10:50:08 +0100 Subject: [PATCH] feat: Vuln debug logs --- server/internal/services/findings.go | 3 +++ server/internal/vulndb/db.go | 3 +++ server/internal/vulndb/match.go | 11 +++++++++ server/internal/vulndb/pull.go | 30 +++++++++++++++++++++++- server/internal/vulnsched/sched.go | 34 +++++++++++++++++++++++++++- 5 files changed, 79 insertions(+), 2 deletions(-) diff --git a/server/internal/services/findings.go b/server/internal/services/findings.go index a93ff42..be0213d 100644 --- a/server/internal/services/findings.go +++ b/server/internal/services/findings.go @@ -207,8 +207,11 @@ func MarkInstanceForRescan(instanceID string) (int64, error) { bson.M{"$set": bson.M{"scan_pending": true}}, ) if err != nil { + log.Printf("vulnsched: mark rescan for instance %s: %v", instanceID, err) return 0, err } + log.Printf("vulnsched: rescan requested for instance %s, %d of %d server(s) flagged", + instanceID, res.ModifiedCount, res.MatchedCount) return res.ModifiedCount, nil } diff --git a/server/internal/vulndb/db.go b/server/internal/vulndb/db.go index dc1dfa7..b3c3fd4 100644 --- a/server/internal/vulndb/db.go +++ b/server/internal/vulndb/db.go @@ -1,6 +1,7 @@ package vulndb import ( + "log" "strings" trivydb "github.com/aquasecurity/trivy-db/pkg/db" @@ -33,8 +34,10 @@ type Store struct { // it appends "trivy.db" itself. func Open(dir string) (*Store, error) { if err := trivydb.Init(dir); err != nil { + log.Printf("vulndb: open %s: %v", dir, err) return nil, err } + log.Printf("vulndb: opened database in %s", dir) return &Store{cfg: trivydb.Config{}}, nil } diff --git a/server/internal/vulndb/match.go b/server/internal/vulndb/match.go index 32d317d..125dcb6 100644 --- a/server/internal/vulndb/match.go +++ b/server/internal/vulndb/match.go @@ -32,9 +32,12 @@ type Result struct { func Match(src AdvisorySource, os models.OSRelease, pkgs []models.InstalledPackage) ([]Result, error) { bucket, err := Bucket(os.Family, os.VersionID) if err != nil { + log.Printf("vulndb: no bucket for family=%q version=%q: %v", os.Family, os.VersionID, err) return nil, err } + log.Printf("vulndb: matching %d packages against bucket %q", len(pkgs), bucket) + var advisoryCount, skipped int var out []Result for _, p := range pkgs { // Debian and Ubuntu advisories are keyed on the source package: one @@ -48,6 +51,10 @@ func Match(src AdvisorySource, os models.OSRelease, pkgs []models.InstalledPacka if err != nil { return nil, fmt.Errorf("advisories for %s: %w", srcName, err) } + advisoryCount += len(advs) + if len(advs) > 0 { + Debugf("%s (src %s, installed %s): %d advisories", p.Name, srcName, p.Version, len(advs)) + } for _, a := range advs { // No published fix. Vulnerable, and the finding most in need of @@ -67,8 +74,10 @@ func Match(src AdvisorySource, os models.OSRelease, pkgs []models.InstalledPacka // on the host. Log it — a silent skip is a silent false // negative, which is the direction that hurts. log.Printf("vulndb: compare %s %s vs %s: %v", p.Name, p.Version, a.FixedVersion, err) + skipped++ continue } + Debugf("%s %s vs fixed %s (%s): vulnerable=%t", p.Name, p.Version, a.FixedVersion, a.CVEID, older) if older { out = append(out, Result{ CVEID: a.CVEID, PackageName: p.Name, @@ -77,5 +86,7 @@ func Match(src AdvisorySource, os models.OSRelease, pkgs []models.InstalledPacka } } } + log.Printf("vulndb: bucket %q done: %d packages, %d advisories considered, %d results, %d unparseable comparisons", + bucket, len(pkgs), advisoryCount, len(out), skipped) return out, nil } diff --git a/server/internal/vulndb/pull.go b/server/internal/vulndb/pull.go index 39b1e78..ab77bf4 100644 --- a/server/internal/vulndb/pull.go +++ b/server/internal/vulndb/pull.go @@ -7,9 +7,11 @@ import ( "encoding/json" "fmt" "io" + "log" "os" "path/filepath" "strings" + "time" ocispec "github.com/opencontainers/image-spec/specs-go/v1" "oras.land/oras-go/v2" @@ -49,6 +51,24 @@ func Disabled() bool { return strings.EqualFold(os.Getenv("VANTAGE_VULNDB_DISABLED"), "true") } +// DebugEnabled turns on per-package and per-advisory tracing. +// +// It is a switch rather than always-on because a single scan asks the store one +// question per installed package — ~2000 lines per server, per tick — which +// would bury every other subsystem's logs on a fleet of any size. The lifecycle +// logs (pull, tick, per-server totals) are unconditional; only the inner loop +// is gated. +func DebugEnabled() bool { + return strings.EqualFold(os.Getenv("VANTAGE_VULN_DEBUG"), "true") +} + +// Debugf logs only when VANTAGE_VULN_DEBUG=true. +func Debugf(format string, args ...any) { + if DebugEnabled() { + log.Printf("vulndb[debug]: "+format, args...) + } +} + // dbMetadata is the subset of trivy-db's metadata.json we read. type dbMetadata struct { Version int `json:"Version"` @@ -62,6 +82,8 @@ type dbMetadata struct { // one that Open would happily accept and scan against. func Pull(ctx context.Context, dir string) (int, error) { ref := Ref() + started := time.Now() + log.Printf("vulndb: pull starting ref=%s dir=%s", ref, dir) parsed, err := registry.ParseReference(ref) if err != nil { @@ -92,6 +114,8 @@ func Pull(ctx context.Context, dir string) (int, error) { if len(man.Layers) == 0 { return 0, fmt.Errorf("artifact %s has no layers", ref) } + log.Printf("vulndb: manifest resolved layers=%d digest=%s size=%dB", + len(man.Layers), man.Layers[0].Digest, man.Layers[0].Size) // Streamed rather than buffered: the layer is ~50MB and there is no reason // to hold it in memory on the way to disk. @@ -110,6 +134,7 @@ func Pull(ctx context.Context, dir string) (int, error) { if err := extractTarGz(rc, staging); err != nil { return 0, fmt.Errorf("extract layer: %w", err) } + log.Printf("vulndb: layer extracted into %s after %s", staging, time.Since(started).Round(time.Millisecond)) metaBytes, err := os.ReadFile(filepath.Join(staging, metaFileName)) if err != nil { @@ -123,9 +148,11 @@ func Pull(ctx context.Context, dir string) (int, error) { return 0, fmt.Errorf("trivy-db schema %d is not supported (want %d)", meta.Version, SupportedSchema) } - if _, err := os.Stat(filepath.Join(staging, dbFileName)); err != nil { + fi, err := os.Stat(filepath.Join(staging, dbFileName)) + if err != nil { return 0, fmt.Errorf("artifact has no %s: %w", dbFileName, err) } + log.Printf("vulndb: %s is %dB, schema %d accepted", dbFileName, fi.Size(), meta.Version) // Both files present and the schema accepted, so it is safe to replace. for _, name := range []string{dbFileName, metaFileName} { @@ -139,6 +166,7 @@ func Pull(ctx context.Context, dir string) (int, error) { } } + log.Printf("vulndb: pull complete ref=%s schema=%d in %s", ref, meta.Version, time.Since(started).Round(time.Millisecond)) return meta.Version, nil } diff --git a/server/internal/vulnsched/sched.go b/server/internal/vulnsched/sched.go index b1d2eeb..d5e6fb5 100644 --- a/server/internal/vulnsched/sched.go +++ b/server/internal/vulnsched/sched.go @@ -51,11 +51,17 @@ func Start(ctx context.Context, deps Deps) { dir, err := os.MkdirTemp("", "vantage-vulndb-") if err != nil { - log.Printf("vulnsched: temp dir: %v", err) + // The classic form of this is "stat /tmp: no such file or directory" on + // the scratch runtime image. It is logged once at boot while everything + // else runs normally, so the only other symptom is a fleet that never + // reports a finding. + log.Printf("vulnsched: temp dir: %v (scan loop NOT started)", err) return } s := &scheduler{deps: deps, dir: dir} + log.Printf("vulnsched: started, ref=%s tick=%s dir=%s debug=%t", + vulndb.Ref(), tickInterval, dir, vulndb.DebugEnabled()) go func() { defer os.RemoveAll(dir) @@ -66,6 +72,7 @@ func Start(ctx context.Context, deps Deps) { for { select { case <-ctx.Done(): + log.Println("vulnsched: leadership lost or shutting down, scan loop stopping") return case <-ticker.C: s.tick(ctx) @@ -75,16 +82,22 @@ func Start(ctx context.Context, deps Deps) { } func (s *scheduler) tick(ctx context.Context) { + started := time.Now() + vulndb.Debugf("vulnsched tick starting (store loaded=%t, db version=%d, pulled %s ago)", + s.store != nil, s.version, time.Since(s.pulled).Round(time.Second)) + if err := s.ensureDB(ctx); err != nil { // Keep the last good database and carry on scanning against it. A // network blip must never clear findings or read as "all fixed". log.Printf("vulnsched: database unavailable: %v", err) s.recordDBError(ctx, err) if s.store == nil { + log.Println("vulnsched: no database loaded at all, nothing can be scanned this tick") return } } s.scanPending(ctx) + vulndb.Debugf("vulnsched tick finished in %s", time.Since(started).Round(time.Millisecond)) } // ensureDB pulls a fresh database when the local copy is stale, and marks the @@ -93,8 +106,11 @@ func (s *scheduler) tick(ctx context.Context) { // next agent report. func (s *scheduler) ensureDB(ctx context.Context) error { if s.store != nil && time.Since(s.pulled) < dbMaxAge { + vulndb.Debugf("database is %s old, under the %s limit; not pulling", + time.Since(s.pulled).Round(time.Second), dbMaxAge) return nil } + log.Printf("vulnsched: pulling database (age %s, max %s)", time.Since(s.pulled).Round(time.Second), dbMaxAge) version, err := vulndb.Pull(ctx, s.dir) if err != nil { @@ -110,6 +126,7 @@ func (s *scheduler) ensureDB(ctx context.Context) error { s.pulled = time.Now() changed := version != s.version + log.Printf("vulnsched: database ready, schema %d (previous %d, changed=%t)", version, s.version, changed) s.version = version _, _ = db.Col("vulndb_meta").UpdateOne(ctx, bson.M{}, @@ -152,6 +169,12 @@ func (s *scheduler) scanPending(ctx context.Context) { return } + if len(pending) == 0 { + vulndb.Debugf("no servers pending scan") + return + } + log.Printf("vulnsched: %d server(s) pending scan", len(pending)) + // Newly opened findings are collected across the whole tick and sent as one // digest per instance. A database refresh can open several hundred findings // at once; one message per finding would rate-limit the webhook or get the @@ -182,6 +205,8 @@ func (s *scheduler) scanPending(ctx context.Context) { func (s *scheduler) scanOne(ctx context.Context, sp models.ServerPackages) []models.VulnFinding { now := time.Now() + log.Printf("vulnsched: scanning server %s (instance %s, os %s %s, %d packages)", + sp.ServerID, sp.InstanceID, sp.OS.Family, sp.OS.VersionID, len(sp.Packages)) results, err := vulndb.Match(s.store, sp.OS, sp.Packages) if err != nil { @@ -193,6 +218,9 @@ func (s *scheduler) scanOne(ctx context.Context, sp models.ServerPackages) []mod if !errors.Is(err, vulndb.ErrUnsupportedFamily) { log.Printf("vulnsched: scan %s: %v", sp.ServerID, err) status = sp.Status + } else { + log.Printf("vulnsched: server %s marked unsupported: no feed for %s %s", + sp.ServerID, sp.OS.Family, sp.OS.VersionID) } s.clearPending(ctx, sp.ID, status, now) return nil @@ -210,6 +238,10 @@ func (s *scheduler) scanOne(ctx context.Context, sp models.ServerPackages) []mod return nil } + log.Printf("vulnsched: server %s scanned: %d matches, %d existing, %d upserts, %d newly opened, %d reopened, %d fixed", + sp.ServerID, len(results), len(existing), len(diff.Upserts), + len(diff.NewlyOpened), len(diff.ReopenIDs), len(diff.FixedIDs)) + s.clearPending(ctx, sp.ID, models.ScanStatusOK, now) for i := range diff.NewlyOpened {