Loading

How to troubleshoot Intermittent Issue while validating the JWT token

Date de publication: Mar 2, 2024
Résolution

SYMPTOM

Validation for JWT is not behaving consistently. For a valid token, it throws an error -  "Invalid token.".   But It accepts the same in subsequent request.

PROCEDURE

1. Turn on http wire log. - How to Enable HTTP Wire Logging for HTTP Connector or Other Connectors Using HTTP Service and What Logs To Collect For API Policy Case turn on debug for package - com.mulesoft.extension.policies.
2. With debug turned on - search for the request which is failing and search for - Authorization: Bearer. 
3. Authorization: Bearer is JWT token which you can decode by pasting the token here -  https://jwt.io/. this will give you human readable format of the token. 
e.g.,
{
"client_id": "XXXXXXXXXXXXXXXX",
"http://schemas.XXX.com/ws/2008/06/identity/claims/expiration": "15/01/2021 22:02:23",
"nbf": 1610747843, 
"exp": 1610834243,
"iat": 1610747843,
"iss": "xxxx.co.uk",
"aud": "xxx.co.uk"
}

4. Analyze the logs just before application is throwing the "Invalid token" error and you will see number of statements and executions done by the package - com.mulesoft.extension.policies.   
5. By looking at the JWT token details and detail logs observed at point 4, you should be able to work out the possible root cause for the failure.   


CAUSE

Just to give you one example of failure. Below are log statements which potentially point to some valid exception.  
[2021-01-15 21:47:31.297] DEBUG org.mule.service.http.impl.service.HttpMessageLogger.XXXXXXX-xxxx-exp-api-httpListenerConfig [http.listener.01 SelectorRunner]: LISTENER
POST /XXXXX-service-exp-api/v1/accounts/5292/renewals HTTP/1.1
X-SSL-Client-Verify: NONE

Content-Type: application/json
Authorization: Bearer eyJhbGciOiJSUzI1NiIsInR5cCI6IkpXVCJ9.eyJjbGllbnRfaWQiOiI4Y2IwYmM4MjMxMzc0ZDkwOWI5ZmVkYTNkYWRlNmE0NiIsImh0dHA6Ly9zY2hlbWFzLm1pY3Jvc29mdC5jb20vd3MvMjAwOC8wNi9pZGVudGl0eS9jbGFpbXMvZXhwaXJhdGlvbiI6IjE1LzAxLzIwMjEgMjE6NTI6NDAiLCJuYmYiOjE2MTA3NDcyNjAsImV4cCI6MTYxMDgzMzY2MCwiaWF0IjoxNjEwNzQ3MjYwLCJpc3MiOiJlbnNlay5jby51ayIsImF1ZCI6ImVuc2VrLmNvLnVrIn0.WD0xjsEAPKfJ8KJ65RsqtWLWt-J5rAYucS7j9YGPyhuYptNW5v8kyOR9AgZVOgqpbMEy_cQeHzzks9Wft_ajE46Q3I7AJciv9ORYrFWalGgofEL_JWL7J1euOfzn9U6EORoWVTtfqfQRWbns7XJcJ4flWKd0z8baXUHjlsINn1_h6MqvkkB1xhW8LDAunW7RXj7Zb8LmsN7gPY5fA35QNFVlaXwKlF1dl0iJ0PVQtdPNwXY1FsCIqyPptH4aJhZ0ToRHp3H0ewXKoJ7-7V3Kuj7UOhFQKO5IuEEtlvJ28IUPqjaOMIhumacZSWqtu5y0lk6nwkgDtkcV79FIFP7_PQ

[2021-01-15 21:47:31.322] DEBUG com.mulesoft.extension.policies.jwt.validator.claims.ClaimValidator [[MuleRuntime].uber.38: [jwt-validation-1446864-xxxx-service-exp-api-main].1446864-client-id-enforcement.CPU_INTENSIVE @53e8545d]: event:44df9770-577b-11eb-9fce-06acea3e07a0 Validating nbf claim.
[2021-01-15 21:47:31.322] DEBUG com.mulesoft.extension.policies.jwt.validator.claims.NbfClaimValidator [[MuleRuntime].uber.38: [jwt-validation-1446864-xxxx-service-exp-api-main].1446864-client-id-enforcement.CPU_INTENSIVE @53e8545d]: event:44df9770-577b-11eb-9fce-06acea3e07a0 The token is not valid yet. It will be rejected.
[2021-01-15 21:47:31.385] DEBUG org.mule.service.http.impl.service.HttpMessageLogger.xxxxx-service-exp-api-httpListenerConfig [[MuleRuntime].uber.38: [jwt-validation-1446864-bgevolve-service-exp-api-main].1446864-client-id-enforcement.CPU_INTENSIVE @53e8545d]: event:44df9770-577b-11eb-9fce-06acea3e07a0 LISTENER
HTTP/1.1 401 Unauthorized
www-authenticate: Bearer
Content-Type: application/json; charset=UTF-8
Content-Length: 31
Date: Fri, 15 Jan 2021 21:47:31 GMT

{
"error": "Invalid token."
}

Decoded JWT below  
If you decode this token you will see below details

{
"client_id": "8cb0bc8231374d909b9feda3dade6a46",
"http://xxx.xxx.com/ws/2008/06/identity/claims/expiration": "15/01/2021 21:52:40",
"nbf": 1610747260, ==> Friday, January 15, 2021 9:47:40 PM
"exp": 1610833660, ==> Saturday, January 16, 2021 9:47:40 PM
"iat": 1610747260, ==> Friday, January 15, 2021 9:47:40 PM
"iss": "xxxx.co.uk",
"aud": "xxxx.co.uk"
}

So "nbf": 1610747260 - if you convert the date for this claim, it is date it is Friday, January 15, 2021 9:47:40 PM which is not yet reached when you see the validation exception at - 2021-01-15 21:47:31.   So as per https://tools.ietf.org/html/rfc7519#section-4.1.5 - validation date/time MUST be after or equal to the not-before date/time.

So the root cause here is application is trying to validate the token before it's due and you will notice the same in the sample logs above.  i.e., "The token is not valid yet. It will be rejected."
 

SOLUTION

  • Not to include nbf claim in JWT token if it's not require OR
  • Validate the token only after it is available for validation. 

NOTE:

Reference: https://docs.mulesoft.com/api-manager/2.x/policy-mule4-jwt-validation#validating-claims

Important Text from above documentation:
You can define each claim validation as mandatory or non-mandatory. If a claim is defined as mandatory and is not present in the incoming JWT, the policy rejects this token. If a claim is defined as non-mandatory and is not present in the incoming JWT, the policy does not reject the token for that specific validation. For both cases, if a claim is present, the policy validates the token value. If the validation fails, the JWT will be rejected.
Numéro d’article de la base de connaissances

001120553

 
Chargement
Salesforce Help | Article