Uploaded image for project: 'Calcite'
  1. Calcite
  2. CALCITE-1183

Sporadic AvaticaSpnegoTest failures with Checksum failed and HTTP 404

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Closed
    • Minor
    • Resolution: Fixed
    • None
    • avatica-1.13.0
    • avatica
    • None

    Description

      I'm noticing the following every now and again.

      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)

      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.

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. CALCITE-1226 Disable AvaticaSpnegoTest due to intermittent failures

          • Major - Major loss of function.
          • Closed
          links to

          Web Link GitHub Pull Request #69

          Activity

            People

              krisden Kevin Risden
              elserj Josh Elser
              Votes:
              1 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: