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

Sporadic AvaticaSpnegoTest failures with Checksum failed and HTTP 404

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: avatica-1.13.0
    • Component/s: avatica
    • Labels:
      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

            Activity

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved: