Test hangs when there are lots of failures

Chris_Carrier · February 10, 2012, 7:35pm

Hey when I push my tests and things start breaking I often see the
test hang at the end and never generate the reports. Things are fine
if I get a response but the checks fail but when requests timeout or
other unexpected things happen I get a bunch of stack traces and then
things just hang in the end. I'll paste an example of the exception
i'm seeing into this message. Would the expectation be that these
produce failed checks? Would additional callbacks on the Asyc client
sort these out?

Chris

Timeouts:

11:23:01.240 [AsyncHttpClient-Reaper][ERROR]
c.e.e.g.h.a.GatlingAsyncHandler - Request 'postSomething' failed
java.util.concurrent.TimeoutException: No response received after 60000
        at com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture.run(NettyAsyncHttpProvider.java:1767)
[async-http-client-1.7.0.jar:na]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441)
[na:1.6.0_22]
        at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317)
[na:1.6.0_22]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150)
[na:1.6.0_22]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98)
[na:1.6.0_22]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180)
[na:1.6.0_22]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204)
[na:1.6.0_22]
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[na:1.6.0_22]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[na:1.6.0_22]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_22]

Other:

11:22:34.708 [New I/O client worker #1-4][ERROR]
c.e.e.g.h.a.GatlingAsyncHandler - Request 'PostOfferClickAction'
failed
java.io.IOException: Remotely Closed [id: 0x395ad219,
/172.16.160.151:51901 :>
zuberance.demo.zuberancess.com/50.20.129.201:80]
        at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.channelClosed(NettyAsyncHttpProvider.java:1352)
[async-http-client-1.7.0.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:93)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:777)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:143)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:777)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.channelClosed(SimpleChannelUpstreamHandler.java:212)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:93)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:777)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.cleanup(ReplayingDecoder.java:558)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.handler.codec.replay.ReplayingDecoder.channelClosed(ReplayingDecoder.java:450)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:93)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:72)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:558)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:553)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.Channels.fireChannelClosed(Channels.java:398)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.close(NioWorker.java:596)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:350)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.processSelectedKeys(NioWorker.java:274)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:194)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:102)
[netty-3.3.1.Final.jar:na]
        at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[netty-3.3.1.Final.jar:na]
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
[na:1.6.0_22]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
[na:1.6.0_22]
        at java.lang.Thread.run(Thread.java:680) [na:1.6.0_22]

Excilys · February 10, 2012, 7:43pm

Hi Chris,

It seems like an AsyncHttpClient bug. The exception should be trapped and passed to our GatlingAsyncHandler.
Let me investigate this investigate.

Thanks,

Stéphane

2012/2/10 Chris Carrier <ctcarrier@gmail.com>

Excilys · February 10, 2012, 7:48pm

Just one question : can you find the corresponding errors in the simulation.log?

2012/2/10 Stéphane Landelle <slandelle@excilys.com>

Chris_Carrier · February 10, 2012, 7:56pm

I do see some errors that look like:

20120210111926 WebFlow4 795 Request
postThing 1328901751267 1328901751839 1328901751784 1328901751839 KO Remotely
Closed [id: 0x23aead2b, /172.16.160.151:52017 :>
ourwebsite.demo.com/50.20.129.201:80]

I don't see anything in the log about timeouts. The only errors I see
look basically like the one I pasted above. If it would help debug I
could probably send you my log off list. I've seen the tests hang
when the only exceptions I see are for request timeouts. So it's
possible the connection closed error is just a red herring.

Chris

Excilys · February 10, 2012, 8:01pm

Sometimes I hate myself…
https://github.com/excilys/gatling/commit/96b9af615f55622e98f1c7d4c90947c54117076a

I’m going to repackage a new SNAPSHOT and send you the link.

Stéphane

2012/2/10 Chris Carrier <ctcarrier@gmail.com>

Chris_Carrier · February 10, 2012, 8:05pm

Hah at least it wasn't a time sucking mystery. I've got the code so I
can pull the change and make a build and test it right now.

Excilys · February 10, 2012, 8:10pm

Cool! So I’ll just remove the SNAPSHOT I uploaded on Github.

