Record "disappears" from client side storage?

[Paul B. Henson]

I no longer use server-side storage for anything, everything is client-side storage. I occasionally get these errors saying that a session has disappeared from the backing store, and I'm not clear on why this happens? It seems the only way the idp would have known about this session in the first place while processing the request is if the client provided the appropriate data to enumerate it? So how would it "disappear" from storage between the time the client provided it and the server wanted to update it?

This is the error part:

2024-09-11 17:42:33,801 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - ERROR [net.shibboleth.idp.session.impl.StorageBackedIdPSession:754] - Record for session a84656a1aba29bee3bea3ea3a595c05109c31af5efad750636c773263f6f702d has disappeared from backing store
2024-09-11 17:42:33,807 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - ERROR [net.shibboleth.idp.session.impl.UpdateSessionWithAuthenticationResult:167] - Profile Action UpdateSessionWithAuthenticationResult: Error updating session a84656a1aba29bee3bea3ea3a595c05109c31af5efad750636c773263f6f702d
net.shibboleth.idp.session.SessionException: Exception saving AuthenticationResult record to storage
        at net.shibboleth.idp.session.impl.StorageBackedIdPSession.addAuthenticationResult(StorageBackedIdPSession.java:249)
Caused by: java.io.IOException: Unable to update session, record disappeared
        at net.shibboleth.idp.session.impl.StorageBackedIdPSession.writeToStorage(StorageBackedIdPSession.java:755)

And here is the complete log for that session. It looks like the user successfully logs in and is issued a ticket, and then immediately successfully authenticates again, but after duo returns the second time it complains about the session disappearing? It seems odd that less than 30 seconds after successfully authenticating the idp would try to authenticate him again?

2024-09-11 17:41:49,656 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shi
bboleth.idp.session.impl.StorageBackedIdPSession:111] - Session a84656a1aba29bee3bea3ea3a595c05109c31af5efad75
0636c773263f6f702d not yet bound to IPV6 address, binding to 2620:df:8000:4785:0:2:5212:97aa
2024-09-11 17:41:57,841 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shi
bboleth.idp.authn.impl.KerberosCredentialValidator:201] - Credential Validator krb5: Login by 'scoronel1' succ
eeded
2024-09-11 17:41:58,204 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shi
bboleth.idp.plugin.authn.duo.impl.DuoOIDCAuthnController:147] - Starting Duo 2FA for client 'DILWIOBUEP58ECKZ9
ANU', user 'scoronel1', and unique request state 'fbaa9e22db258f071de3ad3deea2c6e2'
2024-09-11 17:42:04,037 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.plugin.authn.duo.impl.DuoOIDCAuthnController:219] - Finished Duo 2FA for client 'DILWIOBUEP58ECKZ9ANU', user 'scoronel1', and unique request state 'fbaa9e22db258f071de3ad3deea2c6e2'
2024-09-11 17:42:04,414 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.plugin.authn.duo.impl.ValidateDuoTokenAuthenticationResult:210] - Profile Action ValidateDuoTokenAuthenticationResult: Duo 2FA authentication succeeded for 'scoronel1', using second-factor 'remembered_device'
2024-09-11 17:42:04,415 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.authn.impl.FinalizeAuthentication:201] - Profile Action FinalizeAuthentication: Principal scoronel1 authenticated
2024-09-11 17:42:04,420 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.cas.flow.impl.GrantServiceTicketAction:242] - Profile Action GrantServiceTicketAction: Granted service ticket for https://my.cpp.edu/uPortal/Login
2024-09-11 17:42:30,415 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.authn.impl.KerberosCredentialValidator:201] - Credential Validator krb5: Login by 'scoronel1' succeeded
2024-09-11 17:42:30,439 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.plugin.authn.duo.impl.DuoOIDCAuthnController:147] - Starting Duo 2FA for client 'DILWIOBUEP58ECKZ9ANU', user 'scoronel1', and unique request state '16adb09fe5fb2051e0b6ecb748e12abb'
2024-09-11 17:42:33,407 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.plugin.authn.duo.impl.DuoOIDCAuthnController:219] - Finished Duo 2FA for client 'DILWIOBUEP58ECKZ9ANU', user 'scoronel1', and unique request state '16adb09fe5fb2051e0b6ecb748e12abb'
2024-09-11 17:42:33,799 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.plugin.authn.duo.impl.ValidateDuoTokenAuthenticationResult:210] - Profile Action ValidateDuoTokenAuthenticationResult: Duo 2FA authentication succeeded for 'scoronel1', using second-factor 'remembered_device'
2024-09-11 17:42:33,800 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - INFO [net.shibboleth.idp.authn.impl.FinalizeAuthentication:201] - Profile Action FinalizeAuthentication: Principal scoronel1 authenticated
2024-09-11 17:42:33,801 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - ERROR [net.shibboleth.idp.session.impl.StorageBackedIdPSession:754] - Record for session a84656a1aba29bee3bea3ea3a595c05109c31af5efad750636c773263f6f702d has disappeared from backing store
2024-09-11 17:42:33,807 - 2620:df:8000:4785:0:2:5212:97aa/node0xxbf8hboisledl76wrhp07lg1096463 - ERROR [net.shibboleth.idp.session.impl.UpdateSessionWithAuthenticationResult:167] - Profile Action UpdateSessionWithAuthenticationResult: Error updating session a84656a1aba29bee3bea3ea3a595c05109c31af5efad750636c773263f6f702d


--
Paul B. Henson | Operating Systems and Network Analyst
henson at cpp.edu | California State Polytechnic University Pomona