SNOW-1631790 transport layer

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;
@@ -43,15 +43,11 @@ function Connection(context) {
   Logger.getInstance().trace('Generated connection id: %s', id);
 
   Logger.getInstance().info(
-    'Creating Connection[id: %s] with host: %s, account: %s, accessUrl: %s, user: %s, '
-    + 'password is %s, role: %s, database: %s, schema: %s, warehouse: %s, region: %s, '
+    'Creating Connection[id: %s] with %s, password is %s, region: %s, '
     + 'authenticator: %s, ocsp mode: %s, os: %s, os version: %s',
     id,
-    connectionConfig.host, connectionConfig.account,
-    connectionConfig.accessUrl, connectionConfig.username,
+    connectionConfig.describeIdentityAttributes(),
     LoggingUtil.describePresence(connectionConfig.password),
-    connectionConfig.getRole(), connectionConfig.getDatabase(),
-    connectionConfig.getSchema(), connectionConfig.getWarehouse(),
     connectionConfig.region, connectionConfig.getAuthenticator(),
     connectionConfig.getClientEnvironment().OCSP_MODE,
     connectionConfig.getClientEnvironment().OS,
@@ -153,7 +149,7 @@ function Connection(context) {
 
   this.heartbeat = callback => {
     Logger.getInstance().trace('Issuing heartbeat call');
-    const requestID = uuidv4();
+    const requestId = uuidv4();
 
     services.sf.request(
       {
@@ -163,7 +159,7 @@ function Connection(context) {
             pathname: '/session/heartbeat',
             search: QueryString.stringify(
               {
-                requestId: requestID
+                requestId: requestId
               })
           }),
         callback: Util.isFunction(callback) ? callback : function (err, body) {

lib/connection/connection_config.js

@@ -16,6 +16,7 @@
 const RowMode = require('./../constants/row_mode');
 const DataTypes = require('./result/data_types');
 const Logger = require('../logger');
+const LoggingUtil = require('../logger/logging_util');
 const WAIT_FOR_BROWSER_ACTION_TIMEOUT = 120000;
 const DEFAULT_PARAMS =
 [
@@ -835,6 +836,33 @@
     return passcode;
   };
 
+  /**
+   * Returns attributes of Connection Config object that can be used to identify
+   * the connection, when ID is not available in the scope. This is not sufficient set,
+   * since multiple connections can be instantiated for the same config, but can be treated as a hint.
+   *
+   * @returns {string}
+   */
+  this.describeIdentityAttributes = function () {
+    return `host: ${this.host}, account: ${this.account}, accessUrl: ${this.accessUrl}, `
+        + `user: ${this.username}, role: ${this.getRole()}, database: ${this.getDatabase()}, `
+        + `schema: ${this.getSchema()}, warehouse: ${this.getWarehouse()}, ` + this.describeProxy();
+  };
+
+  /**
+   * @returns {string}
+   */
+  this.describeProxy = function () {
+    const proxy = this.getProxy();
+    if (Util.exists(proxy)) {
+      return `proxyHost: ${proxy.host}, proxyPort: ${proxy.port}, proxyUser: ${proxy.user}, `
+      + `proxyPassword is ${LoggingUtil.describePresence(proxy.password)}, `
+      + `proxyProtocol: ${proxy.protocol}, noProxy: ${proxy.noProxy}`;
+    } else {
+      return 'proxy was not configured';
+    }
+  };
+
   // save config options
   this.username = options.username;
   this.password = options.password;

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,8 @@
  */
 function HttpClient(connectionConfig) {
   // save the connection config
+  Logger.getInstance().trace('Initializing base HttpClient with Connection Config[%s]',
+    connectionConfig.describeIdentityAttributes());
   this._connectionConfig = connectionConfig;
 }
 
@@ -29,42 +33,56 @@
  * @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 +96,38 @@
  * @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 +219,7 @@
 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 +231,13 @@
   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 +253,11 @@
       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 +295,7 @@
     requestOptions.httpAgent = agent;
   }
 
+  Logger.getInstance().debug('Request%s - options - timeout: %s, retryDelay: %s, responseType: %s', requestUtil.describeRequestFromOptions(options), requestOptions.timeout, requestOptions.retryDelay, requestOptions.responseType);
   return requestOptions;
 }
 
@@ -266,10 +308,9 @@
  * @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 +329,19 @@
         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 +356,7 @@
 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 +369,4 @@
   }
 
   return response;
-}
+}

lib/http/browser.js

@@ -5,6 +5,7 @@
 const Util = require('../util');
 const request = require('browser-request');
 const Base = require('./base');
+const Logger = require('../logger');
 
 /**
  * Creates a client that can be used to make requests in the browser.
@@ -13,6 +14,8 @@ const Base = require('./base');
  * @constructor
  */
 function BrowserHttpClient(connectionConfig) {
+  Logger.getInstance().trace('Initializing BrowserHttpClient with Connection Config[%s]',
+    connectionConfig.describeIdentityAttributes());
   Base.apply(this, [connectionConfig]);
 }