That’s definitively the cause : that’s something I had previously fixed, but obviously wrong.
What happened is that the responseEndDate wasn’t fill in case of a TimeOutException, so responseEndDate.get failed and the Session was never passed to the next Actor.

Thanks for reporting!

Stéphane

2012/2/10 Chris Carrier <ctcarrier@gmail.com>

Chris_Carrier · February 10, 2012, 8:43pm

I blew our app up pretty hard and the test finished fine. Thanks
again for the quick fix!

Chris

Excilys · February 10, 2012, 8:52pm

I don’t know of I should say “good news” or not.

Cheers,

Steph

2012/2/10 Chris Carrier <ctcarrier@gmail.com>

David_Martin1 · June 13, 2012, 3:02pm

I’ve got the same kind of problem here using Gatling 1.2.1 : the stress test hangs (and never reaches the log processing) and I’ve got some IOException: Remotely closed

java.io.IOException: Remotely Closed [id: 0x0008f1f5, /10.210.152.213:41621 :> myserverunderheavyload.com/10.210.117.61:8080]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.channelClosed(NettyAsyncHttpProvider.java:1389) [async-http-client-1.7.5.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:93) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:792) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:141) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:792) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.channelClosed(SimpleChannelUpstreamHandler.java:212) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:93) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:792) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.cleanup(ReplayingDecoder.java:649) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.channelClosed(ReplayingDecoder.java:546) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec$Decoder.channelClosed(HttpClientCodec.java:218) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:93) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.Channels.fireChannelClosed(Channels.java:476) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.close(AbstractNioWorker.java:631) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioClientSocketPipelineSink.eventSunk(NioClientSocketPipelineSink.java:90) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:780) [netty-3.4.6.Final.jar:na] at org.jboss.netty.handler.codec.oneone.OneToOneEncoder.handleDownstream(OneToOneEncoder.java:55) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleDownstream(HttpClientCodec.java:97) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendDownstream(DefaultChannelPipeline.java:785) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleDownstream(ChunkedWriteHandler.java:108) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:591) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendDownstream(DefaultChannelPipeline.java:582) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.Channels.close(Channels.java:821) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.AbstractChannel.close(AbstractChannel.java:194) [netty-3.4.6.Final.jar:na]
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider.exceptionCaught(NettyAsyncHttpProvider.java:1529) [async-http-client-1.7.5.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:117) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:792) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.stream.ChunkedWriteHandler.handleUpstream(ChunkedWriteHandler.java:141) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:792) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.exceptionCaught(SimpleChannelUpstreamHandler.java:143) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:117) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline$DefaultChannelHandlerContext.sendUpstream(DefaultChannelPipeline.java:792) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.replay.ReplayingDecoder.exceptionCaught(ReplayingDecoder.java:552) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.SimpleChannelUpstreamHandler.handleUpstream(SimpleChannelUpstreamHandler.java:117) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.handler.codec.http.HttpClientCodec.handleUpstream(HttpClientCodec.java:92) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:564) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.DefaultChannelPipeline.sendUpstream(DefaultChannelPipeline.java:559) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.Channels.fireExceptionCaught(Channels.java:533) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.read(NioWorker.java:76)[netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.processSelectedKeys(AbstractNioWorker.java:372) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.socket.nio.AbstractNioWorker.run(AbstractNioWorker.java:246) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.channel.socket.nio.NioWorker.run(NioWorker.java:38) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:102) [netty-3.4.6.Final.jar:na]
at org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42) [netty-3.4.6.Final.jar:na]
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [na:1.6.0_32]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [na:1.6.0_32]
at java.lang.Thread.run(Thread.java:662) [na:1.6.0_32]

Any idea ?

David

Excilys · June 13, 2012, 4:08pm

Hi,

Could you post a gist of your scenario, please?

Thanks,

Stéphane

2012/6/13 David Martin <dmartin@ippon.fr>

Excilys · June 13, 2012, 4:10pm

Could you also post the lines before the stacktrace so I can see where it was logged, please?

Cheers,

Stéphane

