0004545: NPE under load test in error handling of HttpRequest.handleRequest

Viewing Issue Advanced Details [ Jump to Notes ]

[ View Simple ] [ Issue History ] [ Print ]

Category

Severity

Reproducibility

Date Submitted

Last Update

0004545

[Resin]

minor

always

05-12-11 17:44

05-19-11 14:18

Reporter

rickHigh

View Status

public

Assigned To

ferg

Priority

normal

Resolution

fixed

Platform

Status

closed

Projection

none

OS Version

ETA

none

Fixed in Version

4.0.19

Product Version

4.0.14

Product Build

Summary

0004545: NPE under load test in error handling of HttpRequest.handleRequest

Description

NPE under load test in error handling of HttpRequest.handleRequest.

[11-05-12 11:57:17.426] {http://*:80-31780} [^] java.lang.NullPointerException
                                                at com.caucho.server.http.HttpServletRequestImpl.finishInvocation(HttpServletRequestImpl.java:1787)
                                                at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:205)
                                                at com.caucho.server.cache.ProxyCacheFilterChain.doFilter(ProxyCacheFilterChain.java:148)
                                                at com.caucho.server.webapp.AccessLogFilterChain.doFilter(AccessLogFilterChain.java:95)
                                                at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:287)
                                                at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:792)
                                                at com.caucho.network.listen.TcpSocketLink.dispatchRequest(TcpSocketLink.java:723)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequest(TcpSocketLink.java:685)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequestsImpl(TcpSocketLink.java:665)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequests(TcpSocketLink.java:613)
                                                at com.caucho.network.listen.AcceptTask.doTask(AcceptTask.java:104)
                                                at com.caucho.network.listen.ConnectionReadTask.runThread(ConnectionReadTask.java:98)
                                                at com.caucho.network.listen.ConnectionReadTask.run(ConnectionReadTask.java:81)
                                                at com.caucho.network.listen.AcceptTask.run(AcceptTask.java:67)
                                                at com.caucho.env.thread.ResinThread.runTasks(ResinThread.java:164)
                                                at com.caucho.env.thread.ResinThread.run(ResinThread.java:130)
[11-05-12 11:57:17.426] {http://*:80-31780} [^] TcpSocketLink[id=31780,web-entry-1] java.lang.NullPointerException
                                            java.lang.NullPointerException
                                                at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:801)
                                                at com.caucho.network.listen.TcpSocketLink.dispatchRequest(TcpSocketLink.java:723)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequest(TcpSocketLink.java:685)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequestsImpl(TcpSocketLink.java:665)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequests(TcpSocketLink.java:613)
                                                at com.caucho.network.listen.AcceptTask.doTask(AcceptTask.java:104)
                                                at com.caucho.network.listen.ConnectionReadTask.runThread(ConnectionReadTask.java:98)
                                                at com.caucho.network.listen.ConnectionReadTask.run(ConnectionReadTask.java:81)
                                                at com.caucho.network.listen.AcceptTask.run(AcceptTask.java:67)

The error is an NPE in the error handling code for a request.

