TestKit backend: truncate logging to avoid clogging ram (#1322)

Writing to stdout in nodejs is done asynchronously. So when adding data to the
queue faster than it can be flushed, the process will eventually crash because
the system is running out of memory. By limiting the length of log messages,
this problem can be avoided.

Author: robsdedude

packages/testkit-backend/deno/index.ts

@@ -10,6 +10,7 @@ import {
 import channel from "./channel.ts";
 import controller from "./controller.ts";
 import { RequestHandlerMap } from "./domain.ts";
+import util from "node:util";
 
 const requestHandlers: RequestHandlerMap = handlers as RequestHandlerMap;
 
@@ -26,11 +27,23 @@ const binder = new CypherNativeBinders(neo4j);
 const descriptor = ["async", "deno"];
 const shouldRunTest = getShouldRunTest(descriptor);
 const getFeatures = createGetFeatures(descriptor);
-const logLevel = Deno.env.get("TEST_LOG_LEVEL");
+const logLevel = Deno.env.get("TEST_LOG_LEVEL") ?? "info";
 const createContext = () =>
   new Context(shouldRunTest, getFeatures, binder, logLevel);
 
-configurableConsole.install(logLevel);
+const logWrapper = (...args) => {
+  let output = args.map((arg) => {
+    if (typeof arg === "string") return arg;
+    return util.inspect(arg, { colors: Deno.stdout.isTTY });
+  }).join(" ") + "\n";
+  if (output.length > 1000 * 2 + 3) {
+    output = output.substring(0, 1000) + "..." +
+      output.substring(output.length - 1000);
+  }
+  Deno.stdout.write(new TextEncoder().encode(output));
+};
+
+configurableConsole.install(logLevel, logWrapper);
 const listener = channel.listen(9876);
 const handle = controller.createHandler(neo4j, createContext, requestHandlers);
 

packages/testkit-backend/src/channel/testkit-protocol.js

@@ -61,8 +61,10 @@ export default class Protocol extends EventEmitter {
   }
 
   serializeResponse (response) {
+    const { name, data } = response
     const responseStr = stringify(response)
-    console.log('> writing response', responseStr)
+    console.log('> writing response' + name)
+    console.debug(data)
     return ['#response begin', responseStr, '#response end'].join('\n') + '\n'
   }
 

packages/testkit-backend/src/console.configurable.js

@@ -20,13 +20,17 @@ const config = {
 }
 
 export default {
-  install (level = 'info') {
+  install (level = 'info', logWrapper) {
     this.setLevel(level)
     // eslint-disable-next-line no-global-assign
     console = new Proxy({}, {
       get: (_, method) => (...args) => {
         if (config.canRun(method)) {
-          originalConsole[method].apply(originalConsole, args)
+          if (logWrapper != null) {
+            logWrapper(...args)
+          } else {
+            originalConsole[method].apply(originalConsole, args)
+          }
         }
       }
     })

packages/testkit-backend/src/index.js

@@ -9,6 +9,7 @@ import * as REQUEST_HANDLERS from './request-handlers.js'
 import * as RX_REQUEST_HANDLERS from './request-handlers-rx.js'
 import remoteConsole from './console.remote.js'
 import configurableConsole from './console.configurable.js'
+import util from 'util'
 
 const SUPPORTED_TLS = (() => {
   if (tls.DEFAULT_MAX_VERSION) {
@@ -40,7 +41,17 @@ function main () {
   const shouldRunTest = getShouldRunTest([...driverDescriptorList, sessionTypeDescriptor])
   const getFeatures = createGetFeatures([sessionTypeDescriptor], SUPPORTED_TLS)
 
-  configurableConsole.install(process.env.TEST_LOG_LEVEL || 'info')
+  const logWrapper = (...args) => {
+    let output = args.map(arg => {
+      if (typeof arg === 'string') return arg
+      return util.inspect(arg, { colors: process.stdout.isTTY })
+    }).join(' ') + '\n'
+    if (output.length > 1000 * 2 + 3) {
+      output = output.substring(0, 1000) + '...' + output.substring(output.length - 1000)
+    }
+    process.stdout.write(output)
+  }
+  configurableConsole.install(process.env.TEST_LOG_LEVEL || 'info', logWrapper)
 
   const newChannel = () => {
     if (channelType.toUpperCase() === 'WEBSOCKET') {