In a previous blog, I explained how it was possible to enable the SSO/Atn/Atz (SSO/Authentication/Authorization) debug logs in order to troubleshoot an issue. In this blog, I will show the logs generated by an issue that I had to deal with last month at one of our customers. This issue will probably not occur very often but it is a pretty funny one so I wanted to share it!

So the issue I will talk about in this blog happened on an environment that is configured with a SAML2 SSO. With a fully working SAML2 SSO, the WebLogic hosting the application is supposed to redirect the end-user to the IdP Partner (with a SAML2 request) which process it and then redirect the end-user again to the WebLogic (with the SAML2 response) which process the response and finally grant access to the Application. On this issue, both redirections were apparently happening properly but then for an unknown reason the WebLogic Server was blocking the access to the application with a “403 – Forbidden” message.

Obviously the first thing I did is to enable the debug logs and then I replicated the issue. These are the logs that I could see on the Managed Server log file:

<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <SAML2Servlet: Processing request on URI '/saml2/sp/acs/post'>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <getServiceTypeFromURI(): request URI is '/saml2/sp/acs/post'>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <getServiceTypeFromURI(): service URI is '/sp/acs/post'>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <getServiceTypeFromURI(): returning service type 'ACS'>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <Assertion consumer service: processing>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <get SAMLResponse from http request:PBvbnNSJ1cXMlFtZzaXM6bmHhtbG5zm46NhwOlJlOnNhbWxHbWxIb2Fc3wP6dGM6
U0FiB4bWxuczp4NTAwPSJ1cm46b2FzNTDoyLjA6YXNzZXJ0aW9uIaXM6bmFtZXM6
U0FdG9jb2wiIHhtbG5zOmRzaWc9Imh0dHA6Ly93NTDoyLjA6cHJvd3cudzMub3Jn
aHR0cDoa5vcmcvMjAwMS9W5zdGFuY2vL3d3dy53MyYTUxTY2hlbWEtUiIERlc3Rp
MWNxM2FjNzI1ZDjYmIVhNDM1Zlzc3VlSW5zdGFudD0ijhlNjc3OTkiIEMjAxNy0x
LzINpZyMiIHhtwMDAvMDkveG1sZHbG5DovL3d3dy53My5vczOmVuYz0iaHR0cmcv
MMS8wNC94bWxjAwlbmWxuczpzYW1sPMjIiB4bSJ1aXM6bmFtZXM6dcm46b2FzGM6
dGdXRlOM6U0FNZXM6YXR0cmliTDoyLjAAiIHhtbG5zOnhzaT6cHJvZmlslg1MD0i
bmF0aW9JodHRwczovL5ldS5uPSub3Zhc3BoY2hicy1DIyMinRpcyzdDIyM5uZXQ6
ODA4NSMvcG9zdCI9zYW1sMi9zcC3SUhwRHRuN3I1WH9hY3gSUQ9ImlkLUhhTTFha
Z3hBiIEmVzcWW5URXhybHJlG9uc2VUbz0RVFGbWt1VkRaNC0iXzB4ZluUGM1Mjk2
MS0xNw6SXNzdWjo0OTFZlcnNpVyIEZvo1MloiIlQxMb249IjIuMCI+PHNhbWcm1h
...
LTExIgTDEyPSIyMDE3LFjQ525PcLTE2VETExLTOk2VDOjUyWimdGVym90TEyOjU0
OjUyWiI+PHNh8c2FtbDpBdWRpZW5bWw6QXVkabj4jWVuY2VSZXN0cmljdGlvZT5T
c3NGVkVHJhb3b3JkUHJvdG1sOkF1dGhuQ29udGV4VjdnNwb3J0PC9zYWdENsYXNz
QXV0aG5gQXV0TdGF0LTExLTE2VDEaG5JZW1lbnQSIyMDE3bnN0YW50PyOjQ5OjUy
aEV25PcVucnhPSIyMDE3LTExEZmZ2IiBkFmdGVyLTEJWTTZXNzaW9uTm90T2VDEz
WivUWuZGV4PSJpZC13UlVMWGRYOXd6xWzc2lvbklRThFZDJwRDdIgU2VR210OUc0
dWJXYSUQ8L3NhRE1PQ19XlfREVWTQU1MMl9FbnbWw6QXVkaWVuY2U+RpdHlfPC9z
YWRpb24+P1sOkF1ZGllbHJpY3mPHNhNlUmVzdC9zYW1sOkNvbmRpdGlvbnM+bWw6
YXNzUzpjbYW1YXNpczpuIuMlmVmPnVybjpvDphYxzp0YzpTQU1MOjGFzc2VzOlBh
OjAXh0Pj0OjUyWiI+PHNsOkF1dGhuQhxzYW129udGV4bWw6QXV0aG5Db250ZdENs
UmVnRlepBdXRobkNvbzYWmPjwvc2FtbDF1dGhuU1sOkHQ+PC93RhdGVtZW50Pjwv
c2F9zY25zZtbDpBcW1scDpSZXNwb3NlcnRpb24+PCT4=
>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <BASE64 decoded saml message:<samlp:Response xmlns_samlp="urn:oasis:names:tc:SAML:2.0:protocol" xmlns_dsig="http://www.w3.org/2000/09/xmldsig#" xmlns_enc="http://www.w3.org/2001/04/xmlenc#" xmlns_saml="urn:oasis:names:tc:SAML:2.0:assertion" xmlns_x500="urn:oasis:names:tc:SAML:2.0:profiles:attribute:X500" xmlns_xsi="http://www.w3.org/2001/XMLSchema-instance" Destination="https://weblogic_server_01/saml2/sp/acs/post" ID="id-HpDtn7r5XxxAQFYnwSLXZmkuVgIHTExrlreEDZ4-" InResponseTo="_0x7258edc52961ccbd5a435fb13ac67799" IssueInstant="2017-11-12T12:23:42Z" Version="2.0"><saml:Issuer Format="urn:oasis:names:tc:SAML:2.0:nameid-format:entity">https://idp_partner_01/fed/idp</saml:Issuer><dsig:Signature><dsig:SignedInfo><dsig:CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/><dsig:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"/><dsig:Reference URI="#id-HpDtn7r5XxxAQFYnwSLXZmkuVgIHTExrlreEDZ4-"><dsig:Transforms><dsig:Transform Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"/><dsig:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/></dsig:Transforms><dsig:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"/><dsig:DigestValue>YGtUZvsfo3z51AsBo7UDhbd6Ts=</dsig:DigestValue></dsig:Reference></dsig:SignedInfo><dsig:SignatureValue>al8sJwbqzjh1qgM3Sj0QrX1aZjwyI...JB6l4jmj91BdQrYQ7VxFzvNLczZ2brJSdLLig==</dsig:SignatureValue><dsig:KeyInfo><dsig:X509Data><dsig:X509Certificate>MIwDQUg+nhYqGZ7pCgBQAwTTELMAkGA1UEBhMCQk1ZhQ...aATPRCd113tVqsvCkUwpfQ5zyUHaKw4FkXmiT2nzxxHA==</dsig:X509Certificate></dsig:X509Data></dsig:KeyInfo></dsig:Signature><samlp:Status><samlp:StatusCode Value="urn:oasis:names:tc:SAML:2.0:status:Success"/></samlp:Status><saml:Assertion ID="id-0WrMNbOz6wsuZdFPhfjnw7WIXXQ6k89-1AgHZ9Oi" IssueInstant="2017-11-12T12:23:42Z" Version="2.0"><saml:Issuer Format="urn:oasis:names:tc:SAML:2.0:nameid-format:entity">https://idp_partner_01/fed/idp</saml:Issuer><dsig:Signature><dsig:SignedInfo><dsig:CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/><dsig:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"/><dsig:Reference URI="#id-0WrMNbOz6wsuZdFPhfjnw7WIXXQ6k89-1AgHZ9Oi"><dsig:Transforms><dsig:Transform Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"/><dsig:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/></dsig:Transforms><dsig:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"/><dsig:DigestValue>7+jZtq8SpY3BKVaFjIFeEJm51cA=</dsig:DigestValue></dsig:Reference></dsig:SignedInfo><dsig:SignatureValue>GIlXt4B4rVFoDJRxidpZO73gXB68Dd+mcpoV9DKrjBBjLRz...zGTDcEYY2MG8FgtarZhVQGc4zxkkSg8GRT6Wng3NEuTUuA==</dsig:SignatureValue><dsig:KeyInfo><dsig:X509Data><dsig:X509Certificate>MIwDQUg+nhYqGZ7pCgBQAwTTELMAkGA1UEBhMCQk1ZhQ...aATPRCd113tVqsvCkUwpfQ5zyUHaKw4FkXmiT2nzxxHA==</dsig:X509Certificate></dsig:X509Data></dsig:KeyInfo></dsig:Signature><saml:Subject><saml:NameID Format="urn:oasis:names:tc:SAML:1.1:nameid-format:unspecified">PATOU_MORGAN</saml:NameID><saml:SubjectConfirmation Method="urn:oasis:names:tc:SAML:2.0:cm:bearer"><saml:SubjectConfirmationData InResponseTo="_0x7258edc52961ccbd5a435fb13ac67799" NotOnOrAfter="2017-11-12T12:28:42Z" Recipient="https://weblogic_server_01/saml2/sp/acs/post"/></saml:SubjectConfirmation></saml:Subject><saml:Conditions NotBefore="2017-11-12T12:23:42Z" NotOnOrAfter="2017-11-12T12:28:42Z"><saml:AudienceRestriction><saml:Audience>SAML2_Entity_ID_01</saml:Audience></saml:AudienceRestriction></saml:Conditions><saml:AuthnStatement AuthnInstant="2017-11-12T12:23:42Z" SessionIndex="id-oX9wXdpGmt9GQlVffvY4hEIRULEd25nrxDzE8D7w" SessionNotOnOrAfter="2017-11-12T12:38:42Z"><saml:AuthnContext><saml:AuthnContextClassRef>urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport</saml:AuthnContextClassRef></saml:AuthnContext></saml:AuthnStatement></saml:Assertion></samlp:Response>>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <<samlp:Response> is signed.>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecurityAtn> <com.bea.common.security.internal.service.IdentityAssertionServiceImpl.assertIdentity(SAML2.Assertion.DOM)>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecurityAtn> <com.bea.common.security.internal.service.IdentityAssertionTokenServiceImpl.assertIdentity(SAML2.Assertion.DOM)>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2IdentityAsserterProvider: start assert SAML2 token>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2IdentityAsserterProvider: SAML2IdentityAsserter: tokenType is 'SAML2.Assertion.DOM'>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: Start verify assertion signature>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: The assertion is signed.>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: End verify assertion signature>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: Start verify assertion attributes>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: End verify assertion attributes>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: Start verify assertion issuer>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: End verify assertion issuer>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Atn> <SAML2Assert: Start verify assertion conditions>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecurityAtn> <com.bea.common.security.internal.service.IdentityAssertionTokenServiceImpl.assertIdentity - IdentityAssertionException>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <[Security:090377]Identity Assertion Failed, weblogic.security.spi.IdentityAssertionException: [Security:090377]Identity Assertion Failed, weblogic.security.spi.IdentityAssertionException: [Security:096537]Assertion is not yet valid (NotBefore condition).>
<Nov 12, 2017 12:23:41 PM UTC> <Debug> <SecuritySAML2Service> <exception info
javax.security.auth.login.LoginException: [Security:090377]Identity Assertion Failed, weblogic.security.spi.IdentityAssertionException: [Security:090377]Identity Assertion Failed, weblogic.security.spi.IdentityAssertionException: [Security:096537]Assertion is not yet valid (NotBefore condition).
        at com.bea.common.security.internal.service.IdentityAssertionServiceImpl.assertIdentity(IdentityAssertionServiceImpl.java:89)
        at sun.reflect.GeneratedMethodAccessor1410.invoke(Unknown Source)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at com.bea.common.security.internal.utils.Delegator$ProxyInvocationHandler.invoke(Delegator.java:64)
		...
