Problem with SOAP call to 2.4.4 IdP / port 8443 / F5 load balancer

Benji Wakely B.Wakely at latrobe.edu.au
Tue Nov 10 00:53:14 EST 2015 

Greetings, all.

Summary:
                Previously working httpd frontend/tomcat backend (Shib IdP 2.4.4) fails to work for SOAP
back-channel binding after putting it behind a load balancer.

Full story:

We're migrating from a single-server IdP instance,
apache httpd front-end,
tomcat back end,
mysql server

to:
                separate mysql server instance,
                F5 load-balancer as the front-end,
                Two back-end nodes, still with apache and with tomcat as the back end [1].

It Just Works, for standard front-channel requests,
but there's One service that I can find that does a back-channel request,
SAML 1.0/SOAP call to port 8443,
which is failing.

On the single server it works,
On the new setup, it doesn't.
The new server is a VM directly cloned from the old server,
so there's no significant config differences that I can see.

It also fails when I stick the legacy server behind the F5 load balancer.
Definitely not a config difference.


This is pretty relevant to the email thread at
http://shibboleth.net/pipermail/users/2015-August/023696.html
but the F5 seems like a new component / not mentioned in that email, and it's working without the F5.

There's a full TRACE log of the relevant (failed) transaction below my signature for clarity,
but in essence:

-          front-channel binding happens well, with the published metadata

-          browser pauses for a second at the SP to allow back-channel binding to occur

-          back-channel request comes in with a slightly different certificate

-          back-channel request is denied

-          SP returns "Inter-institutional access failure. Please contact your system administrator for assistance."

I can see why that might get rejected easily enough - the certificate differs, so it gets rejected -
but my question is:

Why was it ever working in the first place with plain apache httpd --> tomcat?

I'm aware of how httpd magically Doesn't Mangle client certificates using AJP (+ExportCertData option),
I've set up the F5 so it should in theory be passing traffic straight through / not acting as an intermediate as such [2]
but Something is still getting mangled.


Does this ring any bells for anyone who has experienced this particular pain?

Best regards,
--Benji

[1]: I know it's more sensible to just have F5 talking straight to tomcat,
but it's an interim measure prior to v3 migration and extreme workload pressure.  Usual story.

[2]: F5 LTM, virtual server - Type, Performance (Layer 4), protocol TCP, Protocol Profile (Client) fastL4, no HTTP Profile, Source Address translation: Auto Map

Benji Wakely
Unix Systems Administrator,
La Trobe University, Melbourne AU


============= Full TRACE email for reference: ======================

Failed back-channel authentication:

