SNOW-1801434 add GUID to request in node.js driver

lib/configuration/client_configuration.js

@@ -259,7 +259,7 @@ function ConfigurationUtil(fsPromisesModule, processModule) {
   }
 
   async function searchForConfigInDefaultDirectories() {
-    Logger.getInstance().debug(`Searching for config in default directories: ${defaultDirectories}`);
+    Logger.getInstance().debug(`Searching for config in default directories: ${JSON.stringify(defaultDirectories)}`);
     for (const directory of defaultDirectories) {
       const configPath = await searchForConfigInDictionary(directory.dir, directory.dirDescription);
       if (exists(configPath)) {

lib/connection/connection.js

@@ -7,7 +7,7 @@ const Url = require('url');
 const QueryString = require('querystring');
 const QueryStatus = require('../constants/query_status');
 
-const LoggingUtil = require('../logger/logging_utils');
+const LoggingUtil = require('../logger/logging_util');
 const Util = require('../util');
 const Errors = require('../errors');
 const ErrorCodes = Errors.codes;
@@ -153,7 +153,7 @@ function Connection(context) {
 
   this.heartbeat = callback => {
     Logger.getInstance().trace('Issuing heartbeat call');
-    const requestID = uuidv4();
+    const requestId = uuidv4();
 
     services.sf.request(
       {
@@ -163,7 +163,7 @@ function Connection(context) {
             pathname: '/session/heartbeat',
             search: QueryString.stringify(
               {
-                requestId: requestID
+                requestId: requestId
               })
           }),
         callback: Util.isFunction(callback) ? callback : function (err, body) {

lib/constants/sf_params.js

@@ -0,0 +1,2 @@
+exports.paramsNames = {};
+exports.paramsNames.SF_REQUEST_GUID = 'request_guid';

lib/http/base.js

@@ -5,8 +5,10 @@
 const zlib = require('zlib');
 const Util = require('../util');
 const Logger = require('../logger');
+const ExecutionTimer = require('../logger/execution_timer');
 const axios = require('axios');
 const URL = require('node:url').URL;
+const requestUtil = require('./request_util');
 
 const DEFAULT_REQUEST_TIMEOUT = 360000;
 
@@ -18,6 +20,7 @@ const DEFAULT_REQUEST_TIMEOUT = 360000;
  */
 function HttpClient(connectionConfig) {
   // save the connection config
+  Logger.getInstance().trace('Initializing base HttpClient with connection config');
   this._connectionConfig = connectionConfig;
 }
 
@@ -29,42 +32,56 @@ function HttpClient(connectionConfig) {
  * @returns {Object} an object representing the request that was issued.
  */
 HttpClient.prototype.request = function (options) {
-  let request;
+  Logger.getInstance().trace('Request%s - preparing for sending.', requestUtil.describeRequestFromOptions(options));
+
+  let requestPromise;
   const requestOptions = prepareRequestOptions.call(this, options);
   let sendRequest = async function sendRequest() {
-    request = axios.request(requestOptions).then(response => {
+    Logger.getInstance().trace('Request%s - sending.', requestUtil.describeRequestFromOptions(requestOptions));
+    const timer = new ExecutionTimer().start();
+    requestPromise = axios.request(requestOptions).then(response => {
+      const httpResponseTime = timer.getDuration();
+      Logger.getInstance().debug('Request%s - response received after %s milliseconds with status %s.', requestUtil.describeRequestFromOptions(requestOptions), httpResponseTime, response.status);
       sanitizeAxiosResponse(response);
       if (Util.isFunction(options.callback)) {
+        Logger.getInstance().trace('Request%s - calling callback function.', requestUtil.describeRequestFromOptions(requestOptions));
         return options.callback(null, normalizeResponse(response), response.data);
       } else {
-        Logger.getInstance().trace(`Callback function was not provided for the call to ${options.url}`);
+        Logger.getInstance().trace('Request%s - callback function was not provided.', requestUtil.describeRequestFromOptions(requestOptions));
         return null;
       }
     }).catch(err => {
+      const httpResponseTime = timer.getDuration();
+      Logger.getInstance().debug('Request%s - failed after %s milliseconds.', requestUtil.describeRequestFromOptions(requestOptions), httpResponseTime);
       sanitizeAxiosError(err);
       if (Util.isFunction(options.callback)) {
         if (err.response) { // axios returns error for not 2xx responses - let's unwrap it
+          Logger.getInstance().trace('Request%s - calling callback function for error from response. Received code: ', requestUtil.describeRequestFromOptions(requestOptions), err.response.status);
           options.callback(null, normalizeResponse(err.response), err.response.data);
         } else {
+          Logger.getInstance().trace('Request%s - calling callback function for error without response.', requestUtil.describeRequestFromOptions(requestOptions));
           options.callback(err, normalizeResponse(null), null);
         }
         return null;
       } else {
+        Logger.getInstance().warn('Request%s - callback function was not provided. Error will be re-raised.', requestUtil.describeRequestFromOptions(requestOptions));
         throw err;
       }
     });
   };
   sendRequest = sendRequest.bind(this);
 
-  Logger.getInstance().trace(`CALL ${requestOptions.method} with timeout ${requestOptions.timeout}: ${requestOptions.url}`);
+  Logger.getInstance().trace('Request%s - issued for the next tick.', requestUtil.describeRequestFromOptions(requestOptions));
   process.nextTick(sendRequest);
 
   // return an externalized request object that only contains
   // methods we're comfortable exposing to the outside world
   return {
     abort: function () {
-      if (request) {
-        request.abort();
+      if (requestPromise) {
+        Logger.getInstance().trace('Request%s - aborting.', requestUtil.describeRequestFromOptions(requestOptions));
+        // TODO: This line won't work - promise has no method called abort
+        requestPromise.abort();
       }
     }
   };
@@ -78,21 +95,38 @@ HttpClient.prototype.request = function (options) {
  * @returns {Object} an object representing the request that was issued.
  */
 HttpClient.prototype.requestAsync = async function (options) {
+  Logger.getInstance().trace('Request%s - preparing for async sending.', requestUtil.describeRequestFromOptions(options));
+  const timer = new ExecutionTimer();
   try {
     const requestOptions = prepareRequestOptions.call(this, options);
+
+    timer.start();
     const response = await axios.request(requestOptions);
-    if (Util.isString(response['data']) &&
-        response['headers']['content-type'] === 'application/json') {
-      response['data'] = JSON.parse(response['data']);
-    }
+    const httpResponseTime = timer.getDuration();
+    Logger.getInstance().debug('Request%s - response received after %s milliseconds with status %s.', requestUtil.describeRequestFromOptions(requestOptions), httpResponseTime, response.status);
+    parseResponseData(response);
     sanitizeAxiosResponse(response);
     return response;
   } catch (err) {
+    const httpResponseTime = timer.getDuration();
+    Logger.getInstance().debug('Request%s - failed after %s milliseconds. Error will be re-raised.', requestUtil.describeRequestFromOptions(options), httpResponseTime);
     sanitizeAxiosError(err);
     throw err;
   }
 };
 
+function parseResponseData(response) {
+  Logger.getInstance().trace('Request%s - parsing response data.', requestUtil.describeRequestFromResponse(response));
+  parseIfJSONData(response);
+}
+
+function parseIfJSONData(response) {
+  if (Util.isString(response['data']) &&
+      response['headers']['content-type'] === 'application/json') {
+    response['data'] = JSON.parse(response['data']);
+  }
+}
+
 /**
  * Issues an HTTP POST request.
  *
@@ -184,6 +218,7 @@ HttpClient.prototype.getAgent = function () {
 module.exports = HttpClient;
 
 function sanitizeAxiosResponse(response) {
+  Logger.getInstance().trace('Request%s - sanitizing response data.', requestUtil.describeRequestFromResponse(response));
   response.request = undefined;
   if (response.config) {
     response.config.data = undefined;
@@ -195,11 +230,13 @@ function sanitizeAxiosError(error) {
   error.request = undefined;
   error.config = undefined;
   if (error.response) {
+    Logger.getInstance().trace('Request%s - sanitizing response error data.', requestUtil.describeRequestFromResponse(error.response));
     sanitizeAxiosResponse(error.response);
   }
 }
 
 function prepareRequestOptions(options) {
+  Logger.getInstance().trace('Request%s - constructing options.', requestUtil.describeRequestFromOptions(options));
   const headers = normalizeHeaders(options.headers) || {};
 
   const timeout = options.timeout ||
@@ -215,8 +252,11 @@ function prepareRequestOptions(options) {
       if (!err) {
         data = bufferCompressed;
         headers['Content-Encoding'] = 'gzip';
+        Logger.getInstance().debug('Request%s - original buffer length: %d bytes. Compressed buffer length: %d bytes.', requestUtil.describeRequestFromOptions(options), bufferUncompressed.buffer.byteLength, bufferCompressed.buffer.byteLength);
       } else {
-        Logger.getInstance().warn('Could not compress request data.');
+        // Logging 'err' variable value should not be done, since it may contain compressed customer's data.
+        // It can be added only for debugging purposes.
+        Logger.getInstance().warn('Request%s - could not compress request data.', requestUtil.describeRequestFromOptions(options));
       }
     });
   }
@@ -254,6 +294,7 @@ function prepareRequestOptions(options) {
     requestOptions.httpAgent = agent;
   }
 
+  Logger.getInstance().trace('Request%s - options - timeout: %s, retryDelay: %s, responseType: %s', requestUtil.describeRequestFromOptions(options), requestOptions.timeout, requestOptions.retryDelay, requestOptions.responseType);
   return requestOptions;
 }
 
@@ -266,10 +307,9 @@ function prepareRequestOptions(options) {
  * @returns {Object}
  */
 function normalizeHeaders(headers) {
-  let ret = headers;
-
+  Logger.getInstance().trace('Normalizing headers');
   if (Util.isObject(headers)) {
-    ret = {
+    const normalizedHeaders = {
       'user-agent': Util.userAgent
     };
 
@@ -288,15 +328,19 @@ function normalizeHeaders(headers) {
         headerNameLowerCase = headerName.toLowerCase();
         if ((headerNameLowerCase === 'accept') ||
           (headerNameLowerCase === 'content-type')) {
-          ret[headerNameLowerCase] = headers[headerName];
+          normalizedHeaders[headerNameLowerCase] = headers[headerName];
         } else {
-          ret[headerName] = headers[headerName];
+          normalizedHeaders[headerName] = headers[headerName];
         }
       }
     }
+    Logger.getInstance().trace('Headers were normalized');
+    return normalizedHeaders;
+  } else {
+    Logger.getInstance().trace('Headers were not an object. Original value will be returned.');
+    return headers;
   }
 
-  return ret;
 }
 
 /**
@@ -311,6 +355,7 @@ function normalizeHeaders(headers) {
 function normalizeResponse(response) {
   // if the response doesn't already have a getResponseHeader() method, add one
   if (response && !response.getResponseHeader) {
+    Logger.getInstance().trace('Request%s - normalizing.', requestUtil.describeRequestFromResponse(response));
     response.getResponseHeader = function (header) {
       return response.headers && response.headers[
         Util.isString(header) ? header.toLowerCase() : header];
@@ -323,4 +368,4 @@ function normalizeResponse(response) {
   }
 
   return response;
-}
+}