Add trace logging.

cmd/litestream/replicate.go

@@ -5,8 +5,10 @@ import (
 	"errors"
 	"flag"
 	"fmt"
+	"log"
 	"net"
 	"net/http"
+	_ "net/http/pprof"
 	"os"
 	"os/signal"
 
@@ -25,6 +27,7 @@ type ReplicateCommand struct {
 // Run loads all databases specified in the configuration.
 func (c *ReplicateCommand) Run(ctx context.Context, args []string) (err error) {
 	fs := flag.NewFlagSet("litestream-replicate", flag.ContinueOnError)
+	verbose := fs.Bool("v", false, "verbose logging")
 	registerConfigFlag(fs, &c.ConfigPath)
 	fs.Usage = c.Usage
 	if err := fs.Parse(args); err != nil {
@@ -40,6 +43,11 @@ func (c *ReplicateCommand) Run(ctx context.Context, args []string) (err error) {
 		return err
 	}
 
+	// Enable trace logging.
+	if *verbose {
+		litestream.Tracef = log.Printf
+	}
+
 	// Setup signal handler.
 	ctx, cancel := context.WithCancel(ctx)
 	ch := make(chan os.Signal, 1)
@@ -119,5 +127,8 @@ Arguments:
 	-config PATH
 	    Specifies the configuration file. Defaults to %s
 
+	-v
+	    Enable verbose logging output.
+
 `[1:], DefaultConfigPath)
 }

db.go

@@ -606,6 +606,7 @@ func (db *DB) Sync() (err error) {
 	if err := db.init(); err != nil {
 		return err
 	} else if db.db == nil {
+		Tracef("%s: sync: no database found", db.path)
 		return nil
 	}
 
@@ -652,6 +653,7 @@ func (db *DB) Sync() (err error) {
 	if err != nil {
 		return fmt.Errorf("cannot verify wal state: %w", err)
 	}
+	Tracef("%s: sync: info=%#v", db.path, info)
 
 	// Track if anything in the shadow WAL changes and then notify at the end.
 	changed := info.walSize != info.shadowWALSize || info.restart || info.reason != ""
@@ -721,6 +723,8 @@ func (db *DB) Sync() (err error) {
 		db.notify = make(chan struct{})
 	}
 
+	Tracef("%s: sync: ok", db.path)
+
 	return nil
 }
 
@@ -898,6 +902,8 @@ func (db *DB) initShadowWALFile(filename string) error {
 }
 
 func (db *DB) copyToShadowWAL(filename string) (newSize int64, err error) {
+	Tracef("%s: copy-shadow: %s", db.path, filename)
+
 	r, err := os.Open(db.WALPath())
 	if err != nil {
 		return 0, err
@@ -946,8 +952,11 @@ func (db *DB) copyToShadowWAL(filename string) (newSize int64, err error) {
 	newSize = origSize
 	buf := make([]byte, db.pageSize+WALFrameHeaderSize)
 	for {
+		Tracef("%s: copy-shadow: %s @ %d", db.path, filename, newSize)
+
 		// Read next page from WAL file.
 		if _, err := io.ReadFull(r, buf); err == io.EOF || err == io.ErrUnexpectedEOF {
+			Tracef("%s: copy-shadow: break %s", db.path, err)
 			break // end of file or partial page
 		} else if err != nil {
 			return newSize, fmt.Errorf("read wal: %w", err)
@@ -957,6 +966,7 @@ func (db *DB) copyToShadowWAL(filename string) (newSize int64, err error) {
 		salt0 := binary.BigEndian.Uint32(buf[8:])
 		salt1 := binary.BigEndian.Uint32(buf[12:])
 		if salt0 != hsalt0 || salt1 != hsalt1 {
+			Tracef("%s: copy-shadow: break: salt mismatch", db.path)
 			break
 		}
 

litestream.go

@@ -313,6 +313,9 @@ func mkdirAll(path string, perm os.FileMode, uid, gid int) error {
 	return nil
 }
 
+// Tracef is used for low-level tracing.
+var Tracef = func(format string, a ...interface{}) {}
+
 func assert(condition bool, message string) {
 	if !condition {
 		panic("assertion failed: " + message)