Investigation on wsscxf.saml.* FAT Unable to initialize SSL connection in defect 285325

meiaus commented 3 years ago

As commented in 285325:

This defect 285325 contained the result from all these wssecxf.saml* FAT on various SOE platforms, which may provide another data point to help investigate. So we'll use it as parent defects and dup the rest:

285702 (com.ibm.ws.wssecurity_fat.wsscxf.saml.2) 285687 (com.ibm.ws.wssecurity_fat.wsscxf.saml.3, com.ibm.ws.wssecurity_fat.wsscxf.saml.4) 285699 (com.ibm.ws.wssecurity_fat.wsscxf.saml.2) 285513 (com.ibm.ws.wssecurity_fat.wsscxf.saml.2) 282040 (com.ibm.ws.wssecurity_fat.wsscxf.saml.2, com.ibm.ws.wssecurity_fat.wsscxf.saml.3, com.ibm.ws.wssecurity_fat.wsscxf.saml.4)

meiaus commented 3 years ago

The observation so far is:

The error appeared after server configuration update
The error may appear randomly on any EE8 test method
saml.2 involving EE9 Lite bucket, so the error can also appear on EE9 test
When the error appeared, the actual test did run through successfully as seen in messages.log; output.txt also indicated the test passed
So far the following platforms seem to have higher frequency for the error to appear:
- Windows (all jdk flavors)
- Non-Windows - JDK8

meiaus commented 3 years ago

Taking saml.2 FAT result as an example:

messages.log


[9/6/21 2:45:52:635 PDT] 00000028 SystemOut                                                    O ENDING TEST CASE: testCxfCaller_mapToUserRegistry_Group_inRegistry_identifiersOmitted_EE8_FEATURES
[9/6/21 2:45:52:635 PDT] 00000028 SystemOut                                                    O -----------------------------------------------------------------------------------------
[9/6/21 2:45:54:757 PDT] 00000028 SystemOut                                                    O -----------------------------------------------------------------------------------------
[9/6/21 2:45:54:758 PDT] 00000028 SystemOut                                                    O STARTING TEST CASE: testCxfCaller_mapToUserRegistry_Group_notInRegistry_identifiersOmitted_EE8_FEATURES
[9/6/21 2:45:54:759 PDT] 00000028 SystemOut                                                    O -----------------------------------------------------------------------------------------
[9/6/21 2:45:56:032 PDT] 00000026 com.ibm.ws.config.xml.internal.ConfigRefresher               A CWWKG0016I: Starting server configuration update.
[9/6/21 2:45:56:069 PDT] 00000022 com.ibm.ws.security.registry.basic.internal.BasicRegistry    W CWWKS3107W: Member entry with the name 'user1' for group 'test_groupIdentifier' does not match a defined user.
[9/6/21 2:45:56:088 PDT] 00000027 com.ibm.ws.kernel.feature.internal.FeatureManager            I CWWKF0007I: Feature update started.
[9/6/21 2:45:56:561 PDT] 00000026 com.ibm.ws.config.xml.internal.ConfigRefresher               A CWWKG0017I: The server configuration was successfully updated in 0.528 seconds.
[9/6/21 2:45:56:573 PDT] 00000027 com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0012I: The server installed the following features: [securitylibertyinternals-1.0].
[9/6/21 2:45:56:574 PDT] 00000027 com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0008I: Feature update completed in 0.513 seconds.
[9/6/21 2:46:12:620 PDT] 00000026 com.ibm.ws.channel.ssl.internal.SSLHandshakeErrorTracker     E CWWKO0801E: Unable to initialize SSL connection. Unauthorized access was denied or security settings have expired. Exception is javax.net.ssl.SSLHandshakeException: Received fatal alert: certificate_unknown
at com.ibm.jsse2.g.a(g.java:28)
at com.ibm.jsse2.g.a(g.java:48)
at com.ibm.jsse2.bb.a(bb.java:33)
at com.ibm.jsse2.g$c.consume(g$c.java:29)
at com.ibm.jsse2.bb.a(bb.java:71)
at com.ibm.jsse2.a0.a(a0.java:43)
at com.ibm.jsse2.bg.g(bg.java:317)
at com.ibm.jsse2.bg.f(bg.java:164)
at com.ibm.jsse2.bg.e(bg.java:199)
at com.ibm.jsse2.bg.unwrap(bg.java:106)
at javax.net.ssl.SSLEngine.unwrap(SSLEngine.java:41)
at com.ibm.ws.channel.ssl.internal.SSLUtils.handleHandshake(SSLUtils.java:904)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.readyInbound(SSLConnectionLink.java:589)
at com.ibm.ws.channel.ssl.internal.SSLConnectionLink.ready(SSLConnectionLink.java:336)
at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.sendToDiscriminators(NewConnectionInitialReadCallback.java:167)
at com.ibm.ws.tcpchannel.internal.NewConnectionInitialReadCallback.complete(NewConnectionInitialReadCallback.java:75)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.requestComplete(WorkQueueManager.java:504)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.attemptIO(WorkQueueManager.java:574)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager.workerRun(WorkQueueManager.java:958)
at com.ibm.ws.tcpchannel.internal.WorkQueueManager$Worker.run(WorkQueueManager.java:1047)
at com.ibm.ws.threading.internal.ExecutorServiceImpl$RunnableWrapper.run(ExecutorServiceImpl.java:238)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1160)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635)
at java.lang.Thread.run(Thread.java:825)
.
[9/6/21 2:46:13:198 PDT] 00000028 SystemOut                                                    O In getPrincipalUserID
[9/6/21 2:46:13:200 PDT] 00000028 SystemOut                                                    O WSSubject.getCallerPrincipal():null:Subject:
Principal: WSPrincipal:testuser
Public Credential: 
. . .

