[
https://issues.apache.org/jira/browse/CALCITE-1183?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Julian Hyde updated CALCITE-1183:
---------------------------------
Fix Version/s: (was: avatica-1.10.0)
avatica-1.11.0
> Sporadic AvaticaSpnegoTest failures with Checksum failed and HTTP 404
> ---------------------------------------------------------------------
>
> Key: CALCITE-1183
> URL: https://issues.apache.org/jira/browse/CALCITE-1183
> Project: Calcite
> Issue Type: Bug
> Components: avatica
> Reporter: Josh Elser
> Priority: Minor
> Fix For: avatica-1.11.0
>
>
> I'm noticing the following every now and again.
> {noformat}
> 2016-04-04 10:59:29,110 [main] INFO - Starting KDC server at localhost:62139
> 2016-04-04 10:59:29,281 [main] INFO - Creating client with keytab
> /Users/jelser/projects/calcite.git/avatica/server/target/AvaticaSpnegoTest_keytabs/client.keytab
> 2016-04-04 10:59:29,286 [main] INFO - Creating HTTP/[email protected]
> with keytab
> /Users/jelser/projects/calcite.git/avatica/server/target/AvaticaSpnegoTest_keytabs/HTTP_localhost.keytab
> 2016-04-04 10:59:29,368 [main] INFO - No metrics implementation available on
> classpath. Using No-op implementation
> 2016-04-04 10:59:29,385 [main] INFO - Logging initialized @618ms
> java.net.SocketTimeoutException: Accept timed out
> java.net.SocketTimeoutException: Accept timed out
> java.net.SocketTimeoutException: Accept timed out
> 2016-04-04 10:59:29,649 [main] INFO - jetty-9.2.15.v20160210
> 2016-04-04 10:59:29,682 [main] INFO - Started
> ServerConnector@11fa682c{HTTP/1.1}{0.0.0.0:62141}
> 2016-04-04 10:59:29,682 [main] INFO - Started @916ms
> 2016-04-04 10:59:29,682 [main] INFO - Service listening on port 62141.
> 2016-04-04 10:59:29,685 [main] INFO - JDBC URL
> jdbc:avatica:remote:url=http://localhost:62141;authentication=SPNEGO;serialization=JSON
> 2016-04-04 10:59:29,686 [main] INFO - No metrics implementation available on
> classpath. Using No-op implementation
> java.net.SocketTimeoutException: Accept timed out
> 2016-04-04 10:59:29,759 [main] INFO - jetty-9.2.15.v20160210
> 2016-04-04 10:59:29,772 [main] INFO - Started
> ServerConnector@5c80435f{HTTP/1.1}{0.0.0.0:62142}
> 2016-04-04 10:59:29,772 [main] INFO - Started @1006ms
> 2016-04-04 10:59:29,772 [main] INFO - Service listening on port 62142.
> 2016-04-04 10:59:29,772 [main] INFO - JDBC URL
> jdbc:avatica:remote:url=http://localhost:62142;authentication=SPNEGO;serialization=PROTOBUF
> 2016-04-04 10:59:29,787 [main] INFO - jetty-9.2.15.v20160210
> 2016-04-04 10:59:29,789 [main] INFO - Started
> ServerConnector@464d02ee{HTTP/1.1}{0.0.0.0:62143}
> 2016-04-04 10:59:29,789 [main] INFO - Started @1023ms
> 2016-04-04 10:59:29,789 [main] INFO - Service listening on port 62143.
> 2016-04-04 10:59:29,790 [main] INFO - jetty-9.2.15.v20160210
> 2016-04-04 10:59:29,791 [main] INFO - Started
> ServerConnector@3ff9f777{HTTP/1.1}{0.0.0.0:62144}
> 2016-04-04 10:59:29,792 [main] INFO - Started @1026ms
> 2016-04-04 10:59:29,792 [main] INFO - Service listening on port 62144.
> java.net.SocketTimeoutException: Accept timed out
> Running org.apache.calcite.avatica.AvaticaSpnegoTest
> 2016-04-04 10:59:29,837 [main] INFO - Starting KDC server at localhost:62146
> 2016-04-04 10:59:29,841 [main] INFO - Creating client with keytab
> /Users/jelser/projects/calcite.git/avatica/server/target/AvaticaSpnegoTest_keytabs/client.keytab
> 2016-04-04 10:59:29,842 [main] INFO - Creating HTTP/[email protected]
> with keytab
> /Users/jelser/projects/calcite.git/avatica/server/target/AvaticaSpnegoTest_keytabs/HTTP_localhost.keytab
> 2016-04-04 10:59:29,845 [main] INFO - No metrics implementation available on
> classpath. Using No-op implementation
> 2016-04-04 10:59:29,846 [main] INFO - jetty-9.2.15.v20160210
> 2016-04-04 10:59:29,847 [main] INFO - Started
> ServerConnector@4cf35c4f{HTTP/1.1}{0.0.0.0:62148}
> 2016-04-04 10:59:29,848 [main] INFO - Started @1082ms
> 2016-04-04 10:59:29,848 [main] INFO - Service listening on port 62148.
> 2016-04-04 10:59:29,848 [main] INFO - JDBC URL
> jdbc:avatica:remote:url=http://localhost:62148;authentication=SPNEGO;serialization=JSON
> 2016-04-04 10:59:29,848 [main] INFO - No metrics implementation available on
> classpath. Using No-op implementation
> 2016-04-04 10:59:29,849 [main] INFO - jetty-9.2.15.v20160210
> 2016-04-04 10:59:29,851 [main] INFO - Started
> ServerConnector@4be0b391{HTTP/1.1}{0.0.0.0:62149}
> 2016-04-04 10:59:29,851 [main] INFO - Started @1085ms
> 2016-04-04 10:59:29,851 [main] INFO - Service listening on port 62149.
> 2016-04-04 10:59:29,851 [main] INFO - JDBC URL
> jdbc:avatica:remote:url=http://localhost:62149;authentication=SPNEGO;serialization=PROTOBUF
> Debug is true storeKey true useTicketCache false useKeyTab true doNotPrompt
> true ticketCache is null isInitiator true KeyTab is
> /Users/jelser/projects/calcite.git/avatica/server/target/AvaticaSpnegoTest_keytabs/client.keytab
> refreshKrb5Config is true principal is [email protected] tryFirstPass is
> false useFirstPass is false storePass is false clearPass is false
> Refreshing Kerberos configuration
> 2016-04-04 10:59:29,872 [pool-2-thread-2] INFO - The preauth data is empty.
> 2016-04-04 10:59:29,875 [pool-2-thread-2] INFO - KRB error occurred while
> processing request:Additional pre-authentication required
> java.net.SocketTimeoutException: Accept timed out
> java.net.SocketTimeoutException: Accept timed out
> principal is [email protected]
> Will use keytab
> Commit Succeeded
> 2016-04-04 10:59:30,477 [qtp1255644396-56] WARN -
> GSSException: Failure unspecified at GSS-API level (Mechanism level: Checksum
> failed)
> at
> sun.security.jgss.krb5.Krb5Context.acceptSecContext(Krb5Context.java:788)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:342)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:285)
> at
> sun.security.jgss.spnego.SpNegoContext.GSS_acceptSecContext(SpNegoContext.java:875)
> at
> sun.security.jgss.spnego.SpNegoContext.acceptSecContext(SpNegoContext.java:548)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:342)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:285)
> at
> org.eclipse.jetty.security.SpnegoLoginService.login(SpnegoLoginService.java:137)
> at
> org.eclipse.jetty.security.authentication.LoginAuthenticator.login(LoginAuthenticator.java:61)
> at
> org.eclipse.jetty.security.authentication.SpnegoAuthenticator.validateRequest(SpnegoAuthenticator.java:99)
> at
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:512)
> at
> org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
> at
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
> at org.eclipse.jetty.server.Server.handle(Server.java:499)
> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
> at
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
> at
> org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: KrbException: Checksum failed
> at
> sun.security.krb5.internal.crypto.Aes128CtsHmacSha1EType.decrypt(Aes128CtsHmacSha1EType.java:102)
> at
> sun.security.krb5.internal.crypto.Aes128CtsHmacSha1EType.decrypt(Aes128CtsHmacSha1EType.java:94)
> at sun.security.krb5.EncryptedData.decrypt(EncryptedData.java:177)
> at sun.security.krb5.KrbApReq.authenticate(KrbApReq.java:278)
> at sun.security.krb5.KrbApReq.<init>(KrbApReq.java:144)
> at
> sun.security.jgss.krb5.InitSecContextToken.<init>(InitSecContextToken.java:108)
> at
> sun.security.jgss.krb5.Krb5Context.acceptSecContext(Krb5Context.java:771)
> ... 19 more
> Caused by: java.security.GeneralSecurityException: Checksum failed
> at
> sun.security.krb5.internal.crypto.dk.AesDkCrypto.decryptCTS(AesDkCrypto.java:451)
> at
> sun.security.krb5.internal.crypto.dk.AesDkCrypto.decrypt(AesDkCrypto.java:272)
> at sun.security.krb5.internal.crypto.Aes128.decrypt(Aes128.java:76)
> at
> sun.security.krb5.internal.crypto.Aes128CtsHmacSha1EType.decrypt(Aes128CtsHmacSha1EType.java:100)
> ... 25 more
> 2016-04-04 10:59:30,490 [main] INFO - Service terminating.
> 2016-04-04 10:59:30,493 [main] INFO - Stopped
> ServerConnector@4cf35c4f{HTTP/1.1}{0.0.0.0:0}
> Debug is true storeKey true useTicketCache false useKeyTab true doNotPrompt
> true ticketCache is null isInitiator true KeyTab is
> /Users/jelser/projects/calcite.git/avatica/server/target/AvaticaSpnegoTest_keytabs/client.keytab
> refreshKrb5Config is true principal is [email protected] tryFirstPass is
> false useFirstPass is false storePass is false clearPass is false
> Refreshing Kerberos configuration
> 2016-04-04 10:59:30,504 [pool-2-thread-2] INFO - The preauth data is empty.
> 2016-04-04 10:59:30,505 [pool-2-thread-2] INFO - KRB error occurred while
> processing request:Additional pre-authentication required
> principal is [email protected]
> Will use keytab
> Commit Succeeded
> java.net.SocketTimeoutException: Accept timed out
> 2016-04-04 10:59:30,554 [qtp942473782-65] WARN -
> GSSException: Failure unspecified at GSS-API level (Mechanism level: Checksum
> failed)
> at
> sun.security.jgss.krb5.Krb5Context.acceptSecContext(Krb5Context.java:788)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:342)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:285)
> at
> sun.security.jgss.spnego.SpNegoContext.GSS_acceptSecContext(SpNegoContext.java:875)
> at
> sun.security.jgss.spnego.SpNegoContext.acceptSecContext(SpNegoContext.java:548)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:342)
> at
> sun.security.jgss.GSSContextImpl.acceptSecContext(GSSContextImpl.java:285)
> at
> org.eclipse.jetty.security.SpnegoLoginService.login(SpnegoLoginService.java:137)
> at
> org.eclipse.jetty.security.authentication.LoginAuthenticator.login(LoginAuthenticator.java:61)
> at
> org.eclipse.jetty.security.authentication.SpnegoAuthenticator.validateRequest(SpnegoAuthenticator.java:99)
> at
> org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:512)
> at
> org.eclipse.jetty.server.handler.HandlerList.handle(HandlerList.java:52)
> at
> org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:97)
> at org.eclipse.jetty.server.Server.handle(Server.java:499)
> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:311)
> at
> org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:257)
> at
> org.eclipse.jetty.io.AbstractConnection$2.run(AbstractConnection.java:544)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:635)
> at
> org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:555)
> at java.lang.Thread.run(Thread.java:745)
> Caused by: KrbException: Checksum failed
> at
> sun.security.krb5.internal.crypto.Aes128CtsHmacSha1EType.decrypt(Aes128CtsHmacSha1EType.java:102)
> at
> sun.security.krb5.internal.crypto.Aes128CtsHmacSha1EType.decrypt(Aes128CtsHmacSha1EType.java:94)
> at sun.security.krb5.EncryptedData.decrypt(EncryptedData.java:177)
> at sun.security.krb5.KrbApReq.authenticate(KrbApReq.java:278)
> at sun.security.krb5.KrbApReq.<init>(KrbApReq.java:144)
> at
> sun.security.jgss.krb5.InitSecContextToken.<init>(InitSecContextToken.java:108)
> at
> sun.security.jgss.krb5.Krb5Context.acceptSecContext(Krb5Context.java:771)
> ... 19 more
> Caused by: java.security.GeneralSecurityException: Checksum failed
> at
> sun.security.krb5.internal.crypto.dk.AesDkCrypto.decryptCTS(AesDkCrypto.java:451)
> at
> sun.security.krb5.internal.crypto.dk.AesDkCrypto.decrypt(AesDkCrypto.java:272)
> at sun.security.krb5.internal.crypto.Aes128.decrypt(Aes128.java:76)
> at
> sun.security.krb5.internal.crypto.Aes128CtsHmacSha1EType.decrypt(Aes128CtsHmacSha1EType.java:100)
> ... 25 more
> 2016-04-04 10:59:30,555 [main] INFO - Service terminating.
> 2016-04-04 10:59:30,556 [main] INFO - Stopped
> ServerConnector@4be0b391{HTTP/1.1}{0.0.0.0:0}
> 2016-04-04 10:59:30,557 [main] INFO - Stopping KDC on 62146
> Tests run: 2, Failures: 0, Errors: 2, Skipped: 0, Time elapsed: 0.723 sec <<<
> FAILURE! - in org.apache.calcite.avatica.AvaticaSpnegoTest
> testAuthenticatedClient[0](org.apache.calcite.avatica.AvaticaSpnegoTest)
> Time elapsed: 0.646 sec <<< ERROR!
> java.lang.RuntimeException: Failed to execute HTTP Request, got HTTP/404
> at
> org.apache.calcite.avatica.remote.AvaticaCommonsHttpClientSpnegoImpl.send(AvaticaCommonsHttpClientSpnegoImpl.java:148)
> at
> org.apache.calcite.avatica.remote.RemoteService.apply(RemoteService.java:34)
> at
> org.apache.calcite.avatica.remote.JsonService.apply(JsonService.java:172)
> at org.apache.calcite.avatica.remote.Driver.connect(Driver.java:155)
> at java.sql.DriverManager.getConnection(DriverManager.java:571)
> at java.sql.DriverManager.getConnection(DriverManager.java:233)
> at
> org.apache.calcite.avatica.AvaticaSpnegoTest$1.run(AvaticaSpnegoTest.java:205)
> at
> org.apache.calcite.avatica.AvaticaSpnegoTest$1.run(AvaticaSpnegoTest.java:1)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:415)
> at
> org.apache.calcite.avatica.AvaticaSpnegoTest.testAuthenticatedClient(AvaticaSpnegoTest.java:203)
> testAuthenticatedClient[1](org.apache.calcite.avatica.AvaticaSpnegoTest)
> Time elapsed: 0.056 sec <<< ERROR!
> java.lang.RuntimeException: Failed to execute HTTP Request, got HTTP/404
> at
> org.apache.calcite.avatica.remote.AvaticaCommonsHttpClientSpnegoImpl.send(AvaticaCommonsHttpClientSpnegoImpl.java:148)
> at
> org.apache.calcite.avatica.remote.RemoteProtobufService._apply(RemoteProtobufService.java:44)
> at
> org.apache.calcite.avatica.remote.ProtobufService.apply(ProtobufService.java:81)
> at org.apache.calcite.avatica.remote.Driver.connect(Driver.java:155)
> at java.sql.DriverManager.getConnection(DriverManager.java:571)
> at java.sql.DriverManager.getConnection(DriverManager.java:233)
> at
> org.apache.calcite.avatica.AvaticaSpnegoTest$1.run(AvaticaSpnegoTest.java:205)
> at
> org.apache.calcite.avatica.AvaticaSpnegoTest$1.run(AvaticaSpnegoTest.java:1)
> at java.security.AccessController.doPrivileged(Native Method)
> at javax.security.auth.Subject.doAs(Subject.java:415)
> at
> org.apache.calcite.avatica.AvaticaSpnegoTest.testAuthenticatedClient(AvaticaSpnegoTest.java:203)
> {noformat}
> For some reason, AvaticaSpnegoTest seems to be having trouble authenticating
> the client's Kerberos identity (I think). Given that this only happens now
> and again, I'm thinking that maybe it's related to the in-memory KDC
> implementation we're using for tests. We should try to get it figured out
> before it starts causing test failures.
--
This message was sent by Atlassian JIRA
(v6.3.15#6346)
