feat(log): integrate @graphile/logger to allow log overrides (#109)

PizzaPartyInc · AxTrusov · web-flow · commit a83b0e63e98e · 2021-04-22T18:28:11.000+01:00
Co-authored-by: Sergey Trusov &lt;Trusov@axinom.com&gt;
diff --git a/__tests__/__snapshots__/settings.test.ts.snap b/__tests__/__snapshots__/settings.test.ts.snap
@@ -30,6 +30,11 @@ Object {
   "connectionString": "postgres://localhost:5432/dbname?ssl=true",
   "databaseName": "dbname",
   "databaseOwner": "dbname",
+  "logger": Logger {
+    "_logFactory": [Function],
+    "_scope": Object {},
+    "log": [Function],
+  },
   "manageGraphileMigrateSchema": true,
   "migrationsFolder": "./migrations",
   "placeholders": undefined,
@@ -66,6 +71,11 @@ Object {
   "connectionString": "postgres://localhost:5432/dbname?ssl=true",
   "databaseName": "dbname",
   "databaseOwner": "dbname",
+  "logger": Logger {
+    "_logFactory": [Function],
+    "_scope": Object {},
+    "log": [Function],
+  },
   "manageGraphileMigrateSchema": true,
   "migrationsFolder": "./migrations",
   "placeholders": undefined,
@@ -97,6 +107,11 @@ Object {
   "connectionString": "postgres://localhost:5432/dbname?ssl=true",
   "databaseName": "dbname",
   "databaseOwner": "dbname",
+  "logger": Logger {
+    "_logFactory": [Function],
+    "_scope": Object {},
+    "log": [Function],
+  },
   "manageGraphileMigrateSchema": true,
   "migrationsFolder": "./migrations",
   "placeholders": undefined,
@@ -136,6 +151,11 @@ Object {
   "connectionString": "postgres://localhost:5432/dbname?ssl=true",
   "databaseName": "dbname",
   "databaseOwner": "dbname",
+  "logger": Logger {
+    "_logFactory": [Function],
+    "_scope": Object {},
+    "log": [Function],
+  },
   "manageGraphileMigrateSchema": true,
   "migrationsFolder": "./migrations",
   "placeholders": undefined,
@@ -172,6 +192,11 @@ Object {
   "connectionString": "postgres://localhost:5432/dbname?ssl=true",
   "databaseName": "dbname",
   "databaseOwner": "dbname",
+  "logger": Logger {
+    "_logFactory": [Function],
+    "_scope": Object {},
+    "log": [Function],
+  },
   "manageGraphileMigrateSchema": true,
   "migrationsFolder": "./migrations",
   "placeholders": undefined,
diff --git a/__tests__/settings.test.ts b/__tests__/settings.test.ts
@@ -77,6 +77,23 @@ it("throws if shadow attempted but no shadow DB", async () => {
         `);
 });
 
+it.each([[[]], [{}], ["test"]])(
+  "throws error for invalid logger",
+  async invalidLogger => {
+    await expect(
+      parseSettings({
+        connectionString: exampleConnectionString,
+        rootConnectionString: "notthesamestring1",
+        shadowConnectionString: "notthesamestring2",
+        logger: invalidLogger as any,
+      }),
+    ).rejects.toMatchInlineSnapshot(`
+          [Error: Errors occurred during settings validation:
+          - Setting 'logger': Expected 'logger' to be a @graphile/logger Logger instance]
+        `);
+  },
+);
+
 describe("makeRootDatabaseConnectionString", () => {
   it("modifies the database name", async () => {
     const parsedSettings = await parseSettings({
diff --git a/package.json b/package.json
@@ -39,6 +39,7 @@
   },
   "homepage": "https://github.com/graphile/migrate#readme",
   "dependencies": {
+    "@graphile/logger": "^0.2.0",
     "@types/json5": "^0.0.30",
     "@types/node": "^14.6.0",
     "@types/pg": "^7.14.1",
diff --git a/src/actions.ts b/src/actions.ts
@@ -1,3 +1,4 @@
+import { Logger } from "@graphile/logger";
 import { exec as rawExec } from "child_process";
 import { promises as fsp } from "fs";
 import { parse } from "pg-connection-string";
@@ -115,18 +116,16 @@ export async function executeActions(
         maxBuffer: 50 * 1024 * 1024,
       });
       if (stdout) {
-        // eslint-disable-next-line no-console
-        console.log(stdout);
+        parsedSettings.logger.info(stdout);
       }
       if (stderr) {
-        // eslint-disable-next-line no-console
-        console.error(stderr);
+        parsedSettings.logger.error(stderr);
       }
     }
   }
 }
 
-export function makeValidateActionCallback(allowRoot = false) {
+export function makeValidateActionCallback(logger: Logger, allowRoot = false) {
   return async (inputValue: unknown): Promise<ActionSpec[]> => {
     const specs: ActionSpec[] = [];
     if (inputValue) {
@@ -141,8 +140,7 @@ export function makeValidateActionCallback(allowRoot = false) {
           !trueRawSpec["_"] &&
           typeof trueRawSpec["command"] === "string";
         if (isV003OrBelowCommand) {
-          // eslint-disable-next-line no-console
-          console.warn(
+          logger.warn(
             "DEPRECATED: graphile-migrate now requires command action specs to have an `_: 'command'` property; we'll back-fill this for now, but please update your configuration",
           );
         }
diff --git a/src/commands/commit.ts b/src/commands/commit.ts
@@ -100,8 +100,7 @@ export async function _commit(
   await fsp.writeFile(newMigrationFilepath, finalBody);
   await fsp.chmod(newMigrationFilepath, "440");
 
-  // eslint-disable-next-line no-console
-  console.log(
+  parsedSettings.logger.info(
     `graphile-migrate: New migration '${newMigrationFilename}' created`,
   );
   try {
@@ -113,13 +112,12 @@ export async function _commit(
       parsedSettings.blankMigrationContent.trim() + "\n",
     );
   } catch (e) {
-    logDbError(e);
-    // eslint-disable-next-line no-console
-    console.error("ABORTING...");
+    logDbError(parsedSettings, e);
+
+    parsedSettings.logger.error("ABORTING...");
     await writeCurrentMigration(parsedSettings, currentLocation, body);
     await fsp.unlink(newMigrationFilepath);
-    // eslint-disable-next-line no-console
-    console.error("ABORTED AND ROLLED BACK");
+    parsedSettings.logger.error("ABORTED AND ROLLED BACK");
     throw e;
   }
 }
diff --git a/src/commands/migrate.ts b/src/commands/migrate.ts
@@ -64,8 +64,7 @@ export async function _migrate(
             parsedSettings.afterAllMigrations,
           );
         }
-        // eslint-disable-next-line no-console
-        console.log(
+        parsedSettings.logger.info(
           `graphile-migrate${logSuffix}: ${
             remainingMigrations.length > 0
               ? `${remainingMigrations.length} committed migrations executed`
diff --git a/src/commands/reset.ts b/src/commands/reset.ts
@@ -37,8 +37,7 @@ export async function _reset(
       await pgClient.query(
         `DROP DATABASE IF EXISTS ${escapeIdentifier(databaseName)};`,
       );
-      // eslint-disable-next-line no-console
-      console.log(
+      parsedSettings.logger.info(
         `graphile-migrate${logSuffix}: dropped database '${databaseName}'`,
       );
       try {
@@ -55,8 +54,7 @@ export async function _reset(
       await pgClient.query(
         `REVOKE ALL ON DATABASE ${escapeIdentifier(databaseName)} FROM PUBLIC;`,
       );
-      // eslint-disable-next-line no-console
-      console.log(
+      parsedSettings.logger.info(
         `graphile-migrate${logSuffix}: recreated database '${databaseName}'`,
       );
     },
diff --git a/src/commands/uncommit.ts b/src/commands/uncommit.ts
@@ -51,8 +51,9 @@ export async function _uncommit(parsedSettings: ParsedSettings): Promise<void> {
   await fsp.unlink(lastMigrationFilepath);
   await undoMigration(parsedSettings, lastMigration);
 
-  // eslint-disable-next-line no-console
-  console.log(`graphile-migrate: migration '${lastMigrationFilepath}' undone`);
+  parsedSettings.logger.info(
+    `graphile-migrate: migration '${lastMigrationFilepath}' undone`,
+  );
 
   // Reset shadow
   await _reset(parsedSettings, true);
diff --git a/src/commands/watch.ts b/src/commands/watch.ts
@@ -32,8 +32,9 @@ export function _makeCurrentMigrationRunner(
     let migrationsAreEquivalent = false;
 
     try {
-      // eslint-disable-next-line no-console
-      console.log(`[${new Date().toISOString()}]: Running current.sql`);
+      parsedSettings.logger.info(
+        `[${new Date().toISOString()}]: Running current.sql`,
+      );
       const start = process.hrtime();
       const connectionString = shadow
         ? parsedSettings.shadowConnectionString
@@ -121,8 +122,7 @@ export function _makeCurrentMigrationRunner(
                 );
               }
             } else {
-              // eslint-disable-next-line no-console
-              console.log(
+              parsedSettings.logger.info(
                 `[${new Date().toISOString()}]: current.sql unchanged, skipping migration`,
               );
             }
@@ -154,16 +154,15 @@ export function _makeCurrentMigrationRunner(
       }
       const interval2 = process.hrtime(start);
       const duration2 = interval2[0] * 1e3 + interval2[1] * 1e-6;
-      // eslint-disable-next-line no-console
-      console.log(
+      parsedSettings.logger.info(
         `[${new Date().toISOString()}]: Finished (${duration2.toFixed(0)}ms${
           duration2 - duration >= 5
             ? `; excluding actions: ${duration.toFixed(0)}ms`
             : ""
         })`,
       );
     } catch (e) {
-      logDbError(e);
+      logDbError(parsedSettings, e);
       throw e;
     }
   }
@@ -199,10 +198,12 @@ export async function _watch(
       running = true;
 
       run()
-        .catch(e => {
-          if (!e["_gmlogged"]) {
-            // eslint-disable-next-line no-console
-            console.error(e);
+        .catch(error => {
+          if (!error["_gmlogged"]) {
+            parsedSettings.logger.error(
+              `Error occurred whilst processing migration: ${error.message}`,
+              { error },
+            );
           }
         })
         .finally(() => {
diff --git a/src/index.ts b/src/index.ts
@@ -1 +1,4 @@
 export * from "./commands";
+export { Settings } from "./settings";
+export { Logger, LogFunctionFactory, LogLevel } from "@graphile/logger";
+export { defaultLogger } from "./logger";
diff --git a/src/instrumentation.ts b/src/instrumentation.ts
@@ -2,6 +2,7 @@ import * as chalk from "chalk";
 
 import indent from "./indent";
 import { Client } from "./pg";
+import { ParsedSettings } from "./settings";
 
 export async function runQueryWithErrorInstrumentation(
   pgClient: Client,
@@ -58,32 +59,33 @@ export async function runQueryWithErrorInstrumentation(
   }
 }
 
-export const logDbError = (e: Error): void => {
+export const logDbError = ({ logger }: ParsedSettings, e: Error): void => {
   /* eslint-disable no-console */
   e["_gmlogged"] = true;
-  console.error("");
+  const messages = [""];
   if (e["_gmMessageOverride"]) {
-    console.error(e["_gmMessageOverride"]);
+    messages.push(e["_gmMessageOverride"]);
   } else {
-    console.error(
+    messages.push(
       chalk.red.bold(`🛑 Error occurred whilst processing migration`),
     );
   }
   const { severity, code, detail, hint } = e as any;
-  console.error(indent(e.stack ? e.stack : e.message, 4));
-  console.error("");
+  messages.push(indent(e.stack ? e.stack : e.message, 4));
+  messages.push("");
   if (severity) {
-    console.error(indent(`Severity:\t${severity}`, 4));
+    messages.push(indent(`Severity:\t${severity}`, 4));
   }
   if (code) {
-    console.error(indent(`Code:    \t${code}`, 4));
+    messages.push(indent(`Code:    \t${code}`, 4));
   }
   if (detail) {
-    console.error(indent(`Detail:  \t${detail}`, 4));
+    messages.push(indent(`Detail:  \t${detail}`, 4));
   }
   if (hint) {
-    console.error(indent(`Hint:    \t${hint}`, 4));
+    messages.push(indent(`Hint:    \t${hint}`, 4));
   }
-  console.error("");
+  messages.push("");
+  logger.error(messages.join("\n"), { error: e });
   /* eslint-enable */
 };
diff --git a/src/logger.ts b/src/logger.ts
@@ -0,0 +1,10 @@
+import { Logger, makeConsoleLogFactory } from "@graphile/logger";
+
+export const defaultLogger = new Logger(
+  makeConsoleLogFactory({
+    format: `%s`,
+    formatParameters(_level, message) {
+      return [message];
+    },
+  }),
+);
diff --git a/src/migration.ts b/src/migration.ts
@@ -472,8 +472,7 @@ export async function runCommittedMigration(
       `Hash for ${realFilename} does not match - ${newHash} !== ${hash}; has the file been tampered with?`,
     );
   }
-  // eslint-disable-next-line no-console
-  console.log(
+  parsedSettings.logger.info(
     `graphile-migrate${logSuffix}: Running migration '${realFilename}'`,
   );
   await runStringMigration(
diff --git a/src/pgReal.ts b/src/pgReal.ts
@@ -37,6 +37,7 @@ export function clearAllPools(): void {
 }
 
 function getPoolDetailsFromConnectionString(
+  { logger }: ParsedSettings,
   connectionString: string,
 ): PoolDetails {
   let details:
@@ -48,9 +49,10 @@ function getPoolDetailsFromConnectionString(
       throw new Error("Connection string does not specify a database");
     }
     const pool = new Pool({ connectionString });
-    pool.on("error", (err: Error) => {
-      // eslint-disable-next-line no-console
-      console.error("An error occurred in the PgPool", err);
+    pool.on("error", (error: Error) => {
+      logger.error(`An error occurred in the PgPool: ${error.message}`, {
+        error,
+      });
       process.exit(1);
     });
 
@@ -98,7 +100,10 @@ export async function withClient<T = void>(
   parsedSettings: ParsedSettings,
   callback: (pgClient: PoolClient, context: Context) => Promise<T>,
 ): Promise<T> {
-  const details = getPoolDetailsFromConnectionString(connectionString);
+  const details = getPoolDetailsFromConnectionString(
+    parsedSettings,
+    connectionString,
+  );
   const { pool: pgPool, database } = details;
   try {
     const pgClient = await pgPool.connect();
diff --git a/src/settings.ts b/src/settings.ts
diff --git a/yarn.lock b/yarn.lock

Original file line number	Diff line number	Diff line change
`@@ -1,3 +1,4 @@`
	`1`	`+import { Logger } from "@graphile/logger";`
`1`	`2`	`import { exec as rawExec } from "child_process";`
`2`	`3`	`import { promises as fsp } from "fs";`
`3`	`4`	`import { parse } from "pg-connection-string";`
`@@ -115,18 +116,16 @@ export async function executeActions(`
`115`	`116`	`maxBuffer: 50 * 1024 * 1024,`
`116`	`117`	`});`
`117`	`118`	`if (stdout) {`
`118`		`- // eslint-disable-next-line no-console`
`119`		`- console.log(stdout);`
	`119`	`+ parsedSettings.logger.info(stdout);`
`120`	`120`	`}`
`121`	`121`	`if (stderr) {`
`122`		`- // eslint-disable-next-line no-console`
`123`		`- console.error(stderr);`
	`122`	`+ parsedSettings.logger.error(stderr);`
`124`	`123`	`}`
`125`	`124`	`}`
`126`	`125`	`}`
`127`	`126`	`}`
`128`	`127`
`129`		`-export function makeValidateActionCallback(allowRoot = false) {`
	`128`	`+export function makeValidateActionCallback(logger: Logger, allowRoot = false) {`
`130`	`129`	`return async (inputValue: unknown): Promise<ActionSpec[]> => {`
`131`	`130`	`const specs: ActionSpec[] = [];`
`132`	`131`	`if (inputValue) {`
`@@ -141,8 +140,7 @@ export function makeValidateActionCallback(allowRoot = false) {`
`141`	`140`	`!trueRawSpec["_"] &&`
`142`	`141`	`typeof trueRawSpec["command"] === "string";`
`143`	`142`	`if (isV003OrBelowCommand) {`
`144`		`- // eslint-disable-next-line no-console`
`145`		`- console.warn(`
	`143`	`+ logger.warn(`
`146`	`144`	"DEPRECATED: graphile-migrate now requires command action specs to have an `_: 'command'` property; we'll back-fill this for now, but please update your configuration",
`147`	`145`	`);`
`148`	`146`	`}`