From 0f58ceccf872c82d32c8fb67dee4a1c7a43f653e Mon Sep 17 00:00:00 2001 From: David Szmolka <69192509+sfc-gh-dszmolka@users.noreply.github.com> Date: Thu, 16 Nov 2023 18:24:26 +0100 Subject: [PATCH] SNOW-926008 supportability/observability enhancement for generic and proxy use-cases (#699) * SNOW-926008 supportability/observability enhancement for generic and proxy use-cases - generic observability: instead of swallowing the underlying error upon connectivity issue and emit a hard-to-debug generic error message, log that underlying error stack on DEBUG loglevel - proxy: detecting if HTTP_PROXY/HTTPS_PROXY environmental variable is set, log them on DEBUG loglevel - proxy: added logging for Connection's proxyPort and proxyUser (if set), had only proxyHost. -- this bit of logging now moved to generic agent - proxy: if both HTTPS_PROXY and proxyHost is set, can lead to not-so-trivial-to-debug situations ; log this on WARN loglevel for more intuitive troubleshooting * * rewrote env proxy detection function with one which can also compare the env PROXY with the agent proxy settings and generate log messages accordingly * moved the proxy (env+agent) detection functionality into agent creation step to try and check it only once, upon agent creation time * adjusted unit tests accordingly * removing accidentally introduced unnecessary empty line --- lib/agent/https_proxy_ocsp_agent.js | 9 ++- lib/http/node.js | 10 +++ lib/services/sf.js | 4 ++ lib/util.js | 69 ++++++++++++++++++ test/unit/util_test.js | 106 ++++++++++++++++++++++++++++ 5 files changed, 197 insertions(+), 1 deletion(-) diff --git a/lib/agent/https_proxy_ocsp_agent.js b/lib/agent/https_proxy_ocsp_agent.js index 1fa686190..e74e4adab 100644 --- a/lib/agent/https_proxy_ocsp_agent.js +++ b/lib/agent/https_proxy_ocsp_agent.js @@ -98,7 +98,14 @@ function connect(req, opts, fn) { var proxy = this.proxy; var agent = this; - Logger.getInstance().debug("Using proxy=%s for host %s", proxy.host, opts.host); + + // is proxy same as the host it's proxying for? that's a problem + // can occur when envvar HTTPS_PROXY is the same as Connection proxyHost + if (proxy.host === opts.host) { + Logger.getInstance().warn('Looks like the proxy (%s) is the same as the host it is proxying for (%s). ' + + 'If you have connectivity problems, please check if HTTPS_PROXY and proxyHost:proxyPort ' + + 'settings are both in effect and if so, try unsetting one of them.', proxy.host, opts.host); + }; // create a socket connection to the proxy server var socket; diff --git a/lib/http/node.js b/lib/http/node.js index d7cf65cc1..942a231f4 100644 --- a/lib/http/node.js +++ b/lib/http/node.js @@ -53,6 +53,16 @@ function getFromCacheOrCreate(agentClass, options, parsedUrl) { const agent = agentClass(agentOptions); httpsAgentCache.set(agentId, agent); Logger.getInstance().trace(`Create and add to cache new agent ${agentId}`); + + // detect and log PROXY envvar + agent proxy settings + const compareAndLogEnvAndAgentProxies = Util.getCompareAndLogEnvAndAgentProxies(agentOptions); + Logger.getInstance().debug(`Proxy settings used in requests:${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}`); + } + return agent; } diff --git a/lib/services/sf.js b/lib/services/sf.js index fd9223539..db6a0f0c4 100644 --- a/lib/services/sf.js +++ b/lib/services/sf.js @@ -615,6 +615,10 @@ function StateAbstract(options) // if we got an error, wrap it into a network error if (err) { + // if we're running in DEBUG loglevel, probably we want to see the full error instead + Logger.getInstance().debug('Encountered an error when sending the request. Details: ' + + JSON.stringify(err, Util.getCircularReplacer())); + err = Errors.createNetworkError( ErrorCodes.ERR_SF_NETWORK_COULD_NOT_CONNECT, err); } diff --git a/lib/util.js b/lib/util.js index f695cf7a2..dfe81d9bd 100644 --- a/lib/util.js +++ b/lib/util.js @@ -637,4 +637,73 @@ exports.getCircularReplacer = function() { exports.isCorrectSubdomain = function (value) { const subdomainRegex = RegExp(/^\w[\w.-]+\w$/i); return subdomainRegex.test(value); +}; + +/** + * Try to get the PROXY environmental variables + * On Windows, envvar name is case-insensitive, but on *nix, it's case-sensitive + * + * Compare them with the proxy specified on the Connection, if any + * Return with the log constructed from the components detection and comparison + * If there's something to warn the user about, return that too + * + * @param the agentOptions object from agent creation + * @returns {object} + */ +exports.getCompareAndLogEnvAndAgentProxies = function(agentOptions) { + const envProxy = {}; + let logMessages = {'messages': '', 'warnings': ''}; + envProxy.httpProxy = process.env.HTTP_PROXY || process.env.http_proxy; + envProxy.httpsProxy = process.env.HTTPS_PROXY || process.env.https_proxy; + envProxy.noProxy = process.env.NO_PROXY || process.env.no_proxy; + + envProxy.logHttpProxy = envProxy.httpProxy ? + 'HTTP_PROXY: ' + envProxy.httpProxy : 'HTTP_PROXY: '; + envProxy.logHttpsProxy = envProxy.httpsProxy ? + 'HTTPS_PROXY: ' + envProxy.httpsProxy : 'HTTPS_PROXY: '; + envProxy.logNoProxy = envProxy.noProxy ? + 'NO_PROXY: ' + envProxy.noProxy : 'NO_PROXY: '; + + // log PROXY envvars + if (envProxy.httpProxy || envProxy.httpsProxy) { + logMessages.messages = logMessages.messages + ` // PROXY environment variables: ` + + `${envProxy.logHttpProxy} ${envProxy.logHttpsProxy} ${envProxy.logNoProxy}.`; + } + + // log proxy config on Connection, if any set + if (agentOptions.host) { + const proxyHostAndPort = agentOptions.host + ':' + agentOptions.port + const proxyProtocolHostAndPort = agentOptions.protocol ? + ' protocol=' + agentOptions.protocol + ' proxy=' + proxyHostAndPort + : ' proxy=' + proxyHostAndPort; + const proxyUsername = agentOptions.user ? ' user=' + agentOptions.user : '' + logMessages.messages = logMessages.messages + ` // Proxy configured in Connection:${proxyProtocolHostAndPort}${proxyUsername}`; + + // check if both the PROXY envvars and Connection proxy config is set + // generate warnings if they are, and are also different + if (envProxy.httpProxy && + this.removeScheme(envProxy.httpProxy).toLowerCase() != this.removeScheme(proxyHostAndPort).toLowerCase()) { + logMessages.warnings = logMessages.warnings + ` Using both the HTTP_PROXY (${envProxy.httpProxy})` + +` and the proxyHost:proxyPort (${proxyHostAndPort}) settings to connect, but with different values.` + +` If you experience connectivity issues, try unsetting one of them.` + }; + if (envProxy.httpsProxy && + this.removeScheme(envProxy.httpsProxy).toLowerCase() != this.removeScheme(proxyHostAndPort).toLowerCase()) { + logMessages.warnings = logMessages.warnings + ` Using both the HTTPS_PROXY (${envProxy.httpsProxy})` + +` and the proxyHost:proxyPort (${proxyHostAndPort}) settings to connect, but with different values.` + +` If you experience connectivity issues, try unsetting one of them.` + }; + } + logMessages.messages = logMessages.messages ? logMessages.messages : ' none.' + + return logMessages; +}; + +/** +* remove http:// or https:// from the input, e.g. used with proxy URL +* @param input +* @returns {string} +*/ +exports.removeScheme = function (input) { + return input.toString().replace(/(^\w+:|^)\/\//, ''); }; \ No newline at end of file diff --git a/test/unit/util_test.js b/test/unit/util_test.js index fd05045c7..53309298c 100644 --- a/test/unit/util_test.js +++ b/test/unit/util_test.js @@ -822,4 +822,110 @@ describe('Util', function () assert.deepEqual(replacedB, shouldMatchCircular); }); }); + + describe("Util Test - removing http or https from string", () => { + const hostAndPortDone = 'my.pro.xy:8080'; + const ipAndPortDone = '10.20.30.40:8080'; + const somethingEntirelyDifferentDone = 'something ENTIRELY different'; + + [ + { name: "remove http from url", text: "http://my.pro.xy:8080", shouldMatch: hostAndPortDone }, + { name: "remove https from url", text: "https://my.pro.xy:8080", shouldMatch: hostAndPortDone }, + { name: "remove http from ip and port", text: "http://10.20.30.40:8080", shouldMatch: ipAndPortDone }, + { name: "remove https from ip and port", text: "https://10.20.30.40:8080", shouldMatch: ipAndPortDone }, + { name: "dont remove http(s) from hostname and port", text: "my.pro.xy:8080", shouldMatch: hostAndPortDone }, + { name: "dont remove http(s) from ip and port", text: "10.20.30.40:8080", shouldMatch: ipAndPortDone }, + { name: "dont remove http(s) from simple string", text: somethingEntirelyDifferentDone, shouldMatch: somethingEntirelyDifferentDone} + ].forEach(({ name, text, shouldMatch }) => { + it(`${name}`, () => { + assert.deepEqual(Util.removeScheme(text), shouldMatch); + }); + }); + }); + + describe("Util Test - detecting PROXY envvars and compare with the agent proxy settings", () => { + // if for some reason there's already a PROXY envvar, try to preserve it + const httpProxyBeforeTest = process.env.HTTP_PROXY ? process.env.HTTP_PROXY : null; + const httpsProxyBeforeTest = process.env.HTTPS_PROXY ? process.env.HTTPS_PROXY : null; + + [ + { + name: "detect http_proxy envvar, no agent proxy", + isWarn: false, + httpproxy: "10.20.30.40:8080", + HTTPSPROXY: '', + agentOptions: {"keepalive": true}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: 10.20.30.40:8080 HTTPS_PROXY: NO_PROXY: ." + }, { + name: "detect HTTPS_PROXY envvar, no agent proxy", + isWarn: false, + httpproxy: '', + HTTPSPROXY: "http://pro.xy:3128", + agentOptions: {"keepalive": true}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: HTTPS_PROXY: http://pro.xy:3128 NO_PROXY: ." + }, { + name: "detect both http_proxy and HTTPS_PROXY envvar, no agent proxy", + isWarn: false, + httpproxy: "10.20.30.40:8080", + HTTPSPROXY: "http://pro.xy:3128", + agentOptions: {"keepalive": true}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: 10.20.30.40:8080 HTTPS_PROXY: http://pro.xy:3128 NO_PROXY: ." + }, { + name: "detect http_proxy envvar, agent proxy set to an unauthenticated proxy, same as the envvar", + isWarn: false, + httpproxy: "10.20.30.40:8080", + HTTPSPROXY: '', + agentOptions: {"keepalive": true, "host": "10.20.30.40", "port": 8080}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: 10.20.30.40:8080 HTTPS_PROXY: NO_PROXY: . // Proxy configured in Connection: proxy=10.20.30.40:8080" + }, { + name: "detect both http_proxy and HTTPS_PROXY envvar, agent proxy set to an unauthenticated proxy, same as the envvar", + isWarn: false, + httpproxy: "10.20.30.40:8080", + HTTPSPROXY: "http://10.20.30.40:8080", + agentOptions: {"keepalive": true, "host": "10.20.30.40", "port": 8080}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: 10.20.30.40:8080 HTTPS_PROXY: http://10.20.30.40:8080 NO_PROXY: . // Proxy configured in Connection: proxy=10.20.30.40:8080" + }, { + name: "detect both http_proxy and HTTPS_PROXY envvar, agent proxy set to an authenticated proxy, same as the envvar", + isWarn: false, + httpproxy: "10.20.30.40:8080", + HTTPSPROXY: "http://10.20.30.40:8080", + agentOptions: {"keepalive": true, "host": "10.20.30.40", "port": 8080, "user": "PRX", "password": "proxypass"}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: 10.20.30.40:8080 HTTPS_PROXY: http://10.20.30.40:8080 NO_PROXY: . // Proxy configured in Connection: proxy=10.20.30.40:8080 user=PRX" + }, { + name: "detect both http_proxy and HTTPS_PROXY envvar, agent proxy set to an authenticated proxy, same as the envvar, with the protocol set", + isWarn: false, + httpproxy: "10.20.30.40:8080", + HTTPSPROXY: "http://10.20.30.40:8080", + agentOptions: {"keepalive": true, "host": "10.20.30.40", "port": 8080, "user": "PRX", "password": "proxypass", "protocol": "http"}, + shouldLog: " // PROXY environment variables: HTTP_PROXY: 10.20.30.40:8080 HTTPS_PROXY: http://10.20.30.40:8080 NO_PROXY: . // Proxy configured in Connection: protocol=http proxy=10.20.30.40:8080 user=PRX" + }, { + // now some WARN level messages + name: "detect HTTPS_PROXY envvar, agent proxy set to an unauthenticated proxy, different from the envvar", + isWarn: true, + httpproxy: '', + HTTPSPROXY: "http://pro.xy:3128", + agentOptions: {"keepalive": true, "host": "10.20.30.40", "port": 8080}, + shouldLog: " Using both the HTTPS_PROXY (http://pro.xy:3128) and the proxyHost:proxyPort (10.20.30.40:8080) settings to connect, but with different values. If you experience connectivity issues, try unsetting one of them." + }, { + name: "detect both http_proxy and HTTPS_PROXY envvar, different from each other, agent proxy set to an unauthenticated proxy, different from the envvars", + isWarn: true, + httpproxy: '169.254.169.254:8080', + HTTPSPROXY: "http://pro.xy:3128", + agentOptions: {"keepalive": true, "host": "10.20.30.40", "port": 8080}, + shouldLog: " Using both the HTTP_PROXY (169.254.169.254:8080) and the proxyHost:proxyPort (10.20.30.40:8080) settings to connect, but with different values. If you experience connectivity issues, try unsetting one of them. Using both the HTTPS_PROXY (http://pro.xy:3128) and the proxyHost:proxyPort (10.20.30.40:8080) settings to connect, but with different values. If you experience connectivity issues, try unsetting one of them." + } + ].forEach(({ name, isWarn, httpproxy, HTTPSPROXY, agentOptions, shouldLog }) => { + it(`${name}`, () => { + process.env.http_proxy = httpproxy; + process.env.HTTPS_PROXY = HTTPSPROXY; + + const compareAndLogEnvAndAgentProxies = Util.getCompareAndLogEnvAndAgentProxies(agentOptions); + if (!isWarn) { + assert.deepEqual(compareAndLogEnvAndAgentProxies.messages, shouldLog, 'expected log message does not match!'); + } else { + assert.deepEqual(compareAndLogEnvAndAgentProxies.warnings, shouldLog, 'expected warning message does not match!'); + } + }); + }); + }); });