feat(backend): logger (#8655)

* add logger to context

* add apollo logger

* apollo logger plugin must be set on createServer to avoid spam in unit tests

backend/package.json

@@ -87,6 +87,7 @@
     "sanitize-html": "~2.17.0",
     "slug": "~9.1.0",
     "trunc-html": "~1.1.2",
+    "tslog": "^4.9.3",
     "uuid": "~9.0.1",
     "validator": "^13.15.15",
     "xregexp": "^5.1.2"

backend/src/config/index.ts

@@ -29,6 +29,7 @@ const environment = {
     ? (env.DISABLED_MIDDLEWARES?.split(',') ?? [])
     : [],
   SEND_MAIL: env.NODE_ENV !== 'test',
+  LOG_LEVEL: 'DEBUG',
 }
 
 const required = {

backend/src/index.ts

@@ -1,9 +1,12 @@
 /* eslint-disable @typescript-eslint/restrict-template-expressions */
 
 import CONFIG from './config'
+import { loggerPlugin } from './plugins/apolloLogger'
 import createServer from './server'
 
-const { server, httpServer } = createServer()
+const { server, httpServer } = createServer({
+  plugins: [loggerPlugin],
+})
 const url = new URL(CONFIG.GRAPHQL_URI)
 httpServer.listen({ port: url.port }, () => {
   /* eslint-disable-next-line no-console */

backend/src/logger.ts

@@ -0,0 +1,63 @@
+import { ILogObj, Logger } from 'tslog'
+
+import CONFIG from './config'
+
+const { LOG_LEVEL } = CONFIG
+
+const logLevels = ['SILLY', 'TRACE', 'DEBUG', 'INFO', 'WARN', 'ERROR', 'FATAL'] as const
+type LogLevel = (typeof logLevels)[number]
+
+function isLogLevel(level: string): level is LogLevel {
+  return logLevels.includes(level as LogLevel)
+}
+
+if (!isLogLevel(LOG_LEVEL)) {
+  throw new Error(`Unknown log level '${LOG_LEVEL}'`)
+}
+
+const logLevelsMap: Record<LogLevel, number> = {
+  SILLY: 0,
+  TRACE: 1,
+  DEBUG: 2,
+  INFO: 3,
+  WARN: 4,
+  ERROR: 5,
+  FATAL: 6,
+}
+
+const minLevel = logLevelsMap[LOG_LEVEL] // eslint-disable-line security/detect-object-injection
+
+/**
+ * The Singleton class defines the `getInstance` method that lets clients access
+ * the unique singleton instance.
+ */
+// eslint-disable-next-line @typescript-eslint/no-extraneous-class
+class LoggerSingleton {
+  private static instance: Logger<ILogObj>
+
+  /**
+   * The Singleton's constructor should always be private to prevent direct
+   * construction calls with the `new` operator.
+   */
+  // eslint-disable-next-line @typescript-eslint/no-empty-function
+  private constructor() {}
+
+  /**
+   * The static method that controls the access to the singleton instance.
+   *
+   * This implementation let you subclass the Singleton class while keeping
+   * just one instance of each subclass around.
+   */
+  public static getInstance(): Logger<ILogObj> {
+    if (!LoggerSingleton.instance) {
+      LoggerSingleton.instance = new Logger({ minLevel, name: 'mainLogger' })
+    }
+
+    return LoggerSingleton.instance
+  }
+}
+
+const logger = LoggerSingleton.getInstance()
+export default logger
+type OcelotLogger = typeof logger
+export type { OcelotLogger as Logger }

backend/src/plugins/apolloLogger.spec.ts

@@ -0,0 +1,89 @@
+/* eslint-disable @typescript-eslint/no-unsafe-call */
+/* eslint-disable @typescript-eslint/no-unsafe-member-access */
+/* eslint-disable @typescript-eslint/no-unsafe-return */
+import { ApolloServer } from 'apollo-server-express'
+import { createTestClient } from 'apollo-server-testing'
+
+import databaseContext from '@context/database'
+import Factory, { cleanDatabase } from '@db/factories'
+import { loginMutation } from '@src/graphql/queries/loginMutation'
+import ocelotLogger from '@src/logger'
+import { loggerPlugin } from '@src/plugins/apolloLogger'
+import createServer, { getContext } from '@src/server'
+
+const database = databaseContext()
+
+let server: ApolloServer
+
+let mutate, authenticatedUser
+
+beforeAll(async () => {
+  await cleanDatabase()
+
+  // eslint-disable-next-line @typescript-eslint/require-await
+  const contextUser = async (_req) => authenticatedUser
+  const context = getContext({ user: contextUser, database })
+
+  server = createServer({ context, plugins: [loggerPlugin] }).server
+
+  const createTestClientResult = createTestClient(server)
+  mutate = createTestClientResult.mutate
+})
+
+afterAll(async () => {
+  await cleanDatabase()
+  void server.stop()
+  void database.driver.close()
+  database.neode.close()
+})
+
+const loggerSpy = jest.spyOn(ocelotLogger, 'debug')
+const consoleSpy = jest.spyOn(console, 'log')
+
+afterEach(async () => {
+  await cleanDatabase()
+})
+
+describe('apollo logger', () => {
+  beforeEach(async () => {
+    await Factory.build(
+      'user',
+      {
+        id: 'user',
+        name: 'user',
+        slug: 'user',
+      },
+      {
+        email: 'test@example.org',
+        password: '1234',
+      },
+    )
+  })
+
+  describe('login mutation', () => {
+    it('logs the request and response', async () => {
+      await mutate({
+        mutation: loginMutation,
+        variables: {
+          email: 'test@example.org',
+          password: '1234',
+        },
+      })
+
+      expect(loggerSpy).toBeCalledTimes(2)
+      expect(loggerSpy).toBeCalledWith(
+        'Apollo Request',
+        expect.any(String),
+        '"mutation ($email: String!, $password: String!) {\\n  login(email: $email, password: $password)\\n}\\n"',
+        JSON.stringify({
+          email: 'test@example.org',
+          password: '***',
+        }),
+      )
+
+      expect(loggerSpy).toBeCalledWith('Apollo Response', expect.any(String), expect.any(String))
+
+      expect(consoleSpy).toBeCalledTimes(2)
+    })
+  })
+})

backend/src/plugins/apolloLogger.ts

@@ -0,0 +1,39 @@
+/* eslint-disable @typescript-eslint/no-unsafe-member-access */
+/* eslint-disable @typescript-eslint/no-unsafe-assignment */
+
+import { randomBytes } from 'node:crypto'
+
+import cloneDeep from 'lodash/cloneDeep'
+
+import ocelotLogger from '@src/logger'
+
+export const loggerPlugin = {
+  requestDidStart(requestContext) {
+    const isIntrospectionQuery = requestContext.request.operationName === 'IntrospectionQuery'
+    const qID = randomBytes(4).toString('hex')
+    if (!isIntrospectionQuery) {
+      const logRequest = ['Apollo Request', qID]
+      logRequest.push(JSON.stringify(requestContext.request.query))
+      if (requestContext.request.variables) {
+        const variables = cloneDeep(requestContext.request.variables)
+        if (variables.password) variables.password = '***'
+        logRequest.push(JSON.stringify(variables))
+      }
+      ocelotLogger.debug(...logRequest)
+    }
+    return {
+      // eslint-disable-next-line @typescript-eslint/require-await
+      async willSendResponse(requestContext) {
+        if (!isIntrospectionQuery) {
+          const logResponse = ['Apollo Response', qID]
+          if (requestContext.errors) {
+            ocelotLogger.error(...logResponse, JSON.stringify(requestContext.errors))
+            return
+          }
+          logResponse.push(JSON.stringify(requestContext.response.data))
+          ocelotLogger.debug(...logResponse)
+        }
+      },
+    }
+  },
+}

backend/src/server.ts

@@ -19,9 +19,12 @@ import pubsubContext from '@context/pubsub'
 import CONFIG from './config'
 import schema from './graphql/schema'
 import decode from './jwt/decode'
+import ocelotLogger from './logger'
 // eslint-disable-next-line import/no-cycle
 import middleware from './middleware'
 
+import type OcelotLogger from './logger'
+
 const serverDatabase = databaseContext()
 const serverPubsub = pubsubContext()
 
@@ -33,11 +36,18 @@ export const getContext =
       database = serverDatabase,
       pubsub = serverPubsub,
       user = databaseUser,
+      logger = ocelotLogger,
     }: {
       database?: ReturnType<typeof databaseContext>
       pubsub?: ReturnType<typeof pubsubContext>
       user?: (any) => Promise<any>
-    } = { database: serverDatabase, pubsub: serverPubsub, user: databaseUser },
+      logger?: typeof OcelotLogger
+    } = {
+      database: serverDatabase,
+      pubsub: serverPubsub,
+      user: databaseUser,
+      logger: ocelotLogger,
+    },
   ) =>
   async (req) => {
     const u = await user(req)
@@ -46,6 +56,7 @@ export const getContext =
       driver: database.driver,
       neode: database.neode,
       pubsub,
+      logger,
       user: u,
       req,
       cypherParams: {
@@ -54,6 +65,8 @@ export const getContext =
     }
   }
 
+export type Context = Awaited<ReturnType<ReturnType<typeof getContext>>>
+
 export const context = async (options) => {
   const { connection, req } = options
   if (connection) {
@@ -79,6 +92,7 @@ const createServer = (options?) => {
       }
       return error
     },
+    plugins: [],
   }
   const server = new ApolloServer(Object.assign(defaults, options))
 
@@ -103,4 +117,3 @@ const createServer = (options?) => {
 }
 
 export default createServer
-export type Context = Awaited<ReturnType<ReturnType<typeof getContext>>>

backend/yarn.lock

@@ -10252,14 +10252,7 @@ string_decoder@^1.1.1, string_decoder@^1.3.0:
   dependencies:
     safe-buffer "~5.2.0"
 
-"strip-ansi-cjs@npm:strip-ansi@^6.0.1":
-  version "6.0.1"
-  resolved "https://registry.yarnpkg.com/strip-ansi/-/strip-ansi-6.0.1.tgz#9e26c63d30f53443e9489495b2105d37b67a85d9"
-  integrity sha512-Y38VPSHcqkFrCpFnQ9vuSXmquuv5oXOKpGeT6aGrr3o3Gc9AlVa6JBfUSOCnbxGGZF+/0ooI7KrPuUSztUdU5A==
-  dependencies:
-    ansi-regex "^5.0.1"
-
-strip-ansi@6.0.1, strip-ansi@^6.0.0, strip-ansi@^6.0.1, strip-ansi@^7.0.1:
+"strip-ansi-cjs@npm:strip-ansi@^6.0.1", strip-ansi@6.0.1, strip-ansi@^6.0.0, strip-ansi@^6.0.1, strip-ansi@^7.0.1:
   version "6.0.1"
   resolved "https://registry.yarnpkg.com/strip-ansi/-/strip-ansi-6.0.1.tgz#9e26c63d30f53443e9489495b2105d37b67a85d9"
   integrity sha512-Y38VPSHcqkFrCpFnQ9vuSXmquuv5oXOKpGeT6aGrr3o3Gc9AlVa6JBfUSOCnbxGGZF+/0ooI7KrPuUSztUdU5A==
@@ -10686,6 +10679,11 @@ tslib@^2.2.0, tslib@^2.4.0, tslib@^2.6.2:
   resolved "https://registry.yarnpkg.com/tslib/-/tslib-2.8.1.tgz#612efe4ed235d567e8aba5f2a5fab70280ade83f"
   integrity sha512-oJFu94HQb+KVduSUQL7wnpmqnfmLsOA/nAh6b6EH0wCEoK0/mPeXU6c3wKDV83MkOuHPRHtSXKKU99IBazS/2w==
 
+tslog@^4.9.3:
+  version "4.9.3"
+  resolved "https://registry.yarnpkg.com/tslog/-/tslog-4.9.3.tgz#d4167d5f51748bdeab593945bc2d8f9827ea0dba"
+  integrity sha512-oDWuGVONxhVEBtschLf2cs/Jy8i7h1T+CpdkTNWQgdAF7DhRo2G8vMCgILKe7ojdEkLhICWgI1LYSSKaJsRgcw==
+
 tsutils@^3.21.0:
   version "3.21.0"
   resolved "https://registry.yarnpkg.com/tsutils/-/tsutils-3.21.0.tgz#b48717d394cea6c1e096983eed58e9d61715b623"
@@ -11221,16 +11219,7 @@ with@^7.0.0:
     assert-never "^1.2.1"
     babel-walk "3.0.0-canary-5"
 
-"wrap-ansi-cjs@npm:wrap-ansi@^7.0.0":
-  version "7.0.0"
-  resolved "https://registry.yarnpkg.com/wrap-ansi/-/wrap-ansi-7.0.0.tgz#67e145cff510a6a6984bdf1152911d69d2eb9e43"
-  integrity sha512-YVGIj2kamLSTxw6NsZjoBxfSwsn0ycdesmc4p+Q21c5zPuZ1pl+NfxVdxPtdHvmNVOQ6XSYG4AUtyt/Fi7D16Q==
-  dependencies:
-    ansi-styles "^4.0.0"
-    string-width "^4.1.0"
-    strip-ansi "^6.0.0"
-
-wrap-ansi@7.0.0, wrap-ansi@^7.0.0, wrap-ansi@^8.1.0:
+"wrap-ansi-cjs@npm:wrap-ansi@^7.0.0", wrap-ansi@7.0.0, wrap-ansi@^7.0.0, wrap-ansi@^8.1.0:
   version "7.0.0"
   resolved "https://registry.yarnpkg.com/wrap-ansi/-/wrap-ansi-7.0.0.tgz#67e145cff510a6a6984bdf1152911d69d2eb9e43"
   integrity sha512-YVGIj2kamLSTxw6NsZjoBxfSwsn0ycdesmc4p+Q21c5zPuZ1pl+NfxVdxPtdHvmNVOQ6XSYG4AUtyt/Fi7D16Q==