http adapter stream never ends and request hangs

[AaronRobinson]

Describe the bug

Intermittent hangs with requests that I've debugged down to end not being called on the stream.

To Reproduce

Code snippet to reproduce, ideally that will work by pasting into something like https://npm.runkit.com/axios, a hosted solution, or a repository that illustrates the issue. If your problem is not reproducible, please file under Support or Usage Question

Excerpts from my code showing the Axios call

const SocksProxyAgent = require('socks-proxy-agent')
const proxyOptions = `socks5://127.0.0.1:9050`
const httpsAgent = new SocksProxyAgent(proxyOptions)
const client = axios.create({ httpsAgent })
...
try {
      response = await client.get(url)  <---- the call of no return
    } catch (err) {
      outcodeLogger.error(err) <---- it never gets here
      throw new Error(`HTTP error ${err} for outcode ${outcodeNumber} `)
    } finally {
      outcodeLogger.trace('13')  <---- it never gets here
    }
 <---- it never gets here

Axios http.js with debug messages added

'use strict';

var utils = require('./../utils');
var settle = require('./../core/settle');
var buildFullPath = require('../core/buildFullPath');
var buildURL = require('./../helpers/buildURL');
var http = require('http');
var https = require('https');
var httpFollow = require('follow-redirects').http;
var httpsFollow = require('follow-redirects').https;
var url = require('url');
var zlib = require('zlib');
var pkg = require('./../../package.json');
var createError = require('../core/createError');
var enhanceError = require('../core/enhanceError');

var isHttps = /https:?/;

/**
 *
 * @param {http.ClientRequestArgs} options
 * @param {AxiosProxyConfig} proxy
 * @param {string} location
 */
function setProxy(options, proxy, location) {
  options.hostname = proxy.host;
  options.host = proxy.host;
  options.port = proxy.port;
  options.path = location;

  // Basic proxy authorization
  if (proxy.auth) {
    var base64 = Buffer.from(proxy.auth.username + ':' + proxy.auth.password, 'utf8').toString('base64');
    options.headers['Proxy-Authorization'] = 'Basic ' + base64;
  }

  // If a proxy is used, any redirects must also pass through the proxy
  options.beforeRedirect = function beforeRedirect(redirection) {
    redirection.headers.host = redirection.host;
    setProxy(redirection, proxy, redirection.href);
  };
}

