add debug logging about bstore db schema upgrades

bstore was updated to v0.0.6 to add this logging.
this simplifies some of the db-handling code in mtastsdb,tlsrptdb,dmarcdb. we
now call the package-level Init() and Close() in all tests properly.

mtastsdb/db.go

@@ -14,7 +14,6 @@ import (
 	"os"
 	"path/filepath"
 	"strings"
-	"sync"
 	"time"
 
 	"github.com/prometheus/client_golang/prometheus"
@@ -68,27 +67,17 @@ var (
 
 var DBTypes = []any{PolicyRecord{}} // Types stored in DB.
 var DB *bstore.DB                   // Exported for backups.
-var mutex sync.Mutex
-
-func database(ctx context.Context) (rdb *bstore.DB, rerr error) {
-	mutex.Lock()
-	defer mutex.Unlock()
-	if DB == nil {
-		p := mox.DataDirPath("mtasts.db")
-		os.MkdirAll(filepath.Dir(p), 0770)
-		db, err := bstore.Open(ctx, p, &bstore.Options{Timeout: 5 * time.Second, Perm: 0660}, DBTypes...)
-		if err != nil {
-			return nil, err
-		}
-		DB = db
-	}
-	return DB, nil
-}
 
 // Init opens the database and starts a goroutine that refreshes policies in
 // the database, and keeps doing so periodically.
 func Init(refresher bool) error {
-	_, err := database(mox.Shutdown)
+	log := mlog.New("mtastsdb", nil)
+
+	p := mox.DataDirPath("mtasts.db")
+	os.MkdirAll(filepath.Dir(p), 0770)
+	opts := bstore.Options{Timeout: 5 * time.Second, Perm: 0660, RegisterLogger: log.Logger}
+	var err error
+	DB, err = bstore.Open(mox.Shutdown, p, &opts, DBTypes...)
 	if err != nil {
 		return err
 	}
@@ -102,14 +91,12 @@ func Init(refresher bool) error {
 }
 
 // Close closes the database.
-func Close() {
-	mutex.Lock()
-	defer mutex.Unlock()
-	if DB != nil {
-		err := DB.Close()
-		mlog.New("mtastsdb", nil).Check(err, "closing database")
-		DB = nil
+func Close() error {
+	if err := DB.Close(); err != nil {
+		return fmt.Errorf("close db: %w", err)
 	}
+	DB = nil
+	return nil
 }
 
 // lookup looks up a policy for the domain in the database.
@@ -119,16 +106,11 @@ func Close() {
 // Returns ErrNotFound if record is not present.
 // Returns ErrBackoff if a recent attempt to fetch a record failed.
 func lookup(ctx context.Context, log mlog.Log, domain dns.Domain) (*PolicyRecord, error) {
-	db, err := database(ctx)
-	if err != nil {
-		return nil, err
-	}
-
 	if domain.IsZero() {
 		return nil, fmt.Errorf("empty domain")
 	}
 	now := timeNow()
-	q := bstore.QueryDB[PolicyRecord](ctx, db)
+	q := bstore.QueryDB[PolicyRecord](ctx, DB)
 	q.FilterNonzero(PolicyRecord{Domain: domain.Name()})
 	q.FilterGreater("ValidEnd", now)
 	pr, err := q.Get()
@@ -139,7 +121,7 @@ func lookup(ctx context.Context, log mlog.Log, domain dns.Domain) (*PolicyRecord
 	}
 
 	pr.LastUse = now
-	if err := db.Update(ctx, &pr); err != nil {
+	if err := DB.Update(ctx, &pr); err != nil {
 		log.Errorx("marking cached mta-sts policy as used in database", err)
 	}
 	if pr.Backoff {
@@ -151,12 +133,7 @@ func lookup(ctx context.Context, log mlog.Log, domain dns.Domain) (*PolicyRecord
 // Upsert adds the policy to the database, overwriting an existing policy for the domain.
 // Policy can be nil, indicating a failure to fetch the policy.
 func Upsert(ctx context.Context, domain dns.Domain, recordID string, policy *mtasts.Policy, policyText string) error {
-	db, err := database(ctx)
-	if err != nil {
-		return err
-	}
-
-	return db.Write(ctx, func(tx *bstore.Tx) error {
+	return DB.Write(ctx, func(tx *bstore.Tx) error {
 		pr := PolicyRecord{Domain: domain.Name()}
 		err := tx.Get(&pr)
 		if err != nil && err != bstore.ErrAbsent {
@@ -195,11 +172,7 @@ func Upsert(ctx context.Context, domain dns.Domain, recordID string, policy *mta
 // PolicyRecords returns all policies in the database, sorted descending by last
 // use, domain.
 func PolicyRecords(ctx context.Context) ([]PolicyRecord, error) {
-	db, err := database(ctx)
-	if err != nil {
-		return nil, err
-	}
-	return bstore.QueryDB[PolicyRecord](ctx, db).SortDesc("LastUse", "Domain").List()
+	return bstore.QueryDB[PolicyRecord](ctx, DB).SortDesc("LastUse", "Domain").List()
 }
 
 // Get retrieves an MTA-STS policy for domain and whether it is fresh.

mtastsdb/refresh.go

@@ -51,19 +51,14 @@ func refresh() int {
 // jitter to the timing. Each refresh is done in a new goroutine, so a single slow
 // refresh doesn't mess up the timing.
 func refresh1(ctx context.Context, log mlog.Log, resolver dns.Resolver, sleep func(d time.Duration)) (int, error) {
-	db, err := database(ctx)
-	if err != nil {
-		return 0, err
-	}
-
 	now := timeNow()
-	qdel := bstore.QueryDB[PolicyRecord](ctx, db)
+	qdel := bstore.QueryDB[PolicyRecord](ctx, DB)
 	qdel.FilterLess("LastUse", now.Add(-180*24*time.Hour))
 	if _, err := qdel.Delete(); err != nil {
 		return 0, fmt.Errorf("deleting old unused policies: %s", err)
 	}
 
-	qup := bstore.QueryDB[PolicyRecord](ctx, db)
+	qup := bstore.QueryDB[PolicyRecord](ctx, DB)
 	qup.FilterLess("LastUpdate", now.Add(-12*time.Hour))
 	prs, err := qup.List()
 	if err != nil {
@@ -89,7 +84,7 @@ func refresh1(ctx context.Context, log mlog.Log, resolver dns.Resolver, sleep fu
 	log.Debug("will refresh mta-sts policies over next 3 hours", slog.Int("count", len(prs)))
 	start := timeNow()
 	for i, pr := range prs {
-		go refreshDomain(ctx, log, db, resolver, pr)
+		go refreshDomain(ctx, log, DB, resolver, pr)
 		if i < len(prs)-1 {
 			interval := 3 * int64(time.Hour) / int64(len(prs)-1)
 			extra := time.Duration(rand.Int63n(interval) - interval/2)

mtastsdb/refresh_test.go

@@ -9,7 +9,7 @@ import (
 	"errors"
 	"fmt"
 	"io"
-	"log"
+	golog "log"
 	"math/big"
 	"net"
 	"net/http"
@@ -39,15 +39,14 @@ func TestRefresh(t *testing.T) {
 	os.Remove(dbpath)
 	defer os.Remove(dbpath)
 
-	if err := Init(false); err != nil {
-		t.Fatalf("init database: %s", err)
-	}
-	defer Close()
+	log := mlog.New("mtastsdb", nil)
 
-	db, err := database(ctxbg)
-	if err != nil {
-		t.Fatalf("database: %s", err)
-	}
+	err := Init(false)
+	tcheckf(t, err, "init database")
+	defer func() {
+		err := Close()
+		tcheckf(t, err, "close database")
+	}()
 
 	cert := fakeCert(t, false)
 	defer func() {
@@ -70,7 +69,7 @@ func TestRefresh(t *testing.T) {
 		}
 
 		pr := PolicyRecord{domain, time.Time{}, validEnd, lastUpdate, lastUse, backoff, recordID, policy, policy.String()}
-		if err := db.Insert(ctxbg, &pr); err != nil {
+		if err := DB.Insert(ctxbg, &pr); err != nil {
 			t.Fatalf("insert policy: %s", err)
 		}
 	}
@@ -114,7 +113,7 @@ func TestRefresh(t *testing.T) {
 			TLSConfig: &tls.Config{
 				Certificates: []tls.Certificate{cert},
 			},
-			ErrorLog: log.New(io.Discard, "", 0),
+			ErrorLog: golog.New(io.Discard, "", 0),
 		}
 		s.ServeTLS(l, "", "")
 	}()
@@ -136,7 +135,6 @@ func TestRefresh(t *testing.T) {
 			t.Fatalf("bad sleep duration %v", d)
 		}
 	}
-	log := mlog.New("mtastsdb", nil)
 	if n, err := refresh1(ctxbg, log, resolver, sleep); err != nil || n != 3 {
 		t.Fatalf("refresh1: err %s, n %d, expected no error, 3", err, n)
 	}
@@ -146,7 +144,7 @@ func TestRefresh(t *testing.T) {
 	time.Sleep(time.Second / 10) // Give goroutine time to write result, before we cleanup the database.
 
 	// Should not do any more refreshes and return immediately.
-	q := bstore.QueryDB[PolicyRecord](ctxbg, db)
+	q := bstore.QueryDB[PolicyRecord](ctxbg, DB)
 	q.FilterNonzero(PolicyRecord{Domain: "policybad.mox.example"})
 	if _, err := q.Delete(); err != nil {
 		t.Fatalf("delete record that would be refreshed: %v", err)