memcached failover question

[Daniel Hutchison]

Hey all,

I've been moving my QA environment over to shibboleth v3.2.1, and I have
been trying to setup memcached for session management (especially SLO).
Everything seems to be working correctly when all three memcached
instances are running.   However, I've run across an unexpected result
(at  least, unexpected for me...) when one of the memcached servers
fails.

I have setup my memcached storage service per the instructions here:
https://wiki.shibboleth.net/confluence/display/IDP30/StorageConfiguration

The test:

        User logs into a service provider.   Result Success.
        User logs out of service provider.  Result Success.
        
        (clean browser):
        User logs into a service provider.  Result success.
        * Stop one of the three memcached servers.
        User logs out of a service provider.  Result failure: SP reports
        ugly unknown principal error, idp logs the following:
        
        
                2016-01-19 11:58:45,994 - ERROR [net.shibboleth.idp.session.impl.StorageBackedSessionManager:758] - Exception while querying based service ID https://myuvu-test.uvu.edu/shibboleth and key AAdzZWNyZXQxlTZPIJ47nqajm+2idesfxm+5pGX9YHbT3PLhLrsQ+OypYa7x+oPoTw292ZqPhtJdnnz1ZEiqWDoIxayuzbOaKYuvgZa1uJ7uHt6fh4O0FKCRJm3CIV8TeyDVD9FPI9hWxAf1syiyeT1RM6w=
                java.io.IOException: Memcached operation error
                        at org.opensaml.storage.impl.memcached.MemcachedStorageService.handleAsyncResult(MemcachedStorageService.java:611)
                Caused by: java.util.concurrent.ExecutionException: java.util.concurrent.CancellationException: Cancelled
                        at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:177)
                Caused by: java.util.concurrent.CancellationException: Cancelled
                        at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:177)
                2016-01-19 11:58:46,008 - ERROR [net.shibboleth.idp.saml.saml2.profile.impl.ProcessLogoutRequest:320] - Profile Action ProcessLogoutRequest: Error resolving matching session(s)
                net.shibboleth.utilities.java.support.resolver.ResolverException: Exception while querying based on SPSession
                        at net.shibboleth.idp.session.impl.StorageBackedSessionManager.lookupBySPSession(StorageBackedSessionManager.java:760)
                Caused by: java.io.IOException: Memcached operation error
                        at org.opensaml.storage.impl.memcached.MemcachedStorageService.handleAsyncResult(MemcachedStorageService.java:611)
                Caused by: java.util.concurrent.ExecutionException: java.util.concurrent.CancellationException: Cancelled
                        at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:177)
                Caused by: java.util.concurrent.CancellationException: Cancelled
                        at net.spy.memcached.internal.OperationFuture.get(OperationFuture.java:177)
                2016-01-19 11:58:46,011 - WARN [org.opensaml.profile.action.impl.LogEvent:76] - An error event occurred while processing the request: SessionNotFound
                
        
        (clean browser): one memcached server still down:
        User logs into a service provider.   Result Success.
        User logs out of service provider.  Result Success.
        
        (clean browser): one memcached server still down:
        User logs into a service provider.   Result Success.
        * Start back up the memcached server that was down.
        * Wait until IdP connects back to the memcached server ( I
        enabled verbose logging on the memcached to see when this
        happened)
        User logs out of a service provider.  Result Failure
        
                SP reports the UnknownPrincipal FatalProfileException
                to the user.
                IDP logs:
                
                        2016-01-19 12:08:22,895 - INFO [net.shibboleth.idp.saml.saml2.profile.impl.ProcessLogoutRequest:315] - Profile Action ProcessLogoutRequest: No active session(s) found matching LogoutRequest
                        2016-01-19 12:08:22,898 - WARN [org.opensaml.profile.action.impl.LogEvent:76] - An error event occurred while processing the request: SessionNotFound
                
                memcached logs:
                
                        <31 GET 000001525b3eb823:AAdzZWNyZXQxyQOTCwPrTRgaS8sEiE1QiBvwmEViuK/bKEIz3uJT427qhbjfvFv4e2B6LSdo2re4LFJ21o/bn/KvRPIxr1GwMnplqHqref445DBqWRTwyHkOKmnLHd+pMBk/MqC2OvrwThS/2VuozMJhkoI=
                        >31 Writing an error: Not found
                        
        
        (clean browser):
        User logs into a service provider.   Result Success.
        User logs out of service provider.  Result Success.
        

So, is this normal behavior, and I read too much into
MemcachedStorageService's ability to handle failover?   If I wanted to
avoid users seeing the UnknownPrincipal errors during a situation like
this, would switching to a database backed storage solve the issue?
Are there any ways to better configure memcached to handle errors when a
node is moving in and out of the memcached "cluster"?

Thanks,

-daniel
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20160119/010441c6/attachment-0001.html>