[Shib-Users] Cannot access https://localhost/shibboleth-idp/SSO. Please help

[Geok Choo Teo-Chee]

Hi,
Appreciate any help on the following problem:
Installed Shibboleth-idp1.3.3 withTomCat 5.5 on a Windows 2003 server,

when accessing the page https://localhost/shibboleth-idp/SSO,
It shows error: HTTP Status 500:

description The server encountered an internal error () that prevented it from fulfilling this request.

javax.servlet.ServletException: Servlet.init() for servlet IdP threw exception
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
java.lang.Thread.run(Unknown Source)

java.lang.NoClassDefFoundError: edu/internet2/middleware/shibboleth/common/ServiceProviderMapper$RelyingPartyImpl$RelyingPartyIdentityProvider
edu.internet2.middleware.shibboleth.common.ServiceProviderMapper$RelyingPartyImpl.<init>(ServiceProviderMapper.java:400)
edu.internet2.middleware.shibboleth.common.ServiceProviderMapper.addRelyingParty(ServiceProviderMapper.java:195)
edu.internet2.middleware.shibboleth.common.ServiceProviderMapper.<init>(ServiceProviderMapper.java:63)
edu.internet2.middleware.shibboleth.idp.IdPResponder.init(IdPResponder.java:143)
org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
java.lang.Thread.run(Unknown Source)
In the tomcat.log file:
13:37:35,406 [TP-Processor3] ERROR StandardWrapper.Throwable - org.apache.catalina.core.ContainerBase.[Catalina].[localhost].[/shibboleth-idp] [20080929]
java.lang.NoClassDefFoundError: edu/internet2/middleware/shibboleth/common/ServiceProviderMapper$RelyingPartyImpl$RelyingPartyIdentityProvider
at edu.internet2.middleware.shibboleth.common.ServiceProviderMapper$RelyingPartyImpl.<init>(ServiceProviderMapper.java:400)
at edu.internet2.middleware.shibboleth.common.ServiceProviderMapper.addRelyingParty(ServiceProviderMapper.java:195)
at edu.internet2.middleware.shibboleth.common.ServiceProviderMapper.<init>(ServiceProviderMapper.java:63)
at edu.internet2.middleware.shibboleth.idp.IdPResponder.init(IdPResponder.java:143)
at org.apache.catalina.core.StandardWrapper.loadServlet(StandardWrapper.java:1139)
at org.apache.catalina.core.StandardWrapper.allocate(StandardWrapper.java:791)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:127)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:174)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:127)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:117)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:108)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:174)
at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:200)
at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:283)
at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:773)
at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:703)
at org.apache.jk.common.ChannelSocket$SocketConnection.runIt(ChannelSocket.java:895)
at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:689)
at java.lang.Thread.run(Unknown Source)

Thanks,
Jasmin

---

NOTICE:
This message may contain privileged/confidential information. If you are not the intended recipient of this email, please delete it immediately and notify the sender .

[Geok Choo Teo-Chee]

Hi,

Running Shibboleth ldP server 1.3.3 on Windows 2003 OS. Testing the ldP with TestShib Service Provider(SP) and getting the following error. Any pointers will be much appreciated.Thanks.

From the TestShib "shibd.log" file,
21:54:51 DEBUG XMLTooling.libcurl [6]: Connected to shibssrv.np.edu.sg (153.20.76.132) port 8443

2008-10-12 21:54:51 DEBUG XMLTooling.libcurl [6]: successfully set certificate verify locations:

2008-10-12 21:54:51 DEBUG XMLTooling.libcurl [6]: CAfile: /usr/share/ssl/certs/ca-bundle.crt
CApath: none

2008-10-12 21:54:51 DEBUG XMLTooling.libcurl [6]: SSLv3, TLS handshake, Client hello (1):

2008-10-12 21:54:51 DEBUG XMLTooling.libcurl [6]: Unknown SSL protocol error in connection to shibssrv.np.edu.sg:8443

2008-10-12 21:54:51 DEBUG XMLTooling.libcurl [6]: Closing connection #0

2008-10-12 21:54:51 ERROR Shibboleth.AttributeResolver [6]: exception during SAML query to https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA: CURLSOAPTransport failed while contacting SOAP responder: Unknown SSL protocol error in connection to shibssrv.np.edu.sg:8443
2008-10-12 21:54:51 ERROR Shibboleth.AttributeResolver [6]: unable to obtain a SAML response from attribute authority
2008-10-12 21:54:51 DEBUG Shibboleth.SessionCache [6]: creating new session

