Merge pull request #9669 from Budibase/budi-6558-configurable-test-log-levels-and-common

Configurable test log levels and common error handling

packages/backend-core/src/environment.ts

@@ -83,6 +83,7 @@ const environment = {
   SESSION_UPDATE_PERIOD: process.env.SESSION_UPDATE_PERIOD,
   DEPLOYMENT_ENVIRONMENT:
     process.env.DEPLOYMENT_ENVIRONMENT || "docker-compose",
+  LOG_4XX: process.env.LOG_4XX,
   _set(key: any, value: any) {
     process.env[key] = value
     // @ts-ignore

packages/backend-core/src/middleware/errorHandling.ts

@@ -0,0 +1,28 @@
+import { APIError } from "@budibase/types"
+import * as errors from "../errors"
+import env from "../environment"
+
+export async function errorHandling(ctx: any, next: any) {
+  try {
+    await next()
+  } catch (err: any) {
+    const status = err.status || err.statusCode || 500
+    ctx.status = status
+
+    if (status > 499 || env.LOG_4XX) {
+      ctx.log.error(err)
+    }
+
+    const error = errors.getPublicError(err)
+    const body: APIError = {
+      message: err.message,
+      status: status,
+      validationErrors: err.validation,
+      error,
+    }
+
+    ctx.body = body
+  }
+}
+
+export default errorHandling

packages/backend-core/src/middleware/index.ts

@@ -1,7 +1,7 @@
 export * as jwt from "./passport/jwt"
 export * as local from "./passport/local"
-export * as google from "./passport/google"
+export * as google from "./passport/sso/google"
-export * as oidc from "./passport/oidc"
+export * as oidc from "./passport/sso/oidc"
 import * as datasourceGoogle from "./passport/datasource/google"
 export const datasource = {
   google: datasourceGoogle,
@@ -16,4 +16,5 @@ export { default as adminOnly } from "./adminOnly"
 export { default as builderOrAdmin } from "./builderOrAdmin"
 export { default as builderOnly } from "./builderOnly"
 export { default as logging } from "./logging"
+export { default as errorHandling } from "./errorHandling"
 export * as joiValidator from "./joi-validator"

packages/backend-core/tests/jestEnv.ts

@@ -1,23 +1,5 @@
-import env from "../src/environment"
+process.env.SELF_HOSTED = "1"
-import { mocks } from "./utilities"
+process.env.MULTI_TENANCY = "1"
-
+process.env.NODE_ENV = "jest"
-// must explicitly enable fetch mock
+process.env.MOCK_REDIS = "1"
-mocks.fetch.enable()
+process.env.LOG_LEVEL = process.env.LOG_LEVEL || "error"
-
-// mock all dates to 2020-01-01T00:00:00.000Z
-// use tk.reset() to use real dates in individual tests
-import tk from "timekeeper"
-tk.freeze(mocks.date.MOCK_DATE)
-
-env._set("SELF_HOSTED", "1")
-env._set("NODE_ENV", "jest")
-
-if (!process.env.DEBUG) {
-  global.console.log = jest.fn() // console.log are ignored in tests
-}
-
-if (!process.env.CI) {
-  // set a longer timeout in dev for debugging
-  // 100 seconds
-  jest.setTimeout(100000)
-}

packages/backend-core/tests/jestSetup.ts

@@ -1,4 +1,23 @@
+import "./logging"
 import env from "../src/environment"
-import { testContainerUtils } from "./utilities"
+import { mocks, testContainerUtils } from "./utilities"
+
+// must explicitly enable fetch mock
+mocks.fetch.enable()
+
+// mock all dates to 2020-01-01T00:00:00.000Z
+// use tk.reset() to use real dates in individual tests
+import tk from "timekeeper"
+tk.freeze(mocks.date.MOCK_DATE)
+
+if (!process.env.DEBUG) {
+  console.log = jest.fn() // console.log are ignored in tests
+}
+
+if (!process.env.CI) {
+  // set a longer timeout in dev for debugging
+  // 100 seconds
+  jest.setTimeout(100000)
+}
 
 testContainerUtils.setupEnv(env)

packages/backend-core/tests/logging.ts

@@ -0,0 +1,34 @@
+export enum LogLevel {
+  TRACE = "trace",
+  DEBUG = "debug",
+  INFO = "info",
+  WARN = "warn",
+  ERROR = "error",
+}
+
+const LOG_INDEX: { [key in LogLevel]: number } = {
+  [LogLevel.TRACE]: 1,
+  [LogLevel.DEBUG]: 2,
+  [LogLevel.INFO]: 3,
+  [LogLevel.WARN]: 4,
+  [LogLevel.ERROR]: 5,
+}
+
+const setIndex = LOG_INDEX[process.env.LOG_LEVEL as LogLevel]
+
+if (setIndex > LOG_INDEX.trace) {
+  global.console.trace = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.debug) {
+  global.console.debug = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.info) {
+  global.console.info = jest.fn()
+  global.console.log = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.warn) {
+  global.console.warn = jest.fn()
+}

packages/server/src/api/index.ts

@@ -1,5 +1,5 @@
 import Router from "@koa/router"
-import { errors, auth } from "@budibase/backend-core"
+import { auth, middleware } from "@budibase/backend-core"
 import currentApp from "../middleware/currentapp"
 import zlib from "zlib"
 import { mainRoutes, staticRoutes, publicRoutes } from "./routes"
@@ -14,6 +14,8 @@ export const router: Router = new Router()
 router.get("/health", ctx => (ctx.status = 200))
 router.get("/version", ctx => (ctx.body = pkg.version))
 
+router.use(middleware.errorHandling)
+
 router
   .use(
     compress({
@@ -54,27 +56,6 @@ router
   .use(currentApp)
   .use(auth.auditLog)
 
-// error handling middleware
-router.use(async (ctx, next) => {
-  try {
-    await next()
-  } catch (err: any) {
-    ctx.status = err.status || err.statusCode || 500
-    const error = errors.getPublicError(err)
-    ctx.body = {
-      message: err.message,
-      status: ctx.status,
-      validationErrors: err.validation,
-      error,
-    }
-    ctx.log.error(err)
-    // unauthorised errors don't provide a useful trace
-    if (!env.isTest()) {
-      console.trace(err)
-    }
-  }
-})
-
 // authenticated routes
 for (let route of mainRoutes) {
   router.use(route.routes())

packages/server/src/tests/jestEnv.ts

@@ -1,9 +1,9 @@
-import env from "../environment"
 import { tmpdir } from "os"
 
-env._set("SELF_HOSTED", "1")
+process.env.SELF_HOSTED = "1"
-env._set("NODE_ENV", "jest")
+process.env.NODE_ENV = "jest"
-env._set("MULTI_TENANCY", "1")
+process.env.MULTI_TENANCY = "1"
 // @ts-ignore
-env._set("BUDIBASE_DIR", tmpdir("budibase-unittests"))
+process.env.BUDIBASE_DIR = tmpdir("budibase-unittests")
-env._set("LOG_LEVEL", "silent")
+process.env.LOG_LEVEL = process.env.LOG_LEVEL || "error"
+process.env.MOCK_REDIS = "1"

packages/server/src/tests/jestSetup.ts

@@ -1,3 +1,4 @@
+import "./logging"
 import env from "../environment"
 import { env as coreEnv } from "@budibase/backend-core"
 import { testContainerUtils } from "@budibase/backend-core/tests"

packages/server/src/tests/logging.ts

@@ -0,0 +1,34 @@
+export enum LogLevel {
+  TRACE = "trace",
+  DEBUG = "debug",
+  INFO = "info",
+  WARN = "warn",
+  ERROR = "error",
+}
+
+const LOG_INDEX: { [key in LogLevel]: number } = {
+  [LogLevel.TRACE]: 1,
+  [LogLevel.DEBUG]: 2,
+  [LogLevel.INFO]: 3,
+  [LogLevel.WARN]: 4,
+  [LogLevel.ERROR]: 5,
+}
+
+const setIndex = LOG_INDEX[process.env.LOG_LEVEL as LogLevel]
+
+if (setIndex > LOG_INDEX.trace) {
+  global.console.trace = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.debug) {
+  global.console.debug = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.info) {
+  global.console.info = jest.fn()
+  global.console.log = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.warn) {
+  global.console.warn = jest.fn()
+}

packages/types/src/api/web/errors.ts

@@ -2,4 +2,5 @@ export interface APIError {
   message: string
   status: number
   error?: any
+  validationErrors?: any
 }

packages/worker/src/api/index.ts

@@ -3,8 +3,7 @@ const compress = require("koa-compress")
 const zlib = require("zlib")
 import { routes } from "./routes"
 import { middleware as pro } from "@budibase/pro"
-import { errors, auth, middleware } from "@budibase/backend-core"
+import { auth, middleware } from "@budibase/backend-core"
-import { APIError } from "@budibase/types"
 
 const PUBLIC_ENDPOINTS = [
   // deprecated single tenant sso callback
@@ -109,7 +108,9 @@ const NO_TENANCY_ENDPOINTS = [
 const NO_CSRF_ENDPOINTS = [...PUBLIC_ENDPOINTS]
 
 const router: Router = new Router()
+
 router
+  .use(middleware.errorHandling)
   .use(
     compress({
       threshold: 2048,
@@ -136,29 +137,12 @@ router
       (!ctx.isAuthenticated || (ctx.user && !ctx.user.budibaseAccess)) &&
       !ctx.internal
     ) {
-      ctx.throw(403, "Unauthorized - no public worker access")
+      ctx.throw(403, "Unauthorized")
     }
     return next()
   })
   .use(middleware.auditLog)
 
-// error handling middleware - TODO: This could be moved to backend-core
-router.use(async (ctx, next) => {
-  try {
-    await next()
-  } catch (err: any) {
-    ctx.log.error(err)
-    ctx.status = err.status || err.statusCode || 500
-    const error = errors.getPublicError(err)
-    const body: APIError = {
-      message: err.message,
-      status: ctx.status,
-      error,
-    }
-    ctx.body = body
-  }
-})
-
 router.get("/health", ctx => (ctx.status = 200))
 
 // authenticated routes

packages/worker/src/api/routes/system/tests/migrations.spec.ts

@@ -30,7 +30,7 @@ describe("/api/system/migrations", () => {
         headers: {},
         status: 403,
       })
-      expect(res.text).toBe("Unauthorized - no public worker access")
+      expect(res.body).toEqual({ message: "Unauthorized", status: 403 })
       expect(migrateFn).toBeCalledTimes(0)
     })
 
@@ -47,7 +47,7 @@ describe("/api/system/migrations", () => {
         headers: {},
         status: 403,
       })
-      expect(res.text).toBe("Unauthorized - no public worker access")
+      expect(res.body).toEqual({ message: "Unauthorized", status: 403 })
     })
 
     it("returns definitions", async () => {

packages/worker/src/middleware/tests/tenancy.spec.ts

@@ -24,7 +24,7 @@ describe("tenancy middleware", () => {
   })
 
   it("should get tenant id from header", async () => {
-    const tenantId = structures.uuid()
+    const tenantId = structures.tenant.id()
     const headers = {
       [constants.Header.TENANT_ID]: tenantId,
     }
@@ -35,7 +35,7 @@ describe("tenancy middleware", () => {
   })
 
   it("should get tenant id from query param", async () => {
-    const tenantId = structures.uuid()
+    const tenantId = structures.tenant.id()
     const res = await config.request.get(
       `/api/global/configs/checklist?tenantId=${tenantId}`
     )
@@ -43,7 +43,7 @@ describe("tenancy middleware", () => {
   })
 
   it("should get tenant id from subdomain", async () => {
-    const tenantId = structures.uuid()
+    const tenantId = structures.tenant.id()
     const headers = {
       host: `${tenantId}.localhost:10000`,
     }
@@ -67,7 +67,7 @@ describe("tenancy middleware", () => {
   it("should throw when no tenant id is found", async () => {
     const res = await config.request.get(`/api/global/configs/checklist`)
     expect(res.status).toBe(403)
-    expect(res.text).toBe("Tenant id not set")
+    expect(res.body).toEqual({ message: "Tenant id not set", status: 403 })
     expect(res.headers[constants.Header.TENANT_ID]).toBe(undefined)
   })
 })

packages/worker/src/tests/jestEnv.ts

@@ -1,7 +1,7 @@
 process.env.SELF_HOSTED = "0"
 process.env.NODE_ENV = "jest"
 process.env.JWT_SECRET = "test-jwtsecret"
-process.env.LOG_LEVEL = "silent"
+process.env.LOG_LEVEL = process.env.LOG_LEVEL || "error"
 process.env.MULTI_TENANCY = "1"
 process.env.MINIO_URL = "http://localhost"
 process.env.MINIO_ACCESS_KEY = "test"

packages/worker/src/tests/jestSetup.ts

@@ -1,5 +1,6 @@
-import { mocks, testContainerUtils } from "@budibase/backend-core/tests"
+import "./logging"
 
+import { mocks, testContainerUtils } from "@budibase/backend-core/tests"
 import env from "../environment"
 import { env as coreEnv } from "@budibase/backend-core"
 
@@ -11,10 +12,6 @@ mocks.fetch.enable()
 const tk = require("timekeeper")
 tk.freeze(mocks.date.MOCK_DATE)
 
-if (!process.env.DEBUG) {
-  global.console.log = jest.fn() // console.log are ignored in tests
-}
-
 if (!process.env.CI) {
   // set a longer timeout in dev for debugging
   // 100 seconds

packages/worker/src/tests/logging.ts

@@ -0,0 +1,34 @@
+export enum LogLevel {
+  TRACE = "trace",
+  DEBUG = "debug",
+  INFO = "info",
+  WARN = "warn",
+  ERROR = "error",
+}
+
+const LOG_INDEX: { [key in LogLevel]: number } = {
+  [LogLevel.TRACE]: 1,
+  [LogLevel.DEBUG]: 2,
+  [LogLevel.INFO]: 3,
+  [LogLevel.WARN]: 4,
+  [LogLevel.ERROR]: 5,
+}
+
+const setIndex = LOG_INDEX[process.env.LOG_LEVEL as LogLevel]
+
+if (setIndex > LOG_INDEX.trace) {
+  global.console.trace = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.debug) {
+  global.console.debug = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.info) {
+  global.console.info = jest.fn()
+  global.console.log = jest.fn()
+}
+
+if (setIndex > LOG_INDEX.warn) {
+  global.console.warn = jest.fn()
+}