sainsburys-tech / next-logger

JSON logging patcher for Next.js
MIT License
144 stars 14 forks source link

next standalone breaks next-logger #13

Closed karl-run closed 2 months ago

karl-run commented 2 years ago

In next 12.1, they added support for standalone output, which outputs a minimal standalone folder with everything you need to run the server.

This naturally causes some issues with how next-logger works.

The first issue is that next-logger is omitted from .next/standalone/node_modules. This is pretty hard for next-logger to anything with. But a "hack" is to copy the library over to the standalone output, e.g:

cp -r node_modules/next-logger .next/standalone/node_modules/next-logger

This works fine.

The bigger issue however, is that using the standalone output seems to break how next-logger patches the internal next logger.

Example when running the standalone server (the JSON-output is my own application logging):

NODE_ENV=production NODE_OPTIONS='-r next-logger/presets/next-only' node server.js
{"level":"info","pid":236240,"hostname":"karlx1","name":"next.js","prefix":"info","msg":"Loaded env from /<snip>/.next/standalone/.env.production"}
Listening on port 3000
devinrhode2 commented 2 years ago

Edit: *next 12.1 landed experimental support for standalone

devinrhode2 commented 2 years ago

@karl-run How is the output you gave broken? 2nd line, the json log, seems perfectly correct to me

Is the issue that Listening on port 3000 is not json?

karl-run commented 2 years ago

The second line is from my apps own logging (that uses the same pino config). The Listening on port 3000 and any subsequent errors I trigger are not logged using the pino-config.

karl-run commented 2 years ago

I did a another try, I built a docker image with the bare minimum, and managed to get it working. Not sure what's different now. :smile:

Edit: The difference might be that I switched to using full patching of console.log instead of next-only-preset.

There is a caveat however: The dependency tracing that nextjs does obviously doesn't "see" next-logger, so when building my docker image I have to manually copy all these dependencies to the standalone output folder's node_modules.

Example dockerfile:

FROM node:16-alpine

RUN apk add --no-cache bash

RUN addgroup --system --gid 1069 nodejs
RUN adduser --system --uid 1069 nextjs

ENV NODE_ENV production

WORKDIR /app

COPY --chown=nextjs:nodejs package.json /app/
COPY --chown=nextjs:nodejs next.config.js /app/
COPY --chown=nextjs:nodejs next-logger.config.js /app/
COPY --chown=nextjs:nodejs .next/standalone /app/
COPY --chown=nextjs:nodejs public /app/public/
COPY --chown=nextjs:nodejs node_modules/next-logger /app/node_modules/next-logger
COPY --chown=nextjs:nodejs node_modules/cosmiconfig /app/node_modules/cosmiconfig
COPY --chown=nextjs:nodejs node_modules/parse-json /app/node_modules/parse-json
COPY --chown=nextjs:nodejs node_modules/error-ex /app/node_modules/error-ex
COPY --chown=nextjs:nodejs node_modules/is-arrayish /app/node_modules/is-arrayish
COPY --chown=nextjs:nodejs node_modules/json-parse-even-better-errors /app/node_modules/json-parse-even-better-errors
COPY --chown=nextjs:nodejs node_modules/lines-and-columns /app/node_modules/lines-and-columns
COPY --chown=nextjs:nodejs node_modules/@babel/code-frame /app/node_modules/@babel/code-frame
COPY --chown=nextjs:nodejs node_modules/@babel/highlight /app/node_modules/@babel/highlight
COPY --chown=nextjs:nodejs node_modules/js-tokens /app/node_modules/js-tokens
COPY --chown=nextjs:nodejs node_modules/@babel/helper-validator-identifier /app/node_modules/@babel/helper-validator-identifier
COPY --chown=nextjs:nodejs node_modules/escape-string-regexp /app/node_modules/escape-string-regexp
COPY --chown=nextjs:nodejs node_modules/import-fresh /app/node_modules/import-fresh
COPY --chown=nextjs:nodejs node_modules/parent-module /app/node_modules/parent-module
COPY --chown=nextjs:nodejs node_modules/callsites /app/node_modules/callsites

USER nextjs

EXPOSE 3000

ENV NODE_OPTIONS '-r next-logger'

CMD ["node", "server.js"]

However, this makes the logger work, so at least nothing changes in regards to how the patching that next-logger does works:

> docker run -p 3000:3000 -it $(docker build -q .)
{"level":"info","pid":1,"hostname":"2b25a4af2947","name":"next.js","prefix":"info","msg":"Loaded env from /app/.env.production"}
{"level":"info","pid":1,"hostname":"2b25a4af2947","name":"console","msg":"Listening on port 3000"}
devinrhode2 commented 2 years ago

