REST API occasionally responds with HTTP 401 error despite valid JWT

[Ori Atkins]

Kia ora all,

I'm writing a library to integrate one of our services with DSpace 7.6 and I'm having an issue with the REST API that occurs when I run integration tests.

Every so often, a call to the REST API will return an HTTP 401 Unauthorized, despite being logged in as an admin account, the JWT not having expired, and correctly sending the CSRF header and cookie.

Looking at the logs, it seems that DSpace is detecting the JWT as invalid. However, the same token is used both before and after this point without issue, as shown below:

2023-11-14 11:28:52,796 DEBUG unknown unknown org.dspace.app.rest.security.jwt.JWTTokenHandler @ Received valid token for username: ori.a...@vuw.ac.nz

2023-11-14 11:28:52,864 WARN  unknown unknown org.dspace.app.rest.security.jwt.JWTTokenHandler @ 0:0:0:0:0:0:0:1 tried to use an expired or non-valid token

2023-11-14 11:28:52,968 DEBUG unknown unknown org.dspace.app.rest.security.jwt.JWTTokenHandler @ Received valid token for username: ori.a...@vuw.ac.nz

This occurs even I if I add a check to the /authn/status endpoint to ensure that the client is still authenticated before making each call.

The only related oddity I've managed to note in the logs is that the EPerson for the user is mostly blank:

2023-11-14 11:28:52,913 DEBUG unknown 4eb31978-f7fd-414f-851c-a9a0d7071efe org.hibernate.internal.util.EntityPrinter @ org.dspace.eperson.EPerson{handles=<uninitialized>, metadata=<uninitialized>, salt=[redacted], lastActive=2023-11-14 11:28:51.279, sessionSalt=, netid=null, resourcePolicies=<uninitialized>, requireCertificate=false, groups=<uninitialized>, digestAlgorithm=SHA-512, selfRegistered=false, canLogIn=true, password=[redacted], legacyId=null, id=41784848-fe6c-4b7e-82db-c81fe3c89f6e, email=ori.a...@vuw.ac.nz}

But for other calls it's populated correctly.

Ngā mihi nui,

Ori

[DSpace Technical Support]

Hi Ori,

This is odd, and the behavior (in the logs) make it seem like there are multiple calls to the REST API happening here (or maybe one of those calls is using a temporary "short lived" token?).

When I see those three logged lines, they don't seem possible to occur *for the same request*.  Each time you see that "Received valid token" or "tried to use an expired token" sort of message should be a separate REST API request (as far as I'm aware).  That'd imply to me that perhaps one of those requests is using either a token that either *is invalid* or *is expired*.

It is also possible that it's something with your EPerson object.  I do see that token "invalidation" occurs by setting the "SessionSalt" to empty.  This kills the user's session.  See the code here: https://github.com/DSpace/DSpace/blob/main/dspace-server-webapp/src/main/java/org/dspace/app/rest/security/jwt/JWTTokenHandler.java#L194-L203

If you are curious about how JWTs are supposed to behave, they have very extensive automated tests (to ensure they are secure) in these classes.  There are many scenarios tested there including expired tokens, tampered tokens, token invalidation, etc.  Maybe they can provide clues to you as well.

* https://github.com/DSpace/DSpace/blob/main/dspace-server-webapp/src/test/java/org/dspace/app/rest/security/jwt/JWTTokenHandlerTest.java

* https://github.com/DSpace/DSpace/blob/main/dspace-server-webapp/src/test/java/org/dspace/app/rest/AuthenticationRestControllerIT.java

I admit, it's very difficult to understand what is going on here. But those are my best guesses based on what you've provided.

Tim

[Ori Atkins]

Kia ora Tim,

 

Thank you for the response! Those were useful places to check.

 

These are separate API requests, but all of them are using the same JWT that was issued via a call to /authn/login. The process is to authenticate, and then use the received JWT to make a series of requests.

 

Thanks for pointing out the sessionSalt; I’ve checked the logs again, and the sessionSalt for the EPerson has the same value for every call the tests make – except the one that is failing, as you noted. I’ve included some of the relevant hibernate log lines:

 

                Line 35779: 2023-11-14 11:28:51,313 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Processing attribute `sessionSalt` : value = LZ0MyzKNja8CngVszdQNKK4rasVLKsVm

                Line 35780: 2023-11-14 11:28:51,313 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Attribute (`sessionSalt`)  - enhanced for lazy-loading? - false

                Line 35820: 2023-11-14 11:28:51,329 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Processing attribute `sessionSalt` : value = LZ0MyzKNja8CngVszdQNKK4rasVLKsVm

                Line 35821: 2023-11-14 11:28:51,329 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Attribute (`sessionSalt`)  - enhanced for lazy-loading? - false

                Line 36242: 2023-11-14 11:28:51,350 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Processing attribute `sessionSalt` : value =

                Line 36243: 2023-11-14 11:28:51,350 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Attribute (`sessionSalt`)  - enhanced for lazy-loading? - false

                Line 36912: 2023-11-14 11:28:51,426 DEBUG unknown unknown org.hibernate.engine.internal.TwoPhaseLoad @ Processing attribute `sessionSalt` : value = LZ0MyzKNja8CngVszdQNKK4rasVLKsVm

 

If the JWT had actually been invalidated or expired, I would not expect the subsequent calls to authenticate successfully using the same JWT. I would also anticipate that the sessionSalt would be different (per https://github.com/DSpace/DSpace/blob/50b47b707ccc4f0d7ed3887f08f0a88a39686f29/dspace-server-webapp/src/main/java/org/dspace/app/rest/security/jwt/JWTTokenHandler.java#L402C31-L402C31). I’m wondering if the issue is occurring during the retrieval, caching, or instantiation of the EPerson. Whether within DSpace or some issue with the database.

 

It’s a bit of a head-scratcher, because when I run the API calls in isolation, they all work perfectly. It’s only when I run the entire suite that this happens.  I’d suggest some sort of race condition, but it’s always failing in the same location. I initially thought it was a expiry or timeout – but the JWT is valid for 30 minutes, and this occurs in a matter of seconds.

 

Ngā mihi,

 

Ori Atkins (any pronouns)

Systems and Integration Developer

Te Pātaka Kōrero | The Library

Te Herenga Waka—Victoria University of Wellington

 

Phone    +64 4 463 5520

www.wgtn.ac.nz | 0800 04 04 04

 

NB: I am on the autistic spectrum, please be clear and direct in your replies

--
All messages to this mailing list should adhere to the Code of Conduct: https://www.lyrasis.org/about/Pages/Code-of-Conduct.aspx
---
You received this message because you are subscribed to a topic in the Google Groups "DSpace Technical Support" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/dspace-tech/JIUBkNfVtXk/unsubscribe.
To unsubscribe from this group and all its topics, send an email to dspace-tech...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/dspace-tech/8b749ac0-6410-4783-922c-8377a291c296n%40googlegroups.com.