/*eslint consistent-return:0*/
module.exports = function httpAdapter(config) {
  const {url:u}=config
  console.log(`${u} start httpAdapter`)
  return new Promise(function dispatchHttpRequest(resolvePromise, rejectPromise) {
    var resolve = function resolve(value) {
      resolvePromise(value);
    };
    var reject = function reject(value) {
      rejectPromise(value);
    };
    var data = config.data;
    var headers = config.headers;

    // Set User-Agent (required by some servers)
    // Only set header if it hasn't been set in config
    // See https://github.com/axios/axios/issues/69
    if (!headers['User-Agent'] && !headers['user-agent']) {
      headers['User-Agent'] = 'axios/' + pkg.version;
    }

    console.log(`${u} buffer stuff`)
    if (data && !utils.isStream(data)) {
      if (Buffer.isBuffer(data)) {
        // Nothing to do...
      } else if (utils.isArrayBuffer(data)) {
        data = Buffer.from(new Uint8Array(data));
      } else if (utils.isString(data)) {
        data = Buffer.from(data, 'utf-8');
      } else {
        return reject(createError(
          'Data after transformation must be a string, an ArrayBuffer, a Buffer, or a Stream',
          config
        ));
      }

      // Add Content-Length header if data exists
      headers['Content-Length'] = data.length;
    }

    // HTTP basic authentication
    console.log(`${u} start auth`)

    var auth = undefined;
    if (config.auth) {
      var username = config.auth.username || '';
      var password = config.auth.password || '';
      auth = username + ':' + password;
    }

    // Parse url
    console.log(`${u} start parse url`)

    var fullPath = buildFullPath(config.baseURL, config.url);
    var parsed = url.parse(fullPath);
    var protocol = parsed.protocol || 'http:';

    if (!auth && parsed.auth) {
      var urlAuth = parsed.auth.split(':');
      var urlUsername = urlAuth[0] || '';
      var urlPassword = urlAuth[1] || '';
      auth = urlUsername + ':' + urlPassword;
    }

    if (auth) {
      delete headers.Authorization;
    }

    var isHttpsRequest = isHttps.test(protocol);
    var agent = isHttpsRequest ? config.httpsAgent : config.httpAgent;

    console.log(`${u} build url`)

    var options = {
      path: buildURL(parsed.path, config.params, config.paramsSerializer).replace(/^\?/, ''),
      method: config.method.toUpperCase(),
      headers: headers,
      agent: agent,
      agents: { http: config.httpAgent, https: config.httpsAgent },
      auth: auth
    };

    if (config.socketPath) {
      options.socketPath = config.socketPath;
    } else {
      options.hostname = parsed.hostname;
      options.port = parsed.port;
    }

    console.log(`${u} start proxy`)

    var proxy = config.proxy;
    if (!proxy && proxy !== false) {
      var proxyEnv = protocol.slice(0, -1) + '_proxy';
      var proxyUrl = process.env[proxyEnv] || process.env[proxyEnv.toUpperCase()];
      if (proxyUrl) {
        var parsedProxyUrl = url.parse(proxyUrl);
        var noProxyEnv = process.env.no_proxy || process.env.NO_PROXY;
        var shouldProxy = true;

        if (noProxyEnv) {
          var noProxy = noProxyEnv.split(',').map(function trim(s) {
            return s.trim();
          });

          shouldProxy = !noProxy.some(function proxyMatch(proxyElement) {
            if (!proxyElement) {
              return false;
            }
            if (proxyElement === '*') {
              return true;
            }
            if (proxyElement[0] === '.' &&
                parsed.hostname.substr(parsed.hostname.length - proxyElement.length) === proxyElement) {
              return true;
            }

            return parsed.hostname === proxyElement;
          });
        }

        if (shouldProxy) {
          proxy = {
            host: parsedProxyUrl.hostname,
            port: parsedProxyUrl.port,
            protocol: parsedProxyUrl.protocol
          };

          if (parsedProxyUrl.auth) {
            var proxyUrlAuth = parsedProxyUrl.auth.split(':');
            proxy.auth = {
              username: proxyUrlAuth[0],
              password: proxyUrlAuth[1]
            };
          }
        }
      }
    }

    console.log(`${u} start proxy 2`)

    if (proxy) {
      options.headers.host = parsed.hostname + (parsed.port ? ':' + parsed.port : '');
      setProxy(options, proxy, protocol + '//' + parsed.hostname + (parsed.port ? ':' + parsed.port : '') + options.path);
    }

    console.log(`${u} start transport`)

    var transport;
    var isHttpsProxy = isHttpsRequest && (proxy ? isHttps.test(proxy.protocol) : true);
    if (config.transport) {
      transport = config.transport;
    } else if (config.maxRedirects === 0) {
      transport = isHttpsProxy ? https : http;
    } else {
      if (config.maxRedirects) {
        options.maxRedirects = config.maxRedirects;
      }
      transport = isHttpsProxy ? httpsFollow : httpFollow;
    }

    if (config.maxBodyLength > -1) {
      options.maxBodyLength = config.maxBodyLength;
    }

    console.log(`${u} start create request`)

    // Create the request
    var req = transport.request(options, function handleResponse(res) {
      if (req.aborted) return;

      // uncompress the response body transparently if required
      var stream = res;

      // return the last request in case of redirects
      var lastRequest = res.req || req;


      // if no content, is HEAD request or decompress disabled we should not decompress
      if (res.statusCode !== 204 && lastRequest.method !== 'HEAD' && config.decompress !== false) {
        switch (res.headers['content-encoding']) {
        /*eslint default-case:0*/
        case 'gzip':
        case 'compress':
        case 'deflate':
        // add the unzipper to the body stream processing pipeline
          stream = stream.pipe(zlib.createUnzip());

          // remove the content-encoding in order to not confuse downstream operations
          delete res.headers['content-encoding'];
          break;
        }
      }

      var response = {
        status: res.statusCode,
        statusText: res.statusMessage,
        headers: res.headers,
        config: config,
        request: lastRequest
      };

      if (config.responseType === 'stream') {
        response.data = stream;
        settle(resolve, reject, response);
      } else {
        var responseBuffer = [];
        stream.on('data', function handleStreamData(chunk) {
          console.log(`${u} stream.on start`)

          responseBuffer.push(chunk);
          console.log(`${u} stream.on pushed ${config.maxContentLength} ${Buffer.concat(responseBuffer).length}`)

          // make sure the content length is not over the maxContentLength if specified
          if (config.maxContentLength > -1 && Buffer.concat(responseBuffer).length > config.maxContentLength) {
            stream.destroy();
            console.log(`${u} destroy`)
            reject(createError('maxContentLength size of ' + config.maxContentLength + ' exceeded',
              config, null, lastRequest));
              console.log(`${u} rejected`)
            }
            console.log(`${u} end`)

        });

        stream.on('error', function handleStreamError(err) {
          console.log(`${u} stream.on error`)

          if (req.aborted) return;
          reject(enhanceError(err, config, null, lastRequest));
        });

        stream.on('end', function handleStreamEnd() {
          console.log(`${u} stream.on end`)

          var responseData = Buffer.concat(responseBuffer);
          if (config.responseType !== 'arraybuffer') {
            responseData = responseData.toString(config.responseEncoding);
            if (!config.responseEncoding || config.responseEncoding === 'utf8') {
              responseData = utils.stripBOM(responseData);
            }
          }

          response.data = responseData;
          settle(resolve, reject, response);
        });
      }
    });

    console.log(`${u} start handle errors`)

    // Handle errors
    req.on('error', function handleRequestError(err) {
      console.log(`${u} ${err.code}`)
      console.log(`${u} ${req.aborted}`)
      if (req.aborted && err.code !== 'ERR_FR_TOO_MANY_REDIRECTS') return;
      reject(enhanceError(err, config, null, req));
    });

    console.log(`${u} start timeout to ${config.timeout}`)

    // Handle request timeout
    if (config.timeout) {

      // Sometime, the response will be very slow, and does not respond, the connect event will be block by event loop system.
      // And timer callback will be fired, and abort() will be invoked before connection, then get "socket hang up" and code ECONNRESET.
      // At this time, if we have a large number of request, nodejs will hang up some socket on background. and the number will up and up.
      // And then these socket which be hang up will devoring CPU little by little.
      // ClientRequest.setTimeout will be fired on the specify milliseconds, and can make sure that abort() will be fired after connect.
      req.setTimeout(config.timeout, function handleRequestTimeout() {
        console.log(`${u} timeout1`)
        req.abort();
        console.log(`${u} timeout2`)
        reject(createError('timeout of ' + config.timeout + 'ms exceeded', config, 'ECONNABORTED', req));
        console.log(`${u} timeout3`)
      });
    }
    console.log(`${u} timeout4`)

    if (config.cancelToken) {
      console.log(`${u} timeout5`)
      // Handle cancellation
      config.cancelToken.promise.then(function onCanceled(cancel) {
        if (req.aborted) return;

        req.abort();
        reject(cancel);
      });
    }
    console.log(`${u} timeout6`)

    // Send the request
    if (utils.isStream(data)) {
      data.on('error', function handleStreamError(err) {
        console.log(`${u} data.on error`)
        reject(enhanceError(err, config, null, req));
      }).pipe(req);
    } else {
      console.log(`${u} 888`)
      req.end(data);
    }
    console.log(`${u} 999`)
  });
};