Actually, a generally more robust way to implement the nextjs patch would be as follows:

  1. Forget it, just patch console methods
  2. Inside console patch, import nextLogger.prefixes
  3. If first argument received to console.foo === matches anything in nextLogger.prefiexes, then we know it's call from next and can switch to the respective logic there.

I actually have a snippet of code for detecting that in my major-ts-based-refactoring branch

Although, goes without saying, ITERATING over nextLogger.prefixes every time anyone calls console.log will not yield the best performance

atkinchris commented 2 years ago

Although, goes without saying, interacting over nextLogger.prefixes every call is expensive

To clarify, next-logger at present only does this iteration once, when the module is loaded.

devinrhode2 commented 2 years ago

I did a another try, I built a docker image with the bare minimum, and managed to get it working. Not sure what's different now. 😄 https://github.com/atkinchris/next-logger/issues/13#issuecomment-1103960738 I think copying over dependencies is fine, potentially best approach.

I wonder if we could "trick" next.js into including our logger node_modules into standalone output. Maybe if next-logger.config.js was inside of src/ folder, and/or maybe if we imported it in the next.config.js. (Of course, we import it, but don't call the exported logger at all)

@karl-run Regarding your setup "suddenly" working, it would 100% be because you included the console.* patch.

The next.js internal log methods SIMPLY call console.* methods. First argument is a colorful string from nextLogger.prefixes object, and then rest of the arguments are plain strings, you can just call args.join(', ')

You can use this debug snippet as a starting point for properly handling the internal next logs hitting console.* methods: https://github.com/atkinchris/next-logger/pull/15/commits/f0268dc72c90814ca3a0c41e8cc15af208e242ef

CleanShot 2022-04-22 at 14 24 33@2x

Commit is from this branch: https://github.com/atkinchris/next-logger/pull/15/commits

devinrhode2 commented 2 years ago

If copying logger node_modules over manually becomes the long-term solution, we should absolutely remove cosmiconfig and just do a normal require of where we expect to find the users next-logger.config.js file.

Removing cosmiconfig will probably remove half the dependencies we see listed in @karl-run's Dockerfile

devinrhode2 commented 2 years ago

I wonder if we could "trick" next.js into including our logger node_modules into standalone output. Maybe if next-logger.config.js was inside of src/ folder, and/or maybe if we imported it in the next.config.js. (Of course, we import it, but don't call the exported logger at all)

====

I think this may be the best long-term solution for patching next logger methods:

  1. If we can monkey-patch next logger methods at top of next.config.js, that would be great. A. If we lose out on a COUPLE of logs, I think that's fine

I don't like the idea of iterating over nextLogger.prefixes every time anyone calls console.*

~Maybe we could force chalk into producing a plain string for all of the nextLogger.prefixes, and then we just don't give any special treatment to nextLogger. (Looking at chalk's type defs here, I'm not seeing anything that may help us convert colorful strings back to plain text. This package color-convert seems to do a lot of heavy lifting in this area, but also doesn't appear to have anything here)~ UPDATE: We can easily remove all ansi escape code stuff with: https://www.npmjs.com/package/strip-ansi (hosted under/created by the "chalk" org, no less!)

====

I mention all this, because if we can simplify how we patch nextLogger methods, it opens doors for a more "normal" solution to this standalone build issue. Maybe we wouldn't have to "trick" next to include our code in the standalone output, because we aren't doing anything very abnormal.

devinrhode2 commented 2 years ago

I'd take a "strict" approach: if we detect nextLogger.prefixes contains ansi escape codes (i.e. nextLogger.prefixes.info !== "info - "), just fail/crash. It's painful, but then the whole life of the server does not actually need to worry about ansi escape codes at all, and, we can basically just completely forget about nextLogger.* methods.

devinrhode2 commented 2 years ago

Might look something like this:

// next.config.js
const { startNextLogger } = require('next-logger')

startNextLogger({
  customLogger: require('next-logger.config.js').logger,
})

The key here is that it feels less like a "framework" and more like a "library". The user calls startNextLogger, instead of next-logger calling require('next-logger.config.js').logger()

When startNextLogger runs, it will: 0: Ensure nextLogger.prefixes is plain text:

const nextLogger = require('next/dist/build/output/log')

if (nextLogger.prefixes.info !== "info - ") {
  throw new Error('nextLogger.prefixes.info contains color codes and is NOT plain text: ' + nextLogger.prefixes.info)
}
  1. Patch console methods:
    require('lib/patches/console')
devinrhode2 commented 2 years ago

@karl-run You could actually try this out pretty easily:

// next.config.js
// 0. Directly check nextLogger.prefixes:
const nextLogger = require('next/dist/build/output/log')

if (nextLogger.prefixes.info !== "info - ") {
  console.warn('nextLogger.prefixes.info contains color codes and is NOT plain text: ' + nextLogger.prefixes.info)
}

require('next-logger/lib/patches/console')
// alternative available in my "major-ts-based-refactoring" branch:
// require('next-logger/lib/patches/strict-console')

When you require the console patch, it will then require your next-logger.config.js file.

The only real difference would be that any logs that happen before next.config.js would not be captured, which, idk, probably nbd?

Hopefully this would "trick" next.js into including all the necessary files without having to manually COPY them!

UPDATE: We could actually run the console patch before next.js with --require next-logger/lib/patches/console AND require the console patch again inside of next.config.js. It should be a no-op when it's required the second time inside of next.config.js. This way startup logs are still captured, and all we are really doing is tricking next into including files in the standalone output.

devinrhode2 commented 2 years ago

In my particular situation, azure applicationinsights likes to be loaded before anything else, so it can monkey patch stuff. So in my particular situation, I would still want to do some sort of --require call, maybe it defines a global, or I just have a 1-line file that does something like this:

// initAppInsights.js
const { initAppInsights } = require('initAppInsights')
initAppInsights()

And then do --require ./initAppInsights.js or whatever.

karl-run commented 2 years ago

@karl-run You could actually try this out pretty easily:

// next.config.js
// 0. Directly check nextLogger.prefixes:
const nextLogger = require('next/dist/build/output/log')

if (nextLogger.prefixes.info !== "info - ") {
  console.warn('nextLogger.prefixes.info contains color codes and is NOT plain text: ' + nextLogger.prefixes.info)
}

require('next-logger/lib/patches/console')
// alternative available in my "major-ts-based-refactoring" branch:
// require('next-logger/lib/patches/strict-console')

I gave it another attempt. I tried what you posted here. It does seem to apply the patch during the build (the build output is the pino logger). But the modules are still missing from .next/standalone/node_modules. :shrug:

devinrhode2 commented 2 years ago

Best bet is to simply override console methods in your main next.config.js. Nothing fancy, at all.

My fork isn't designed for this use case, but if you poke around, you should be able to set this up without writing hardly any code.

Instead of "require'ing" next-logger via the -r command in next start.. you need to require the right console patch inside of next.config.js.

AkshayKumar007 commented 2 years ago

Just wanted to check if there's something other than the standard setup for next-logger for standalone docker deployments as this issue is still open. Like do we need to copy the node_module for the library?

devinrhode2 commented 2 years ago

I'm at a different company, not working with next.js anymore

If you have the opportunity, Sentry has a server+client logging integration. This repo is only concerned with server side logging.

If you are set on using next-logger for some reason.. I've heavily outlined how to get this working by simply patching console.log/warn/error/info/etc

valleywood commented 1 year ago

Any updates on this? It works in standalone mode when copying node_modules as a part of the docker setup but that feels like a hack and not a long term solution 🤔

devinrhode2 commented 1 year ago

I've provided guidance above, you can use my fork for this.

karl-run commented 1 year ago

I migrated a few of my apps to using the standalone output now. What I ended up doing:

In the custom document (_document.tsx)

import 'next-logger'

This will allow the output file tracing process to include next-logger in the standalone output.

And my Dockerfile looks something like this:

FROM gcr.io/distroless/nodejs:18

WORKDIR /app

COPY package.json /app/
COPY next-logger.config.js /app/
COPY .next/standalone /app/
COPY public /app/public/

EXPOSE 3000

ENV NODE_ENV=production
ENV NODE_OPTIONS '-r next-logger'

CMD ["server.js"]
karl-run commented 1 year ago

The above trick doesn't work when you have a fully app-directory'd app.

Simply doing a import 'next-logger' in your app/layout.tsx to "trick" @vercel/nft to copy next-logger fails spectacularly.

./node_modules/cosmiconfig/dist/loaders.js
Critical dependency: the request of a dependency is an expression

Import trace for requested module:
./node_modules/cosmiconfig/dist/loaders.js
./node_modules/cosmiconfig/dist/index.js
./node_modules/next-logger/lib/logger.js
./node_modules/next-logger/lib/patches/next.js
./node_modules/next-logger/presets/all.js
./node_modules/next-logger/index.js
./src/app/layout.tsx

./node_modules/import-fresh/index.js
Critical dependency: the request of a dependency is an expression

Import trace for requested module:
./node_modules/import-fresh/index.js
./node_modules/cosmiconfig/dist/loaders.js
./node_modules/cosmiconfig/dist/index.js
./node_modules/next-logger/lib/logger.js
./node_modules/next-logger/lib/patches/next.js
./node_modules/next-logger/presets/all.js
./node_modules/next-logger/index.js
./src/app/layout.tsx

and:

 Cannot find module '/home/karl/git/syfosmmanuell/next-logger.config.js'
    at webpackEmptyContext (/home/karl/git/syfosmmanuell/.next/server/chunks/28.js:28:10)
    at module.exports (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114780:61)
    at loadJsSync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114506:20)
    at ExplorerSync.loadFileContentSync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114166:20)
    at ExplorerSync.createCosmiconfigResultSync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114173:34)
    at ExplorerSync.loadSearchPlaceSync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114155:21)
    at ExplorerSync.searchDirectorySync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114145:38)
    at run (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114131:33)
    at cacheWrapperSync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114224:20)
    at ExplorerSync.searchFromDirectorySync (/home/karl/git/syfosmmanuell/.next/server/chunks/161.js:114139:55) {
  code: 'MODULE_NOT_FOUND',
  filepath: '/home/karl/git/syfosmmanuell/next-logger.config.js'
}

