Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

[Bug?]: Unformatted pino logger outputs when running yarn rw test #11757

Open
1 task done
Philzen opened this issue Dec 8, 2024 · 1 comment
Open
1 task done

[Bug?]: Unformatted pino logger outputs when running yarn rw test #11757

Philzen opened this issue Dec 8, 2024 · 1 comment
Labels
bug/needs-info More information is needed for reproduction

Comments

@Philzen
Copy link
Contributor

Philzen commented Dec 8, 2024

What's not working?

When running the test suite we're seeing a lot of debug outputs such as these:

{"level":50,"time":1733650950679,"pid":193323,"hostname":"my-machine","prisma":{"clientVersion":"5.20.0"},"message":"\nInvalid `.update()` invocation in\n/./api/src/services/interviews/interviews.ts:388:6\n\n  385 // alternatively, use *many-operation: https://github.com/prisma/prisma/discussions/4185\n  386 // ... both have the disadvantage of not returning the initial object\n  387 return db.user\n→ 388   .update(\nThe records for relation `InterviewToUser` between the `User` and `Interview` models are not connected.","target":"user.update","timestamp":"2024-12-08T09:42:30.679Z","msg":"\nInvalid `.update()` invocation in\n./api/src/services/interviews/interviews.ts:388:6\n\n  385 // alternatively, use *many-operation: https://github.com/prisma/prisma/discussions/4185\n  386 // ... both have the disadvantage of not returning the initial object\n  387 return db.user\n→ 388   .update(\nThe records for relation `InterviewToUser` between the `User` and `Interview` models are not connected."}
{"level":30,"time":1733650955451,"pid":193323,"hostname":"my-machine","prisma":{"clientVersion":"5.20.0"},"timestamp":"2024-12-08T09:42:35.451Z","message":"Starting a sqlite pool with 5 connections.","target":"quaint::pooled","msg":"Starting a sqlite pool with 5 connections."}

I tried yarn rw test | yarn rw-log-formatter which i found in the RW docs. It makes these messages being formatted much more nicely. However, it also interacts too heavily with the other output of jest, leading to it's colored output and all other formatting (and also the interaction options, such as keyboard commands) being dropped.

Maybe there's an option for rw-log-formatter to only reformat message objects containing a "level": nn info and leave the rest untouched? Then it would be nice if that could be added by default to redwood's yarn script that starts the test suite.

How do we reproduce the bug?

Good question… currently i'm not really sure what triggers these log messages as i believe they are not in our code-base, but rather coming from prisma directly.

A good start would be to use an sqlite db and watch out for those "Starting a sqlite pool" (sic!) messages.

What's your environment? (If it applies)

System:
    OS: Linux 6.12 Manjaro Linux
    Shell: 5.2.37 - /bin/bash
  Binaries:
    Node: 20.16.0 - /tmp/xfs-699d3109/node
    Yarn: 4.4.0 - /tmp/xfs-699d3109/yarn
  Databases:
    SQLite: 3.47.1 - /usr/bin/sqlite3
  npmPackages:
    @redwoodjs/auth-dbauth-setup: 8.4.1 => 8.4.1 
    @redwoodjs/cli-storybook-vite: 8.4.1 => 8.4.1 
    @redwoodjs/core: 8.4.1 => 8.4.1 
    @redwoodjs/project-config: 8.4.1 => 8.4.1 
  redwood.toml:
    [web]
      title = "Interviewtool"
      sourceMap = true
      port = 8910
      apiUrl = "/.redwood/functions" # you can customise graphql and dbauth urls individually too: see https://redwoodjs.com/docs/app-configuration-redwood-toml#api-paths
      includeEnvironmentVariables = ['LIVEKIT_URL', 'LIVEKIT_REC_DOWNLOAD_URL', 'FAQ_URL', 'MANUAL_URL', 'RELEASE_NOTES_URL'] # any ENV vars that should be available to the web side, see https://redwoodjs.com/docs/environment-variables#web
      # host = "0.0.0.0"  # listen to all interfaces – for local network testing purposes only
    [api]
      port = 8911
      debugPort = 18911 # https://redwoodjs.com/docs/project-configuration-dev-test-build#customizing-the-debug-port
      # host = "0.0.0.0"  # listen to all interfaces – for local network testing purposes only
    [browser]
      open = false

Are you interested in working on this?

  • I'm interested in working on this
@Philzen Philzen added the bug/needs-info More information is needed for reproduction label Dec 8, 2024
@Philzen Philzen changed the title [Bug?]: Unformatted debug log outputs when running yarn rw test [Bug?]: Unformatted pino logger outputs when running yarn rw test Jan 6, 2025
@Philzen
Copy link
Contributor Author

Philzen commented Jan 6, 2025

As a thought – is pino logger output actually useful when running jest or merely a general disturbance (following the comment here)? Then a different approach could be to disable / suppress pino's output completely when starting jest.

Otherwise, attaching some reference here that deals with the known issue of pretty-printing pino's output in jest without ruining jest's colouring:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug/needs-info More information is needed for reproduction
Projects
None yet
Development

No branches or pull requests

1 participant