2012/6/13 Stéphane Landelle <slandelle@excilys.com>

David_Martin1 · June 14, 2012, 9:05am

Hi,

My scenario is rather simple: I’ve recorded a typical user session, representing about 60 requests. I’ve executed it with 300 users, giving a ramp of 30.

The line just before the stacktrace I’ve provided is the following one:

10:52:20.419 [WARN ] c.e.e.g.h.a.GatlingAsyncHandler - Request ‘request_13’ fail
ed

Nothing more: the lines before this one are the end of another identical stacktrace (same reason).

Tell me if you need something else.

David

Excilys · June 14, 2012, 11:39am

So the line “GatlingAsyncHandler - Request ‘request_13’ fail” tells that Gatling has correctly trapped this error and handled it correctly, so the problem is somewhere else.
As Gatling is a fully async engine, you cannot think that a stacktrace just before it hangs is the root of the problem.

If the engine hangs, it means that some users/sessions/messages were lost along the way and doesn’t reach the end of the scenario that count them down and shutdown when it reaches 0. The trick is to identify why those messages were lost… There can be 2 types of problems:

Some problems in the IO layer are not propagated to the applicative layer (those are the ones I’m really afraid of, as they are a hell to track).
An Actor crashes, it is automatically restared by the current message is lost (not that appreciated this, but this is something I can fix)
Could you send your simulation.log so I can guess where the message loss happens, please?

2012/6/14 David Martin <dmartin@ippon.fr>

Excilys · June 14, 2012, 2:10pm

Could you also try with the brand new 1.2.2, please?

2012/6/14 Stéphane Landelle <slandelle@excilys.com>

Excilys · June 15, 2012, 12:07pm

Last ping: any update on this?

2012/6/14 Stéphane Landelle <slandelle@excilys.com>

Amuthan_G · February 14, 2013, 8:42am

I am also having the same problem, I am using gatling 1.4.2 and here is the stack trace

12:32:05.381 [WARN ] c.e.e.g.h.a.GatlingAsyncHandler - Request ‘Read Customer Instance Request’ failed
java.util.concurrent.TimeoutException: No response received after 60000
at com.ning.http.client.providers.netty.NettyAsyncHttpProvider$ReaperFuture.run(NettyAsyncHttpProvider.java:1869) [async-http-client-1.7.9.jar:na]
at java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source) [na:1.7.0_04]
at java.util.concurrent.FutureTask$Sync.innerRunAndReset(Unknown Source) [na:1.7.0_04]
at java.util.concurrent.FutureTask.runAndReset(Unknown Source) [na:1.7.0_04]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(Unknown Source) [na:1.7.0_04]
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(Unknown Source) [na:1.7.0_04]
at java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source) [na:1.7.0_04]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) [na:1.7.0_04]
at java.lang.Thread.run(Unknown Source) [na:1.7.0_04]
12:32:05.382 [WARN ] c.e.e.g.h.a.GatlingAsyncHandlerActor - Request ‘Read Customer Instance Request’ failed : No response received after 60000
12:32:05.382 [TRACE] c.e.e.g.h.a.GatlingAsyncHandlerActor -

Regards
Amuthan

Excilys · February 14, 2013, 8:49am

So?
Request time out after 60 sec, your application can’t handle the load.

Amuthan_G · February 14, 2013, 9:06am

Thank you,

okay, in that case how can I set it to waite for more than 60 sec

Regards
Amuthan

Nicolas_R · February 14, 2013, 9:09am

It’s defined in gatling.conf

Topic		Replies	Views
Gatling hangs at end of test Gatling (Open-Source)	9	224	May 17, 2012
Gatling hanging AFTER reports are generated? Gatling (Open-Source)	8	146	August 23, 2012
Gatling Threads Hanging Could Not Quit Gatling (Open-Source)	8	99	January 30, 2014
Gatling Hanging??? No response...No Console Logs.. Gatling (Open-Source)	11	238	October 16, 2014
Java.util.concurrentTimeout Exception : Request timed out to TestEnv of 60000 ms Gatling (Open-Source)	9	240	September 2, 2014

Test hangs when there are lots of failures

Related topics