feat(logger): simplify logger API (#2344)

Similar to #2342, this aims to unify the user-facing API and provide an easier way to extend in the future. In addition, this PR also solves the problem when the `logger.error` method sometimes did not print results, because `Error` instances are not serializable and will be printed as empty objects `"{}"`. After this PR, we make any `Error` instances serializable as described here: https://iaincollins.medium.com/error-handling-in-javascript-a6172ccdf9af Closes #1602 Achieved by adding a `client: true` flag when logs are coming from the frontend. BREAKING CHANGE: The main change is that instead of an unknown number of parameters, the log events have at most two, where the second parameter is usually an object. In the case of the `error` event, it can also be an `Error` instance (that is serializable by `JSON.stringify`). If it is an object, an `Error` instance will be available on `metadata.error`, and `message` will default to `metadata.error.message`. This is done so that an error event always provides some kind of a stack to see where the error happened ```diff // [...nextauth.js] import log from "some-logger-service" ... logger: { - error(code, ...message) {}, + error(code, metadata) {}, - warn(code, ...message) {}, + warn(code) {} - debug(code, ...message) {} + debug(code, metadata) {} } ```
nextauthjs · Jul 11, 2021 · acc9393 · acc9393
1 parent 6911dd9
commit acc9393
Show file tree

Hide file tree

Showing 16 changed files with 121 additions and 174 deletions.
diff --git a/src/client/__tests__/csrf.test.js b/src/client/__tests__/csrf.test.js
@@ -78,11 +78,10 @@ test("when the fetch fails it'll throw a client fetch error", async () => {
 
   await waitFor(() => {
     expect(logger.error).toHaveBeenCalledTimes(1)
-    expect(logger.error).toBeCalledWith(
-      "CLIENT_FETCH_ERROR",
-      "csrf",
-      new SyntaxError("Unexpected token s in JSON at position 0")
-    )
+    expect(logger.error).toBeCalledWith("CLIENT_FETCH_ERROR", {
+      path: "csrf",
+      error: new SyntaxError("Unexpected token s in JSON at position 0"),
+    })
   })
 })
 

diff --git a/src/client/__tests__/providers.test.js b/src/client/__tests__/providers.test.js
@@ -56,11 +56,10 @@ test("when failing to fetch the providers, it'll log the error", async () => {
 
   await waitFor(() => {
     expect(logger.error).toHaveBeenCalledTimes(1)
-    expect(logger.error).toBeCalledWith(
-      "CLIENT_FETCH_ERROR",
-      "providers",
-      new SyntaxError("Unexpected token s in JSON at position 0")
-    )
+    expect(logger.error).toBeCalledWith("CLIENT_FETCH_ERROR", {
+      path: "providers",
+      error: new SyntaxError("Unexpected token s in JSON at position 0"),
+    })
   })
 })
 

diff --git a/src/client/__tests__/session.test.js b/src/client/__tests__/session.test.js
@@ -70,11 +70,10 @@ test("if there's an error fetching the session, it should log it", async () => {
 
   await waitFor(() => {
     expect(logger.error).toHaveBeenCalledTimes(1)
-    expect(logger.error).toBeCalledWith(
-      "CLIENT_FETCH_ERROR",
-      "session",
-      new SyntaxError("Unexpected token S in JSON at position 0")
-    )
+    expect(logger.error).toBeCalledWith("CLIENT_FETCH_ERROR", {
+      path: "session",
+      error: new SyntaxError("Unexpected token S in JSON at position 0"),
+    })
   })
 })
 

diff --git a/src/client/__tests__/sign-in.test.js b/src/client/__tests__/sign-in.test.js
@@ -250,11 +250,10 @@ test("when it fails to fetch the providers, it redirected back to signin page",
     expect(window.location.replace).toHaveBeenCalledWith(`/api/auth/error`)
 
     expect(logger.error).toHaveBeenCalledTimes(1)
-    expect(logger.error).toBeCalledWith(
-      "CLIENT_FETCH_ERROR",
-      "providers",
-      errorMsg
-    )
+    expect(logger.error).toBeCalledWith("CLIENT_FETCH_ERROR", {
+      error: "Error when retrieving providers",
+      path: "providers",
+    })
   })
 })
 

