On first call I'm getting "[Directus Error]: FetchError: 500 Internal Server Error"

[sandros94]

So I'm tring to figure out why I'm getting this error only on the first call after an idle time.
[Directus Error]: FetchError: 500 Internal Server Error (...FullURL...)

I'm 99% sure it's something related to directus configuration more than a nuxt/nuxt-directus related issue, but I wanted to ask here first.
My current setup is everything containerized on different servers (so nuxt deployed on ServerX and directus with its database and folders on ServerY).

The only logical conclusion is that directus or nuxt have a max response time threashold, so if directus gets a call after N minutes of no requests received it could take it, lets say, 200ms to give the response back, but nuxt wait only 150ms, so it gives me the FetchError. On the other end if I make the request right after the first one (the FetchError one or any other request for the next 5-10minutes) I get a successfull response every time with an average of 70ms.

How can I troubleshoot this?

example of a script setup

const { getItems } = useDirectusItems();
const { getThumbnail: img } = useDirectusFiles();
const { data: wallpaper } = await useAsyncData('wallpaper', () => getItems({
    collection: "website",
    params: {
            fields: [
                "gallery_background.id",
                "gallery_background.filename_download",
            ],
        }
}));

[sandros94]

An additional note could be that is mainly related to images (all optimized via directus in avif/webp, max 600KB and usually 1-4 per page).

[sandros94]

The error I get from the browser is something along the lines of: 500 Cannot read properties of null (reading 'gallery_background')
Again, an image

[Intevel]

@rijkvanzanten Do you have an idea? I'm not sure if this is a nuxt directus related issue.

[rijkvanzanten]

Not really. Once we're getting into errors and timeouts on self-hosted infrastructure there's little I can do to help..

[sandros94]

The only thresholds, related to a timebased event, I've been able to find in the directus self hosted docs are:

• rate limiter one
• database healthcheck threshold
• cache healthcheck threshold
• storage threshold

Since I'm dealing with images I'm thinking something related to the storage threshold.
But I'm not sure I'm looking at the right thing...

[rijkvanzanten]

@sandros94 There's also a number of variables based on your exact server setup and configuration. For example, it could be that your ServerY has trouble streaming the images from the file storage fast enough for ServerX to pull them in, causing timeouts in between unrelated to Directus. That's also why I said that there's little that I can do once it comes to custom dedicated server architecture 🤔

[sandros94]

That could be something, because at the moment that particural vps I'm selfhosting Directus on has little to no IO disk activity (to my knowledge). This could lead to some OEM stanby features or similar.
I need to setup some tools to monitor this

[sandros94]

So, I've only now noticed that I didn't point out that the images I'm requesting are all transformations of the originals that are on directus local storage (I'm mainly transforming them to webp from jpeg). And yes, this happens on first request, if I refresh the page right after I do get the images.
Reading this reply from @rijkvanzanten I do think this is exactly my problem.

