Apache 2.4 producing 500 error when serving DirectoryIndex page from Shib SP protected areas

Wed Oct 3 10:38:53 EDT 2012

Scott,
Thanks for the quick reply.

I've checked out the files from SVN - and can confirm my patched version matches.

https://ueacisr6test.uea.ac.uk/Shibboleth.sso/Metadata is the entity ID of my SP, but it is the IDP (OpenAthens) producing this message.

Removing the hook to /AttrChecker, doesn't affect the behaviour (in terms of the end result in the browser). I'm pretty sure it's passing though the AttrChecker successfully, as it initially failed displaying an error template (due to our not releasing a required field in our IDP). When we released that field it now progresses to the " Please wait while we transfer you to https://ueacisr6test.uea.ac.uk/Shibboleth.sso/Metadata..." (my SP), the same as if I remove the sessionHook entirely. My expectation was that if the client requested https://ueacisr6test.uea.ac.uk/secure/ then they would be authenticated and sent back to the original location (https://ueacisr6test.uea.ac.uk/secure/) to see the content.

After the message is displayed, if I re-request the page: https://ueacisr6test.uea.ac.uk/secure/ the browser whirrs away, but nothing gets returned.

Sorry the access log details I included were just the bit after the client returned from the IDP, when no sessionHook was configured. Access log details of the different sessionHook configurations is below. 

With no sessionHook set, the access log shows:
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:15:06:10 +0100] 0 3819 "GET /secure/ HTTP/1.1" 302 776 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:15:06:38 +0100] 0 5180 "POST /Shibboleth.sso/SAML2/POST HTTP/1.1" 302 222 "https://testlogin.uea.ac.uk/oala/sso?SAMLRequest=lVLJboMwEP0V5HuwIQuNFZBocmikpI0K7aGXysAoWDU29Zguf18IrZpeIvUwB2veNk9eoWhUy9PO1foeXjtA5300SiM%2FLWLSWc2NQIlciwaQu5Jn6X7HQ5%2Fx1hpnSqOIlyKCddLotdHYNWAzsG%2ByhIf7XUxq51rklHYgSol24XoTv3%2F4ovS7F5rVsiiMAlf7iIYO6iE93GU58TY9UmoxCP%2FKDHRljlKfaRihBO3ZxNtuYvJ8NQ0rUc5myyiCaFksWTSfF%2F0sWABhNWc9DLGDrUYntItJyIJwErAJm%2BbBjLMFD9gT8Q7f511LXUl9vNxFMYKQ3%2BT5YTLGfwSLp%2Bg9gCSroVF%2BMrZnHV%2BWFT%2FFkuR%2FNe7BiUo4saJntmOGlt%2F2PtvNwShZfnqpUuZ9bUE4iElAaDJS%2Fn6K5As%3D&RelayState=ss%3Amem%3A2d87b5ad51b5b17a137f5ec4d3b856cce2f2e18fec2928c9126d29c4aa7c83f5" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"

When using sessionHook="/Shibboleth.sso/Session", the access log shows:
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:14:56:47 +0100] 0 2297 "GET /secure/ HTTP/1.1" 302 774 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:14:57:02 +0100] 0 5359 "POST /Shibboleth.sso/SAML2/POST HTTP/1.1" 302 475 "https://testlogin.uea.ac.uk/oala/sso?SAMLRequest=lZJNT4MwGMe%2FCul9QIGhNIMEt4NLNiUbevBiCns2GkuLfYov3142NM7LEo9N%2F2%2F9pTPkrexY3ttGbeC1B7TORysVstNFSnqjmOYokCneAjJbs22%2BXrHA9VlntNW1lsTJEcFYodVcK%2BxbMFswb6KGh80qJY21HTLP64HXAk1shxJ3OLi8dvsXb9uIqtISbOMiau%2BYHnjF%2FbYkzmJQCsWPwb8xR7vUB6HOMjSX3BvcxFkuUvJMkziJ6DQJqzCgNNlD7Yf7feRf%2BxBHFYVBhtjDUqHlyqYk8Gkwof7ED0sasmnMoqsn4hTfz7sRaifU4TKLahQhuy3LYjLOfwSDp%2BmDgGSzI1F2KjZnjC%2FH8h%2BwJPsfxjVYvuOWz7yz2nFDx%2B6GnuWi0FLUn04upX6fG%2BAWUkKJl42Wv58i%2BwI%3D&RelayState=ss%3Amem%3A6028d3ebecb04d54f6c707969d8172563a8b16be4f479e41f0b86262e6d08058" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:14:57:02 +0100] 0 1561 "GET /Shibboleth.sso/Session?return=https%3A%2F%2Fueacisr6test.uea.ac.uk%2FShibboleth.sso%2FSAML2%2FPOST%3Fhook%3D1%26target%3Dss%253Amem%253A6028d3ebecb04d54f6c707969d8172563a8b16be4f479e41f0b86262e6d08058&target=https%3A%2F%2Fueacisr6test.uea.ac.uk%2Fsecure%2F HTTP/1.1" 200 447 "https://testlogin.uea.ac.uk/oala/sso?SAMLRequest=lZJNT4MwGMe%2FCul9QIGhNIMEt4NLNiUbevBiCns2GkuLfYov3142NM7LEo9N%2F2%2F9pTPkrexY3ttGbeC1B7TORysVstNFSnqjmOYokCneAjJbs22%2BXrHA9VlntNW1lsTJEcFYodVcK%2BxbMFswb6KGh80qJY21HTLP64HXAk1shxJ3OLi8dvsXb9uIqtISbOMiau%2BYHnjF%2FbYkzmJQCsWPwb8xR7vUB6HOMjSX3BvcxFkuUvJMkziJ6DQJqzCgNNlD7Yf7feRf%2BxBHFYVBhtjDUqHlyqYk8Gkwof7ED0sasmnMoqsn4hTfz7sRaifU4TKLahQhuy3LYjLOfwSDp%2BmDgGSzI1F2KjZnjC%2FH8h%2BwJPsfxjVYvuOWz7yz2nFDx%2B6GnuWi0FLUn04upX6fG%2BAWUkKJl42Wv58i%2BwI%3D&RelayState=ss%3Amem%3A6028d3ebecb04d54f6c707969d8172563a8b16be4f479e41f0b86262e6d08058" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:14:57:02 +0100] 0 853 "GET /favicon.ico HTTP/1.1" 200 3638 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"

