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

Viewing Issue Simple Details [ Jump to Notes ]

[ View Advanced ] [ 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

Status

closed

Product Version

4.0.14

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.

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.