From 2ec8d4a73daa037f3f69c7a9cf9d51e1ad3ac9a8 Mon Sep 17 00:00:00 2001 From: John Yun <140559986+sfc-gh-ext-simba-jy@users.noreply.github.com> Date: Thu, 5 Dec 2024 00:34:57 -0800 Subject: [PATCH 1/3] SNOW-1789759: NodeJS Support GCS region specific endpoint (#975) --- lib/file_transfer_agent/gcs_util.js | 11 +++- lib/file_transfer_agent/s3_util.js | 13 +++- test/unit/file_transfer_agent/gcs_test.js | 76 +++++++++++++++++++++++ test/unit/file_transfer_agent/s3_test.js | 57 ++++++++++++++++- 4 files changed, 151 insertions(+), 6 deletions(-) diff --git a/lib/file_transfer_agent/gcs_util.js b/lib/file_transfer_agent/gcs_util.js index 2a9cf251d..fc46557ac 100644 --- a/lib/file_transfer_agent/gcs_util.js +++ b/lib/file_transfer_agent/gcs_util.js @@ -69,8 +69,15 @@ function GCSUtil(httpclient, filestream) { } }); - const storage = new Storage({ interceptors_: interceptors }); - + //TODO: SNOW-1789759 hardcoded region will be replaced in the future + const isRegionalUrlEnabled = (stageInfo.region).toLowerCase() === 'me-central2' || stageInfo.useRegionalUrl; + let endPoint = null; + if (stageInfo['endPoint']) { + endPoint = stageInfo['endPoint']; + } else if (isRegionalUrlEnabled) { + endPoint = `storage.${stageInfo.region.toLowerCase()}.rep.googleapis.com`; + } + const storage = endPoint ? new Storage({ interceptors_: interceptors, apiEndpoint: endPoint }) : new Storage({ interceptors_: interceptors }); client = { gcsToken: gcsToken, gcsClient: storage }; } else { client = null; diff --git a/lib/file_transfer_agent/s3_util.js b/lib/file_transfer_agent/s3_util.js index 088d780b2..de3dfbc67 100644 --- a/lib/file_transfer_agent/s3_util.js +++ b/lib/file_transfer_agent/s3_util.js @@ -54,12 +54,19 @@ function S3Util(connectionConfig, s3, filestream) { this.createClient = function (stageInfo, useAccelerateEndpoint) { const stageCredentials = stageInfo['creds']; const securityToken = stageCredentials['AWS_TOKEN']; + const isRegionalUrlEnabled = stageInfo.useRegionalUrl || stageInfo.useS3RegionalUrl; + // if GS sends us an endpoint, it's likely for FIPS. Use it. let endPoint = null; if (stageInfo['endPoint']) { - endPoint = 'https://' + stageInfo['endPoint']; + endPoint = `https://${stageInfo['endPoint']}`; + } else { + if (stageInfo.region && isRegionalUrlEnabled) { + const domainSuffixForRegionalUrl = (stageInfo.region).toLowerCase().startsWith('cn-') ? 'amazonaws.com.cn' : 'amazonaws.com'; + endPoint = `https://s3.${stageInfo.region}.${domainSuffixForRegionalUrl}`; + } } - + const config = { apiVersion: '2006-03-01', region: stageInfo['region'], @@ -80,7 +87,7 @@ function S3Util(connectionConfig, s3, filestream) { } } if (proxy) { - const proxyAgent = getProxyAgent(proxy, new URL(connectionConfig.accessUrl), SNOWFLAKE_S3_DESTINATION); + const proxyAgent = getProxyAgent(proxy, new URL(connectionConfig.accessUrl), endPoint || SNOWFLAKE_S3_DESTINATION); config.requestHandler = new NodeHttpHandler({ httpAgent: proxyAgent, httpsAgent: proxyAgent diff --git a/test/unit/file_transfer_agent/gcs_test.js b/test/unit/file_transfer_agent/gcs_test.js index bd2de06e9..6ce0c84d9 100644 --- a/test/unit/file_transfer_agent/gcs_test.js +++ b/test/unit/file_transfer_agent/gcs_test.js @@ -64,6 +64,82 @@ describe('GCS client', function () { GCS = new SnowflakeGCSUtil(httpclient, filestream); }); + describe('GCS client endpoint testing', async function () { + const testCases = [ + { + name: 'when the useRegionalURL is only enabled', + stageInfo: { + endPoint: null, + useRegionalUrl: true, + region: 'mockLocation', + }, + result: 'https://storage.mocklocation.rep.googleapis.com' + }, + { + name: 'when the region is me-central2', + stageInfo: { + endPoint: null, + useRegionalUrl: false, + region: 'me-central2' + }, + result: 'https://storage.me-central2.rep.googleapis.com' + }, + { + name: 'when the region is me-central2 (mixed case)', + stageInfo: { + endPoint: null, + useRegionalUrl: false, + region: 'ME-cEntRal2' + }, + result: 'https://storage.me-central2.rep.googleapis.com' + }, + { + name: 'when the region is me-central2 (uppercase)', + stageInfo: { + endPoint: null, + useRegionalUrl: false, + region: 'ME-CENTRAL2' + }, + result: 'https://storage.me-central2.rep.googleapis.com' + }, + { + name: 'when the endPoint is specified', + stageInfo: { + endPoint: 'https://storage.specialEndPoint.rep.googleapis.com', + useRegionalUrl: false, + region: 'ME-cEntRal1' + }, + result: 'https://storage.specialEndPoint.rep.googleapis.com' + }, + { + name: 'when both the endPoint and the useRegionalUrl are specified', + stageInfo: { + endPoint: 'https://storage.specialEndPoint.rep.googleapis.com', + useRegionalUrl: true, + region: 'ME-cEntRal1' + }, + result: 'https://storage.specialEndPoint.rep.googleapis.com' + }, + { + name: 'when both the endPoint is specified and the region is me-central2', + stageInfo: { + endPoint: 'https://storage.specialEndPoint.rep.googleapis.com', + useRegionalUrl: true, + region: 'ME-CENTRAL2' + }, + result: 'https://storage.specialEndPoint.rep.googleapis.com' + }, + ]; + + testCases.forEach(({ name, stageInfo, result }) => { + it(name, () => { + const client = GCS.createClient({ ...stageInfo, ...meta.stageInfo, creds: { GCS_ACCESS_TOKEN: 'mockToken' } }); + assert.strictEqual(client.gcsClient.apiEndpoint, result); + } ); + + }); + }); + it('extract bucket name and path', async function () { const GCS = new SnowflakeGCSUtil(); diff --git a/test/unit/file_transfer_agent/s3_test.js b/test/unit/file_transfer_agent/s3_test.js index 244a84fbe..64bf0bf07 100644 --- a/test/unit/file_transfer_agent/s3_test.js +++ b/test/unit/file_transfer_agent/s3_test.js @@ -44,7 +44,7 @@ describe('S3 client', function () { before(function () { mock('s3', { - S3: function () { + S3: function (config) { function S3() { this.getObject = function () { function getObject() { @@ -57,6 +57,8 @@ describe('S3 client', function () { return new getObject; }; + + this.config = config; this.putObject = function () { function putObject() { this.then = function (callback) { @@ -82,6 +84,59 @@ describe('S3 client', function () { AWS = new SnowflakeS3Util(noProxyConnectionConfig, s3, filesystem); }); + describe('AWS client endpoint testing', async function () { + const originalStageInfo = meta.stageInfo; + const testCases = [ + { + name: 'when useS3RegionalURL is only enabled', + stageInfo: { + ...originalStageInfo, + useS3RegionalUrl: true, + endPoint: null, + }, + result: null + }, + { + name: 'when useS3RegionalURL and is enabled and domain starts with cn', + stageInfo: { + ...originalStageInfo, + useS3RegionalUrl: true, + endPoint: null, + region: 'cn-mockLocation' + }, + result: 'https://s3.cn-mockLocation.amazonaws.com.cn' + }, + { + name: 'when endPoint is enabled', + stageInfo: { + ...originalStageInfo, + endPoint: 's3.endpoint', + useS3RegionalUrl: false + }, + result: 'https://s3.endpoint' + }, + { + name: 'when both endPoint and useS3PReiongalUrl is valid', + stageInfo: { + ...originalStageInfo, + endPoint: 's3.endpoint', + useS3RegionalUrl: true, + + }, + result: 'https://s3.endpoint' + }, + ]; + + testCases.forEach(({ name, stageInfo, result }) => { + it(name, () => { + const client = AWS.createClient(stageInfo); + assert.strictEqual(client.config.endpoint, result); + } ); + + }); + }); + + it('extract bucket name and path', async function () { let result = extractBucketNameAndPath('sfc-eng-regression/test_sub_dir/'); assert.strictEqual(result.bucketName, 'sfc-eng-regression'); From cf7b3a3d7bcee69f0815e31a0b4b7b02486c556b Mon Sep 17 00:00:00 2001 From: Przemyslaw Motacki Date: Thu, 5 Dec 2024 10:52:11 +0100 Subject: [PATCH 2/3] SNOW-1843504 - Testing resubmitting requests using request id (#979) --- test/integration/testExecute.js | 67 ++++++++++++++++++++++++++++++++- test/integration/testUtil.js | 12 ++++++ 2 files changed, 78 insertions(+), 1 deletion(-) diff --git a/test/integration/testExecute.js b/test/integration/testExecute.js index 5f62b7a58..48f32357c 100644 --- a/test/integration/testExecute.js +++ b/test/integration/testExecute.js @@ -431,5 +431,70 @@ describe('Execute test - variant', function () { it(testCase.name, createItCallback(testCase, rowAsserts)); }); -}); + describe( 'connection.execute() Resubmitting requests using requestId and different connections', function () { + const createTable = 'create or replace table test_request_id(colA string)'; + let firstConnection; + let secondConnection; + before(async () => { + firstConnection = testUtil.createConnection(); + secondConnection = testUtil.createConnection(); + await testUtil.connectAsync(firstConnection); + await testUtil.connectAsync(secondConnection); + await testUtil.executeCmdAsync(firstConnection, createTable); + }); + + beforeEach(async () => { + await testUtil.executeCmdAsync(firstConnection, 'truncate table if exists test_request_id'); + }); + + after(async () => { + await testUtil.executeCmdAsync(firstConnection, 'drop table if exists test_request_id'); + await testUtil.destroyConnectionAsync(firstConnection); + await testUtil.destroyConnectionAsync(secondConnection); + }); + + it('Do not INSERT twice when the same request id and connection', async () => { + let result; + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'INSERT INTO test_request_id VALUES (\'testValue\');'); + const requestId = result.rowStatement.getRequestId(); + + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, + 'INSERT INTO test_request_id VALUES (\'testValue\');', + { requestId: requestId }); + assert.strictEqual(result.rowStatement.getRequestId(), requestId); + + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'SELECT * from test_request_id ;'); + assert.strictEqual(result.rows.length, 1); + }); + + it('Execute INSERT for the same request id and different connection', async () => { + let result; + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'INSERT INTO test_request_id VALUES (\'testValue\');'); + const requestId = result.rowStatement.getRequestId(); + + result = await testUtil.executeCmdAsyncWithAdditionalParameters(secondConnection, 'INSERT INTO test_request_id VALUES (\'testValue\');', { requestId: requestId }); + assert.strictEqual(result.rowStatement.getRequestId(), requestId); + + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'SELECT * from test_request_id ;'); + assert.strictEqual(result.rows.length, 2); + }); + + it('Execute SELECT for the same request id and different data', async () => { + await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'INSERT INTO test_request_id VALUES (\'testValue\');'); + let result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'SELECT * from test_request_id;'); + assert.strictEqual(result.rows.length, 1); + const requestId = result.rowStatement.getRequestId(); + + await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'INSERT INTO test_request_id VALUES (\'testValue\');'); + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'SELECT * from test_request_id;', { requestId: requestId }); + assert.strictEqual(result.rows.length, 1); + + result = await testUtil.executeCmdAsyncWithAdditionalParameters(firstConnection, 'SELECT * from test_request_id ;'); + assert.strictEqual(result.rows.length, 2); + }); + }); + + + +}); diff --git a/test/integration/testUtil.js b/test/integration/testUtil.js index 9348a3275..c15b61449 100644 --- a/test/integration/testUtil.js +++ b/test/integration/testUtil.js @@ -96,6 +96,18 @@ const executeCmdAsync = function (connection, sqlText, binds = undefined) { module.exports.executeCmdAsync = executeCmdAsync; +const executeCmdAsyncWithAdditionalParameters = function (connection, sqlText, additionalParameters) { + return new Promise((resolve, reject) => { + const executeParams = { ...{ + sqlText: sqlText, + complete: (err, rowStatement, rows) => + err ? reject(err) : resolve({ rowStatement: rowStatement, rows: rows }) + }, ...additionalParameters }; + connection.execute(executeParams); + }); +}; + +module.exports.executeCmdAsyncWithAdditionalParameters = executeCmdAsyncWithAdditionalParameters; /** * Drop tables one by one if exist - any connection error is ignored * @param connection Connection From b74508ba50b2d4ecfc94a701409440f909a8780b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Filip=20Paw=C5=82owski?= Date: Thu, 5 Dec 2024 12:45:27 +0100 Subject: [PATCH 3/3] SNOW-1631790 transport layer (#963) --- lib/configuration/client_configuration.js | 2 +- lib/connection/connection.js | 14 ++-- lib/connection/connection_config.js | 28 +++++++ lib/http/base.js | 82 +++++++++++++++---- lib/http/browser.js | 3 + lib/http/node.js | 49 +++++++---- lib/http/request_util.js | 26 ++++++ .../{logging_utils.js => logging_util.js} | 0 lib/secret_detector.js | 4 +- lib/services/sf.js | 2 +- test/unit/secret_detector_test.js | 59 +++++++++++++ 11 files changed, 221 insertions(+), 48 deletions(-) create mode 100644 lib/http/request_util.js rename lib/logger/{logging_utils.js => logging_util.js} (100%) diff --git a/lib/configuration/client_configuration.js b/lib/configuration/client_configuration.js index 370232008..49694f7d5 100644 --- a/lib/configuration/client_configuration.js +++ b/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)) { diff --git a/lib/connection/connection.js b/lib/connection/connection.js index 1e24e38a9..56c11af1b 100644 --- a/lib/connection/connection.js +++ b/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) { diff --git a/lib/connection/connection_config.js b/lib/connection/connection_config.js index 2bbec6519..3b0f7aef4 100644 --- a/lib/connection/connection_config.js +++ b/lib/connection/connection_config.js @@ -16,6 +16,7 @@ const levenshtein = require('fastest-levenshtein'); 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 @@ function ConnectionConfig(options, validateCredentials, qaMode, clientInfo) { 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; diff --git a/lib/http/base.js b/lib/http/base.js index e2d3b8445..a365f6e25 100644 --- a/lib/http/base.js +++ b/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 @@ const DEFAULT_REQUEST_TIMEOUT = 360000; */ 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 @@ 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 +96,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 +219,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 +231,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 +253,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 +295,7 @@ function prepareRequestOptions(options) { 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 @@ 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 +329,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 +356,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 +369,4 @@ function normalizeResponse(response) { } return response; -} \ No newline at end of file +} diff --git a/lib/http/browser.js b/lib/http/browser.js index a13f1828f..ce224d4de 100644 --- a/lib/http/browser.js +++ b/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]); } diff --git a/lib/http/node.js b/lib/http/node.js index 04e30b7c4..b5752313d 100644 --- a/lib/http/node.js +++ b/lib/http/node.js @@ -12,20 +12,22 @@ const Logger = require('../logger'); /** * Returns the delay time calculated by exponential backoff with - * decorrelated jitter. - * for more details, check out: + * decorrelated jitter. For more details, check out: * http://www.awsarchitectureblog.com/2015/03/backoff.html - * @param base minimum seconds - * @param cap maximum seconds - * @param previousSleep previous sleep time * @return {Number} number of milliseconds to wait before retrying again the request. */ NodeHttpClient.prototype.constructExponentialBackoffStrategy = function () { - let sleep = this._connectionConfig.getRetrySfStartingSleepTime(); + Logger.getInstance().trace('Calculating exponential backoff strategy'); + + const previousSleepTime = this._connectionConfig.getRetrySfStartingSleepTime(); + // maximum seconds const cap = this._connectionConfig.getRetrySfMaxSleepTime(); + // minimum seconds const base = 1; - sleep = Util.nextSleepTime(base, cap, sleep); - return sleep * 1000; + const nextSleepTime = Util.nextSleepTime(base, cap, previousSleepTime); + const nextSleepTimeInMilliseconds = nextSleepTime * 1000; + Logger.getInstance().trace('Calculated exponential backoff strategy sleep time: %d', nextSleepTimeInMilliseconds); + return nextSleepTimeInMilliseconds; }; /** @@ -35,6 +37,8 @@ NodeHttpClient.prototype.constructExponentialBackoffStrategy = function () { * @constructor */ function NodeHttpClient(connectionConfig) { + Logger.getInstance().trace('Initializing NodeHttpClient with Connection Config[%s]', + connectionConfig.describeIdentityAttributes()); Base.apply(this, [connectionConfig]); } @@ -43,26 +47,28 @@ Util.inherits(NodeHttpClient, Base); const httpsAgentCache = new Map(); function getFromCacheOrCreate(agentClass, options, agentId) { + Logger.getInstance().trace('Agent[id: %s] - trying to retrieve from cache or create.', agentId); let agent = {}; function createAgent(agentClass, agentOptions, agentId) { + Logger.getInstance().trace('Agent[id: %s] - creating a new agent instance.', agentId); const agent = agentClass(agentOptions); httpsAgentCache.set(agentId, agent); - Logger.getInstance().trace(`Create and add to cache new agent ${agentId}`); + Logger.getInstance().trace('Agent[id: %s] - new instance stored in cache.', agentId); // detect and log PROXY envvar + agent proxy settings const compareAndLogEnvAndAgentProxies = Util.getCompareAndLogEnvAndAgentProxies(agentOptions); - Logger.getInstance().debug(`Proxy settings used in requests:${compareAndLogEnvAndAgentProxies.messages}`); + Logger.getInstance().debug('Agent[id: %s] - proxy settings used in requests: %s', agentId, compareAndLogEnvAndAgentProxies.messages); // if there's anything to warn on (e.g. both envvar + agent proxy used, and they are different) // log warnings on them if (compareAndLogEnvAndAgentProxies.warnings) { - Logger.getInstance().warn(`${compareAndLogEnvAndAgentProxies.warnings}`); + Logger.getInstance().warn('Agent[id: %s] - %s', agentId, compareAndLogEnvAndAgentProxies.warnings); } return agent; } if (httpsAgentCache.has(agentId)) { - Logger.getInstance().trace(`Get agent with id: ${agentId} from cache`); + Logger.getInstance().trace('Agent[id: %s] - retrieving an agent instance from cache.', agentId); agent = httpsAgentCache.get(agentId); } else { agent = createAgent(agentClass, options, agentId); @@ -80,7 +86,7 @@ function enrichAgentOptionsWithProxyConfig(agentOptions, proxy) { } } -function isBypassProxy(proxy, destination) { +function isBypassProxy(proxy, destination, agentId) { if (proxy && proxy.noProxy) { const bypassList = proxy.noProxy.split('|'); for (let i = 0; i < bypassList.length; i++) { @@ -88,7 +94,7 @@ function isBypassProxy(proxy, destination) { host = host.replace('*', '.*?'); const matches = destination.match(host); if (matches) { - Logger.getInstance().debug('bypassing proxy for %s', destination); + Logger.getInstance().debug('Agent[id: %s] - bypassing proxy allowed for destination: %s', agentId, destination); return true; } } @@ -100,17 +106,19 @@ function isBypassProxy(proxy, destination) { * @inheritDoc */ NodeHttpClient.prototype.getAgent = function (parsedUrl, proxy, mock) { + Logger.getInstance().trace('Agent[url: %s] - getting an agent instance.', parsedUrl.href); if (!proxy && GlobalConfig.isEnvProxyActive()) { const isHttps = parsedUrl.protocol === 'https:'; proxy = Util.getProxyFromEnv(isHttps); if (proxy) { - Logger.getInstance().debug(`Load the proxy info from the environment variable host: ${proxy.host} in getAgent`); + Logger.getInstance().debug('Agent[url: %s] - proxy info loaded from the environment variable. Proxy host: %s', parsedUrl.href, proxy.host); } } return getProxyAgent(proxy, parsedUrl, parsedUrl.href, mock); }; function getProxyAgent(proxyOptions, parsedUrl, destination, mock) { + Logger.getInstance().trace('Agent[url: %s] - getting a proxy agent instance.', parsedUrl.href); const agentOptions = { protocol: parsedUrl.protocol, hostname: parsedUrl.hostname, @@ -120,29 +128,34 @@ function getProxyAgent(proxyOptions, parsedUrl, destination, mock) { if (mock) { const mockAgent = mock.agentClass(agentOptions); if (mockAgent.protocol === parsedUrl.protocol) { + Logger.getInstance().debug('Agent[url: %s] - the mock agent will be used.', parsedUrl.href); return mockAgent; } } const destHost = Util.getHostFromURL(destination); - Logger.getInstance().debug(`The destination host is: ${destHost}`); - const agentId = createAgentId(agentOptions.protocol, agentOptions.hostname, destHost, agentOptions.keepAlive); - const bypassProxy = isBypassProxy(proxyOptions, destination); + Logger.getInstance().debug('Agent[id: %s] - the destination host is: %s.', agentId, destHost); + + const bypassProxy = isBypassProxy(proxyOptions, destination, agentId); let agent; const isHttps = agentOptions.protocol === 'https:'; if (isHttps) { if (proxyOptions && !bypassProxy) { + Logger.getInstance().trace('Agent[id: %s] - using HTTPS agent enriched with proxy options.', agentId); enrichAgentOptionsWithProxyConfig(agentOptions, proxyOptions); agent = getFromCacheOrCreate(HttpsProxyAgent, agentOptions, agentId); } else { + Logger.getInstance().trace('Agent[id: %s] - using HTTPS agent without proxy.', agentId); agent = getFromCacheOrCreate(HttpsAgent, agentOptions, agentId); } } else if (proxyOptions && !bypassProxy) { + Logger.getInstance().trace('Agent[id: %s] - using HTTP agent enriched with proxy options.', agentId); enrichAgentOptionsWithProxyConfig(agentOptions, proxyOptions); agent = getFromCacheOrCreate(HttpAgent, agentOptions, agentId); } else { + Logger.getInstance().trace('Agent[id: %s] - using HTTP agent without proxy.', agentId); agent = getFromCacheOrCreate(HttpAgent, agentOptions, agentId); } return agent; diff --git a/lib/http/request_util.js b/lib/http/request_util.js new file mode 100644 index 000000000..a86db249a --- /dev/null +++ b/lib/http/request_util.js @@ -0,0 +1,26 @@ + +/** + * Should work with not yet parsed options as well (before calling prepareRequestOptions method). + * + * @param requestOptions - object representing the request data with top-level keys + * @returns {string} + */ +exports.describeRequestFromOptions = function (requestOptions) { + return exports.describeRequestData({ method: requestOptions.method, url: requestOptions.url }); +}; + +/** + * Creates string that represents response data. + * Should allow to identify request, which was the source for this response. + * @param response - axios response object + * @returns {string} + */ +exports.describeRequestFromResponse = function (response) { + // Uppercase is used to allow finding logs corresponding to the same request - response pair, + // by matching identical options' descriptions. + return exports.describeRequestData({ method: response.config?.method.toUpperCase(), url: response.config?.url }); +}; + +exports.describeRequestData = function (requestData) { + return `[method: ${requestData.method}, url: ${requestData.url}]`; +}; \ No newline at end of file diff --git a/lib/logger/logging_utils.js b/lib/logger/logging_util.js similarity index 100% rename from lib/logger/logging_utils.js rename to lib/logger/logging_util.js diff --git a/lib/secret_detector.js b/lib/secret_detector.js index 3ccbc8791..700b576c8 100644 --- a/lib/secret_detector.js +++ b/lib/secret_detector.js @@ -64,7 +64,9 @@ function SecretDetector(customPatterns, mock) { 'gim'); const PRIVATE_KEY_DATA_PATTERN = new RegExp(String.raw`"privateKeyData": "([a-z0-9/+=\\n]{10,})"`, 'gim'); - const CONNECTION_TOKEN_PATTERN = new RegExp(String.raw`(token|assertion content)([\'\"\s:=]+)([a-z0-9=/_\-\+]{8,})`, + // Colon in the group ([a-z0-9=/:_%-+]{8,}) was added to detect tokens that contain additional details before the actual token. + // Such as version or hint (token=ver:1-hint:1233-realToken...). + const CONNECTION_TOKEN_PATTERN = new RegExp(String.raw`(token|assertion content)([\'\"\s:=]+)([a-z0-9=/:_\%\-\+]{8,})`, 'gi'); const PASSWORD_PATTERN = new RegExp( String.raw`(password|pwd)([\'\"\s:=]+)([a-z0-9!\"#\$%&\\\'\(\)\*\+\,-\./:;<=>\?\@\[\]\^_` + diff --git a/lib/services/sf.js b/lib/services/sf.js index 17ec85d80..4a1ce42a9 100644 --- a/lib/services/sf.js +++ b/lib/services/sf.js @@ -1256,7 +1256,7 @@ function buildLoginUrl(connectionConfig) { const queryStringObject = {}; if (!connectionConfig.isQaMode()) { - // no requestId is attached to login-request in test mode. + // No requestId is attached to login-request in test mode. queryStringObject.requestId = uuidv4(); } for (let index = 0, length = queryParams.length; index < length; index++) { diff --git a/test/unit/secret_detector_test.js b/test/unit/secret_detector_test.js index 36803878d..ee6a188c3 100644 --- a/test/unit/secret_detector_test.js +++ b/test/unit/secret_detector_test.js @@ -329,4 +329,63 @@ describe('Secret Detector', function () { assert.strictEqual(result.maskedtxt, 'otac=****'); assert.strictEqual(result.errstr, null); }); + + it('test - url token masking', async function () { + const TEST_TOKEN_VALUE = 'ETMsDgAAAZNi6aPlABRBRVMvQ0JDL1BLQ1M1UGFkZGluZwEAABAAEExQLlI3h9PIi9TcCRVdwlEAAABQLsgIQdJ0%2B8eQhDMjViFuY5v03Daxt235tNHYVLNoIqM70yLw4zyVdPlkEi208dS88lSqRvPdgQ/RACU7u%2Bn9gWLiTZ79dkZwl4zQactAKJgAFCUrvbxA2tnUP%2BsX6nPBNBzVWnK5'; + const TEST_TOKEN_VERSION_PREFIX = 'ver:1'; + const TEST_TOKEN_HINT_PREFIX = 'hint:1036'; + const TEST_TOKEN_PREFIX = TEST_TOKEN_VERSION_PREFIX + '-' + TEST_TOKEN_HINT_PREFIX + '-'; + + const tokenWithVersionAndHint = 'token=' + TEST_TOKEN_PREFIX + TEST_TOKEN_VALUE; + let result = SecretDetector.maskSecrets(tokenWithVersionAndHint); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token=' + '****'); + assert.strictEqual(result.errstr, null); + + const tokenWithVersionAndHintAndManyEqualsSigns = 'token=====' + TEST_TOKEN_PREFIX + TEST_TOKEN_VALUE; + result = SecretDetector.maskSecrets(tokenWithVersionAndHintAndManyEqualsSigns); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token=====' + '****'); + assert.strictEqual(result.errstr, null); + + const tokenWithVersionAndHintAndColon = 'token:' + TEST_TOKEN_PREFIX + TEST_TOKEN_VALUE; + result = SecretDetector.maskSecrets(tokenWithVersionAndHintAndColon); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token:' + '****'); + assert.strictEqual(result.errstr, null); + + + const TEST_NEXT_PARAMETER_NOT_TO_BE_MASKED = 'jobID=123fdas4-2133212-12'; + const tokenWithVersionAndHintAndAnotherParameterToIgnore = 'token=' + TEST_TOKEN_PREFIX + TEST_TOKEN_VALUE + '&' + TEST_NEXT_PARAMETER_NOT_TO_BE_MASKED; + result = SecretDetector.maskSecrets(tokenWithVersionAndHintAndAnotherParameterToIgnore); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token=' + '****' + '&' + TEST_NEXT_PARAMETER_NOT_TO_BE_MASKED); + assert.strictEqual(result.errstr, null); + + + const tokenWithVersionAndHintAndManySpaces = 'token = ' + TEST_TOKEN_PREFIX + TEST_TOKEN_VALUE; + result = SecretDetector.maskSecrets(tokenWithVersionAndHintAndManySpaces); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token = ' + '****'); + assert.strictEqual(result.errstr, null); + + + const tokenWithVersion = 'token=' + TEST_TOKEN_VERSION_PREFIX + '-' + TEST_TOKEN_VALUE; + result = SecretDetector.maskSecrets(tokenWithVersion); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token=' + '****'); + assert.strictEqual(result.errstr, null); + + const tokenWithHint = 'token=' + TEST_TOKEN_HINT_PREFIX + '-' + TEST_TOKEN_VALUE; + result = SecretDetector.maskSecrets(tokenWithHint); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token=' + '****'); + assert.strictEqual(result.errstr, null); + + const longToken = 'token=' + TEST_TOKEN_VALUE; + result = SecretDetector.maskSecrets(longToken); + assert.strictEqual(result.masked, true); + assert.strictEqual(result.maskedtxt, 'token=****'); + assert.strictEqual(result.errstr, null); + }); });