Unable to register the client - TimeoutError

Help me!
1

Hey masters!

I’ve just done the upgrade to v7, and now I am facing this problem when I try to log in:
(please see some screenshots)

image
image1482×1018 138 KB

image
image1626×1104 156 KB

image
image1892×438 95.9 KB

Do they help you guys to help me with this issue?

BTW, this is the console log:

[forest] 🌳🌳🌳  Unable to register the client
{
  "configuration": {
    "authorization_endpoint": "https://api.forestadmin.com/oidc/auth",
    "device_authorization_endpoint": "https://api.forestadmin.com/oidc/device/auth",
    "claims_parameter_supported": false,
    "claims_supported": [
      "sub",
      "email",
      "sid",
      "auth_time",
      "iss"
    ],
    "code_challenge_methods_supported": [
      "S256"
    ],
    "end_session_endpoint": "https://api.forestadmin.com/oidc/session/end",
    "grant_types_supported": [
      "authorization_code",
      "urn:ietf:params:oauth:grant-type:device_code"
    ],
    "id_token_signing_alg_values_supported": [
      "HS256",
      "RS256"
    ],
    "issuer": "https://api.forestadmin.com",
    "jwks_uri": "https://api.forestadmin.com/oidc/jwks",
    "registration_endpoint": "https://api.forestadmin.com/oidc/reg",
    "response_modes_supported": [
      "query"
    ],
    "response_types_supported": [
      "code",
      "none"
    ],
    "scopes_supported": [
      "openid",
      "email",
      "profile"
    ],
    "subject_types_supported": [
      "public"
    ],
    "token_endpoint_auth_methods_supported": [
      "none"
    ],
    "token_endpoint_auth_signing_alg_values_supported": [],
    "token_endpoint": "https://api.forestadmin.com/oidc/token",
    "request_object_signing_alg_values_supported": [
      "HS256",
      "RS256"
    ],
    "request_parameter_supported": false,
    "request_uri_parameter_supported": true,
    "require_request_uri_registration": true,
    "claim_types_supported": [
      "normal"
    ]
  },
  "registration": {
    "redirect_uris": [
      "http://localhost:3310/forest/authentication/callback"
    ],
    "token_endpoint_auth_method": "none"
  },
  "error": {
    "name": "TimeoutError",
    "code": "ETIMEDOUT",
    "timings": {
      "start": 1625686114556,
      "socket": 1625686114556,
      "error": 1625686118061,
      "phases": {
        "wait": 0,
        "total": 3505
      }
    },
    "event": "request"
  }
}
[forest] 🌳🌳🌳  Unexpected error: Timeout awaiting 'request' for 3500ms
{
  "name": "TimeoutError",
  "code": "ETIMEDOUT",
  "timings": {
    "start": 1625686114556,
    "socket": 1625686114556,
    "error": 1625686118061,
    "phases": {
      "wait": 0,
      "total": 3505
    }
  },
  "event": "request",
  "stack": "RequestError: Timeout awaiting 'request' for 3500ms\n    at ClientRequest.<anonymous> (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/got/dist/source/core/index.js:956:65)\n    at Object.onceWrapper (node:events:483:26)\n    at ClientRequest.emit (node:events:388:22)\n    at ClientRequest.origin.emit (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/@szmarczak/http-timer/dist/source/index.js:39:20)\n    at TLSSocket.socketErrorListener (node:_http_client:490:9)\n    at TLSSocket.emit (node:events:376:20)\n    at emitErrorNT (node:internal/streams/destroy:188:8)\n    at emitErrorCloseNT (node:internal/streams/destroy:153:3)\n    at processTicksAndRejections (node:internal/process/task_queues:80:21)\n    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)\n    at listOnTimeout (node:internal/timers:558:17)\n    at processTimers (node:internal/timers:499:7)"
}
POST /forest/authentication 500 98 - 5866.418 ms

My package.json:

  "dependencies": {
    "chalk": "~1.1.3",
    "cookie-parser": "1.4.4",
    "debug": "~4.0.1",
    "dotenv": "~6.1.0",
    "express": "^4.17.1",
    "forest-express-sequelize": "^7.12.2",
    "morgan": "1.9.1",
    "pg": "8.2.2",
    "require-all": "^3.0.0",
    "sequelize": "^5.15.2"
  }

All changes I did was copied from here:

I just didn’t do the section “Running up multiple server instances”.

What else do you need to see to help me out?

2

Hello @fabmarc,

