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<http://www.wgtn.ac.nz/> | 0800 04 04 04
NB: I am on the autistic spectrum, please be clear and direct in your replies
From: DSpace Technical Support <[email protected]>
Sent: Friday, 17 November 2023 6:47 am
To: DSpace Technical Support <[email protected]>
Subject: [dspace-tech] Re: REST API occasionally responds with HTTP 401 error
despite valid JWT
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
On Monday, November 13, 2023 at 5:52:51 PM UTC-6
[email protected]<mailto:[email protected]> wrote:
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: [email protected]
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: [email protected]
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 protected]}
But for other calls it's populated correctly.
Ngā mihi nui,
Ori
--
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
[email protected]<mailto:[email protected]>.
To view this discussion on the web visit
https://groups.google.com/d/msgid/dspace-tech/8b749ac0-6410-4783-922c-8377a291c296n%40googlegroups.com<https://groups.google.com/d/msgid/dspace-tech/8b749ac0-6410-4783-922c-8377a291c296n%40googlegroups.com?utm_medium=email&utm_source=footer>.
--
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 the Google Groups
"DSpace Technical Support" group.
To unsubscribe from this group and stop receiving emails from it, send an email
to [email protected].
To view this discussion on the web visit
https://groups.google.com/d/msgid/dspace-tech/SY4PR01MB6316AB177C6607DC907A1DE6C8B0A%40SY4PR01MB6316.ausprd01.prod.outlook.com.
