feat: add optional logging in Provider with verbose option (#668)

provider.go

@@ -62,6 +62,7 @@ func NewProvider(dialect Dialect, db *sql.DB, fsys fs.FS, opts ...ProviderOption
 		registered:      make(map[int64]*Migration),
 		excludePaths:    make(map[string]bool),
 		excludeVersions: make(map[int64]bool),
+		logger:          &stdLogger{},
 	}
 	for _, opt := range opts {
 		if err := opt.apply(&cfg); err != nil {
@@ -152,7 +153,7 @@ func (p *Provider) Status(ctx context.Context) ([]*MigrationStatus, error) {
 // which migrations were applied. For example, if migrations were applied out of order (1,4,2,3),
 // this method returns 4. If no migrations have been applied, it returns 0.
 func (p *Provider) GetDBVersion(ctx context.Context) (int64, error) {
-	return p.getDBMaxVersion(ctx)
+	return p.getDBMaxVersion(ctx, nil)
 }
 
 // ListSources returns a list of all migration sources known to the provider, sorted in ascending
@@ -369,6 +370,7 @@ func (p *Provider) down(
 	}
 	// We never migrate the zero version down.
 	if dbMigrations[0].Version == 0 {
+		p.printf("no migrations to run, current version: 0")
 		return nil, nil
 	}
 	var apply []*Migration
@@ -413,15 +415,15 @@ func (p *Provider) apply(
 	//  1. direction is up
 	//    a. migration is applied, this is an error (ErrAlreadyApplied)
 	//    b. migration is not applied, apply it
+	if direction && result != nil {
+		return nil, fmt.Errorf("version %d: %w", version, ErrAlreadyApplied)
+	}
 	//  2. direction is down
 	//    a. migration is applied, rollback
 	//    b. migration is not applied, this is an error (ErrNotApplied)
-	if result == nil && !direction {
+	if !direction && result == nil {
 		return nil, fmt.Errorf("version %d: %w", version, ErrNotApplied)
 	}
-	if result != nil && direction {
-		return nil, fmt.Errorf("version %d: %w", version, ErrAlreadyApplied)
-	}
 	d := sqlparser.DirectionDown
 	if direction {
 		d = sqlparser.DirectionUp
@@ -462,15 +464,23 @@ func (p *Provider) status(ctx context.Context) (_ []*MigrationStatus, retErr err
 	return status, nil
 }
 
-func (p *Provider) getDBMaxVersion(ctx context.Context) (_ int64, retErr error) {
-	conn, cleanup, err := p.initialize(ctx)
-	if err != nil {
-		return 0, fmt.Errorf("failed to initialize: %w", err)
+// getDBMaxVersion returns the highest version recorded in the database, regardless of the order in
+// which migrations were applied. conn may be nil, in which case a connection is initialized.
+//
+// optimize(mf): we should only fetch the max version from the database, no need to fetch all
+// migrations only to get the max version. This means expanding the Store interface.
+func (p *Provider) getDBMaxVersion(ctx context.Context, conn *sql.Conn) (_ int64, retErr error) {
+	if conn == nil {
+		var cleanup func() error
+		var err error
+		conn, cleanup, err = p.initialize(ctx)
+		if err != nil {
+			return 0, err
+		}
+		defer func() {
+			retErr = multierr.Append(retErr, cleanup())
+		}()
 	}
-	defer func() {
-		retErr = multierr.Append(retErr, cleanup())
-	}()
-
 	res, err := p.store.ListMigrations(ctx, conn)
 	if err != nil {
 		return 0, err

provider_options.go

@@ -184,6 +184,11 @@ type config struct {
 	disableVersioning     bool
 	allowMissing          bool
 	disableGlobalRegistry bool
+
+	// Let's not expose the Logger just yet. Ideally we consolidate on the std lib slog package
+	// added in go1.21 and then expose that (if that's even necessary). For now, just use the std
+	// lib log package.
+	logger Logger
 }
 
 type configFunc func(*config) error

provider_run.go

@@ -121,6 +121,17 @@ func (p *Provider) prepareMigration(fsys fs.FS, m *Migration, direction bool) er
 	return fmt.Errorf("invalid migration type: %+v", m)
 }
 
+// printf is a helper function that prints the given message if verbose is enabled. It also prepends
+// the "goose: " prefix to the message.
+func (p *Provider) printf(msg string, args ...interface{}) {
+	if p.cfg.verbose {
+		if !strings.HasPrefix(msg, "goose:") {
+			msg = "goose: " + msg
+		}
+		p.cfg.logger.Printf(msg, args...)
+	}
+}
+
 // runMigrations runs migrations sequentially in the given direction. If the migrations list is
 // empty, return nil without error.
 func (p *Provider) runMigrations(
@@ -131,6 +142,15 @@ func (p *Provider) runMigrations(
 	byOne bool,
 ) ([]*MigrationResult, error) {
 	if len(migrations) == 0 {
+		if !p.cfg.disableVersioning {
+			// No need to print this message if versioning is disabled because there are no
+			// migrations being tracked in the goose version table.
+			maxVersion, err := p.getDBMaxVersion(ctx, conn)
+			if err != nil {
+				return nil, err
+			}
+			p.printf("no migrations to run, current version: %d", maxVersion)
+		}
 		return nil, nil
 	}
 	apply := migrations
@@ -162,7 +182,7 @@ func (p *Provider) runMigrations(
 
 	var results []*MigrationResult
 	for _, m := range apply {
-		current := &MigrationResult{
+		result := &MigrationResult{
 			Source: &Source{
 				Type:    m.Type,
 				Path:    m.Source,
@@ -175,18 +195,25 @@ func (p *Provider) runMigrations(
 		if err := p.runIndividually(ctx, conn, m, direction.ToBool()); err != nil {
 			// TODO(mf): we should also return the pending migrations here, the remaining items in
 			// the apply slice.
-			current.Error = err
-			current.Duration = time.Since(start)
+			result.Error = err
+			result.Duration = time.Since(start)
 			return nil, &PartialError{
 				Applied: results,
-				Failed:  current,
+				Failed:  result,
 				Err:     err,
 			}
 		}
-		current.Duration = time.Since(start)
-		results = append(results, current)
+		result.Duration = time.Since(start)
+		results = append(results, result)
+		p.printf("%s", result)
+	}
+	if !p.cfg.disableVersioning && !byOne {
+		maxVersion, err := p.getDBMaxVersion(ctx, conn)
+		if err != nil {
+			return nil, err
+		}
+		p.printf("successfully migrated database, current version: %d", maxVersion)
 	}
-
 	return results, nil
 }
 

provider_types.go

@@ -36,12 +36,31 @@ type MigrationResult struct {
 	Error error
 }
 
+// String returns a string representation of the migration result.
+//
+// Example down:
+//
+//	EMPTY down 00006_posts_view-copy.sql (607.83µs)
+//	OK    down 00005_posts_view.sql (646.25µs)
+//
+// Example up:
+//
+//	OK    up 00005_posts_view.sql (727.5µs)
+//	EMPTY up 00006_posts_view-copy.sql (378.33µs)
 func (m *MigrationResult) String() string {
-	state := "OK"
+	var format string
+	if m.Direction == "up" {
+		format = "%-5s %-2s %s (%s)"
+	} else {
+		format = "%-5s %-4s %s (%s)"
+	}
+	var state string
 	if m.Empty {
 		state = "EMPTY"
+	} else {
+		state = "OK"
 	}
-	return fmt.Sprintf("%-6s %-4s %s (%s)",
+	return fmt.Sprintf(format,
 		state,
 		m.Direction,
 		filepath.Base(m.Source.Path),