If I let sit nuxt/directus idle for 15minutes (the only timeframe I'm sure of) I do get this problem, but only on first load. Again, If I refresh the page or continue browsing the website everything works fine.

I did catch this event under the network tab and it never exceeded 150ms (the slowest one I've seen was 149ms), so I'm starting to think it's not something related to rate or threshold configuration.

Looking at the generated html I can see the correct url with both id and transformation parameters, so the issue is not the rest api but more like the actual file retrieval.

Lastly, my config is based on this docker-compose and deployed on a VPS confort on OVH.
The thing that is making me rethink that it could be an hardware related issue is that, if it was so, I should have noticed something similar inside directus itself, but it never happened. While the nuxt deployment happens in the same node so no other network interfaces should be involved.

[sandros94]

I'm typing this mainly as a backlog, but I did have some time today and yes: nuxt (nor nuxt-directus) doesn't have anything to do with this problem.

The first request of an image (without any conversion) via rest api gives {"errors":[{"message":"An unexpected error occurred.","extensions":{"code":"INTERNAL_SERVER_ERROR"}}]}, as soon as I reload the image appears.

Currently the directus files aren't publicly available, they are served via an access token from a read-only user (and the token is appended in the rest url)

[sandros94]

So, @rijkvanzanten I'm sorry to disturb you, but I really need you on this:
After my last comment almost 3 days ago I though that the problem could be as simple as a file read permission, so I decided to set the Directus Files read access globally permitted, via the Roles & Permission ui. For the past two days I've tested it every so often (with a minimum period of 15mins between tests) and everything worked perfectly at least 20 times, while earlier one image wouldn't load almost every time...
(actually it happened once, that in the tests of these days, one specific image didn't load. But for that case I'm 99% sure it's a problem related to the component I'm using, props aren't working correctly).

So my actual question:
Could it be that the actual file request is happening so fast that the first request after sleep isn't able to verify the token?

The token currently is a static token from a ReadOnly_API user (no email) with a read only role and the token is inside nuxt-directus options in nuxt.confg.ts.

[sandros94]

Changing the ACCESS_TOKEN_TTL to 1m didn't change the behavior.

But this time (maybe since it was the first error 500 of that instance) it printed out this error:

[23:44:46.301] INFO: Server started at http://0.0.0.0:8055
[23:45:05] GET /items/website?access_token=--redacted-- 304 56ms
[23:45:06] GET /items/website?access_token=--redacted-- 304 8ms
[23:45:06] GET /items/website?access_token=--redacted-- 304 6ms
[23:45:07] GET /items/website?access_token=--redacted-- 304 5ms
[23:45:07] GET /items/website?access_token=--redacted-- 304 5ms
[23:45:07] GET /items/website?access_token=--redacted-- 304 5ms
[23:46:25] GET /items/website?access_token=--redacted-- 304 7ms
[23:49:38] GET /items/website?access_token=--redacted-- 200 6ms
[23:49:38] GET /favicon.ico 404 26ms
[23:54:54] GET /items/website?access_token=--redacted-- 200 20ms
[23:54:54] GET /favicon.ico 404 16ms
[00:05:13] GET /items/website?access_token=--redacted-- 200 22ms
[00:05:14] GET /favicon.ico 404 13ms
[00:20:28] GET /items/website?access_token=--redacted-- 500 11ms
[00:20:28] GET /favicon.ico 500 5ms
[00:20:28.744] ERROR: select "directus_users"."id", "directus_users"."role", "directus_roles"."admin_access", "directus_roles"."app_access" from "directus_users" left join "directus_roles" on "directus_users"."role" = "directus_roles"."id" where "directus_users"."token" = $1 and "status" = $2 limit $3 - Connection terminated unexpectedly
    err: {
      "type": "Error",
      "message": "select \"directus_users\".\"id\", \"directus_users\".\"role\", \"directus_roles\".\"admin_access\", \"directus_roles\".\"app_access\" from \"directus_users\" left join \"directus_roles\" on \"directus_users\".\"role\" = \"directus_roles\".\"id\" where \"directus_users\".\"token\" = $1 and \"status\" = $2 limit $3 - Connection terminated unexpectedly",
      "stack":
          Error: select "directus_users"."id", "directus_users"."role", "directus_roles"."admin_access", "directus_roles"."app_access" from "directus_users" left join "directus_roles" on "directus_users"."role" = "directus_roles"."id" where "directus_users"."token" = $1 and "status" = $2 limit $3 - Connection terminated unexpectedly
              at Connection.<anonymous> (/directus/node_modules/pg/lib/client.js:131:73)
              at Object.onceWrapper (node:events:627:28)
              at Connection.emit (node:events:513:28)
              at Socket.<anonymous> (/directus/node_modules/pg/lib/connection.js:62:12)
              at Socket.emit (node:events:513:28)
              at TCP.<anonymous> (node:net:322:12)
    }
[00:20:28.843] WARN: Connection Error: Connection ended unexpectedly
[00:20:28.846] ERROR: select "ip_access" from "directus_roles" where "id" is null limit $1 - Connection terminated unexpectedly
    err: {
      "type": "Error",
      "message": "select \"ip_access\" from \"directus_roles\" where \"id\" is null limit $1 - Connection terminated unexpectedly",
      "stack":
          Error: select "ip_access" from "directus_roles" where "id" is null limit $1 - Connection terminated unexpectedly
              at Connection.<anonymous> (/directus/node_modules/pg/lib/client.js:131:73)
              at Object.onceWrapper (node:events:627:28)
              at Connection.emit (node:events:513:28)
              at Socket.<anonymous> (/directus/node_modules/pg/lib/connection.js:62:12)
              at Socket.emit (node:events:513:28)
              at TCP.<anonymous> (node:net:322:12)
    }

To be honest I've already seen it, right after some 500s, but not always occurring at every 500.

Back to square one, I guess...

[sandros94]

Just to double check I decided to set ACCESS_TOKEN_TTL to 20m

But still, this is what I got:

[00:28:55.500] INFO: Server started at http://0.0.0.0:8055
[00:29:07] GET /items/website?access_token=--redacted-- 200 54ms
[00:29:07] GET /favicon.ico 404 15ms
[00:44:32] GET /items/website?access_token=--redacted-- 500 10ms
[00:44:32] GET /favicon.ico 500 4ms
[00:44:32.674] ERROR: select "directus_users"."id", "directus_users"."role", "directus_roles"."admin_access", "directus_roles"."app_access" from "directus_users" left join "directus_roles" on "directus_users"."role" = "directus_roles"."id" where "directus_users"."token" = $1 and "status" = $2 limit $3 - Connection terminated unexpectedly
    err: {
      "type": "Error",
      "message": "select \"directus_users\".\"id\", \"directus_users\".\"role\", \"directus_roles\".\"admin_access\", \"directus_roles\".\"app_access\" from \"directus_users\" left join \"directus_roles\" on \"directus_users\".\"role\" = \"directus_roles\".\"id\" where \"directus_users\".\"token\" = $1 and \"status\" = $2 limit $3 - Connection terminated unexpectedly",
      "stack":
          Error: select "directus_users"."id", "directus_users"."role", "directus_roles"."admin_access", "directus_roles"."app_access" from "directus_users" left join "directus_roles" on "directus_users"."role" = "directus_roles"."id" where "directus_users"."token" = $1 and "status" = $2 limit $3 - Connection terminated unexpectedly
              at Connection.<anonymous> (/directus/node_modules/pg/lib/client.js:131:73)
              at Object.onceWrapper (node:events:627:28)
              at Connection.emit (node:events:513:28)
              at Socket.<anonymous> (/directus/node_modules/pg/lib/connection.js:62:12)
              at Socket.emit (node:events:513:28)
              at TCP.<anonymous> (node:net:322:12)
    }
[00:44:32.773] WARN: Connection Error: Connection ended unexpectedly
[00:44:32.775] ERROR: select "ip_access" from "directus_roles" where "id" is null limit $1 - Connection terminated unexpectedly
    err: {
      "type": "Error",
      "message": "select \"ip_access\" from \"directus_roles\" where \"id\" is null limit $1 - Connection terminated unexpectedly",
      "stack":
          Error: select "ip_access" from "directus_roles" where "id" is null limit $1 - Connection terminated unexpectedly
              at Connection.<anonymous> (/directus/node_modules/pg/lib/client.js:131:73)
              at Object.onceWrapper (node:events:627:28)
              at Connection.emit (node:events:513:28)
              at Socket.<anonymous> (/directus/node_modules/pg/lib/connection.js:62:12)
              at Socket.emit (node:events:513:28)
              at TCP.<anonymous> (node:net:322:12)
    }

[sandros94]

Last test prior going to bed:

ACCESS_TOKEN_TTL back to default
Same result as before:

[00:52:28.512] INFO: Server started at http://0.0.0.0:8055
[01:35:03] GET /items/website?access_token=--redacted-- 500 17ms
[01:35:03] GET /favicon.ico 500 8ms
[01:35:03.727] ERROR: select "directus_users"."id", "directus_users"."role", "directus_roles"."admin_access", "directus_roles"."app_access" from "directus_users" left join "directus_roles" on "directus_users"."role" = "directus_roles"."id" where "directus_users"."token" = $1 and "status" = $2 limit $3 - Connection terminated unexpectedly
    err: {
      "type": "Error",
      "message": "select \"directus_users\".\"id\", \"directus_users\".\"role\", \"directus_roles\".\"admin_access\", \"directus_roles\".\"app_access\" from \"directus_users\" left join \"directus_roles\" on \"directus_users\".\"role\" = \"directus_roles\".\"id\" where \"directus_users\".\"token\" = $1 and \"status\" = $2 limit $3 - Connection terminated unexpectedly",
      "stack":
          Error: select "directus_users"."id", "directus_users"."role", "directus_roles"."admin_access", "directus_roles"."app_access" from "directus_users" left join "directus_roles" on "directus_users"."role" = "directus_roles"."id" where "directus_users"."token" = $1 and "status" = $2 limit $3 - Connection terminated unexpectedly
              at Connection.<anonymous> (/directus/node_modules/pg/lib/client.js:131:73)
              at Object.onceWrapper (node:events:627:28)
              at Connection.emit (node:events:513:28)
              at Socket.<anonymous> (/directus/node_modules/pg/lib/connection.js:62:12)
              at Socket.emit (node:events:513:28)
              at TCP.<anonymous> (node:net:322:12)
    }
[01:35:03.834] WARN: Connection Error: Connection ended unexpectedly
[01:35:03.839] ERROR: select "ip_access" from "directus_roles" where "id" is null limit $1 - Connection terminated unexpectedly
    err: {
      "type": "Error",
      "message": "select \"ip_access\" from \"directus_roles\" where \"id\" is null limit $1 - Connection terminated unexpectedly",
      "stack":
          Error: select "ip_access" from "directus_roles" where "id" is null limit $1 - Connection terminated unexpectedly
              at Connection.<anonymous> (/directus/node_modules/pg/lib/client.js:131:73)
              at Object.onceWrapper (node:events:627:28)
              at Connection.emit (node:events:513:28)
              at Socket.<anonymous> (/directus/node_modules/pg/lib/connection.js:62:12)
              at Socket.emit (node:events:513:28)
              at TCP.<anonymous> (node:net:322:12)
    }

[rijkvanzanten]

Connection terminated unexpectedly

Sounds like the database is suddenly dropping the connection to Directus. Really hard for me to help out with, as it's so environment specific..

[sandros94]

Really hard for me to help out with, as it's so environment specific..

Compliterlly understandable. But even small hits like this one you gave me can help me point on where I should move my testing.

I've deployed a number of databases on this vps. One of which was a postgresql that had to deal with time sensitive data, but it worked flawlessly out of the box.
The only different thing I'm doing is using redis as a cache. Something that I've never used on this vps nor I've done in the past.

I'll probably look for a debug mode and see if I can catch if its the pg or redis that drops the connection.

[sandros94]

Since I'm now 100% sure that my problem is related with directus itself, and nuxt-directus doesn't have anything to do with it, I'm moving this discussion to directus/directus.
This way I can involve the community (and try to reduce the team's distractions).

[sandros94]

Opened a new discussion in directus/directus#17663

[sandros94]

I've described the actual solution here.

TL;DR
It was indeed DB_POOL__MIN:0 with two underscores, no need to setup endpoint_mode: dnsrr. And yes, the problem is caused by Docker Swarm that after 15 mins of inactivity it drops all tcp connections between directus and postgresql.