15:59:05.711 - DEBUG [org.opensaml.ws.security.provider.ClientCertAuthRule:118] - MIIEzDCCA7SgAwIBAgIBCDANBgkqhkiG9w0BAQUFADCBpDEaMBgGA1UEAxMRcHJveHkudmR4aG9z
dC5jb20xCzAJBgNVBAYTAlVTMQ0wCwYDVQQIEwRPaGlvMQ8wDQYDVQQHEwZEdWJsaW4xMTAvBgNV
BAoTKE9DTEMgT25saW5lIENvbXB1dGVyIExpYnJhcnkgQ2VudGVyIEluYy4xJjAkBgkqhkiG9w0B
CQEWF2hhcnVuLmFiZHVsbGFoQG9jbGMub3JnMB4XDTE1MDcwMTA3MjkyNFoXDTI1MDYzMDA3Mjky
NFowgaQxGjAYBgNVBAMTEXByb3h5LnZkeGhvc3QuY29tMQswCQYDVQQGEwJVUzENMAsGA1UECBME
T2hpbzEPMA0GA1UEBxMGRHVibGluMTEwLwYDVQQKEyhPQ0xDIE9ubGluZSBDb21wdXRlciBMaWJy
YXJ5IENlbnRlciBJbmMuMSYwJAYJKoZIhvcNAQkBFhdoYXJ1bi5hYmR1bGxhaEBvY2xjLm9yZzCC
ASIwDQYJKoZIhvcNAQEBBQADggEPADCCAQoCggEBAOTqNhNJbkIriaLVu1a4Dj/GBul2sBHQT9DJ
vAjGqdWP1NSCuri2Dq1y0k0ng3OkNXDdse+zkyQ9goN9rypHpuRbfcuODLbqt8DLun6p04C4b0ad
/hFnRiIyTbJZ1WORjQ8x5krQrIpfti7GACKYwK/viV68HUGrAffXlEmNNUc8F3pt3yayPx+V0o27
6mwYNVRJKhJblwTRDw6I+SCa4HBPZlxzhXTrEHBkT1HQ1tV15en15EFMb+6nBJFDSxWzg5abzW8h
V+9PkeO8WCSqDi6Q5n2IPY2L6E94UlxKF62AFnQwWTY4pD6ssZydtLUKDe89lNhokjt/GOWholEy
9vkCAwEAAaOCAQUwggEBMB0GA1UdDgQWBBTwXv99NVdEop0UslZ+0ysmMHulsjCB0QYDVR0jBIHJ
MIHGgBTwXv99NVdEop0UslZ+0ysmMHulsqGBqqSBpzCBpDEaMBgGA1UEAxMRcHJveHkudmR4aG9z
dC5jb20xCzAJBgNVBAYTAlVTMQ0wCwYDVQQIEwRPaGlvMQ8wDQYDVQQHEwZEdWJsaW4xMTAvBgNV
BAoTKE9DTEMgT25saW5lIENvbXB1dGVyIExpYnJhcnkgQ2VudGVyIEluYy4xJjAkBgkqhkiG9w0B
CQEWF2hhcnVuLmFiZHVsbGFoQG9jbGMub3JnggEIMAwGA1UdEwQFMAMBAf8wDQYJKoZIhvcNAQEF
BQADggEBANwzPoZqFiZjPiuvxhYM9FHnpTV52JZP+VTh6kzjD1opWBbjhTNFGHtbedg2goLRBdKP
bZhT6z5qbqd01GHeX3Ag4Uq9oJFq5s5q2XFjIfKKrjRLmw0Pga6ACPDHSilqGKqqhHYhodtGo9d+
uS0gUBMLp8uRFj+I/ItjTlKY8Or426O9QDmEriqKtnkqXUBo09ikMu86hYBYe8jD0hhZZ89cVIhM
EWp6Da/Qie76v6y7mRDyRPxjpx7+d1RvtsGk/7wEnhwJnx6/w9ChqUqRCGPI9yAAL8OhjnnC0WLK
D5umMB37dMgvO74eFTMWTUVMpfA7EEBbpsAn0n69iqGqpYw=
15:59:05.711 - DEBUG [org.opensaml.ws.security.provider.ClientCertAuthRule:150] - Attempting client certificate authentication using context presenter entity ID: https://proxy.vdxhost.com/shibboleth
15:59:05.716 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:225] - Checking trusted names against credential: [subjectName='1.2.840.113549.1.9.1=#1617686172756e2e616264756c6c6168406f636c632e6f7267,O=OCLC Online Computer Library Center Inc.,L=Dublin,ST=Ohio,C=US,CN=proxy.vdxhost.com']
15:59:05.716 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:227] - Trusted names being evaluated are: [https://proxy.vdxhost.com/shibboleth, *.vdxhost.com]
15:59:05.716 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:356] - Processing subject alt names
15:59:05.716 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:361] - Extracted subject alt names from certificate: []
15:59:05.716 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:288] - Processing subject DN common name
15:59:05.717 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:297] - Extracted common name from certificate: proxy.vdxhost.com
15:59:05.717 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:319] - Processing subject DN
15:59:05.717 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:323] - Extracted X500Principal from certificate: 1.2.840.113549.1.9.1=#1617686172756e2e616264756c6c6168406f636c632e6f7267,O=OCLC Online Computer Library Center Inc.,L=Dublin,ST=Ohio,C=US,CN=proxy.vdxhost.com
15:59:05.717 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:340] - Trusted name was not a DN or could not be parsed: https://proxy.vdxhost.com/shibboleth
15:59:05.718 - DEBUG [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:340] - Trusted name was not a DN or could not be parsed: *.vdxhost.com
15:59:05.718 - ERROR [org.opensaml.xml.security.x509.BasicX509CredentialNameEvaluator:273] - Credential failed name check: [subjectName='1.2.840.113549.1.9.1=#1617686172756e2e616264756c6c6168406f636c632e6f7267,O=OCLC Online Computer Library Center Inc.,L=Dublin,ST=Ohio,C=US,CN=proxy.vdxhost.com']
15:59:05.718 - ERROR [org.opensaml.ws.security.provider.ClientCertAuthRule:157] - Authentication via client certificate failed for context presenter entity ID https://proxy.vdxhost.com/shibboleth

