From 5cd6cb166ab51f0d07bab1367d0549abd8aaa6af Mon Sep 17 00:00:00 2001
From: Rory Powell <rory.codes@gmail.com>
Date: Mon, 13 Feb 2023 11:53:01 +0000
Subject: [PATCH 1/2] Configurable test log levels and common error handling

---
 .../src/middleware/errorHandling.ts           | 28 +++++++++++++++
 packages/backend-core/src/middleware/index.ts |  5 +--
 packages/backend-core/tests/jestEnv.ts        | 28 +++------------
 packages/backend-core/tests/jestSetup.ts      | 21 +++++++++++-
 packages/backend-core/tests/logging.ts        | 34 +++++++++++++++++++
 packages/server/src/api/index.ts              | 25 ++------------
 packages/server/src/tests/jestEnv.ts          | 12 +++----
 packages/server/src/tests/jestSetup.ts        |  1 +
 packages/server/src/tests/logging.ts          | 34 +++++++++++++++++++
 packages/types/src/api/web/errors.ts          |  1 +
 packages/worker/src/api/index.ts              | 24 +++----------
 .../routes/system/tests/migrations.spec.ts    |  4 +--
 .../src/middleware/tests/tenancy.spec.ts      |  8 ++---
 packages/worker/src/tests/jestEnv.ts          |  2 +-
 packages/worker/src/tests/jestSetup.ts        |  7 ++--
 packages/worker/src/tests/logging.ts          | 34 +++++++++++++++++++
 16 files changed, 182 insertions(+), 86 deletions(-)
 create mode 100644 packages/backend-core/src/middleware/errorHandling.ts
 create mode 100644 packages/backend-core/tests/logging.ts
 create mode 100644 packages/server/src/tests/logging.ts
 create mode 100644 packages/worker/src/tests/logging.ts

diff --git a/packages/backend-core/src/middleware/errorHandling.ts b/packages/backend-core/src/middleware/errorHandling.ts
new file mode 100644
index 0000000000..1baaa92501
--- /dev/null
+++ b/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
diff --git a/packages/backend-core/src/middleware/index.ts b/packages/backend-core/src/middleware/index.ts
index 4986cde64b..de609f9a3e 100644
--- a/packages/backend-core/src/middleware/index.ts
+++ b/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 oidc from "./passport/oidc"
+export * as google from "./passport/sso/google"
+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"
diff --git a/packages/backend-core/tests/jestEnv.ts b/packages/backend-core/tests/jestEnv.ts
index 1190eb3bb7..71cf865737 100644
--- a/packages/backend-core/tests/jestEnv.ts
+++ b/packages/backend-core/tests/jestEnv.ts
@@ -1,23 +1,5 @@
-import env from "../src/environment"
-import { mocks } 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)
-
-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)
-}
+process.env.SELF_HOSTED = "1"
+process.env.MULTI_TENANCY = "1"
+process.env.NODE_ENV = "jest"
+process.env.MOCK_REDIS = "1"
+process.env.LOG_LEVEL = process.env.LOG_LEVEL || "error"
diff --git a/packages/backend-core/tests/jestSetup.ts b/packages/backend-core/tests/jestSetup.ts
index f7887ec824..e786086de6 100644
--- a/packages/backend-core/tests/jestSetup.ts
+++ b/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)
diff --git a/packages/backend-core/tests/logging.ts b/packages/backend-core/tests/logging.ts
new file mode 100644
index 0000000000..271f4d62ff
--- /dev/null
+++ b/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()
+}
diff --git a/packages/server/src/api/index.ts b/packages/server/src/api/index.ts
index 3375161dd8..78a6056366 100644
--- a/packages/server/src/api/index.ts
+++ b/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())
diff --git a/packages/server/src/tests/jestEnv.ts b/packages/server/src/tests/jestEnv.ts
index 9707893bd9..b1ef038c1b 100644
--- a/packages/server/src/tests/jestEnv.ts
+++ b/packages/server/src/tests/jestEnv.ts
@@ -1,9 +1,9 @@
-import env from "../environment"
 import { tmpdir } from "os"
 
