Unable to register the client - TimeoutError

It actually ran nicely as well, no TimeoutError.
If I put http://localhost:3310/forest/authentication/callback in the browser then I get TimeoutError.


I think I already said that.
FYI, it happens in both browsers I have:

  • Chrome, Version 91.0.4472.114 (Official Build) (x86_64)
  • Safari, Version 14.1.1 (15611.2.7.1.6, 15611)

Thanks for your answer.

I just wanted to check the exact same call that is done under the hood. Did you try the second version too?

Hey @GuillaumeGautreau ,

Now I am confused :thinking:
As I said before, your second version of the code ran nicely, and then you asked me again, and then I double-checked it, and then I got this:

➜  UCM-3.0 git:(master) ✗ npm start

> ucm-3.0@0.5.2 start
> node ./bin/www

Your application is listening on port 3310.
node:internal/process/promises:225
          triggerUncaughtException(err, true /* fromPromise */);
          ^

RequestError: Timeout awaiting 'request' for 3500ms
    at ClientRequest.<anonymous> (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/got/dist/source/core/index.js:956:65)
    at Object.onceWrapper (node:events:483:26)
    at ClientRequest.emit (node:events:388:22)
    at ClientRequest.origin.emit (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/@szmarczak/http-timer/dist/source/index.js:39:20)
    at TLSSocket.socketErrorListener (node:_http_client:490:9)
    at TLSSocket.emit (node:events:376:20)
    at emitErrorNT (node:internal/streams/destroy:188:8)
    at emitErrorCloseNT (node:internal/streams/destroy:153:3)
    at processTicksAndRejections (node:internal/process/task_queues:80:21)
    at Timeout.timeoutHandler [as _onTimeout] (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/got/dist/source/core/utils/timed-out.js:36:25)
    at listOnTimeout (node:internal/timers:558:17)
    at processTimers (node:internal/timers:499:7) {
  name: 'TimeoutError',
  code: 'ETIMEDOUT',
  timings: {
    start: 1626099918404,
    socket: 1626099918409,
    lookup: 1626099921861,
    connect: 1626099921904,
    secureConnect: undefined,
    upload: undefined,
    response: undefined,
    end: undefined,
    error: 1626099921906,
    abort: undefined,
    phases: {
      wait: 5,
      dns: 3452,
      tcp: 43,
      tls: undefined,
      request: undefined,
      firstByte: undefined,
      download: undefined,
      total: 3502
    }
  },
  event: 'request'
}

And then I ran it again and again, and I get this:

➜  UCM-3.0 git:(master) ✗ npm start

> ucm-3.0@0.5.2 start
> node ./bin/www

Your application is listening on port 3310.
body {
  redirect_uris: [
    'http://localhost:3310/admin/forest/authentication/callback'
  ],
  token_endpoint_auth_method: 'none',
  application_type: 'web',
  grant_types: [ 'authorization_code' ],
  response_types: [ 'code' ],
  environment_id: 56529,
  client_id: 'eyJraWQiOiJ6d0VjbU5LVVpVTkdYUnlNRzZ2blablablabla'
}

Now, it’s intermittent cause sometimes I get TimeoutError again (first output above).
Actually, it seems that I get TimeoutError again after a while.

So, what I did was… I appended that code in my app.js like this:

(async function () {
  const Got = require('got');
  const got = Got.extend({
    followRedirect: false,
    headers: {
      'User-Agent': 'openid-client/4.2.0 (https://github.com/panva/node-openid-client)'
    },
    retry: 0,
    timeout: 3500,
    throwHttpErrors: false
  });

  const { body } = await got({
    headers: {
      Authorization: 'Bearer blablablabla'
    },
    responseType: 'json',
    json: {
      client_id: undefined,
      redirect_uris: [ 'http://localhost:3310/admin/forest/authentication/callback' ],
      token_endpoint_auth_method: 'none'
    },
    url: 'https://api.forestadmin.com/oidc/reg',
    method: 'POST'
  })
  console.log('body', body);
})();

Does it make sense to you?

Do you have any network instabilities? Can you run ping 8.8.8.8 wait for 10 responses and paste the result?

Hi @GuillaumeGautreau !

Here you are:

➜  UCM-3.0 git:(master) ✗ ping 8.8.8.8
PING 8.8.8.8 (8.8.8.8): 56 data bytes
64 bytes from 8.8.8.8: icmp_seq=0 ttl=117 time=26.686 ms
64 bytes from 8.8.8.8: icmp_seq=1 ttl=117 time=26.072 ms
64 bytes from 8.8.8.8: icmp_seq=2 ttl=117 time=25.915 ms
64 bytes from 8.8.8.8: icmp_seq=3 ttl=117 time=25.360 ms
64 bytes from 8.8.8.8: icmp_seq=4 ttl=117 time=37.303 ms
64 bytes from 8.8.8.8: icmp_seq=5 ttl=117 time=77.671 ms
64 bytes from 8.8.8.8: icmp_seq=6 ttl=117 time=146.304 ms
64 bytes from 8.8.8.8: icmp_seq=7 ttl=117 time=121.203 ms
64 bytes from 8.8.8.8: icmp_seq=8 ttl=117 time=27.164 ms
64 bytes from 8.8.8.8: icmp_seq=9 ttl=117 time=24.744 ms
^C
--- 8.8.8.8 ping statistics ---
10 packets transmitted, 10 packets received, 0.0% packet loss
round-trip min/avg/max/stddev = 24.744/53.842/146.304/43.112 ms

FYI, right now, 4 out of 23 attempts (starting admin backend with your code) I got TimeoutError.

If you change the code to set retry: 3,, do you see any difference? If it’s a network problem, then you should not be able to reproduce the problem with this parameter.

Sincerely, I think it’s still the same.
With retry: 3, I’ve tried 30 times and I’ve got 8 TimeoutError.

Hey @GuillaumeGautreau ,

I’ve done a small change to the code to not need a restart manually.
I’ve put a for loop in it to see the ratio between succeeded requests and failed ones.

(async function () {
  const Got = require('got');
  const got = Got.extend({
    followRedirect: false,
    headers: {
      'User-Agent': 'openid-client/4.2.0 (https://github.com/panva/node-openid-client)'
    },
    retry: 3,
    timeout: 3500,
    throwHttpErrors: false
  });

  let successes = 0;
  let errors = 0;

  for (let i = 0; i < 30; i++) {
    try {
      const { body } = await got({
        headers: {
          Authorization: 'Bearer [MY FOREST_ENV_SECRET]'
        },
        responseType: 'json',
        json: {
          client_id: undefined,
          redirect_uris: [ 'http://localhost:3310/admin/forest/authentication/callback' ],
          token_endpoint_auth_method: 'none'
        },
        url: 'https://api.forestadmin.com/oidc/reg',
        method: 'POST'
      });
      console.log('body', body);
      successes++;
    } catch (error) {
      console.log('error', error);
      errors++;
    }
  }
  console.log('successes', successes, 'errors', errors);
})();

The first got invoke is a success, the rest is TimeoutError (every time I run admin backend this way):

successes 1 errors 29

Thanks for the tests.

I admit that I don’t have any idea why you have this error. It seems to be related to how node or got is accessing the internet.

We tested with curl, and it seems to be working as expected.

We tested with got, and you can reproduce the issue. So I guess that something is wrong with either your node setup or maybe your node_modules.

I did not find any relevant bug report on the repository of got, and the version you are using is not totally new, so I suppose that if the problem came from got, other people should have encountered it.

On our side, the server is returning responses in 40 ms at the very maximum. We don’t see any issue on the server.

Could you test if you can reproduce this issue by using only native node code? If you reproduce this way and not with curl, then I suppose that we could say that something is wrong with your node setup.

You can use http.request to make the same calls and test if you also get timeouts.

I’ve created a file index.js and run it.

const https = require('https');

const data = JSON.stringify({
  token_endpoint_auth_method: 'none',
  redirect_uris: ['http://localhost:3310/forest/authentication/callback'],
});

const options = {
  protocol: 'https:',
  hostname: 'api.forestadmin.com',
  path: '/oidc/reg',
  method: 'POST',
  headers: {
    'Content-Type': 'application/json',
    Authorization: 'Bearer [MY FOREST_ENV_SECRET]',
  }
};

let successes = 0;
let errors = 0;

function logCounter() {
  console.log('Time:', new Date().getTime(), 'Successes:', successes, 'Errors:', errors);
}

function request (totalLoops, actualLoop) {
  if (actualLoop > totalLoops) return;

  function next() {
    setTimeout(() => {
      request(totalLoops, ++actualLoop)
    }, 0); // tried 0, 1000, 5000
  }

  const req = https.request(options, (res) => {
    let data = '';
  
    res.on('data', (chunk) => {
      data += chunk;
    });
  
    res.on('end', () => {
      console.log('Response:', JSON.parse(data));
      successes++;
      logCounter();
      next();
    });
  
  }).on('error', (err) => {
    console.log('Error:', err.message);
    errors++;
    logCounter();
    next();
  });

  req.write(data);
  req.end();
}

request(30, 1);

All requests were successful, no TimeoutError, even with 0, 1000, or 5000 ms delay in between.

Hey @GuillaumeGautreau ,

I’ve just tried my admin backend in another laptop and I could log in to my old project in the local environment. There’s other error after the login, but it’s another topic, what matter now is that the login passed.

I need to find out what my laptop has different.
Thank you all for the great help :+1:

1 Like

Hi @GuillaumeGautreau ,

Can you help me with this matter?

Btw, my local environment with the upgrade to v7 started working.
The only thing new I did was… I upgraded my macOS (Big Sur version 11.4) but it alone didn’t solve TimeoutError right away, I mean, not on the same or the next day. After that, I was 2 weeks off, and now today, everything is working out of nothing (same laptop).
Crazy! :confused:

I’m sending you the new value by DM, I’ll make the change on our side when you’re ready.

@GuillaumeGautreau, I know this is an oldtopic, but I just ran in to the same problem and have verified that I’m getting timeouts when making auth requests to Forest from multiple different servers on multiple different networks. The weird thing is that the first request is basically instantaneous, but every subsequent request appears to fail due to Client network socket disconnected before secure TLS connection was established when using the index.js file provided by fabmarc (unless I basically sleep between requests for long enough). Oddly, requests via curl don’t seem to fail, which suggests an issue in the node version I’m using perhaps? Requests to http://api.forestadmin and not https://api.forestadmin also don’t ever fail.

Exact same pb here. I don’t know how I can deal with it

Hello @john-evan08 and @schalkwijk.

Do you have any dependency in your project that interacts with http requests, for monitoring for instance? We already noticed that some packages mess up with http, resulting to problems with external calls sometimes.

@GuillaumeGautreau, not that I’m aware of, but you know how the NPM dependency ecosystem is :stuck_out_tongue: Two things to note:

  • This problem went away overnight without me deploying any additional changes to my production servers, which makes me think it’s not really an internal dependency problem.
  • I managed to solve the problem in local testing via https.globalAgent.maxCachedSessions = 0; as suggested here. This further suggests to me that Forest’s API was just slow on the draw for some time window last night.

Cheers,

Sam

Thanks for the clarification @schalkwijk. I’ll investigate on our side, but I’m not aware of any particular issue on our side.