feat: Normalize logging

outline · tommoor · Sep 15, 2021 · Sep 14, 2021 · Sep 14, 2021 · Sep 14, 2021
commit c25ff7dd3e79a6420cb9d9e801d4d504eff41e3d
diff --git a/flow-typed/globals.js b/flow-typed/globals.js
@@ -9,6 +9,8 @@ declare var process: {
   env: {
     [string]: string,
   },
+  stdout: Stream,
+  stderr: Stream,
 };
 
 declare var EDITOR_VERSION: string;
diff --git a/package.json b/package.json
@@ -10,7 +10,7 @@
     "build:webpack": "webpack --config webpack.config.prod.js",
     "build": "yarn clean && yarn build:webpack && yarn build:i18n && yarn build:server",
     "start": "node ./build/server/index.js",
-    "dev": "yarn concurrently --kill-others -n server,multiplayer \"node --inspect=0.0.0.0 build/server/index.js --services=websockets,admin,web,worker\" \"node build/server/index.js --services=collaboration --port=4000\"",
+    "dev": "yarn concurrently --kill-others -n api,collaboration  -c \"blue,magenta\" \"node --inspect=0.0.0.0 build/server/index.js --services=websockets,admin,web,worker\" \"node build/server/index.js --services=collaboration --port=4000\"",
     "dev:watch": "nodemon --exec \"yarn build:server && yarn build:i18n && yarn dev\" -e js --ignore build/ --ignore app/ --ignore flow-typed/",
     "lint": "eslint app server shared",
     "deploy": "git push heroku master",
@@ -73,7 +73,6 @@
     "datadog-metrics": "^0.9.3",
     "date-fns": "2.22.1",
     "dd-trace": "^0.32.2",
-    "debug": "^4.1.1",
     "dotenv": "^4.0.0",
     "emoji-regex": "^6.5.1",
     "es6-error": "^4.1.1",
@@ -175,6 +174,7 @@
     "utf8": "^3.0.0",
     "uuid": "^8.3.2",
     "validator": "5.2.0",
+    "winston": "^3.3.3",
     "y-indexeddb": "^9.0.6",
     "y-prosemirror": "^1.0.9",
     "yjs": "^13.5.12"

diff --git a/server/collaboration/logger.js b/server/collaboration/logger.js
@@ -1,22 +1,19 @@
 // @flow
