Merge branch 'wc-praefect-migrat-print' into 'master'

migrate: Print execution time of migrations

See merge request gitlab-org/gitaly!4308

3 files changed, 142 insertions, 9 deletions

diff --git a/cmd/praefect/subcmd.go b/cmd/praefect/subcmd.go
index 8f2858e3e..3a4148244 100644
--- a/cmd/praefect/subcmd.go
+++ b/cmd/praefect/subcmd.go
@@ -33,7 +33,7 @@ const (
 
 var subcommands = map[string]subcmd{
 	sqlPingCmdName:                &sqlPingSubcommand{},
-	sqlMigrateCmdName:             &sqlMigrateSubcommand{},
+	sqlMigrateCmdName:             newSQLMigrateSubCommand(os.Stdout),
 	dialNodesCmdName:              newDialNodesSubcommand(os.Stdout),
 	sqlMigrateDownCmdName:         &sqlMigrateDownSubcommand{},
 	sqlMigrateStatusCmdName:       &sqlMigrateStatusSubcommand{},
diff --git a/cmd/praefect/subcmd_sql_migrate.go b/cmd/praefect/subcmd_sql_migrate.go
index 3bb4f9b11..1d4ee3420 100644
--- a/cmd/praefect/subcmd_sql_migrate.go
+++ b/cmd/praefect/subcmd_sql_migrate.go
@@ -3,24 +3,38 @@ package main
 import (
 	"flag"
 	"fmt"
+	"io"
+	"time"
 
+	migrate "github.com/rubenv/sql-migrate"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/praefect/config"
 	"gitlab.com/gitlab-org/gitaly/v14/internal/praefect/datastore/glsql"
+	"gitlab.com/gitlab-org/gitaly/v14/internal/praefect/datastore/migrations"
 )
 
-const sqlMigrateCmdName = "sql-migrate"
+const (
+	sqlMigrateCmdName = "sql-migrate"
+	timeFmt           = "2006-01-02T15:04:05"
+)
 
 type sqlMigrateSubcommand struct {
+	w             io.Writer
 	ignoreUnknown bool
+	verbose       bool
+}
+
+func newSQLMigrateSubCommand(writer io.Writer) *sqlMigrateSubcommand {
+	return &sqlMigrateSubcommand{w: writer}
 }
 
-func (s *sqlMigrateSubcommand) FlagSet() *flag.FlagSet {
+func (cmd *sqlMigrateSubcommand) FlagSet() *flag.FlagSet {
 	flags := flag.NewFlagSet(sqlMigrateCmdName, flag.ExitOnError)
-	flags.BoolVar(&s.ignoreUnknown, "ignore-unknown", true, "ignore unknown migrations (default is true)")
+	flags.BoolVar(&cmd.ignoreUnknown, "ignore-unknown", true, "ignore unknown migrations (default is true)")
+	flags.BoolVar(&cmd.verbose, "verbose", false, "show text of migration query (default is false)")
 	return flags
 }
 
-func (s *sqlMigrateSubcommand) Exec(flags *flag.FlagSet, conf config.Config) error {
+func (cmd *sqlMigrateSubcommand) Exec(flags *flag.FlagSet, conf config.Config) error {
 	const subCmd = progname + " " + sqlMigrateCmdName
 
 	db, clean, err := openDB(conf.DB)
@@ -29,11 +43,52 @@ func (s *sqlMigrateSubcommand) Exec(flags *flag.FlagSet, conf config.Config) err
 	}
 	defer clean()
 
-	n, err := glsql.Migrate(db, s.ignoreUnknown)
-	if err != nil {
-		return fmt.Errorf("%s: fail: %v", subCmd, err)
+	migrationSet := migrate.MigrationSet{
+		IgnoreUnknown: cmd.ignoreUnknown,
+		TableName:     migrations.MigrationTableName,
+	}
+
+	planSource := &migrate.MemoryMigrationSource{
+		Migrations: migrations.All(),
+	}
+
+	// Find all migrations that are currently down.
+	planMigrations, _, _ := migrationSet.PlanMigration(db, "postgres", planSource, migrate.Up, 0)
+
+	if len(planMigrations) == 0 {
+		fmt.Fprintf(cmd.w, "%s: all migrations are up\n", subCmd)
+		return nil
+	}
+	fmt.Fprintf(cmd.w, "%s: migrations to apply: %d\n\n", subCmd, len(planMigrations))
+
+	executed := 0
+	for _, mig := range planMigrations {
+		fmt.Fprintf(cmd.w, "=  %s %v: migrating\n", time.Now().Format(timeFmt), mig.Id)
+		start := time.Now()
+
+		if cmd.verbose {
+			fmt.Fprintf(cmd.w, "\t%v\n", mig.Up)
+		}
+
+		n, err := glsql.MigrateSome(mig.Migration, db, cmd.ignoreUnknown)
+		if err != nil {
+			return fmt.Errorf("%s: fail: %v", time.Now().Format(timeFmt), err)
+		}
+
+		if n > 0 {
+			fmt.Fprintf(cmd.w, "== %s %v: applied (%s)\n", time.Now().Format(timeFmt), mig.Id, time.Since(start))
+
+			// Additional migrations were run. No harm, but prevents us from tracking their execution duration.
+			if n > 1 {
+				fmt.Fprintf(cmd.w, "warning: %v additional migrations were applied successfully\n", n-1)
+			}
+		} else {
+			fmt.Fprintf(cmd.w, "== %s %v: skipped (%s)\n", time.Now().Format(timeFmt), mig.Id, time.Since(start))
+		}
+
+		executed += n
 	}
 
-	fmt.Printf("%s: OK (applied %d migrations)\n", subCmd, n)
+	fmt.Fprintf(cmd.w, "\n%s: OK (applied %d migrations)\n", subCmd, executed)
 	return nil
 }
diff --git a/cmd/praefect/subcmd_sql_migrate_test.go b/cmd/praefect/subcmd_sql_migrate_test.go
new file mode 100644
index 000000000..d7381b82f
--- /dev/null
+++ b/cmd/praefect/subcmd_sql_migrate_test.go
@@ -0,0 +1,78 @@
+package main
+
+import (
+	"bytes"
+	"flag"
+	"fmt"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+	"gitlab.com/gitlab-org/gitaly/v14/internal/praefect/config"
+	"gitlab.com/gitlab-org/gitaly/v14/internal/praefect/datastore/migrations"
+	"gitlab.com/gitlab-org/gitaly/v14/internal/testhelper/testdb"
+)
+
+func TestSubCmdSqlMigrate(t *testing.T) {
+	db := testdb.New(t)
+	dbCfg := testdb.GetConfig(t, db.Name)
+	cfg := config.Config{DB: dbCfg}
+
+	migrationCt := len(migrations.All())
+
+	for _, tc := range []struct {
+		desc           string
+		up             int
+		verbose        bool
+		expectedOutput []string
+	}{
+		{
+			desc:           "All migrations up",
+			up:             migrationCt,
+			expectedOutput: []string{"praefect sql-migrate: all migrations are up"},
+		},
+		{
+			desc: "All migrations down",
+			up:   0,
+			expectedOutput: []string{
+				fmt.Sprintf("praefect sql-migrate: migrations to apply: %d", migrationCt),
+				"20200109161404_hello_world: migrating",
+				"20200109161404_hello_world: applied (",
+				fmt.Sprintf("praefect sql-migrate: OK (applied %d migrations)", migrationCt),
+			},
+		},
+		{
+			desc: "Some migrations down",
+			up:   10,
+			expectedOutput: []string{
+				fmt.Sprintf("praefect sql-migrate: migrations to apply: %d", migrationCt-10),
+				"20201126165633_repository_assignments_table: migrating",
+				"20201126165633_repository_assignments_table: applied (",
+				fmt.Sprintf("praefect sql-migrate: OK (applied %d migrations)", migrationCt-10),
+			},
+		},
+		{
+			desc:    "Verbose output",
+			up:      0,
+			verbose: true,
+			expectedOutput: []string{
+				fmt.Sprintf("praefect sql-migrate: migrations to apply: %d", migrationCt),
+				"20200109161404_hello_world: migrating",
+				"[CREATE TABLE hello_world (id integer)]",
+				"20200109161404_hello_world: applied (",
+				fmt.Sprintf("praefect sql-migrate: OK (applied %d migrations)", migrationCt),
+			},
+		},
+	} {
+		t.Run(tc.desc, func(t *testing.T) {
+			testdb.SetMigrations(t, db, cfg, tc.up)
+
+			var stdout bytes.Buffer
+			migrateCmd := sqlMigrateSubcommand{w: &stdout, ignoreUnknown: true, verbose: tc.verbose}
+			assert.NoError(t, migrateCmd.Exec(flag.NewFlagSet("", flag.PanicOnError), cfg))
+
+			for _, out := range tc.expectedOutput {
+				assert.Contains(t, stdout.String(), out)
+			}
+		})
+	}
+}