Error stacktrace overhaul (#1944)

Highlight user code in internal stacktrace.

Other Changes

    Avoid to use process.env at runtime because it does an expensive syscall (CF: nodejs/node#3104 (comment))

Boyscout

    export Global in a TS file to avoid the necessity of building the app to run it

.eslintignore

@@ -43,6 +43,8 @@ lib/types/ResponsePayload.js
 lib/types/StrategyDefinition.js
 lib/types/Token.js
 lib/types/User.js
+lib/types/Global.d.ts
+lib/types/Global.js
 lib/util/interfaces.js
 lib/util/mutex.js
 features/support/application/functional-tests-app.js

.gitignore

@@ -113,6 +113,8 @@ lib/types/StrategyDefinition.js
 lib/types/Token.js
 lib/types/User.js
 lib/types/index.js
+lib/types/Global.d.ts
+lib/types/Global.js
 lib/util/interfaces.js
 lib/util/mutex.js
 features-sdk/support/application/functional-tests-app.js

doc/2/guides/introduction/general-purpose-backend/index.md

@@ -168,7 +168,7 @@ The entire realtime engine is used exclusively from a client (frontend or backen
 
 ## Integrated Cluster Mode
 
-Kuzzle is a backend designed to **scroll horizontally to millions of users**.  
+Kuzzle is a backend designed to **scale horizontally to millions of users**.  
 
 With its integrated [masterless cluster mode](/core/2/guides/advanced/cluster-scalability), it allows hot-starting new application instances to handle the load.
 

docker/scripts/start-kuzzle-dev.ts

@@ -5,7 +5,6 @@
 
 import should from 'should'
 import { omit } from 'lodash'
-import Bluebird from 'bluebird';
 
 import { Backend, Request, Mutex } from '../../index';
 import { FunctionalTestsController } from './functional-tests-controller';

lib/api/request/kuzzle-request.ts

@@ -258,7 +258,7 @@ export class KuzzleRequest {
    * @param message message displayed in the warning
    */
   addDeprecation (version: string, message: string) {
-    if (process.env.NODE_ENV !== 'development') {
+    if (global.NODE_ENV !== 'development') {
       return;
     }
 

lib/core/network/protocols/mqtt.js

@@ -213,11 +213,12 @@ class MqttProtocol extends Protocol {
   _respond (client, response) {
     debug('sending response: %o', response.content);
 
-    if (process.env.NODE_ENV === 'development' && this.config.developmentMode) {
+    if (global.NODE_ENV === 'development' && this.config.developmentMode) {
       this.broadcast({
         channels: [this.config.responseTopic],
         payload: response.content,
       });
+
       return;
     }
 

lib/core/network/removeErrorStack.js

@@ -23,6 +23,8 @@
 
 const util = require('util');
 
+const { hilightUserCode } = require('../../util/stackTrace');
+
 /**
  * utility method: must be invoked by all protocols to remove stack traces
  * from payloads before sending them
@@ -31,12 +33,20 @@ const util = require('util');
  * @returns {*} return the data minus the stack trace
  */
 module.exports = data => {
-  if (process.env.NODE_ENV !== 'development') {
-    if (util.isError(data)) {
-      delete data.stack;
+  if (util.isError(data)) {
+    if (global.NODE_ENV !== 'development') {
+      data.stack = undefined;
+    }
+    else {
+      data.stack = data.stack.split('\n').map(hilightUserCode).join('\n');
+    }
+  }
+  else if (data && data.content && data.content.error) {
+    if (global.NODE_ENV !== 'development') {
+      data.content.error.stack = undefined;
     }
-    else if (data && data.content && data.content.error) {
-      delete data.content.error.stack;
+    else {
+      data.content.error.stack = data.content.error.stack.split('\n').map(hilightUserCode).join('\n');
     }
   }
 

lib/core/shared/sdk/funnelProtocol.js

@@ -25,6 +25,7 @@ const { KuzzleEventEmitter } = require('kuzzle-sdk');
 
 const { Request } = require('../../../api/request');
 const kerror = require('../../../kerror');
+const { hilightUserCode } = require('../../../util/stackTrace');
 
 class FunnelProtocol extends KuzzleEventEmitter {
   constructor(user = null) {
@@ -57,12 +58,6 @@ class FunnelProtocol extends KuzzleEventEmitter {
    *  Hydrate the user and execute SDK query
    */
   async query (request) {
-    // Keep a more complete stacktrace in development
-    let stack;
-    if (process.env.NODE_ENV !== 'production') {
-      stack = Error().stack;
-    }
-
     if (! this.requestOptions) {
       this.requestOptions = {
         connection: {
@@ -81,9 +76,8 @@ class FunnelProtocol extends KuzzleEventEmitter {
       return { result };
     }
     catch (error) {
-      // enhance stacktrace
-      if (process.env.NODE_ENV !== 'production') {
-        error.stack = stack;
+      if (error.stack) {
+        error.stack = error.stack.split('\n').map(hilightUserCode).join('\n');
       }
 
       throw error;

lib/kerror/index.js

@@ -28,6 +28,7 @@ const _ = require('lodash');
 
 const { domains } = require('./codes');
 const errors = require('./errors');
+const { hilightUserCode } = require('../util/stackTrace');
 
 /**
  * Gets this file name in the exact same format than the one printed in the
@@ -113,17 +114,19 @@ function cleanStackTrace (error) {
   // we keep the new error instantiation line ("new ...Error (") on purpose:
   // this will allow us to replace it without inserting a new line in the array,
   // saving us from building a new array
-  const newStack = error.stack.split('\n').filter((line, index) => {
-    if (index < messageLength) {
-      return true;
-    }
+  const newStack = error.stack.split('\n')
+    .filter((line, index) => {
+      if (index < messageLength) {
+        return true;
+      }
 
-    // filter all lines related to the kerror object
-    return !line.includes(currentFileName);
-  });
+      // filter all lines related to the kerror object
+      return !line.includes(currentFileName);
+    })
+    .map(hilightUserCode);
 
   // insert a deletion message in place of the new error instantiation line
-  newStack[messageLength] = '    [...Kuzzle internal calls deleted...]';
+  newStack[messageLength] = '      [...Kuzzle internal calls deleted...]';
 
   error.stack = newStack.join('\n');
 }

lib/kuzzle/kuzzle.js

@@ -299,9 +299,9 @@ class Kuzzle extends KuzzleEventEmitter {
       // Crashing on an unhandled rejection is a good idea during development
       // as it helps spotting code errors. And according to the warning messages,
       // this is what Node.js will do automatically in future versions anyway.
-      if (process.env.NODE_ENV === 'development') {
+      if (global.NODE_ENV === 'development') {
         this.log.error('Kuzzle caught an unhandled rejected promise and will shutdown.');
-        this.log.error('This behavior is only triggered if NODE_ENV is set to "development"');
+        this.log.error('This behavior is only triggered if global.NODE_ENV is set to "development"');
 
         throw reason;
       }

lib/service/storage/elasticsearch.js

@@ -142,7 +142,7 @@ class ElasticSearch extends Service {
       return;
     }
 
-    if ( process.env.NODE_ENV === 'production'
+    if ( global.NODE_ENV === 'production'
       && this._config.commonMapping.dynamic === 'true'
     ) {
       global.kuzzle.log.warn([
@@ -845,7 +845,7 @@ class ElasticSearch extends Service {
       id,
       index: esIndex,
     };
-    
+
     try {
       debug('DeleteFields document: %o', esRequest);
       const { body } = await this._client.get(esRequest);

lib/service/storage/esWrapper.js

@@ -158,7 +158,7 @@ class ESWrapper {
       return error;
     }
 
-    if (process.env.NODE_ENV === 'production') {
+    if (global.NODE_ENV === 'production') {
       global.kuzzle.log.info(JSON.stringify({
         message: `Elasticsearch Client error: ${error.message}`,
         // /!\ not all ES error classes have a "meta" property

lib/types/Deprecation.ts

@@ -21,7 +21,7 @@
 
 /**
  * Deprecation warning about a specific feature.
- * Only available in developement mode (NODE_ENV=development)
+ * Only available in developement mode (global.NODE_ENV=development)
  */
 export type Deprecation = {
   /**

lib/types/Global.ts

@@ -0,0 +1,16 @@
+/* eslint-disable @typescript-eslint/no-namespace */
+
+declare global {
+  namespace NodeJS {
+    interface Global {
+      kuzzle: any;
+      NODE_ENV: string;
+    }
+  }
+}
+
+global.NODE_ENV = process.env.NODE_ENV;
+
+export {};
+
+/* eslint-enable @typescript-eslint/no-namespace */

lib/types/ResponsePayload.ts

@@ -43,7 +43,7 @@ export type ResponseErrorPayload = {
   status: number;
 
   /**
-   * Error stacktrace (only if NODE_ENV=development)
+   * Error stacktrace (only if global.NODE_ENV=development)
    */
   stack?: string;
 };

lib/types/index.ts

@@ -29,3 +29,4 @@ export * from './EventHandler';
 export * from './User';
 export * from './Token';
 export * from './InternalLogger';
+export * from './Global';

lib/util/deprecate.js

@@ -22,7 +22,7 @@
 'use strict';
 
 const deprecationWarning = (logger, ...args) => {
-  if (process.env.NODE_ENV !== 'production') {
+  if (global.NODE_ENV !== 'production') {
     logger.warn('DEPRECATION WARNING');
     logger.warn(...args);
   }
@@ -49,7 +49,7 @@ const warnIfDeprecated = (logger, deprecations, member) => {
 };
 
 const deprecateProperties = (logger, target, deprecations = {}) => {
-  if (process.env.NODE_ENV === 'production') {
+  if (global.NODE_ENV === 'production') {
     return target;
   }
 

lib/util/didYouMean.js

@@ -24,7 +24,7 @@
 const didYouMean = require('didyoumean');
 
 function printDidYouMean(...args) {
-  if (process.env.NODE_ENV === 'production') {
+  if (global.NODE_ENV === 'production') {
     return '';
   }
 

lib/util/stackTrace.js

@@ -0,0 +1,53 @@
+/*
+ * Kuzzle, a backend software, self-hostable and ready to use
+ * to power modern apps
+ *
+ * Copyright 2015-2020 Kuzzle
+ * mailto: support AT kuzzle.io
+ * website: http://kuzzle.io
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * https://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+'use strict';
+
+/**
+  * Hilight user code
+  *
+  * e.g.
+  *     at BackendController._add (/home/kuzzle/lib/core/application/backend.ts:261:28)
+  *     at BackendController.register (/home/kuzzle/lib/core/application/backend.ts:187:10)
+  * >  at registerFoo (/home/aschen/projets/app/test.ts:12:18)
+  * >  at init (/home/aschen/projets/app/test.ts:8:3)
+  *     at Module._compile (internal/modules/cjs/loader.js:1133:30)
+  */
+function hilightUserCode (line) {
+  // ignore first line (error message) or already enhanced
+  if (! line.includes(' at ') || line.startsWith('>')) {
+    return line;
+  }
+
+  if ( line.includes('kuzzle/lib/') // ignore kuzzle code
+    || (line.indexOf('at /') === -1 && line.charAt(line.indexOf('(') + 1) !== '/') // ignore node internal
+    || line.includes('node_modules') // ignore dependencies
+  ) {
+    return '   ' + line;
+  }
+
+  // hilight user code
+  return '>' + line;
+}
+
+module.exports = {
+  hilightUserCode,
+};

package.json

@@ -67,7 +67,7 @@
     "koncorde": "^3.0.0",
     "kuzzle-plugin-auth-passport-local": "^6.2.0",
     "kuzzle-plugin-logger": "^2.0.7",
-    "kuzzle-sdk": "^7.4.9",
+    "kuzzle-sdk": "^7.5.2",
     "kuzzle-vault": "^2.0.0",
     "lodash": "4.17.20",
     "moment": "^2.29.1",

plugins/available/kuzzle-plugin-cluster/lib/index.js

@@ -839,10 +839,10 @@ class KuzzleCluster {
     // Crashing on an unhandled rejection is a good idea during development
     // as it helps spotting code errors. And according to the warning messages,
     // this is what Node.js will do automatically in future versions anyway.
-    if (process.env.NODE_ENV === 'development') {
+    if (global.NODE_ENV === 'development') {
       process.on('unhandledRejection', () => {
         this.log('error', 'Kuzzle caught an unhandled rejected promise and will shutdown.');
-        this.log('error', 'This behavior is only triggered if NODE_ENV is set to "development"');
+        this.log('error', 'This behavior is only triggered if global.NODE_ENV is set to "development"');
         this._onShutDown('unhandledRejection');
       });
     }