SNOW-1633278 connection layer (#911)

Author: sfc-gh-fpawlowski

lib/connection/connection.js

@@ -6,6 +6,7 @@ const Util = require('../util');
 const Errors = require('../errors');
 const SfService = require('../services/sf');
 const LargeResultSetService = require('../services/large_result_set');
+const Logger = require('../logger');
 
 /**
  * Creates a new ConnectionContext.
@@ -18,26 +19,31 @@ const LargeResultSetService = require('../services/large_result_set');
  */
 function ConnectionContext(connectionConfig, httpClient, config) {
   // validate input
+  Logger.getInstance().trace('Creating ConnectionContext object.');
   Errors.assertInternal(Util.isObject(connectionConfig));
   Errors.assertInternal(Util.isObject(httpClient));
 
   // if a config object was specified, verify
   // that it has all the information we need
   let sfServiceConfig;
   if (Util.exists(config)) {
+    Logger.getInstance().trace('ConnectionContext - validating received config.');
+
     Errors.assertInternal(Util.isObject(config));
     Errors.assertInternal(Util.isObject(config.services));
     Errors.assertInternal(Util.isObject(config.services.sf));
 
     sfServiceConfig = config.services.sf;
   }
+  Logger.getInstance().debug('ConnectionContext - received data was validated.');
 
   // create a map that contains all the services we'll be using
   const services =
     {
       sf: new SfService(connectionConfig, httpClient, sfServiceConfig),
       largeResultSet: new LargeResultSetService(connectionConfig, httpClient)
     };
+  Logger.getInstance().debug('ConnectionContext - services were instantiated.');
 
   /**
    * Returns the ConnectionConfig for use by the connection.

lib/connection/connection_context.js

@@ -32,15 +32,18 @@ function Core(options) {
 
   // set the logger instance
   Logger.setInstance(new (options.loggerClass)());
+  Logger.getInstance().trace('Logger was initialized.');
 
   // if a connection class is specified, it must be an object or function
   let connectionClass = options.connectionClass;
   if (Util.exists(connectionClass)) {
     Errors.assertInternal(
       Util.isObject(connectionClass) || Util.isFunction(connectionClass));
+    Logger.getInstance().debug('Connection class provided in driver core options will be used.');
   } else {
     // fall back to Connection
     connectionClass = Connection;
+    Logger.getInstance().debug('Connection class was not overridden. Default connection class will be used.');
   }
 
   const qaMode = options.qaMode;
@@ -64,27 +67,38 @@ function Core(options) {
     // Alternatively, if the connectionOptions includes token information then we will use that
     // instead of the username/password
 
+    Logger.getInstance().info('Creating new connection object');
+
     if (connectionOptions == null) {
+      Logger.getInstance().info('Connection options were not specified. Loading connection configuration.');
       try {
         connectionOptions = loadConnectionConfiguration();
       } catch ( error ) {
-        Logger.getInstance().debug(`Problem during reading connection configuration from file: ${error.message}`);
+        Logger.getInstance().error('Unable to load the connection configuration. Error: %s',  error.message);
         Errors.checkArgumentExists(Util.exists(connectionOptions),
           ErrorCodes.ERR_CONN_CREATE_MISSING_OPTIONS);
       }
     }
 
     const validateCredentials = !config && (connectionOptions && !connectionOptions.sessionToken);
+
     const connectionConfig =
       new ConnectionConfig(connectionOptions, validateCredentials, qaMode, clientInfo);
+    Logger.getInstance().debug('Connection configuration object created');
 
     // if an http client was specified in the options passed to the module, use
     // it, otherwise create a new HttpClient
     const httpClient = options.httpClient ||
       new options.httpClientClass(connectionConfig);
+    Logger.getInstance().debug('HttpClient setup finished');
+
 
-    return new connectionClass(
-      new ConnectionContext(connectionConfig, httpClient, config));
+    const connection = new connectionClass(
+      new ConnectionContext(connectionConfig, httpClient, config)
+    );
+
+    Logger.getInstance().info('Connection[id: %s] - connection object created successfully.', connection.getId());
+    return connection;
   };
 
   const instance =
@@ -124,13 +138,17 @@ function Core(options) {
        */
       deserializeConnection: function (options, serializedConnection) {
         // check for missing serializedConfig
+        Logger.getInstance().trace('Deserializing connection');
+
         Errors.checkArgumentExists(Util.exists(serializedConnection),
           ErrorCodes.ERR_CONN_DESERIALIZE_MISSING_CONFIG);
 
         // check for invalid serializedConfig
         Errors.checkArgumentValid(Util.isString(serializedConnection),
           ErrorCodes.ERR_CONN_DESERIALIZE_INVALID_CONFIG_TYPE);
 
+        Logger.getInstance().debug('Deserializing connection from string object');
+
         // try to json-parse serializedConfig
         let config;
         try {
@@ -140,6 +158,7 @@ function Core(options) {
           Errors.checkArgumentValid(Util.isObject(config),
             ErrorCodes.ERR_CONN_DESERIALIZE_INVALID_CONFIG_FORM);
         }
+        Logger.getInstance().debug('Connection deserialized successfully');
 
         return createConnection(options, config);
       },
@@ -152,6 +171,7 @@ function Core(options) {
        * @returns {String} a serialized version of the connection.
        */
       serializeConnection: function (connection) {
+        Logger.getInstance().trace('Connection[id: %s] - serializing connection.', connection.getId());
         return connection ? connection.serialize() : connection;
       },
 
@@ -161,11 +181,13 @@ function Core(options) {
        * @param {Object} options
        */
       configure: function (options) {
+        Logger.getInstance().debug('Configuring Snowflake core module.');
         const logLevel = extractLogLevel(options);
         const logFilePath = options.logFilePath;
         const additionalLogToConsole = options.additionalLogToConsole;
+
         if (logLevel != null || logFilePath) {
-          Logger.getInstance().debug(`Configuring logger with level: ${logLevel}, filePath: ${logFilePath}, additionalLogToConsole: ${additionalLogToConsole}`);
+          Logger.getInstance().info('Configuring logger with level: %s, filePath: %s, additionalLogToConsole: %s', logLevel, logFilePath, additionalLogToConsole);
           Logger.getInstance().configure(
             {
               level: logLevel,
@@ -181,6 +203,7 @@ function Core(options) {
             ErrorCodes.ERR_GLOBAL_CONFIGURE_INVALID_INSECURE_CONNECT);
 
           GlobalConfig.setInsecureConnect(insecureConnect);
+          Logger.getInstance().debug('Setting insecureConnect to value from core options: %s', insecureConnect);
         }
 
         const ocspFailOpen = options.ocspFailOpen;
@@ -189,6 +212,7 @@ function Core(options) {
             ErrorCodes.ERR_GLOBAL_CONFIGURE_INVALID_OCSP_MODE);
 
           GlobalConfig.setOcspFailOpen(ocspFailOpen);
+          Logger.getInstance().debug('Setting ocspFailOpen to value from core options: %s ', ocspFailOpen);
         }
 
         const jsonColumnVariantParser = options.jsonColumnVariantParser;
@@ -197,6 +221,7 @@ function Core(options) {
             ErrorCodes.ERR_GLOBAL_CONFIGURE_INVALID_JSON_PARSER);
 
           GlobalConfig.setJsonColumnVariantParser(jsonColumnVariantParser);
+          Logger.getInstance().debug('Setting JSON Column Variant Parser to value from core options');
         }
 
         const xmlColumnVariantParser = options.xmlColumnVariantParser;
@@ -206,8 +231,10 @@ function Core(options) {
             ErrorCodes.ERR_GLOBAL_CONFIGURE_INVALID_XML_PARSER);
 
           GlobalConfig.setXmlColumnVariantParser(xmlColumnVariantParser);
+          Logger.getInstance().debug('Setting XML Column Variant Parser to value from core options');
         } else if (Util.exists(xmlParserConfig)) {
           GlobalConfig.createXmlColumnVariantParserWithParameters(xmlParserConfig);
+          Logger.getInstance().debug('Creating XML Column Variant Parser with parameters from core options');
         }
 
         const keepAlive = options.keepAlive;
@@ -216,6 +243,7 @@ function Core(options) {
             ErrorCodes.ERR_GLOBAL_CONFIGURE_INVALID_KEEP_ALIVE);
 
           GlobalConfig.setKeepAlive(keepAlive);
+          Logger.getInstance().debug('Setting keepAlive to value from core options: %s', keepAlive);
         }
 
         const useEnvProxy = options.useEnvProxy;
@@ -232,7 +260,8 @@ function Core(options) {
             ErrorCodes.ERR_GLOBAL_CONFIGURE_INVALID_CUSTOM_CREDENTIAL_MANAGER);
 
           GlobalConfig.setCustomCredentialManager(customCredentialManager);
-        } 
+          Logger.getInstance().debug('Setting customCredentialManager to value from core options %s', customCredentialManager);
+        }
       }
     };
 