15:59:05.719 - WARN [edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler:180] - Message did not meet security requirements
org.opensaml.ws.security.SecurityPolicyException: Client certificate authentication failed for context presenter entity ID
        at org.opensaml.ws.security.provider.ClientCertAuthRule.doEvaluate(ClientCertAuthRule.java:159) ~[openws-1.5.5.jar:na]
        at org.opensaml.ws.security.provider.ClientCertAuthRule.evaluate(ClientCertAuthRule.java:123) ~[openws-1.5.5.jar:na]
        at org.opensaml.ws.security.provider.BasicSecurityPolicy.evaluate(BasicSecurityPolicy.java:51) ~[openws-1.5.5.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.processSecurityPolicy(BaseMessageDecoder.java:132) ~[openws-1.5.5.jar:na]
        at org.opensaml.ws.message.decoder.BaseMessageDecoder.decode(BaseMessageDecoder.java:83) ~[openws-1.5.5.jar:na]
        at org.opensaml.saml1.binding.decoding.BaseSAML1MessageDecoder.decode(BaseSAML1MessageDecoder.java:109) ~[opensaml-2.6.5.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.decodeRequest(AttributeQueryProfileHandler.java:165) [shibboleth-identityprovider-2.4.4.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:88) [shibboleth-identityprovider-2.4.4.jar:na]
        at edu.internet2.middleware.shibboleth.idp.profile.saml1.AttributeQueryProfileHandler.processRequest(AttributeQueryProfileHandler.java:57) [shibboleth-identityprovider-2.4.4.jar:na]
        at edu.internet2.middleware.shibboleth.common.profile.ProfileRequestDispatcherServlet.service(ProfileRequestDispatcherServlet.java:83) [shibboleth-common-1.4.4.jar:na]
        at javax.servlet.http.HttpServlet.service(HttpServlet.java:717) [tomcat6-servlet-2.5-api-6.0.36.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:290) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina-6.0.36.jar:6.0.36]
        at ch.SWITCH.aai.uApprove.Intercepter.intercept(Intercepter.java:147) [uApprove-2.5.0.jar:na]
        at ch.SWITCH.aai.uApprove.Intercepter.doFilter(Intercepter.java:118) [uApprove-2.5.0.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina-6.0.36.jar:6.0.36]
        at edu.internet2.middleware.shibboleth.idp.util.NoCacheFilter.doFilter(NoCacheFilter.java:50) [shibboleth-identityprovider-2.4.4.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina-6.0.36.jar:6.0.36]
        at edu.internet2.middleware.shibboleth.idp.session.IdPSessionFilter.doFilter(IdPSessionFilter.java:87) [shibboleth-identityprovider-2.4.4.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina-6.0.36.jar:6.0.36]
        at edu.internet2.middleware.shibboleth.common.log.SLF4JMDCCleanupFilter.doFilter(SLF4JMDCCleanupFilter.java:52) [shibboleth-common-1.4.4.jar:na]
        at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:235) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:206) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:219) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:191) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:103) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:109) [catalina-6.0.36.jar:6.0.36]
        at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:293) [catalina-6.0.36.jar:6.0.36]
        at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:190) [tomcat-coyote-6.0.36.jar:6.0.36]
        at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:311) [tomcat-coyote-6.0.36.jar:6.0.36]
        at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:776) [tomcat-coyote-6.0.36.jar:6.0.36]
        at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:705) [tomcat-coyote-6.0.36.jar:6.0.36]
        at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:898) [tomcat-coyote-6.0.36.jar:6.0.36]
        at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:690) [tomcat-coyote-6.0.36.jar:6.0.36]
        at java.lang.Thread.run(Thread.java:662) [na:1.6.0_26]
15:59:05.722 - INFO [Shibboleth-Audit:745] - 20151110T045905Z|urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding|_14471315447819|https://proxy.vdxhost.com/shibboleth|urn:mace:shibboleth:2.0:profiles:saml1:query:attribute|https://aaf-test.latrobe.edu.au/idp/shibboleth|urn:oasis:names:tc:SAML:1.0:bindings:SOAP-binding|_49f0143eb2e37fb1b11ff328f5e5d2ab||||_7a8013c4fe2d95660b5f35c837e7959a||
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://shibboleth.net/pipermail/users/attachments/20151110/f3462c79/attachment-0001.html>

More information about the users mailing list