Skip to content

Commit 0acb636

Browse files
kvchkvch
authored
Add verbose logging (#804)
This PR adds a new flag called `--verbose`. If you set it, `pgroll` will be more verbose. It logs the following events with contextual info to stdout: * starting migration * starting operation * starting backfilling * completing operation * completing migration * completing backfilling * creating versioned schema * dropping versioned schema ### Example outputs #### Create multiple tables table ```sh 2025-04-29 12:12:32 INFO starting migration ├ name: 01_create_tables └ operation_count: 3 2025-04-29 12:12:32 INFO starting operation ├ operation: create_table ├ name: customers ├ columns: [id name credit_card] ├ comment: <nil> └ constraints: [] 2025-04-29 12:12:32 INFO starting operation ├ operation: create_table ├ name: bills ├ columns: [id date quantity] ├ comment: <nil> └ constraints: [] 2025-04-29 12:12:32 INFO starting operation ├ operation: create_table ├ name: sellers ├ columns: [name zip description] ├ comment: <nil> └ constraints: [] 2025-04-29 12:12:32 INFO created versioned schema for migration ├ migration: 01_create_tables └ schema_name: public_01_create_tables 2025-04-29 12:12:32 INFO completing migration ├ migration: 01_create_tables └ operation_count: 3 2025-04-29 12:12:32 INFO completing operation ├ operation: create_table ├ name: customers ├ columns: [id name credit_card] ├ comment: <nil> └ constraints: [] 2025-04-29 12:12:32 INFO completing operation ├ operation: create_table ├ name: bills ├ columns: [id date quantity] ├ comment: <nil> └ constraints: [] 2025-04-29 12:12:32 INFO completing operation ├ operation: create_table ├ name: sellers ├ columns: [name zip description] ├ comment: <nil> └ constraints: [] 2025-04-29 12:12:32 INFO completed migration ├ migration: 01_create_tables └ operation_count: 3 SUCCESS New version of the schema available under the postgres "public_01_create_tables" schema ``` #### Add foreign key constraint ```sh 2025-04-29 12:12:34 INFO starting migration ├ name: 47_add_table_foreign_key_constraint └ operation_count: 1 2025-04-29 12:12:34 INFO starting operation ├ operation: create_constraint ├ table: tickets └ name: fk_sellers 2025-04-29 12:12:35 INFO created versioned schema for migration ├ migration: 47_add_table_foreign_key_constraint └ schema_name: public_47_add_table_foreign_key_constraint 2025-04-29 12:12:35 INFO backfilling started table: tickets 2025-04-29 12:12:35 INFO backfilling completed table: tickets 2025-04-29 12:12:35 INFO completing migration ├ migration: 47_add_table_foreign_key_constraint └ operation_count: 1 2025-04-29 12:12:35 INFO completing operation ├ operation: create_constraint ├ table: tickets └ name: fk_sellers 2025-04-29 12:12:35 INFO completing operation ├ operation: alter_column ├ table: tickets ├ column: └ references: fk_sellers 2025-04-29 12:12:35 INFO completed migration ├ migration: 47_add_table_foreign_key_constraint └ operation_count: 1 SUCCESS New version of the schema available under the postgres "public_47_add_table_foreign_key_constraint" schema ``` #### Rollback ``` $ go run . rollback 54_create_index_with_opclass --verbose 2025-04-29 12:13:15 INFO rolling back migration ├ migration: 54_create_index_with_opclass └ operation_count: 1 2025-04-29 12:13:15 INFO dropped versioned schema for migration ├ migration: 54_create_index_with_opclass └ schema_name: public_54_create_index_with_opclass 2025-04-29 12:13:15 INFO rolling back operation ├ operation: create_index ├ name: idx_fruits_custom_opclass ├ table: fruits └ index_type: 2025-04-29 12:13:15 INFO rolled back migration ├ migration: 54_create_index_with_opclass └ operation_count: 1 SUCCESS Migration rolled back. Changes made since the last version have been reverted ``` Closes #784
1 parent b74a551 commit 0acb636

30 files changed

+492
-82
lines changed

‎cli-definition.json

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -192,6 +192,11 @@
192192
"name": "schema",
193193
"description": "Postgres schema to use for the migration",
194194
"default": "public"
195+
},
196+
{
197+
"name": "verbose",
198+
"description": "Enable verbose logging",
199+
"default": "false"
195200
}
196201
]
197202
}