Thanks for this details post ! Let’s try to find the culprit.

  • In which PORT the application is running ?
  • Have you defined your environment variables ? ( APPLICATION_URL, FOREST_ENV_SECRET, FOREST_AUTH_SECRET)
  • Lastly, since you haven’t check the section “Running up multiple server instances” you haven’t define the CLIENT_ID ? (You don’t need to define this in development and when you have only one instance running)

Kind regards,
Morgan

3

Hi @morganperre ,

This is my .env content:

APPLICATION_PORT=3310
APPLICATION_URL=http://localhost:3310
DATABASE_URL=postgres://fabio.marconi:@localhost:5432/falcon_api_development
DATABASE_SCHEMA=public
DATABASE_SSL=false
FOREST_AUTH_SECRET=blablabla
FOREST_ENV_SECRET=blablabla
FOREST_CLIENT_ID=blablabla.blablabla.blablabla-blablabla-blablabla-blablabla
NODE_ENV=development

And that is the output on the console when I try to log in with FOREST_CLIENT_ID set:

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

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

Your application is listening on port 3310.
Your admin panel is available here: https://app.forestadmin.com/projects
OPTIONS /forest/authentication 204 0 - 1.544 ms
POST /forest/authentication 200 923 - 2386.602 ms
OPTIONS /forest/authentication/callback?code=ysh9UmPPhJ3v9BkA7bN_6wiS66S9bN-YuKV25VsQ5alJvallzSvNTOgyVwsY9lCW&state=%7B%22renderingId%22%3A66917%7D 204 0 - 0.230 ms
[forest] 🌳🌳🌳  Unexpected error: Timeout awaiting 'request' for 3500ms
{
  "name": "TimeoutError",
  "code": "ETIMEDOUT",
  "timings": {
    "start": 1625735957248,
    "socket": 1625735957249,
    "error": 1625735960753,
    "phases": {
      "wait": 1,
      "total": 3505
    }
  },
  "event": "request",
  "stack": "RequestError: Timeout awaiting 'request' for 3500ms\n    at ClientRequest.<anonymous> (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/got/dist/source/core/index.js:956:65)\n    at Object.onceWrapper (node:events:483:26)\n    at ClientRequest.emit (node:events:388:22)\n    at ClientRequest.origin.emit (/Users/fabio.marconi/projects/forest-backend/UCM-3.0/node_modules/@szmarczak/http-timer/dist/source/index.js:39:20)\n    at TLSSocket.socketErrorListener (node:_http_client:490:9)\n    at TLSSocket.emit (node:events:376:20)\n    at emitErrorNT (node:internal/streams/destroy:188:8)\n    at emitErrorCloseNT (node:internal/streams/destroy:153:3)\n    at processTicksAndRejections (node:internal/process/task_queues:80:21)\n    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)\n    at listOnTimeout (node:internal/timers:558:17)\n    at processTimers (node:internal/timers:499:7)"
}
GET /forest/authentication/callback?code=ysh9UmPPhJ3v9BkA7bN_6wiS66S9bN-YuKV25VsQ5alJvallzSvNTOgyVwsY9lCW&state=%7B%22renderingId%22%3A66917%7D 500 98 - 3582.605 ms

I noticed the error printed on the console is shorter, but the same: TimeoutError.

So, as you can see above, the PORT the application is running is 3310.

4

Hey again,

Ok, It’s the first time a client get this issue.

So first of all remove the FOREST_CLIENT_ID from your config.

In your server.js file can you add the following code at the end of your file ? (I will let a longer time to you backend to try to resolve HTTP request)

server.keepAliveTimeout = 60000;

Let me know if you still have the issue.

Thanks in advance,
Morgan

5

Hey @morganperre

I usually don’t use FOREST_CLIENT_ID, I just added now for test purpose, already removed it.
So, I added the statement you said, the behavior/error remains the same though.
Let me show you my Javascript console:

image
image2880×1550 735 KB

Does that help?

I even tried different node versions:

➜  UCM-3.0 git:(master) ✗ nvm list
->     v10.24.1
       v12.22.3
        v15.3.0
         system
default -> node (-> v15.3.0)

With all 3 versions, the problem remains!

Any clue, like, any dependency I am missing?

6

Hey @fabmarc,

It doesn’t help at all. I was wondering how/why you have this error and I thought it could help understand.

