Structured logging (attempt 2) (#1234)

* Revert "Revert "feat(structured logging): implements structured logging for backend (#1217)" (#1227)"

This reverts commit 63e6581162.

* Use pino-http instead of express pino logger
* Use correct reference to knex and do not instantiate HttpLogger prematurely
* Adds missing dependency for pino to webhook-service
* Do not instantiate middleware when passed to express
* Refactor to move logging into shared
* Copy shared packages into dockerfiles
* Build shared workspace in docker build-stage for fileimport & webhook

packages/server/modules/cli/commands/activities/send.ts

@@ -2,7 +2,7 @@ import { CommandModule } from 'yargs'
 import { initializeQueue } from '@/modules/notifications/services/queue'
 import { sendActivityNotifications } from '@/modules/activitystream/services/summary'
 import { publishNotification } from '@/modules/notifications/services/publication'
-import { cliDebug } from '@/modules/shared/utils/logger'
+import { cliLogger } from '@/logging/logging'
 
 const command: CommandModule = {
   command: 'send [days]',
@@ -22,7 +22,7 @@ const command: CommandModule = {
     const start = new Date(end.getTime())
     start.setDate(start.getDate() - numberOfDays)
     await sendActivityNotifications(start, end, publishNotification)
-    cliDebug('Sent activity notifications')
+    cliLogger.info('Sent activity notifications')
   }
 }
 

packages/server/modules/cli/commands/bull/monitor.ts

@@ -7,8 +7,8 @@ import {
   NOTIFICATIONS_QUEUE,
   buildNotificationsQueue
 } from '@/modules/notifications/services/queue'
-import { cliDebug } from '@/modules/shared/utils/logger'
 import { noop } from 'lodash'
+import { cliLogger } from '@/logging/logging'
 
 const PORT = 3032
 
@@ -25,15 +25,15 @@ const command: CommandModule<unknown, { testQueueId: string }> = {
   handler: async (argv) => {
     const testQueueId = argv.testQueueId
 
-    cliDebug('Initializing bull queues...')
+    cliLogger.info('Initializing bull queues...')
     const queues = [buildNotificationsQueue(NOTIFICATIONS_QUEUE)]
 
     if (testQueueId) {
-      cliDebug('Also initializing queue ' + testQueueId + '...')
+      cliLogger.info('Also initializing queue %s...', testQueueId)
       queues.push(buildNotificationsQueue(testQueueId))
     }
 
-    cliDebug('Initializing monitor...')
+    cliLogger.info('Initializing monitor...')
     const app = express()
     const serverAdapter = new ExpressAdapter()
 
@@ -45,8 +45,8 @@ const command: CommandModule<unknown, { testQueueId: string }> = {
     app.use(serverAdapter.getRouter())
 
     app.listen(PORT, () => {
-      cliDebug(`Running on ${PORT}...`)
-      cliDebug(
+      cliLogger.info(`Running on ${PORT}...`)
+      cliLogger.info(
         `For the UI, open http://localhost:${PORT}/, and make sure Redis is running`
       )
     })

packages/server/modules/cli/commands/bull/test-consume.ts

@@ -1,6 +1,6 @@
+import { cliLogger } from '@/logging/logging'
 import { NotificationType } from '@/modules/notifications/helpers/types'
 import { initializeConsumption } from '@/modules/notifications/index'
-import { cliDebug } from '@/modules/shared/utils/logger'
 import { get, noop } from 'lodash'
 import { CommandModule } from 'yargs'
 
@@ -8,12 +8,12 @@ const command: CommandModule = {
   command: 'test-consume',
   describe: 'Consume incoming messages inserted through test-push',
   handler: async () => {
-    cliDebug('Starting consumption...')
+    cliLogger.info('Starting consumption...')
 
     // Overriding handler for test purposes, we don't want the actual mentions logic to run
     await initializeConsumption({
-      [NotificationType.MentionedInComment]: async (msg, { debug, job }) => {
-        debug('Received test message with payload', msg, job)
+      [NotificationType.MentionedInComment]: async (msg, { logger, job }) => {
+        logger.info('Received test message with payload', msg, job)
 
         if (get(msg.data, 'error')) {
           throw new Error('Forced to throw error!')

packages/server/modules/cli/commands/bull/test-push.ts

@@ -1,10 +1,10 @@
+import { cliLogger } from '@/logging/logging'
 import {
   MentionedInCommentData,
   NotificationType
 } from '@/modules/notifications/helpers/types'
 import { publishNotification } from '@/modules/notifications/services/publication'
 import { initializeQueue } from '@/modules/notifications/services/queue'
-import { cliDebug } from '@/modules/shared/utils/logger'
 import { CommandModule } from 'yargs'
 
 const command: CommandModule = {
@@ -36,7 +36,7 @@ const command: CommandModule = {
       } as unknown as MentionedInCommentData
     })
 
-    cliDebug('Queued a fake notification...')
+    cliLogger.info('Queued a fake notification...')
   }
 }
 

packages/server/modules/cli/commands/db/migrate/create.js

@@ -1,6 +1,7 @@
 const knex = require('@/db/knex')
 const { appRoot } = require('@/bootstrap')
 const fs = require('fs/promises')
+const { logger } = require('@/logging/logging')
 
 /** @type {import('yargs').CommandModule} */
 const command = {
@@ -30,12 +31,12 @@ const command = {
       )
     }
 
-    console.log('Creating migration...')
+    logger.info('Creating migration...')
     await knex.migrate.make(name, {
       directory: migrationDir,
       extension: 'ts'
     })
-    console.log('...done')
+    logger.info('migration is complete')
   }
 }
 

packages/server/modules/cli/commands/db/migrate/down.js

@@ -1,13 +1,14 @@
 const knex = require('@/db/knex')
+const { logger } = require('@/logging/logging')
 
 /** @type {import('yargs').CommandModule} */
 const command = {
   command: 'down',
   describe: 'Undo last run migration',
   async handler() {
-    console.log('Undoing last migration...')
+    logger.info('Undoing last migration...')
     await knex.migrate.down()
-    console.log('...done')
+    logger.info('Completed undoing last migration')
   }
 }
 

packages/server/modules/cli/commands/db/migrate/latest.js

@@ -1,13 +1,14 @@
 const knex = require('@/db/knex')
+const { logger } = require('@/logging/logging')
 
 /** @type {import('yargs').CommandModule} */
 const command = {
   command: 'latest',
   describe: 'Run all migrations that have not yet been run',
   async handler() {
-    console.log('Running...')
+    logger.info('Running latest migration...')
     await knex.migrate.latest()
-    console.log('...done')
+    logger.info('Completed running migration')
   }
 }
 

packages/server/modules/cli/commands/db/migrate/rollback.js

@@ -1,13 +1,14 @@
 const knex = require('@/db/knex')
+const { logger } = require('@/logging/logging')
 
 /** @type {import('yargs').CommandModule} */
 const command = {
   command: 'rollback',
   describe: 'Roll back all migrations',
   async handler() {
-    console.log('Rolling back...')
+    logger.info('Rolling back migrations...')
     await knex.migrate.rollback(null, true)
-    console.log('...done')
+    logger.info('Completed rolling back migrations')
   }
 }
 

packages/server/modules/cli/commands/db/migrate/up.js

@@ -1,13 +1,14 @@
 const knex = require('@/db/knex')
+const { logger } = require('@/logging/logging')
 
 /** @type {import('yargs').CommandModule} */
 const command = {
   command: 'up',
   describe: 'Run next migration that has not yet been run',
   async handler() {
-    console.log('Running...')
+    logger.info('Running next migration...')
     await knex.migrate.up()
-    console.log('...done')
+    logger.info('Completed running next migration')
   }
 }
 

packages/server/modules/cli/commands/db/seed/commits.ts

@@ -1,6 +1,6 @@
+import { cliLogger } from '@/logging/logging'
 import { getStream } from '@/modules/core/repositories/streams'
 import { getUser } from '@/modules/core/repositories/users'
-import { cliDebug } from '@/modules/shared/utils/logger'
 import { BasicTestCommit, createTestCommits } from '@/test/speckle-helpers/commitHelper'
 import dayjs from 'dayjs'
 import { times } from 'lodash'
@@ -48,7 +48,7 @@ const command: CommandModule<
       )
     }
 
-    cliDebug(`Generating ${count} objects & commits for stream ${streamId}...`)
+    cliLogger.info(`Generating ${count} objects & commits for stream ${streamId}...`)
     await createTestCommits(
       times(
         count,
@@ -61,7 +61,7 @@ const command: CommandModule<
         })
       )
     )
-    cliDebug(`...done`)
+    cliLogger.info(`...done`)
   }
 }
 

packages/server/modules/cli/commands/db/seed/users.js

@@ -1,3 +1,4 @@
+const { logger } = require('@/logging/logging')
 const { Users, ServerAcl } = require('@/modules/core/dbSchema')
 const { Roles } = require('@/modules/core/helpers/mainConstants')
 const { faker } = require('@faker-js/faker')
@@ -45,11 +46,11 @@ async function* batchedOperationGenerator({
   batchSize,
   retryCount = 3
 }) {
-  console.log('Starting batched operation...')
+  logger.info('Starting batched operation...')
   let currentItemCount = 0
   const batchCount = Math.ceil(itemCount / batchSize)
   for (let i = 0; i < batchCount; i++) {
-    console.log(`Processing batch ${i + 1} out of ${batchCount}...`)
+    logger.info(`Processing batch ${i + 1} out of ${batchCount}...`)
 
     const newItemCount = Math.min(currentItemCount + batchSize, itemCount)
     const insertCount = newItemCount - currentItemCount
@@ -59,7 +60,7 @@ async function* batchedOperationGenerator({
     const execute = () =>
       Promise.resolve(batchInsertGenerator(insertCount, currentItemCount))
     let batchPromise = execute().then((res) => {
-      console.log(`...processed batch ${i + 1} out of ${batchCount}`)
+      logger.info(`...processed batch ${i + 1} out of ${batchCount}`)
       return res
     })
 
@@ -70,7 +71,7 @@ async function* batchedOperationGenerator({
       })
     })
     batchPromise = batchPromise.catch((e) => {
-      console.error('Operation failed all retries: ', e)
+      logger.error('Operation failed all retries: ', e)
     })
 
     currentItemCount = newItemCount
@@ -110,14 +111,14 @@ const command = {
     })
 
     for await (const insertedIds of userBatchedInsertionGenerator) {
-      console.log('Inserting ACL entries for batch...')
+      logger.info('Inserting ACL entries for batch...')
       const entries = insertedIds.map((id) => ({
         role: Roles.Server.User,
         userId: id
       }))
 
       await ServerAcl.knex().insert(entries)
-      console.log('...inserted ACL')
+      logger.info('...inserted ACL')
     }
   }
 }

packages/server/modules/cli/commands/download/commit.ts

@@ -7,7 +7,6 @@ import {
   HttpLink,
   ApolloQueryResult
 } from '@apollo/client/core'
-import { cliDebug } from '@/modules/shared/utils/logger'
 import { CommandModule } from 'yargs'
 import { getBaseUrl, getServerVersion } from '@/modules/shared/helpers/envHelper'
 import { Commit } from '@/test/graphql/generated/graphql'
@@ -20,6 +19,7 @@ import { createObject } from '@/modules/core/services/objects'
 import { getObject } from '@/modules/core/repositories/objects'
 import ObjectLoader from '@speckle/objectloader'
 import { noop } from 'lodash'
+import { cliLogger } from '@/logging/logging'
 
 type LocalResources = Awaited<ReturnType<typeof getLocalResources>>
 type ParsedCommitUrl = ReturnType<typeof parseCommitUrl>
@@ -188,7 +188,7 @@ const createNewObject = async (
   targetStreamId: string
 ) => {
   if (!newObject) {
-    cliDebug('Encountered falsy object!')
+    cliLogger.error('Encountered falsy object!')
     return
   }
 
@@ -230,7 +230,9 @@ const loadAllObjectsFromParent = async (params: {
   let processedObjectCount = 1
   for await (const obj of objectLoader.getObjectIterator()) {
     const typedObj = obj as ObjectLoaderObject
-    cliDebug(`Processing ${obj.id} - ${processedObjectCount++}/${totalObjectCount}`)
+    cliLogger.info(
+      `Processing ${obj.id} - ${processedObjectCount++}/${totalObjectCount}`
+    )
     await createNewObject(typedObj, targetStreamId)
   }
 }
@@ -259,24 +261,24 @@ const command: CommandModule<
   },
   handler: async (argv) => {
     const { commitUrl, targetStreamId, branchName } = argv
-    cliDebug(`Process started at: ${new Date().toISOString()}`)
+    cliLogger.info(`Process started at: ${new Date().toISOString()}`)
 
     const localResources = await getLocalResources(targetStreamId, branchName)
-    cliDebug(
+    cliLogger.info(
       `Using local branch ${branchName} of stream ${targetStreamId} to dump the incoming commit`
     )
 
     const parsedCommitUrl = parseCommitUrl(commitUrl)
-    cliDebug('Loading the following commit: ', parsedCommitUrl)
+    cliLogger.info('Loading the following commit: %s', parsedCommitUrl)
 
     const client = await createApolloClient(parsedCommitUrl.origin)
     const commit = await getCommitMetadata(client, parsedCommitUrl)
-    cliDebug('Loaded commit metadata', commit)
+    cliLogger.info('Loaded commit metadata: %s', commit)
 
     const newCommitId = await saveNewCommit(commit, localResources)
-    cliDebug(`Created new local commit: ${newCommitId}`)
+    cliLogger.info(`Created new local commit: ${newCommitId}`)
 
-    cliDebug(`Pulling & saving all objects! (${commit.totalChildrenCount})`)
+    cliLogger.info(`Pulling & saving all objects! (${commit.totalChildrenCount})`)
     await loadAllObjectsFromParent({
       targetStreamId,
       sourceCommit: commit,
@@ -284,7 +286,7 @@ const command: CommandModule<
     })
 
     const linkToNewCommit = `${getBaseUrl()}/streams/${targetStreamId}/commits/${newCommitId}`
-    cliDebug(`All done! Find your commit here: ${linkToNewCommit}`)
+    cliLogger.info(`All done! Find your commit here: ${linkToNewCommit}`)
   }
 }
 

packages/server/modules/cli/index.js

@@ -1,3 +1,4 @@
+const { logger } = require('@/logging/logging')
 const path = require('path')
 const yargs = require('yargs')
 require('../../bootstrap')
@@ -10,12 +11,12 @@ const execution = yargs
   .fail((msg, err, yargs) => {
     if (!err) {
       // If validation error (no err instance) then just show help and show the message
-      console.error(yargs.help())
-      console.error('\n', msg)
+      logger.error(yargs.help())
+      logger.error('\n', msg)
     } else {
       // If actual app error occurred, show the msg, but don't show help info
-      console.error(err)
-      console.error('\n', 'Specify --help for available options')
+      logger.error(err)
+      logger.error('\n', 'Specify --help for available options')
     }
 
     process.exit(1)