#Custom Logger: Cannot read properties of undefined (reading ‘context’) How to debug it?

5 messages · Page 1 of 1 (latest)

grand crow
#

Hi! We see the error of reading context but we don't even have such code, it's somewhere inside NestJs's packages and I have no idea how to debug it and find what can cause it. I'd appreciate any help.
The error track is the next:

    at error (/usr/src/app/node_modules/@nestjs/common/services/logger.service.js:41:31)
    at descriptor.value (/usr/src/app/node_modules/@nestjs/common/services/logger.service.js:165:27)
    at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
    at async Promise.all (index 5)
    at async OnboardingService._OnboardingService_finishOnboarding (/usr/src/app/dist/onboarding/onboarding.service.js:198:5)```

We're using custom logger that we connect like this (file main.ts)

```ts
app.use(
    requestLogger({
      customProps: {...}
    }),
  )```

then we create an instance in a service in constructor like this

```ts
@Injectable()
export class OnboardingService {
  private logger = new Logger(OnboardingService.name)
  // and use it in one of class's methods like this

   ...
  this.logger.log(`[finishOnboarding]`, { uid, onboardingTopics }) // here we see unhandled error sometimes (really rare)
   ...
}```
#

Here the custom logger itself (you cna see we don't read property context in any place):

import type { NextFunction, Response, Request } from 'express'
import moment from 'moment'
import { getHost } from '../utils/utils'
import logger from '../logger/logger'

export function requestLogger(config?: {
    customProps?: Record<string, any>
    contentTypes?: string[]
}) {
    const { customProps = {}, contentTypes = [] } = config || {}

    const _customProps = customProps
    const _contentTypes = [...new Set([...contentTypes, 'application/json'])]

    const disableResponseLogs = process.env.DISABLE_RESPONSE_LOGS

    console.log(
        `DISABLE_RESPONSE_LOGS is ${
            disableResponseLogs
                ? 'set. to disable, unset DISABLE_RESPONSE_LOGS env var'
                : 'unset. to enable, set DISABLE_RESPONSE_LOGS env var'
        }.`,
    )

  ...
}```
#
...
  return (req: Request, res: Response, next: NextFunction) => {
        try {
            if (!_contentTypes.includes(req?.headers?.['content-type'] || ''))
                return next()
            const start = moment(new Date())

            const logMetadata = {
                method: req.method,
                latency: 0,
                responseCode: 0,
                user: req?.user?.email || 'anonymous',
                time: start.toISOString(),
                host: getHost(),
                url: req.path,
                env: process.env.GCLOUD_PROJECT,
                query: JSON.stringify(req.query),
                userAgent: req?.headers?.['user-agent'] || 'unknown',
                ip: req.ip,
                ..._customProps,
            }

            const responseJson = res.json
            res.json = (body: unknown) => {
                logMetadata.latency = moment(new Date()).diff(start)
                logMetadata.responseCode = res.statusCode

                res.json = responseJson

                if (!disableResponseLogs) {
                    logger[logMetadata.responseCode >= 400 ? 'error' : 'info'](
                        JSON.stringify(logMetadata),
                        { ...logMetadata, body: JSON.stringify(req.body) },
                    )
                }

                return res.json(body)
            }
            return next()
        } catch (error) {
            logger.error('[requestLogger] error occured: ', error)
            return next()
        }
    }```
#

Here's logger.ts file:

import * as winston from 'winston'
import { LoggingWinston } from '@google-cloud/logging-winston'

const loggingWinston = new LoggingWinston({ maxEntrySize: 250000 })

const SeverityLookup: { [key: string]: string } = {
    default: 'DEFAULT',
    silly: 'DEFAULT',
    verbose: 'DEBUG',
    debug: 'DEBUG',
    http: 'NOTICE',
    info: 'INFO',
    warn: 'WARNING',
    error: 'ERROR',
}
// Create a Winston logger that streams to Cloud Logging
// Logs will be written to: "projects/YOUR_PROJECT_ID/logs/winston_log"
const stackdriverFormat = winston.format((info: any) => {
    const { level, ...record } = info
    record.severity = SeverityLookup[level] || SeverityLookup.default
    return record
})

const simpleLogs = process.env.SIMPLE_LOGS

console.log(
    `SIMPLE_LOGS is ${
        simpleLogs
            ? 'enabled. to disable, unset SIMPLE_LOGS env var'
            : 'disabled. to enable, set SIMPLE_LOGS env var'
    }.`,
)

const logger = simpleLogs
    ? console
    : winston.createLogger({
          level: 'info',
          transports: [
              new winston.transports.Console({
                  format: winston.format.combine(
                      stackdriverFormat(),
                      winston.format.json(),
                  ),
              }),
              loggingWinston,
          ],
      })

export default logger```
#

I even don't know which exactly logger can cause it, because we have two loggers. Here's another one, which we connect in main.ts like this
consoleLogger(app)

and that's its realization

import util from 'util'
import { Express } from 'express'
import httpContext from 'express-http-context'
import { generate } from 'short-uuid'
import logger from '../logger/logger'

const server = generate()

type Severity = 'INFO' | 'ERROR'

function patchedConsole(severity: Severity) {
    return function (data: any, ...args: any[]) {
        const session = httpContext.get('session') || ''
        const message = util.format(data, ...args)
        const messageMetadata = {
            severity,
            server,
            session,
        }

        const isSimpleLogs = process.env.SIMPLE_LOGS
        switch (severity) {
            case 'INFO':
                isSimpleLogs
                    ? logger.info(message)
                    : logger.info(message, messageMetadata)
                break
            case 'ERROR':
                isSimpleLogs
                    ? logger.error(message)
                    : logger.error(message, messageMetadata)
                break
            default:
                isSimpleLogs
                    ? logger.debug(message)
                    : logger.debug(message, messageMetadata)
                break
        }
    }
}

export function consoleLogger(app: Express) {
    console.log = patchedConsole('INFO')
    console.error = patchedConsole('ERROR')

    app.use(httpContext.middleware)
    app.use((req, res, next) => {
        httpContext.set('session', generate())
        return next()
    })
}```