🌲 Redwood Logging - Ideas?

dthyresson · August 14, 2020, 3:43pm

Even though “ Redwood Logging” seems like something one would not want to do often in the real-world, when building apps, it needs to be done … so should want to try to do it well.

Was hoping to collect from the community a list features, use cases, requirements, wishes, ideas for what people would want logging in Redwood to be.

I’ll start off – but need your input – and then will collect the list and can scope and prioritize.

Logging

Break down into tools (possible logging frameworks/libraries), features (what they can do/offer), what in RW you’d like to see logged out-of-box (prisma queries, auth errors, cell error states etc) and intangibles anything noteworthy.

Tools

Features

Performant (fast, low footprint, small size)
Multiple log levels that can be configured per side and/or package
Well structured detailed output (not just a message, but data that can be saved to sent to another service)
Visual indication of log message types (colors, icons/emoji)
Can be sent to other services (maybe logre.io or Papertrail etc)
Can hide/obfuscate sensitive data (like auth tokens or passwords) aka “redaction”
Ease if integration in all sides (web/api/other)

Redwood Logs

Prisma logs (Expose a logger interface · Issue #2204 · prisma/prisma · GitHub)
Auth errors (user and role)
Cell lifecycle

Intangibles

Pino is a too, And it has a tool called pino-colada

Commonly used (weekly npm dl’s)

Let’s make a great list to help evaluate what the DX for logging in Redwood can be!

dthyresson · August 14, 2020, 3:45pm

I forgot to add:

@BrunoQuaresma Be great to have your experience and input. I’ve signed up for logre.io but not yet used. Maybe together RW can help!

BrunoQuaresma · August 15, 2020, 1:42am

Hey, did you try to use the apollo plugin?

peterp · August 17, 2020, 3:32pm

Do we make a distinction between “debug/ development time” logs and “production logs?” And is that desirable?

As an example: I’m developing a new app and I’m adding user-authentication. Is it helpful for me to see “debug type” information during development of what Redwood’s doing internally?

As an example, this is what we might see when inspecting “auth logs”

yarn rw logs | grep [rw-auth]
[rw-auth/auth] provider (auth0) has token.
[rw-auth/auth] fetching current user... <token>
[rw-auth/api] calling src/lib/auth.js#getCurrentUser, returning:
[rw-auth/api] { username: 'peterp', role: 'admin' }
[rw-auth/auth] received current user
[rw-auth/auth] { username: 'peterp', role: 'admin' }
[rw-auth/auth] setState: { isAuthenticated: true }

Here’s an example of what it might look like when inspecting “graphql logs”

yarn rw logs | grep [rw-graphql]
[rw-graphql/web] Cell (src/components/BlogPostsCell)
[rw-graphql/web] Query:
[rw-graphql/web] Query Q { blogPosts { id } } 
[rw-graphql/api/] Fieldname (blogPosts) (src/graphql/blogPost.sdl.ts) 
[rw-graphql/api/service] -> Service (src/services/blogPost.ts#blogPosts)
[rw-graphql/api/service] Return response:
[rw-graphql/api/service] [ { id: 123 }, { id: 456 }]

I know these are verbose, but I think they might be helpful, especially if they’re only emitted during development and we come up with a structure that allows people to filter them.

dthyresson · February 28, 2021, 3:58pm

FYI I have started work on a PoC using pino as the default logger.

I hope to have a PR Draft for review shortly.

While this issue is from December

it still represents the current PoC thinking (minus a few minor things).

Thoughts much appreciated.

adriatic · February 28, 2021, 6:09pm

I wanted to respond before checking pino, so I do not forget to mention https://logrocket.com/ . Eons ago, I wrote something very similar to LogRocket and it saved my life, when I was supporting my Editor. Any problem ended with a crash was trivial to debug - as I could replay that log and walk to problem moving forward (instead of walking back as it is the case with today’s debugger)

dthyresson · February 28, 2021, 7:23pm

Just to clarify the scope and objectives @adriatic this effort is to help with serverless api logging – not browser-side user tracking or exception reporting. Those are very important features to once apps go to production and need monitoring, but for this I was looking for a solid logging library that solved some main problems when in serverless, namely your logs “don’t go anywhere”/ephemeral and are not formatted nicely. Vercel does support log drains but you still need a library to log your messages (warnings, errors, etc).

When logging via console in Netlify or Vercel in your api, these logs are ephemeral. There isn’t a good way to just log certain level events (like warns or errors but not trace or infos).

log levels (log just warn and above in prod)
redaction (hide pwds or tokens)
easy to read output (both in dev and up in cloud)
support logging to external services (logFlare or Datadog or Papertrail etc) but service-agnostic (ie, you can chose your logging service if you want it persisted and searchable)
Here’s a list of pino supported transports but note that not all can work in serverless
etc

Bugsnag, LogRocket are also useful on the api side, but really helpful on the web/browser side to monitor user interaction and errors.

Even with the api side logging, you can still setup LogRocket on a per project basis. But I can see Redwood offering cookbooks or setups with some opinionated choices in the future.

Definitely is helpful to know which of these is most wanted.

BTW - LogRocket recently wrote about Pino:

Tobbe · February 28, 2021, 7:55pm

This is sorely needed. Thanks for working on it DT! Looking forward to getting some better insight into my lambdas

adriatic · February 28, 2021, 8:08pm

Thanks for the explanation about the context for your research, David. This is clearly an important aspect:

You may get by using console.log in hobby projects. In production-grade Node.js applications, however, it’s often useful to be able to distinguish between different log levels.

My current focus is to finish the article described in Windows Dev and Setup: Recommendations and Best Practices by writing sections on debugging tools (VSCode and browser resident development tools), so for some time, I am searching for a sample to be used as a model. I finally settled on the Redwood Tutorial and as Murphy’s law would predict run into a real bug (mine, not Tutorial’s) that I wanted to solve by using LogRocket (out of curiosity, not desperation )

I wrote the above paragraph to point out the great timing of your post.

adriatic · February 28, 2021, 8:39pm

Once discussing the concept of logging as a tool to detect otherwise difficult to find bugs, did anyone think about logging as a means to automate the application development? The idea is simple: the current development consists of the following steps (as documented in the tutorial doc)

Run yarn create redwood-app
Run several generators
Edit manually some of the generated files
…

My problem with this approach is in its unidirectional characteristics (from beginning to end). So, if I mess something up after step 21 dependent on the size of the problem, I have to start from scratch (unless I am so experienced to address the problem directly). If however, all these steps are sufficiently described in the log that is being created as I type, I could simply grab my Log player tool and run the whole development work up to the point where I made a bubbu.

This could significantly improve the tool development process, make it more reliable and enable the library of such logs (scripts) as a replacement for application skeletons and more. One can view this as a very primitive docker

dthyresson · March 1, 2021, 12:13am

@adriatic this sounds like a separate concept from this current topic which is a Logging Library for RedwoodJS.

If so, could you create a new topic so one might discuss this there?

It sounds like you are suggesting either:

bundling a series of setups and generators into a “recipe” that creates a RedwoodJS with a set of features, ie “Create a new app with Auth0, TailwindCss, Netlify Deployment, logFlare logging” in one go; or,
some sort of VCR-like recording and replay of your yarn rw commands that you can record, rollback or replay?

If that the case, I’ll move this post into that new topic.

adriatic · March 1, 2021, 1:07am

First, my apologies for mixing this idea with your theme. My excuse was to use your context for my question; likely I did not feel whether this idea was too “radical”, so wanted to see your reaction.

As far as my meaning goes, I prefer your interpretation stated as

as I meant to use the logging “script” as a side effect of the current app development process, not to “raise” the programming level to the scripting process. However, if done right, it could be used to create the application “beginnings” way further than yarn create redwood-app, in addition to the customer problem reports as the best method of reproducing the problem.

jvanbaarsen · March 5, 2021, 1:33pm

@dthyresson This would be super helpful to have, debugging API side is now harder then it should be (Coming from a Rails background).

Is this something you can use help with? If so let me know!

dthyresson · March 5, 2021, 8:51pm

Yup. So

  logger.debug(
    { some: 'object' },
    'This is my object. There are many like this but this one is mine'
  )

And by default, in dev (because dev will prettyPrint):

api | DEBUG [2021-03-05 20:49:36.319 +0000]: This is my object. There are many like this but this one is mine
api |     log: {
api |       "some": "object"
api |     }

The second is an info for Prisma.

You can

specify pretty or not
log level
redaction, etc.

dthyresson · March 5, 2021, 8:54pm

I’ll put the PR and then to test, test, and feedback.

Some doc writing and review would be helpful since there are many settings and some default rules to explain: you can log to a file, but you can’t do that on Netlify because no filesystem. It warns but needs docs. etc.

Thanks!

dthyresson · March 6, 2021, 5:02pm

The logger PR is up and still Draft, so please try it out and add comments to the PR.

github.com/redwoodjs/redwood

Implement Redwood API side Logger

redwoodjs:main ← dthyresson:dt-logger

opened 04:57PM - 06 Mar 21 UTC

dthyresson

+2721 -1658

Implements api-side logging using the [pino](https://getpino.io/#/) logger. T…his 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: ```js 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 ... ```js 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 ```js 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 ```js 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. ```js /* * 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: ```js 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?

Cheers!

dthyresson · March 19, 2021, 5:12am

Logger is in canary for v0.28!

Feedback, issues, improvements and testing is super welcome! If there are issues, please use GitHub – but questions about setup can go here.

See its README for all the features and setup details and some Quick Start instructions:

To manually upgrade an existing app:

If you are upgrading an existing RedwoodJS app and would like to include logging, you simply need to copy over files from the "Create Redwood Application" template:

* Copy `packages/create-redwood-app/template/api/src/lib/logger.ts` to `api/lib/logger.ts`. Required.

For optional Prisma logging:

* Copy `packages/create-redwood-app/template/api/src/lib/db.ts` to `api/src/lib/db.ts`. Optional.
* Copy `packages/create-redwood-app/template/api/src/lib/prisma.ts` to `api/src/lib/prisma.ts`. Optional.

The first file `logger.ts` defines the logger instance. You will import `logger` and use in your services, functions or other libraries. You may then replace existing `console.log()` statements with `logger.info()` or `logger.debug()`.

The second set of files `db.ts` and `prisma.ts` -- which are optional -- replace how the `db` Prisma client instance is declares and exported. It configures Prisma logging, if desired. See below for more information of Prisma logging options.

Note: if you want Prisma logging, these is a small correction to the README which I have included here (reference to prisma.ts).

Example

Debug logging on. Prisma logging at also at info and query levels.

api | [1616128547061] INFO (49614 on xxxx.local): Fetched a connection from the pool
api |     message: "Fetched a connection from the pool"
api |     target: "quaint::connector::metrics"
api | [1616128547117] DEBUG (49614 on xxxx.local): Query performed in 55 msec
api |     query: "SELECT \"public\".\"Post\".\"id\", \"public\".\"Post\".\"createdAt\", \"public\".\"Post\".\"title\", \"public\".\"Post\".\"body\", \"public\".\"Post\".\"authorId\", \"public\".\"Post\".\"editorId\", \"public\".\"Post\".\"publisherId\", \"public\".\"Post\".\"publishedAt\", \"public\".\"Post\".\"updatedAt\" FROM \"public\".\"Post\" WHERE \"public\".\"Post\".\"id\" = $1 LIMIT $2 OFFSET $3"
api |     params: "[5,1,0]"
api |     duration: 55
api |     target: "quaint::connector::metrics"
api | [1616128547118] DEBUG (49614 on xxxx.local): Fetching post A Forest
api |     payload: {
api |       "id": 5,
api |       "createdAt": "2021-03-18T05:32:39.623Z",
api |       "title": "A Forest",
api |       "body": "I hear her voice \\ Calling my name \\ The sound is deep \\ In the dark \\ I hear her voice \\ And start to run \\ Into the trees \\ Into the trees",
api |       "authorId": null,
api |       "editorId": null,
api |       "publisherId": null,
api |       "publishedAt": "2021-03-18T05:32:39.623Z",
api |       "updatedAt": "2021-03-18T05:32:39.623Z"
api |     }
api | POST /graphql 200 63.958 ms - 342

With Redaction

api | POST /graphql 200 396.269 ms - 2037
api | [1616128547055] TRACE (49614 on xxxx.local): In getCurrentUser
api | [1616128547055] DEBUG (49614 on xxxx.local): Info for user 3e278db4-c0ce-48f9-8c47-c01bbdaae482
api |     exp: 1616130132
api |     sub: "3e278db4-c0ce-48f9-8c47-c01bbdaae482"
api |     email: "[Redacted]"
api |     app_metadata: {
api |       "provider": "email",
api |       "roles": [
api |         "author"
api |       ]
api |     }

Netlify Pretty Print Example in Prod

cjReimer · March 19, 2021, 11:05pm

Awesome, I love it!

Just noticed a typo for anyone else trying this… probably easy for most to figure out, but just in case:
In the manual instructions:

The files need to be moved to the folder: api/src/lib/

dthyresson · March 20, 2021, 12:12pm

Thanks, @cjReimer good catch.

I’ll be pushing a fix for that, a few other docs tweaks, and file logging (that I introduced at the last minute) today.

realStandal · March 20, 2021, 11:56pm

Yay! No more ‘------ can you see this?’ console.logging!

Setup was no trouble at all; I had a few questions after playing around with it for a bit:

Is it expected that any configuration in createLogger overwrites what is set by default? I haven’t tested every option, but by adjusting translateTime to 'yyyy-mm-dd HH:MM:ss' I loose all other prettyPrint options (levelFirst, ignore, …).

Should TypeScript support be considered complete? I’m receiving the following when setting up src/lib/prisma.ts

Where $on is given as:

And is being backed by my rw prisma generated .prisma/client, defined as:

Where U is

(Please excuse my attempt to hand-format the ternary)

It works, Prisma’s logging will be handled by Pino and is configurable for each level-it’s just the typings.

I did receive “prisma:warn Your typescript version is 4.0.7, which is outdated. Please update it to 4.1.0 or newer in order to use Prisma Client.” when running rw prisma generate, not sure if that’s related, figured it’s worth mentioning.

I’ll be more than happy to make the appropriate issue(s) depending on the response