[9/6/21 2:46:13:200 PDT] 00000028 SystemOut O caller_princ IS null [9/6/21 2:46:13:200 PDT] 00000028 SystemOut O Returning principal: testuser [9/6/21 2:46:13:201 PDT] 00000028 SystemOut O In getRealmName [9/6/21 2:46:13:202 PDT] 00000028 SystemOut O In getGroups [9/6/21 2:46:13:202 PDT] 00000028 SystemOut O groups is null [9/6/21 2:46:13:203 PDT] 00000028 SystemOut O Returning groups: null [9/6/21 2:46:13:203 PDT] 00000028 SystemOut O test.libertyfat.samlcaller.SAMLCaller_bac02a gets a client request [9/6/21 2:46:13:539 PDT] 00000028 com.ibm.ws.config.xml.internal.ConfigRefresher A CWWKG0016I: Starting server configuration update. [9/6/21 2:46:13:599 PDT] 00000029 com.ibm.ws.kernel.feature.internal.FeatureManager I CWWKF0007I: Feature update started. [9/6/21 2:46:14:030 PDT] 00000028 com.ibm.ws.config.xml.internal.ConfigRefresher A CWWKG0017I: The server configuration was successfully updated in 0.491 seconds. [9/6/21 2:46:14:039 PDT] 00000029 com.ibm.ws.kernel.feature.internal.FeatureManager A CWWKF0013I: The server removed the following features: [securitylibertyinternals-1.0]. [9/6/21 2:46:14:040 PDT] 00000029 com.ibm.ws.kernel.feature.internal.FeatureManager A CWWKF0008I: Feature update completed in 0.472 seconds. [9/6/21 2:46:28:377 PDT] 00000026 SystemOut O ----------------------------------------------------------------------------------------- [9/6/21 2:46:28:378 PDT] 00000026 SystemOut O ENDING TEST CASE: testCxfCaller_mapToUserRegistry_Group_notInRegistry_identifiersOmitted_EE8_FEATURES

- output.txt:

... [09/06/2021 02:46:12:308 PDT] 001 CommonMessageTools printAllCookies I Cookie: JSESSIONID Value: 0000zmkk4IcQi9wyMNj8ouLYW7H:817b4a24-f310-4317-a5e2-99dddab9cf32 isSecure: false Path: / Expires: null Domain: localhost [09/06/2021 02:46:12:308 PDT] 001 CommonMessageTools printAllCookies I Cookie: shib_idp_session Value: b4c45744f1836c28e18e8ee659b77973e7915ef4f35a29f582e9ba4bca0db8b8 isSecure: false Path: /idp Expires: null Domain: localhost [09/06/2021 02:46:12:308 PDT] 001 SAMLCommonTestHelpers invokeACSWithSAMLResponse I Cookies after we clear cookies (psst: this should not log any cookies) [09/06/2021 02:46:12:308 PDT] 001 CommonMessageTools printAllCookies I printAllCookies [09/06/2021 02:46:12:308 PDT] 001 SAMLCommonTestHelpers invokeACSWithSAMLResponse I ACS request: https://localhost:8020/ibm/saml20/sp1/acs [09/06/2021 02:46:13:280 PDT] 001 TestHelpers waitBeforeContinuing I Waiting for HtmlUnit to finish its business [09/06/2021 02:46:13:280 PDT] 001 CommonMessageTools printAllCookies I printAllCookies

...

meiaus commented 3 years ago

For comparison,

messages.log from a successful run on the same test method (above)