-import debug from "debug";
-
-const log = debug("server");
-
-export default class Logger {
+import Logger from "../utils/logger";
+export default class CollaborationLogger {
   async onCreateDocument(data: { documentName: string }) {
-    log(`Created document "${data.documentName}"`);
+    Logger.info("collaboration", `Created document "${data.documentName}"`);
   }
 
   async onConnect(data: { documentName: string }) {
-    log(`New connection to "${data.documentName}"`);
+    Logger.info("collaboration", `New connection to "${data.documentName}"`);
   }
 
   async onDisconnect(data: { documentName: string }) {
-    log(`Connection to "${data.documentName}" closed`);
+    Logger.info("collaboration", `Connection to "${data.documentName}" closed`);
   }
 
   async onUpgrade() {
-    log("Upgrading connection");
+    Logger.info("collaboration", "Upgrading connection");
   }
 }
diff --git a/server/collaboration/persistence.js b/server/collaboration/persistence.js
@@ -1,12 +1,11 @@
 // @flow
-import debug from "debug";
 import { debounce } from "lodash";
 import * as Y from "yjs";
 import documentUpdater from "../commands/documentUpdater";
 import { Document, User } from "../models";
+import Logger from "../utils/logger";
 import markdownToYDoc from "./utils/markdownToYDoc";
 
-const log = debug("server");
 const DELAY = 3000;
 
 export default class Persistence {
@@ -30,12 +29,18 @@ export default class Persistence {
 
     if (document.state) {
       const ydoc = new Y.Doc();
-      log(`Document ${documentId} is already in state`);
+      Logger.info(
+        "collaboration",
+        `Document ${documentId} is in database state`
+      );
       Y.applyUpdate(ydoc, document.state);
       return ydoc;
     }
 
-    log(`Document ${documentId} is not in state, creating state from markdown`);
+    Logger.info(
+      "collaboration",
+      `Document ${documentId} is not in state, creating from markdown`
+    );
     const ydoc = markdownToYDoc(document.text, fieldName);
     const state = Y.encodeStateAsUpdate(ydoc);
 
@@ -55,7 +60,7 @@ export default class Persistence {
     }) => {
       const [, documentId] = documentName.split(".");
 
-      log(`persisting ${documentId}`);
+      Logger.info("collaboration", `Persisting ${documentId}`);
 
       await documentUpdater({
         documentId,

diff --git a/server/commands/collectionImporter.js b/server/commands/collectionImporter.js
@@ -2,20 +2,18 @@
 import fs from "fs";
 import os from "os";
 import path from "path";
-import debug from "debug";
 import File from "formidable/lib/file";
 import invariant from "invariant";
 import { values, keys } from "lodash";
 import { v4 as uuidv4 } from "uuid";
 import { parseOutlineExport } from "../../shared/utils/zip";
 import { FileImportError } from "../errors";
 import { Attachment, Event, Document, Collection, User } from "../models";
+import Logger from "../utils/logger";
 import attachmentCreator from "./attachmentCreator";
 import documentCreator from "./documentCreator";
 import documentImporter from "./documentImporter";
 
-const log = debug("commands");
-
 export default async function collectionImporter({
   file,
   type,
@@ -155,7 +153,7 @@ export default async function collectionImporter({
       continue;
     }
 
-    log(`Skipped importing ${item.path}`);
+    Logger.info("commands", `Skipped importing ${item.path}`);
   }
 
   // All collections, documents, and attachments have been created – time to

diff --git a/server/commands/documentPermanentDeleter.js b/server/commands/documentPermanentDeleter.js
@@ -1,11 +1,9 @@
 // @flow
-import debug from "debug";
 import { Document, Attachment } from "../models";
 import { sequelize } from "../sequelize";
+import Logger from "../utils/logger";
 import parseAttachmentIds from "../utils/parseAttachmentIds";
 
-const log = debug("commands");
-
 export async function documentPermanentDeleter(documents: Document[]) {
   const activeDocument = documents.find((doc) => !doc.deletedAt);
 
@@ -47,9 +45,9 @@ export async function documentPermanentDeleter(documents: Document[]) {
         if (attachment) {
           await attachment.destroy();
 
-          log(`Attachment ${attachmentId} deleted`);
+          Logger.info("commands", `Attachment ${attachmentId} deleted`);
         } else {
-          log(`Unknown attachment ${attachmentId} ignored`);
+          Logger.info("commands", `Unknown attachment ${attachmentId} ignored`);
         }
       }
     }

diff --git a/server/commands/teamCreator.js b/server/commands/teamCreator.js
@@ -1,12 +1,10 @@
 // @flow
-import debug from "debug";
 import { MaximumTeamsError } from "../errors";
 import { Team, AuthenticationProvider } from "../models";
 import { sequelize } from "../sequelize";
 import { getAllowedDomains } from "../utils/authentication";
 import { generateAvatarUrl } from "../utils/avatars";
-
-const log = debug("server");
+import Logger from "../utils/logger";
 
 type TeamCreatorResult = {|
   team: Team,
@@ -111,7 +109,10 @@ export default async function teamCreator({
   try {
     await team.provisionSubdomain(subdomain);
   } catch (err) {
-    log(`Provisioning subdomain failed: ${err.message}`);
+    Logger.error("Provisioning subdomain failed", err, {
+      teamId: team.id,
+      subdomain,
+    });
   }
 
   return {

diff --git a/server/index.js b/server/index.js
@@ -3,7 +3,6 @@ import env from "./env"; // eslint-disable-line import/order
 import "./tracing"; // must come before importing any instrumented module
 
 import http from "http";
-import debug from "debug";
 import Koa from "koa";
 import compress from "koa-compress";
 import helmet from "koa-helmet";
@@ -15,6 +14,7 @@ import stoppable from "stoppable";
 import throng from "throng";
 import services from "./services";
 import { getArg } from "./utils/args";
+import Logger from "./utils/logger";
 import { requestErrorHandler } from "./utils/sentry";
 import { checkEnv, checkMigrations } from "./utils/startup";
 import { checkUpdates } from "./utils/updates";
@@ -55,12 +55,12 @@ async function start(id: string, disconnect: () => void) {
 
   const app = new Koa();
   const server = stoppable(http.createServer(app.callback()));
-  const httpLogger = debug("http");
-  const log = debug("server");
   const router = new Router();
 
   // install basic middleware shared by all services
-  app.use(logger((str, args) => httpLogger(str)));
+  if ((env.DEBUG || "").includes("http")) {
+    app.use(logger((str, args) => Logger.info("http", str)));
+  }
   app.use(compress());
   app.use(helmet());
 
@@ -87,7 +87,7 @@ async function start(id: string, disconnect: () => void) {
       throw new Error(`Unknown service ${name}`);
     }
 
-    log(`Starting ${name} service…`);
+    Logger.info("lifecycle", `Starting ${name} service`);
     const init = services[name];
     await init(app, server);
   }
@@ -98,7 +98,7 @@ async function start(id: string, disconnect: () => void) {
 
   server.on("listening", () => {
     const address = server.address();
-    console.log(`\n> Listening on http://localhost:${address.port}\n`);
+    Logger.info("lifecycle", `Listening on http://localhost:${address.port}`);
   });
 
   server.listen(normalizedPortFlag || env.PORT || "3000");
@@ -107,7 +107,7 @@ async function start(id: string, disconnect: () => void) {
   process.once("SIGINT", shutdown);
 
   function shutdown() {
-    console.log("\n> Stopping server");
+    Logger.info("lifecycle", "Stopping server");
     server.stop(disconnect);
   }
 }

diff --git a/server/mailer.js b/server/mailer.js
@@ -1,6 +1,5 @@
 // @flow
 import * as Sentry from "@sentry/node";
-import debug from "debug";
 import nodemailer from "nodemailer";
 import Oy from "oy-vey";
 import * as React from "react";
@@ -32,8 +31,8 @@ import { SigninEmail, signinEmailText } from "./emails/SigninEmail";
 import { WelcomeEmail, welcomeEmailText } from "./emails/WelcomeEmail";
 import { baseStyles } from "./emails/components/EmailLayout";
 import { emailsQueue } from "./queues";
+import Logger from "./utils/logger";
 
-const log = debug("emails");
 const useTestEmailService =
   process.env.NODE_ENV === "development" && !process.env.SMTP_USERNAME;
 
@@ -101,7 +100,10 @@ export class Mailer {
     }
 
     if (useTestEmailService) {
-      log("SMTP_USERNAME not provided, generating test account…");
+      Logger.info(
+        "email",
+        "SMTP_USERNAME not provided, generating test account…"
+      );
 
       try {
         let testAccount = await nodemailer.createTestAccount();
@@ -118,7 +120,10 @@ export class Mailer {
 
         this.transporter = nodemailer.createTransport(smtpConfig);
       } catch (err) {
-        log(`Could not generate test account: ${err.message}`);
+        Logger.error(
+          "Couldn't generate a test account with ethereal.email",
+          err
+        );
       }
     }
   }
@@ -134,7 +139,7 @@ export class Mailer {
       });
 
       try {
-        log(`Sending email "${data.title}" to ${data.to}`);
+        Logger.info("email", `Sending email "${data.title}" to ${data.to}`);
         const info = await transporter.sendMail({
           from: process.env.SMTP_FROM_EMAIL,
           replyTo: process.env.SMTP_REPLY_EMAIL || process.env.SMTP_FROM_EMAIL,
@@ -145,7 +150,10 @@ export class Mailer {
         });
 
         if (useTestEmailService) {
-          log("Email Preview URL: %s", nodemailer.getTestMessageUrl(info));
+          Logger.info(
+            "email",
+            `Preview Url: ${nodemailer.getTestMessageUrl(info)}`
+          );
         }
       } catch (err) {
         if (process.env.SENTRY_DSN) {

diff --git a/server/queues/processors/exports.js b/server/queues/processors/exports.js
@@ -1,14 +1,12 @@
 // @flow
 import fs from "fs";
-import debug from "debug";
 import mailer from "../../mailer";
 import { FileOperation, Collection, Event, Team, User } from "../../models";
 import type { Event as TEvent } from "../../types";
+import Logger from "../../utils/logger";
 import { uploadToS3FromBuffer } from "../../utils/s3";
 import { archiveCollections } from "../../utils/zip";
 
-const log = debug("commands");
-
 export default class ExportsProcessor {
   async on(event: TEvent) {
     switch (event.name) {
@@ -30,7 +28,10 @@ export default class ExportsProcessor {
         });
 
         // heavy lifting of creating the zip file
-        log(`Archiving collections for file operation ${exportData.id}`);
+        Logger.info(
+          "processor",
+          `Archiving collections for file operation ${exportData.id}`
+        );
         const filePath = await archiveCollections(collections);
 
         let url, state;
@@ -43,18 +44,26 @@ export default class ExportsProcessor {
             size: stat.size,
           });
 
-          log(`Uploading archive for file operation ${exportData.id}`);
+          Logger.info(
+            "processor",
+            `Uploading archive for file operation ${exportData.id}`
+          );
           url = await uploadToS3FromBuffer(
             readBuffer,
             "application/zip",
             exportData.key,
             "private"
           );
 
-          log(`Upload complete for file operation ${exportData.id}`);
+          Logger.info(
+            "processor",
+            `Upload complete for file operation ${exportData.id}`
+          );
           state = "complete";
-        } catch (e) {
-          log("Failed to export data", e);
+        } catch (error) {
+          Logger.error("Error exporting collection data", error, {
+            fileOperationId: exportData.id,
+          });
           state = "error";
           url = null;
         } finally {

diff --git a/server/queues/processors/notifications.js b/server/queues/processors/notifications.js
@@ -1,5 +1,4 @@
 // @flow
-import debug from "debug";
 import mailer from "../../mailer";
 import {
   View,
@@ -11,8 +10,7 @@ import {
 } from "../../models";
 import { Op } from "../../sequelize";
 import type { DocumentEvent, CollectionEvent, Event } from "../../types";
-
-const log = debug("services");
+import Logger from "../../utils/logger";
 
 export default class NotificationsProcessor {
   async on(event: Event) {
@@ -98,7 +96,8 @@ export default class NotificationsProcessor {
       });
 
       if (view) {
-        log(
+        Logger.info(
+          "processor",
           `suppressing notification to ${setting.userId} because update viewed`
         );
         continue;