Add prettyLogger to migrator (#412)

* Add prettyLogger to migrator

Add exported prettyLogger object which converts log objects to strings
and outputs them to console. Update incorrect default logger value.

* Handle invalid input

* Narrow MESSAGE_FORMATS type

* Move constants outside of log function

* Move prettyLogger to static property of SlonikMigrator

* Add tests for prettyLogger

* Add event name to up and down events

Author: samuliasmala

packages/demo/migrate.js

@@ -5,7 +5,7 @@ const migrator = new SlonikMigrator({
   slonik,
   migrationTableName: 'demo_migration',
   migrationsPath: __dirname + '/migrations',
-  logger: console,
+  logger: SlonikMigrator.prettyLogger,
 })
 
 migrator.runAsCLI()

packages/migrator/readme.md

@@ -56,6 +56,7 @@ const migrator = new SlonikMigrator({
   migrationsPath: __dirname + '/migrations',
   migrationTableName: 'migration',
   slonik,
+  logger: SlonikMigrator.prettyLogger,
 })
 
 migrator.runAsCLI()
@@ -364,8 +365,10 @@ parameters for the `SlonikMigrator` constructor
 | `slonik` | slonik database pool instance, created by `createPool`. | N/A |
 | `migrationsPath` | path pointing to directory on filesystem where migration files will live. | N/A |
 | `migrationTableName` | the name for the table migrations information will be stored in. You can change this to avoid a clash with existing tables, or to conform with your team's naming standards. Set to an array to change the schema e.g. `['public', 'dbmigrations']` | N/A |
-| `logger` | how information about the migrations will be logged. You can set to `undefined` to prevent logs appearing at all. | `console` |
+| `logger` | how information about the migrations will be logged. You can set to `console` to log raw objects to console, `undefined` to prevent logs appearing at all, use `SlonikMigrator.prettyLogger` or supply a custom logger. | `undefined` |
+
+`SlonikMigrator.prettyLogger` logs all messages to console. Known events are prettified to strings, unknown events or unexpected message properties in known events are logged as objects.
 
 ## Implementation
 
-Under the hood, the library thinly wraps [umzug](https://npmjs.com/package/umzug) with a custom slonik-based stoage implementation.
+Under the hood, the library thinly wraps [umzug](https://npmjs.com/package/umzug) with a custom slonik-based storage implementation.

packages/migrator/src/index.ts

@@ -56,6 +56,17 @@ export class SlonikMigrator extends umzug.Umzug<SlonikMigratorContext> {
     }
   }
 
+  /**
+   * Logs messages to console. Known events are prettified to strings, unknown
+   * events or unexpected message properties in known events are logged as objects.
+   */
+  static prettyLogger: NonNullable<SlonikMigratorOptions['logger']> = {
+    info: message => prettifyAndLog('info', message),
+    warn: message => prettifyAndLog('warn', message),
+    error: message => prettifyAndLog('error', message),
+    debug: message => prettifyAndLog('debug', message),
+  }
+
   getCli(options?: umzug.CommandLineParserOptions) {
     const cli = super.getCli({toolDescription: `@slonik/migrator - PostgreSQL migration tool`, ...options})
     cli.addAction(new RepairAction(this))
@@ -403,3 +414,53 @@ class RepairAction extends CommandLineAction {
 export interface RepairOptions {
   dryRun?: boolean
 }
+
+type LogMessage = Record<string, unknown>
+
+const createMessageFormats = <T extends Record<string, (msg: LogMessage) => [string, LogMessage]>>(formats: T) =>
+  formats
+
+const MESSAGE_FORMATS = createMessageFormats({
+  created: msg => {
+    const {event, path, ...rest} = msg
+    return [`created   ${path}`, rest]
+  },
+  migrating: msg => {
+    const {event, name, ...rest} = msg
+    return [`migrating ${name}`, rest]
+  },
+  migrated: msg => {
+    const {event, name, durationSeconds, ...rest} = msg
+    return [`migrated  ${name} in ${durationSeconds} s`, rest]
+  },
+  reverting: msg => {
+    const {event, name, ...rest} = msg
+    return [`reverting ${name}`, rest]
+  },
+  reverted: msg => {
+    const {event, name, durationSeconds, ...rest} = msg
+    return [`reverted  ${name} in ${durationSeconds} s`, rest]
+  },
+  up: msg => {
+    const {event, message, ...rest} = msg
+    return [`up migration completed, ${message}`, rest]
+  },
+  down: msg => {
+    const {event, message, ...rest} = msg
+    return [`down migration completed, ${message}`, rest]
+  },
+})
+
+function isProperEvent(event: unknown): event is keyof typeof MESSAGE_FORMATS {
+  return typeof event === 'string' && event in MESSAGE_FORMATS
+}
+
+function prettifyAndLog(level: keyof typeof SlonikMigrator.prettyLogger, message: LogMessage) {
+  const {event} = message || {}
+  if (!isProperEvent(event)) return console[level](message)
+
+  const [messageStr, rest] = MESSAGE_FORMATS[event](message)
+  console[level](messageStr)
+
+  if (Object.keys(rest).length > 0) console[level](rest)
+}

packages/migrator/test/pretty-logger.test.ts

@@ -0,0 +1,68 @@
+import {SlonikMigrator} from '../src'
+
+const {prettyLogger} = SlonikMigrator
+
+describe('prettyLogger', () => {
+  const originalInfo = console.info
+  const originalDebug = console.debug
+  const originalWarn = console.warn
+  const originalError = console.error
+
+  beforeEach(() => {
+    console.info = jest.fn()
+    console.debug = jest.fn()
+    console.warn = jest.fn()
+    console.error = jest.fn()
+  })
+
+  afterEach(() => {
+    console.info = originalInfo
+    console.debug = originalDebug
+    console.warn = originalWarn
+    console.error = originalError
+  })
+
+  test('known events', () => {
+    prettyLogger.info({event: 'created', path: './db/migrations/2022.08.25T12.51.47.test.sql'})
+    prettyLogger.info({event: 'migrating', name: '2022.08.25T12.51.47.test.sql'})
+    prettyLogger.debug({event: 'migrated', name: '2022.08.25T12.51.47.test.sql', durationSeconds: 0.024})
+    prettyLogger.debug({event: 'up', message: 'applied 1 migrations.'})
+    prettyLogger.warn({event: 'reverting', name: '2022.08.25T12.51.47.test.sql'})
+    prettyLogger.warn({event: 'reverted', name: '2022.08.25T12.51.47.test.sql', durationSeconds: 0.026})
+    prettyLogger.error({event: 'down', message: 'reverted 1 migrations.'})
+
+    expect((console.info as jest.Mock).mock.calls[0][0]).toBe('created   ./db/migrations/2022.08.25T12.51.47.test.sql')
+    expect((console.info as jest.Mock).mock.calls[1][0]).toBe('migrating 2022.08.25T12.51.47.test.sql')
+    expect((console.debug as jest.Mock).mock.calls[0][0]).toBe('migrated  2022.08.25T12.51.47.test.sql in 0.024 s')
+    expect((console.debug as jest.Mock).mock.calls[1][0]).toBe('up migration completed, applied 1 migrations.')
+    expect((console.warn as jest.Mock).mock.calls[0][0]).toBe('reverting 2022.08.25T12.51.47.test.sql')
+    expect((console.warn as jest.Mock).mock.calls[1][0]).toBe('reverted  2022.08.25T12.51.47.test.sql in 0.026 s')
+    expect((console.error as jest.Mock).mock.calls[0][0]).toBe('down migration completed, reverted 1 migrations.')
+  })
+
+  test('known events with additional parameters', () => {
+    prettyLogger.info({event: 'up', message: 'applied 1 migrations.', totalMigrations: 10})
+
+    expect((console.info as jest.Mock).mock.calls[0][0]).toBe('up migration completed, applied 1 migrations.')
+    expect((console.info as jest.Mock).mock.calls[1][0]).toEqual({totalMigrations: 10})
+  })
+
+  test('unknown events', () => {
+    prettyLogger.info({event: 'finished', message: 'process finished.', durationSeconds: 0.1})
+
+    expect((console.info as jest.Mock).mock.calls[0][0]).toEqual({
+      event: 'finished',
+      message: 'process finished.',
+      durationSeconds: 0.1,
+    })
+  })
+
+  test('invalid parameters', () => {
+    prettyLogger.info(null as any)
+    prettyLogger.info(undefined as any)
+    prettyLogger.info(0 as any)
+    prettyLogger.info('1' as any)
+
+    expect((console.info as jest.Mock).mock.calls).toEqual([[null], [undefined], [0], ['1']])
+  })
+})