trying out Antonio's ajax dedup

[Diego Medina]

Hi Antonio (and/or anyone who tried his branch,

Did you happen to get errors like this using your branch from
https://github.com/lift/framework/pull/1309


12:27:03.223 [pool-955-thread-13] ERROR net.liftweb.actor.ActorLogger
- Actor threw an exception
java.lang.NullPointerException: null
at sun.reflect.GeneratedMethodAccessor18.invoke(Unknown Source) ~[na:na]
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
~[na:1.6.0_33]
at java.lang.reflect.Method.invoke(Method.java:597) ~[na:1.6.0_33]
at net.liftweb.http.provider.servlet.containers.Servlet30AsyncProvider.resume(Servlet30AsyncProvider.scala:110)
~[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.provider.servlet.HTTPRequestServlet.resume(HTTPRequestServlet.scala:163)
~[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.LiftServlet$$anonfun$handleAjax$1$$anonfun$suspendingActor$1$1.apply(LiftServlet.scala:696)
~[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.LiftServlet$$anonfun$handleAjax$1$$anonfun$suspendingActor$1$1.apply(LiftServlet.scala:695)
~[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.LiftServlet$AjaxContinuationActor$$anonfun$messageHandler$1.apply(LiftServlet.scala:465)
~[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.LiftServlet$AjaxContinuationActor$$anonfun$messageHandler$1.apply(LiftServlet.scala:457)
~[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.LiftActor$class.execTranslate(LiftActor.scala:441)
~[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.LiftServlet$AjaxContinuationActor.execTranslate(LiftServlet.scala:452)
[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$class.net$liftweb$actor$SpecializedLiftActor$$proc2(LiftActor.scala:289)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$$anonfun$net$liftweb$actor$SpecializedLiftActor$$processMailbox$1.apply$mcV$sp(LiftActor.scala:210)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$$anonfun$net$liftweb$actor$SpecializedLiftActor$$processMailbox$1.apply(LiftActor.scala:210)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$$anonfun$net$liftweb$actor$SpecializedLiftActor$$processMailbox$1.apply(LiftActor.scala:210)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$class.around(LiftActor.scala:224)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.http.LiftServlet$AjaxContinuationActor.around(LiftServlet.scala:452)
[lift-webkit_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$class.net$liftweb$actor$SpecializedLiftActor$$processMailbox(LiftActor.scala:209)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.SpecializedLiftActor$$anonfun$2$$anonfun$apply$mcV$sp$1.apply$mcV$sp(LiftActor.scala:173)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at net.liftweb.actor.LAScheduler$$anonfun$9$$anon$2$$anon$3.run(LiftActor.scala:64)
[lift-actor_2.9.1.jar:2.5-SNAPSHOT]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[na:1.6.0_33]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[na:1.6.0_33]
at java.lang.Thread.run(Thread.java:680) [na:1.6.0_33]
12:28:18.239 [pool-955-thread-5] ERROR net.liftweb.actor.ActorLogger -
Actor threw an exception

After I start my app, I let it sit there for a few minutes (maybe
10-15 min), and then I see a few of those errors. I just went back to
regular master and I don't see them any more.
I'll do a few more things and try to narrow this down more (I admit
this is a pretty generic error to report)

Thanks

Diego


--
Diego Medina
Lift/Scala Developer
di...@fmpwizard.com
http://www.fmpwizard.com

[Diego Medina]

Ok, it really seems that the new changes are the culprit, I once again
rm -Rf ~./ivy2/cache/net.liftweb , local and then I publish-local from
Antonio's branch.
I then started jetty
completed Aug 25, 2012 1:55:58 PM
and 7 minutes later: 2:02:20.314

I got the first java.lang.NullPointerException error.

After I get the first npe, they keep coming, not very often, the intervals are:

14:02:02.162
14:04:50.932
14:06:05.956
14:07:20.971
14:08:35.999
14:09:51.018
14:11:06.040
14:12:21.053

so, about every 2 minutes I get one of those errors.

Firebug on the UI does not show any failed gc requests, they all
return just fine (well, I get the 0 bytes returned, and a 200 OK)

This page has reactive web on it, but not using comet. and in case it
helps, the html of the only page I load to get this error is the home
page:
https://gist.github.com/930190756a1f08b321bc

This is running from sbt, using jetty:
"org.eclipse.jetty" % "jetty-webapp" % "8.1.0.v20120127" %
"container; test; it" ,


Thanks

Diego

[Diego Medina]

Just a bit more information, even if I remove the reactive web
snippet, I still get those null PE on the terminal.

Thanks

Diego

[Diego Medina]

I added some debug entries near the code that is giving the NPE and
this is the result:
https://gist.github.com/736fb885a6f3cfdb3768

One thing I noticed (which may or may not be relevant), is that the
response is an Empty Box, so I'm thinking that we are trying to do
something with it, even though is not Full.

The relevant code is:

def messageHandler = {
case AjaxResponseComplete(completeResponse) =>
response = completeResponse
LAPinger.schedule(this, BreakOut(), 5 millis)

case BreakOut() if ! done =>
logger.debug("response is %s" format response)
done = true
session.exitComet(this)
onBreakout(response) // <-- from the last gist I included
in this email, this line number is LiftServlet.scala:468

case _ =>
}


If I followed the code correctly, this is where the onBreakout param is pass:
(I added those debug entries)

def suspendingActor = {
logger.debug("1- requestState is %s" format requestState)
logger.debug("1- requestState.request is %s" format
requestState.request)
logger.debug("1- liftSession is %s" format liftSession)
new AjaxContinuationActor(requestState, liftSession,
response => {
requestState.request.resume((requestState,
S.init(requestState, liftSession)
(response.map(LiftRules.performTransform) openOr
EmptyResponse)))})
}





Now, the NPE only happens with

"org.eclipse.jetty" % "jetty-webapp" % "8.1.0.v20120127" %
"container; test; it",

but does not happen with:
"org.eclipse.jetty" % "jetty-webapp" % "7.5.4.v20111024" %
"container; test; it",

The only diff. I can see affecting us here is that jetty 8.1 has the
servlet 3.0 continuation, while jetty 7.x has it;s own continuation.

[Diego Medina]

Alright, I found why I get this NPE using jetty 8.x

The code is in the class Servlet30AsyncProvider:


def resume(what: (Req, LiftResponse)): Boolean = {
logger.trace("Servlet 3.0 begin resume")
logger.debug("asyncCtx is %s" format asyncCtx)
val httpRes =
getResponse.invoke(asyncCtx).asInstanceOf[javax.servlet.http.HttpServletResponse]
val httpResponse = new HTTPResponseServlet(httpRes)
val liftServlet = req.provider.liftServlet
try {
liftServlet.sendResponse(what._2, httpResponse, what._1)
complete.invoke(asyncCtx)
} catch {
case e: Exception => logger.error("Servlet 3.0 Async: Couldn't
resume thread", e)
}
logger.trace("Servlet 3.0 resume")
true
}


and asyncCtx is null here:

val httpRes = getResponse.invoke(asyncCtx).asInstanceOf[javax.servlet.http.HttpServletResponse]

My latest theory is that we are not calling suspend, or something like
that, because in the same class we have:

def suspend(timeout: Long): RetryState.Value = {
logger.debug("suspending")
asyncCtx = startAsync.invoke(servletReq)
logger.debug("suspending and asyncCtx is %s" format asyncCtx)
try {
val st = asyncCtx.asInstanceOf[SetTimeout];
st.setTimeout(0l)
} catch {
case e: Exception => logger.error("Servlet 3.0 Async: Failed to
set timeout", e)
}
logger.trace("Servlet 3.0 suspend")
RetryState.SUSPENDED
}

there is where we set asyncCtx, I just added the logging, but it;s
also 2am here, so I better go to sleep and continue tomorrow.

Diego

[Antonio Salazar Cardozo]

Hey Diego,

Did you get a chance to peer into this in more detail? And also, you're only seeing this in jetty 8?

I'll go through the relevant code and see if I can find a path where you can try to resume without having suspended.

Thanks,

Antonio

[Diego Medina]

Hi Antonio,

Welcome back :)

On Tue, Sep 11, 2012 at 9:11 AM, Antonio Salazar Cardozo
<savedf...@gmail.com> wrote:
> Hey Diego,
> Did you get a chance to peer into this in more detail? And also, you're only
> seeing this in jetty 8?
>

yes, only on jetty8, when I go back to jetty 7, the NPE does not happen.
After I found out that the suspend was not being called, I stopped
looking, let me know if you would need some help, I should have some
time later this week (I'm recovering from a cold, so my computer time
is kind of limited .

Thanks

Diego

> --
> --
> Lift, the simply functional web framework: http://liftweb.net
> Code: http://github.com/lift
> Discussion: http://groups.google.com/group/liftweb
> Stuck? Help us help you:
> https://www.assembla.com/wiki/show/liftweb/Posting_example_code

[Antonio Salazar Cardozo]

On Tuesday, September 11, 2012 9:20:58 AM UTC-4, fmpwizard wrote:

Hi Antonio,

Welcome back :)

Thanks!

yes, only on jetty8, when I go back to jetty 7, the NPE does not happen.
After I found out that the suspend was not being called, I stopped
looking, let me know if you would need some help, I should have some
time later this week (I'm recovering from a cold, so my computer time
is kind of limited .

Ok cool. Looks like I just got hit by a bug too, but I'll let you know if I can think of anything I can use your help for :)

Thanks,

Antonio

[Dano]

Hello,

I am running into the exact same problem that Diego encountered back in 2012 running on Jetty8.  My version of Lift is 2.5.  I am using RestContinuation.async support for a REST api and patterning my code off of the example in http://simply.liftweb.net/index-5.4.html#prev.   It appears that the second invocation of the satisfyRequest function is generating the exception (stack trace below).

Any advice/information greatly appreciated.

Thanks.

01 Mar 2015 22:30:11,414 -0800 ERROR - Servlet 3.0 Async: Couldn't resume thread
java.lang.reflect.InvocationTargetException
    at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
    at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
    at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
    at java.lang.reflect.Method.invoke(Method.java:606)
    at net.liftweb.http.provider.servlet.containers.Servlet30AsyncProvider.resume(Servlet30AsyncProvider.scala:115)
    at net.liftweb.http.provider.servlet.HTTPRequestServlet.resume(HTTPRequestServlet.scala:163)
    at net.liftweb.http.LiftServlet$$anonfun$handleGenericContinuation$1$$anonfun$apply$1.apply$mcV$sp(LiftServlet.scala:122)
    at net.liftweb.util.Schedule$$anon$1.run(Schedule.scala:152)
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
    at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.IllegalStateException: IDLE,initial
    at org.eclipse.jetty.server.AsyncContinuation.complete(AsyncContinuation.java:579)
    ... 11 more

[Antonio Salazar Cardozo]

This is an old and not-easily-fixable issue. As I recall, this is symptomatic of the fact that

you are getting too many requests in during the time that the request is taking to be

satisfied. The end result is that Jetty discards the old request to process a new one, but

that happens before we try to revive it. Then, when we try to revive it, it's invalid, and we

can't use it because it's been terminated. That triggers the exception.

At least that's what I remember tracing it to. It manifests in a variety of places as null pointers

or other types of exceptions in the async resume pipeline. See my post from 3 years ago for

a longer explanation.

Thanks,

Antonio

[Dano]

Antonio,

Thanks very much for the quick response and helpful link.

In my case, the server was not loaded at all (one outstanding request only).  However, I will heed the advice in the post link you sent and dig into why the jetty server is terminating the request. 

[Dano]

Just wanted to report back some findings that may be useful to folks who have seen this issue (NPE/InvocationTargetException when using RestContinuation.async).

When I reported this issue originally, I was running on Jetty 8.1.10.v20130312.  I upgraded to Jetty 8.1.16.v20140903 and the issue I was experiencing went away.  This does not necessarily mean it is gone from this newer release, but it is a promising sign.

[Antonio Salazar Cardozo]

Good to hear. Wonder if there was a bug in that earlier version that caused requests to

be reclaimed early even in low-load scenarios or something.

Thanks,

Antonio