Postgrest: JWTIssuedAtFuture failure for valid JWT token

[dudleycarr]

Environment

• PostgreSQL version: docker:latest
• PostgREST version: 0.5
• Operating system: GCP Kubernetes

Description of issue

Postgrest intermittently returns {"message":"JWTIssuedAtFuture"} for valid JWT tokens. I verified that there was no clock drift between the client and the PostgREST server.

(Steps to reproduce: Include a minimal SQL definition plus how you make the request to PostgREST and the response body)

The easiest way to reproduce is to generate a new JWT token for each request. The issue seems to stem from the change to cache the system timestamp for 1 second within PostgREST. This was a non-issue prior to 0.5.

[steve-chavez]

Reproduced. You're generating a JWT with an iat claim right?(provide a sample JWT if possible).
Now, the bug is also present in v0.4.4.0(see if you can test this version to double check), this was prior to the time caching addition, seems the problem appears when we upgrade the version of our jwt lib(this PR), I'll have to dig further into that.

Steps to reproduce:

## Must have the pgjwt extension and reallyreallyreallyreallyverysafe as jwt-secret in postgrest.conf
for i in {1..10}; do \
  JWT=$(psql -X -t -c "select sign(row_to_json(r), 'reallyreallyreallyreallyverysafe') from ( select 'postgres' as role, extract(epoch from now())::integer as iat) r" | xargs);\
  curl -s -H "Authorization: Bearer $JWT" localhost:3000/authors_only; echo;\
  sleep .5;\
done

{"message":"JWTIssuedAtFuture"}
[]
{"message":"JWTIssuedAtFuture"}
[]
{"message":"JWTIssuedAtFuture"}
[]
[]
{"message":"JWTIssuedAtFuture"}
[]
{"message":"JWTIssuedAtFuture"}

[dudleycarr]

@steve-chavez Yes, the JWT does include the iat claim. I'll produce a rejected JWT later today. My bad on not checking the previous version for the existence of the bug.

[miaojianxin]

i use the iat claim, but it also print this:{"message":"JWSError JWSInvalidSignature"}

the token is produced in the web:https://jwt.io/:
i edit the role, and the secret,
{
"role": "postgres",
"iat": 1516239022
}

HMACSHA256(
base64UrlEncode(header) + "." +
base64UrlEncode(payload),

postgres

) secret base64 encoded

[steve-chavez]

@miaojianxin That seems more related to #991, check if your secret is at least 32 characters long.

[steve-chavez]

Can confirm that by removing the time cache the issue still persists.

Edit: this issue can be fixed by setting a 1 second allowedSkew in hs-jose, but not sure why this is needed even when the time cache is not used, want to find why that happens before submitting this fix.

[dudleycarr]

@steve-chavez I've confirmed that removing the iat resolves the issue. Thanks!

[statik]

Interesting, we started hitting this too as soon as we upgraded to postgrest 5.0.

[steve-chavez]

My bad. I confused myself because the test case I proposed had an extract(epoch from now())::integer which rounded the seconds. This issue is totally because of the time cache, I removed the casting in my test case and traced the values on the server:

Listening on port 3000                                                                                                                                 [13/546]
Attempting to connect to the database...
Connection successful
iat: 2018-08-11 22:39:16.59797 UTC
now: 2018-08-11 22:39:16.607357455 UTC
127.0.0.1 - - [11/Aug/2018:17:39:16 -0500] "GET /authors_only HTTP/1.1" 200 - "" "curl/7.59.0"
iat: 2018-08-11 22:39:17.11555 UTC
##
## here the now is the same as the previous request(time cache) thus failing with 
## 401 {"message":"JWTIssuedAtFuture"}
now: 2018-08-11 22:39:16.607357455 UTC
127.0.0.1 - - [11/Aug/2018:17:39:16 -0500] "GET /authors_only HTTP/1.1" 401 - "" "curl/7.59.0"
iat: 2018-08-11 22:39:17.63194 UTC
now: 2018-08-11 22:39:17.643028166 UTC
127.0.0.1 - - [11/Aug/2018:17:39:17 -0500] "GET /authors_only HTTP/1.1" 200 - "" "curl/7.59.0"
iat: 2018-08-11 22:39:18.14894 UTC
##
## ditto
now: 2018-08-11 22:39:17.643028166 UTC
127.0.0.1 - - [11/Aug/2018:17:39:17 -0500] "GET /authors_only HTTP/1.1" 401 - "" "curl/7.59.0"
iat: 2018-08-11 22:39:18.66477 UTC
now: 2018-08-11 22:39:18.67697622 UTC
127.0.0.1 - - [11/Aug/2018:17:39:18 -0500] "GET /authors_only HTTP/1.1" 200 - "" "curl/7.59.0"
iat: 2018-08-11 22:39:19.19219 UTC
##
## ditto
now: 2018-08-11 22:39:18.67697622 UTC
127.0.0.1 - - [11/Aug/2018:17:39:18 -0500] "GET /authors_only HTTP/1.1" 401 - "" "curl/7.59.0"

