hc-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Oleg Kalnichevski (JIRA)" <j...@apache.org>
Subject [jira] Commented: (HTTPCORE-243) NPE in DefaultClientIOEventDispatch#inputReady
Date Mon, 29 Nov 2010 13:36:02 GMT

    [ https://issues.apache.org/jira/browse/HTTPCORE-243?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12964748#action_12964748
] 

Oleg Kalnichevski commented on HTTPCORE-243:
--------------------------------------------

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

> NPE in DefaultClientIOEventDispatch#inputReady
> ----------------------------------------------
>
>                 Key: HTTPCORE-243
>                 URL: https://issues.apache.org/jira/browse/HTTPCORE-243
>             Project: HttpComponents HttpCore
>          Issue Type: Bug
>          Components: HttpCore NIO
>    Affects Versions: 4.1
>         Environment: Linux 2.6.18-6-amd64,  Java 6 Update 21, 32bit
>            Reporter: Eric Hubert
>         Attachments: synapse_session_wire.log
>
>
> 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.

-- 
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.


---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@hc.apache.org
For additional commands, e-mail: dev-help@hc.apache.org


Mime
View raw message