Marvin, Indeed it is complaining about an XML that cannot be parsed:
[Tue Aug 27 13:17:09 2013] [error] [client 127.0.0.1] MOD_AUTH_CAS: Error parsing XML content (Internal error), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html Here is the full log output: [Tue Aug 27 13:16:19 2013] [info] Loading certificate & private key of SSL-aware server [Tue Aug 27 13:16:20 2013] [info] Configuring server for SSL protocol [Tue Aug 27 13:16:20 2013] [warn] RSA server certificate CommonName (CN) `mint' does NOT match server name!? [Tue Aug 27 13:16:20 2013] [debug] mod_auth_cas.c(2409): entering check_vhost_config() [Tue Aug 27 13:16:20 2013] [info] Loading certificate & private key of SSL-aware server [Tue Aug 27 13:16:20 2013] [info] Configuring server for SSL protocol [Tue Aug 27 13:16:20 2013] [warn] RSA server certificate CommonName (CN) `mint' does NOT match server name!? [Tue Aug 27 13:16:20 2013] [debug] mod_auth_cas.c(2409): entering check_vhost_config() [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 0 in child 10319 for worker http://steppra1-linux-mint:9558/best_buy/ [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 0 in child 10319 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 1 in child 10319 for worker http://build.local.apps/ [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 1 in child 10319 for (build.local.apps) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 2 in child 10319 for worker http://steppra1-linux-mint:9558/ [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 2 in child 10319 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 3 in child 10319 for worker https://steppra1-linux-mint:8443/cas [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 3 in child 10319 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 0 in child 10320 for worker http://steppra1-linux-mint:9558/best_buy/ [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1837): proxy: worker http://steppra1-linux-mint:9558/best_buy/ already initialized [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 0 in child 10320 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 1 in child 10320 for worker http://build.local.apps/ [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1837): proxy: worker http://build.local.apps/ already initialized [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 1 in child 10320 for (build.local.apps) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 2 in child 10320 for worker http://steppra1-linux-mint:9558/ [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1837): proxy: worker http://steppra1-linux-mint:9558/ already initialized [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 2 in child 10320 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 3 in child 10320 for worker https://steppra1-linux-mint:8443/cas [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1837): proxy: worker https://steppra1-linux-mint:8443/cas already initialized [Tue Aug 27 13:16:20 2013] [debug] proxy_util.c(1914): proxy: initialized worker 3 in child 10320 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:16:53 2013] [info] [client 127.0.0.1] Connection to child 2 established (server dev.local.fe2:443) [Tue Aug 27 13:16:53 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:16:53 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1, Cipher: DHE-RSA-CAMELLIA256-SHA (256/256 bits) [Tue Aug 27 13:16:53 2013] [info] Initial (No.1) HTTPS request received for child 2 (server dev.local.fe2:443) [Tue Aug 27 13:16:53 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //steppra1-linux-mint:8443/cas/logout [Tue Aug 27 13:16:53 2013] [debug] proxy_util.c(1506): [client 127.0.0.1] proxy: https: found worker https://steppra1-linux-mint:8443/cas for https://steppra1-linux-mint:8443/cas/logout [Tue Aug 27 13:16:53 2013] [debug] mod_proxy.c(1020): Running scheme https handler (attempt 0) [Tue Aug 27 13:16:53 2013] [debug] mod_proxy_http.c(1973): proxy: HTTP: serving URL https://steppra1-linux-mint:8443/cas/logout [Tue Aug 27 13:16:53 2013] [debug] proxy_util.c(2011): proxy: HTTPS: has acquired connection for (steppra1-linux-mint) [Tue Aug 27 13:16:53 2013] [debug] proxy_util.c(2067): proxy: connecting https://steppra1-linux-mint:8443/cas/logout to steppra1-linux-mint:8443 [Tue Aug 27 13:16:53 2013] [debug] proxy_util.c(2193): proxy: connected /cas/logout to steppra1-linux-mint:8443 [Tue Aug 27 13:16:53 2013] [debug] proxy_util.c(2444): proxy: HTTPS: fam 2 socket created to connect to steppra1-linux-mint [Tue Aug 27 13:16:53 2013] [debug] proxy_util.c(2576): proxy: HTTPS: connection complete to 127.0.0.1:8443 (steppra1-linux-mint) [Tue Aug 27 13:16:53 2013] [info] [client 127.0.0.1] Connection to child 0 established (server dev.local.fe2:443) [Tue Aug 27 13:16:53 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:16:53 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1.1, Cipher: ECDHE-RSA-DES-CBC3-SHA (168/168 bits) [Tue Aug 27 13:16:54 2013] [debug] mod_proxy_http.c(1743): proxy: start body send [Tue Aug 27 13:16:54 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter() [Tue Aug 27 13:16:54 2013] [debug] mod_deflate.c(615): [client 127.0.0.1] Zlib: Compressed 2026 to 845 : URL /cas/logout [Tue Aug 27 13:16:54 2013] [debug] mod_proxy_http.c(1847): proxy: end body send [Tue Aug 27 13:16:54 2013] [debug] proxy_util.c(2029): proxy: HTTPS: has released connection for (steppra1-linux-mint) [Tue Aug 27 13:16:59 2013] [info] [client 127.0.0.1] (70007)The timeout specified has expired: SSL input filter read failed. [Tue Aug 27 13:16:59 2013] [info] [client 127.0.0.1] Connection closed to child 2 with standard shutdown (server dev.local.fe2:443) [Tue Aug 27 13:17:01 2013] [info] [client 127.0.0.1] Connection to child 66 established (server dev.local.fe2:443) [Tue Aug 27 13:17:01 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:17:01 2013] [info] [client 127.0.0.1] Connection to child 1 established (server dev.local.fe2:443) [Tue Aug 27 13:17:01 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:17:01 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1, Cipher: DHE-RSA-CAMELLIA256-SHA (256/256 bits) [Tue Aug 27 13:17:01 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1, Cipher: DHE-RSA-CAMELLIA256-SHA (256/256 bits) [Tue Aug 27 13:17:01 2013] [info] Initial (No.1) HTTPS request received for child 1 (server dev.local.fe2:443) [Tue Aug 27 13:17:01 2013] [debug] mod_auth_cas.c(1958): [client 127.0.0.1] Entering cas_authenticate() [Tue Aug 27 13:17:01 2013] [debug] mod_auth_cas.c(578): [client 127.0.0.1] CAS Service 'https%3a%2f%2fdev.local.fe2%2ffe2.html' [Tue Aug 27 13:17:01 2013] [debug] mod_auth_cas.c(526): [client 127.0.0.1] entering getCASLoginURL() [Tue Aug 27 13:17:01 2013] [debug] mod_auth_cas.c(503): [client 127.0.0.1] entering getCASGateway() [Tue Aug 27 13:17:01 2013] [debug] mod_auth_cas.c(593): [client 127.0.0.1] entering redirectRequest() [Tue Aug 27 13:17:01 2013] [debug] mod_auth_cas.c(605): [client 127.0.0.1] Adding outgoing header: Location: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:01 2013] [debug] mod_deflate.c(615): [client 127.0.0.1] Zlib: Compressed 342 to 247 : URL /fe2.html [Tue Aug 27 13:17:01 2013] [info] Subsequent (No.2) HTTPS request received for child 1 (server dev.local.fe2:443) [Tue Aug 27 13:17:01 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //steppra1-linux-mint:8443/cas/login [Tue Aug 27 13:17:01 2013] [debug] proxy_util.c(1506): [client 127.0.0.1] proxy: https: found worker https://steppra1-linux-mint:8443/cas for https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:01 2013] [debug] mod_proxy.c(1020): Running scheme https handler (attempt 0) [Tue Aug 27 13:17:01 2013] [debug] mod_proxy_http.c(1973): proxy: HTTP: serving URL https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:01 2013] [debug] proxy_util.c(2011): proxy: HTTPS: has acquired connection for (steppra1-linux-mint) [Tue Aug 27 13:17:01 2013] [debug] proxy_util.c(2067): proxy: connecting https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:01 2013] [debug] proxy_util.c(2193): proxy: connected /cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:01 2013] [debug] mod_proxy_http.c(1743): proxy: start body send [Tue Aug 27 13:17:01 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter() [Tue Aug 27 13:17:01 2013] [debug] mod_deflate.c(615): [client 127.0.0.1] Zlib: Compressed 6882 to 1829 : URL /cas/login [Tue Aug 27 13:17:01 2013] [debug] mod_proxy_http.c(1847): proxy: end body send [Tue Aug 27 13:17:01 2013] [debug] proxy_util.c(2029): proxy: HTTPS: has released connection for (steppra1-linux-mint) [Tue Aug 27 13:17:06 2013] [info] Subsequent (No.3) HTTPS request received for child 1 (server dev.local.fe2:443) [Tue Aug 27 13:17:06 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //steppra1-linux-mint:8443/cas/login [Tue Aug 27 13:17:06 2013] [debug] proxy_util.c(1506): [client 127.0.0.1] proxy: https: found worker https://steppra1-linux-mint:8443/cas for https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:06 2013] [debug] mod_proxy.c(1020): Running scheme https handler (attempt 0) [Tue Aug 27 13:17:06 2013] [debug] mod_proxy_http.c(1973): proxy: HTTP: serving URL https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:06 2013] [debug] proxy_util.c(2011): proxy: HTTPS: has acquired connection for (steppra1-linux-mint) [Tue Aug 27 13:17:06 2013] [debug] proxy_util.c(2067): proxy: connecting https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:06 2013] [debug] proxy_util.c(2193): proxy: connected /cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:06 2013] [info] [client 127.0.0.1] Connection closed to child 66 with standard shutdown (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1743): proxy: start body send [Tue Aug 27 13:17:09 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter() [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1847): proxy: end body send [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2029): proxy: HTTPS: has released connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [info] Subsequent (No.4) HTTPS request received for child 1 (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //steppra1-linux-mint:8443/cas/login [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(1506): [client 127.0.0.1] proxy: https: found worker https://steppra1-linux-mint:8443/cas for https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_proxy.c(1020): Running scheme https handler (attempt 0) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1973): proxy: HTTP: serving URL https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2011): proxy: HTTPS: has acquired connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2067): proxy: connecting https://steppra1-linux-mint:8443/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2193): proxy: connected /cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1743): proxy: start body send [Tue Aug 27 13:17:09 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter() [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1847): proxy: end body send [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2029): proxy: HTTPS: has released connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [info] Subsequent (No.5) HTTPS request received for child 1 (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1958): [client 127.0.0.1] Entering cas_authenticate(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(648): [client 127.0.0.1] Modified r->args (now ''), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1660): [client 127.0.0.1] entering getResponseFromServer(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(578): [client 127.0.0.1] CAS Service 'https%3a%2f%2fdev.local.fe2%2ffe2.html', referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Connection to child 67 established (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:17:09 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1.2, Cipher: DHE-RSA-AES128-SHA (128/128 bits) [Tue Aug 27 13:17:09 2013] [info] Initial (No.1) HTTPS request received for child 67 (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //steppra1-linux-mint:8443/cas/samlValidate [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(1506): [client 127.0.0.1] proxy: https: found worker https://steppra1-linux-mint:8443/cas for https://steppra1-linux-mint:8443/cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_proxy.c(1020): Running scheme https handler (attempt 0) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1973): proxy: HTTP: serving URL https://steppra1-linux-mint:8443/cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2011): proxy: HTTPS: has acquired connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2067): proxy: connecting https://steppra1-linux-mint:8443/cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2193): proxy: connected /cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2444): proxy: HTTPS: fam 2 socket created to connect to steppra1-linux-mint [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2576): proxy: HTTPS: connection complete to 127.0.0.1:8443 (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Connection to child 0 established (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:17:09 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1.1, Cipher: ECDHE-RSA-DES-CBC3-SHA (168/168 bits) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1743): proxy: start body send [Tue Aug 27 13:17:09 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter() [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1847): proxy: end body send [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2029): proxy: HTTPS: has released connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1738): [client 127.0.0.1] Validation response: <?xml version="1.0" encoding="UTF-8"?><SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/";><SOAP-ENV:Body><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2013-08-27T11:17:09.573Z" MajorVersion="1" MinorVersion="1" Recipient="https://dev.local.fe2/fe2.html"; ResponseID="_f94a5f372491aaefc2245a15fe2c9e33"><saml1p:Status><saml1p:StatusCode Value="saml1p:Success"/></saml1p:Status><saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_5578671330d800acff947bd5204631c5" IssueInstant="2013-08-27T11:17:09.573Z" Issuer="localhost" MajorVersion="1" MinorVersion="1"><saml1:Conditions NotBefore="2013-08-27T11:17:09.573Z" NotOnOrAfter="2013-08-27T11:17:39.573Z"><saml1:AudienceRestrictionCondition><saml1:Audience>https://dev.local.fe2/fe2.html</saml1:Audience></saml1:AudienceRestrictionCondition></saml1:Conditions><saml1:AuthenticationStatement AuthenticationInstant="2013-08-27T11:17:09.345Z" AuthenticationMethod="urn:oasis:names:tc:SAML:1.0:am:password"><saml1:Subject><saml1:NameIdentifier>steppra1</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:artifact</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject></saml1:AuthenticationStatement></saml1:Assertion></saml1p:Response></SOAP-ENV:Body></SOAP-ENV:Envelope>, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Connection closed to child 67 with standard shutdown (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1360): [client 127.0.0.1] entering isValidCASTicket(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1366): [client 127.0.0.1] MOD_AUTH_CAS: response = <?xml version="1.0" encoding="UTF-8"?><SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/";><SOAP-ENV:Body><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2013-08-27T11:17:09.573Z" MajorVersion="1" MinorVersion="1" Recipient="https://dev.local.fe2/fe2.html"; ResponseID="_f94a5f372491aaefc2245a15fe2c9e33"><saml1p:Status><saml1p:StatusCode Value="saml1p:Success"/></saml1p:Status><saml1:Assertion xmlns:saml1="urn:oasis:names:tc:SAML:1.0:assertion" AssertionID="_5578671330d800acff947bd5204631c5" IssueInstant="2013-08-27T11:17:09.573Z" Issuer="localhost" MajorVersion="1" MinorVersion="1"><saml1:Conditions NotBefore="2013-08-27T11:17:09.573Z" NotOnOrAfter="2013-08-27T11:17:39.573Z"><saml1:AudienceRestrictionCondition><saml1:Audience>https://dev.local.fe2/fe2.html</saml1:Audience></saml1:AudienceRestrictionCondition></saml1:Conditions><saml1:AuthenticationStatement AuthenticationInstant="2013-08-27T11:17:09.345Z" AuthenticationMethod="urn:oasis:names:tc:SAML:1.0:am:password"><saml1:Subject><saml1:NameIdentifier>steppra1</saml1:NameIdentifier><saml1:SubjectConfirmation><saml1:ConfirmationMethod>urn:oasis:names:tc:SAML:1.0:cm:artifact</saml1:ConfirmationMethod></saml1:SubjectConfirmation></saml1:Subject></saml1:AuthenticationStatement></saml1:Assertion></saml1p:Response></SOAP-ENV:Body></SOAP-ENV:Envelope>, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Successfully authenticated ticket ST-2-L3XuP9nifz4q1wapuxDn-steppra1-linux-mint for user (null), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1192): [client 127.0.0.1] entering createCASCookie(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1013): [client 127.0.0.1] entering CASCleanCache(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1055): [client 127.0.0.1] Beginning cache clean, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1073): [client 127.0.0.1] Processing cache file 'd8e0f5fce75b88162b4243a787868971', referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(872): [client 127.0.0.1] entering readCASCacheFile(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [error] [client 127.0.0.1] MOD_AUTH_CAS: Error parsing XML content (Internal error), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1089): [client 127.0.0.1] Removing corrupt cache entry 'd8e0f5fce75b88162b4243a787868971', referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1332): [client 127.0.0.1] entering deleteCASCacheFile(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(872): [client 127.0.0.1] entering readCASCacheFile(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [error] [client 127.0.0.1] MOD_AUTH_CAS: Error parsing XML content (Internal error), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1111): [client 127.0.0.1] entering writeCASCacheEntry(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Connection to child 68 established (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:17:09 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1, Cipher: DHE-RSA-CAMELLIA256-SHA (256/256 bits) [Tue Aug 27 13:17:09 2013] [info] Initial (No.1) HTTPS request received for child 68 (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1958): [client 127.0.0.1] Entering cas_authenticate(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(648): [client 127.0.0.1] Modified r->args (now ''), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1660): [client 127.0.0.1] entering getResponseFromServer(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(578): [client 127.0.0.1] CAS Service 'https%3a%2f%2fdev.local.fe2%2ffe2.html', referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Connection to child 65 established (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [info] Seeding PRNG with 656 bytes of entropy [Tue Aug 27 13:17:09 2013] [info] Connection: Client IP: 127.0.0.1, Protocol: TLSv1.2, Cipher: DHE-RSA-AES128-SHA (128/128 bits) [Tue Aug 27 13:17:09 2013] [info] Initial (No.1) HTTPS request received for child 65 (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(56): proxy: HTTP: canonicalising URL //steppra1-linux-mint:8443/cas/samlValidate [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(1506): [client 127.0.0.1] proxy: https: found worker https://steppra1-linux-mint:8443/cas for https://steppra1-linux-mint:8443/cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_proxy.c(1020): Running scheme https handler (attempt 0) [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1973): proxy: HTTP: serving URL https://steppra1-linux-mint:8443/cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2011): proxy: HTTPS: has acquired connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2067): proxy: connecting https://steppra1-linux-mint:8443/cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2193): proxy: connected /cas/samlValidate?TARGET=https%3a%2f%2fdev.local.fe2%2ffe2.html to steppra1-linux-mint:8443 [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1743): proxy: start body send [Tue Aug 27 13:17:09 2013] [debug] mod_headers.c(756): headers: ap_headers_output_filter() [Tue Aug 27 13:17:09 2013] [debug] mod_proxy_http.c(1847): proxy: end body send [Tue Aug 27 13:17:09 2013] [debug] proxy_util.c(2029): proxy: HTTPS: has released connection for (steppra1-linux-mint) [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1738): [client 127.0.0.1] Validation response: <?xml version="1.0" encoding="UTF-8"?><SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/";><SOAP-ENV:Body><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2013-08-27T11:17:09.744Z" MajorVersion="1" MinorVersion="1" Recipient="https://dev.local.fe2/fe2.html"; ResponseID="_27be6264766f8a0f44056825d49087ae"><saml1p:Status><saml1p:StatusCode Value="saml1p:RequestDenied"/><saml1p:StatusMessage>ticket 'ST-2-L3XuP9nifz4q1wapuxDn-steppra1-linux-mint' not recognized</saml1p:StatusMessage></saml1p:Status></saml1p:Response></SOAP-ENV:Body></SOAP-ENV:Envelope>, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [info] [client 127.0.0.1] Connection closed to child 65 with standard shutdown (server dev.local.fe2:443) [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1360): [client 127.0.0.1] entering isValidCASTicket(), referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_auth_cas.c(1366): [client 127.0.0.1] MOD_AUTH_CAS: response = <?xml version="1.0" encoding="UTF-8"?><SOAP-ENV:Envelope xmlns:SOAP-ENV="http://schemas.xmlsoap.org/soap/envelope/";><SOAP-ENV:Body><saml1p:Response xmlns:saml1p="urn:oasis:names:tc:SAML:1.0:protocol" IssueInstant="2013-08-27T11:17:09.744Z" MajorVersion="1" MinorVersion="1" Recipient="https://dev.local.fe2/fe2.html"; ResponseID="_27be6264766f8a0f44056825d49087ae"><saml1p:Status><saml1p:StatusCode Value="saml1p:RequestDenied"/><saml1p:StatusMessage>ticket 'ST-2-L3XuP9nifz4q1wapuxDn-steppra1-linux-mint' not recognized</saml1p:StatusMessage></saml1p:Status></saml1p:Response></SOAP-ENV:Body></SOAP-ENV:Envelope>, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:09 2013] [debug] mod_deflate.c(615): [client 127.0.0.1] Zlib: Compressed 481 to 324 : URL /fe2.html, referer: https://dev.local.fe2/cas/login?service=https%3a%2f%2fdev.local.fe2%2ffe2.html [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 0 in child 10450 for worker http://steppra1-linux-mint:9558/best_buy/ [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1837): proxy: worker http://steppra1-linux-mint:9558/best_buy/ already initialized [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1914): proxy: initialized worker 0 in child 10450 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 1 in child 10450 for worker http://build.local.apps/ [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1837): proxy: worker http://build.local.apps/ already initialized [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1914): proxy: initialized worker 1 in child 10450 for (build.local.apps) min=0 max=25 smax=25 [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 2 in child 10450 for worker http://steppra1-linux-mint:9558/ [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1837): proxy: worker http://steppra1-linux-mint:9558/ already initialized [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1914): proxy: initialized worker 2 in child 10450 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1818): proxy: grabbed scoreboard slot 3 in child 10450 for worker https://steppra1-linux-mint:8443/cas [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1837): proxy: worker https://steppra1-linux-mint:8443/cas already initialized [Tue Aug 27 13:17:11 2013] [debug] proxy_util.c(1914): proxy: initialized worker 3 in child 10450 for (steppra1-linux-mint) min=0 max=25 smax=25 [Tue Aug 27 13:17:14 2013] [info] [client 127.0.0.1] (70007)The timeout specified has expired: SSL input filter read failed. [Tue Aug 27 13:17:14 2013] [info] [client 127.0.0.1] Connection closed to child 68 with standard shutdown (server dev.local.fe2:443) Ralf ________________________________________ From: Steppacher Ralf [[email protected]] Sent: Tuesday, August 27, 2013 11:52 To: [email protected] Subject: RE: [cas-user] SAML Ticket Validation Marvin, Re #1: Yes, I have not bothered yet with the attributes and what I need to do in order to release them As I cannot make the request succeed I figured I have no chance to verify that whatever I do to make the attributes available is working or not. But maybe that is what confuses mod_auth_cas or the SAML validation? I will build and deploy your modified version of the module later today and report back. Re #2: Indeed we can see an odd request for /favicon.ico that that is redirected via CAS. But not all the time. CSS and JS I don't see redirected. The CSS and JS that is in the log I posted is that of CAS itself. Is it not? Thanks and regards Ralf ________________________________________ From: Marvin Addison [[email protected]] Sent: Monday, August 26, 2013 14:39 To: [email protected] Subject: Re: [cas-user] SAML Ticket Validation > OK. Here we go... Something indeed seems to be wrong with mod_auth_cas. With > every http request for SAML validation I get one or more segfaults in the > apache default error.log. Two observations about the logs you shared: 1. You're getting a successful SAML ticket validation response. 2. Looks like you're getting redirected to CAS for resources (JS, CSS, favicon) other than your application entry point HTML page. There's nothing strictly wrong with #2 per se, but it makes reading the logs much harder and it's relatively less efficient. It would be interesting to have some logging to indicate successful parsing of attributes, but I don't see an AttributeResponse in the SAML message, which indicates you haven't configured CAS for attribute release or you haven't allowed attributes to be released in the service manager. I have a patched version you can use that provides additional attribute logging, https://github.com/serac/mod_auth_cas/tree/attr-logging, which you may find helpful. In my experience most problems are in parsing the XML; it would be reassuring to know you're getting past that part. M -- You are currently subscribed to [email protected] as: [email protected] To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user -- You are currently subscribed to [email protected] as: [email protected] To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user -- You are currently subscribed to [email protected] as: [email protected] To unsubscribe, change settings or access archives, see http://www.ja-sig.org/wiki/display/JSG/cas-user