<URL> start proxy
<URL> start proxy 2
<URL> start transport
<URL> start create request
<URL> start handle errors
<URL> start timeout to 0
<URL> timeout4
<URL> timeout6
<URL> 888
<URL> 999
<URL> stream.on start
<URL> stream.on pushed -1 812
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 2260
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 3708
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 5156
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 6604
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 8052
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 8184
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 9492
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 10940
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 12388
<URL> end
<URL> stream.on start
<URL> stream.on pushed -1 13836
<URL> end

No call to stream.end so the promise is never resolved/rejected

Expected behavior

It doesn't hang or it times out

Environment

• Axios Version 0.21.1
• Adapter HTTP
• Browser n/a
• Browser Version n/a
• Node.js Version 14.16
• OS: Ubuntu 20.04
• Additional Library Versions : using socks-proxy-agent": "^5.0.0",

Additional context/Screenshots

Add any other context about the problem here. If applicable, add screenshots to help explain.

[danconnell]

@AaronRobinson Have you come up with a workaround for this at all? We've been using Axios for years and all of a sudden 2 days ago this has become a huge issue for us out of nowhere without upgrading or changing anything.

I've debugged it down to the same thing, that the Axios promise just doesn't resolve (even though the network request is actually made and does respond).

I have to repeatedly restart the app until it stops happening so I assume there's some sort of network connection being made initially that gets corrupted and then is kept alive in the background or something like that? I don't know.

[AaronRobinson]