When removing the time cache the problem is gone, I'm going to add a 1 second allowedSkew and call this fixed.

[skokenes]

Not sure if I should open a new issue for this so I'll start with commenting here first.

I am using PostgREST 5.1 in a docker container and I am still getting JWTIssuedAtFuture errors. If I put a time delay in between my token fetching and my API call of 1 to 2 seconds, the problem goes away so I'm guessing it is a clock issue. It is not something I can consistently reproduce but it seems to pop up in waves. Ie it will be working fine for a while, then suddenly every time I launch the container it will give these errors. I am not sure how to debug PostgREST so at this point I don't know how to produce an example of it. Any suggestions on how I could do that?

One question this raises for me is, could you provide a config parameter for the clock skew, rather than defaulting the value to 1? Then users could adjust the clock tolerance as needed.

Thanks in advance for any advice you can provide.

[steve-chavez]

@skokenes That's weird. How are you running postgrest in docker? Could you please double check that you're on v5.1.0?

[skokenes]

Yes, using a docker-compose file similar to this:

version: "3"
services:
  postgres:
    container_name: postgres
    restart: always
    image: postgres:9.6.10
    volumes:
      - ./postgres:/docker-entrypoint-initdb.d
    ports:
      - "5432:5432"
  postgrest:
    container_name: "postgrest"
    image: postgrest/postgrest:v5.1.0
    environment:
      - PGRST_DB_URI=postgres://postgres:mysecretpassword@postgres:5432/postgres
      - PGRST_DB_SCHEMA=public
      - PGRST_DB_ANON_ROLE=postgres
      - PGRST_SERVER_PORT=3005
      - PGRST_JWT_SECRET=<my secret>
    ports:
      - "3005:3005"
    depends_on:
      - postgres

I've tried reproducing with a very simplified version of my code that triggers the JWTIssuedAtFuture error with no luck. Not sure what factor is contributing to it. If you have any other debugging advice, I will pursue on my side and see if I can get something reproducible.

[ruslantalpa]

Check the clock on both computers, the one generating the jwt and the one consuming

On 28 Nov 2018, at 02:04, Speros Kokenes [e-mail] wrote:

Yes, using a docker-compose file similar to this:

version: "3"
services:
postgres:
container_name: postgres
restart: always
image: postgres:9.6.10
volumes:
- ./postgres:/docker-entrypoint-initdb.d
ports:
- "5432:5432"
postgrest:
container_name: "postgrest"
image: postgrest/postgrest:v5.1.0
environment:
- PGRST_DB_URI=postgres://postgres:mysecretpassword@postgres:5432/postgres
- PGRST_DB_SCHEMA=public
- PGRST_DB_ANON_ROLE=postgres
- PGRST_SERVER_PORT=3005
- PGRST_JWT_SECRET=
ports:
- "3005:3005"
depends_on:
- postgres

I've tried reproducing with a very simplified version of my code that triggers the JWTIssuedAtFuture error with no luck. Not sure what factor is contributing to it. If you have any other debugging advice, I will pursue on my side and see if I can get something reproducible.

—
You are receiving this because you are subscribed to this thread.
Reply to this email directly, view it on GitHub, or mute the thread.

[skokenes]

I will and report back. Thoughts on allowing a parameter to be supplied for the allowedSkew value? I believe it would solve my issue. This issue is popping up again for me today.

