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

Avatica server responds with HTTP/401 prior to consuming all data written by client

    XMLWordPrintableJSON

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Critical
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: avatica-1.18.0
    • Component/s: avatica
    • Labels:
      None

      Description

      First off, big thanks to Kevin Risden for pointing me to HIVE-22231 which was the similar problem on the Hive side.

      Symptoms: the client, when sending a large HTTP request to the Avatica server which is configured for SPNEGO authentication, e.g. an ExecuteBatchRequest with 100's to 1000's of rows to execute, will receive an HTTP/401 response as a part of the normal SPNEGO negotiation (described in https://tools.ietf.org/html/rfc4559#section-5). The client will observe an error similar to the following, indicate "Broken pipe".

      2020-08-24 17:21:54,512 DEBUG http.wire: http-outgoing-1 >> "[write] I/O error: Broken pipe (Write failed)"
      2020-08-24 17:21:54,512 DEBUG conn.DefaultManagedHttpClientConnection: http-outgoing-1: Close connection
      2020-08-24 17:21:54,512 DEBUG conn.DefaultManagedHttpClientConnection: http-outgoing-1: Shutdown connection
      2020-08-24 17:21:54,512 DEBUG execchain.MainClientExec: Connection discarded
      2020-08-24 17:21:54,512 DEBUG conn.PoolingHttpClientConnectionManager: Connection released: [id: 1][route: {}->http://avatica-server:8765][total kept alive: 0; route allocated: 0 of 25; total allocated: 0 of 100]
      2020-08-24 17:21:54,512 INFO execchain.RetryExec: I/O exception (java.net.SocketException) caught when processing request to {}->http://avatica-server:8765: Broken pipe (Write failed)
      2020-08-24 17:21:54,512 DEBUG execchain.RetryExec: Broken pipe (Write failed)
      java.net.SocketException: Broken pipe (Write failed)
              at java.net.SocketOutputStream.socketWrite0(Native Method)
              at java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:111)
              at java.net.SocketOutputStream.write(SocketOutputStream.java:155)
              at org.apache.calcite.avatica.org.apache.http.impl.conn.LoggingOutputStream.write(LoggingOutputStream.java:74)
              at org.apache.calcite.avatica.org.apache.http.impl.io.SessionOutputBufferImpl.streamWrite(SessionOutputBufferImpl.java:124)
              at org.apache.calcite.avatica.org.apache.http.impl.io.SessionOutputBufferImpl.write(SessionOutputBufferImpl.java:160)
              at org.apache.calcite.avatica.org.apache.http.impl.io.ContentLengthOutputStream.write(ContentLengthOutputStream.java:113)
              at org.apache.calcite.avatica.org.apache.http.entity.ByteArrayEntity.writeTo(ByteArrayEntity.java:112)
              at org.apache.calcite.avatica.org.apache.http.impl.DefaultBHttpClientConnection.sendRequestEntity(DefaultBHttpClientConnection.java:156)
              at org.apache.calcite.avatica.org.apache.http.impl.conn.CPoolProxy.sendRequestEntity(CPoolProxy.java:152)
              at org.apache.calcite.avatica.org.apache.http.protocol.HttpRequestExecutor.doSendRequest(HttpRequestExecutor.java:238)
              at org.apache.calcite.avatica.org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:123)
              at org.apache.calcite.avatica.org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
              at org.apache.calcite.avatica.org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
              at org.apache.calcite.avatica.org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
              at org.apache.calcite.avatica.org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
              at org.apache.calcite.avatica.org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
              at org.apache.calcite.avatica.org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
              at org.apache.calcite.avatica.remote.AvaticaCommonsHttpClientSpnegoImpl.send(AvaticaCommonsHttpClientSpnegoImpl.java:129)
              at org.apache.calcite.avatica.remote.DoAsAvaticaHttpClient$1.run(DoAsAvaticaHttpClient.java:39)
              at org.apache.calcite.avatica.remote.DoAsAvaticaHttpClient$1.run(DoAsAvaticaHttpClient.java:37)
              at java.security.AccessController.doPrivileged(Native Method)
              at javax.security.auth.Subject.doAs(Subject.java:360)
              at org.apache.calcite.avatica.remote.DoAsAvaticaHttpClient.send(DoAsAvaticaHttpClient.java:37)
              at org.apache.calcite.avatica.remote.RemoteProtobufService._apply(RemoteProtobufService.java:44)
              at org.apache.calcite.avatica.remote.ProtobufService.apply(ProtobufService.java:117)
              at org.apache.calcite.avatica.remote.RemoteMeta$20.call(RemoteMeta.java:430)
              at org.apache.calcite.avatica.remote.RemoteMeta$20.call(RemoteMeta.java:427)
              at org.apache.calcite.avatica.AvaticaConnection.invokeWithRetries(AvaticaConnection.java:793)
              at org.apache.calcite.avatica.remote.RemoteMeta.executeBatch(RemoteMeta.java:427)
              at org.apache.calcite.avatica.AvaticaConnection.executeBatchUpdateInternal(AvaticaConnection.java:593)
              at org.apache.calcite.avatica.AvaticaPreparedStatement.executeLargeBatch(AvaticaPreparedStatement.java:266)
              at org.apache.calcite.avatica.AvaticaPreparedStatement.executeBatch(AvaticaPreparedStatement.java:259)
              at TestThinClient.main(TestThinClient.java:62) 

      What happens: as a result of how Jetty operates, the request will be dispatched into the Avatica Handler classes before all of the data has been read off of the wire. Jetty will notice that the request does not come with the WWW-Authenticate challenge response, so it will immediately trigger the code to respond to the client and begin the handshake process.

      Why Avatica/Jetty do this, the client is still in the process of sending the data over the wire, but Avatica/Jetty is "done" processing this request and closes the socket. As the client continues to write the rest of the data (for the request which Avatica has already responded to with HTTP/401), Jetty will send back a TCP reset and close the socket.

      The result is that the client sees an exception like above. Again, note, this will only happen with SPNEGO being enabled. It would not happen for no authentication or Basic/Digest authentication.

      All this considered, the solution is simple: read all of the data the client is sending prior to replying back with the HTTP/401.

        Attachments

          Issue Links

            Activity

              People

              • Assignee:
                elserj Josh Elser
                Reporter:
                elserj Josh Elser
              • Votes:
                0 Vote for this issue
                Watchers:
                5 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 1h 10m
                  1h 10m