I propose you to update your dependencies. Use the following ones. (It’s from a recently created project on my side)

 "dependencies": {
    "body-parser": "1.19.0",
    "chalk": "~1.1.3",
    "cookie-parser": "1.4.4",
    "cors": "2.8.5",
    "debug": "~4.0.1",
    "dotenv": "~6.1.0",
    "express": "~4.17.1",
    "express-jwt": "5.3.1",
    "forest-express-sequelize": "^7.12.2",
    "morgan": "1.9.1",
    "require-all": "^3.0.0",
    "sequelize": "~5.15.2",
    "pg": "~8.2.2"
  }

If it doesn’t work I propose to share your app.js and also you to create a fresh new project to see if you encounter the same issue.

Thanks for your time.
Morgan

7

Hey @morganperre ,

This issue came up cause I decided to upgrade my backend, I was in a version before v6.
I also wanna use a new feature (filterable smart field).

Now my package.json looks like:

{
  "name": "ucm-3.0",
  "version": "0.5.2",
  "private": true,
  "scripts": {
    "start": "node ./bin/www"
  },
  "dependencies": {
    "body-parser": "^1.19.0",
    "chalk": "~1.1.3",
    "cookie-parser": "1.4.4",
    "cors": "^2.8.5",
    "debug": "~4.0.1",
    "dotenv": "~6.1.0",
    "express": "^4.17.1",
    "express-jwt": "^6.0.0",
    "forest-express-sequelize": "^7.12.2",
    "morgan": "1.9.1",
    "pg": "8.2.2",
    "require-all": "^3.0.0",
    "sequelize": "^5.15.2"
  }
}

I’ve added only body-parser, cors and express-jwt to it.
After that, the error remains.

My app.js, here you are:

const express = require('express');
const requireAll = require('require-all');
const path = require('path');
const cookieParser = require('cookie-parser');
const bodyParser = require('body-parser');
const cors = require('cors');
const jwt = require('express-jwt');
const morgan = require('morgan');
const {
  PUBLIC_ROUTES,
  ensureAuthenticated,
} = require('forest-express-sequelize');

const app = express();

app.use(morgan('tiny'));
app.use(bodyParser.json());
app.use(bodyParser.urlencoded({ extended: false }));
app.use(cookieParser());
app.use(express.static(path.join(__dirname, 'public')));

let allowedOrigins = [/\.forestadmin\.com$/, /localhost:\d{4}$/];

if (process.env.CORS_ORIGINS) {
  allowedOrigins = allowedOrigins.concat(process.env.CORS_ORIGINS.split(','));
}

const corsConfig = {
  origin: allowedOrigins,
  allowedHeaders: ['Authorization', 'X-Requested-With', 'Content-Type'],
  maxAge: 86400, // NOTICE: 1 day
  credentials: true,
};

app.use('/forest/authentication', cors({
  ...corsConfig,
  // The null origin is sent by browsers for redirected AJAX calls
  // we need to support this in authentication routes because OIDC
  // redirects to the callback route
  origin: corsConfig.origin.concat('null')
}));

app.use(cors(corsConfig));

app.use(jwt({
  secret: process.env.FOREST_AUTH_SECRET,
  credentialsRequired: false,
  algorithms: ['HS256'],
}));

app.use('/forest', (request, response, next) => {
  if (PUBLIC_ROUTES.includes(request.url)) {
    return next();
  }
  return ensureAuthenticated(request, response, next);
});

requireAll({
  dirname: path.join(__dirname, 'routes'),
  recursive: true,
  resolve: Module => app.use('/forest', Module),
});

requireAll({
  dirname: path.join(__dirname, 'middlewares'),
  recursive: true,
  resolve: Module => Module(app),
});

module.exports = app;

Kind regards,
-Marconi

8

Hey @morganperre ,

I did what you suggested, I created a fresh new project and unfortunately I get the same error :disappointed:

9

Hey @fabmarc,

Ok, that’s a bad new. I’m wondering if you have an issue with the connection to our server. Can you try the following command and paste the output ? :slight_smile:

curl -I https://api.forestadmin.com/

Plus, can you describe your ecosystem (linux/Mac OS/docker ?) ?

I’m sure we will finally find the issue here.

Kind regards,
Morgan

10

Yes, locally I am on Mac Catalina version: 10.15.7 (19H2) and NPM 7.0.14 (no Docker).

Output:

➜  UCM-4.0 git:(master) ✗ curl -I https://api.forestadmin.com/
HTTP/1.1 404 Not Found
Server: Cowboy
Connection: keep-alive
X-Dns-Prefetch-Control: off
X-Frame-Options: SAMEORIGIN
Strict-Transport-Security: max-age=15552000; includeSubDomains
X-Download-Options: noopen
X-Content-Type-Options: nosniff
X-Xss-Protection: 1; mode=block
Content-Security-Policy: default-src 'none'
Content-Type: text/html; charset=utf-8
Content-Length: 140
Vary: Accept-Encoding
Date: Fri, 09 Jul 2021 08:16:09 GMT
Via: 1.1 vegur
1 Like
11

Hey @fabmarc,

Thanks for your time. It indicates that you can accès our server.

I will try to summarize a little bit here.

  • You have an issue at the /authentification route (error 500 on the agent caused by a TimeoutError)
  • You have upgraded dependencies same issue
  • You have created a fresh new project same issue
  • You have verified that you can access our server from your hosting machin. OK
  • Your ecosystem is the same as me. So no issue here

I’m wondering if your antivirus can block some networking request that could lead to the TimeoutError.

  • Which antivirus are you using ?
  • Can you also share your project name ?
  • Can you update your source by adding a errorHandler to your code maybe we could have more informations.
// add errorHandler to imports
const {
  errorHandler,
  ensureAuthenticated,
  PUBLIC_ROUTES,
} = require('forest-express-sequelize');

// add this to the end of the app.js file
app.use(errorHandler());

module.exports = app;

Side note - Working config on my side

  • npm v7.18.1
  • node v12.13.0 or v14.16.0
  • macOS BigSur 11.2.3 (20D91) (but I used to be in Catalina a few month ago)
  • antivirus SentinelOne (can lead to weird issue I try to have the latest version to avoid bugs)
12

Hey @morganperre

The command curl -I https://api.forestadmin.com/ result was:
HTTP/1.1 404 Not Found
You’ve seen that, right?

I already had added the errorHandler code lines to my old project (UCM-3.0), cause I had copied from the new/test project (UCM-4.0), so both already had and have the errorHandler set. The project I want to continue working on is the UCM-3.0.

morganperre, I actually don’t have AntiVirus.
Now, desperate mode, I even rebooted my computer, but it didn’t solve the problem. :disappointed: :disappointed: :disappointed:

One more thing, just FYI, when I try this URL http://localhost:3310/forest/authentication/callback in the browser, I get the same error printed in the console when trying to log in to the local environment:
{"errors":[{"status":500,"detail":"Timeout awaiting 'request' for 3500ms","name":"TimeoutError"}]}

13

Hey again,

HTTP/1.1 404 Not Found means you access our server but it respond 404 which is normal is this case. :slight_smile:

Don’t be desperate, we will find a solution. :frowning:

I’m asking some help from a colleague. He will take over the thread I think.

Kind regards,
Morgan

14

Hello @fabmarc,

If I look at the original stack trace, we have:

    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)

The package got is the one that is calling the forestadmin api, with a POST on /api/oidc/reg. This call is falling on your computer for an unknown reason.

Before this call, the agent is doing a GET on /api/oidc/.well-known/openid-configuration and retrieves the JSON without any problem. I don’t know if this call is made with the library got in this case.

Just to be sure, can you run npm list got on your repository, and post here the result? I doubt that there could be an issue related to its version, but it’s worth trying.

You also wrote that you tested with several versions of node, did you remove the node_modules directory after changing? Sometimes some packages can be built for a specific version, and changing can cause strange bugs.

15

Hi @GuillaumeGautreau ,

Here you are:

➜  UCM-3.0 git:(master) ✗ npm list got
ucm-3.0@0.5.2 /Users/fabio.marconi/projects/forest-backend/UCM-3.0
└─┬ forest-express-sequelize@7.12.2
  └─┬ forest-express@8.7.4
    └─┬ openid-client@4.2.0
      └── got@11.8.2

And, yes, I cleaned my node_modules folder, I ran every time I changed Node/NPM:
rm -rf ./node_modules/ && npm i

16

You are using the last version of got, which has been released 4 months ago, it seems good.

Can you launch this command on the same machine you’re running the server?

curl -H "Content-Type: application/json" \
     -H "Authorization: Bearer FOREST_ENV_SECRET" \
     -X POST \
     -d '{"token_endpoint_auth_method": "none", "redirect_uris": ["APPLICATION_URL/forest/authentication/callback"]}' \
     https://api.forestadmin.com/oidc/reg

Please replace FOREST_ENV_SECRET and APPLICATION_URL by the values for your environment.

  • FOREST_ENV_SECRET is the value from your .env file
  • APPLICATION_URL is probably http://localhost:3310

If you do this, do you have a proper response, or a timeout?

