🌲 Redwood Logging - Ideas?

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!

1 Like

Hey, did you try to use the apollo plugin?

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.

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.

1 Like

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)

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:

1 Like

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

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 :wink:)

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

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)

  1. Run yarn create redwood-app
  2. Run several generators
  3. 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

@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.

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.

@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!

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.

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!

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

Cheers!

Logger is in :baby_chick: canary for :crossed_fingers: 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

3 Likes

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/

:slight_smile:

1 Like

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.

1 Like

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:

image

Where U is

image

(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 :smiley:

Thanks @realStandal – This is a huge help and I very much appreciate it!

No - that’s definitely a bug / oversight on my part.

export const defaultLoggerOptions: LoggerOptions = {
  prettyPrint: isPretty && {
    colorize: true,
    ignore: 'hostname,pid',
    levelFirst: true,
    messageFormat: false,
    translateTime: true,
  },

I can see now how the others are getting lost.

I’ll address that. I may have to create a defaultPrettyOptions and then merge in overrides.

Note to me: See DefinitelyTyped/index.d.ts at afdb4fac83531e27b6ba7a13e65e519b87bcaa30 · DefinitelyTyped/DefinitelyTyped · GitHub

I get those warnings too but had not yet figured out how to work around that … but now you’ve given me the answer or at least a direction! Thanks!

Interesting. I’ll look out for that as well. I had not seen that.

If you could, I’d appreciate it – that way I can make sure I don’t miss a step and also create tests for the prettyPrint overrides. Three separate ones would be best for me so I can make discrete PR/commits.

Glad it worked out for you.

Cheers!