Josh Elser created CALCITE-1183:
-----------------------------------
Summary: 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
Assignee: Julian Hyde
Priority: Minor
Fix For: avatica-1.8.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.4#6332)
