Red Hat Bugzilla – Bug 1097276
[GSS](6.4.z) MsSql datasource throws IllegalStateException while obtaining connection
Last modified: 2017-01-17 05:50:47 EST
Created attachment 895132 [details] server.log *Description of problem: Exception "java.lang.IllegalStateException: This ticket is no longer valid" is thrown in mssql XA datasource while obtaining connection. This error doesn't happen with non-XA datasource. I'll try to debug and some more details. Datasource: <xa-datasource jndi-name="java:jboss/datasources/TestDatasource" pool-name="TestDatasource" enabled="true" spy="true"> <xa-datasource-property name="URL"> jdbc:sqlserver://dpaz-win2008.msdomain.mw.lab.eng.bos.redhat.com;DatabaseName=krbusr01 </xa-datasource-property> <xa-datasource-property name="integratedSecurity"> true </xa-datasource-property> <xa-datasource-property name="authenticationScheme"> JavaKerberos </xa-datasource-property> <xa-datasource-class>com.microsoft.sqlserver.jdbc.SQLServerXADataSource</xa-datasource-class> <driver>mssql2008R2.jar</driver> <xa-pool> <min-pool-size>0</min-pool-size> <max-pool-size>1</max-pool-size> <allow-multiple-users>true</allow-multiple-users> </xa-pool> <security> <security-domain>DatabaseUser</security-domain> </security> </xa-datasource> I also tried to remove elements <xa-datasource-property> for integratedSecurity and authenticationScheme and add them direcly to URL Exception: (full stacktrace in attached server.log) Caused by: java.lang.IllegalStateException: This ticket is no longer valid at javax.security.auth.kerberos.KerberosTicket.toString(KerberosTicket.java:638) [rt.jar:1.7.0_17] at sun.security.jgss.GSSCredentialImpl.toString(GSSCredentialImpl.java:633) [rt.jar:1.7.0_17] at java.lang.String.valueOf(String.java:2854) [rt.jar:1.7.0_17] at java.lang.StringBuilder.append(StringBuilder.java:128) [rt.jar:1.7.0_17] at sun.security.jgss.GSSUtil$1.run(GSSUtil.java:342) [rt.jar:1.7.0_17] at sun.security.jgss.GSSUtil$1.run(GSSUtil.java:331) [rt.jar:1.7.0_17] at java.security.AccessController.doPrivileged(Native Method) [rt.jar:1.7.0_17] at sun.security.jgss.GSSUtil.searchSubject(GSSUtil.java:329) [rt.jar:1.7.0_17] at sun.security.jgss.krb5.Krb5MechFactory.getCredFromSubject(Krb5MechFactory.java:68) [rt.jar:1.7.0_17] at sun.security.jgss.krb5.Krb5MechFactory.getCredentialElement(Krb5MechFactory.java:115) [rt.jar:1.7.0_17] at sun.security.jgss.GSSManagerImpl.getCredentialElement(GSSManagerImpl.java:192) [rt.jar:1.7.0_17] at sun.security.jgss.GSSCredentialImpl.add(GSSCredentialImpl.java:406) [rt.jar:1.7.0_17] at sun.security.jgss.GSSCredentialImpl.<init>(GSSCredentialImpl.java:60) [rt.jar:1.7.0_17] at sun.security.jgss.GSSManagerImpl.createCredential(GSSManagerImpl.java:153) [rt.jar:1.7.0_17] at com.microsoft.sqlserver.jdbc.KerbAuthentication$1.run(KerbAuthentication.java:189) at com.microsoft.sqlserver.jdbc.KerbAuthentication$1.run(KerbAuthentication.java:187) at java.security.AccessController.doPrivileged(Native Method) [rt.jar:1.7.0_17] at javax.security.auth.Subject.doAs(Subject.java:415) [rt.jar:1.7.0_17] at com.microsoft.sqlserver.jdbc.KerbAuthentication.getClientCredential(KerbAuthentication.java:199) at com.microsoft.sqlserver.jdbc.KerbAuthentication.intAuthInit(KerbAuthentication.java:150) at com.microsoft.sqlserver.jdbc.KerbAuthentication.GenerateClientContext(KerbAuthentication.java:268) at com.microsoft.sqlserver.jdbc.SQLServerConnection.sendLogon(SQLServerConnection.java:2691) at com.microsoft.sqlserver.jdbc.SQLServerConnection.logon(SQLServerConnection.java:2234) at com.microsoft.sqlserver.jdbc.SQLServerConnection.access$000(SQLServerConnection.java:41) at com.microsoft.sqlserver.jdbc.SQLServerConnection$LogonCommand.doExecute(SQLServerConnection.java:2220) at com.microsoft.sqlserver.jdbc.TDSCommand.execute(IOBuffer.java:5696) at com.microsoft.sqlserver.jdbc.SQLServerConnection.executeCommand(SQLServerConnection.java:1715) at com.microsoft.sqlserver.jdbc.SQLServerConnection.connectHelper(SQLServerConnection.java:1326) at com.microsoft.sqlserver.jdbc.SQLServerConnection.login(SQLServerConnection.java:991) at com.microsoft.sqlserver.jdbc.SQLServerConnection.connect(SQLServerConnection.java:827) at com.microsoft.sqlserver.jdbc.SQLServerXAConnection.<init>(SQLServerXAConnection.java:43) at com.microsoft.sqlserver.jdbc.SQLServerXADataSource.getXAConnection(SQLServerXADataSource.java:51) at org.jboss.jca.adapters.jdbc.xa.XAManagedConnectionFactory.getXAManagedConnection(XAManagedConnectionFactory.java:497) *Version-Release number of selected component (if applicable): EAP 6.3.0.ER3 IronJacamar 1.0.26 *Steps to Reproduce: 1. clone datasource-kerberos test suite git://git.app.eng.bos.redhat.com/jbossqe-eap-tests-domain-mode.git 2. extract eap somewhere 3. run mvn integration-test -Djboss.dist=<path-to-eap> -Ddb.profile=mssql2008R2 -Djdbc.installation.type=deployment -Dit.test=org.jboss.qa.krbds.test.XADatasourceWithAllowMultipleUsersTestCase#testDatasource 4. test fails, see server.log for manual testing you can now run eap and deploy app target/deployment/_DEFAULT__hostTestDeployment_HostTestWebApp.war and then access http://localhost:8080/HostTestWebApp/HostTestServlet?profile=mssql2008R2 *Additional info: I've chosen security component, because error message seems to be related to kerberos ticket. But it could be related also to JCA as there is no error with non XA datasource. Setting blocker? flag because it's RFE
same problem with non-XA datasource. It does not happen while running single test (-Dit.test=) but it always fails with all tests task. With XA datasource it happens in both cases, all tests and single test.
I will get an EAP build running in a minute, we should not be hitting any timeouts here but I am wondering if something is calling dispose on the GSSCredential and making it invalid.
Created attachment 896426 [details] MSSQL Stack Traces Attaching a debugger I can confirm that the error message being reported is as a result of the JDBC driver disposing of the KerberosTicket that it is using and then subsequently attempting to use it again, the two stacks in the file illustrate this.
I think the following could now be beneficial: - - Update testing so that the category 'com.microsoft' is logged at level FINEST - Update the test to use ByteMan to log the stack each time javax.security.auth.kerberos.KerberosTicket.dispose() us called. My feeling at the moment is that the driver is taking a valid Subject, something during the call is causing the driver to invalidate one of the tickets and the driver subsequently tries to use it an fails. The additional logging should help map this better with the ByteMan traces as well. It could be that there is something we can fix and it is an initial connection attempt that is failing but we only see an error message for a retry or it could be an issue within the JDBC driver.
Created attachment 897158 [details] byteman-server.log suggested changes were added to test suite, branch byteman. KerberosTicket.destroy is always called after authentication. Details in attached server.log
Created attachment 927065 [details] byteman-two-test-connection-in-pool-calls-server.log Attached server.log with two test-connection-in-pool calls. First passes, second fails. com.microsoft log category set to TRACE byteman rule that logs stack each time javax.security.auth.kerberos.KerberosTicket.destroy() us called
Don't think we already added clarification regarding the difference between XA and non-XA but simply it is the recovery thread for the XA connections that is causing the error to be reported sooner as that thread can result in an attempt to obtain a connection sooner.
Kabir Khan <kabir.khan@jboss.com> updated the status of jira EAP6-217 to Resolved
John Doyle <jdoyle@jboss.org> updated the status of jira EAP6-217 to Closed
As per https://bugzilla.redhat.com/show_bug.cgi?id=1097276#c25 I believe the authentication cache disabling must be applied in conjunction with disabling prefill. Most likely IronJacamar fills the cache in a loop with the same Subject. If that is the case, maybe we can change that loop to always go through authentication and leave the Subject caching to the security configuration.
As suggested by Derek Horton: > Change: > > <security-domain name="SQLJDBC_KERBEROS" cache-type="default"> > > to this: > > <security-domain name="SQLJDBC_KERBEROS">
verified with EAP 6.4.4.CP.CR3
Martin Simka <msimka@redhat.com> updated the status of jira JBEAP-843 to Closed
Per erich, "I have been given information that EAP 6.4.4 shipped and should be available." Curious why this BZ doesn't reflect that and why it is not in closed state?
Retroactively bulk-closing issues from released EAP 6.4 cumulative patches.