@@ -275,15 +304,17 @@ function Core(options) {
      * @returns {Object}
      */
     this.create = function () {
+      Logger.getInstance().debug('Creating new connection from factory.');
       const connection = new createConnection(connectionOptions);
 
       return new Promise((resolve, reject) => {
         connection.connect(
           function (err, conn) {
             if (err) {
-              Logger.getInstance().error('Unable to connect: ' + err.message);
+              Logger.getInstance().error('Connection[id: %s] - Unable to connect. Error: %s', conn.getId(), err.message);
               reject(new Error(err.message));
             } else {
+              Logger.getInstance().debug('Connection[id: %s] - connected successfully. Callback called.', conn.getId());
               resolve(conn);
             }
           }
@@ -299,10 +330,13 @@ function Core(options) {
     * @returns {Object}
     */
     this.destroy = function (connection) {
+      Logger.getInstance().debug('Destroying connection instance.');
       return new Promise((resolve) => {
-        connection.destroy(function (err) {
+        connection.destroy(function (err, conn) {
           if (err) {
-            Logger.getInstance().error('Unable to disconnect: ' + err.message);
+            Logger.getInstance().error('Connection[id: %s] - disconnecting failed with error: %s', conn.getId(), err.message);
+          } else {
+            Logger.getInstance().debug('Connection[id: %s] - connection disconnected successfully. Callback called.', conn.getId());
           }
           resolve();
         });
@@ -317,6 +351,7 @@ function Core(options) {
     * @returns {Boolean}
     */
     this.validate = async function (connection) {
+      Logger.getInstance().debug('Connection[id: %s] - validating connection instance', connection.getId());
       return await connection.isValidAsync();
     };
   }
@@ -330,19 +365,25 @@ function Core(options) {
   * @returns {Object}
   */
   const createPool = function createPool(connectionOptions, poolOptions) {
+    Logger.getInstance().info('Creating connection pool with provided options');
+
     const connectionPool = GenericPool.createPool(
       new ConnectionFactory(connectionOptions),
       poolOptions
     );
+    Logger.getInstance().debug('Base for connection pool created');
 
     // avoid infinite loop if factory creation fails
     connectionPool.on('factoryCreateError', function (err) {
+      Logger.getInstance().error('Connection pool factory creation failed: %s',  err.message);
       const clientResourceRequest = connectionPool._waitingClientsQueue.dequeue();
       if (clientResourceRequest) {
         clientResourceRequest.reject(err);
       }
     });
 
+    Logger.getInstance().info('Connection pool object created successfully');
+
     return connectionPool;
   };
 

lib/core.js

@@ -0,0 +1,45 @@
+const { performance } = require('perf_hooks');
+const Logger = require('../logger');
+const Util = require('../util');
+
+function ExecutionTimer() {
+  let startTime = null;
+  let endTime = null;
+
+  // Private function to log and check if the timer was started
+  function wasStarted() {
+    return Util.exists(startTime);
+
+  }
+
+  this.start = function () {
+    startTime = performance.now();
+    endTime = null; // Reset endTime if the timer is reused
+    return this;
+  };
+
+
+  this.stop = function () {
+    if (!wasStarted()) {
+      // Returning this to allow chaining even after invalid call.
+      // startTime can be used to check, if any start point was ever recorded.
+      Logger.getInstance().debug('Tried to stop timer, that was not started');
+      return this;
+    }
+    endTime = performance.now();
+    return this;
+  };
+
+  // Get the duration in milliseconds
+  this.getDuration = function () {
+    if (!wasStarted()) {
+      return;
+    }
+    if (endTime === null) {
+      endTime = performance.now();
+    }
+    return endTime - startTime;
+  };
+}
+
+module.exports = ExecutionTimer;

lib/logger/execution_timer.js

@@ -0,0 +1,8 @@
+const Util = require('../util');
+
+exports.describePresence = function (valueToDescribe) {
+  const VAR_PROVIDED_TEXT = 'provided';
+  const VAR_NOT_PROVIDED_TEXT = 'not provided';
+
+  return Util.isNotEmptyAsString(valueToDescribe) ? VAR_PROVIDED_TEXT : VAR_NOT_PROVIDED_TEXT;
+};

lib/logger/logging_utils.js

@@ -71,6 +71,8 @@ function SecretDetector(customPatterns, mock) {
     '`' +
     String.raw`\{\|\}~]{8,})`,
     'gi');
+  const PASSCODE_PATTERN = new RegExp(String.raw`(passcode|otp|pin|otac)\s*([:=])\s*([0-9]{4,6})`, 'gi');
+
 
   function maskAwsKeys(text) {
     return text.replace(AWS_KEY_PATTERN, String.raw`$1$2****`);
@@ -100,6 +102,11 @@ function SecretDetector(customPatterns, mock) {
     return text.replace(PASSWORD_PATTERN, String.raw`$1$2****`);
   }
 
+  function maskPasscode(text) {
+    return text.replace(PASSCODE_PATTERN, String.raw`$1$2****`);
+  }
+
+
   /**
    * Masks any secrets.
    *
@@ -128,13 +135,15 @@ function SecretDetector(customPatterns, mock) {
       }
 
       maskedtxt =
-        maskConnectionToken(
-          maskPassword(
-            maskPrivateKeyData(
-              maskPrivateKey(
-                maskAwsToken(
-                  maskSasToken(
-                    maskAwsKeys(text)
+        maskPasscode(
+          maskConnectionToken(
+            maskPassword(
+              maskPrivateKeyData(
+                maskPrivateKey(
+                  maskAwsToken(
+                    maskSasToken(
+                      maskAwsKeys(text)
+                    )
                   )
                 )
               )

lib/secret_detector.js

@@ -892,4 +892,11 @@ exports.getNoProxyEnv = function () {
     return noProxy.split(',').join('|');
   }
   return undefined;
+};
+
+exports.isNotEmptyAsString = function (variable) {
+  if (typeof variable === 'string') {
+    return variable;
+  }
+  return exports.exists(variable);
 };

lib/util.js

@@ -5,7 +5,7 @@ const snowflake = require('../lib/snowflake');
 /**
  * @param logLevel one of OFF | ERROR | WARN | INFO | DEBUG | TRACE
  */
-exports.configureLogger = (logLevel = 'ERROR') => {
+exports.configureLogger = (logLevel = 'INFO') => {
   Logger.getInstance().closeTransports();
   Logger.setInstance(new NodeLogger({ filePath: 'STDOUT' }));
   snowflake.configure({ logLevel });