MemCached StoragesService Compatibility
Esmeralda Câmara
epires at fccn.pt
Wed Jan 11 15:06:03 GMT 2012
Hi Manuel,
Yes, x509 authentication was working ok before the Memcached Storage
Service.
The only difference from the instructions on
https://wiki.shibboleth.net/confluence/display/SHIB2/X.509+Login+Handler
Is that I had to change the filter in data connectorbecause I need
SERIALNUMBER=BI<VALUE> to match my users on LDAP.
<resolver:Dependency ref="x500Principal" />
<dc:FilterTemplate>
<![CDATA[
#if( !$x500Principal.Empty )
#set( $subject = $requestContext.getUserSession().getSubject())
#set( $sub_str = $subject.toString() )
#set( $dn = $sub_str.split(", ") )
#foreach( $item in $dn )
#if( $item.startsWith("SERIALNUMBER=BI") )
#set( $size = $item.length() )
#set( $last_pos = $size - 1 )
#set( $serial = $item.substring(15,$last_pos) )
#end
#end
(info=$serial)
#else
(sAMAccountName=$requestContext.principalName)
#end
]]>
</dc:FilterTemplate>
But before the Memcached Storage Service it was working fine.
In attached a new file with log lines.
Thanks
Esmeralda
On 11-01-2012 14:13, Manuel Haim wrote:
> Hi Esmeralda,
>
> thank you for sending your logs. Now, I will see what I can do.
>
> Did x509 authentication work for you before, i.e. without the Memcached
> StorageService?
>
> I am still confused there is no error message within your logs, but the
> log lines seem to tell me the x509 authentication itself is working
> correctly. The client certificate is read, and its principal is put into
> the Subject (which will later be read by the attribute resolver).
>
> Then I see some output from the Memcached StorageService. The only line
> which seems to be suspicious to me is
>
> 10:39:40.769 - DEBUG
> [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:94] -
> storageService.contains: session!CN=ESMERALDA ...
>
> as it should be followed by a line like "contained global" or "contained
> nowhere", but it is not.
>
> Could you send me some more lines, maybe a complete login attempt? I
> need to see the point where the IdP fails, so I may have a guess where
> things start to get wrong... it would also be helpful if you enabled
> TRACE mode in logging.xml, just replace "INFO" with "TRACE" in this line:
>
> <logger name="edu.internet2.middleware.shibboleth" level="TRACE" />
>
>
>> Do we have to update or change something on the configuration of x509
>> login handler similar to what we have done on login.config
> No. Looking at the X509LoginServlet.java sourcecode and your logs, only
> a javax.security.auth.x500.X500Principal (which is serializable) is
> added to the Subject. This should not be a problem.
>
>
>> Another issue that I notice, when I run tomcat shutdown.sh some java
>> process ( I think clients of mechached //usr/local/jdk1.6.0_29/bin/java
>> -Djava.util.logging.config.file=/usr/local/apache-tomcat-6.0.33/conf/logging.properties
>> -Djava.util.logging.manager=org.apache.juli.ClassLoade ) do not die.
> That is true, the Memcached connection is not closed automatically.
> However, when you shutdown tomcat, all ressources are freed, and this
> one is reported as a "possible memory leak". It would be one, if you
> only restarted the IdP webapp and not the whole servlet container (i.e.
> tomcat). According to the Shibboleth team, the IdP is not intended to be
> restarted itself, but you should always restart the servlet container.
>
> In our current development, we added the following code to the
> UniMrMemcachedStorageService constructor to circumvent this problem (not
> yet sure if this already works):
>
> Runtime.getRuntime().addShutdownHook(new Thread(new Runnable() {
> public void run() {
> client.shutdown(); // shutdown the memcached client
> }
> }));
>
>
> -Manuel
>
> --
> To unsubscribe from this list send an email to users-unsubscribe at shibboleth.net
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://shibboleth.net/pipermail/users/attachments/20120111/7495a6a6/attachment-0001.html
-------------- next part --------------
14:31:52.762 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - Retrieved LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:31:52.763 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.provider.UsernamePasswordLoginServlet:150] - Redirecting to login page /login.jsp
14:31:52.837 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:52.848 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:52.861 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:52.863 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:53.682 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:53.687 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:53.688 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:31:53.688 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:32:42.704 - TRACE [ch.SWITCH.aai.idp.x509.X509LoginServlet:49] - servlet initialization
14:32:42.705 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:32:42.705 - TRACE [ch.SWITCH.aai.idp.x509.X509LoginServlet:53] - servlet service
14:32:42.707 - DEBUG [ch.SWITCH.aai.idp.x509.X509LoginServlet:56] - 1 X509Certificates found in request
14:32:42.708 - DEBUG [ch.SWITCH.aai.idp.x509.X509LoginServlet:74] - Adding SubjectX500Principal CN=ESMERALDA PIRES CÂMARA, SERIALNUMBER=BIxxxxxxx, GIVENNAME=ESMERALDA, SURNAME=PIRES CÂMARA, OU=Autenticação do Cidadão, OU=Cidadão Português, O=Cartão de Cidadão, C=PT of type class javax.security.auth.x500.X500Principal as principal to subject
14:32:42.708 - DEBUG [ch.SWITCH.aai.idp.x509.X509LoginServlet:97] - Certificate contains no subjectAlternativeNames
14:32:42.720 - DEBUG [ch.SWITCH.aai.idp.x509.X509LoginServlet:103] - Forward subject Subject:
Principal: CN=ESMERALDA PIRES CÂMARA, SERIALNUMBER=BIxxxxxxx, GIVENNAME=ESMERALDA, SURNAME=PIRES CÂMARA, OU=Autenticação do Cidadão, OU=Cidadão Português, O=Cartão de Cidadão, C=PT
.................
to the AuthenticationEngine
14:32:42.720 - DEBUG [ch.SWITCH.aai.idp.x509.X509LoginServlet:106] - GET parameter x509-pass-through is null
14:32:42.721 - TRACE [ch.SWITCH.aai.idp.x509.X509LoginServlet:113] - Set request attribute authnMethod to urn:oasis:names:tc:SAML:2.0:ac:classes:X509
14:32:42.721 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:144] - Returning control to authentication engine
14:32:42.721 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:333] - Looking up LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:32:42.721 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5bb19dc3-7e2e-48da-896a-dbd556b0fb34
14:32:42.722 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:200] - memcached global value is null
14:32:42.723 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:208] - local value is: edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 6972f1
14:32:42.723 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 6972f1
14:32:42.723 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - Retrieved LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:32:42.723 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:209] - Processing incoming request
14:32:42.724 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:333] - Looking up LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:32:42.724 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5bb19dc3-7e2e-48da-896a-dbd556b0fb34
14:32:42.725 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:200] - memcached global value is null
14:32:42.725 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:208] - local value is: edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 6972f1
14:32:42.725 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 6972f1
14:32:42.726 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - Retrieved LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:32:42.726 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:517] - Completing user authentication process
14:32:42.726 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:588] - Validating authentication was performed successfully
14:32:42.726 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:699] - Updating session information for principal CN=ESMERALDA PIRES CÂMARA,2.5.4.5=#130b4249313438343431333139,2.5.4.42=#0c0453415241,2.5.4.4=#0c0d50495245532043c3824d415241,OU=Autenticação do Cidadão,OU=Cidadão Português,O=Cartão de Cidadão,C=PT
14:32:42.727 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:703] - Creating shibboleth session for principal CN=ESMERALDA PIRES CÂMARA,2.5.4.5=#130b4249313438343431333139,2.5.4.42=#0c0453415241,2.5.4.4=#0c0d50495245532043c3824d415241,OU=Autenticação do Cidadão,OU=Cidadão Português,O=Cartão de Cidadão,C=PT
14:32:42.732 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:288] - storageService.put: session!f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2 edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 148ab5c
14:32:42.733 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:395] - put writes global value.
14:32:42.746 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:402] - index: f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2
14:32:42.746 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:411] - writing global publicCredentials... []
14:32:42.747 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:467] - put writes local value.
14:32:42.747 - TRACE [edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerImpl:98] - Created session f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2
14:32:42.747 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:809] - Adding IdP session cookie to HTTP response
14:32:42.757 - DEBUG [edu.internet2.middleware.shibboleth.idp.authn.AuthenticationEngine:718] - Recording authentication and service information in Shibboleth session for principal: CN=ESMERALDA PIRES CÂMARA,2.5.4.5=#130b4249313438343431333139,2.5.4.42=#0c0453415241,2.5.4.4=#0c0d50495245532043c3824d415241,OU=Autenticação do Cidadão,OU=Cidadão Português,O=Cartão de Cidadão,C=PT
14:32:42.758 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:94] - storageService.contains: session!CN=ESMERALDA PIRES CÂMARA,2.5.4.5=#130b4249313438343431333139,2.5.4.42=#0c0453415241,2.5.4.4=#0c0d50495245532043c3824d415241,OU=Autenticação do Cidadão,OU=Cidadão Português,O=Cartão de Cidadão,C=PT
14:32:42.771 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:333] - Looking up LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:32:42.771 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: loginContexts!5bb19dc3-7e2e-48da-896a-dbd556b0fb34
14:32:42.772 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:200] - memcached global value is null
14:32:42.772 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:208] - local value is: edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 6972f1
14:32:42.773 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.authn.LoginContextEntry at 6972f1
14:32:42.773 - TRACE [edu.internet2.middleware.shibboleth.idp.util.HttpServletHelper:339] - Retrieved LoginContext with key 5bb19dc3-7e2e-48da-896a-dbd556b0fb34 from StorageService parition: loginContexts
14:32:42.785 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:109] - Attempting to retrieve IdP session cookie.
14:32:42.786 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:115] - Found IdP session cookie.
14:32:42.786 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: session!f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2
14:32:42.796 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:186] - memcached global value is: edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 109558d
14:32:42.797 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:189] - retrieving global publicCredentials...
14:32:42.799 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:195] - added global publicCredentials to global value.
14:32:42.799 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:208] - local value is: edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 148ab5c
14:32:42.799 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:226] - comparing and merging global/local value...
14:32:42.799 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:235] - localValue time: 2012-01-11T15:02:42.731Z
14:32:42.799 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:236] - globalObject time: 2012-01-11T15:02:42.731Z
14:32:42.799 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:237] - localValueIsNewer: true
14:32:42.804 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:256] - overwriting global publicCredentials... []
14:32:42.804 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:260] - returning local value (overwriting global)...
14:32:42.804 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 148ab5c
14:32:42.805 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:75] - Updating IdP session activity time and adding session object to the request
14:32:42.805 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:61] - UniMrMemcachedServletFilter: session available, storing on memcached.
14:32:42.805 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:130] - storageService.get: session!f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2
14:32:42.810 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:186] - memcached global value is: edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 8edd79
14:32:42.810 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:189] - retrieving global publicCredentials...
14:32:42.811 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:195] - added global publicCredentials to global value.
14:32:42.811 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:208] - local value is: edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 148ab5c
14:32:42.811 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:226] - comparing and merging global/local value...
14:32:42.812 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:235] - localValue time: 2012-01-11T15:02:42.805Z
14:32:42.812 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:236] - globalObject time: 2012-01-11T15:02:42.731Z
14:32:42.812 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:237] - localValueIsNewer: true
14:32:42.814 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:256] - overwriting global publicCredentials... []
14:32:42.814 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:260] - returning local value (overwriting global)...
14:32:42.814 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:270] - get returns edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 148ab5c
14:32:42.814 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:288] - storageService.put: session!f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2 edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 148ab5c
14:32:42.818 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:344] - memcached global value is: edu.internet2.middleware.shibboleth.idp.session.impl.SessionManagerEntry at 16e3f87
14:32:42.818 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:361] - localValue time: 2012-01-11T15:02:42.805Z
14:32:42.818 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:362] - globalObject time: 2012-01-11T15:02:42.805Z
14:32:42.818 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:363] - localValueIsNewer: true
14:32:42.818 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:395] - put writes global value.
14:32:42.820 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:402] - index: f95b520c87fc8b4f62838187bcadb545ba7c27abcd6360469c57cc938b08fed2
14:32:42.820 - TRACE [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:411] - writing global publicCredentials... []
14:32:42.820 - DEBUG [edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter:467] - put writes local value.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: smime.p7s
Type: application/pkcs7-signature
Size: 1910 bytes
Desc: S/MIME Cryptographic Signature
Url : http://shibboleth.net/pipermail/users/attachments/20120111/7495a6a6/attachment-0001.bin
More information about the users
mailing list