Add request ID in log

lib/api/funnel.js

@@ -21,26 +21,26 @@
 
 'use strict';
 
-const
-  debug = require('../util/debug')('kuzzle:funnel'),
-  Bluebird = require('bluebird'),
-  Deque = require('denque'),
-  AuthController = require('./controllers/auth'),
-  BulkController = require('./controllers/bulk'),
-  CollectionController = require('./controllers/collection'),
-  DocumentController = require('./controllers/document'),
-  IndexController = require('./controllers/index'),
-  MemoryStorageController = require('./controllers/memoryStorage'),
-  RealtimeController = require('./controllers/realtime'),
-  SecurityController = require('./controllers/security'),
-  ServerController = require('./controllers/server'),
-  AdminController = require('./controllers/admin'),
-  errorsManager = require('../util/errors'),
-  { errors: { KuzzleError } } = require('kuzzle-common-objects'),
-  documentEventAliases = require('../config/documentEventAliases'),
-  DocumentExtractor = require('../util/DocumentExtractor'),
-  sdkCompatibility = require('../config/sdkCompatibility'),
-  RateLimiter = require('./rateLimiter');
+const Bluebird = require('bluebird');
+const Deque = require('denque');
+
+const debug = require('../util/debug')('kuzzle:funnel');
+const AuthController = require('./controllers/auth');
+const BulkController = require('./controllers/bulk');
+const CollectionController = require('./controllers/collection');
+const DocumentController = require('./controllers/document');
+const IndexController = require('./controllers/index');
+const MemoryStorageController = require('./controllers/memoryStorage');
+const RealtimeController = require('./controllers/realtime');
+const SecurityController = require('./controllers/security');
+const ServerController = require('./controllers/server');
+const AdminController = require('./controllers/admin');
+const errorsManager = require('../util/errors');
+const { errors: { KuzzleError } } = require('kuzzle-common-objects');
+const documentEventAliases = require('../config/documentEventAliases');
+const DocumentExtractor = require('../util/DocumentExtractor');
+const sdkCompatibility = require('../config/sdkCompatibility');
+const RateLimiter = require('./rateLimiter');
 
 const processError = errorsManager.wrap('api', 'process');
 
@@ -268,33 +268,37 @@ class Funnel {
 
     let _request;
 
-    this.checkRights(request)
-      .then(modifiedRequest => {
-        _request = modifiedRequest;
-        return this.rateLimiter.isAllowed(_request);
-      })
-      .then(allowed => {
-        if (!allowed) {
-          throw processError.get('too_many_requests');
-        }
+    this.kuzzle.asyncStore.run(() => {
+      this.kuzzle.asyncStore.set('REQUEST', request);
+
+      this.checkRights(request)
+        .then(modifiedRequest => {
+          _request = modifiedRequest;
+          return this.rateLimiter.isAllowed(_request);
+        })
+        .then(allowed => {
+          if (!allowed) {
+            throw processError.get('too_many_requests');
+          }
 
-        return this.processRequest(_request);
-      })
-      .then(processResult => {
-        debug('Request %s successfully executed. Result: %a',
-          request.id,
-          processResult);
-
-        callback(null, processResult);
-
-        // disables a bluebird warning in dev. mode triggered when
-        // a promise is created and not returned
-        return null;
-      })
-      .catch(err => {
-        debug('Error processing request %s: %a', request.id, err);
-        return this._executeError(err, request, true, callback);
-      });
+          return this.processRequest(_request);
+        })
+        .then(processResult => {
+          debug('Request %s successfully executed. Result: %a',
+            request.id,
+            processResult);
+
+          callback(null, processResult);
+
+          // disables a bluebird warning in dev. mode triggered when
+          // a promise is created and not returned
+          return null;
+        })
+        .catch(err => {
+          debug('Error processing request %s: %a', request.id, err);
+          return this._executeError(err, request, true, callback);
+        });
+    });
 
     return 0;
   }

