calcite-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Josh Elser (JIRA)" <j...@apache.org>
Subject [jira] [Created] (CALCITE-1183) Sporadic AvaticaSpnegoTest failures with Checksum failed and HTTP 404
Date Mon, 04 Apr 2016 15:04:25 GMT
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/localhost@EXAMPLE.COM 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/localhost@EXAMPLE.COM 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 client@EXAMPLE.COM 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 client@EXAMPLE.COM
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 client@EXAMPLE.COM 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 client@EXAMPLE.COM
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)

Mime
View raw message