feat: nicer logging with tracer

server/lib/cache/methods/entitiesUpdatedSince.ts

@@ -2,6 +2,7 @@ import { baseNotesQuery, leanTypeEnumFixer } from '../../notes/notesMethods'
 import { Note } from '../../notes/notesModels'
 import { Tag } from '../../tags/tagModel'
 import { baseTagsQuery } from '../../tags/tagsMethods'
+import { timerEnd, timerStart } from '../../util/logging'
 import { Cache } from '../cacheModel'
 import { cacheDiff } from './cacheDiff'
 import { updateCacheFromDiff } from './updateCacheFromDiff'
@@ -11,6 +12,8 @@ export const entitiesUpdatedSince = async (cacheId, user) => {
     throw new Error('Need to be logged in to fetch links.')
   }
 
+  timerStart('entitiesUpdatedSince')
+
   let cache = (await Cache.findOne({ _id: cacheId, user }).lean()) || {
     _id: undefined,
     value: {
@@ -134,6 +137,8 @@ export const entitiesUpdatedSince = async (cacheId, user) => {
       ._id
   }
 
+  timerEnd('entitiesUpdatedSince', "Complete Method 'Entities Updated Since'")
+
   return {
     addedNotes: notesDiff.added,
     updatedNotes: notesDiff.updated,

server/lib/index.ts

@@ -14,6 +14,9 @@ import restApi from './restApi.js'
 import { resolvers, typeDefs } from './schema'
 import { setUpGitHubLogin } from './users/githubLogin.js'
 import { SessionContext } from './util/types'
+import { logger, timerEnd, timerStart } from './util/logging'
+
+timerStart('startup')
 
 const graphQlPath = '/graphql'
 
@@ -69,8 +72,8 @@ const runExpressServer = async () => {
               (JSON.stringify(responseContext.response).length * 2) /
               1024
             ).toFixed(1)
-            console.log(
-              `\x1b[33mApollo:\x1b[0m ${
+            logger.debug_raw(
+              `\x1b[33m[Apollo]\x1b[0m ${
                 requestContext.operation?.operation || 'UNKNOWN'
               } ${requestContext.operationName || 'UNNAMED'} (${
                 requestContext.contextValue.user?.name || 'ANONYMOUS'
@@ -89,7 +92,7 @@ const runExpressServer = async () => {
     typeDefs,
     resolvers,
     formatError: (formattedError) => {
-      console.error(
+      logger.error(
         `[Apollo Error] ${formattedError.message} @ ${
           formattedError.path?.join('.') || 'NO PATH'
         }\n `,
@@ -118,21 +121,22 @@ const runExpressServer = async () => {
   restApi(app)
 
   await new Promise<void>((resolve) => server.listen(config.PORT, resolve))
-  console.log(`REST Server running at http://localhost:${config.PORT}...`)
-  console.log(
+  logger.info(`REST Server running at http://localhost:${config.PORT}...`)
+  logger.info(
     `GraphQL Server running at http://localhost:${config.PORT}${graphQlPath}...`,
   )
+  timerEnd('startup', "Server startup")
 }
 
 await initializeMongo()
 
 try {
-  console.log('Running migrations...')
+  logger.info('Running migrations...')
   await migrationSystem.migrateTo(7)
-  console.log('Migrations complete.')
+  logger.info('Migrations complete.')
   await runExpressServer()
 } catch (error) {
-  console.error('Migration failed.')
-  console.error(error)
+  logger.info('Migration failed.')
+  logger.error(error)
   process.exit(1)
 }

server/lib/migrations/migrations.ts

@@ -6,6 +6,7 @@ import { ALL_PERMISSIONS } from '../tags/tagsMethods'
 import { User } from '../users/userModel'
 
 import { createOwnershipTagOnUser } from '../users/methods/createOwnershipTagOnUser'
+import { logger } from '../util/logging'
 
 const migrations = new Map()
 migrations.set(0, {
@@ -14,8 +15,7 @@ migrations.set(0, {
     const highestMigration = await mongoose.connection.db
       .collection('migrations')
       .findOne({ state: 'up' }, { sort: { createdAt: -1 } })
-    console.log('Detected highest previously run migration:')
-    console.log(highestMigration)
+    logger.info('Detected highest previously run migration:', highestMigration)
     let highestVersion = 0
     if (highestMigration !== null) {
       migrations.forEach((migration, version) => {
@@ -29,14 +29,14 @@ migrations.set(0, {
       _id: 'database-version',
       value: highestVersion,
     })
-    console.log(`Database version set to ${highestVersion}`)
-    console.log(
+    logger.info(`Database version set to ${highestVersion}`)
+    logger.info(
       "Obsolete 'migrations' collection not deleted, you can do so manually.",
     )
     return migrationMetaEntry.save()
   },
   async down() {
-    console.log('This migration is irreversible. Performing no action.')
+    logger.warn('This migration is irreversible. Performing no action.')
   },
 })
 migrations.set(1, {
@@ -120,7 +120,7 @@ const collectionsToAddUpdatedAtField = [Meta, User, Note, Tag]
 migrations.set(6, {
   name: 'create-field-updated-at',
   async up() {
-    console.log(
+    logger.info(
       "[Migration 6.1] Ensure the (previously missing) 'createdAt' field exists on all users...",
     )
     await User.find().then((users) =>
@@ -129,7 +129,7 @@ migrations.set(6, {
           if (user.createdAt) {
             return
           }
-          console.log(`Setting best-guess 'createdAt' for user ${user._id}...`)
+          logger.info(`Setting best-guess 'createdAt' for user ${user._id}...`)
           let oldestNoteCreatedAt = (
             await Note.findOne(
               { user: user._id },
@@ -140,17 +140,17 @@ migrations.set(6, {
             )
           )?.createdAt
           if (!oldestNoteCreatedAt) {
-            console.log('! User has no notes, using current time.')
+            logger.warn('User has no notes, using current time.')
             oldestNoteCreatedAt = new Date()
           }
           user.createdAt = oldestNoteCreatedAt
           return user.save({ timestamps: false })
         }),
       ),
     )
-    console.log('[Migration 6.1] OK\n')
+    logger.info('[Migration 6.1] OK\n')
 
-    console.log(
+    logger.info(
       "[Migration 6.2] Ensure the (previously missing) 'createdAt' field exists on all tags...",
     )
     await Tag.updateMany(
@@ -166,9 +166,9 @@ migrations.set(6, {
       ],
       { timestamps: false },
     )
-    console.log('[Migration 6.2] OK\n')
+    logger.info('[Migration 6.2] OK\n')
 
-    console.log(
+    logger.info(
       "[Migration 6.3] Ensure the (previously missing) 'createdAt' field exists on meta collection...",
     )
     const oldestUserCreatedAt =
@@ -190,9 +190,9 @@ migrations.set(6, {
       },
       { timestamps: false },
     )
-    console.log('[Migration 6.3] OK\n')
+    logger.info('[Migration 6.3] OK\n')
 
-    console.log("[Migration 6.4] Create field 'updatedAt' throughout...")
+    logger.info("[Migration 6.4] Create field 'updatedAt' throughout...")
     for (const collection of collectionsToAddUpdatedAtField) {
       await collection.updateMany(
         {},
@@ -206,34 +206,34 @@ migrations.set(6, {
         { timestamps: false },
       )
     }
-    console.log('[Migration 6.4] OK\n')
+    logger.info('[Migration 6.4] OK\n')
   },
   async down() {
-    console.log("[Migration 6.1] Delete 'createdAt' on user...")
+    logger.info("[Migration 6.1] Delete 'createdAt' on user...")
     await User.updateMany(
       {},
       { $unset: { createdAt: true } },
       { timestamps: false },
     )
-    console.log('[Migration 6.1] OK\n')
+    logger.info('[Migration 6.1] OK\n')
 
-    console.log("[Migration 6.2] Delete 'createdAt' on tag...")
+    logger.info("[Migration 6.2] Delete 'createdAt' on tag...")
     await Tag.updateMany(
       {},
       { $unset: { createdAt: true } },
       { timestamps: false },
     )
-    console.log('[Migration 6.2] OK\n')
+    logger.info('[Migration 6.2] OK\n')
 
-    console.log("[Migration 6.3] Delete 'createdAt' on meta collection...")
+    logger.info("[Migration 6.3] Delete 'createdAt' on meta collection...")
     await Meta.updateMany(
       {},
       { $unset: { createdAt: true } },
       { timestamps: false },
     )
-    console.log('[Migration 6.3] OK\n')
+    logger.info('[Migration 6.3] OK\n')
 
-    console.log("[Migration 6.4] Delete field 'updatedAt' throughout...")
+    logger.info("[Migration 6.4] Delete field 'updatedAt' throughout...")
     for (const collection of collectionsToAddUpdatedAtField) {
       await collection.updateMany(
         {},
@@ -245,7 +245,7 @@ migrations.set(6, {
         { timestamps: false },
       )
     }
-    console.log('[Migration 6.4] OK\n')
+    logger.info('[Migration 6.4] OK\n')
   },
 })
 

server/lib/mongo.ts

@@ -1,14 +1,25 @@
 import config from '@structure/config'
 import mongoose from 'mongoose'
+import util from 'util'
 import { Cache } from './cache/cacheModel'
+import { logger, colors } from './util/logging'
 
 export const initializeMongo = async () => {
   await mongoose.connect(config.MONGO_URL)
-  mongoose.set('debug', config.MONGOOSE_DEBUG)
+  if (config.MONGOOSE_DEBUG) {
+    // mongoose.set('debug', true)
+    mongoose.set('debug', (collectionName, methodName, ...methodArgs) =>
+      logger.debug_raw(
+        `${colors.cyan("[Mongoose]")} ${collectionName}.${methodName}(${methodArgs
+          .map((arg) => util.inspect(arg, { breakLength: Infinity }))
+          .join(', ')})`,
+      ),
+    )
+  }
   mongoose.set('strictQuery', 'throw')
 
   const clearOldCaches = async () => {
-    console.log('Clearing old caches...')
+    logger.info('Clearing old caches...')
     await Cache.deleteMany({
       updatedAt: {
         $lt: Date.now() - 30 * 24 * 60 * 60 * 1000,

server/lib/notes/notesResolvers.ts

@@ -12,6 +12,7 @@ import {
   submitLink,
 } from './notesMethods'
 import { Link, Note, Text } from './notesModels'
+import { logger } from '../util/logging'
 
 const INoteResolvers = {
   async tags(note, args, context) {
@@ -121,7 +122,7 @@ export const notesResolvers: NoteResolvers = {
       try {
         return fetchTitleSuggestions(link.url)
       } catch (error) {
-        console.warn(`Failed to fetch title suggestions for ${linkId}`, error)
+        logger.warn(`Failed to fetch title suggestions for ${linkId}`, error)
         return []
       }
     },

server/lib/restApi.ts

@@ -7,6 +7,7 @@ import { Link, Note } from './notes/notesModels.js'
 import { Tag } from './tags/tagModel.js'
 import { addTagByNameToNote } from './tags/tagsMethods.js'
 import { User } from './users/userModel.js'
+import { logger } from './util/logging.js'
 
 const restApi = (app) => {
   app.get('/bookmarklet', (request, response) => {
@@ -33,7 +34,7 @@ const restApi = (app) => {
         ),
       )
       .catch((error) => {
-        console.error('Bookmarklet URL insert failed!', error)
+        logger.error('Bookmarklet URL insert failed!', error)
         response
           .status(500)
           .send(
@@ -110,7 +111,7 @@ const restApi = (app) => {
           })
       })
       .catch((error) => {
-        console.error('Generating RSS feed failed!', error)
+        logger.error('Generating RSS feed failed!', error)
         response
           .status(500)
           .send(

server/lib/users/githubLogin.ts

@@ -5,6 +5,7 @@ import passport from 'passport'
 import PassportGithub from 'passport-github'
 import { createOwnershipTagOnUser } from './methods/createOwnershipTagOnUser'
 import { User } from './userModel'
+import { logger } from '../util/logging'
 
 // named import isn't working at the moment
 const GitHubStrategy = PassportGithub.Strategy
@@ -18,7 +19,7 @@ const store = new MongoDBSession({
 
 export function setUpGitHubLogin(app) {
   if (!config.GITHUB_CLIENT_ID) {
-    console.warn("GitHub client ID not passed; login won't work.") // eslint-disable-line no-console
+    logger.error("GitHub client ID not passed; login won't work.")
     return
   }
 

server/lib/util/logging.ts

@@ -0,0 +1,41 @@
+import { performance } from 'perf_hooks'
+import tracer from 'tracer'
+import colors from 'colors/safe'
+export { default as colors } from 'colors'
+
+export const logger = tracer.colorConsole({
+    methods: ['trace', 'trace_raw', 'debug', 'debug_raw', 'info', 'warn', 'error', 'fatal'],
+    filters: {
+        trace: colors.magenta,
+        trace_raw: colors.magenta,
+        debug: colors.white,
+        debug_raw: colors.white,
+        info: colors.green,
+        warn: colors.yellow,
+        error: [colors.red, colors.bold],
+        fatal: [colors.red, colors.bold, colors.underline]
+      },
+      format: [
+        '{{timestamp}} <{{title}}> {{file}}:{{line}} ({{method}}) {{message}}', //default format
+        {
+            trace_raw: '{{timestamp}} <trace> {{message}}',
+            debug_raw: '{{timestamp}} <debug> {{message}}',
+        }
+      ],
+})
+
+const timers: { [key: string]: number } = {};
+export const timerStart = (identifier: string) => {
+    if (timers[identifier]) {
+        logger.warn(`Duplicate timer identifier "${identifier}"`)
+    }
+    timers[identifier] = performance.now()
+}
+export const timerEnd = (identifier: string, message?: string) => {
+    if (!timers[identifier]) {
+        logger.warn(`No such timer identifier "${identifier}"`)
+        return
+    }
+    logger.trace_raw(`⏰ ${(performance.now() - timers[identifier]).toFixed(0).padStart(5)}ms`, message || identifier)
+    delete timers[identifier]
+}