https://issues.apache.org/bugzilla/show_bug.cgi?id=51180
Bug #: 51180
Summary: AsyncContextImpl With
org.apache.coyote.http11.Http11NioProtocol Closes
Connection Immediately Upon First Request
Product: Tomcat 7
Version: 7.0.12
Platform: All
OS/Version: All
Status: NEW
Severity: blocker
Priority: P2
Component: Catalina
AssignedTo: dev@tomcat.apache.org
ReportedBy: psniv...@vmware.com
Classification: Unclassified
On a connector configured with org.apache.coyote.http11.Http11NioProtocol, the
first request to a 3.0 servlet results in an NPE. Successive requests behave
correctly. Below is a catalina.out log excerpt covering two identical
consecutive requests, created with
"org.apache.catalina.core.AsyncContextImpl.level = FINE" added to the end of
conf/logging.properties:
May 9, 2011 11:33:55 AM org.apache.catalina.core.AsyncContextImpl logDebug
FINE: Req: null CReq: null RP: null Stage: - Thread:
ttp-nio-8080"-exec-1 State: N/A Method: Constructor URI:
N/A
05/09 11:33:55 DEBUG[akka:event-driven:dispatcher:global-2]
a.d.MonitorableThread - Created thread akka:event-driven:dispatcher:global-2
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-2] c.s.RootService -
Received HttpRequest(GET,http://localhost:8080/hello/CliveBarker,List(host:
localhost:8080, user-agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6;
en-US; rv:1.9.2.17) Gecko/20110420 Firefox/3.6.17, Accept:
MediaType(text/html), MediaType(application/xhtml+xml),
MediaType(application/xml), MediaRange(*/*), Accept-Encoding: gzip, deflate,
Accept-Charset: Charset(ISO-8859-1), Charset(UTF-8), CharsetRange(*),
keep-alive: 115, connection: keep-alive, cookie:
__utma=111872281.1546197940.1294377584.1295211055.1295212368.20;
__utmz=111872281.1294377584.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)),None,Some(0:0:0:0:0:0:0:1%0),Some(HTTP/1.1))
with one attached service, dispatching...
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-3]
a.d.MonitorableThread - Created thread akka:event-driven:dispatcher:global-3
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-3]
c.v.v.v.e.HelloServiceBuilder - *** HTTP GET METHOD RECEIVED ON PATH WITH KEY
CliveBarker, CALLING PERSISTENCE SERVICE ***
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-4]
a.d.MonitorableThread - Created thread akka:event-driven:dispatcher:global-4
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-4] c.r.RedisClient -
C: *2\r\n$3\r\nGET\r\n$28\r\npersistentHellos:CliveBarker\r\n
May 9, 2011 11:33:56 AM org.apache.catalina.core.AsyncContextImpl logDebug
FINE: Req: 3ac58af4 CReq: 7f25b750 RP: 5262667 Stage: 3 Thread:
ttp-nio-8080"-exec-2 State: N/A Method: complete URI:
/hello/CliveBarker
May 9, 2011 11:33:56 AM org.apache.catalina.core.AsyncContextImpl logDebug
FINE: Req: 3ac58af4 CReq: 7f25b750 RP: 5262667 Stage: 3 Thread:
ttp-nio-8080"-exec-3 State: N/A Method: recycle URI:
/hello/CliveBarker
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-4]
c.v.v.v.e.HelloServiceBuilder$PersistenceService - *** 'GET DIDN'T FIND KEY
CliveBarker, RETURNING NONE ***
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-3]
c.v.v.v.e.HelloServiceBuilder - *** PERSISTENCE SERVICE DIDN'T RETURN OBJECT
FOR KEY CliveBarker, RETURNING 403 TO CLIENT ***
05/09 11:33:56 ERROR[akka:event-driven:dispatcher:global-3]
a.h.Servlet30ContextMethodFactory$$anon$2 - Failed to write data to connection
on resume - the client probably disconnected
java.lang.NullPointerException: null
at
cc.spray.ServletConverter$$anonfun$fromSprayResponse$1.apply(ServletConverter.scala:88)
~[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.ServletConverter$$anonfun$fromSprayResponse$1.apply(ServletConverter.scala:87)
~[spray_2.8.1-0.5.0.jar:na]
at akka.http.RequestMethod$class.rawComplete(Mist.scala:394)
~[akka-http-1.0.jar:na]
at akka.http.Get.rawComplete(Mist.scala:458) [akka-http-1.0.jar:na]
at
cc.spray.RootService.cc$spray$RootService$$completeRequest(RootService.scala:80)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.RootService$$anonfun$cc$spray$RootService$$handleOneService$1.apply(RootService.scala:57)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.RootService$$anonfun$cc$spray$RootService$$handleOneService$1.apply(RootService.scala:57)
[spray_2.8.1-0.5.0.jar:na]
at
akka.dispatch.DefaultCompletableFuture.akka$dispatch$DefaultCompletableFuture$$notifyListener(Future.scala:324)
[akka-actor-1.0.jar:na]
at
akka.dispatch.DefaultCompletableFuture$$anonfun$notifyListeners$1.apply(Future.scala:320)
[akka-actor-1.0.jar:na]
at
akka.dispatch.DefaultCompletableFuture$$anonfun$notifyListeners$1.apply(Future.scala:319)
[akka-actor-1.0.jar:na]
at
scala.collection.LinearSeqOptimized$class.foreach(LinearSeqOptimized.scala:61)
[scala-library.jar:na]
at scala.collection.immutable.List.foreach(List.scala:45)
[scala-library.jar:na]
at akka.dispatch.DefaultCompletableFuture.notifyListeners(Future.scala:319)
[akka-actor-1.0.jar:na]
at
akka.dispatch.DefaultCompletableFuture.completeWithResult(Future.scala:279)
[akka-actor-1.0.jar:na]
at akka.actor.ScalaActorRef$$anon$1.$bang(ActorRef.scala:1398)
[akka-actor-1.0.jar:na]
at cc.spray.HttpServiceActor$$anon$1.apply(HttpServiceActor.scala:39)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.HttpServiceActor$$anon$1.apply(HttpServiceActor.scala:37)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.RequestContext.reject(RequestContext.scala:67)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1$$anonfun$apply$2.apply(MiscBuilders.scala:80)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1$$anonfun$apply$2.apply(MiscBuilders.scala:78)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.RequestContext.reject(RequestContext.scala:67)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:59)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:56)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1.apply(MiscBuilders.scala:76)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1.apply(MiscBuilders.scala:74)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.RequestContext.reject(RequestContext.scala:67)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1$$anonfun$apply$2.apply(MiscBuilders.scala:80)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1$$anonfun$apply$2.apply(MiscBuilders.scala:78)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.RequestContext.reject(RequestContext.scala:67)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:59)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:56)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1.apply(MiscBuilders.scala:76)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1$$anonfun$apply$1.apply(MiscBuilders.scala:74)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.RequestContext.reject(RequestContext.scala:67)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.RequestContext.reject(RequestContext.scala:62)
[spray_2.8.1-0.5.0.jar:na]
at
com.vmware.vcloud.vmole.example.HelloServiceBuilder$$anonfun$helloService$1$$anonfun$apply$3.apply(HelloServiceBuilder.scala:107)
[HelloServiceBuilder$$anonfun$helloService$1$$anonfun$apply$3.class:na]
at
com.vmware.vcloud.vmole.example.HelloServiceBuilder$$anonfun$helloService$1$$anonfun$apply$3.apply(HelloServiceBuilder.scala:98)
[HelloServiceBuilder$$anonfun$helloService$1$$anonfun$apply$3.class:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:58)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:56)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1.apply(MiscBuilders.scala:72)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1.apply(MiscBuilders.scala:71)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:58)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:56)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:58)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.FilterRoute$$anonfun$fromRouting$1.apply(FilterBuilders.scala:56)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1.apply(MiscBuilders.scala:72)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.builders.MiscBuilders$$anon$1$$anonfun$$tilde$1.apply(MiscBuilders.scala:71)
[spray_2.8.1-0.5.0.jar:na]
at cc.spray.HttpServiceLogic$class.handle(HttpServiceLogic.scala:33)
[spray_2.8.1-0.5.0.jar:na]
at
com.vmware.vcloud.vmole.example.CustomHttpService.handle(HelloServiceBuilder.scala:50)
[CustomHttpService.class:na]
at
cc.spray.HttpServiceActor$$anonfun$receive$1.apply(HttpServiceActor.scala:34)
[spray_2.8.1-0.5.0.jar:na]
at
cc.spray.HttpServiceActor$$anonfun$receive$1.apply(HttpServiceActor.scala:33)
[spray_2.8.1-0.5.0.jar:na]
at akka.actor.Actor$$anonfun$4.apply(Actor.scala:481)
[akka-actor-1.0.jar:na]
at akka.actor.Actor$$anonfun$4.apply(Actor.scala:464)
[akka-actor-1.0.jar:na]
at akka.actor.Actor$class.apply(Actor.scala:435) [akka-actor-1.0.jar:na]
at
com.vmware.vcloud.vmole.example.CustomHttpService.apply(HelloServiceBuilder.scala:50)
[CustomHttpService.class:na]
at
akka.actor.LocalActorRef.akka$actor$LocalActorRef$$dispatch(ActorRef.scala:1012)
[akka-actor-1.0.jar:na]
at
akka.actor.LocalActorRef$$anonfun$invoke$1.apply$mcV$sp(ActorRef.scala:832)
[akka-actor-1.0.jar:na]
at akka.actor.LocalActorRef$$anonfun$invoke$1.apply(ActorRef.scala:828)
[akka-actor-1.0.jar:na]
at akka.actor.LocalActorRef$$anonfun$invoke$1.apply(ActorRef.scala:828)
[akka-actor-1.0.jar:na]
at akka.util.ReentrantGuard.withGuard(LockUtil.scala:19)
[akka-actor-1.0.jar:na]
at akka.actor.LocalActorRef.invoke(ActorRef.scala:827)
[akka-actor-1.0.jar:na]
at akka.dispatch.MessageInvocation.invoke(MessageHandling.scala:23)
[akka-actor-1.0.jar:na]
at
akka.dispatch.ExecutableMailbox$class.processMailbox(ExecutorBasedEventDrivenDispatcher.scala:190)
[akka-actor-1.0.jar:na]
at
akka.dispatch.ExecutorBasedEventDrivenDispatcher$$anon$1.processMailbox(ExecutorBasedEventDrivenDispatcher.scala:109)
[akka-actor-1.0.jar:na]
at
akka.dispatch.ExecutableMailbox$class.run(ExecutorBasedEventDrivenDispatcher.scala:166)
[akka-actor-1.0.jar:na]
at
akka.dispatch.ExecutorBasedEventDrivenDispatcher$$anon$1.run(ExecutorBasedEventDrivenDispatcher.scala:109)
[akka-actor-1.0.jar:na]
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[na:1.6.0_24]
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[na:1.6.0_24]
at java.lang.Thread.run(Thread.java:680) [na:1.6.0_24]
at akka.dispatch.MonitorableThread.run(ThreadPoolBuilder.scala:185)
[akka-actor-1.0.jar:na]
05/09 11:33:56 DEBUG[akka:event-driven:dispatcher:global-3]
c.v.v.v.e.HelloServiceBuilder - *** PERSISTENCE SERVICE TIMED OUT FOR KEY
CliveBarker, RETURNING 403 TO CLIENT ***
May 9, 2011 11:33:59 AM org.apache.catalina.core.AsyncContextImpl logDebug
FINE: Req: null CReq: null RP: null Stage: - Thread:
ttp-nio-8080"-exec-4 State: N/A Method: Constructor URI:
N/A
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-5]
a.d.MonitorableThread - Created thread akka:event-driven:dispatcher:global-5
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-5] c.s.RootService -
Received HttpRequest(GET,http://localhost:8080/hello/CliveBarker,List(host:
localhost:8080, user-agent: Mozilla/5.0 (Macintosh; U; Intel Mac OS X 10.6;
en-US; rv:1.9.2.17) Gecko/20110420 Firefox/3.6.17, Accept:
MediaType(text/html), MediaType(application/xhtml+xml),
MediaType(application/xml), MediaRange(*/*), Accept-Encoding: gzip, deflate,
Accept-Charset: Charset(ISO-8859-1), Charset(UTF-8), CharsetRange(*),
keep-alive: 115, connection: keep-alive, cookie:
__utma=111872281.1546197940.1294377584.1295211055.1295212368.20;
__utmz=111872281.1294377584.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none)),None,Some(0:0:0:0:0:0:0:1%0),Some(HTTP/1.1))
with one attached service, dispatching...
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-6]
a.d.MonitorableThread - Created thread akka:event-driven:dispatcher:global-6
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-6]
c.v.v.v.e.HelloServiceBuilder - *** HTTP GET METHOD RECEIVED ON PATH WITH KEY
CliveBarker, CALLING PERSISTENCE SERVICE ***
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-7]
a.d.MonitorableThread - Created thread akka:event-driven:dispatcher:global-7
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-7] c.r.RedisClient -
C: *2\r\n$3\r\nGET\r\n$28\r\npersistentHellos:CliveBarker\r\n
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-7]
c.v.v.v.e.HelloServiceBuilder$PersistenceService - *** 'GET DIDN'T FIND KEY
CliveBarker, RETURNING NONE ***
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-6]
c.v.v.v.e.HelloServiceBuilder - *** PERSISTENCE SERVICE DIDN'T RETURN OBJECT
FOR KEY CliveBarker, RETURNING 403 TO CLIENT ***
May 9, 2011 11:33:59 AM org.apache.catalina.core.AsyncContextImpl logDebug
FINE: Req: 3ac58af4 CReq: 7f25b750 RP: 5262667 Stage: 7 Thread:
:dispatcher:global-6 State: N/A Method: complete URI:
/hello/CliveBarker
05/09 11:33:59 DEBUG[akka:event-driven:dispatcher:global-6]
c.v.v.v.e.HelloServiceBuilder - *** PERSISTENCE SERVICE TIMED OUT FOR KEY
CliveBarker, RETURNING 403 TO CLIENT ***
May 9, 2011 11:33:59 AM org.apache.catalina.core.AsyncContextImpl logDebug
FINE: Req: 3ac58af4 CReq: 7f25b750 RP: 5262667 Stage: 3 Thread:
ttp-nio-8080"-exec-6 State: N/A Method: recycle URI:
/hello/CliveBarker
As you can see, on the first request, the AsyncContextImpl has complete()ed and
recycle()d the connection immediately upon the main thread returning control.
On the second request, however, the AsyncContextImpl does not complete() and
recycle() the connection until after the forked thread has complete()ed the
context.
--
Configure bugmail: https://issues.apache.org/bugzilla/userprefs.cgi?tab=email
------- You are receiving this mail because: -------
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscr...@tomcat.apache.org
For additional commands, e-mail: dev-h...@tomcat.apache.org
