From 09e012fdbc5314b81af14fe5d6a8346479b49175 Mon Sep 17 00:00:00 2001 From: neopostmodern Date: Fri, 3 May 2024 19:08:55 +0200 Subject: [PATCH] feat: nicer logging with `tracer` --- .../lib/cache/methods/entitiesUpdatedSince.ts | 5 ++ server/lib/index.ts | 22 ++--- server/lib/migrations/migrations.ts | 46 +++++------ server/lib/mongo.ts | 15 +++- server/lib/notes/notesResolvers.ts | 3 +- server/lib/restApi.ts | 5 +- server/lib/users/githubLogin.ts | 3 +- server/lib/util/logging.ts | 41 ++++++++++ server/package-lock.json | 81 +++++++++++++++++++ server/package.json | 1 + 10 files changed, 184 insertions(+), 38 deletions(-) create mode 100644 server/lib/util/logging.ts diff --git a/server/lib/cache/methods/entitiesUpdatedSince.ts b/server/lib/cache/methods/entitiesUpdatedSince.ts index ab9dee9..f802929 100644 --- a/server/lib/cache/methods/entitiesUpdatedSince.ts +++ b/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, diff --git a/server/lib/index.ts b/server/lib/index.ts index 6e8e5b8..ec5a29e 100644 --- a/server/lib/index.ts +++ b/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((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) } diff --git a/server/lib/migrations/migrations.ts b/server/lib/migrations/migrations.ts index c1510a5..051754e 100644 --- a/server/lib/migrations/migrations.ts +++ b/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,7 +140,7 @@ 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 @@ -148,9 +148,9 @@ migrations.set(6, { }), ), ) - 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') }, }) diff --git a/server/lib/mongo.ts b/server/lib/mongo.ts index a837fef..7cb4800 100644 --- a/server/lib/mongo.ts +++ b/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, diff --git a/server/lib/notes/notesResolvers.ts b/server/lib/notes/notesResolvers.ts index 78d9eef..8eb2412 100644 --- a/server/lib/notes/notesResolvers.ts +++ b/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 [] } }, diff --git a/server/lib/restApi.ts b/server/lib/restApi.ts index 428c1f5..af0e568 100644 --- a/server/lib/restApi.ts +++ b/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( diff --git a/server/lib/users/githubLogin.ts b/server/lib/users/githubLogin.ts index efb9f43..4f1bc93 100644 --- a/server/lib/users/githubLogin.ts +++ b/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 } diff --git a/server/lib/util/logging.ts b/server/lib/util/logging.ts new file mode 100644 index 0000000..c42686f --- /dev/null +++ b/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}} {{message}}', + debug_raw: '{{timestamp}} {{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] +} diff --git a/server/package-lock.json b/server/package-lock.json index 3ebd6c9..642692d 100644 --- a/server/package-lock.json +++ b/server/package-lock.json @@ -31,6 +31,7 @@ "node-fetch": "^3.3.1", "passport": "^0.6.0", "passport-github": "^1.1.0", + "tracer": "^1.3.0", "ts-node": "^10.9.1", "typescript": "^5.2.2" }, @@ -4757,6 +4758,14 @@ "integrity": "sha512-3tlv/dIP7FWvj3BsbHrGLJ6l/oKh1O3TcgBqMn+yyCagOxc23fyzDS6HypQbgxWbkpDnf52p1LuR4eWDQ/K9WQ==", "dev": true }, + "node_modules/colors": { + "version": "1.4.0", + "resolved": "https://registry.npmjs.org/colors/-/colors-1.4.0.tgz", + "integrity": "sha512-a+UqTh4kgZg/SlGvfbzDHpgRu7AAQOmmqRHJnxhRZICKFUT91brVhNNt58CMWU9PsBbv3PDCZUHbVxuDiH2mtA==", + "engines": { + "node": ">=0.1.90" + } + }, "node_modules/combined-stream": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", @@ -4993,6 +5002,14 @@ "integrity": "sha512-8YnDaaf7N3k/q5HnTJVuzSyLETjoZjVmHc4AeKAzOvKHEFQKcn64OKBfzHYtE9zGjctNM7V9I0MfnUVLpi7M5g==", "dev": true }, + "node_modules/dateformat": { + "version": "4.5.1", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.5.1.tgz", + "integrity": "sha512-OD0TZ+B7yP7ZgpJf5K2DIbj3FZvFvxgFUuaqA/V5zTjAtAAXZ1E8bktHxmAGs4x5b7PflqA9LeQ84Og7wYtF7Q==", + "engines": { + "node": "*" + } + }, "node_modules/debounce": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/debounce/-/debounce-1.2.1.tgz", @@ -6810,6 +6827,17 @@ "node": "*" } }, + "node_modules/mkdirp": { + "version": "1.0.4", + "resolved": "https://registry.npmjs.org/mkdirp/-/mkdirp-1.0.4.tgz", + "integrity": "sha512-vVqVZQyf3WLx2Shd0qJ9xuvqgAyKPLAiqITEtqW0oIUjzo3PePDd6fW9iFz30ef7Ysp/oiWqbhszeGWW2T6Gzw==", + "bin": { + "mkdirp": "bin/cmd.js" + }, + "engines": { + "node": ">=10" + } + }, "node_modules/moment": { "version": "2.29.4", "resolved": "https://registry.npmjs.org/moment/-/moment-2.29.4.tgz", @@ -8203,6 +8231,14 @@ "integrity": "sha1-DdTJ/6q8NXlgsbckEV1+Doai4fU=", "dev": true }, + "node_modules/tinytim": { + "version": "0.1.1", + "resolved": "https://registry.npmjs.org/tinytim/-/tinytim-0.1.1.tgz", + "integrity": "sha512-NIpsp9lBIxPNzB++HnMmUd4byzJSVbbO4F+As1Gb1IG/YQT5QvmBDjpx8SpDS8fhGC+t+Qw8ldQgbcAIaU+2cA==", + "engines": { + "node": ">= 0.2.0" + } + }, "node_modules/title-case": { "version": "3.0.3", "resolved": "https://registry.npmjs.org/title-case/-/title-case-3.0.3.tgz", @@ -8272,6 +8308,20 @@ "resolved": "https://registry.npmjs.org/tr46/-/tr46-0.0.3.tgz", "integrity": "sha1-gYT9NH2snNwYWZLzpmIuFLnZq2o=" }, + "node_modules/tracer": { + "version": "1.3.0", + "resolved": "https://registry.npmjs.org/tracer/-/tracer-1.3.0.tgz", + "integrity": "sha512-8G2okIuUNThM1W8HU9YUCsQgxROw9VpewE2f8Tsw3B90b0acvBiATqnUIvv07qG/aBTs7ALDr7tLVUVD86kPPA==", + "dependencies": { + "colors": "1.4.0", + "dateformat": "4.5.1", + "mkdirp": "^1.0.4", + "tinytim": "0.1.1" + }, + "engines": { + "node": ">= 16.20.1" + } + }, "node_modules/ts-log": { "version": "2.2.4", "resolved": "https://registry.npmjs.org/ts-log/-/ts-log-2.2.4.tgz", @@ -12561,6 +12611,11 @@ "integrity": "sha512-3tlv/dIP7FWvj3BsbHrGLJ6l/oKh1O3TcgBqMn+yyCagOxc23fyzDS6HypQbgxWbkpDnf52p1LuR4eWDQ/K9WQ==", "dev": true }, + "colors": { + "version": "1.4.0", + "resolved": "https://registry.npmjs.org/colors/-/colors-1.4.0.tgz", + "integrity": "sha512-a+UqTh4kgZg/SlGvfbzDHpgRu7AAQOmmqRHJnxhRZICKFUT91brVhNNt58CMWU9PsBbv3PDCZUHbVxuDiH2mtA==" + }, "combined-stream": { "version": "1.0.8", "resolved": "https://registry.npmjs.org/combined-stream/-/combined-stream-1.0.8.tgz", @@ -12748,6 +12803,11 @@ "integrity": "sha512-8YnDaaf7N3k/q5HnTJVuzSyLETjoZjVmHc4AeKAzOvKHEFQKcn64OKBfzHYtE9zGjctNM7V9I0MfnUVLpi7M5g==", "dev": true }, + "dateformat": { + "version": "4.5.1", + "resolved": "https://registry.npmjs.org/dateformat/-/dateformat-4.5.1.tgz", + "integrity": "sha512-OD0TZ+B7yP7ZgpJf5K2DIbj3FZvFvxgFUuaqA/V5zTjAtAAXZ1E8bktHxmAGs4x5b7PflqA9LeQ84Og7wYtF7Q==" + }, "debounce": { "version": "1.2.1", "resolved": "https://registry.npmjs.org/debounce/-/debounce-1.2.1.tgz", @@ -14104,6 +14164,11 @@ "brace-expansion": "^1.1.7" } }, + "mkdirp": { + "version": "1.0.4", + "resolved": "https://registry.npmjs.org/mkdirp/-/mkdirp-1.0.4.tgz", + "integrity": "sha512-vVqVZQyf3WLx2Shd0qJ9xuvqgAyKPLAiqITEtqW0oIUjzo3PePDd6fW9iFz30ef7Ysp/oiWqbhszeGWW2T6Gzw==" + }, "moment": { "version": "2.29.4", "resolved": "https://registry.npmjs.org/moment/-/moment-2.29.4.tgz", @@ -15141,6 +15206,11 @@ "integrity": "sha1-DdTJ/6q8NXlgsbckEV1+Doai4fU=", "dev": true }, + "tinytim": { + "version": "0.1.1", + "resolved": "https://registry.npmjs.org/tinytim/-/tinytim-0.1.1.tgz", + "integrity": "sha512-NIpsp9lBIxPNzB++HnMmUd4byzJSVbbO4F+As1Gb1IG/YQT5QvmBDjpx8SpDS8fhGC+t+Qw8ldQgbcAIaU+2cA==" + }, "title-case": { "version": "3.0.3", "resolved": "https://registry.npmjs.org/title-case/-/title-case-3.0.3.tgz", @@ -15195,6 +15265,17 @@ "resolved": "https://registry.npmjs.org/tr46/-/tr46-0.0.3.tgz", "integrity": "sha1-gYT9NH2snNwYWZLzpmIuFLnZq2o=" }, + "tracer": { + "version": "1.3.0", + "resolved": "https://registry.npmjs.org/tracer/-/tracer-1.3.0.tgz", + "integrity": "sha512-8G2okIuUNThM1W8HU9YUCsQgxROw9VpewE2f8Tsw3B90b0acvBiATqnUIvv07qG/aBTs7ALDr7tLVUVD86kPPA==", + "requires": { + "colors": "1.4.0", + "dateformat": "4.5.1", + "mkdirp": "^1.0.4", + "tinytim": "0.1.1" + } + }, "ts-log": { "version": "2.2.4", "resolved": "https://registry.npmjs.org/ts-log/-/ts-log-2.2.4.tgz", diff --git a/server/package.json b/server/package.json index bba8491..534aafe 100644 --- a/server/package.json +++ b/server/package.json @@ -30,6 +30,7 @@ "node-fetch": "^3.3.1", "passport": "^0.6.0", "passport-github": "^1.1.0", + "tracer": "^1.3.0", "ts-node": "^10.9.1", "typescript": "^5.2.2" },