Prevent file corruption when writing tar backup to stdout (#2344)

* Prevent file corruption when writing tar backup to stdout

FB-1794

Tar backups written to stdout were coming out corrupt. This turned
out to be due to log messages getting written to stdout and ending
up in the tar file. We now check to see if the tar file and the log
are both going to stdout, and if they are, send the logs to stderr
instead.

Testing did not have any kind of consistency or validity check. We
now compare a tar file sent to a file and a tar file sent to stdout
to make sure they're the same. This does not guarantee correctness
but does at least catch this form of corruption.

* trying different index name

Co-authored-by: tgruben <tgruben@gmail.com>
Co-authored-by: Todd Gruben <todd@molecula.com>

cmd/backup_tar.go

@@ -2,12 +2,13 @@
 package cmd
 
 import (
+	"io"
+
 	"github.com/molecula/featurebase/v3/ctl"
-	"github.com/molecula/featurebase/v3/logger"
 	"github.com/spf13/cobra"
 )
 
-func newBackupTarCommand(logdest logger.Logger) *cobra.Command {
+func newBackupTarCommand(logdest io.Writer) *cobra.Command {
 	cmd := ctl.NewBackupTarCommand(logdest)
 	ccmd := &cobra.Command{
 		Use:   "backuptar",

cmd/root.go

@@ -92,7 +92,7 @@ at https://docs.molecula.cloud/.
 	rc.AddCommand(newChkSumCommand(logdest))
 	rc.AddCommand(newBackupCommand(logdest))
 	rc.AddCommand(newRestoreCommand(logdest))
-	rc.AddCommand(newBackupTarCommand(logdest))
+	rc.AddCommand(newBackupTarCommand(stderr))
 	rc.AddCommand(newRestoreTarCommand(logdest))
 	rc.AddCommand(newConfigCommand(stderr))
 	rc.AddCommand(newExportCommand(logdest))

ctl/backup_tar.go

@@ -21,7 +21,6 @@ import (
 	"github.com/molecula/featurebase/v3/encoding/proto"
 	"github.com/molecula/featurebase/v3/logger"
 	"github.com/molecula/featurebase/v3/server"
-	"github.com/molecula/featurebase/v3/vprint"
 	"github.com/pkg/errors"
 )
 
@@ -52,7 +51,8 @@ type BackupTarCommand struct { // nolint: maligned
 	client *pilosa.InternalClient
 
 	// Standard input/output
-	logDest logger.Logger
+	logwriter io.Writer
+	logDest   logger.Logger
 
 	TLS server.TLSConfig
 
@@ -65,9 +65,10 @@ func (cmd *BackupTarCommand) Logger() logger.Logger {
 }
 
 // NewBackupTarCommand returns a new instance of BackupCommand.
-func NewBackupTarCommand(logdest logger.Logger) *BackupTarCommand {
+func NewBackupTarCommand(logwriter io.Writer) *BackupTarCommand {
 	return &BackupTarCommand{
-		logDest:       logdest,
+		logwriter:     logwriter,
+		logDest:       logger.NewStandardLogger(logwriter),
 		RetryPeriod:   time.Minute,
 		HeaderTimeout: time.Second * 3,
 		Pprof:         "localhost:0",
@@ -76,18 +77,24 @@ func NewBackupTarCommand(logdest logger.Logger) *BackupTarCommand {
 
 // Run executes the main program execution.
 func (cmd *BackupTarCommand) Run(ctx context.Context) (err error) {
-	logger := cmd.Logger()
-	close, err := startProfilingServer(cmd.Pprof, logger)
-	if err != nil {
-		return errors.Wrap(err, "starting profiling server")
-	}
-	defer close()
-
+	logdest := cmd.Logger()
 	// Validate arguments.
 	if cmd.OutputPath == "" {
 		return fmt.Errorf("%w: -o flag required", UsageError)
 	}
 	useStdout := cmd.OutputPath == "-"
+	if useStdout && cmd.logwriter == os.Stdout {
+		logdest = logger.NewStandardLogger(os.Stderr)
+	}
+
+	// This was the very first thing in the function, but since logging to stdout causes file corruption
+	// if the tarfile is also going to stdout, we need to check that before we can safely send anything
+	// to the logger.
+	close, err := startProfilingServer(cmd.Pprof, logdest)
+	if err != nil {
+		return errors.Wrap(err, "starting profiling server")
+	}
+	defer close()
 
 	if cmd.HeaderTimeoutStr != "" {
 		if dur, err := time.ParseDuration(cmd.HeaderTimeoutStr); err != nil {
@@ -137,6 +144,13 @@ func (cmd *BackupTarCommand) Run(ctx context.Context) (err error) {
 	var w io.Writer
 	if useStdout {
 		w = os.Stdout
+		// if writing tarfile to stdout, the logs can't also go there or the file ends up corrupt
+		// redirect to stderr and log a message there to avoid this
+		// commented out for testing
+		//if dest := logger.Logger(); dest.Writer() == os.Stdout {
+		//	dest.SetOutput(os.Stderr)
+		//	logger.Printf("redirected logs to stderr to avoid file corruption")
+		//}
 	} else {
 		f, err := os.Create(cmd.OutputPath + ".tmp")
 		if err != nil {
@@ -171,7 +185,7 @@ func (cmd *BackupTarCommand) Run(ctx context.Context) (err error) {
 
 	// Move data file to final location.
 	if !useStdout {
-		logger.Printf("writing backup: %s", cmd.OutputPath)
+		logdest.Printf("writing backup: %s", cmd.OutputPath)
 		if err := os.Rename(cmd.OutputPath+".tmp", cmd.OutputPath); err != nil {
 			return err
 		}
@@ -359,7 +373,7 @@ func (cmd *BackupTarCommand) backupTarShardDataframe(ctx context.Context, tw *ta
 	}
 
 	filename := filepath.Join("indexes", indexName, "dataframe", fmt.Sprintf("%04d", shard))
-	vprint.VV("wrting %v", filename)
+	logger.Printf("writing %v", filename)
 	var buf bytes.Buffer
 	if _, err := buf.ReadFrom(resp.Body); err != nil {
 		return fmt.Errorf("copying shard data to memory: %w", err)

ctl/backup_tar_test.go

@@ -1,14 +1,13 @@
 package ctl
 
 import (
+	"bytes"
 	"context"
-	"io"
-	"net/http"
+	"os"
 	"path/filepath"
-	"strings"
 	"testing"
 
-	"github.com/molecula/featurebase/v3/logger"
+	pilosa "github.com/molecula/featurebase/v3"
 	"github.com/molecula/featurebase/v3/test"
 )
 
@@ -16,27 +15,54 @@ func TestBackupTarCommand_Run(t *testing.T) {
 	cluster := test.MustRunCluster(t, 1)
 	defer cluster.Close()
 	cmd := cluster.GetNode(0)
+	indexName := "backuptar"
 
-	cmLog := logger.NewStandardLogger(io.Discard)
-	cm := NewBackupTarCommand(cmLog)
+	// this might produce some annoying spam in tests but we need to make sure log messages to
+	// stdout are being redirected properly when the tarfile is also going to stdout
+	cm := NewBackupTarCommand(os.Stdout)
 	hostport := cmd.API.Node().URI.HostPort()
 	cm.Host = hostport
 	dir := t.TempDir()
 	cm.OutputPath = filepath.Join(dir, "backuptest.tar")
 
-	resp, err := http.DefaultClient.Do(test.MustNewHTTPRequest("POST", "http://"+hostport+"/index/i", strings.NewReader("")))
+	_, err := cmd.API.CreateIndex(context.Background(), indexName, pilosa.IndexOptions{Keys: true, TrackExistence: true})
 	if err != nil {
-		t.Fatalf("making http request: %v", err)
+		t.Fatalf("creating test index: %v", err)
 	}
-	resp.Body.Close()
-	resp, err = http.DefaultClient.Do(test.MustNewHTTPRequest("POST", "http://"+hostport+"/index/i/field/f", strings.NewReader("")))
+	_, err = cmd.API.CreateField(context.Background(), indexName, "f", pilosa.OptFieldKeys())
 	if err != nil {
-		t.Fatalf("making http request: %v", err)
+		t.Fatalf("creating test field: %v", err)
 	}
-	resp.Body.Close()
 
-	cm.Index = "i"
+	cm.Index = indexName
 	if err := cm.Run(context.Background()); err != nil {
 		t.Fatalf("BackupTarCommand Run error: %s", err)
 	}
+
+	oldpath := cm.OutputPath
+	cm.OutputPath = "-"
+	cfpath := filepath.Join(dir, "stdouttest.tar") //capture file
+	cf, err := os.Create(cfpath)
+	if err != nil {
+		t.Fatalf("opening file to compare file and stdout outputs: %v", err)
+	}
+	defer cf.Close()
+	// I don't like this at all but it's all i'm really finding for capturing os.Stdout
+	old := os.Stdout
+	defer func() { os.Stdout = old }()
+	os.Stdout = cf
+	if err := cm.Run(context.Background()); err != nil {
+		t.Fatalf("BackupTarCommand Run error: %s", err)
+	}
+	fdata, err := os.ReadFile(oldpath)
+	if err != nil {
+		t.Fatalf("unable to read from direct-to-file backup: %v", err)
+	}
+	cdata, err := os.ReadFile(cfpath)
+	if err != nil {
+		t.Fatalf("unable to read from captured stdout backup: %v", err)
+	}
+	if !bytes.Equal(fdata, cdata) {
+		t.Fatalf("backing up to file and to stdout produced different results")
+	}
 }