Got: "RequestError: socket hang up" in `.json()` within `afterResponse` hook and agent keepAlive

[PopGoesTheWza]

Describe the bug

• Node.js version: 12.16.1
• OS & version: lastest MacOS

Updating from working got@10 to [email protected]

Consider this snippet:

    const opportunitiesIterator = client.paginate<Opportunity>('Opportunities', {
      json: { filter: [{ someField: 'someValue' }] },
    });
    for await (const record of opportunitiesIterator) {
      // Some processing
    }

the client variable is a [email protected] instance with the following notable options:

• agent with Agent({ keepAlive: true }) for both http and https
• prefixUrl with public https base url of our Sugar CRM rest api
• allowGetBody as true for most CRM queries implies an http GET with a body full of json
• hooks.afterResponse with an async function to acquire/renew OAuth token
• mutableDefaults as true
• pagination.paginate and pagination.transform

Actual behavior

Upon first evaluation of for await (const record of opportunitiesIterator) there is this error:

✖ [ERROR] RequestError: socket hang up
    at ClientRequest.<anonymous> (/Users/guillaumec/rc-dev/rcsf/node_modules/got/dist/source/core/index.js:759:25)
    at Object.onceWrapper (events.js:418:26)
    at ClientRequest.emit (events.js:323:22)
    at ClientRequest.origin.emit (/Users/guillaumec/rc-dev/rcsf/node_modules/@szmarczak/http-timer/dist/source/index.js:39:20)
    at TLSSocket.socketCloseListener (_http_client.js:400:11)
    at TLSSocket.emit (events.js:323:22)
    at net.js:668:12
    at connResetException (internal/errors.js:604:14)
    at TLSSocket.socketCloseListener (_http_client.js:400:25)
    at TLSSocket.emit (events.js:323:22)
    at net.js:668:12
    at TCP.done (_tls_wrap.js:556:7) {
  name: 'RequestError',
  code: 'ECONNRESET',
  timings: {
    start: 1587549556887,
    socket: 1587549556887,
    lookup: undefined,
    connect: undefined,
    secureConnect: undefined,
    upload: undefined,
    response: undefined,
    end: undefined,
    error: 1587549556888,
    abort: 1587549556889,
    phases: {
      wait: 0,
      dns: undefined,
      tcp: undefined,
      tls: undefined,
      request: undefined,
      firstByte: undefined,
      download: undefined,
      total: 2
    }
  }
}

Expected behavior

Well, it shouldn't crash, should it?

Code to reproduce

// working on it...

Checklist

• [x] I have read the documentation.
• [x] I have tried my code with the latest version of Node.js and Got.

[PopGoesTheWza]

One interesting thing that I must add: there is no crash if I remove agent from options, so it would hint at an interaction with { keepAlive: true }

Sadly, removing agent only reveals another issue which I'll investigate separately.

[PopGoesTheWza]

@szmarczak I failed at building a simple reproducible test for this issue. Still I can confirm that it disappears after dropping the https keepAlive options...

This now reveals another problem: This one happens during the got.paginate() call of a GET method with allowGetBody: true option and a json payload... Well the payload is ignored. I was able to trace the disappearance of the json payload down to dist/source/create.js line 87:

            const normalizedOptions = normalizeArguments(url, options, defaults.options);

The normalizeArguments function will ignore my options.json (because defaults.options.json is undefined?)

Since the json payload is necessary to filter queries... .paginate() now enable me to retrieve the entire CRM! o/

Please advise.

[szmarczak]

I failed at building a simple reproducible test for this issue

No problem. I'll try once I've got the time.

[szmarczak]

Please advise.

Can you sketch an example of this one? I'll check this out tomorrow anyway.

[PopGoesTheWza]

Can you sketch an example of this one? I'll check this out tomorrow anyway.

Too busy and stressed at the moment to work on it. Maybe later next week. :/

[PopGoesTheWza]

@szmarczak Is it just me or the withServer helper does not handle/process the request's body data?

When trying this minimal test for GET with json payload, request.body is always an empty object.