>

 

I cut some of the strings above (like all signatures, the SSL Certificates, aso…) because it was really too big and it is not really important. What is important above is the java exception. Indeed, the Identity Assertion failed because of the following: ‘Assertion is not yet valid (NotBefore condition)’. This message might seems a little bit mystical but it actually points you right to the issue: the ‘NotBefore’ condition is causing the validation to fail.

So why is that? Well when you have a SAML2 SSO like I said above, you first have a request and then a response. For security reasons, there are some conditions that apply on them and that need to be fulfilled for the SSO to be working. To understand that a little bit better, I took the decoded SAML2 response from the logs above (line 32) and I reformatted it into an XML format so it is more readable:

<samlp:Response xmlns_samlp="urn:oasis:names:tc:SAML:2.0:protocol" xmlns_dsig="http://www.w3.org/2000/09/xmldsig#" xmlns_enc="http://www.w3.org/2001/04/xmlenc#" xmlns_saml="urn:oasis:names:tc:SAML:2.0:assertion" xmlns_x500="urn:oasis:names:tc:SAML:2.0:profiles:attribute:X500" xmlns_xsi="http://www.w3.org/2001/XMLSchema-instance" Destination="https://weblogic_server_01/saml2/sp/acs/post" ID="id-HpDtn7r5XxxAQFYnwSLXZmkuVgIHTExrlreEDZ4-" InResponseTo="_0x7258edc52961ccbd5a435fb13ac67799" IssueInstant="2017-11-12T12:23:42Z" Version="2.0">
	<saml:Issuer Format="urn:oasis:names:tc:SAML:2.0:nameid-format:entity">https://idp_partner_01/fed/idp</saml:Issuer>
	<dsig:Signature>
		<dsig:SignedInfo>
			<dsig:CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/>
			<dsig:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"/>
			<dsig:Reference URI="#id-HpDtn7r5XxxAQFYnwSLXZmkuVgIHTExrlreEDZ4-">
				<dsig:Transforms>
					<dsig:Transform Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"/>
					<dsig:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/>
				</dsig:Transforms>
				<dsig:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"/>
				<dsig:DigestValue>YGtUZvsfo3z51AsBo7UDhbd6Ts=</dsig:DigestValue>
			</dsig:Reference>
		</dsig:SignedInfo>
		<dsig:SignatureValue>al8sJwbqzjh1qgM3Sj0QrX1aZjwyI...JB6l4jmj91BdQrYQ7VxFzvNLczZ2brJSdLLig==</dsig:SignatureValue>
		<dsig:KeyInfo>
			<dsig:X509Data>
				<dsig:X509Certificate>MIwDQUg+nhYqGZ7pCgBQAwTTELMAkGA1UEBhMCQk1ZhQ...aATPRCd113tVqsvCkUwpfQ5zyUHaKw4FkXmiT2nzxxHA==</dsig:X509Certificate>
			</dsig:X509Data>
		</dsig:KeyInfo>
	</dsig:Signature>
	<samlp:Status>
		<samlp:StatusCode Value="urn:oasis:names:tc:SAML:2.0:status:Success"/>
	</samlp:Status>
	<saml:Assertion ID="id-0WrMNbOz6wsuZdFPhfjnw7WIXXQ6k89-1AgHZ9Oi" IssueInstant="2017-11-12T12:23:42Z" Version="2.0">
		<saml:Issuer Format="urn:oasis:names:tc:SAML:2.0:nameid-format:entity">https://idp_partner_01/fed/idp</saml:Issuer>
		<dsig:Signature>
			<dsig:SignedInfo>
				<dsig:CanonicalizationMethod Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/>
				<dsig:SignatureMethod Algorithm="http://www.w3.org/2000/09/xmldsig#rsa-sha1"/>
				<dsig:Reference URI="#id-0WrMNbOz6wsuZdFPhfjnw7WIXXQ6k89-1AgHZ9Oi">
					<dsig:Transforms>
						<dsig:Transform Algorithm="http://www.w3.org/2000/09/xmldsig#enveloped-signature"/>
						<dsig:Transform Algorithm="http://www.w3.org/2001/10/xml-exc-c14n#"/>
					</dsig:Transforms>
					<dsig:DigestMethod Algorithm="http://www.w3.org/2000/09/xmldsig#sha1"/>
					<dsig:DigestValue>7+jZtq8SpY3BKVaFjIFeEJm51cA=</dsig:DigestValue>
				</dsig:Reference>
			</dsig:SignedInfo>
			<dsig:SignatureValue>GIlXt4B4rVFoDJRxidpZO73gXB68Dd+mcpoV9DKrjBBjLRz...zGTDcEYY2MG8FgtarZhVQGc4zxkkSg8GRT6Wng3NEuTUuA==</dsig:SignatureValue>
			<dsig:KeyInfo>
				<dsig:X509Data>
					<dsig:X509Certificate>MIwDQUg+nhYqGZ7pCgBQAwTTELMAkGA1UEBhMCQk1ZhQ...aATPRCd113tVqsvCkUwpfQ5zyUHaKw4FkXmiT2nzxxHA==</dsig:X509Certificate>
				</dsig:X509Data>
			</dsig:KeyInfo>
		</dsig:Signature>
		<saml:Subject>
			<saml:NameID Format="urn:oasis:names:tc:SAML:1.1:nameid-format:unspecified">PATOU_MORGAN</saml:NameID>
			<saml:SubjectConfirmation Method="urn:oasis:names:tc:SAML:2.0:cm:bearer">
				<saml:SubjectConfirmationData InResponseTo="_0x7258edc52961ccbd5a435fb13ac67799" NotOnOrAfter="2017-11-12T12:28:42Z" Recipient="https://weblogic_server_01/saml2/sp/acs/post"/>
			</saml:SubjectConfirmation>
		</saml:Subject>
		<saml:Conditions NotBefore="2017-11-12T12:23:42Z" NotOnOrAfter="2017-11-12T12:28:42Z">
			<saml:AudienceRestriction>
				<saml:Audience>SAML2_Entity_ID_01</saml:Audience>
			</saml:AudienceRestriction>
		</saml:Conditions>
		<saml:AuthnStatement AuthnInstant="2017-11-12T12:23:42Z" SessionIndex="id-oX9wXdpGmt9GQlVffvY4hEIRULEd25nrxDzE8D7w" SessionNotOnOrAfter="2017-11-12T12:38:42Z">
			<saml:AuthnContext>
				<saml:AuthnContextClassRef>urn:oasis:names:tc:SAML:2.0:ac:classes:PasswordProtectedTransport</saml:AuthnContextClassRef>
			</saml:AuthnContext>
		</saml:AuthnStatement>
	</saml:Assertion>
</samlp:Response>

 

As you can see on the XML, there are two conditions that apply on the SAML2 response:

  • The usage of the response needs to take place ‘NotBefore’ the current time
  • The usage of the response needs to take place ‘NotOnOrAfter’ the current time + 5 minutes

In this case, the NotBefore is set to ‘2017-11-12T12:23:42Z’ which is the current time of the IdP Partner Server. However you can see in the logs that the WebLogic Server hosting the application is actually one second before this time (Nov 12, 2017 12:23:41 PM UTC) and therefore the NotBefore restriction applies and the WebLogic Server hosting the application has no other choice than to return a ‘403 – Forbidden’ message because the SAML2 response is NOT valid.

In this case, the NTP daemon (Network Time Protocol) on the IdP Partner Linux server has been restarted and the time on this server has been resynched which solved the issue. Having a server in the future can cause some interesting behaviors :).

 

Post Views: 1,226
Thumbnail [60x60]
by
Morgan Patou