@danconnell i didn’t solve it but I’m not convinced it’s an axios issue. My best guess is that somewhere between axios and the target server doesn’t send all the packets as I have debugged that axios never gets the end event. There's plenty online describing this behaviour including some specific cases where axios doesn't deal with it as expected.

For the record I was using node->axios with socks-proxy-agent as the httpsagent->tor->target. I was also doing limited (20-50) concurrent requests (using p-limit). So it’s possible that any combination of NodeJS, the socks lib or tor itself couldn’t cope. I also later discovered that on occasion the server running this code would become CPU saturated and so that could have had an impact. Since moving to multiple node runtimes with serial requests I haven't had the issue yet.

[janaz]

I came across a similar issue in my handcrafted HTTP client and what fixed the issue for me was handling the aborted event on the HTTP response object

The Node.js http module documentation says:

In the case of a premature connection close after the response is received, the following events will be emitted in the following order:

• 'socket'
• 'response'
  • 'data' any number of times, on the res object
• (connection closed here)
• 'aborted' on the res object
  'close'
  'close' on the res object

It means that the error event will not be triggered on the response object when:

• the connection is prematurely closed after the client establishes a connection, and
• partial response has been already received

I was thinking about replacing my client with Axios and I wanted to check if the library handles the aborted event and I couldn't find it anywhere in the source code of Axios.

Axios is only listening on data, error, and end events. It doesn't handle the aborted event. If the above scenario happens Axios will never notify us about the error.

Edit: It seems like Node.js v13 introduced a change around the events that are emitted on the response object -nodejs/node#31630

[munepom]

Hi!
I came across a similar issue. (never handling response... and can't view network log)

Environment:

• Node.js v14.15.4
• Ubuntu 18.04
• not using socks-proxy-agent

Sorry if the following is misguided.

I'm guessing the same as @janaz.
e.g.) response (http.IncomingMessage extends stream.Readable) is chunked and closed for any reason.
Looking at Axios source code, Axios may not be listening on aborted event, so I'm afraid Axios can't deal with above scenario.

As said in the following issue, aborted stream is not successful, so end event shouldn't trigger.
nodejs/node#31630 (comment)
nodejs/node#31630 (comment)

Just to be sure, checked the Node.js source code...
Since Node.js v13.0.0, check res.aborted flag before firing response 'end' event (exec res.push(null);)
https://github.com/nodejs/node/blob/v13.0.0/lib/_http_client.js#L367

If possible, how about adding abortHandler below stream handler section?

axios/lib/adapters/http.js

Lines 242 to 266 in 199c8aa

	stream.on('data', function handleStreamData(chunk) {
	responseBuffer.push(chunk);
	totalResponseBytes += chunk.length;
	// make sure the content length is not over the maxContentLength if specified
	if (config.maxContentLength > -1 && totalResponseBytes > config.maxContentLength) {
	stream.destroy();
	reject(createError('maxContentLength size of ' + config.maxContentLength + ' exceeded',
	config, null, lastRequest));
	}
	});
	stream.on('error', function handleStreamError(err) {
	if (req.aborted) return;
	reject(enhanceError(err, config, null, lastRequest));
	});
	stream.on('end', function handleStreamEnd() {
	var responseData = Buffer.concat(responseBuffer);
	if (config.responseType !== 'arraybuffer') {
	responseData = responseData.toString(config.responseEncoding);
	if (!config.responseEncoding || config.responseEncoding === 'utf8') {
	responseData = utils.stripBOM(responseData);
	}
	}

(One thing that bothers me is why req.setTimeout doesn't seem to be working...)
(Maybe req.emit('close'); will be executed? https://github.com/nodejs/node/blob/v13.0.0/lib/_http_client.js#L366 )

Thank you.

[AaronRobinson]

My theory on the timeout is that it's based on the initial response so if some data is received but not all it will no longer timeout. I have no evidence to back this up.

[munepom]

Oh, by the way...
I've experimented with options.timeout & network throttling, but I did't observed the timeout event firing.
e.g.) use https://www.npmjs.com/package/@sitespeed.io/throttle, and options.timeout is 1 sec, but console.time shows 2 or 3 sec and handled Promise.prototype.then()

I understand the behavior 🙌 Thank you.

[munepom]

I found got's issue!!!

Server side aborted request with Transfer-Encoding: chunked never resolve/reject
sindresorhus/got#1096

I still think to need aborted event handler...

[scr4bble]

I am having the same problem. Happens very sporadically.
axios.get(URL).finally(/* in some cases it never gets executed*/)