You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@calcite.apache.org by "Francis Chuang (JIRA)" <ji...@apache.org> on 2018/06/26 00:57:01 UTC
[jira] [Updated] (CALCITE-1183) Sporadic AvaticaSpnegoTest failures
with Checksum failed and HTTP 404
[ https://issues.apache.org/jira/browse/CALCITE-1183?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Francis Chuang updated CALCITE-1183:
------------------------------------
Fix Version/s: (was: avatica-1.12.0)
avatica-1.13.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.13.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
(v7.6.3#76005)