When using sessionHook="/Shibboleth.sso/AttrCheck" the access log shows:
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:15:04:20 +0100] 0 3501 "GET /secure/ HTTP/1.1" 302 776 "-" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:15:04:31 +0100] 0 4503 "POST /Shibboleth.sso/SAML2/POST HTTP/1.1" 302 479 "https://testlogin.uea.ac.uk/oala/sso?SAMLRequest=lZJNT4MwGMe%2FCul9lDdxNoMEt4NLNl0GevBiHqCOxtJin%2BLLtxeGxnlZ4rHp%2F62%2FdIHQyo5lvW3Unr%2F2HK3z0UqF7HiRkN4opgEFMgUtR2YrlmfbDQtcj3VGW11pSZwMkRsrtFpqhX3LTc7Nm6j4%2FX6TkMbaDhmlPYdKoIntUOIOBxcqt3%2BheSPKUktuGxdR0zE9oLu7vCDOalAKBWPwb8xol%2Fog1EmGBgl0cBNnvUrIU%2BVB6UPslxGPQv8yCsO4nsfzMHquL%2FhV6A8yxJ6vFVpQNiGB5wcz35t5YeFHzItY4D0SZ%2Ff9vGuhaqEO51mUkwjZTVHsZtP8B27wOH0QkHQxEmXHYnPC%2BHws%2FIAl6f8wbrmFGiws6EnttKFjt0PPerXTUlSfTialfl8aDpYnxCc0nSx%2FP0X6BQ%3D%3D&RelayState=ss%3Amem%3Ab302200fcaccd568cb3cecb6526e40c3220ab2a7f1429cf197c274f3b322b2b8" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:15:04:31 +0100] 0 1176 "GET /Shibboleth.sso/AttrChecker?return=https%3A%2F%2Fueacisr6test.uea.ac.uk%2FShibboleth.sso%2FSAML2%2FPOST%3Fhook%3D1%26target%3Dss%253Amem%253Ab302200fcaccd568cb3cecb6526e40c3220ab2a7f1429cf197c274f3b322b2b8&target=https%3A%2F%2Fueacisr6test.uea.ac.uk%2Fsecure%2F HTTP/1.1" 302 334 "https://testlogin.uea.ac.uk/oala/sso?SAMLRequest=lZJNT4MwGMe%2FCul9lDdxNoMEt4NLNl0GevBiHqCOxtJin%2BLLtxeGxnlZ4rHp%2F62%2FdIHQyo5lvW3Unr%2F2HK3z0UqF7HiRkN4opgEFMgUtR2YrlmfbDQtcj3VGW11pSZwMkRsrtFpqhX3LTc7Nm6j4%2FX6TkMbaDhmlPYdKoIntUOIOBxcqt3%2BheSPKUktuGxdR0zE9oLu7vCDOalAKBWPwb8xol%2Fog1EmGBgl0cBNnvUrIU%2BVB6UPslxGPQv8yCsO4nsfzMHquL%2FhV6A8yxJ6vFVpQNiGB5wcz35t5YeFHzItY4D0SZ%2Ff9vGuhaqEO51mUkwjZTVHsZtP8B27wOH0QkHQxEmXHYnPC%2BHws%2FIAl6f8wbrmFGiws6EnttKFjt0PPerXTUlSfTialfl8aDpYnxCc0nSx%2FP0X6BQ%3D%3D&RelayState=ss%3Amem%3Ab302200fcaccd568cb3cecb6526e40c3220ab2a7f1429cf197c274f3b322b2b8" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"
ueacisr6test.uea.ac.uk:443 139.222.120.221 - - [03/Oct/2012:15:04:31 +0100] 0 790 "GET /Shibboleth.sso/SAML2/POST?hook=1&target=ss%3Amem%3Ab302200fcaccd568cb3cecb6526e40c3220ab2a7f1429cf197c274f3b322b2b8 HTTP/1.1" 302 222 "https://testlogin.uea.ac.uk/oala/sso?SAMLRequest=lZJNT4MwGMe%2FCul9lDdxNoMEt4NLNl0GevBiHqCOxtJin%2BLLtxeGxnlZ4rHp%2F62%2FdIHQyo5lvW3Unr%2F2HK3z0UqF7HiRkN4opgEFMgUtR2YrlmfbDQtcj3VGW11pSZwMkRsrtFpqhX3LTc7Nm6j4%2FX6TkMbaDhmlPYdKoIntUOIOBxcqt3%2BheSPKUktuGxdR0zE9oLu7vCDOalAKBWPwb8xol%2Fog1EmGBgl0cBNnvUrIU%2BVB6UPslxGPQv8yCsO4nsfzMHquL%2FhV6A8yxJ6vFVpQNiGB5wcz35t5YeFHzItY4D0SZ%2Ff9vGuhaqEO51mUkwjZTVHsZtP8B27wOH0QkHQxEmXHYnPC%2BHws%2FIAl6f8wbrmFGiws6EnttKFjt0PPerXTUlSfTialfl8aDpYnxCc0nSx%2FP0X6BQ%3D%3D&RelayState=ss%3Amem%3Ab302200fcaccd568cb3cecb6526e40c3220ab2a7f1429cf197c274f3b322b2b8" "Mozilla/5.0 (Windows NT 6.1; WOW64; rv:15.0) Gecko/20100101 Firefox/15.0.1"

