Merge pull request #15402 from Budibase/feature/js-logging

JS console log support

packages/bbui/src/bbui.css

@@ -45,6 +45,11 @@
   --purple: #806fde;
   --purple-dark: #130080;
 
+  --error-bg: rgba(226, 109, 105, 0.3);
+  --warning-bg: rgba(255, 210, 106, 0.3);
+  --error-content: rgba(226, 109, 105, 0.6);
+  --warning-content: rgba(255, 210, 106, 0.6);
+
   --rounded-small: 4px;
   --rounded-medium: 8px;
   --rounded-large: 16px;

packages/builder/src/components/common/bindings/BindingPanel.svelte

@@ -12,7 +12,7 @@
     decodeJSBinding,
     encodeJSBinding,
     processObjectSync,
-    processStringSync,
+    processStringWithLogsSync,
   } from "@budibase/string-templates"
   import { readableToRuntimeBinding } from "@/dataBinding"
   import CodeEditor from "../CodeEditor/CodeEditor.svelte"
@@ -41,6 +41,7 @@
     InsertAtPositionFn,
     JSONValue,
   } from "@budibase/types"
+  import type { Log } from "@budibase/string-templates"
   import type { CompletionContext } from "@codemirror/autocomplete"
 
   const dispatch = createEventDispatcher()
@@ -66,6 +67,7 @@
   let insertAtPos: InsertAtPositionFn | undefined
   let targetMode: BindingMode | null = null
   let expressionResult: string | undefined
+  let expressionLogs: Log[] | undefined
   let expressionError: string | undefined
   let evaluating = false
 