@Override
public boolean handleRequest()
   throws IOException
{
   boolean isInvocation = false;

  ...

   try {
     thread.setContextClassLoader(server.getClassLoader());

     startRequest(server.allocateHttpBuffer());

      ...

   }
  catch (ClientDisconnectException e) {
    ...
    throw e;
   } catch (Throwable e) {
     log.log(Level.FINE, e.toString(), e);

     getResponseFacade().killCache(); //NPE happens here I think <------------------------------------------------------------------------------------------------ Here
     killKeepalive();

     sendRequestError(e);

     return false;
   } finally {
...

Requested them to turn up logging. And try latest version as this might be a fixed issue.
They are going to use 4.0.18 and turn up logging.

Steps To Reproduce

Additional Information

[11-05-12 11:57:17.422] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7912
[11-05-12 11:57:17.422] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.422] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(38)
[11-05-12 11:57:17.422] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 280
[11-05-12 11:57:17.422] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7906
[11-05-12 11:57:17.422] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.422] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(40)
[11-05-12 11:57:17.422] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 286
[11-05-12 11:57:17.422] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7900
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(42)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 292
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7894
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(44)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 298
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7888
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(46)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 304
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7882
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(48)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 310
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7876
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(50)
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 316
[11-05-12 11:57:17.423] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 7870
[11-05-12 11:57:17.425] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-next-buffer(8184)
[11-05-12 11:57:17.425] {http://*:80-31780} [^] Http[web-entry-1, 31780] write-set-offset(52)
[11-05-12 11:57:17.425] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 322
[11-05-12 11:57:17.425] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] D: 395
[11-05-12 11:57:17.425] {http://*:80-31780} [^] load balance [web-entry-1->qa1:46] Q (keepalive)
[11-05-12 11:57:17.426] {http://*:80-31780} [^] java.lang.NullPointerException
                                                at com.caucho.server.http.HttpServletRequestImpl.finishInvocation(HttpServletRequestImpl.java:1787)
                                                at com.caucho.server.webapp.WebAppFilterChain.doFilter(WebAppFilterChain.java:205)
                                                at com.caucho.server.cache.ProxyCacheFilterChain.doFilter(ProxyCacheFilterChain.java:148)
                                                at com.caucho.server.webapp.AccessLogFilterChain.doFilter(AccessLogFilterChain.java:95)
                                                at com.caucho.server.dispatch.ServletInvocation.service(ServletInvocation.java:287)
                                                at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:792)
                                                at com.caucho.network.listen.TcpSocketLink.dispatchRequest(TcpSocketLink.java:723)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequest(TcpSocketLink.java:685)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequestsImpl(TcpSocketLink.java:665)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequests(TcpSocketLink.java:613)
                                                at com.caucho.network.listen.AcceptTask.doTask(AcceptTask.java:104)
                                                at com.caucho.network.listen.ConnectionReadTask.runThread(ConnectionReadTask.java:98)
                                                at com.caucho.network.listen.ConnectionReadTask.run(ConnectionReadTask.java:81)
                                                at com.caucho.network.listen.AcceptTask.run(AcceptTask.java:67)
                                                at com.caucho.env.thread.ResinThread.runTasks(ResinThread.java:164)
                                                at com.caucho.env.thread.ResinThread.run(ResinThread.java:130)
[11-05-12 11:57:17.426] {http://*:80-31780} [^] TcpSocketLink[id=31780,web-entry-1] java.lang.NullPointerException
                                            java.lang.NullPointerException
                                                at com.caucho.server.http.HttpRequest.handleRequest(HttpRequest.java:801)
                                                at com.caucho.network.listen.TcpSocketLink.dispatchRequest(TcpSocketLink.java:723)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequest(TcpSocketLink.java:685)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequestsImpl(TcpSocketLink.java:665)
                                                at com.caucho.network.listen.TcpSocketLink.handleRequests(TcpSocketLink.java:613)
                                                at com.caucho.network.listen.AcceptTask.doTask(AcceptTask.java:104)
                                                at com.caucho.network.listen.ConnectionReadTask.runThread(ConnectionReadTask.java:98)
                                                at com.caucho.network.listen.ConnectionReadTask.run(ConnectionReadTask.java:81)
                                                at com.caucho.network.listen.AcceptTask.run(AcceptTask.java:67)
                                                at com.caucho.env.thread.ResinThread.runTasks(ResinThread.java:164)
                                                at com.caucho.env.thread.ResinThread.run(ResinThread.java:130)
[11-05-12 11:57:17.497] {http://*:80-31783} [^] TcpSocketLink[id=31783,web-entry-1] starting connection TcpSocketLink[id=http://*:80-31783,http://*:80,ACCEPT], [^] total=-31767
[11-05-12 11:57:17.497] {http://*:80-31783} [^] TcpSocketLink[id=http://*:80-31783,http://*:80,ACCEPT] [^] accept
[11-05-12 11:57:17.498] {http://*:80-31784} [^] TcpSocketLink[id=http://*:80-31784,http://*:80,INIT] [^] starting listen thread
[11-05-12 11:57:17.498] {http://*:80-31783} [^] Http[web-entry-1, 31783] GET /home-garden HTTP/1.1
[11-05-12 11:57:17.498] {http://*:80-31783} [^] Http[web-entry-1, 31783] Remote-IP: 76.8.64.130:62586
[11-05-12 11:57:17.498] {http://*:80-31783} [^] Http[web-entry-1, 31783] User-Agent: Java/1.6.0_13
[11-05-12 11:57:17.499] {http://*:80-31783} [^] Http[web-entry-1, 31783] Host: qa.uncommongoods.com
[11-05-12 11:57:17.499] {http://*:80-31783} [^] Http[web-entry-1, 31783] Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
[11-05-12 11:57:17.499] {http://*:80-31783} [^] Http[web-entry-1, 31783] Connection: keep-alive
[11-05-12 11:57:17.499] {http://*:80-31783} [^] Dispatch '/home-garden' to AccessLogFilterChain[http://localhost:80, [^] next=ProxyCacheFilterChain[/home-garden?null, next=WebAppFilterChain[http://localhost:80, [^] next=com.caucho.rewrite.LoadBalance$LoadBalanceFilterChain@382b7bd9]]]
[11-05-12 11:57:17.499] {http://*:80-31783} [^] load balance cost: 4.32482140154676 conn:3 cpu:0.0 latency:132.482140154676 ClientSocketFactory[web-entry-1->qa1,192.168.3.84:6800]
[11-05-12 11:57:17.499] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] URL /home-garden
[11-05-12 11:57:17.499] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] User-Agent: Java/1.6.0_13
[11-05-12 11:57:17.499] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] Host: qa.uncommongoods.com
[11-05-12 11:57:17.499] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] Accept: text/html, image/gif, image/jpeg, *; q=.2, */*; q=.2
[11-05-12 11:57:17.499] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] Connection: keep-alive
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] 200 OK
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] Cache-Control:private
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] M cpu-load:0
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] Set-Cookie:JSESSIONID=baaxHPDr_9Yal58us7K-s; path=/
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] unknown code 'G' 0x47 length=0
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] D: 8080
[11-05-12 11:57:17.501] {http://*:80-31783} [^] Http[web-entry-1, 31783] HTTP/1.1 200 OK
[11-05-12 11:57:17.501] {http://*:80-31783} [^] Http[web-entry-1, 31783] Cache-Control: private
[11-05-12 11:57:17.501] {http://*:80-31783} [^] Http[web-entry-1, 31783] Set-Cookie: JSESSIONID=baaxHPDr_9Yal58us7K-s; path=/
[11-05-12 11:57:17.501] {http://*:80-31783} [^] Http[web-entry-1, 31783] Transfer-Encoding: chunked
[11-05-12 11:57:17.501] {http://*:80-31783} [^] Http[web-entry-1, 31783] write-next-buffer(8002)
[11-05-12 11:57:17.501] {http://*:80-31783} [^] Http[web-entry-1, 31783] write-set-offset(86)
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] D: 112
[11-05-12 11:57:17.501] {http://*:80-31783} [^] load balance [web-entry-1->qa1:46] D: 8074

Attached Files

Relationships

There are no notes attached to this issue.

Issue History
Date Modified	Username	Field	Change
05-12-11 17:44	rickHigh	New Issue
05-19-11 14:18	ferg	Assigned To	=> ferg
05-19-11 14:18	ferg	Status	new => closed
05-19-11 14:18	ferg	Resolution	open => fixed
05-19-11 14:18	ferg	Fixed in Version	=> 4.0.19

Mantis 1.0.0rc3[^]

27 total queries executed.
25 unique queries executed.