tka: improve logging for Compact and Commit operations

Log whenever we:

* Commit an AUM which was previously soft-deleted (which we don't expect
  to happen in practice, and may indicate an issue with our sync code)
* Purge AUMs during a Compact operation.
* Successfully commit AUMs as part of a bootstrap or sync operation.

All three logs mention `tka` for easy of discoverability.

Updates tailscale/corp#39455

Change-Id: I2b07bb0ef075877f40ec34b80bb668be59e1cdc3
Signed-off-by: Alex Chan <alexc@tailscale.com>

2 files changed, 13 insertions, 0 deletions

diff --git a/tka/tailchonk.go b/tka/tailchonk.go
index 3b083f327..da1915acb 100644
--- a/tka/tailchonk.go
+++ b/tka/tailchonk.go
@@ -597,6 +597,9 @@ func (c *FS) CommitVerifiedAUMs(updates []AUM) error {
 	for i, aum := range updates {
 		h := aum.Hash()
 		err := c.commit(h, func(info *fsHashInfo) {
+			if info.PurgedUnix > 0 {
+				log.Printf("tka: CommitVerifiedAUMs: committing previously-deleted AUM %s", h.String())
+			}
 			info.PurgedUnix = 0 // just in-case it was set for some reason
 			info.AUM = &aum
 		})
@@ -973,5 +976,8 @@ func Compact(storage CompactableChonk, head AUMHash, opts CompactionOptions) (la
 	if err := storage.SetLastActiveAncestor(lastActiveAncestor); err != nil {
 		return AUMHash{}, err
 	}
+	if len(toDelete) > 0 {
+		log.Printf("tka compaction: purging %d AUM(s) [%q]", len(toDelete), toDelete)
+	}
 	return lastActiveAncestor, storage.PurgeAUMs(toDelete)
 }
diff --git a/tka/tka.go b/tka/tka.go
index 9b22edc2e..57a8bd122 100644
--- a/tka/tka.go
+++ b/tka/tka.go
@@ -10,6 +10,7 @@ import (
 	"bytes"
 	"errors"
 	"fmt"
+	"log"
 	"os"
 	"sort"
 
@@ -556,6 +557,8 @@ func Bootstrap(storage Chonk, bootstrap AUM) (*Authority, error) {
 	// Everything looks good, write it to storage.
 	if err := storage.CommitVerifiedAUMs([]AUM{bootstrap}); err != nil {
 		return nil, fmt.Errorf("commit: %v", err)
+	} else {
+		log.Printf("tka.Bootstrap: successfully committed bootstrap AUM (%s)", bootstrap.Hash())
 	}
 	if err := storage.SetLastActiveAncestor(bootstrap.Hash()); err != nil {
 		return nil, fmt.Errorf("set ancestor: %v", err)
@@ -587,6 +590,7 @@ func (a *Authority) InformIdempotent(storage Chonk, updates []AUM) (Authority, e
 	}
 	stateAt := make(map[AUMHash]State, len(updates)+1)
 	toCommit := make([]AUM, 0, len(updates))
+	toCommitHashes := make([]AUMHash, 0, len(updates))
 	prevHash := a.Head()
 
 	// The state at HEAD is the current state of the authority. It's likely
@@ -636,10 +640,13 @@ func (a *Authority) InformIdempotent(storage Chonk, updates []AUM) (Authority, e
 		}
 		prevHash = hash
 		toCommit = append(toCommit, update)
+		toCommitHashes = append(toCommitHashes, update.Hash())
 	}
 
 	if err := storage.CommitVerifiedAUMs(toCommit); err != nil {
 		return Authority{}, fmt.Errorf("commit: %v", err)
+	} else {
+		log.Printf("tka.CommitVerifiedAUMs: successfully committed %d AUMs: %v", len(toCommit), toCommitHashes)
 	}
 
 	if isHeadChain {