Implement Redwood API side Logger

[dthyresson]

Implements api-side logging using the pino logger.

This is an opinionated logger that has some useful default configuration, such as:

• pretty printing in development
• development log level is trace, but production is warn
• supports file system logging, but will warn if string to log to a file in a non-dev environment (need filesystem access)
• support log transports (Datadog, logFlare etc via library of pino tranports)

This feature

• is implemented in @redwood/api/logger
• adds a /src/lib/logger.ts to the CRWA template (lives alongside db.js)

Example /src/lib/logger.ts and use:

import { createLogger, defaultLoggerOptions } from '@redwoodjs/api/logger'

/**
 * Creates a logger. Options define how to log. Destination defines where to log.
 * If no destination, std out.
 */
export const logger = createLogger({
  options: { ...defaultLoggerOptions, level: 'trace' },
  // destination: stream,
})

then ...

import { logger } from 'src/lib/logger'
...
  logger.info(`Saving widget ${widget.id} ${widget.name}`)

  logger.debug(
    { rawData: widget },
    `Widget ${widget.id} ${widget.name} detail`
  )

Please see:

• the defaultLoggerOptions as this is opinonated
• other examples of log config in the CRWA logger template (logging file, log love override, etc).

Still TODO

• Does one need to flush the log? Since may not be done automatically, need to document
• Consider setup commands to create logTransports for datadog ands logFlare etc (probably separate PR)
• Consider making a flavor of the logger that accepts an event and context to be used in functions, including graphql that can add extra details to logger data
• This could be used by graphql

