Bug 1097276

Summary: [GSS](6.4.z) MsSql datasource throws IllegalStateException while obtaining connection
Product: [JBoss] JBoss Enterprise Application Platform 6 Reporter: Martin Simka <msimka>
Component: SecurityAssignee: Darran Lofthouse <darran.lofthouse>
Status: CLOSED CURRENTRELEASE QA Contact: Martin Simka <msimka>
Severity: high Docs Contact: Russell Dickenson <rdickens>
Priority: unspecified    
Version: 6.3.0CC: bbaranow, bmaxwell, cdewolf, deisner, dpal, dsulliva, hokuda, istudens, jawilson, jmartisk, jolee, mharvey, myarboro, smumford, tfonteyn, tkonishi, tom.jenkinson, vvasilev, zrhoads
Target Milestone: CR1Keywords: TestCaseNeeded
Target Release: EAP 6.4.4   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Known Issue
Doc Text:
This release of JBoss EAP 6 carries a bug that produces the exception; `java.lang.IllegalStateException: This ticket is no longer valid` in MySQ datasources while obtaining connection. This issue is expected to be resolved in a future release.
Story Points: ---
Clone Of:
: 1257226 (view as bug list) Environment:
Last Closed: 2017-01-17 10:49:54 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Bug Depends On:    
Bug Blocks: 1235744, 1256953, 1257226    
Attachments:
Description Flags
server.log
none
MSSQL Stack Traces
none
byteman-server.log
none
byteman-two-test-connection-in-pool-calls-server.log none

Description Martin Simka 2014-05-13 13:19:32 UTC
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

Comment 1 Martin Simka 2014-05-16 11:39:06 UTC
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.

Comment 2 Darran Lofthouse 2014-05-16 11:45:27 UTC
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.

Comment 3 Darran Lofthouse 2014-05-16 14:34:37 UTC
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.

Comment 4 Darran Lofthouse 2014-05-16 14:56:24 UTC
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.

Comment 5 Martin Simka 2014-05-19 13:54:42 UTC
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

Comment 8 Martin Simka 2014-08-15 11:08:44 UTC
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

Comment 10 Darran Lofthouse 2014-11-04 15:56:52 UTC
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.

Comment 11 JBoss JIRA Server 2014-12-09 12:15:34 UTC
Kabir Khan <kabir.khan> updated the status of jira EAP6-217 to Resolved

Comment 12 JBoss JIRA Server 2015-04-28 15:04:19 UTC
John Doyle <jdoyle> updated the status of jira EAP6-217 to Closed

Comment 46 Carlo de Wolf 2015-08-21 07:13:23 UTC
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.

Comment 47 Carlo de Wolf 2015-08-21 07:15:00 UTC
As suggested by Derek Horton:
> Change:
>  
>   <security-domain name="SQLJDBC_KERBEROS" cache-type="default"> 
> 
> to this:
>  
>   <security-domain name="SQLJDBC_KERBEROS">

Comment 63 Martin Simka 2015-09-25 08:39:27 UTC
verified with EAP 6.4.4.CP.CR3

Comment 64 JBoss JIRA Server 2015-10-08 13:08:52 UTC
Martin Simka <msimka> updated the status of jira JBEAP-843 to Closed

Comment 65 Dave Sullivan 2015-10-28 16:41:21 UTC
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?

Comment 66 Petr Penicka 2017-01-17 10:49:54 UTC
Retroactively bulk-closing issues from released EAP 6.4 cumulative patches.

Comment 67 Petr Penicka 2017-01-17 10:50:47 UTC
Retroactively bulk-closing issues from released EAP 6.4 cumulative patches.