feat: Vuln debug logs

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
 }
 

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
 }
 

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
 }

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
 }
 

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 {