[skokenes]

I don't think I can check the clock on both computers given my setup. I am using auth0 to get a generated token. Don't think I can check the clock there.

I am consuming the JWT in a PostgREST docker container. I could check that but I'm not sure what the point is without the former.

[MrMarshall]

I had the same issue with the Postgrest v5.1.0 running in a docker container. For me the Linux clock time of the machine running Postgrest was 15 minutes off. Fixing the clock solved the issue immediately, even without restarting Postgrest.

[steve-chavez]

@skokenes For now what you could do is to change the allowedSkew 1 to 2 and build from source.

About exposing a config value for allowedSkew, I think we shouldn't because that's an internal detail and if there's a bug we should fix it. All is missing is a reproducible test case.

[skokenes]

I may be out of my depth but I would think of it more as a feature than a bug? Isn't clock skew just a normal problem that you'll have to support? In this example, I have a third party server generating my token (auth0) so I have no control over how that clock syncs up with the clock inside the docker container that's running postgREST.

[ruslantalpa]

It’s true you have no control but at the same time they are a service so them having the clock wrong is unlikeley (and if they do it’s upt to them to fix it for the customers). It’s the clock on your box. Also, the clock thing. It’s not like it’s a random value that everybody configures the way they like (or sync with 3rd parties that give different values) “what time is now” is a universally agreed on thing, computers have time time down to ms at least so having postgrest preconfigured as “my clock can be up to 1s wrong” is a wide enough interval.

On 6 Dec 2018, at 19:59, Speros Kokenes [e-mail] wrote:

I may be out of my depth but I would think of it more as a feature than a bug? Isn't clock skew just a normal problem that you'll have to support? In this example, I have a third party server generating my token (auth0) so I have no control over how that clock syncs up with the clock inside the docker container that's running postgREST.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

[skokenes]

Makes sense, thanks for the explanation. Sounds like the docker container must be generating the clock issues, although I don't know the rhyme or reason behind it since sometimes the container is fine.

[ruslantalpa]

I dont think its the container, it’s the host. Make sure you configure it to sync the time with an external service

On 6 Dec 2018, at 21:21, Speros Kokenes [e-mail] wrote:

Makes sense, thanks for the explanation. Sounds like the docker container must be generating the clock issues, although I don't know the rhyme or reason behind it since sometimes the container is fine.

—
You are receiving this because you commented.
Reply to this email directly, view it on GitHub, or mute the thread.

[steve-chavez]

@skokenes Did you managed to solve your clock issue?

Since we have a time cache of 1s maybe we could have a total of 2s of clock skew instead of just 1s.

[steve-chavez]

Closing for now. If the problem persists I'll reopen.

[skokenes]

FWIW I wasn't able to resolve it and instead I changed my architecture so
that I didn't need to use JWT in PostgREST.

On Wed, Mar 6, 2019 at 1:49 PM Steve Chávez [e-mail]
wrote:

Closing for now. If the problem persists I'll reopen.

—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub
https://github.com/PostgREST/postgrest/issues/1139#issuecomment-470228268,
or mute the thread
https://github.com/notifications/unsubscribe-auth/AFTAxW-nLOEojNuhgS-iVY4Ap_vLxM8rks5vUA3BgaJpZM4VF8BA
.

[HamzaAitOumghar]

i'm generating JWT using spring boot :

    public String generateTokenForPostgREST(UserDetails userDetails) {
        Map<String, Object> claims = new HashMap<>();
        final Date createdDate = timeProvider.now();
        final Date expirationDate = new Date(createdDate.getTime() + expiration * 1000);

        claims.put(CLAIM_KEY_POSTGREST_ROLE,"postgres");

        return Jwts.builder()
                .setClaims(claims)
                .setExpiration(expirationDate)
                .signWith(SignatureAlgorithm.HS256,PostgREST_SECRET)
                .compact();
    }

i'm using a secret key >32 : F194A9D75FF3A34338EEA1D8521BE64A51265C and still JWSError JWSInvalidSignature

[savv]

I just ran into this issue on 6.0.2. In my case, postgrest and the token generator (=another server) run on the same machine, which makes me suspect that the issue was on PostgREST's side.