test('allowGetBody sends json payload', withServer, async (t, server, got) => {
    server.get('/*', (request, response) => {
        if (request.body.hello !== 'world') {
            response.statusCode = 400;
        }

        response.end();
    });

    const {statusCode} = await got.get({
        allowGetBody: true,
        json: {hello: 'world'},
        retry: 0,
        throwHttpErrors: false
    });
    t.is(statusCode, 200);
});

[szmarczak]

Maybe there's a middleware missing.

[PopGoesTheWza]

This won't help putting up a test case to reproduce these issues... :/

[PopGoesTheWza]

Hum... https://www.npmjs.com/package/create-test-server#optionsbodyparser should be the answer

[PopGoesTheWza]

I opened #1186 to distinguish the two issues.

[szmarczak]

Are you able to reproduce the issue? If not, please let me take a few hours / days more to fix the confirmed ones first. I'll try to look at this when I have the time.

[PopGoesTheWza]

I have not yet retried putting up a test case

[PopGoesTheWza]

Also this issue is not (yet) critical since there is a workaround with disabling keepAlive

[PopGoesTheWza]

@szmarczak the WIP tries to mimick my problem but fails reproducing it yet. I'll resume working on it after next got release if it still occurs.

[szmarczak]

No worries. I'll try to reproduce it anyway.

[PopGoesTheWza]

@szmarczak while trying (without success) to investigate this issue, I wonder if it could be related to the http server and its configuration.

Maybe these http response headers can help you:

[szmarczak]

Is this the first request you make? Or is it one of the following?

[PopGoesTheWza]

Sorry. This screen-grab is from Postman as I was looking if the response header would give hint at how it configured.

If you have link to how-to trace got's traffic, I'd gladly assist.

[szmarczak]

When does the error occur? On the first request you make?

The timings say that abort event was fired, which is caused by clientRequest.abort(). Got calls it only when gotStream.destroy() is called. timed-out module calls clientRequest.destroy(error) so it doesn't trigger the abort event. I can't think of a reason gotStream.destroy(...) would be called when paginating (but that does NOT mean impossible), I'll try anyway.

[PopGoesTheWza]

Well... I was able to trace the following sequence:

1. initial got request (get method but without OAuth token)
2. async afterResponse hook is invoked, sees the 401 statusCode and calls custom async getNewAuthToken function
3. getNewAuthToken makes another got request (post method) and crashes on the await responsePromise.json()

getNewAuthToken looks like this:

export const getNewAuthToken = async (): Promise<string> => {
  const responsePromise = authenticationInstance(authURL);
  const body = await responsePromise.json();
  if (is.plainObject(body) && body.access_token) {
    token = body.access_token as string;
    return token;
  }

  throw new Error('getNewAuthToken() bad response');
};

[szmarczak]

So got.paginate(...) was executed after the Got promise?

[szmarczak]

Can you try master? Maybe 63c1b725c93006461121aa5c4a329573fc7a555a fixed the issue. (I tried reproducing on master only, didn't try 11.0.2 yet)

[szmarczak]

I noticed that this error handler is not cleaned up on a redirect:

https://github.com/sindresorhus/got/blob/adf5b8ac0b01e2cc2feecca741c3f534c04d5bc9/source/core/index.ts#L1157-L1165

[szmarczak]

Maybe this .abort() causes somehow socket hang up throwing before the actual error, will make a test.

https://github.com/sindresorhus/got/blob/adf5b8ac0b01e2cc2feecca741c3f534c04d5bc9/source/core/index.ts#L1466-L1474

[PopGoesTheWza]

Sorry. I realise now how my last update must be confusing.
This morning, while investigating, I was able to reproduce the error using a simple got request (i.e. not using .paginate())

Thus the issue can be simplified to a crash in .json() execution of a got request within an afterResponse hook (with agent keepAlive)

The issue occurs with any got@11 version (including last night master)

[szmarczak]

Upon first evaluation of for await (const record of opportunitiesIterator) there is this error:

Do you make any Got requests before that?

Thus the issue can be simplified to a crash in .json() execution of a got request within an afterResponse hook (with agent keepAlive)

Nice! Can you post the code please? It doesn't have to be a test, it just needs to show that it's a bug :)

[PopGoesTheWza]

Here is a minimal test case.

• crash occurs within .json() call from getNewAuthToken()
• switch keepAlive to false and no more crashes