Even though the file exists. But app dir builds and bundles completely differently. :shrug:

So far I haven't found any good work-around for this. But with the amount of bugs and weird behaviours with the app directory, I won't be going to prod with this any time soon anyway. :smiling_face_with_tear:

karl-run commented 11 months ago

I got this working in app dir as well now.

in your root layout.tsx: import 'next'logger'

:point_up: This will make sure it's part of the standalone output.

Here's the crux, in your next.config.js add this:

experimental: {
   serverComponentsExternalPackages: ['next-logger'],
}

Then next will leave it alone, and simply copy it over to the output node_modules. :+1: Happy logging.

karl-run commented 11 months ago

Example: https://github.com/navikt/syfosmmanuell/pull/183

Disregard any references to @navikt/next-logger, that's just my internal config and isomorphic logger utils.

GAsplund commented 10 months ago

Using @karl-run's solution, I was never able to patch logging unless I specifically re-built a page in dev mode. For my use case, I found a pretty elegant solution for those who are willing to let the first few logs be in a non-JSON format. The following works on Next 13.5.4:

// next.config.js

const nextConfig = {
    // [...]
    experimental: {
      instrumentationHook: true
    }
}

Then, create a file under src (or in the project root) named instrumentation.js (or instrumentation.ts if you wish)

