ConstraintViolationException: Last activity instant must be greater than 0

[kevinfoote]

Under certain conditions this error is exposed. Out of 30k logins this error was present 160 times during the course of a day. The result is a failed login where the users has to restart their browser to gain access to a shibboleth protected service.

In the thread linked below Scott indicated this can not be storage related. However, I have moved back to server-side storage and the error has been eliminated.

https://marc.info/?l=shibboleth-users&m=145409096929032&w=2

2016-01-29 08:43:55,118 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:126] - [my.ip] - Profile Action PopulateAuthenticationContext: Installing custom PrincipalEvalPredicateFactoryRegistry into AuthenticationContext
2016-01-29 08:43:55,118 - DEBUG [net.shibboleth.idp.authn.impl.PopulateAuthenticationContext:167] - [my.ip] - Profile Action PopulateAuthenticationContext: Installed 1 authentication flows into AuthenticationContext
2016-01-29 08:43:55,118 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedSessionManager:707] - [my.ip] - Performing primary lookup on session ID bbd2cdb85ba41117918adc88c1b06939a728d85bcec3d629e656ae11901b3904
2016-01-29 08:43:55,119 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedIdPSession:90] - [my.ip] - Updating expiration of master record for session bbd2cdb85ba41117918adc88c1b06939a728d85bcec3d629e656ae11901b3904 to 2016-01-29T09:43:55.119-08:00
2016-01-29 08:43:55,121 - DEBUG [net.shibboleth.idp.session.impl.StorageBackedIdPSession:528] - [my.ip] - Loading AuthenticationResult for flow authn/Password in session bbd2cdb85ba41117918adc88c1b06939a728d85bcec3d629e656ae11901b3904
2016-01-29 08:43:55,122 - ERROR [net.shibboleth.idp.authn:-2] - [my.ip] - Uncaught runtime exception
net.shibboleth.utilities.java.support.logic.ConstraintViolationException: Last activity instant must be greater than 0
        at net.shibboleth.utilities.java.support.logic.Constraint.isGreaterThan(Constraint.java:81)
2016-01-29 08:43:55,122 - WARN [org.opensaml.profile.action.impl.LogEvent:76] - [my.ip] - An error event occurred while processing the request: RuntimeException

[scalding]

Couple questions:

1. Did this happen in a previous version of the IdP? I've not been able to do any full testing on 3.2.1, yet (it's on my todo list)
2. Can you provide a full stack trace for the exception? I'd like to see if I can induce the problem.

Something I find odd in that thread is that expiration can be null, so a last time used based on that could be tricky. Need to find out what type of storage records are getting stored poorly. Thanks

[scalding]

Another thought that came to mind: are you running on multiple systems? If so, how close are their clocks?

[kevinfoote]

2 nodes same campus, same time server.
I'm trying to reproduce on test env in idp 3.2.1 currently
I'll try to post more info..

[kevinfoote]

So the way I can reproduce this reliably is to throw an SP in to the mix that has forceAuthn to true.
Not sure what exactly that means session wise or why it would matter.

[idp.properties]
idp.storage.cleanupInterval = PT10M
idp.storage.htmlLocalStorage = false
idp.session.enabled = true
idp.session.StorageService = shibboleth.HazelcastStorageService
idp.replayCache.StorageService = shibboleth.HazelcastStorageService
idp.cas.StorageService = shibboleth.HazelcastStorageService

[scalding]

Great, thanks. I'll need to dig into this later, but this gives me a good place to start.

[scalding]

Okay, I'm able to replicate the problem, and notice that -6 is, indeed, not greater than 0. I'll dig into it and see what bubbles.

[scalding]

Okay, I was able to track down the problem. Turns out I was (wrongly) storing a computed time with the record. I'm surprised this hasn't turned up before. Thanks for the report, and let me know if the latest commit fixes this problem.

[kevinfoote]

Nice!

[kevinfoote]

Rebuilt jar off the new code and deployed into testing locally.
I have not been able to reproduce at all using previous steps.

[kevinfoote]

Update: (nearly 3 months later)
Test environment showed no errors.
Moved this to production and hazelcast session layer seems to be stable.

[scalding]

Looks to be resolved