Repository: amacneil/dbmate
Pull request #138 (2020-05-28 17:55:33)

adding verbose output for statement execution
Adding a verbose command line flag to allow users to print the result of each statement execution. Should not disrupt the existing flow for users as it's completely optional. Summary of changes:
- new `verbose` flag
- new field for `db` to print result of migrations
- new interface methods for drivers to pass verbose flag
- capture and print of result for every `exec` based on verbose flag across db and drivers

vperiyasamy: changed name from `--verbose` because urfave cli was panicking at redefining the flag `v`. new flag is now called `print-result`
vperiyasamy: @amacneil - not sure how to assign reviewers
amacneil: Hey, sorry for the delay on this, it has been a busy few days.

Some quick thoughts/feedback:
* I think it would make more sense for the flag to exist on the command, rather than globally (it's a `urfave/cli` thing). So this would make the argument `dbmate up --verbose` rather than `dbmate --verbose up`. I assume that might also fix your problem with overloading the `-v` shorthand.
* Any thoughts on how to test this?
* What does the output look like? Is it worth formatting that `result` struct to make it prettier?

Otherwise looks good, thanks for the contribution!
vperiyasamy: thanks for the comments, no worries. I think I've addressed these concerns with the new commit:
- moved flag to subcommands for `up`, `migrate`, and `rollback` - you were right, I am able to use verbose now
- I added a test in `db_test.go` which captures the stdout and makes sure it reports the `Rows affected` value
- output is a formatted string I've created, you can see it in `utils.go`
- originally in this PR I had added verbose statements to all of the driver execution results, but after testing I found out that these have no effect because there is no `InsertId` or `RowsAffected` for those commands, so have removed those 👍 
vperiyasamy: @amacneil bump
vperiyasamy: @amacneil sorry for the pestering, but any chance you would be able to look at this soon? we feel that without this logging we are missing a crucial sanity check when running our db migrations at scale
amacneil: Cool, this looks good. Sorry I have been busy lately and not much time for OSS. I added you as a contributor, so if you're happy with it and it's passing CI feel free to merge!
vperiyasamy: @amacneil thank you! no worries, I appreciate it.

Patch:
diff --git a/go.mod b/go.mod
index 0bfe1e6..d9493c6 100644
--- a/go.mod
+++ b/go.mod
@@ -7,6 +7,7 @@ require (
 	github.com/davecgh/go-spew v1.1.1 // indirect
 	github.com/go-sql-driver/mysql v1.5.0
 	github.com/joho/godotenv v1.3.0
+	github.com/kami-zh/go-capturer v0.0.0-20171211120116-e492ea43421d
 	github.com/kr/pretty v0.1.0 // indirect
 	github.com/lib/pq v1.5.2
 	github.com/mattn/go-sqlite3 v1.13.0
diff --git a/go.sum b/go.sum
index f654df9..9719e7f 100644
--- a/go.sum
+++ b/go.sum
@@ -9,6 +9,8 @@ github.com/go-sql-driver/mysql v1.5.0 h1:ozyZYNQW3x3HtqT1jira07DN2PArx2v7/mN66gG
 github.com/go-sql-driver/mysql v1.5.0/go.mod h1:DCzpHaOWr8IXmIStZouvnhqoel9Qv2LBy8hT2VhHyBg=
 github.com/joho/godotenv v1.3.0 h1:Zjp+RcGpHhGlrMbJzXTrZZPrWj+1vfm90La1wgB6Bhc=
 github.com/joho/godotenv v1.3.0/go.mod h1:7hK45KPybAkOC6peb+G5yklZfMxEjkZhHbwpqxOKXbg=
+github.com/kami-zh/go-capturer v0.0.0-20171211120116-e492ea43421d h1:cVtBfNW5XTHiKQe7jDaDBSh/EVM4XLPutLAGboIXuM0=
+github.com/kami-zh/go-capturer v0.0.0-20171211120116-e492ea43421d/go.mod h1:P2viExyCEfeWGU259JnaQ34Inuec4R38JCyBx2edgD0=
 github.com/kr/pretty v0.1.0 h1:L/CwN0zerZDmRFUapSPitk6f+Q3+0za1rQkzVuMiMFI=
 github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORNo=
 github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ=
diff --git a/main.go b/main.go
index 04a4e76..8452277 100644
--- a/main.go
+++ b/main.go
@@ -75,7 +75,14 @@ func NewApp() *cli.App {
 		{
 			Name:  "up",
 			Usage: "Create database (if necessary) and migrate to the latest version",
+			Flags: []cli.Flag{
+				cli.BoolFlag{
+					Name:  "verbose, v",
+					Usage: "print the result of each statement execution",
+				},
+			},
 			Action: action(func(db *dbmate.DB, c *cli.Context) error {
+				db.Verbose = c.Bool("verbose")
 				return db.CreateAndMigrate()
 			}),
 		},
@@ -96,7 +103,14 @@ func NewApp() *cli.App {
 		{
 			Name:  "migrate",
 			Usage: "Migrate to the latest version",
+			Flags: []cli.Flag{
+				cli.BoolFlag{
+					Name:  "verbose, v",
+					Usage: "print the result of each statement execution",
+				},
+			},
 			Action: action(func(db *dbmate.DB, c *cli.Context) error {
+				db.Verbose = c.Bool("verbose")
 				return db.Migrate()
 			}),
 		},
@@ -104,7 +118,14 @@ func NewApp() *cli.App {
 			Name:    "rollback",
 			Aliases: []string{"down"},
 			Usage:   "Rollback the most recent migration",
+			Flags: []cli.Flag{
+				cli.BoolFlag{
+					Name:  "verbose, v",
+					Usage: "print the result of each statement execution",
+				},
+			},
 			Action: action(func(db *dbmate.DB, c *cli.Context) error {
+				db.Verbose = c.Bool("verbose")
 				return db.Rollback()
 			}),
 		},
diff --git a/pkg/dbmate/db.go b/pkg/dbmate/db.go
index e899cc0..8c9342b 100644
--- a/pkg/dbmate/db.go
+++ b/pkg/dbmate/db.go
@@ -30,6 +30,7 @@ type DB struct {
 	DatabaseURL    *url.URL
 	MigrationsDir  string
 	SchemaFile     string
+	Verbose        bool
 	WaitBefore     bool
 	WaitInterval   time.Duration
 	WaitTimeout    time.Duration
@@ -304,8 +305,11 @@ func (db *DB) Migrate() error {
 
 		execMigration := func(tx Transaction) error {
 			// run actual migration
-			if _, err := tx.Exec(up.Contents); err != nil {
+			result, err := tx.Exec(up.Contents)
+			if err != nil {
 				return err
+			} else if db.Verbose {
+				printVerbose(result)
 			}
 
 			// record migration
@@ -425,8 +429,11 @@ func (db *DB) Rollback() error {
 
 	execMigration := func(tx Transaction) error {
 		// rollback migration
-		if _, err := tx.Exec(down.Contents); err != nil {
+		result, err := tx.Exec(down.Contents)
+		if err != nil {
 			return err
+		} else if db.Verbose {
+			printVerbose(result)
 		}
 
 		// remove migration record
diff --git a/pkg/dbmate/utils.go b/pkg/dbmate/utils.go
index 07352f3..aa2a6e6 100644
--- a/pkg/dbmate/utils.go
+++ b/pkg/dbmate/utils.go
@@ -127,3 +127,14 @@ func queryColumn(db *sql.DB, query string) ([]string, error) {
 
 	return result, nil
 }
+
+func printVerbose(result sql.Result) {
+	lastInsertId, err := result.LastInsertId()
+	if err == nil {
+		fmt.Printf("Last insert ID: %d\n", lastInsertId)
+	}
+	rowsAffected, err := result.RowsAffected()
+	if err == nil {
+		fmt.Printf("Rows affected: %d\n", rowsAffected)
+	}
+}


Test patch:
diff --git a/pkg/dbmate/db_test.go b/pkg/dbmate/db_test.go
index 4b5ebc0..5eeec24 100644
--- a/pkg/dbmate/db_test.go
+++ b/pkg/dbmate/db_test.go
@@ -8,6 +8,7 @@ import (
 	"testing"
 	"time"
 
+	"github.com/kami-zh/go-capturer"
 	"github.com/stretchr/testify/require"
 )
 
@@ -161,9 +162,10 @@ func checkWaitCalled(t *testing.T, u *url.URL, command func() error) {
 	u.Host = oldHost
 }
 
-func TestWaitBefore(t *testing.T) {
+func testWaitBefore(t *testing.T, verbose bool) {
 	u := postgresTestURL(t)
 	db := newTestDB(t, u)
+	db.Verbose = verbose
 	db.WaitBefore = true
 	// so that checkWaitCalled returns quickly
 	db.WaitInterval = time.Millisecond
@@ -200,6 +202,24 @@ func TestWaitBefore(t *testing.T) {
 	checkWaitCalled(t, u, db.DumpSchema)
 }
 
+func TestWaitBefore(t *testing.T) {
+	testWaitBefore(t, false)
+}
+
+func TestWaitBeforeVerbose(t *testing.T) {
+	output := capturer.CaptureOutput(func() {
+		testWaitBefore(t, true)
+	})
+	require.Contains(t, output,
+		`Applying: 20151129054053_test_migration.sql
+Rows affected: 1
+Applying: 20200227231541_test_posts.sql
+Rows affected: 0`)
+	require.Contains(t, output,
+		`Rolling back: 20200227231541_test_posts.sql
+Rows affected: 0`)
+}
+
 func testURLs(t *testing.T) []*url.URL {
 	return []*url.URL{
 		postgresTestURL(t),