HttpComponents HttpCore
  1. HttpComponents HttpCore
  2. HTTPCORE-243

NPE in DefaultClientIOEventDispatch#inputReady

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 4.1
    • Fix Version/s: 4.1.1
    • Component/s: HttpCore NIO
    • Labels:
      None
    • Environment:
      Linux 2.6.18-6-amd64, Java 6 Update 21, 32bit

      Description

      While using Synapse 1.2 with httpcore-nio 4.1 the following exceptions occurs

      WARN 2010-11-27 23:55:07,737 [http-Sender I/O dispatcher-1][][] org.apache.synapse.transport.nhttp.HttpCoreNIOSender 'System may be unstable: IOReactor encountered a runtime exception : null'
      java.lang.NullPointerException
      at org.apache.http.impl.nio.DefaultClientIOEventDispatch.inputReady(DefaultClientIOEventDispatch.java:148)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:161)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:335)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:275)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
      at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:542)
      at java.lang.Thread.run(Thread.java:619)
      FATAL 2010-11-27 23:55:08,678 [HttpCoreNIOSender][][] org.apache.synapse.transport.nhttp.HttpCoreNIOSender 'Encountered an I/O error: I/O dispatch worker terminated abnormally'
      org.apache.http.nio.reactor.IOReactorException: I/O dispatch worker terminated abnormally
      at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.execute(AbstractMultiworkerIOReactor.java:324)
      at org.apache.synapse.transport.nhttp.HttpCoreNIOSender.executeClientEngine(HttpCoreNIOSender.java:188)
      at org.apache.synapse.transport.nhttp.HttpCoreNIOSender.access$000(HttpCoreNIOSender.java:77)
      at org.apache.synapse.transport.nhttp.HttpCoreNIOSender$3.run(HttpCoreNIOSender.java:209)
      at java.lang.Thread.run(Thread.java:619)
      Caused by: java.lang.NullPointerException
      at org.apache.http.impl.nio.DefaultClientIOEventDispatch.inputReady(DefaultClientIOEventDispatch.java:148)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.readable(BaseIOReactor.java:161)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvent(AbstractIOReactor.java:335)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.processEvents(AbstractIOReactor.java:315)
      at org.apache.http.impl.nio.reactor.AbstractIOReactor.execute(AbstractIOReactor.java:275)
      at org.apache.http.impl.nio.reactor.BaseIOReactor.execute(BaseIOReactor.java:104)
      at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor$Worker.run(AbstractMultiworkerIOReactor.java:542)
      ... 1 more

      I will give my best to provide a wire log later on.

        Activity

        Hide
        Supun Kamburugamuva added a comment -

        It seems this is an intermittent issue. I'm getting the error randomly.

        Thanks,
        Supun..

        Show
        Supun Kamburugamuva added a comment - It seems this is an intermittent issue. I'm getting the error randomly. Thanks, Supun..
        Hide
        Eric Hubert added a comment -

        I now tested on multiple machines. I was not able to reproduce the issue on fast physical hardware. On a rather slow virtualized environment I can reproduce the issue at will.

        Show
        Eric Hubert added a comment - I now tested on multiple machines. I was not able to reproduce the issue on fast physical hardware. On a rather slow virtualized environment I can reproduce the issue at will.
        Hide
        Eric Hubert added a comment -

        Please find attached a log output of a test case to reproduce the issue.

        Show
        Eric Hubert added a comment - Please find attached a log output of a test case to reproduce the issue.
        Hide
        Eric Hubert added a comment -

        I guess the first log did not contain enough output from the session. This time I included more lines before the issue occured.

        Show
        Eric Hubert added a comment - I guess the first log did not contain enough output from the session. This time I included more lines before the issue occured.
        Hide
        Oleg Kalnichevski added a comment -

        Eric

        I think I found the cause of the problem. Here's the relevant bits of the log

        45:38,737 [dispatcher-2] DefaultNHttpClientConnection 'Consume input'
        45:38,737 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: 725 bytes read'
        45:38,737 [dispatcher-2] wire '>> "HTTP/1.1 200 OK[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "Server: Apache-Coyote/1.1[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "xxx"'
        45:38,737 [dispatcher-2] wire '>> "Content-Type: text/xml;charset=UTF-8[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "Transfer-Encoding: chunked[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "Date: Mon, 29 Nov 2010 10:45:38 GMT[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "1c0[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" ...
        45:38,737 [dispatcher-2] wire '>> "0[\r][\n]"'
        45:38,737 [dispatcher-2] wire '>> "[\r][\n]"'
        45:38,737 [dispatcher-2] ClientHandler 'HTTP connection [<hostname>/xx.xx.xx.xx:50103] : HTTP/1.1 200 OK [Request Message ID : urn:uuid:1CD35CE531BE8D787A22035167021095501-526448396]'
        45:38,738 [dispatcher-2] ClientHandler 'Response Received for Request : Axis2Request [Message ID : urn:uuid:1CD35CE531BE8D787A22035167021095501-526448396] [Status Completed : true] [Status SendingCompleted : true]'
        45:38,738 [dispatcher-2] NHttpConfiguration 'Using nhttp tuning parameter : nhttp_buffer_size = 8192'
        45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Set attribute synapse.response-sink-buffer'
        45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Set attribute http.response'
        45:38,738 [dispatcher-2] ClientHandler 'HTTP connection [<hostname>/xx.xx.xx.xx:50103]: Input ready [Request Message ID : urn:uuid:1CD35CE531BE8D787A22035167021095501-526448396]'
        45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: 0 bytes read'
        45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: 0 bytes read'
        45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: 0 bytes read'
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute synapse.axis2-http-request'
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute synapse.axis2_message_context'
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute synapse.request-source-buffer'
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute synapse.response-sink-buffer'
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute http.request'
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute http.response'
        >>> ----------------------------------------- trouble!!!! -------------------------------
        45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r]; ready ops: [r]]: Remove attribute http.connection'
        >>> ----------------------------------------- trouble!!!! -------------------------------
        45:38,739 [dispatcher-2] ConnectionPool 'Released a connection to host: <hostname> on port : 50103 to the connection pool of current size : 1'
        45:38,739 [dispatcher-2] ClientHandler 'HTTP connection [<hostname>/xx.xx.xx.xx:50103]: Content decoder [chunk-coded; completed: true]'
        >>> ----------- Big kaboom ---------------
        45:58,736 [dispatcher-2] HttpCoreNIOSender 'System may be unstable: IOReactor encountered a runtime exception : null'

        So, the response from the origin server gets correctly processed. All is nice and dandy. The connection is kept alive and returned to the connection pool. The trouble is that for some reason the Synapse's NHTTP transport code removes the 'http.connection' attribute from the I/O session context. As a result the I/O session loses all its HTTP protocol state. In 20 seconds the origin server closes the connection on its end. The I/O reactor on the opposite wakes up and fires #inputReady event for that session. DefaultClientIOEventDispatch assumes the I/O session always contains a valid HTTP connection object and causes a NPE by trying to invoke a method on a null HTTP connection instance.

        Supun

        What is the reason Synapse removes ' http.connection' attribute from the I/O session?

        I'll tweak HttpCore to throw a different type of exception (IllegalStateException most probably) but fundamentally the issue is caused by the Synapse NHTTP transport code.

        Oleg

        Show
        Oleg Kalnichevski added a comment - Eric I think I found the cause of the problem. Here's the relevant bits of the log — 45:38,737 [dispatcher-2] DefaultNHttpClientConnection 'Consume input' 45:38,737 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: 725 bytes read' 45:38,737 [dispatcher-2] wire '>> "HTTP/1.1 200 OK [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> "Server: Apache-Coyote/1.1 [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> "xxx"' 45:38,737 [dispatcher-2] wire '>> "Content-Type: text/xml;charset=UTF-8 [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> "Transfer-Encoding: chunked [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> "Date: Mon, 29 Nov 2010 10:45:38 GMT [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> " [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> "1c0 [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> "<soap:Envelope xmlns:soap="http://schemas.xmlsoap.org/soap/envelope/" ... 45:38,737 [dispatcher-2] wire '>> "0 [\r] [\n] "' 45:38,737 [dispatcher-2] wire '>> " [\r] [\n] "' 45:38,737 [dispatcher-2] ClientHandler 'HTTP connection [<hostname>/xx.xx.xx.xx:50103] : HTTP/1.1 200 OK [Request Message ID : urn:uuid:1CD35CE531BE8D787A22035167021095501-526448396] ' 45:38,738 [dispatcher-2] ClientHandler 'Response Received for Request : Axis2Request [Message ID : urn:uuid:1CD35CE531BE8D787A22035167021095501-526448396] [Status Completed : true] [Status SendingCompleted : true] ' 45:38,738 [dispatcher-2] NHttpConfiguration 'Using nhttp tuning parameter : nhttp_buffer_size = 8192' 45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Set attribute synapse.response-sink-buffer' 45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Set attribute http.response' 45:38,738 [dispatcher-2] ClientHandler 'HTTP connection [<hostname>/xx.xx.xx.xx:50103] : Input ready [Request Message ID : urn:uuid:1CD35CE531BE8D787A22035167021095501-526448396] ' 45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: 0 bytes read' 45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: 0 bytes read' 45:38,738 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: 0 bytes read' 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute synapse.axis2-http-request' 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute synapse.axis2_message_context' 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute synapse.request-source-buffer' 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute synapse.response-sink-buffer' 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute http.request' 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute http.response' >>> ----------------------------------------- trouble!!!! ------------------------------- 45:38,739 [dispatcher-2] IOSessionImpl 'I/O session client-15 [interested ops: [r] ; ready ops: [r] ]: Remove attribute http.connection' >>> ----------------------------------------- trouble!!!! ------------------------------- 45:38,739 [dispatcher-2] ConnectionPool 'Released a connection to host: <hostname> on port : 50103 to the connection pool of current size : 1' 45:38,739 [dispatcher-2] ClientHandler 'HTTP connection [<hostname>/xx.xx.xx.xx:50103] : Content decoder [chunk-coded; completed: true] ' >>> ----------- Big kaboom --------------- 45:58,736 [dispatcher-2] HttpCoreNIOSender 'System may be unstable: IOReactor encountered a runtime exception : null' — So, the response from the origin server gets correctly processed. All is nice and dandy. The connection is kept alive and returned to the connection pool. The trouble is that for some reason the Synapse's NHTTP transport code removes the 'http.connection' attribute from the I/O session context. As a result the I/O session loses all its HTTP protocol state. In 20 seconds the origin server closes the connection on its end. The I/O reactor on the opposite wakes up and fires #inputReady event for that session. DefaultClientIOEventDispatch assumes the I/O session always contains a valid HTTP connection object and causes a NPE by trying to invoke a method on a null HTTP connection instance. Supun What is the reason Synapse removes ' http.connection' attribute from the I/O session? I'll tweak HttpCore to throw a different type of exception (IllegalStateException most probably) but fundamentally the issue is caused by the Synapse NHTTP transport code. Oleg
        Hide
        Eric Hubert added a comment -

        Oleg,
        your analysis sound very reasonable to me. There is only one detail which still confuses me. Why does this issue suddenly occur after upgrading from http-core 4.0 beta2 to http-core 4.1 without any change in the Synapse code? Has there been some change in http-core 4.1 bringing this issue up?

        Show
        Eric Hubert added a comment - Oleg, your analysis sound very reasonable to me. There is only one detail which still confuses me. Why does this issue suddenly occur after upgrading from http-core 4.0 beta2 to http-core 4.1 without any change in the Synapse code? Has there been some change in http-core 4.1 bringing this issue up?
        Hide
        Oleg Kalnichevski added a comment -

        Synchronisation code in the IOSessionImpl changed quite a bit and this must have trigged some kind of race condition in HttpCore / NHTTP stack, which was previously undetected. The usual delights of the non-blocking I/O model.

        I think all that needs to be done to fix the problem is to tweak the Synapse code to retain the 'http.connection' attribute in the session context.

        Oleg

        Show
        Oleg Kalnichevski added a comment - Synchronisation code in the IOSessionImpl changed quite a bit and this must have trigged some kind of race condition in HttpCore / NHTTP stack, which was previously undetected. The usual delights of the non-blocking I/O model. I think all that needs to be done to fix the problem is to tweak the Synapse code to retain the 'http.connection' attribute in the session context. Oleg
        Hide
        Eric Hubert added a comment -

        Many thanks Oleg. I think an IllegalStateException would be perfectly fine and suitable.

        OFFTOPIC:

        I see. It looks like the change has already been done for Synapse on trunk.
        Following your hints I checked

        org.apache.synapse.transport.nhttp.ConnectionPool#release
        --> org.apache.synapse.transport.nhttp.ConnectionPool#cleanConnectionReferences

        on 1.2 branch:
        ...
        ctx.removeAttribute(ExecutionContext.HTTP_REQUEST);
        ctx.removeAttribute(ExecutionContext.HTTP_RESPONSE);
        ctx.removeAttribute(ExecutionContext.HTTP_CONNECTION);

        on trunk:
        ...
        ctx.removeAttribute(ExecutionContext.HTTP_REQUEST);
        ctx.removeAttribute(ExecutionContext.HTTP_RESPONSE);

        So the connection attribute will no longer be removed for released persistent connections.

        Checking the svn log it looks like Ruwan did the change quite some time ago.
        Revision: 823049
        Author: ruwan
        Date: 08:03:22, Donnerstag, 8. Oktober 2009
        Message:
        Fixing the build issue on trunk

        Show
        Eric Hubert added a comment - Many thanks Oleg. I think an IllegalStateException would be perfectly fine and suitable. OFFTOPIC: I see. It looks like the change has already been done for Synapse on trunk. Following your hints I checked org.apache.synapse.transport.nhttp.ConnectionPool#release --> org.apache.synapse.transport.nhttp.ConnectionPool#cleanConnectionReferences on 1.2 branch: ... ctx.removeAttribute(ExecutionContext.HTTP_REQUEST); ctx.removeAttribute(ExecutionContext.HTTP_RESPONSE); ctx.removeAttribute(ExecutionContext.HTTP_CONNECTION); on trunk: ... ctx.removeAttribute(ExecutionContext.HTTP_REQUEST); ctx.removeAttribute(ExecutionContext.HTTP_RESPONSE); So the connection attribute will no longer be removed for released persistent connections. Checking the svn log it looks like Ruwan did the change quite some time ago. Revision: 823049 Author: ruwan Date: 08:03:22, Donnerstag, 8. Oktober 2009 Message: Fixing the build issue on trunk
        Hide
        Oleg Kalnichevski added a comment -

        Fixed in SVN trunk.

        Oleg

        Show
        Oleg Kalnichevski added a comment - Fixed in SVN trunk. Oleg
        Hide
        Eric Hubert added a comment -

        Verified change on trunk which now throws IllegalStateException at several places where a set connection is mandatory.

        For the record: Oleg's analysis has been correct. Once Synapse does not remove the connection attribute from the context while releasing persistent connections the problem does not occur. Synapse trunk already correctly handles this situation.

        Show
        Eric Hubert added a comment - Verified change on trunk which now throws IllegalStateException at several places where a set connection is mandatory. For the record: Oleg's analysis has been correct. Once Synapse does not remove the connection attribute from the context while releasing persistent connections the problem does not occur. Synapse trunk already correctly handles this situation.

          People

          • Assignee:
            Unassigned
            Reporter:
            Eric Hubert
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development