Thanks,
Paul

>-----Original Message-----
>From: users-bounces at shibboleth.net [mailto:users-bounces at shibboleth.net]
>On Behalf Of Cantor, Scott
>Sent: Wednesday, October 03, 2012 1:45 PM
>To: Shib Users
>Subject: Re: Apache 2.4 producing 500 error when serving DirectoryIndex
>page from Shib SP protected areas
>
>On 10/3/12 8:31 AM, "Paul Beckett (ITCS)" <P.Beckett at uea.ac.uk> wrote:
>>
>>I couldn't manage to checkout the updated file from SVN, so applied the
>>patch of diffs between 3765 and 4643.
>>http://svn.shibboleth.net/view/cpp-
>sp/branches/REL_2/apache/mod_shib.cp
>>p?r
>>1=3643&r2=3765&pathrev=3765
>>I assume r3643 is the same as 2.5.0, as 2.5.0's release date seems to
>>be newer than r3643's commit date?
>
>I don¹t know the rev, but the 2.5.0 tag would tell you what the exact one was.
>
>If you want to check out, it's just svn co
>https://svn.shibboleth.net/cpp-sp/branches/REL_2
>
>>Applying this patch has resulted in different behaviour .... but it's
>>still not working for me. I'm not entirely sure if this is my
>>configuration, or an issue with the Apache 2.4 module.
>
>I think it's you, but I don't have enough to go on. All I can say is that it worked
>ok for me, and the bug was nothing that involves routine processing of
>handler requests. I'll double check that I have the sessionHook configured, I
>don't know if I did or not.
>
>>When requesting a page, I'm redirected to the IDP, successfully
>>authenticate there, and get redirected back to my Apache 2.4 server
>>running the SP, but instead of receiving the page all I see is the
>>message:
>>" Please wait while we transfer you to
>>https://ueacisr6test.uea.ac.uk/Shibboleth.sso/Metadata..."
>
>That's your IdP I think. You used that as an entityID, so it's hung up on
>something at the SP end.
>
>>If I replace the sessionHook="/Shibboleth.sso/AttrChecker" in
>>Application defaults with sessionHook="/Shibboleth.sso/Session" , I can
>>see I'm receiving attributes back from the IDP.
>
>I'd start without the sessionHook, but it sounds to me like the problem is with
>the attribute checker handler. Are you expecting it to pass you on, or display
>the error template?
>
>>In the apache access log all I see is:
>
>There'd have to be additional logging of the /Session request or the
>/AttrChecker request, those are full redirects back to the client.
>
>>In the shibd.log all I see is:
>>2012-10-03 13:16:23 INFO Shibboleth.AttributeExtractor.XML [1]:
>>skipping unmapped SAML 2.0 Attribute with Name: eduPersonTargetedID
>>2012-10-03 13:16:23 INFO Shibboleth.SessionCache [1]: new session
>>created: ID (_9599c0fa5d154f3bcb351131a2bc01e5) IdP
>>(https://testlogin.uea.ac.uk/entity)
>>Protocol(urn:oasis:names:tc:SAML:2.0:protocol) Address
>>(139.222.120.221)
>
>That's pretty much the SP finishing.
>
>-- Scott
>
>
>--
>To unsubscribe from this list send an email to users-
>unsubscribe at shibboleth.net