// src/instrumentation.js

export async function register() {
    // Make sure that we don't attempt to patch in the edge runtime
    if (process.env.NEXT_RUNTIME === 'nodejs') {
        await require('pino')
        await require('next-logger')
    }
}

This way, there's also no need to manually specify modules in next.config.js (and in my opinion allows for a marginally higher level of SoC)

schallerala commented 8 months ago

As a follow-up of @GAsplund answer above,

[...] solution for those who are willing to let the first few logs be in a non-JSON format.

Actually doing exactly that, next-logger will be present in the node_modules folder, and you can use the NODE_OPTIONS='-r "next-logger"' env variable or --require when starting the standalone server.

In case you are working in a mono-repo and/or pnpm and hoist dependencies, just make sure that the current working directory is the correct one with the node_modules with the next-logger dependency.

Hope it helps others.

Happy Next.js app deployment 🚀

pixelpax commented 5 months ago

For those using @GAsplund 's solution, it will not capture logs from anything inside of middleware, as middleware is apparently not considered the nodenjs environment. Would love to find a comprehensive solution here, but still haven't found one.

CHC383 commented 3 months ago

Starting from Next 14.2, @GAsplund's solution above won't work in the Next development mode (next dev), the generated Webpack instrumentation code won't include next-logger. Combining @karl-run's solution to add next-logger experimental.serverComponentsExternalPackages in next.config.js solves the problem.

experimental: {
   serverComponentsExternalPackages: ['next-logger'],
}
vncsna commented 3 months ago

Please, could you remove cosmiconfig? As it's really hard to make it work in next.js 12

atkinchris commented 2 months ago

In version v5.0.0 published today with @CHC383's contributions, cosmiconfig has been removed in favour of lilconfig. Can you try this version and see if it solves your issue, please?

CHC383 commented 2 months ago

I have verified that with v5.0.0, we don't need to set next-logger in experimental.serverComponentsExternalPackages as mentioned in https://github.com/sainsburys-tech/next-logger/issues/13#issuecomment-2113625702.

And this issue was originally about using next-logger in the standalone mode, which is resolved by importing the library in the Next instrumentation hook. The README of the library has been updated with the new usage instructions, so I think this issue could be closed.

karl-run commented 2 months ago

Perfect. Our platform recently started supporting automatic instrumentation using OTEL-hooks. This overwrote my NODE_OPTIONS='-r next-logger' causing the log-patching to stop working.

With next-logger@v5 using instrumentation.ts I can have both working together. :)

Here's the commit for reference in case anyone else wants to reference it in the future.

https://github.com/navikt/syk-dig/commit/e504886e0de748f18aca376e68d3a328c93760cc