From a8996a149d71affea7e356d79b1dbd4ba68cee53 Mon Sep 17 00:00:00 2001 From: Lory Cloutier <118481783+lorycloutier@users.noreply.github.com> Date: Tue, 13 Dec 2022 13:03:16 -0600 Subject: [PATCH] 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 Co-authored-by: Todd Gruben --- cmd/backup_tar.go | 5 ++-- cmd/root.go | 2 +- ctl/backup_tar.go | 40 +++++++++++++++++++++----------- ctl/backup_tar_test.go | 52 +++++++++++++++++++++++++++++++----------- 4 files changed, 70 insertions(+), 29 deletions(-) diff --git a/cmd/backup_tar.go b/cmd/backup_tar.go index b1309b293..5d19b4ba3 100644 --- a/cmd/backup_tar.go +++ b/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", diff --git a/cmd/root.go b/cmd/root.go index 10611c038..6453cc511 100644 --- a/cmd/root.go +++ b/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)) diff --git a/ctl/backup_tar.go b/ctl/backup_tar.go index d89fcb665..b94062850 100644 --- a/ctl/backup_tar.go +++ b/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) diff --git a/ctl/backup_tar_test.go b/ctl/backup_tar_test.go index 80f1cfbf8..356e8c13b 100644 --- a/ctl/backup_tar_test.go +++ b/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") + } }