import is from '@sindresorhus/is';
import got, { ExtendOptions } from 'got';
import { Agent as HttpsAgent } from 'https';
import logSymbols from 'log-symbols';

import { getBaseUrl, getCredentials } from './client/read-configuration';

// TODO: better token managment
let token: string | undefined;

const authURL = 'oauth2/token';

const baseOptions: ExtendOptions = {
  agent: {
    https: new HttpsAgent({ keepAlive: true }), // Set to `false` to prevent crash
  },
  prefixUrl: getBaseUrl(),
};

const authOptions: ExtendOptions = {
  method: 'POST',
  json: {
    grant_type: 'password',
    client_id: 'sugar',
    client_secret: '',
    platform: 'base',
    ...getCredentials(),
  },
};

const authenticationInstance = got.extend(baseOptions, authOptions);

export const getNewAuthToken = async (): Promise<string> => {
  const responsePromise = authenticationInstance(authURL);
  const body = await responsePromise.json(); // And there it goes boom!
  if (is.plainObject(body) && body.access_token) {
    token = body.access_token as string;
    return token;
  }

  throw new Error('getNewAuthToken() bad response');
};

const authenticatedInstance = got.extend(baseOptions, {
  hooks: {
    afterResponse: [
      async (response, retryWithMergedOptions) => {
        // Unauthorized
        if (response.statusCode === 401) {
          const updatedOptions: ExtendOptions = { headers: { 'oauth-token': await getNewAuthToken() } };

          // Save for further requests
          authenticatedInstance.defaults.options = got.mergeOptions(
            authenticatedInstance.defaults.options,
            updatedOptions
          );

          return retryWithMergedOptions(updatedOptions);
        }

        // No changes otherwise
        return response;
      },
    ],
  },
  mutableDefaults: true,
});

(async () => {
  await authenticatedInstance('Opportunities', {
    // allowGetBody: true,
    // json: { filter: [{ someAttribute: 'someValue' }] },
  });

  console.log(logSymbols.info, 'All is well…');
})();

[PopGoesTheWza]

Do you make any Got requests before that?

In my use case, it is bound to happen upon first Got request for at that time there no OAuth token yet... thus the afterResponse hook kicking in to handle authentication...

[szmarczak]

the afterResponse hook kicking in to handle authentication

But the afterResponse hook doesn't run when using streams... Only when using promises.

[PopGoesTheWza]

But the afterResponse hook doesn't run when using streams... Only when using promises.

I could be mistaken but I never intended to waddle some streams... I thought my above code to be full of promises and free of any streams...

[szmarczak]

Sorry, my bad, you're right. The async iterator API utilizes the Promise.

[szmarczak]

and afterResponse hooks should work there too

[szmarczak]

Can you set up a simple Node.js server for the test case?

[PopGoesTheWza]

You mean, a public instance of the rest api I am querying? It is publicly hosted.

[szmarczak]

https://gist.github.com/szmarczak/d5dae7453bc747be70437f5d370c72a3 I cannot reproduce, maybe I'm doing something wrong?

[PopGoesTheWza]

Note that I only encounter the issue using https. Not sure if it also happens with plain http...

[szmarczak]

Not sure if it also happens with plain http.

Can you try? If the API forces you to use HTTPS, let me know, then I'll try again.

[PopGoesTheWza]

Can you try? If the API forces you to use HTTPS, let me know, then I'll try again.

Hopefully, our service provider do not allow plain http ;)

[szmarczak]

I've updated the gist to use HTTPS and still cannot reproduce.

[PopGoesTheWza]

I could email you url and credentials...

[szmarczak]

Sure thing: [edited]

[szmarczak]

Indeed. It is failing only on Node.js 12.16.1... Looking right now.

[szmarczak]

On Node.js 13 it's working as expected

[PopGoesTheWza]

I tested this using node 12.16.2 and it fails. Then node 12.16.3 and it passes...

[szmarczak]

Good news! I can finally reproduce the issue!

[szmarczak]

Indeed, it passes on Node.js 13 but works on Node.js 12.

[PopGoesTheWza]

Thanks for the time invested.

Executive summary:

• try turning keepAlive off
• try upgrading to node 12.16.3 or more