-env._set("SELF_HOSTED", "1")
-env._set("NODE_ENV", "jest")
-env._set("MULTI_TENANCY", "1")
+process.env.SELF_HOSTED = "1"
+process.env.NODE_ENV = "jest"
+process.env.MULTI_TENANCY = "1"
 // @ts-ignore
-env._set("BUDIBASE_DIR", tmpdir("budibase-unittests"))
-env._set("LOG_LEVEL", "silent")
+process.env.BUDIBASE_DIR = tmpdir("budibase-unittests")
+process.env.LOG_LEVEL = process.env.LOG_LEVEL || "error"
+process.env.MOCK_REDIS = "1"
diff --git a/packages/server/src/tests/jestSetup.ts b/packages/server/src/tests/jestSetup.ts
index d87ccbfe7c..b052d9941b 100644
--- a/packages/server/src/tests/jestSetup.ts
+++ b/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"
diff --git a/packages/server/src/tests/logging.ts b/packages/server/src/tests/logging.ts
new file mode 100644
index 0000000000..271f4d62ff
--- /dev/null
+++ b/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()
+}
diff --git a/packages/types/src/api/web/errors.ts b/packages/types/src/api/web/errors.ts
index 65870d6a29..996c0ba34c 100644
--- a/packages/types/src/api/web/errors.ts
+++ b/packages/types/src/api/web/errors.ts
@@ -2,4 +2,5 @@ export interface APIError {
   message: string
   status: number
   error?: any
+  validationErrors?: any
 }
diff --git a/packages/worker/src/api/index.ts b/packages/worker/src/api/index.ts
index d8df62f532..b390d36bb8 100644
--- a/packages/worker/src/api/index.ts
+++ b/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 { APIError } from "@budibase/types"
+import { auth, middleware } from "@budibase/backend-core"
 
 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
diff --git a/packages/worker/src/api/routes/system/tests/migrations.spec.ts b/packages/worker/src/api/routes/system/tests/migrations.spec.ts
index 304a64761e..950f5c2153 100644
--- a/packages/worker/src/api/routes/system/tests/migrations.spec.ts
+++ b/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 () => {
diff --git a/packages/worker/src/middleware/tests/tenancy.spec.ts b/packages/worker/src/middleware/tests/tenancy.spec.ts
index a8b7a50e55..8853291634 100644
--- a/packages/worker/src/middleware/tests/tenancy.spec.ts
+++ b/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)
   })
 })
diff --git a/packages/worker/src/tests/jestEnv.ts b/packages/worker/src/tests/jestEnv.ts
index 0b27cf52aa..602a505c1b 100644
--- a/packages/worker/src/tests/jestEnv.ts
+++ b/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"
diff --git a/packages/worker/src/tests/jestSetup.ts b/packages/worker/src/tests/jestSetup.ts
index 2deef96176..31d36f00ae 100644
--- a/packages/worker/src/tests/jestSetup.ts
+++ b/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
diff --git a/packages/worker/src/tests/logging.ts b/packages/worker/src/tests/logging.ts
new file mode 100644
index 0000000000..271f4d62ff
--- /dev/null
+++ b/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()
+}

From f53faff7ad80fd7530a20036cd51d22d5933048d Mon Sep 17 00:00:00 2001
From: Rory Powell <rory.codes@gmail.com>
Date: Mon, 13 Feb 2023 12:27:49 +0000
Subject: [PATCH 2/2] Add LOG_4XX to environment

---
 packages/backend-core/src/environment.ts | 1 +
 1 file changed, 1 insertion(+)

diff --git a/packages/backend-core/src/environment.ts b/packages/backend-core/src/environment.ts
index d742ca1cc9..9a07695734 100644
--- a/packages/backend-core/src/environment.ts
+++ b/packages/backend-core/src/environment.ts
@@ -82,6 +82,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