import { logger, serviceLogger } from 'src/lib/logger'
...
export const handler = createGraphQLHandler({
  getCurrentUser,
  context: ({ event, context }) => {
    context.logger = serviceLogger({ event, context }) 
  },

• so that in any service, one can context.logger.debug({model}, 'My message'}

For example, this would auto add the function path to the log info data which could be useful in custom functions

export const serviceLogger = ({ event, _context }) => {
  const _logger = createLogger({
    options: { ...defaultLoggerOptions, level: 'trace' },
  })

  return _logger.child({ function: event?.path })
}

Ideally, I would want to fetch the resolver name and set it.

Some Example Configs for Different Loggers

These examples are in the CRWA logger.ts file.

/*
 * Examples of how to configure and
 * send to log transport streams
/*

/**
 * Override log level
 */
export const logger = createLogger({
  options: { ...defaultLoggerOptions, level: 'warn' },
})

/**
 * Always pretty print
 */
export const logger = createLogger({
  options: { ...defaultLoggerOptions, prettyPrint: 'true' },
})

/**
 * Custom redaction list
 */
import { redactionsList } from '@redwoodjs/api/logger'
export const logger = createLogger({
  options: { ...defaultLoggerOptions, redact: [...redactionsList, 'my_secret_key'] },
})

/**
 * Log to a File
 */
export const logger = createLogger({
  options: { ...defaultLoggerOptions, file: '/path/to/file'},
})

/**
 * Datadog example
 */
import datadog from 'pino-datadog'

/**
 * Creates a pino-logflare stream
 *
 * @param {string} apiKey - Your logFlare API Key
 * @param {string} sourceToken - Your logFlare source token id
 *
 * @typedef {DestinationStream}
 */
export const stream = datadog.createWriteStreamSync({
  apiKey: process.env.DATADOG_API_KEY,
  ddsource: 'my-source-name',
  ddtags: 'tag,not,it',
  service: 'my-service-name',
  size: 1,
})

export const logger = createLogger({
  options: { ...defaultLoggerOptions, destination: stream},
})

/**
 * logFlare Example
 */
import { createWriteStream } from 'pino-logflare'

/**
 * Creates a pino-logflare stream
 *
 * @param {string} apiKey - Your logFlare API Key
 * @param {string} sourceToken - Your logFlare source token id
 *
 * @typedef {DestinationStream}
 */
export const stream = createWriteStream({
  apiKey: process.env.LOGFLARE_API_KEY,
  sourceToken: process.env.LOGFLARE_SOURCE_TOKEN,
})

export const logger = createLogger({
  options: { ...defaultLoggerOptions, destination: stream},
})

Prisma

I'd like to make it easy to log Prisma db output as well.

I'd like to simplify or include this setup:

import { PrismaClient } from '@prisma/client'

import { logger } from './logger'

/* Determines the type and level of logging.
 *
 * See: https://www.prisma.io/docs/reference/api-reference/prisma-client-reference#log
 */
const defaultPrismaLoggerOptions = [
  {
    emit: 'event',
    level: 'query',
  },
  {
    emit: 'event',
    level: 'info',
  },
  {
    emit: 'event',
    level: 'error',
  },
  {
    emit: 'event',
    level: 'warn',
  },
]

export const db = new PrismaClient({
  log: defaultPrismaLoggerOptions,
  errorFormat: 'colorless',
})

/*
 * To use event-based logging:
 * Set emit to event for a specific log level, such as query
 * Use the $on() method to subscribe to the event
 *
 * https://www.prisma.io/docs/concepts/components/prisma-client/working-with-prismaclient/logging
 */

db.$on('query', (queryEvent) => {
  logger.debug(
    { ...queryEvent },
    `${queryEvent.query} in ${queryEvent.duration} msec`
  )
})

db.$on('info', (logEvent) => {
  logger.info({ ...logEvent }, logEvent.message)
})

db.$on('warn', (logEvent) => {
  logger.warn({ ...logEvent }, logEvent.message)
})

db.$on('error', (logEvent) => {
  logger.error({ ...logEvent }, logEvent.message)
})

• declare a prismaLogger?
• define the defaults
• add a method that take the db instance and wires up the events?

[dthyresson]

First main questions:

• Do we want setups for log transports
• Should those be separate PRs? (I think so)
• Needs docs, but code comments are useful to start
• Should these docs me in a README.md ?
• How to make prisma logging easier
• How to make service, function logging easier
• How to add to context via createGraphQLHandler

[jvanbaarsen]

I added a couple of thoughts about the code.

Setting this up in an existing app was a breeze! Only thing that I didn't see work is the Prisma logging, but I believe this is not yet implemented, right?

[dthyresson]

Only thing that I didn't see work is the Prisma logging, but I believe this is not yet implemented, right?

That's correct @jvanbaarsen - I am not sure how best to simplify the setup.

This is my current db.js in an exsiting RW app:

// See https://www.prisma.io/docs/reference/tools-and-interfaces/prisma-client/constructor
// for options.

import { PrismaClient } from '@prisma/client'

import { logger } from './logger'

/* Determines the type and level of logging.
 *
 * See: https://www.prisma.io/docs/reference/api-reference/prisma-client-reference#log
 */
const defaultPrismaLoggerOptions = [
  {
    emit: 'event',
    level: 'query',
  },
  {
    emit: 'event',
    level: 'info',
  },
  {
    emit: 'event',
    level: 'error',
  },
  {
    emit: 'event',
    level: 'warn',
  },
]

export const db = new PrismaClient({
  log: defaultPrismaLoggerOptions,
  errorFormat: 'colorless',
})

/*
 * To use event-based logging:
 * Set emit to event for a specific log level, such as query
 * Use the $on() method to subscribe to the event
 *
 * https://www.prisma.io/docs/concepts/components/prisma-client/working-with-prismaclient/logging
 */

db.$on('query', (queryEvent) => {
  logger.debug(
    { ...queryEvent },
    `${queryEvent.query} in ${queryEvent.duration} msec`
  )
})

db.$on('info', (logEvent) => {
  logger.info({ ...logEvent }, logEvent.message)
})

db.$on('warn', (logEvent) => {
  logger.warn({ ...logEvent }, logEvent.message)
})

db.$on('error', (logEvent) => {
  logger.error({ ...logEvent }, logEvent.message)
})

I'm not sure how best to include this:

• update db.js?
• add a method to take the db instance and add the "on" event handling
• Add a method used when creating the Prisma client that sets up

  errorFormat: 'colorless',```

Maybe something that takes

{ query: Boolean, levels: ['info, 'warn']}

or even options like: `{ query: false, warn: true, error: true}` and constructs the emitter list.

The tricky part is to turn on the custom emitters, the client has to already be created.

[dthyresson]

Setting this up in an existing app was a breeze!

Thanks! That was my goal. The pino logger is easy, but wanted to make the DX somewhat "out-of-the box".

Only thing that I didn't see work is the Prisma logging.

I spent some time this morning and converted my app's db.js to db.ts and now use:

// See https://www.prisma.io/docs/reference/tools-and-interfaces/prisma-client/constructor
// for options.

import { PrismaClient, Prisma } from '@prisma/client'
import { logger } from './logger'

/* Determines the type and level of logging.
 *
 * See: https://www.prisma.io/docs/reference/api-reference/prisma-client-reference#log
 */
const logLevels: Prisma.LogLevel[] = ['info', 'warn', 'error'] // add 'query' in dev?

const prismaLoggerOptions = (
  logLevels: Prisma.LogLevel[]
): Prisma.LogDefinition[] => {
  return logLevels?.map((level) => {
    return { emit: 'event', level } as Prisma.LogDefinition
  })
}

const createPrismaClient = (logLevels: Prisma.LogLevel[]) => {
  const client = new PrismaClient({
    log: prismaLoggerOptions(logLevels),
    errorFormat: 'colorless',
  })

  /*
   * To use event-based logging:
   * Set emit to event for a specific log level, such as query
   * Use the $on() method to subscribe to the event
   *
   * https://www.prisma.io/docs/concepts/components/prisma-client/working-with-prismaclient/logging
   */

  logLevels.forEach((level) => {
    if (level === 'query') {
      client.$on(level, (queryEvent: Prisma.QueryEvent) => {
        logger.debug(
          { ...queryEvent },
          `${queryEvent.query} in ${queryEvent.duration} msec`
        )
      })
    } else {
      client.$on(level, (logEvent: Prisma.LogEvent) => {
        logger.info({ ...logEvent }, logEvent.message)
      })
    }
  })

  return client
}

export const db = createPrismaClient(logLevels)

This still creates the db instance but sets up all the logging in Prisma based on just the level chosen:

const logLevels: Prisma.LogLevel[] = ['info', 'warn', 'error'] // add 'query' in dev?

@jvanbaarsen Can you try this out to see if you like it? If so perhaps change the CRWA db.js template to something like this.

One idea would be to construct:

const logLevels: Prisma.LogLevel[] = ['info', 'warn', 'error'] // add 'query' in dev?

based on the logger's level and silent would be none or [] with an option to add query.

[dthyresson]

db.$on('query', (queryEvent) => {
  logger.debug(
    { ...queryEvent },
    `${queryEvent.query} in ${queryEvent.duration} msec`
  )
})

Actually, what is very cool i that one can warn on slow queries (ie duration over a threshold):

 logLevels.forEach((level) => {
    if (level === 'query') {
      client.$on(level, (queryEvent: Prisma.QueryEvent) => {
        if (queryEvent.duration > 20) {
          logger.warn(
            { ...queryEvent },
            `Slow Query performed in ${queryEvent.duration} msec`
          )
        } else {
          logger.debug(
            { ...queryEvent },
            `Query performed in ${queryEvent.duration} msec`
          )
        }
      })
    } else {
      client.$on(level, (logEvent: Prisma.LogEvent) => {
        logger.info({ ...logEvent }, logEvent.message)
      })
    }
  })

then it appears as:

api | WARN [2021-03-07 14:50:52.691 +0000]: Slow Query performed in 34 msec
api |     log: {
api |       "timestamp": "2021-03-07T14:50:52.690Z",

[dthyresson]

Note: I've added db.ts to this PR to finalize features and suggest an opinionated Prisma client with logging configured.

Moving out of draft.

Subsequent PRs will setup logFlare and dataddog transports.

[jvanbaarsen]

@dthyresson I'll give the Prisma setup a try tomorrow 👍

[peterp]

Maybe we can just leave these as the default in the function itself?

[dthyresson]

I thought about that, but I really like explicitly showing it here because you gives some nice help:

and

which I think help you know what the defaults are and the expected config out-of-the-box.

What do you think, @peterp ? Happy to move though.

[dthyresson]

Ah some typos ... I fix!

[peterp]

You can actually make that part of the type, then it'll be auto-completed and typed checked. I think the comment will also show up.

[peterp]

Would you be OK with making the defaultLoggerOptions part of the function, and using types to document them to the user during design time?

If so, and if you need any guidance to make this happen let me know.

[dthyresson]

@peterp

Would you be OK with making the defaultLoggerOptions part of the function,

I think so.

if you need any guidance to make this happen let me know.

I'm not sure I understand what is needed to do that though.

export const createLogger = ({
  options,
  destination,
  showConfig = isDevelopment,
}: RedwoodLoggerOptions): BaseLogger => {

Include the defaultLoggerOptions always? And then just override with options that are LoggerOptions?

Like

export const createLogger = ({
  options,
  destination,
  showConfig = isDevelopment,
}: RedwoodLoggerOptions): BaseLogger => {

const loggerOptions = { ...defaultLoggerOptions, options }

and then use loggerOptions in the function?

That way you'd declare a logger like:

export const logger = createLogger()

But if you do want to override:

export const logger = createLogger({ options: { level: 'warn' } })

?

[dthyresson]

@peterp and @Tobbe I am rather happy with the state of the logger now.

The only large unresolved question is how to treat logging in test?

• Turn it off ie silent?
• Set it to error?
• Do nothing?

[peterp]

Looking great David, I've left a few notes, questions and suggestions

[peterp]

@dthyresson I know this has now merged, but I was wondering if we could hide most of this implementation?

The reason is I'm worried that Prisma changes the logging interfaces and we have to ship a huge code mod.

Maybe there's a way to internalize configureLogLevels?

[dthyresson]

@peterp

Definitely would like to.

I commented yesterday above:

Can we hide these implementations in the logger library in the api package?

@peterp I didn't know if I wanted to have the api/logger depend on Prisma.

Some deploys won't have Prisma so then would that prevent people from using the logger?

I'm concerned that Prisma changes the format

...

But not sure I can think of an alternative.

But of course when you say:

The reason is I'm worried that Prisma changes the logging interfaces and we have to ship a huge code mod

I definitely want to avoid that scenario.

I am having a hard time visualizing what

if we could hide most of this implementation?

or

internalizing

it might look like?

Can you give me a direction or maybe we jump of a quick call?

I wanted to get logging in so people could give feedback like this and can improve the implementation so can assess if we want to ship the CRWA template changes in w/ v0.28.