lib/kuzzle.js

@@ -52,6 +52,7 @@ const StorageEngine = require('./core/storage/storageEngine');
 const runShutdown = require('./util/shutdown');
 const Logger = require('./util/log');
 const Promback = require('./util/promback');
+const AsyncStore = require('./util/asyncStore');
 const memoize = require('./util/memoize');
 
 
@@ -173,6 +174,9 @@ class Kuzzle extends EventEmitter {
 
     // Vault component (will be initialized after bootstrap)
     this.vault = null;
+
+    // Async Local Storage wrapper
+    this.asyncStore = new AsyncStore(this);
   }
 
   /**

lib/util/asyncStore.js

@@ -0,0 +1,116 @@
+/*
+ * 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';
+
+const assert = require('assert');
+const { AsyncLocalStorage } = require('async_hooks');
+
+class AsyncStore {
+  constructor (kuzzle) {
+    this._kuzzle = kuzzle;
+
+    this._asyncLocalStorage = new AsyncLocalStorage();
+  }
+
+  /**
+   * Run the provided method with an async store context
+   *
+   * @param {Function} callback
+   */
+  run (callback) {
+    this._asyncLocalStorage.run(new Map(), callback);
+  }
+
+  /**
+   * Returns true if an async store exists
+   * for the current asynchronous context
+   */
+  exists () {
+    return Boolean(this._asyncLocalStorage.getStore());
+  }
+
+  /**
+   * Sets a value in the current async store
+   *
+   * @param {String} key
+   * @param {any} value
+   */
+  set (key, value) {
+    return this._getStore().set(key, value);
+  }
+
+  /**
+   * Gets a value from the current async store
+   *
+   * @param {String} key
+   *
+   * @returns {any} value
+   */
+  get (key) {
+    return this._getStore().get(key);
+  }
+
+  /**
+   * Checks if a value exists in the current async store
+   *
+   * @param {String} key
+   *
+   * @returns {Boolean}
+   */
+  has (key) {
+    return this._getStore().has(key);
+  }
+
+  _getStore () {
+    const store = this._asyncLocalStorage.getStore();
+
+    assert(Boolean(store), 'Associated AsyncStore is not set');
+
+    return store;
+  }
+}
+
+
+class AsyncStoreStub {
+  constructor () {}
+
+  run (callback) {
+    callback();
+  }
+
+  exists () {
+    return false;
+  }
+
+  set () {}
+
+  get () {}
+
+  has () {}
+}
+
+if (process.version >= 'v14.0.0') {
+  module.exports = AsyncStore;
+}
+else {
+  module.exports = AsyncStoreStub;
+}

lib/util/log.js

@@ -22,13 +22,13 @@
 'use strict';
 
 class Logger {
-  constructor(eventEmitter) {
-    this.eventEmitter = eventEmitter;
+  constructor(kuzzle) {
+    this.kuzzle = kuzzle;
     this.logMethods = ['info', 'warn', 'error', 'silly', 'debug', 'verbose'];
 
     this._useConsole();
 
-    this.eventEmitter.once('core:kuzzleStart', this._useLogger.bind(this));
+    this.kuzzle.once('core:kuzzleStart', this._useLogger.bind(this));
   }
 
   _useConsole() {
@@ -42,7 +42,16 @@ class Logger {
   _useLogger() {
     // when kuzzle has started, use the event to dispatch logs
     for (const method of this.logMethods) {
-      this[method] = (...args) => this.eventEmitter.emit(`log:${method}`, args);
+      this[method] = message => {
+        if (this.kuzzle.asyncStore.exists() && this.kuzzle.asyncStore.has('REQUEST')) {
+          const request = this.kuzzle.asyncStore.get('REQUEST');
+
+          this.kuzzle.emit(`log:${method}`, `[${request.id}] ${message}`);
+        }
+        else {
+          this.kuzzle.emit(`log:${method}`, message);
+        }
+      };
     }
   }
 }