handshake timeout only with logging level = DEBUG

Gatling (Open-Source)
1

Hi,

I’m running into some handshake errors in my test when logging level = DEBUG (writing to both console and file). When logging level = INFO or WARN, then the same test, with the same parameters, on the same servers do not have handshake errors. It’s hard to believe but I’ve run and rerun the tests many times, and I’m getting this result.

Has anyone else experience this? What would be the cause? Is Gatling too busy on the client side to handle the TLS handshake?

Here’s the stack trace:

java.net.ConnectException: handshake timed out
at org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:162)
at org.asynchttpclient.netty.channel.NettyConnectListener$1.onFailure(NettyConnectListener.java:133)
at org.asynchttpclient.netty.SimpleFutureListener.operationComplete(SimpleFutureListener.java:26)
at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:514)
at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:507)
at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:486)
at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:427)
at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:129)
at io.netty.handler.ssl.SslHandler.notifyHandshakeFailure(SslHandler.java:1238)
at io.netty.handler.ssl.SslHandler.access$800(SslHandler.java:160)
at io.netty.handler.ssl.SslHandler$5.run(SslHandler.java:1386)
at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38)
at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:120)
at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:408)
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:455)
at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:140)
at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
at java.lang.Thread.run(Thread.java:745)
Caused by: javax.net.ssl.SSLException: handshake timed out
at io.netty.handler.ssl.SslHandler.handshake(…)(Unknown Source)

I’m also not making that many requests to the system under test:

[info] ================================================================================
[info] ---- Global Information --------------------------------------------------------
[info] > request count                                       2581 (OK=2489   KO=92    )
[info] > min response time                                      0 (OK=22     KO=0     )
[info] > max response time                                  24949 (OK=24949  KO=0     )
[info] > mean response time                                  4307 (OK=4466   KO=0     )
[info] > std deviation                                       4780 (OK=4794   KO=0     )
[info] > response time 50th percentile                       3041 (OK=3156   KO=0     )
[info] > response time 75th percentile                       5207 (OK=5327   KO=0     )
[info] > response time 95th percentile                      17126 (OK=17437  KO=0     )
[info] > response time 99th percentile                      22672 (OK=22747  KO=0     )
[info] > mean requests/sec                                 19.261 (OK=18.575 KO=0.687 )
[info] ---- Response Time Distribution ------------------------------------------------
[info] > t < 800 ms                                           326 ( 13%)
[info] > 800 ms < t < 1200 ms                                 183 (  7%)
[info] > t > 1200 ms                                         1980 ( 77%)
[info] > failed                                                92 (  4%)
[info] ---- Errors --------------------------------------------------------------------
[info] > j.n.ConnectException: handshake timed out                          92 (100.0%)
[info] ================================================================================



Thanks in advance,



Nguyen
2

Reproducer? With current master?

3

Having the same issue here

  1. 9:59:24.856 [DEBUG] i.g.h.a.AsyncHandler - Request ‘Search’ failed for user 1492
  2. javax.net.ssl.SSLException: handshake timed out
  3. at io.netty.handler.ssl.SslHandler.handshake(…)(Unknown Source)
  4. Wrapped by: java.net.ConnectException: handshake timed out
  5. at org.asynchttpclient.netty.channel.NettyConnectListener.onFailure(NettyConnectListener.java:162)
  6. at org.asynchttpclient.netty.channel.NettyConnectListener$1.onFailure(NettyConnectListener.java:133)
  7. at org.asynchttpclient.netty.SimpleFutureListener.operationComplete(SimpleFutureListener.java:26)
  8. at io.netty.util.concurrent.DefaultPromise.notifyListener0(DefaultPromise.java:514)
  9. at io.netty.util.concurrent.DefaultPromise.notifyListeners0(DefaultPromise.java:507)
  10. at io.netty.util.concurrent.DefaultPromise.notifyListenersNow(DefaultPromise.java:486)
  11. at io.netty.util.concurrent.DefaultPromise.notifyListeners(DefaultPromise.java:427)
  12. at io.netty.util.concurrent.DefaultPromise.tryFailure(DefaultPromise.java:129)
  13. at io.netty.handler.ssl.SslHandler.notifyHandshakeFailure(SslHandler.java:1238)
  14. at io.netty.handler.ssl.SslHandler.access$800(SslHandler.java:160)
  15. at io.netty.handler.ssl.SslHandler$5.run(SslHandler.java:1386)
  16. at io.netty.util.concurrent.PromiseTask$RunnableAdapter.call(PromiseTask.java:38)
  17. at io.netty.util.concurrent.ScheduledFutureTask.run(ScheduledFutureTask.java:120)
  18. at io.netty.util.concurrent.SingleThreadEventExecutor.runAllTasks(SingleThreadEventExecutor.java:408)
  19. at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:455)
  20. at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:140)
  21. at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144)
  22. at java.lang.Thread.run(Thread.java:745)
  23. 09:59:24.856 [WARN ] i.g.h.a.ResponseProcessor - Request ‘Search’ failed: j.n.ConnectException: handshake timed out
  24. 09:59:24.856 [DEBUG] i.g.h.a.ResponseProcessor -
  26. Request:
  27. Search: KO j.n.ConnectException: handshake timed out
  28. =========================
    Using Gatling 2.2.3 in this case.

Bests,
Martin

4

Have you considered your TLS layer could indeed not be able to withstand the load your generating?

5

Hey Stéphane

valid idea, do you have an idea how we could test that?

Bests,
Martin

6

Wireshark