[Nate Klingenstein]

Jasmin,

I think that means the SP couldn't find a mutually acceptable SSL version or ciphersuite in the handshake.  I have no problem connecting to your port 443 virtual host, so Apache itself is fine.  Your port 8443 virtual host's SSL configuration(assuming it's Apache listening, which you should verify) is probably wrong.  It should look like the one in the Wiki, from section 2:

https://spaces.internet2.edu/display/SHIB/JKIdPInstall

If it already does, look for other strange configuration issues.  If you still can't find it then we'd probably have to do some really painful debugging, so I hope this solves it.

Take care,

Nate.

[Geok Choo Teo-Chee]

Hi,
I had modified the file " c:\tomcat\conf\server.xml" with:
<!-- Define an AJP 1.3 Connector on port 8009 -->
<Connector port="8009"
enableLookups="false" redirectPort="8443" protocol="AJP/1.3" tomcatAuthentication="false" address="127.0.0.1" />
And also tested that https request are redirected to TomCat.

But in the URL https://spaces.internet2.edu/display/SHIB/JKIdPInstall, it mentioned that you need to add in the httpd.conf file:

<Location /shibboleth-idp/SSO>  AuthType Basic  AuthName "Villain Verification Service (VVS)"  AuthUserFile /etc/httpd/conf/user.db  require valid-user </Location>

Should I be adding the above to the file "httpd.conf" or extra\httpd-ssl.conf" or extra\httpd-ssl-8443.conf?

Thanks,
Jasmin
Nate Klingenstein <n...@internet2.edu>

Nate Klingenstein <n...@internet2.edu> 13-Oct-2008 10:44 AM Please respond to shibbole...@internet2.edu

To shibbole...@internet2.edu cc Subject Re: [Shib-Users] SAML query Error

[Nate Klingenstein]

Jasmin,

The section you pasted should be added to httpd-ssl.conf, probably, but that's not related to your current problem.  You need to add the 8443 virtual host definition, following the example in section 2, to httpd.conf, outside all virtual hosts.  Make sure Apache doesn't complain about any configuration errors during startup.

Take care,

Nate.

On 13 Oct 2008, at 03:56, Geok Choo Teo-Chee wrote:

Hi,
I had modified the file " c:\tomcat\conf\server.xml" with:
<!-- Define an AJP 1.3 Connector on port 8009 -->
<Connector port="8009"
enableLookups="false" redirectPort="8443" protocol="AJP/1.3" tomcatAuthentication="false" address="127.0.0.1" />
And also tested that https request are redirected to TomCat.

But in the URL https://spaces.internet2.edu/display/SHIB/JKIdPInstall, it mentioned that you need to add in the httpd.conf file:

<Location /shibboleth-idp/SSO>  AuthType Basic  AuthName "Villain Verification Service (VVS)"  AuthUserFile /etc/httpd/conf/user.db  require valid-user </Location>

Should I be adding the above to the file "httpd.conf" or extra\httpd-ssl.conf" or extra\httpd-ssl-8443.conf?

Thanks,
Jasmin

<graycol.gif>Nate Klingenstein <n...@internet2.edu>

Nate Klingenstein <n...@internet2.edu> 13-Oct-2008 10:44 AM Please respond to shibbole...@internet2.edu

<ecblank.gif> To <ecblank.gif> shibbole...@internet2.edu <ecblank.gif> cc <ecblank.gif> <ecblank.gif> Subject <ecblank.gif>

Re: [Shib-Users] SAML query Error

<ecblank.gif> <ecblank.gif>

Jasmin,

I think that means the SP couldn't find a mutually acceptable SSL version or ciphersuite in the handshake.  I have no problem connecting to your port 443 virtual host, so Apache itself is fine.  Your port 8443 virtual host's SSL configuration(assuming it's Apache listening, which you should verify) is probably wrong.  It should look like the one in the Wiki, from section 2:

https://spaces.internet2.edu/display/SHIB/JKIdPInstall

If it already does, look for other strange configuration issues.  If you still can't find it then we'd probably have to do some really painful debugging, so I hope this solves it.

Take care,
Nate.

On 13 Oct 2008, at 02:31, Geok Choo Teo-Chee wrote:

[Geok Choo Teo-Chee]

Hi,
I had added a file httpd-ssl-8443.conf and included this file in the httpd.conf file. The contents of the httpd-ssl-8443.conf is:
Listen 8443
AddType application/x-x509-ca-cert .crt
AddType application/x-pkcs7-crl .crl
SSLPassPhraseDialog builtin
SSLSessionCache shmcb:C:/Apache2.2/logs/ssl_scache(512000)
SSLSessionCacheTimeout 300
SSLMutex default
<VirtualHost _default_:8443>
DocumentRoot "C:/Apache2.2/htdocs"
ServerName shibssrv.np.edu.sg:8443
ServerAdmin ad...@npnet.np.edu.sg
ErrorLog C:/Apache2.2/logs/error_8443.log
TransferLog C:/Apache2.2/logs/access_8443.log
SSLEngine on
SSLCipherSuite ALL:!ADH:!EXPORT56:!EXPORT40:RC4+RSA:+HIGH:+MEDIUM:+LOW:+SSLv2:+EXP:+eNULL
SSLCertificateFile C:/PKI/testshib.crt
SSLCertificateKeyFile C:/PKI/testshib.key
SSLVerifyClient optional_no_ca
SSLVerifyDepth 10
<FilesMatch "\.(cgi|shtml|phtml|php)$">
SSLOptions +StdEnvVars
</FilesMatch>
<Directory "C:/Apache2.2/cgi-bin">
SSLOptions +StdEnvVars
</Directory>
BrowserMatch ".*MSIE.*" \
nokeepalive ssl-unclean-shutdown \
downgrade-1.0 force-response-1.0
CustomLog C:/Apache2.2/logs/ssl_request_log \
"%t %h %{SSL_PROTOCOL}x %{SSL_CIPHER}x \"%r\" %b"
</VirtualHost>

Thanks,
Jasmin

[Nate Klingenstein]

Jasmin,

Eyeballing it, I don't see anything obviously wrong with that configuration(except for enabling SSLv2 and eNULL, which aren't secure), but I'm almost positive something in it is causing this error.

I know it takes a long time, but can you start from the port 8443 example configuration in the Wiki and gradually move towards this by adding one or two lines at a time and testing?  I think that's the best way to identify the problem.

Sorry I can't spot it,

Nate.

[Geok Choo Teo-Chee]

Hi,
I had edited httpd-ssl-8443.conf to what was mentioned it the Wiki and changing only what is necessary. But when accessing the TestShib Service Provider, the shibd.log file still showed:
RequestID="_8917a0cabd24563a5f4875b53b9bdbd8"><samlp:AttributeQuery Resource="https://sp.testshib.org/shibboleth-sp"><saml:Subject xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion"><saml:NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier" NameQualifier="https://shibssrv.np.edu.sg/shibboleth/testshib/idp">_53b82df69f9487c38e927fa2dc1e3139</saml:NameIdentifier></saml:Subject></samlp:AttributeQuery></samlp:Request></S:Body></S:Envelope>
2008-10-13 22:31:00 DEBUG XMLTooling.SOAPTransport.CURL [7]: sending SOAP message to https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: About to connect() to shibssrv.np.edu.sg port 8443
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: Trying 153.20.76.132...
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: connected
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: Connected to shibssrv.np.edu.sg (153.20.76.132) port 8443
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: successfully set certificate verify locations:
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: CAfile: /usr/share/ssl/certs/ca-bundle.crt
CApath: none
2008-10-13 22:31:00 DEBUG XMLTooling.libcurl [7]: SSLv3, TLS handshake, Client hello (1):
2008-10-13 22:31:01 DEBUG XMLTooling.libcurl [7]: Unknown SSL protocol error in connection to shibssrv.np.edu.sg:8443
2008-10-13 22:31:01 DEBUG XMLTooling.libcurl [7]: Closing connection #0
2008-10-13 22:31:01 ERROR Shibboleth.AttributeResolver [7]: exception during SAML query to https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA: CURLSOAPTransport failed while contacting SOAP responder: Unknown SSL protocol error in connection to shibssrv.np.edu.sg:8443
2008-10-13 22:31:01 ERROR Shibboleth.AttributeResolver [7]: unable to obtain a SAML response from attribute authority
2008-10-13 22:31:01 DEBUG Shibboleth.SessionCache [7]: creating new session
2008-10-13 22:31:01 DEBUG Shibboleth.SessionCache [7]: storing new session...
2008-10-13 22:31:01 DEBUG XMLTooling.StorageService [7]: inserted record (session) in context (_850d4495b1a9452bb330035c2e51d785)
2008-10-13 22:31:01 DEBUG XMLTooling.StorageService [7]: inserted record (_53b82df69f9487c38e927fa2dc1e3139) in context (NameID)
2008-10-13 22:31:01 DEBUG XMLTooling.StorageService [7]: inserted record (_872547fa8286fcead0da077150324ec1) in context (_850d4495b1a9452bb330035c2e51d785)
2008-10-13 22:31:01 INFO Shibboleth.SessionCache [7]: new session created: ID (_850d4495b1a9452bb330035c2e51d785) IdP (https://shibssrv.np.edu.sg/shibboleth/testshib/idp) Protocol(urn:oasis:names:tc:SAML:1.1:protocol) Address (153.20.95.70)
2008-10-13 22:31:01 DEBUG Shibboleth.Listener [6]: dispatching message (find::StorageService::SessionCache)
2008-10-13 22:31:01 DEBUG XMLTooling.StorageService [6]: updated expiration of valid records in context (_850d4495b1a9452bb330035c2e51d785)
2008-10-13 22:31:02 DEBUG Shibboleth.Listener [7]: dispatching message (find::StorageService::SessionCache)
2008-10-13 22:31:02 DEBUG XMLTooling.StorageService [7]: updated expiration of valid records in context (_850d4495b1a9452bb330035c2e51d785)
2008-10-13 22:31:02 DEBUG Shibboleth.Listener [6]: dispatching message (touch::StorageService::SessionCache)
2008-10-13 22:31:02 DEBUG XMLTooling.StorageService [6]: updated expiration of valid records in context (_850d4495b1a9452bb330035c2e51d785)

[Nate Klingenstein]

Jasmin,

That's bad news.  I'm stumped based on the information I have now.

It's not hopeless.  The next step, if you want to take it, is to crank up the logging of this SSL virtual host to DEBUG and look through error_8443.log.  You'll find the reason the handshake is failing somewhere in there, but you're probably going to need to bring it to a better SSL expert than me.

Take care,

Nate.

[Geok Choo Teo-Chee]

Hi,
But does the error message causes the attributes display showing only the following? Does the following attributes display showed that the IdP server is working properly?

Here are some pieces of information I can tell about you using the information Shibboleth gives me:

• UA-CPU is: x86
• Cache-Control is: no-cache
• Shib-Session-ID is: _709df98cb8ba48a71254e31dd1a8bfe1
• Shib-Identity-Provider is: https://shibssrv.np.edu.sg/shibboleth/testshib/idp
• Shib-Authentication-Method is: urn:oasis:names:tc:SAML:1.0:am:unspecified
• Shib-Authentication-Instant is: 2008-10-14T03:18:25.140Z
• Shib-AuthnContext-Class is: urn:oasis:names:tc:SAML:1.0:am:unspecified
• Shib-Application-ID is: default

[Nate Klingenstein]

Jasmin,

Unfortunately, it doesn't show you that the IdP is working completely correctly.  In Shibboleth 1.3, the flows happens in two pieces.

First, the user authenticates to the IdP.  It carries proof of that to the SP, called an assertion.  In that assertion, there's also a unique, opaque, one-time identifier.

For piece #2, the SP then uses that one-time identifier to gather information about the user; potentially a username, or some attributes.  This information is usually pretty important.  Right now, the SP can't get that information because your Apache is broken.  That's why it only displays the basics that it knows from the initial assertion.

If you switched to Shibboleth 2.0 and SAML 2.0, this would only be an issue for backward compatibility and advanced use cases, but that's a pretty big issue still.  I think you should fix this.  If you can't, you can still use Shibboleth in most cases, but we'd have to talk more about some trade-offs.

Take care,

Nate.

[Geok Choo Teo-Chee]

Hi,
I had started off with Shibv2. but the whole installation didn't work out right and unfortunately I had no knowledge to troubleshoot it. So , I had installed v1.3.3 following some URL site which showed step-by-step for idiots like me.
The only error in the error_8443.log file is:
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Tue Oct 14 11:44:57 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?

BTW, the server (Windows 2003 server) hostname is not the same as the URL name of which the IdP is installed.

[Nate Klingenstein]

Jasmin,

Yeah, I didn't expect to see more in there than that at the WARN
level. Those WARN's are not a serious issue and certainly won't
cause this failure. That's why you need to add a directive like
"LogLevel debug" to that vhost's configuration, reboot Apache, try
again, and see what comes out. A failed handshake probably wouldn't
be explicitly reported as an error.

Thanks,
Nate.

[Scott Cantor]

You can also do some debugging using curl or openssl s_client to do
command-line level connections to the port and see if it can handshake
successfully.

But no, this isn't a Shibboleth issue, libcurl/openssl is just not able to
handshake with that Apache server using SSLv3.

-- Scott

[Geok Choo Teo-Chee]

HI,
Added "LogLevel Debug:" in the httpd-ssl-8443.conf file. And from the error_8443.log file show:
[Wed Oct 15 08:20:04 2008] [info] Loading certificate & private key of SSL-aware server
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_pphrase.c(469): unencrypted RSA private key - pass phrase not required
[Wed Oct 15 08:20:04 2008] [info] Configuring server for SSL protocol
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(405): Creating new SSL context (protocols: SSLv2, SSLv3, TLSv1)
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(601): Configuring permitted SSL ciphers [ALL:!ADH:!EXPORT56:!EXPORT40:RC4+RSA:!SSLv2:+HIGH:+MEDIUM:+LOW:+EXP]
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(729): Configuring RSA server certificate
[Wed Oct 15 08:20:04 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Wed Oct 15 08:20:04 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(768): Configuring RSA server private key
[Wed Oct 15 08:20:04 2008] [info] Loading certificate & private key of SSL-aware server
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_pphrase.c(469): unencrypted RSA private key - pass phrase not required
[Wed Oct 15 08:20:04 2008] [info] Configuring server for SSL protocol
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(405): Creating new SSL context (protocols: SSLv2, SSLv3, TLSv1)
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(601): Configuring permitted SSL ciphers [ALL:!ADH:!EXPORT56:!EXPORT40:RC4+RSA:!SSLv2:+HIGH:+MEDIUM:+LOW:+EXP]
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(729): Configuring RSA server certificate
[Wed Oct 15 08:20:04 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Wed Oct 15 08:20:04 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(768): Configuring RSA server private key
[Wed Oct 15 08:20:04 2008] [info] Loading certificate & private key of SSL-aware server
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_pphrase.c(469): unencrypted RSA private key - pass phrase not required
[Wed Oct 15 08:20:04 2008] [info] Configuring server for SSL protocol
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(405): Creating new SSL context (protocols: SSLv2, SSLv3, TLSv1)
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(601): Configuring permitted SSL ciphers [ALL:!ADH:!EXPORT56:!EXPORT40:RC4+RSA:!SSLv2:+HIGH:+MEDIUM:+LOW:+EXP]
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(729): Configuring RSA server certificate
[Wed Oct 15 08:20:04 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Wed Oct 15 08:20:04 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_init.c(768): Configuring RSA server private key
[Wed Oct 15 08:20:04 2008] [info] Loading certificate & private key of SSL-aware server
[Wed Oct 15 08:20:04 2008] [debug] ssl_engine_pphrase.c(469): unencrypted RSA private key - pass phrase not required
[Wed Oct 15 08:20:05 2008] [info] Configuring server for SSL protocol
[Wed Oct 15 08:20:05 2008] [debug] ssl_engine_init.c(405): Creating new SSL context (protocols: SSLv2, SSLv3, TLSv1)
[Wed Oct 15 08:20:05 2008] [debug] ssl_engine_init.c(601): Configuring permitted SSL ciphers [ALL:!ADH:!EXPORT56:!EXPORT40:RC4+RSA:!SSLv2:+HIGH:+MEDIUM:+LOW:+EXP]
[Wed Oct 15 08:20:05 2008] [debug] ssl_engine_init.c(729): Configuring RSA server certificate
[Wed Oct 15 08:20:05 2008] [warn] RSA server certificate is a CA certificate (BasicConstraints: CA == TRUE !?)
[Wed Oct 15 08:20:05 2008] [warn] RSA server certificate CommonName (CN) `TestShib Identity Provider' does NOT match server name!?
[Wed Oct 15 08:20:05 2008] [debug] ssl_engine_init.c(768): Configuring RSA server private key
Thanks,
Jasmin

---

[Geok Choo Teo-Chee]

Hi,
Tried the command openssl s_client -connect {hostname}:8443 -ssl3 with the following results and looks ok. BTW, this command is run on the host itself.
[Wed Oct 15 09:47:32 2008] [info] [client 153.20.76.132] Connection to child 249 established (server shibssrv.np.edu.sg:8443)
[Wed Oct 15 09:47:32 2008] [info] Seeding PRNG with 136 bytes of entropy
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1752): OpenSSL: Handshake: start
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: before/accept initialization
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 read client hello A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 write server hello A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 write certificate A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1143): [client 153.20.76.132] handing out temporary 1024 bit DH key
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 write key exchange A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 write certificate request A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 flush data
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1765): OpenSSL: Read: SSLv3 read client certificate A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 read client key exchange A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 read finished A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 write change cipher spec A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 write finished A
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1760): OpenSSL: Loop: SSLv3 flush data
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(670): inside shmcb_store_session
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(676): session_id[0]=138, masked index=10
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(1059): entering shmcb_insert_encoded_session, *queue->pos_count = 0
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(983): entering shmcb_expire_division
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(1115): we have 14386 bytes and 133 indexes free - enough
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(1144): storing in index 0, at offset 0
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(1159): session_id[0]=138, idx->s_id2=244
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(1170): leaving now with 148 bytes in the cache and 1 indexes
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(1174): leaving shmcb_insert_encoded_session
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(704): leaving shmcb_store successfully
[Wed Oct 15 09:47:32 2008] [debug] ssl_scache_shmcb.c(418): shmcb_store successful
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1598): Inter-Process Session Cache: request=SET status=OK id=8AF4981C5C29C67F1EE65BD78E44961D4EAB063490442A7594E8843D72C57C7C timeout=300s (session caching)
[Wed Oct 15 09:47:32 2008] [debug] ssl_engine_kernel.c(1756): OpenSSL: Handshake: done
Thanks,
Jasmin.

[Nate Klingenstein]

Jasmin,

I just attempted from my machine and got the same error I've been
getting. Maybe you can review your logs from my connection attempt
and find something informative now.

ndk$ openssl s_client -connect shibssrv.np.edu.sg:8443 -ssl3
CONNECTED(00000003)
1585:error:1409E0E5:SSL routines:SSL3_WRITE_BYTES:ssl handshake
failure:s3_pkt.c:529:
ndk$ date
Wed Oct 15 03:13:57 UTC 2008

Thanks,
Nate.

[Geok Choo Teo-Chee]

Hi,
Not getting anything on my side that the client is connected, unlike when I am testing from within the campus.
Will try from outside, as from internet, and see if it could be a firewall problem.

Thank you very much,
Jasmin

[Scott Cantor]

> Tried the command openssl s_client -connect {hostname}:8443 -ssl3 with the
> following results and looks ok. BTW, this command is run on the host
itself.

You could try curl as well. Apart from that slight difference, with libcurl
on top, this is the same code the SP uses. But you need to run the tests
from the same box with the SP.

-- Scott

[Geok Choo Teo-Chee]

Hi,
Testing the IdP server with TestShib SP, so will not be able to do the curl testing if it has to be on the same box as the SP.

Thanks,
Jasmin Teo-Chee | Computer Centre
T: (65) 64606577 | F: (65) 64698325
Ngee Ann Polytechnic, 535 Clementi Road, Singapore 599489

[Scott Cantor]

> Testing the IdP server with TestShib SP, so will not be able to do the
curl
> testing if it has to be on the same box as the SP.

Well, nothing else is going to matter, really. Nate apparently can reproduce
the problem, so I suppose trying any other box is a start.

-- Scott

[Nate Klingenstein]

No difference from TestShib, of course.  I think Jasmin's guess that there's a box intercepting connections somewhere is a very good one.

[ndk@metroid ~]$ openssl s_client -connect shibssrv.np.edu.sg:8443 -ssl3

CONNECTED(00000003)

8886:error:1409E0E5:SSL routines:SSL3_WRITE_BYTES:ssl handshake failure:s3_pkt.c:529:

[Geok Choo Teo-Chee]

Hi,

Yes, the problem was indeed that the port 8443 was not opened. Opened the port 8443 but there are still the following error:
From err_8443.log
Thu Oct 16 16:55:43 2008] [info] Initial (No.1) HTTPS request received for child 248 (server shibssrv.np.edu.sg:8443)
[Thu Oct 16 16:55:49 2008] [debug] ssl_engine_io.c(1786): OpenSSL: I/O error, 5 bytes expected to read on BIO#a0df48 [mem: a94fe8]
[Thu Oct 16 16:55:49 2008] [info] [client 128.118.27.52] (OS 10060)A connection attempt failed because the connected party did not properly respond after a period of time, or established connection failed because connected host has failed to respond. : SSL input filter read failed.
[Thu Oct 16 16:55:49 2008] [debug] ssl_engine_kernel.c(1770): OpenSSL: Write: SSL negotiation finished successfully
[Thu Oct 16 16:55:49 2008] [info] [client 128.118.27.52] Connection closed to child 248 with standard shutdown (server shibssrv.np.edu.sg:8443)
From TestShib shibd.log
2008-10-16 04:56:27 DEBUG XMLTooling.SOAPClient [6]: received XML:
<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"><soap:Body><Response xmlns="urn:oasis:names:tc:SAML:1.0:protocol" InResponseTo="_c6980ae24b7c9a0e9519ab837930bbe2" IssueInstant="2008-10-16T08:55:43.687Z" MajorVersion="1" MinorVersion="1" ResponseID="_bc40287b1b807775dcf98c2efc95c663" xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol"><Status><StatusCode Value="samlp:Responder"/><StatusMessage>Request submitted to an invalid location.</StatusMessage></Status></Response></soap:Body></soap:Envelope>
2008-10-16 04:56:27 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [6]: evaluating message flow policy (replay checking on, expiration 60)
2008-10-16 04:56:27 DEBUG OpenSAML.SecurityPolicyRule.MessageFlow [6]: evaluating message flow policy (replay checking on, expiration 60)
2008-10-16 04:56:27 DEBUG XMLTooling.StorageService [6]: inserted record (_bc40287b1b807775dcf98c2efc95c663) in context (MessageFlow)
2008-10-16 04:56:27 ERROR OpenSAML.SOAPClient [6]: SOAP client detected a SAML error: (samlp:Responder) (Request submitted to an invalid location.)
2008-10-16 04:56:27 ERROR Shibboleth.AttributeResolver [6]: attribute authority returned a SAML error

Any pointers to the error? Thank you.
Thanks,
Jasmin

[Nate Klingenstein]

Jasmin,

I'm not sure why you got that SSL error.  It seems spurious, and I connected successfully to you this time.  Do you get it regularly?

The below error most likely means that your IdP's metadata, as loaded by the SP, doesn't match up with your IdP's configuration.  

2008-10-16 04:56:25 DEBUG XMLTooling.SOAPTransport.CURL [6]: getting connection handle to https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA

Does your IdP's configuration allow for attribute queries on port 8443?  It should look like this in idp.xml:

        <ProtocolHandler implementation="edu.internet2.middleware.shibboleth.idp.provider.SAMLv1_AttributeQueryHandler">

                <Location>.+:8443/shibboleth-idp/AA</Location>

        </ProtocolHandler>

Take care,

Nate.

[Geok Choo Teo-Chee]

Hi,

Following is what the idp.xml 8443 portion looks like:
<ProtocolHandler implementation="edu.internet2.middleware.shibboleth.idp.provider.SAMLv1_AttributeQueryHandler">
<Location>.+:8443/shibboleth-idp/aa</Location>
</ProtocolHandler>

[Geok Choo Teo-Chee]

Hi,
Some additional info. on the error:
in the shibs-error.log file:
2008-10-17 09:42:19,562 ERROR [IdP] 1784172325 - No protocol handler registered for location (https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA).
2008-10-17 09:42:19,562 ERROR [IdP] 1784172325 - Error while processing request: org.opensaml.SAMLException: Request submitted to an invalid location.
2008-10-17 09:42:19,562 DEBUG [IdP] 1784172325 - Dumping generated SAML Error Response:
<Response xmlns="urn:oasis:names:tc:SAML:1.0:protocol" xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" InResponseTo="_12252d497b4a9a137ebca2bdb4fd8254" IssueInstant="2008-10-17T01:42:19.562Z" MajorVersion="1" MinorVersion="1" ResponseID="_907ed9b5e7ddf5ad3c4bf19c272f280a"><Status><StatusCode Value="samlp:Responder"></StatusCode><StatusMessage>Request submitted to an invalid location.</StatusMessage></Status></Response>
2008-10-17 09:42:19,562 DEBUG [IdP] 1784172325 - Returning SAML Error Response.
In Shibboleth-idp.log file:
09:42:12,937 DEBUG Dumping generated SAML Response:
</ds:KeyInfo></ds:Signature><Status><StatusCode Value="samlp:Success"></StatusCode></Status><Assertion xmlns="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_4abb787b2e52ba5dfafc62c7132f77a7" IssueInstant="2008-10-17T01:42:12.875Z" Issuer="https://shibssrv.np.edu.sg/shibboleth/testshib/idp" MajorVersion="1" MinorVersion="1"><Conditions NotBefore="2008-10-17T01:42:12.875Z" NotOnOrAfter="2008-10-17T01:47:12.875Z"><AudienceRestrictionCondition><Audience>https://sp.testshib.org/shibboleth-sp</Audience><Audience>urn:mace:shibboleth:testshib</Audience></AudienceRestrictionCondition></Conditions><AuthenticationStatement AuthenticationInstant="2008-10-17T01:42:12.859Z" AuthenticationMethod="urn:oasis:names:tc:SAML:1.0:am:unspecified"><Subject><NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier" NameQualifier="https://shibssrv.np.edu.sg/shibboleth/testshib/idp">_90202e4f574adb25e33cc354d9592dc3</NameIdentifier><SubjectConfirmation><ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:bearer</ConfirmationMethod></SubjectConfirmation></Subject><SubjectLocality IPAddress="153.20.200.129"></SubjectLocality></AuthenticationStatement></Assertion></Response> - edu.internet2.middleware.shibboleth.idp.provider.ShibbolethV1SSOHandler [TP-Processor2;20081017]
09:42:19,531 DEBUG Received a request via POST for location (https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA). - edu.internet2.middleware.shibboleth.idp.IdPResponder [TP-Processor2;20081017]
09:42:19,562 DEBUG Dumping generated SAML Request:
<samlp:Request xmlns="urn:oasis:names:tc:SAML:1.0:protocol" xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" IssueInstant="2008-10-17T01:42:58Z" MajorVersion="1" MinorVersion="1" RequestID="_12252d497b4a9a137ebca2bdb4fd8254"><samlp:AttributeQuery Resource="https://sp.testshib.org/shibboleth-sp"><saml:Subject><saml:NameIdentifier Format="urn:mace:shibboleth:1.0:nameIdentifier" NameQualifier="https://shibssrv.np.edu.sg/shibboleth/testshib/idp">_90202e4f574adb25e33cc354d9592dc3</saml:NameIdentifier></saml:Subject></samlp:AttributeQuery></samlp:Request> - edu.internet2.middleware.shibboleth.idp.IdPResponder [TP-Processor2;20081017]
09:42:19,562 ERROR No protocol handler registered for location (https://shibssrv.np.edu.sg:8443/shibboleth-idp/AA). - edu.internet2.middleware.shibboleth.idp.IdPResponder [TP-Processor2;20081017]
09:42:19,562 ERROR Error while processing request: org.opensaml.SAMLException: Request submitted to an invalid location. - edu.internet2.middleware.shibboleth.idp.IdPResponder [TP-Processor2;20081017]
09:42:19,562 DEBUG Dumping generated SAML Error Response:
<Response xmlns="urn:oasis:names:tc:SAML:1.0:protocol" xmlns:saml="urn:oasis:names:tc:SAML:1.0:assertion" xmlns:samlp="urn:oasis:names:tc:SAML:1.0:protocol" xmlns:xsd="http://www.w3.org/2001/XMLSchema" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" InResponseTo="_12252d497b4a9a137ebca2bdb4fd8254" IssueInstant="2008-10-17T01:42:19.562Z" MajorVersion="1" MinorVersion="1" ResponseID="_907ed9b5e7ddf5ad3c4bf19c272f280a"><Status><StatusCode Value="samlp:Responder"></StatusCode><StatusMessage>Request submitted to an invalid location.</StatusMessage></Status></Response> - edu.internet2.middleware.shibboleth.idp.IdPResponder [TP-Processor2;20081017]
09:42:19,562 DEBUG Returning SAML Error Response. - edu.internet2.middleware.shibboleth.idp.IdPResponder [TP-Processor2;20081017]

[Geok Choo Teo-Chee]

Hi All,
Thanks for all your help, epecaillly to Nate Klingenstein and Scott. Had finally found the problem and solved it.

Thank you once again.

[Nate Klingenstein]

Jasmin,

Somehow, this become /aa, lowercase, in your configuration.  It's uppercase in your metadata, and in the distribution configuration.  I have no idea how that could've happened.

Try changing it to /shibboleth-idp/AA.

This should help a lot,

Nate.