diff --git a/src/client/react.js b/src/client/react.js
@@ -320,25 +320,23 @@ export function SessionProvider(props) {
  */
 async function _fetchData(path, { ctx, req = ctx?.req } = {}) {
   try {
-    const baseUrl = await _apiBaseUrl()
     const options = req ? { headers: { cookie: req.headers.cookie } } : {}
-    const res = await fetch(`${baseUrl}/${path}`, options)
+    const res = await fetch(`${_apiBaseUrl()}/${path}`, options)
     const data = await res.json()
     if (!res.ok) throw data
     return Object.keys(data).length > 0 ? data : null // Return null if data empty
   } catch (error) {
-    logger.error("CLIENT_FETCH_ERROR", path, error)
+    logger.error("CLIENT_FETCH_ERROR", {
+      error,
+      path,
+      ...(req ? { header: req.headers } : {}),
+    })
     return null
   }
 }
 
 function _apiBaseUrl() {
   if (typeof window === "undefined") {
-    // NEXTAUTH_URL should always be set explicitly to support server side calls - log warning if not set
-    if (!process.env.NEXTAUTH_URL) {
-      logger.warn("NEXTAUTH_URL", "NEXTAUTH_URL environment variable not set")
-    }
-
     // Return absolute path when called server side
     return `${__NEXTAUTH.baseUrlServer}${__NEXTAUTH.basePathServer}`
   }

diff --git a/src/lib/errors.js b/src/lib/errors.js
@@ -32,67 +32,3 @@ export class OAuthCallbackError extends UnknownError {
 export class AccountNotLinkedError extends UnknownError {
   name = "AccountNotLinkedError"
 }
-
-export class CreateUserError extends UnknownError {
-  name = "CreateUserError"
-}
-
-export class GetUserError extends UnknownError {
-  name = "GetUserError"
-}
-
-export class GetUserByEmailError extends UnknownError {
-  name = "GetUserByEmailError"
-}
-
-export class GetUserByIdError extends UnknownError {
-  name = "GetUserByIdError"
-}
-
-export class GetUserByProviderAccountIdError extends UnknownError {
-  name = "GetUserByProviderAccountIdError"
-}
-
-export class UpdateUserError extends UnknownError {
-  name = "UpdateUserError"
-}
-
-export class DeleteUserError extends UnknownError {
-  name = "DeleteUserError"
-}
-
-export class LinkAccountError extends UnknownError {
-  name = "LinkAccountError"
-}
-
-export class UnlinkAccountError extends UnknownError {
-  name = "UnlinkAccountError"
-}
-
-export class CreateSessionError extends UnknownError {
-  name = "CreateSessionError"
-}
-
-export class GetSessionError extends UnknownError {
-  name = "GetSessionError"
-}
-
-export class UpdateSessionError extends UnknownError {
-  name = "UpdateSessionError"
-}
-
-export class DeleteSessionError extends UnknownError {
-  name = "DeleteSessionError"
-}
-
-export class CreateVerificationRequestError extends UnknownError {
-  name = "CreateVerificationRequestError"
-}
-
-export class GetVerificationRequestError extends UnknownError {
-  name = "GetVerificationRequestError"
-}
-
-export class DeleteVerificationRequestError extends UnknownError {
-  name = "DeleteVerificationRequestError"
-}
diff --git a/src/lib/logger.js b/src/lib/logger.js
@@ -1,22 +1,37 @@
+import { UnknownError } from "./errors"
+
+/** Makes sure that error is always serializable */
+function formatError(o) {
+  if (o instanceof Error && !(o instanceof UnknownError)) {
+    return { message: o.message, stack: o.stack, name: o.name }
+  }
+  if (o?.error) {
+    o.error = formatError(o.error)
+    o.message = o.message ?? o.error.message
+  }
+  return o
+}
+
 /** @type {import("types").LoggerInstance} */
 const _logger = {
-  error(code, ...message) {
+  error(code, metadata) {
+    metadata = formatError(metadata)
     console.error(
       `[next-auth][error][${code.toLowerCase()}]`,
       `\nhttps://next-auth.js.org/errors#${code.toLowerCase()}`,
-      ...message
+      metadata.message,
+      metadata
     )
   },
-  warn(code, ...message) {
+  warn(code) {
     console.warn(
       `[next-auth][warn][${code.toLowerCase()}]`,
-      `\nhttps://next-auth.js.org/warnings#${code.toLowerCase()}`,
-      ...message
+      `\nhttps://next-auth.js.org/warnings#${code.toLowerCase()}`
     )
   },
-  debug(code, ...message) {
+  debug(code, metadata) {
     if (!process?.env?._NEXTAUTH_DEBUG) return
-    console.log(`[next-auth][debug][${code.toLowerCase()}]`, ...message)
+    console.log(`[next-auth][debug][${code.toLowerCase()}]`, metadata)
   },
 }
 
@@ -47,31 +62,19 @@ export function proxyLogger(logger = _logger, basePath) {
 
     const clientLogger = {}
     for (const level in logger) {
-      clientLogger[level] = (code, ...message) => {
-        _logger[level](code, ...message) // Log on client as usual
+      clientLogger[level] = (code, metadata) => {
+        _logger[level](code, metadata) // Logs to console
 
+        if (level === "error") {
+          metadata = formatError(metadata)
+        }
+        metadata.client = true
         const url = `${basePath}/_log`
-        const body = new URLSearchParams({
-          level,
-          code,
-          message: JSON.stringify(
-            message.map((m) => {
-              if (m instanceof Error) {
-                // Serializing errors: https://iaincollins.medium.com/error-handling-in-javascript-a6172ccdf9af
-                return { name: m.name, message: m.message, stack: m.stack }
-              }
-              return m
-            })
-          ),
-        })
+        const body = new URLSearchParams({ level, code, ...metadata })
         if (navigator.sendBeacon) {
           return navigator.sendBeacon(url, body)
         }
-        return fetch(url, {
-          method: "POST",
-          headers: { "Content-Type": "application/json" },
-          body,
-        })
+        return fetch(url, { method: "POST", body, keepalive: true })
       }
     }
     return clientLogger

diff --git a/src/server/index.js b/src/server/index.js
@@ -17,7 +17,7 @@ import * as state from "./lib/oauth/state-handler"
 // To work properly in production with OAuth providers the NEXTAUTH_URL
 // environment variable must be set.
 if (!process.env.NEXTAUTH_URL) {
-  logger.warn("NEXTAUTH_URL", "NEXTAUTH_URL environment variable not set")
+  logger.warn("NEXTAUTH_URL")
 }
 
 /**
@@ -43,11 +43,11 @@ async function NextAuthHandler(req, res, userOptions) {
     extendRes(req, res, resolve)
 
     if (!req.query.nextauth) {
-      const error =
+      const message =
         "Cannot find [...nextauth].js in pages/api/auth. Make sure the filename is written correctly."
 
-      logger.error("MISSING_NEXTAUTH_API_ROUTE_ERROR", error)
-      return res.status(500).end(`Error: ${error}`)
+      logger.error("MISSING_NEXTAUTH_API_ROUTE_ERROR", new Error(message))
+      return res.status(500).end(`Error: ${message}`)
     }
 
     const {
@@ -244,13 +244,8 @@ async function NextAuthHandler(req, res, userOptions) {
         case "_log":
           if (userOptions.logger) {
             try {
-              const {
-                code = "CLIENT_ERROR",
-                level = "error",
-                message = "[]",
-              } = req.body
-
-              logger[level](code, ...JSON.parse(message))
+              const { code, level, ...metadata } = req.body
+              logger[level](code, metadata)
             } catch (error) {
               // If logging itself failed...
               logger.error("LOGGER_ERROR", error)

diff --git a/src/server/lib/oauth/callback.js b/src/server/lib/oauth/callback.js
@@ -23,13 +23,12 @@ export default async function oAuthCallback(req) {
         code = body.code
         user = body.user != null ? JSON.parse(body.user) : null
       } catch (error) {
-        logger.error(
-          "OAUTH_CALLBACK_HANDLER_ERROR",
+        logger.error("OAUTH_CALLBACK_HANDLER_ERROR", {
           error,
-          req.body,
-          provider.id,
-          code
-        )
+          body: req.body,
+          providerId: provider.id,
+          code,
+        })
         throw error
       }
     }
@@ -62,7 +61,11 @@ export default async function oAuthCallback(req) {
 
       return getProfile({ profileData, provider, tokens, user })
     } catch (error) {
-      logger.error("OAUTH_GET_ACCESS_TOKEN_ERROR", error, provider.id, code)
+      logger.error("OAUTH_GET_ACCESS_TOKEN_ERROR", {
+        error,
+        providerId: provider.id,
+        code,
+      })
       throw error
     }
   }
@@ -74,7 +77,11 @@ export default async function oAuthCallback(req) {
 
     // eslint-disable-next-line camelcase
     const { token_secret } = await client.getOAuthRequestToken(provider.params)
-    const tokens = await client.getOAuthAccessToken(oauth_token, token_secret, oauth_verifier)
+    const tokens = await client.getOAuthAccessToken(
+      oauth_token,
+      token_secret,
+      oauth_verifier
+    )
     const profileData = await client.get(
       provider.profileUrl,
       tokens.oauth_token,
@@ -113,7 +120,7 @@ export default async function oAuthCallback(req) {
 async function getProfile({ profileData, tokens, provider, user }) {
   try {
     // Convert profileData into an object if it's a string
-    if (typeof profileData === "string" || profileData instanceof String) {
+    if (typeof profileData === "string") {
       profileData = JSON.parse(profileData)
     }
 
@@ -122,7 +129,7 @@ async function getProfile({ profileData, tokens, provider, user }) {
       profileData.user = user
     }
 
-    logger.debug("PROFILE_DATA", profileData)
+    logger.debug("PROFILE_DATA", { profile: profileData })
 
     const profile = await provider.profile(profileData, tokens)
     // Return profile, raw profile and auth provider details
@@ -139,15 +146,15 @@ async function getProfile({ profileData, tokens, provider, user }) {
       },
       OAuthProfile: profileData,
     }
-  } catch (exception) {
+  } catch (error) {
     // If we didn't get a response either there was a problem with the provider
     // response *or* the user cancelled the action with the provider.
     //
     // Unfortuately, we can't tell which - at least not in a way that works for
     // all providers, so we return an empty object; the user should then be
     // redirected back to the sign up page. We log the error to help developers
     // who might be trying to debug this when configuring a new provider.
-    logger.error("OAUTH_PARSE_PROFILE_ERROR", exception, profileData)
+    logger.error("OAUTH_PARSE_PROFILE_ERROR", { error, profileData })
     return {
       profile: null,
       account: null,

diff --git a/src/server/lib/oauth/client.js b/src/server/lib/oauth/client.js
@@ -188,7 +188,11 @@ async function getOAuth2AccessToken(code, provider, codeVerifier) {
       null,
       (error, data, response) => {
         if (error) {
-          logger.error("OAUTH_GET_ACCESS_TOKEN_ERROR", error, data, response)
+          logger.error("OAUTH_GET_ACCESS_TOKEN_ERROR", {
+            error,
+            data,
+            response,
+          })
           return reject(error)
         }