[9/2/21, 20:45:19:941 PDT] 00000101 SystemOut                                                    O -----------------------------------------------------------------------------------------
[9/2/21, 20:45:19:941 PDT] 00000101 SystemOut                                                    O STARTING TEST CASE: testCxfCaller_mapToUserRegistry_Group_notInRegistry_identifiersOmitted_EE8_FEATURES
[9/2/21, 20:45:19:941 PDT] 00000101 SystemOut                                                    O -----------------------------------------------------------------------------------------
[9/2/21, 20:45:21:786 PDT] 000000f5 com.ibm.ws.config.xml.internal.ConfigRefresher               A CWWKG0016I: Starting server configuration update.
[9/2/21, 20:45:21:816 PDT] 000000fd com.ibm.ws.security.registry.basic.internal.BasicRegistry    W CWWKS3107W: Member entry with the name 'user1' for group 'test_groupIdentifier' does not match a defined user.
[9/2/21, 20:45:21:879 PDT] 000000f3 com.ibm.ws.kernel.feature.internal.FeatureManager            I CWWKF0007I: Feature update started.
[9/2/21, 20:45:22:504 PDT] 000000f5 com.ibm.ws.config.xml.internal.ConfigRefresher               A CWWKG0017I: The server configuration was successfully updated in 0.720 seconds.
[9/2/21, 20:45:22:520 PDT] 000000f3 com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0012I: The server installed the following features: [securitylibertyinternals-1.0].
[9/2/21, 20:45:22:520 PDT] 000000f3 com.ibm.ws.kernel.feature.internal.FeatureManager            A CWWKF0008I: Feature update completed in 0.710 seconds.
[9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut                                                    O In getPrincipalUserID
[9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut                                                    O WSSubject.getCallerPrincipal():null:Subject:
Principal: WSPrincipal:testuser
Public Credential: 
. . .

[9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O caller_princ IS null [9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O Returning principal: testuser [9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O In getRealmName [9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O In getGroups [9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O groups is null [9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O Returning groups: null [9/2/21, 20:45:40:004 PDT] 000000f3 SystemOut O test.libertyfat.samlcaller.SAMLCaller_bac02a gets a client request [9/2/21, 20:45:40:441 PDT] 0000010d com.ibm.ws.config.xml.internal.ConfigRefresher A CWWKG0016I: Starting server configuration update. [9/2/21, 20:45:40:551 PDT] 00000100 com.ibm.ws.kernel.feature.internal.FeatureManager I CWWKF0007I: Feature update started. [9/2/21, 20:45:41:082 PDT] 0000010d com.ibm.ws.config.xml.internal.ConfigRefresher A CWWKG0017I: The server configuration was successfully updated in 0.648 seconds. [9/2/21, 20:45:41:098 PDT] 00000100 com.ibm.ws.kernel.feature.internal.FeatureManager A CWWKF0013I: The server removed the following features: [securitylibertyinternals-1.0]. [9/2/21, 20:45:41:098 PDT] 00000100 com.ibm.ws.kernel.feature.internal.FeatureManager A CWWKF0008I: Feature update completed in 0.641 seconds. [9/2/21, 20:45:55:879 PDT] 000000f3 SystemOut O ----------------------------------------------------------------------------------------- [9/2/21, 20:45:55:879 PDT] 000000f3 SystemOut O ENDING TEST CASE: testCxfCaller_mapToUserRegistry_Group_notInRegistry_identifiersOmitted_EE8_FEATURES [9/2/21, 20:45:55:879 PDT] 000000f3 SystemOut O ----------------------------------------------------------------------------------------- [9/2/21, 20:45:59:191 PDT] 00000099 SystemOut O ----------------------------------------------------------------------------------------- [9/2/21, 20:45:59:207 PDT] 00000099 SystemOut

- output.txt:

. . .

[09/02/2021 20:45:38:473 PDT] 001 CommonMessageTools printAllCookies I Cookie: JSESSIONID Value: 00002ktWAHXgoNoXD-1AO23t--I:39fbbf2a-d410-40cb-980e-4f0567be768f isSecure: false Path: / Expires: null Domain: localhost [09/02/2021 20:45:38:473 PDT] 001 CommonMessageTools printAllCookies I Cookie: shib_idp_session Value: 570d33e75670f09542e4039e874a95635bcfabb15e3962e49608798450306145 isSecure: false Path: /idp Expires: null Domain: localhost [09/02/2021 20:45:38:473 PDT] 001 SAMLCommonTestHelpers invokeACSWithSAMLResponse I Cookies after we clear cookies (psst: this should not log any cookies) [09/02/2021 20:45:38:473 PDT] 001 CommonMessageTools printAllCookies I printAllCookies [09/02/2021 20:45:38:473 PDT] 001 SAMLCommonTestHelpers invokeACSWithSAMLResponse I ACS request: https://localhost:8020/ibm/saml20/sp1/acs [09/02/2021 20:45:40:113 PDT] 001 TestHelpers waitBeforeContinuing I Waiting for HtmlUnit to finish its business [09/02/2021 20:45:40:113 PDT] 001 CommonMessageTools printAllCookies I printAllCookies

. . .

meiaus commented 3 years ago

Some idea, wondering in SAMLCommonTestHelpers invokeACSWithSAMLResponse, testSleep needs to add something for cxf saml scenario?

meiaus commented 2 years ago

The RTC 285325 is resolved through this PR https://github.com/OpenLiberty/open-liberty/pull/18580.

No action is needed for this issue.

OpenLiberty / open-liberty

Investigation on wsscxf.saml.* FAT Unable to initialize SSL connection in defect 285325 #18459