17

Hi @GuillaumeGautreau ,

Here you are:

➜  UCM-3.0 git:(master) ✗ curl -H "Content-Type: application/json" \
     -H "Authorization: Bearer fd4923ca502b0be36c25fb348490604d936ad4392211a8a53069c4665903edd6" \
     -X POST \
     -d '{"token_endpoint_auth_method": "none", "redirect_uris": ["http://localhost:3310/forest/authentication/callback"]}' \
     https://api.forestadmin.com/oidc/reg
{"token_endpoint_auth_method":"none","redirect_uris":["http://localhost:3310/forest/authentication/callback"],"application_type":"web","grant_types":["authorization_code"],"response_types":["code"],"environment_id":56529,"client_id":"eyJraWQiOiJ6d0VjbU5LVVpVTkdYUnlNRzZ2QUoyTTVfYzBoZGhfblBXS0hYWjhGUTFBIiwiYWxnIjoiUlMyNTYifQ.eyJ0b2tlbl9lbmRwb2ludF9hdXRoX21ldGhvZCI6Im5vbmUiLCJyZWRpcmVjdF91cmlzIjpbImh0dHA6Ly9sb2NhbGhvc3Q6MzMxMC9mb3Jlc3QvYXV0aGVudGljYXRpb24vY2FsbGJhY2siXSwiYXBwbGljYXRpb25fdHlwZSI6IndlYiIsImdyYW50X3R5cGVzIjpbImF1dGhvcml6YXRpb25fY29kZSJdLCJyZXNwb25zZV90eXBlcyI6WyJjb2RlIl0sImVudmlyb25tZW50X2lkIjo1NjUyOSwiaXNzIjoiRk9SRVNUX0FVVEhFTlRJQ0FUSU9OX1NZU1RFTSIsImlhdCI6MTYyNTg1MzY0MX0.P0UooC-rHL7DM06E8Z_2T-Vs4TdmWnwQOZupIpaIFKEsF4Hf8p3w7CQsDgzdwISqdEaSMIjkbTENrsAOXVCHqR1rEn4thNh1Ix1ITSv2YOv5aXDOhArcYrwIsSHChxSRsq0e62YWZUGX_SYPBnRJ8jaMXhEOSI-2_J2V94iboTp04gBoFBUAhMS6S7rfK_ll14CzquJ0lxikk8j2NFFxZ04EWcKqm0WJ70fqfEJ47rdjlaVXuexCYxd_YfL9RHe4jLHhGf5qtHsNjplFwTrD3LvylB3RqDIqwsiOUvxRhoBnNWhIOaxPenvUL5S5CSfRi8WJFHLjeKvfT0BnYMaVTQ"}%

I am wondering about my FOREST_AUTH_SECRET.
I have 3 remote environments. Each remote environment has your own FOREST_AUTH_SECRET value.
For local development, I am using the same value as in one of my 3 remote environments, and it always worked this way before this upgrade to v7.

Does this env. var. have to be changed for local development because of the v7?

18

Hello @fabmarc,

Ok, it seems that the call that is failing is actually working on your machine. So the problem is not related to the network configuration or something blocking it.

The variable FOREST_AUTH_SECRET is only used to generate and verify JWT for authenticated users. So this variable is not used at all at this point.

The only values that are used and sent to the server, are FOREST_ENV_SECRET and APPLICATION_URL.

As you posted your env secret publicly, we will have to change it once your environment will be working, as it is supposed to be secret :slightly_smiling_face:

Inside your project, could you please launch the same query, but with got, to see if we can reproduce the timeout error?

You’ll have to do something like:

	const {body} = await got.post('https://api.forestadmin.com/oidc/reg', {
		json: {"token_endpoint_auth_method": "none", "redirect_uris": ["http://localhost:3310/forest/authentication/callback"]},
                headers: {
                  "Authorization": "Bearer [FOREST_ENV_SECRET]",
                },
		responseType: 'json'
	});

Are you able to log a response, if you add this in your code?

19

Oh no, my bad :frowning:
How can I generate a new one?

And, yes, that code block ran successfully instead of TimeoutError.
Do you need to see the body/response?

20

We will generate a new one, and change it in the project settings, but for that we need to make it work first. If you prefer I can generate a new one and update it in our database, and send it to you.

In the meantime, can you make another test, to try to replicate the issue? I logged the exact calls to got that are made by the library, and you can replicate them with the following code:

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 response = await got({
  headers: {
    Authorization: 'Bearer [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'
})