‎cmd/flags/flags.go

Lines changed: 2 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -27,3 +27,5 @@ func SkipValidation() bool { return viper.GetBool("SKIP_VALIDATION") }
2727
func Role() string {
2828
return viper.GetString("ROLE")
2929
}
30+
31+
func Verbose() bool { return viper.GetBool("VERBOSE") }

‎cmd/root.go

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ func NewRoll(ctx context.Context) (*roll.Roll, error) {
2323
lockTimeout := flags.LockTimeout()
2424
role := flags.Role()
2525
skipValidation := flags.SkipValidation()
26+
verbose := flags.Verbose()
2627

2728
state, err := state.New(ctx, pgURL, stateSchema)
2829
if err != nil {
@@ -33,6 +34,7 @@ func NewRoll(ctx context.Context) (*roll.Roll, error) {
3334
roll.WithLockTimeoutMs(lockTimeout),
3435
roll.WithRole(role),
3536
roll.WithSkipValidation(skipValidation),
37+
roll.WithLogging(verbose),
3638
)
3739
}
3840

@@ -52,12 +54,14 @@ func Prepare() *cobra.Command {
5254
rootCmd.PersistentFlags().String("pgroll-schema", "pgroll", "Postgres schema to use for pgroll internal state")
5355
rootCmd.PersistentFlags().Int("lock-timeout", 500, "Postgres lock timeout in milliseconds for pgroll DDL operations")
5456
rootCmd.PersistentFlags().String("role", "", "Optional postgres role to set when executing migrations")
57+
rootCmd.PersistentFlags().Bool("verbose", false, "Enable verbose logging")
5558

5659
viper.BindPFlag("PG_URL", rootCmd.PersistentFlags().Lookup("postgres-url"))
5760
viper.BindPFlag("SCHEMA", rootCmd.PersistentFlags().Lookup("schema"))
5861
viper.BindPFlag("STATE_SCHEMA", rootCmd.PersistentFlags().Lookup("pgroll-schema"))
5962
viper.BindPFlag("LOCK_TIMEOUT", rootCmd.PersistentFlags().Lookup("lock-timeout"))
6063
viper.BindPFlag("ROLE", rootCmd.PersistentFlags().Lookup("role"))
64+
viper.BindPFlag("VERBOSE", rootCmd.PersistentFlags().Lookup("verbose"))
6165

6266
// register subcommands
6367
rootCmd.AddCommand(startCmd())

‎pkg/migrations/migrations.go

Lines changed: 6 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import (
77
"fmt"
88

99
_ "github.com/lib/pq"
10+
"github.com/pterm/pterm"
1011

1112
"github.com/xataio/pgroll/pkg/db"
1213
"github.com/xataio/pgroll/pkg/schema"
@@ -18,16 +19,16 @@ type Operation interface {
1819
// version in the database (through a view)
1920
// update the given views to expose the new schema version
2021
// Returns the table that requires backfilling, if any.
21-
Start(ctx context.Context, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error)
22+
Start(ctx context.Context, logger pterm.Logger, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error)
2223

2324
// Complete will update the database schema to match the current version
2425
// after calling Start.
2526
// This method should be called once the previous version is no longer used.
26-
Complete(ctx context.Context, conn db.DB, s *schema.Schema) error
27+
Complete(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error
2728

2829
// Rollback will revert the changes made by Start. It is not possible to
2930
// rollback a completed migration.
30-
Rollback(ctx context.Context, conn db.DB, s *schema.Schema) error
31+
Rollback(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error
3132

3233
// Validate returns a descriptive error if the operation cannot be applied to the given schema.
3334
Validate(ctx context.Context, s *schema.Schema) error
@@ -82,11 +83,12 @@ func (m *Migration) Validate(ctx context.Context, s *schema.Schema) error {
8283
// made by the migration. No changes are made to the physical database.
8384
func (m *Migration) UpdateVirtualSchema(ctx context.Context, s *schema.Schema) error {
8485
db := &db.FakeDB{}
86+
logger := pterm.Logger{Level: pterm.LogLevelDisabled}
8587

8688
// Run `Start` on each operation using the fake DB. Updates will be made to
8789
// the in-memory schema `s` without touching the physical database.
8890
for _, op := range m.Operations {
89-
if _, err := op.Start(ctx, db, "", s); err != nil {
91+
if _, err := op.Start(ctx, logger, db, "", s); err != nil {
9092
return err
9193
}
9294
}

‎pkg/migrations/op_add_column.go

Lines changed: 21 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@ import (
99
"strings"
1010

1111
"github.com/lib/pq"
12+
"github.com/pterm/pterm"
1213

1314
"github.com/xataio/pgroll/internal/defaults"
1415
"github.com/xataio/pgroll/pkg/backfill"
@@ -18,7 +19,9 @@ import (
1819

1920
var _ Operation = (*OpAddColumn)(nil)
2021

21-
func (o *OpAddColumn) Start(ctx context.Context, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
22+
func (o *OpAddColumn) Start(ctx context.Context, logger pterm.Logger, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
23+
logger.Info("starting operation", logger.Args(o.loggerArgs()...))
24+
2225
table := s.GetTable(o.Table)
2326
if table == nil {
2427
return nil, TableDoesNotExistError{Name: o.Table}
@@ -120,7 +123,9 @@ func toSchemaColumn(c Column) *schema.Column {
120123
return tmpColumn
121124
}
122125

123-
func (o *OpAddColumn) Complete(ctx context.Context, conn db.DB, s *schema.Schema) error {
126+
func (o *OpAddColumn) Complete(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
127+
logger.Info("completing operation", logger.Args(o.loggerArgs()...))
128+
124129
err := NewRenameColumnAction(conn, o.Table, TemporaryName(o.Column.Name), o.Column.Name).Execute(ctx)
125130
if err != nil {
126131
return err
@@ -189,7 +194,9 @@ func (o *OpAddColumn) Complete(ctx context.Context, conn db.DB, s *schema.Schema
189194
return nil
190195
}
191196

192-
func (o *OpAddColumn) Rollback(ctx context.Context, conn db.DB, s *schema.Schema) error {
197+
func (o *OpAddColumn) Rollback(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
198+
logger.Info("rolling back operation", logger.Args(o.loggerArgs()...))
199+
193200
table := s.GetTable(o.Table)
194201
if table == nil {
195202
return TableDoesNotExistError{Name: o.Table}
@@ -393,6 +400,17 @@ func IsNotNullConstraintName(name string) bool {
393400
return strings.HasPrefix(name, "_pgroll_check_not_null_")
394401
}
395402

403+
func (o *OpAddColumn) loggerArgs() []any {
404+
return []any{
405+
"operation", OpNameAddColumn,
406+
"name", o.Column.Name,
407+
"type", o.Column.Type,
408+
"table", o.Table,
409+
"nullable", o.Column.Nullable,
410+
"unique", o.Column.Unique,
411+
}
412+
}
413+
396414
// ColumnSQLWriter writes a column to SQL
397415
// It can optionally include the primary key constraint
398416
// When creating a table, the primary key constraint is not added to the column definition

‎pkg/migrations/op_alter_column.go

Lines changed: 19 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import (
77
"fmt"
88

99
"github.com/lib/pq"
10+
"github.com/pterm/pterm"
1011

1112
"github.com/xataio/pgroll/pkg/backfill"
1213
"github.com/xataio/pgroll/pkg/db"
@@ -15,7 +16,9 @@ import (
1516

1617
var _ Operation = (*OpAlterColumn)(nil)
1718

18-
func (o *OpAlterColumn) Start(ctx context.Context, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
19+
func (o *OpAlterColumn) Start(ctx context.Context, logger pterm.Logger, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
20+
logger.Info("starting operation", logger.Args(o.loggerArgs()...))
21+
1922
table := s.GetTable(o.Table)
2023
if table == nil {
2124
return nil, TableDoesNotExistError{Name: o.Table}
@@ -78,20 +81,21 @@ func (o *OpAlterColumn) Start(ctx context.Context, conn db.DB, latestSchema stri
7881

7982
// perform any operation specific start steps
8083
for _, op := range ops {
81-
if _, err := op.Start(ctx, conn, latestSchema, s); err != nil {
84+
if _, err := op.Start(ctx, logger, conn, latestSchema, s); err != nil {
8285
return nil, err
8386
}
8487
}
8588

8689
return table, nil
8790
}
8891

89-
func (o *OpAlterColumn) Complete(ctx context.Context, conn db.DB, s *schema.Schema) error {
92+
func (o *OpAlterColumn) Complete(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
93+
logger.Info("completing operation", logger.Args(o.loggerArgs()...))
9094
ops := o.subOperations()
9195

9296
// Perform any operation specific completion steps
9397
for _, op := range ops {
94-
if err := op.Complete(ctx, conn, s); err != nil {
98+
if err := op.Complete(ctx, logger, conn, s); err != nil {
9599
return err
96100
}
97101
}
@@ -134,7 +138,8 @@ func (o *OpAlterColumn) Complete(ctx context.Context, conn db.DB, s *schema.Sche
134138
return nil
135139
}
136140

137-
func (o *OpAlterColumn) Rollback(ctx context.Context, conn db.DB, s *schema.Schema) error {
141+
func (o *OpAlterColumn) Rollback(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
142+
logger.Info("rolling back operation", logger.Args(o.loggerArgs()...))
138143
table := s.GetTable(o.Table)
139144
if table == nil {
140145
return TableDoesNotExistError{Name: o.Table}
@@ -147,7 +152,7 @@ func (o *OpAlterColumn) Rollback(ctx context.Context, conn db.DB, s *schema.Sche
147152
// Perform any operation specific rollback steps
148153
ops := o.subOperations()
149154
for _, ops := range ops {
150-
if err := ops.Rollback(ctx, conn, nil); err != nil {
155+
if err := ops.Rollback(ctx, logger, conn, nil); err != nil {
151156
return err
152157
}
153158
}
@@ -341,3 +346,11 @@ func (o *OpAlterColumn) upSQLForOperations(ops []Operation) string {
341346

342347
return ""
343348
}
349+
350+
func (o *OpAlterColumn) loggerArgs() []any {
351+
return []any{
352+
"operation", OpNameAlterColumn,
353+
"column", o.Column,
354+
"table", o.Table,
355+
}
356+
}

‎pkg/migrations/op_change_type.go

Lines changed: 19 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,6 +5,7 @@ package migrations
55
import (
66
"context"
77

8+
"github.com/pterm/pterm"
89
"github.com/xataio/pgroll/pkg/db"
910
"github.com/xataio/pgroll/pkg/schema"
1011
)
@@ -19,7 +20,9 @@ type OpChangeType struct {
1920

2021
var _ Operation = (*OpChangeType)(nil)
2122

22-
func (o *OpChangeType) Start(ctx context.Context, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
23+
func (o *OpChangeType) Start(ctx context.Context, logger pterm.Logger, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
24+
logger.Info("starting operation", logger.Args(o.loggerArgs()...))
25+
2326
table := s.GetTable(o.Table)
2427
if table == nil {
2528
return nil, TableDoesNotExistError{Name: o.Table}
@@ -28,11 +31,15 @@ func (o *OpChangeType) Start(ctx context.Context, conn db.DB, latestSchema strin
2831
return table, nil
2932
}
3033

31-
func (o *OpChangeType) Complete(ctx context.Context, conn db.DB, s *schema.Schema) error {
34+
func (o *OpChangeType) Complete(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
35+
logger.Info("completing operation", logger.Args(o.loggerArgs()...))
36+
3237
return nil
3338
}
3439

35-
func (o *OpChangeType) Rollback(ctx context.Context, conn db.DB, s *schema.Schema) error {
40+
func (o *OpChangeType) Rollback(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
41+
logger.Info("rolling back operation", logger.Args(o.loggerArgs()...))
42+
3643
return nil
3744
}
3845

@@ -46,3 +53,12 @@ func (o *OpChangeType) Validate(ctx context.Context, s *schema.Schema) error {
4653
}
4754
return nil
4855
}
56+
57+
func (o *OpChangeType) loggerArgs() []any {
58+
return []any{
59+
"operation", OpNameAlterColumn,
60+
"column", o.Column,
61+
"table", o.Table,
62+
"type", o.Type,
63+
}
64+
}

‎pkg/migrations/op_create_constraint.go

Lines changed: 21 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -7,6 +7,7 @@ import (
77
"fmt"
88

99
"github.com/lib/pq"
10+
"github.com/pterm/pterm"
1011

1112
"github.com/xataio/pgroll/pkg/backfill"
1213
"github.com/xataio/pgroll/pkg/db"
@@ -15,7 +16,9 @@ import (
1516

1617
var _ Operation = (*OpCreateConstraint)(nil)
1718

18-
func (o *OpCreateConstraint) Start(ctx context.Context, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
19+
func (o *OpCreateConstraint) Start(ctx context.Context, logger pterm.Logger, conn db.DB, latestSchema string, s *schema.Schema) (*schema.Table, error) {
20+
logger.Info("starting operation", logger.Args(o.loggerArgs()...))
21+
1922
table := s.GetTable(o.Table)
2023
if table == nil {
2124
return nil, TableDoesNotExistError{Name: o.Table}
@@ -96,14 +99,16 @@ func (o *OpCreateConstraint) Start(ctx context.Context, conn db.DB, latestSchema
9699
return table, nil
97100
}
98101

99-
func (o *OpCreateConstraint) Complete(ctx context.Context, conn db.DB, s *schema.Schema) error {
102+
func (o *OpCreateConstraint) Complete(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
103+
logger.Info("completing operation", logger.Args(o.loggerArgs()...))
104+
100105
switch o.Type {
101106
case OpCreateConstraintTypeUnique:
102107
uniqueOp := &OpSetUnique{
103108
Table: o.Table,
104109
Name: o.Name,
105110
}
106-
err := uniqueOp.Complete(ctx, conn, s)
111+
err := uniqueOp.Complete(ctx, logger, conn, s)
107112
if err != nil {
108113
return err
109114
}
@@ -114,7 +119,7 @@ func (o *OpCreateConstraint) Complete(ctx context.Context, conn db.DB, s *schema
114119
Name: o.Name,
115120
},
116121
}
117-
err := checkOp.Complete(ctx, conn, s)
122+
err := checkOp.Complete(ctx, logger, conn, s)
118123
if err != nil {
119124
return err
120125
}
@@ -125,7 +130,7 @@ func (o *OpCreateConstraint) Complete(ctx context.Context, conn db.DB, s *schema
125130
Name: o.Name,
126131
},
127132
}
128-
err := fkOp.Complete(ctx, conn, s)
133+
err := fkOp.Complete(ctx, logger, conn, s)
129134
if err != nil {
130135
return err
131136
}
@@ -176,7 +181,9 @@ func (o *OpCreateConstraint) Complete(ctx context.Context, conn db.DB, s *schema
176181
return err
177182
}
178183

179-
func (o *OpCreateConstraint) Rollback(ctx context.Context, conn db.DB, s *schema.Schema) error {
184+
func (o *OpCreateConstraint) Rollback(ctx context.Context, logger pterm.Logger, conn db.DB, s *schema.Schema) error {
185+
logger.Info("starting operation", logger.Args(o.loggerArgs()...))
186+
180187
table := s.GetTable(o.Table)
181188
if table == nil {
182189
return TableDoesNotExistError{Name: o.Table}
@@ -198,6 +205,14 @@ func (o *OpCreateConstraint) Rollback(ctx context.Context, conn db.DB, s *schema
198205
return err
199206
}
200207

208+
func (o *OpCreateConstraint) loggerArgs() []any {
209+
return []any{
210+
"operation", OpCreateConstraintName,
211+
"table", o.Table,
212+
"name", o.Name,
213+
}
214+
}
215+
201216
func (o *OpCreateConstraint) removeTriggers(ctx context.Context, conn db.DB) error {
202217
dropFuncs := make([]string, 0, len(o.Columns)*2)
203218
for _, column := range o.Columns {

0 commit comments

Comments
 (0)