feat: TECH make graphql requests more verbose (#105)

* feat: TECH log graphql operation name

* Log query unless operation name provided

* fix: TECH trigger release

.circleci/config.yml

@@ -9,7 +9,7 @@ defaults: &defaults
   working_directory: /logger
   resource_class: small
   docker:
-    - image: node:20.8.1
+    - image: node:20.11.0
       <<: *docker-auth
 
 references:

.node-version

@@ -1 +1 @@
-16.20.0
+20.11.0

packages/gcloud-express-logger/jest.config.js

@@ -0,0 +1,7 @@
+module.exports = {
+  testEnvironment: 'node',
+  testPathIgnorePatterns: ['/node_modules/', 'dist', '.eslintrc.js', '/support/'],
+  runtime: '@side/jest-runtime',
+  transform: { '^.+\\.tsx?$': '@swc/jest' },
+  resetMocks: true,
+}

packages/gcloud-express-logger/package.json

@@ -10,8 +10,8 @@
     "url": "git+https://github.com/join-com/logger.git"
   },
   "keywords": [
-    "gcloud",
     "logger",
+    "gcloud",
     "express",
     "google cloud platform",
     "typescript"
@@ -25,7 +25,7 @@
     "lint:eslint": "eslint . --ext .ts --max-warnings 0",
     "lint:tsc": "tsc --noEmit",
     "prepublishOnly": "yarn lint && yarn build",
-    "test": "echo not tests"
+    "test": "jest"
   },
   "dependencies": {
     "on-finished": "^2.4.1"
@@ -34,9 +34,13 @@
     "@join-private/eslint-config-backend": "^1.3.0",
     "@types/express": "^4.17.17",
     "@types/on-finished": "^2.3.1",
+    "@types/supertest": "^6.0.2",
+    "body-parser": "^1.20.2",
     "eslint": "^8.37.0",
     "express": "^4.18.2",
+    "jest": "^29.7.0",
     "prettier": "^2.8.7",
+    "supertest": "^7.0.0",
     "typescript": "^5.0.2"
   },
   "publishConfig": {

packages/gcloud-express-logger/src/__tests__/requestLogger.test.ts

@@ -0,0 +1,93 @@
+import request from 'supertest'
+import { IGcloudLogger } from '..'
+import { createApp } from './support/app'
+
+const loggerMock = jest.mocked<IGcloudLogger>({
+  info: jest.fn(),
+  warn: jest.fn(),
+  error: jest.fn(),
+})
+
+describe('requestLogger', () => {
+  const app = createApp(loggerMock)
+
+  describe('with rest API', () => {
+    it('logs request', async () => {
+      const body = { title: 'Backend Engineer' }
+
+      await request(app)
+        .post('/api/jobs')
+        .set('release', '[email protected]')
+        .set('transaction-id', 'z8zpql5')
+        .set('transaction-name', 'PublishJob')
+        .set('user-agent', 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 ...')
+        .set('referer', 'https://join.com/dashboard')
+        .send(body)
+        .expect(201)
+
+      expect(loggerMock.info).toHaveBeenCalledWith('/api/jobs', {
+        httpRequest: expect.objectContaining({
+          requestMethod: 'POST',
+          requestUrl: '/api/jobs',
+          status: 201,
+          release: '[email protected]',
+          transactionId: 'z8zpql5',
+          transactionName: 'PublishJob',
+          userAgent: 'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 ...',
+          referer: 'https://join.com/dashboard',
+          latency: expect.stringMatching(/\d+\.\d+ms/),
+          remoteIp: expect.any(String),
+        }),
+        requestTime: expect.any(Number),
+        reqBody: body,
+        query: {},
+      })
+    })
+  })
+
+  describe('with graphql API', () => {
+    const query = `
+        query ListCompanies {
+          companies {
+            id
+          }
+        }
+      `
+
+    it('logs request', async () => {
+      await request(app).post('/graphql').send({ query }).expect(200)
+      expect(loggerMock.info).toHaveBeenCalledWith('/graphql ListCompanies', {
+        httpRequest: expect.objectContaining({
+          requestMethod: 'POST',
+          requestUrl: '/graphql',
+          status: 200,
+        }),
+        requestTime: expect.any(Number),
+        reqBody: { query },
+        query: {},
+      })
+    })
+
+    it('logs operation name if provided', async () => {
+      const operationName = 'ListCompaniesOperation'
+
+      await request(app).post('/graphql').send({ query, operationName }).expect(200)
+
+      expect(loggerMock.info).toHaveBeenCalledWith(`/graphql ${operationName}`, expect.any(Object))
+    })
+
+    it('logs mutation name', async () => {
+      const query = `
+        mutation RegisterCompany {
+          companies {
+            id
+          }
+        }
+      `
+
+      await request(app).post('/graphql').send({ query }).expect(200)
+
+      expect(loggerMock.info).toHaveBeenCalledWith('/graphql RegisterCompany', expect.any(Object))
+    })
+  })
+})

packages/gcloud-express-logger/src/__tests__/support/app.ts

@@ -0,0 +1,32 @@
+import bodyParser from 'body-parser'
+import express, { Application } from 'express'
+import { IGcloudLogger, requestLogger } from '../../'
+
+const jobsRouter = express.Router()
+jobsRouter.post('/jobs', (_req, res) => {
+  res.status(201).send('OK')
+})
+
+const companiesRouter = express.Router()
+jobsRouter.post('/companies', (_req, res) => {
+  res.status(201).send('OK')
+})
+
+const graphqlHandler = (_req: express.Request, res: express.Response) => {
+  res.status(200).send('OK')
+}
+
+export const createApp = (logger: IGcloudLogger): Application => {
+  const app = express()
+
+  app.use(requestLogger(logger))
+  app.use(bodyParser.json())
+
+  const restRouter = express.Router()
+  restRouter.use([jobsRouter, companiesRouter])
+
+  app.use('/api', restRouter)
+  app.use('/graphql', graphqlHandler)
+
+  return app
+}

packages/gcloud-express-logger/src/index.ts

@@ -13,41 +13,59 @@ const requestLogMessage = (req: Request, res: Response, ms: number) => ({
     transactionName: req.headers['transaction-name'],
     referer: req.headers.referer,
     latency: `${ms.toFixed(3)}ms`,
-    path: req.route && req.route.path,
   },
   query: req.query,
   reqBody: req.body,
   requestTime: ms,
 })
 
+const requestOperationName = (req: Request): string | undefined => {
+  if ('operationName' in req.body && typeof req.body.operationName === 'string') {
+    return req.body.operationName
+  }
+
+  if (req.originalUrl.endsWith('graphql') && 'query' in req.body && typeof req.body.query === 'string') {
+    const query = req.body.query as string
+    const match = query.match(/\s*(query|mutation)\s+(\w+)/)
+    return match ? match[2] : undefined
+  }
+
+  return undefined
+}
+
 export interface IGcloudLogger {
   info: (message: string, payload?: unknown) => void
   warn: (message: string, payload?: unknown) => void
   error: (message: string, payload?: unknown) => void
 }
 
-export const requestLogger = (logger: IGcloudLogger) => (req: Request, res: Response, next: NextFunction): void => {
-  const startTime = process.hrtime()
-
-  const logRequest = () => {
-    const diff = process.hrtime(startTime)
-    const ms = diff[0] * 1e3 + diff[1] * 1e-6
-    const message = requestLogMessage(req, res, ms)
-    if (res.statusCode >= 500) {
-      logger.error(req.path, message)
-    } else if (res.statusCode >= 400) {
-      logger.warn(req.path, message)
-    } else {
-      logger.info(req.path, message)
+export const requestLogger =
+  (logger: IGcloudLogger) =>
+  (req: Request, res: Response, next: NextFunction): void => {
+    const startTime = process.hrtime()
+
+    const logRequest = () => {
+      const diff = process.hrtime(startTime)
+      const ms = diff[0] * 1e3 + diff[1] * 1e-6
+      const payload = requestLogMessage(req, res, ms)
+      const operationName = requestOperationName(req)
+      const message = operationName ? `${req.originalUrl} ${operationName}` : req.originalUrl
+
+      if (res.statusCode >= 500) {
+        logger.error(message, payload)
+      } else if (res.statusCode >= 400) {
+        logger.warn(message, payload)
+      } else {
+        logger.info(message, payload)
+      }
     }
+    if (
+      req.originalUrl !== '/healthz' &&
+      req.originalUrl !== '/readiness' &&
+      req.originalUrl !== '/api/healthz' &&
+      req.originalUrl !== '/api/readiness'
+    ) {
+      onFinished(res, logRequest)
+    }
+    next()
   }
-  if (
-    req.originalUrl !== '/healthz' &&
-    req.originalUrl !== '/readiness' &&
-    req.originalUrl !== '/api/healthz' &&
-    req.originalUrl !== '/api/readiness'
-  ) {
-    onFinished(res, logRequest)
-  }
-  next()
-}

packages/gcloud-express-logger/tsconfig.json

@@ -1,8 +1,8 @@
 {
   "extends": "../../tsconfig.json",
-  "include": ["./src/**/*"],
+  "include": ["./src/**/*", "./__tests__"],
   "compilerOptions": {
     "noEmit": true,
-    "types": ["node"],
+    "types": ["node", "jest"],
   }
 }