@@ -157,7 +159,7 @@
     (expression: string | null, context: any, snippets: Snippet[]) => {
       try {
         expressionError = undefined
-        expressionResult = processStringSync(
+        const output = processStringWithLogsSync(
           expression || "",
           {
             ...context,
@@ -167,6 +169,8 @@
             noThrow: false,
           }
         )
+        expressionResult = output.result
+        expressionLogs = output.logs
       } catch (err: any) {
         expressionResult = undefined
         expressionError = err
@@ -421,6 +425,7 @@
         <EvaluationSidePanel
           {expressionResult}
           {expressionError}
+          {expressionLogs}
           {evaluating}
           expression={editorValue ? editorValue : ""}
         />

packages/builder/src/components/common/bindings/EvaluationSidePanel.svelte

@@ -4,11 +4,13 @@
   import { Helpers } from "@budibase/bbui"
   import { fade } from "svelte/transition"
   import { UserScriptError } from "@budibase/string-templates"
+  import type { Log } from "@budibase/string-templates"
   import type { JSONValue } from "@budibase/types"
 
   // this can be essentially any primitive response from the JS function
   export let expressionResult: JSONValue | undefined = undefined
   export let expressionError: string | undefined = undefined
+  export let expressionLogs: Log[] = []
   export let evaluating = false
   export let expression: string | null = null
 
@@ -16,6 +18,11 @@
   $: empty = expression == null || expression?.trim() === ""
   $: success = !error && !empty
   $: highlightedResult = highlight(expressionResult)
+  $: highlightedLogs = expressionLogs.map(l => ({
+    log: highlight(l.log.join(", ")),
+    line: l.line,
+    type: l.type,
+  }))
 
   const formatError = (err: any) => {
     if (err.code === UserScriptError.code) {
@@ -25,14 +32,14 @@
   }
 
   // json can be any primitive type
-  const highlight = (json?: any | null) => {
+  const highlight = (json?: JSONValue | null) => {
     if (json == null) {
       return ""
     }
 
     // Attempt to parse and then stringify, in case this is valid result
     try {
-      json = JSON.stringify(JSON.parse(json), null, 2)
+      json = JSON.stringify(JSON.parse(json as any), null, 2)
     } catch (err) {
       // couldn't parse/stringify, just treat it as the raw input
     }
@@ -61,7 +68,7 @@
   <div class="header" class:success class:error>
     <div class="header-content">
       {#if error}
-        <Icon name="Alert" color="var(--spectrum-global-color-red-600)" />
+        <Icon name="Alert" color="var(--error-content)" />
         <div>Error</div>
         {#if evaluating}
           <div transition:fade|local={{ duration: 130 }}>
@@ -90,8 +97,36 @@
     {:else if error}
       {formatError(expressionError)}
     {:else}
-      <!-- eslint-disable-next-line svelte/no-at-html-tags-->
+      <div class="output-lines">
-      {@html highlightedResult}
+        {#each highlightedLogs as logLine}
+          <div
+            class="line"
+            class:error-log={logLine.type === "error"}
+            class:warn-log={logLine.type === "warn"}
+          >
+            <div class="icon-log">
+              {#if logLine.type === "error"}
+                <Icon
+                  size="XS"
+                  name="CloseCircle"
+                  color="var(--error-content)"
+                />
+              {:else if logLine.type === "warn"}
+                <Icon size="XS" name="Alert" color="var(--warning-content)" />
+              {/if}
+              <!-- eslint-disable-next-line svelte/no-at-html-tags-->
+              <span>{@html logLine.log}</span>
+            </div>
+            {#if logLine.line}
+              <span style="color: var(--blue)">:{logLine.line}</span>
+            {/if}
+          </div>
+        {/each}
+        <div class="line">
+          <!-- eslint-disable-next-line svelte/no-at-html-tags-->
+          {@html highlightedResult}
+        </div>
+      </div>
     {/if}
   </div>
 </div>
@@ -130,20 +165,37 @@
     height: 100%;
     z-index: 1;
     position: absolute;
-    opacity: 10%;
   }
   .header.error::before {
-    background: var(--spectrum-global-color-red-400);
+    background: var(--error-bg);
   }
   .body {
     flex: 1 1 auto;
     padding: var(--spacing-m) var(--spacing-l);
     font-family: var(--font-mono);
     font-size: 12px;
-    overflow-y: scroll;
+    overflow-y: auto;
     overflow-x: hidden;
-    white-space: pre-wrap;
+    white-space: pre-line;
     word-wrap: break-word;
     height: 0;
   }
+  .output-lines {
+    display: flex;
+    flex-direction: column;
+    gap: var(--spacing-xs);
+  }
+  .line {
+    border-bottom: var(--border-light);
+    display: flex;
+    flex-direction: row;
+    justify-content: space-between;
+    align-items: end;
+    padding: var(--spacing-s);
+  }
+  .icon-log {
+    display: flex;
+    gap: var(--spacing-s);
+    align-items: start;
+  }
 </style>

packages/server/src/jsRunner/index.ts

@@ -4,12 +4,17 @@ import {
   JsTimeoutError,
   setJSRunner,
   setOnErrorLog,
+  setTestingBackendJS,
 } from "@budibase/string-templates"
 import { context, logging } from "@budibase/backend-core"
 import tracer from "dd-trace"
 import { IsolatedVM } from "./vm"
 
 export function init() {
+  // enforce that if we're using isolated-VM runner then we are running backend JS
+  if (env.isTest()) {
+    setTestingBackendJS()
+  }
   setJSRunner((js: string, ctx: Record<string, any>) => {
     return tracer.trace("runJS", {}, () => {
       try {

packages/string-templates/src/environment.ts

@@ -0,0 +1,23 @@
+function isJest() {
+  return (
+    process.env.NODE_ENV === "jest" ||
+    (process.env.JEST_WORKER_ID != null &&
+      process.env.JEST_WORKER_ID !== "null")
+  )
+}
+
+export function isTest() {
+  return isJest()
+}
+
+export const isJSAllowed = () => {
+  return process && !process.env.NO_JS
+}
+
+export const isTestingBackendJS = () => {
+  return process && process.env.BACKEND_JS
+}
+
+export const setTestingBackendJS = () => {
+  process.env.BACKEND_JS = "1"
+}

packages/string-templates/src/helpers/javascript.ts

@@ -1,9 +1,16 @@
-import { atob, isBackendService, isJSAllowed } from "../utilities"
+import {
+  atob,
+  frontendWrapJS,
+  isBackendService,
+  isJSAllowed,
+} from "../utilities"
 import { LITERAL_MARKER } from "../helpers/constants"
 import { getJsHelperList } from "./list"
 import { iifeWrapper } from "../iife"
 import { JsTimeoutError, UserScriptError } from "../errors"
 import { cloneDeep } from "lodash/fp"
+import { Log, LogType } from "../types"
+import { isTest } from "../environment"
 
 // The method of executing JS scripts depends on the bundle being built.
 // This setter is used in the entrypoint (either index.js or index.mjs).
@@ -81,7 +88,7 @@ export function processJS(handlebars: string, context: any) {
 
     let clonedContext: Record<string, any>
     if (isBackendService()) {
-      // On the backned, values are copied across the isolated-vm boundary and
+      // On the backend, values are copied across the isolated-vm boundary and
       // so we don't need to do any cloning here. This does create a fundamental
       // difference in how JS executes on the frontend vs the backend, e.g.
       // consider this snippet:
@@ -96,10 +103,9 @@ export function processJS(handlebars: string, context: any) {
       clonedContext = cloneDeep(context)
     }
 
-    const sandboxContext = {
+    const sandboxContext: Record<string, any> = {
       $: (path: string) => getContextValue(path, clonedContext),
       helpers: getJsHelperList(),
-
       // Proxy to evaluate snippets when running in the browser
       snippets: new Proxy(
         {},
@@ -114,8 +120,49 @@ export function processJS(handlebars: string, context: any) {
       ),
     }
 
+    const logs: Log[] = []
+    // logging only supported on frontend
+    if (!isBackendService()) {
+      // this counts the lines in the wrapped JS *before* the user's code, so that we can minus it
+      const jsLineCount = frontendWrapJS(js).split(js)[0].split("\n").length
+      const buildLogResponse = (type: LogType) => {
+        return (...props: any[]) => {
+          if (!isTest()) {
+            console[type](...props)
+          }
+          props.forEach((prop, index) => {
+            if (typeof prop === "object") {
+              props[index] = JSON.stringify(prop)
+            }
+          })
+          // quick way to find out what line this is being called from
+          // its an anonymous function and we look for the overall length to find the
+          // line number we care about (from the users function)
+          // JS stack traces are in the format function:line:column
+          const lineNumber = new Error().stack?.match(
+            /<anonymous>:(\d+):\d+/
+          )?.[1]
+          logs.push({
+            log: props,
+            line: lineNumber ? parseInt(lineNumber) - jsLineCount : undefined,
+            type,
+          })
+        }
+      }
+      sandboxContext.console = {
+        log: buildLogResponse("log"),
+        info: buildLogResponse("info"),
+        debug: buildLogResponse("debug"),
+        warn: buildLogResponse("warn"),
+        error: buildLogResponse("error"),
+        // table should be treated differently, but works the same
+        // as the rest of the logs for now
+        table: buildLogResponse("table"),
+      }
+    }
+
     // Create a sandbox with our context and run the JS
-    const res = { data: runJS(js, sandboxContext) }
+    const res = { data: runJS(js, sandboxContext), logs }
     return `{{${LITERAL_MARKER} js_result-${JSON.stringify(res)}}}`
   } catch (error: any) {
     onErrorLog && onErrorLog(error)

packages/string-templates/src/index.ts

@@ -1,13 +1,14 @@
 import { createContext, runInNewContext } from "vm"
 import { create, TemplateDelegate } from "handlebars"
 import { registerAll, registerMinimum } from "./helpers/index"
-import { postprocess, preprocess } from "./processors"
+import { postprocess, postprocessWithLogs, preprocess } from "./processors"
 import {
   atob,
   btoa,
   FIND_ANY_HBS_REGEX,
   FIND_HBS_REGEX,
   findDoubleHbsInstances,
+  frontendWrapJS,
   isBackendService,
   prefixStrings,
 } from "./utilities"
@@ -15,9 +16,11 @@ import { convertHBSBlock } from "./conversion"
 import { removeJSRunner, setJSRunner } from "./helpers/javascript"
 
 import manifest from "./manifest.json"
-import { ProcessOptions } from "./types"
+import { Log, ProcessOptions } from "./types"
 import { UserScriptError } from "./errors"
 
+export type { Log, LogType } from "./types"
+export { setTestingBackendJS } from "./environment"
 export { helpersToRemoveForJs, getJsHelperList } from "./helpers/list"
 export { FIND_ANY_HBS_REGEX } from "./utilities"
 export { setJSRunner, setOnErrorLog } from "./helpers/javascript"
@@ -187,23 +190,27 @@ export function processObjectSync(
   return object
 }
 
-/**
+// keep the logging function internal, don't want to add this to the process options directly
- * This will process a single handlebars containing string. If the string passed in has no valid handlebars statements
+// as it can't be used for object processing etc.
- * then nothing will occur. This is a pure sync call and therefore does not have the full functionality of the async call.
+function processStringSyncInternal(
- * @param {string} string The template string which is the filled from the context object.
+  str: string,
- * @param {object} context An object of information which will be used to enrich the string.
+  context?: object,
- * @param {object|undefined} [opts] optional - specify some options for processing.
+  opts?: ProcessOptions & { logging: false }
- * @returns {string} The enriched string, all templates should have been replaced if they can be.
+): string
- */
+function processStringSyncInternal(
-export function processStringSync(
+  str: string,
+  context?: object,
+  opts?: ProcessOptions & { logging: true }
+): { result: string; logs: Log[] }
+function processStringSyncInternal(
   string: string,
   context?: object,
-  opts?: ProcessOptions
+  opts?: ProcessOptions & { logging: boolean }
-): string {
+): string | { result: string; logs: Log[] } {
   // Take a copy of input in case of error
   const input = string
   if (typeof string !== "string") {
-    throw "Cannot process non-string types."
+    throw new Error("Cannot process non-string types.")
   }
   function process(stringPart: string) {
     // context is needed to check for overlap between helpers and context
@@ -217,16 +224,24 @@ export function processStringSync(
       },
       ...context,
     })
-    return postprocess(processedString)
+    return opts?.logging
+      ? postprocessWithLogs(processedString)
+      : postprocess(processedString)
   }
   try {
     if (opts && opts.onlyFound) {
+      let logs: Log[] = []
       const blocks = findHBSBlocks(string)
       for (let block of blocks) {
         const outcome = process(block)
-        string = string.replace(block, outcome)
+        if (typeof outcome === "object" && "result" in outcome) {
+          logs = logs.concat(outcome.logs || [])
+          string = string.replace(block, outcome.result)
+        } else {
+          string = string.replace(block, outcome)
+        }
       }
-      return string
+      return !opts?.logging ? string : { result: string, logs }
     } else {
       return process(string)
     }
@@ -239,6 +254,42 @@ export function processStringSync(
   }
 }
 
+/**
+ * This will process a single handlebars containing string. If the string passed in has no valid handlebars statements
+ * then nothing will occur. This is a pure sync call and therefore does not have the full functionality of the async call.
+ * @param {string} string The template string which is the filled from the context object.
+ * @param {object} context An object of information which will be used to enrich the string.
+ * @param {object|undefined} [opts] optional - specify some options for processing.
+ * @returns {string} The enriched string, all templates should have been replaced if they can be.
+ */
+export function processStringSync(
+  string: string,
+  context?: object,
+  opts?: ProcessOptions
+): string {
+  return processStringSyncInternal(string, context, {
+    ...opts,
+    logging: false,
+  })
+}
+
+/**
+ * Same as function above, but allows logging to be returned - this is only for JS bindings.
+ */
+export function processStringWithLogsSync(
+  string: string,
+  context?: object,
+  opts?: ProcessOptions
+): { result: string; logs: Log[] } {
+  if (isBackendService()) {
+    throw new Error("Logging disabled for backend bindings")
+  }
+  return processStringSyncInternal(string, context, {
+    ...opts,
+    logging: true,
+  })
+}
+
 /**
  * By default with expressions like {{ name }} handlebars will escape various
  * characters, which can be problematic. To fix this we use the syntax {{{ name }}},
@@ -462,20 +513,7 @@ export function browserJSSetup() {
   setJSRunner((js: string, context: Record<string, any>) => {
     createContext(context)
 
-    const wrappedJs = `
+    const wrappedJs = frontendWrapJS(js)
-        result = {
-          result: null,
-          error: null,
-        };
-
-        try {
-          result.result = ${js};
-        } catch (e) {
-          result.error = e;
-        }
-
-        result;
-      `
 
     const result = runInNewContext(wrappedJs, context, { timeout: 1000 })
     if (result.error) {

packages/string-templates/src/processors/index.ts

@@ -1,9 +1,16 @@
 import { FIND_HBS_REGEX } from "../utilities"
 import * as preprocessor from "./preprocessor"
+import type { Preprocessor } from "./preprocessor"
 import * as postprocessor from "./postprocessor"
-import { ProcessOptions } from "../types"
+import type { Postprocessor } from "./postprocessor"
+import { Log, ProcessOptions } from "../types"
 
-function process(output: string, processors: any[], opts?: ProcessOptions) {
+function process(
+  output: string,
+  processors: (Preprocessor | Postprocessor)[],
+  opts?: ProcessOptions
+) {
+  let logs: Log[] = []
   for (let processor of processors) {
     // if a literal statement has occurred stop
     if (typeof output !== "string") {
@@ -16,10 +23,18 @@ function process(output: string, processors: any[], opts?: ProcessOptions) {
       continue
     }
     for (let match of matches) {
-      output = processor.process(output, match, opts)
+      const res = processor.process(output, match, opts || {})
+      if (typeof res === "object") {
+        if ("logs" in res && res.logs) {
+          logs = logs.concat(res.logs)
+        }
+        output = res.result
+      } else {
+        output = res as string
+      }
     }
   }
-  return output
+  return { result: output, logs }
 }
 
 export function preprocess(string: string, opts: ProcessOptions) {
@@ -30,8 +45,13 @@ export function preprocess(string: string, opts: ProcessOptions) {
     )
   }
 
-  return process(string, processors, opts)
+  return process(string, processors, opts).result
 }
+
 export function postprocess(string: string) {
+  return process(string, postprocessor.processors).result
+}
+
+export function postprocessWithLogs(string: string) {
   return process(string, postprocessor.processors)
 }

packages/string-templates/src/processors/postprocessor.ts

@@ -1,12 +1,16 @@
 import { LITERAL_MARKER } from "../helpers/constants"
+import { Log } from "../types"
 
 export enum PostProcessorNames {
   CONVERT_LITERALS = "convert-literals",
 }
 
-type PostprocessorFn = (statement: string) => string
+export type PostprocessorFn = (statement: string) => {
+  result: any
+  logs?: Log[]
+}
 
-class Postprocessor {
+export class Postprocessor {
   name: PostProcessorNames
   private readonly fn: PostprocessorFn
 
@@ -23,12 +27,12 @@ class Postprocessor {
 export const processors = [
   new Postprocessor(
     PostProcessorNames.CONVERT_LITERALS,
-    (statement: string) => {
+    (statement: string): { result: any; logs?: Log[] } => {
       if (
         typeof statement !== "string" ||
         !statement.includes(LITERAL_MARKER)
       ) {
-        return statement
+        return { result: statement }
       }
       const splitMarkerIndex = statement.indexOf("-")
       const type = statement.substring(12, splitMarkerIndex)
@@ -38,20 +42,22 @@ export const processors = [
       )
       switch (type) {
         case "string":
-          return value
+          return { result: value }
         case "number":
-          return parseFloat(value)
+          return { result: parseFloat(value) }
         case "boolean":
-          return value === "true"
+          return { result: value === "true" }
         case "object":
-          return JSON.parse(value)
+          return { result: JSON.parse(value) }
-        case "js_result":
+        case "js_result": {
           // We use the literal helper to process the result of JS expressions
           // as we want to be able to return any types.
           // We wrap the value in an abject to be able to use undefined properly.
-          return JSON.parse(value).data
+          const parsed = JSON.parse(value)
+          return { result: parsed.data, logs: parsed.logs }
+        }
       }
-      return value
+      return { result: value }
     }
   ),
 ]

packages/string-templates/src/processors/preprocessor.ts

@@ -11,9 +11,12 @@ export enum PreprocessorNames {
   NORMALIZE_SPACES = "normalize-spaces",
 }
 
-type PreprocessorFn = (statement: string, opts?: ProcessOptions) => string
+export type PreprocessorFn = (
+  statement: string,
+  opts?: ProcessOptions
+) => string
 
-class Preprocessor {
+export class Preprocessor {
   name: string
   private readonly fn: PreprocessorFn
 

packages/string-templates/src/types.ts

@@ -8,3 +8,11 @@ export interface ProcessOptions {
   onlyFound?: boolean
   disabledHelpers?: string[]
 }
+
+export type LogType = "log" | "info" | "debug" | "warn" | "error" | "table"
+
+export interface Log {
+  log: any[]
+  line?: number
+  type?: LogType
+}

packages/string-templates/src/utilities.ts

@@ -1,15 +1,20 @@
+import { isTest, isTestingBackendJS } from "./environment"
+
 const ALPHA_NUMERIC_REGEX = /^[A-Za-z0-9]+$/g
 
 export const FIND_HBS_REGEX = /{{([^{].*?)}}/g
 export const FIND_ANY_HBS_REGEX = /{?{{([^{].*?)}}}?/g
 export const FIND_TRIPLE_HBS_REGEX = /{{{([^{].*?)}}}/g
 
-const isJest = () => typeof jest !== "undefined"
-
 export const isBackendService = () => {
+  // allow configuring backend JS mode when testing - we default to assuming
+  // frontend, but need a method to control this
+  if (isTest() && isTestingBackendJS()) {
+    return true
+  }
   // We consider the tests for string-templates to be frontend, so that they
   // test the frontend JS functionality.
-  if (isJest()) {
+  if (isTest()) {
     return false
   }
   return typeof window === "undefined"
@@ -86,3 +91,20 @@ export const prefixStrings = (
   const regexPattern = new RegExp(`\\b(${escapedStrings.join("|")})\\b`, "g")
   return baseString.replace(regexPattern, `${prefix}$1`)
 }
+
+export function frontendWrapJS(js: string) {
+  return `
+        result = {
+          result: null,
+          error: null,
+        };
+
+        try {
+          result.result = ${js};
+        } catch (e) {
+          result.error = e;
+        }
+
+        result;
+      `
+}

packages/string-templates/test/jsLogging.spec.ts

@@ -0,0 +1,53 @@
+import {
+  processStringWithLogsSync,
+  encodeJSBinding,
+  defaultJSSetup,
+} from "../src/index"
+
+const processJS = (js: string, context?: object) => {
+  return processStringWithLogsSync(encodeJSBinding(js), context)
+}
+
+describe("Javascript", () => {
+  beforeAll(() => {
+    defaultJSSetup()
+  })
+
+  describe("Test logging in JS bindings", () => {
+    it("should execute a simple expression", () => {
+      const output = processJS(
+        `console.log("hello"); 
+         console.log("world"); 
+         console.log("foo"); 
+         return "hello"`
+      )
+      expect(output.result).toEqual("hello")
+      expect(output.logs[0].log).toEqual(["hello"])
+      expect(output.logs[0].line).toEqual(1)
+      expect(output.logs[1].log).toEqual(["world"])
+      expect(output.logs[1].line).toEqual(2)
+      expect(output.logs[2].log).toEqual(["foo"])
+      expect(output.logs[2].line).toEqual(3)
+    })
+  })
+
+  it("should log comma separated values", () => {
+    const output = processJS(`console.log(1, { a: 1 }); return 1`)
+    expect(output.logs[0].log).toEqual([1, JSON.stringify({ a: 1 })])
+    expect(output.logs[0].line).toEqual(1)
+  })
+
+  it("should return the type working with warn", () => {
+    const output = processJS(`console.warn("warning"); return 1`)
+    expect(output.logs[0].log).toEqual(["warning"])
+    expect(output.logs[0].line).toEqual(1)
+    expect(output.logs[0].type).toEqual("warn")
+  })
+
+  it("should return the type working with error", () => {
+    const output = processJS(`console.error("error"); return 1`)
+    expect(output.logs[0].log).toEqual(["error"])
+    expect(output.logs[0].line).toEqual(1)
+    expect(output.logs[0].type).toEqual("error")
+  })
+})