Where are the logs? I'm troubleshooting webSocket "1006: Connection was closed abnormally"

Gatling (Open-Source)
1

I’m running scenario with WebSockets (see scenario below).

And in some cases, not always, I see this exception in console:

Websocket 'gatling.http.webSocket' was unexpectedly closed with status 1006 and message Connection was closed abnormally

I'm trying to troubleshoot, - why this exception happening? 


I never can reproduce the issue, when repeating steps manually. And as you can see - I'm not really generating any load - it's just one user.



So, please assist - what can I do to troubleshoot?

One specific question I have:

- I can see some exception details, as you see above (status 1006), but **where I can see the details of that exception (log, stack trace, etc...)?**

Scenario:

val scn = scenario("WebSocket")
  .exec(ws("Connect WS").open(""))
  .exec(ws("Sending query")
         .sendText(session => query())
         .check(wsAwait.within(300).until(1).regex(""".*"status":"Finished".*""").saveAs("SiftOutput"))
  )
  .exec{ session =>
      session("SiftOutput").asOption[String].foreach(println)
      session
      }
  .exec(ws("Close WS").close)


setUp(scn.inject(atOnceUsers(1)).protocols(httpConf))
2

It means your server closed the connection without sending a close frame first.

3

Actually,
As I’m troubleshooting, I see, that connection gets closed by Gatling, not by my server:

4

I finally found, that issue was caused by this configuration parameter:

#webSocketMaxFrameSize = 10240 # Maximum frame payload size

Our server was sending bigger, than 10K frames.
So, issue is resolved by increasing the value.

Now, I looked at the default size of the MaxFrameSize in the browsers and found, that their’s frame-size limit is 2^63 octets (~80TB), as answered here:
http://stackoverflow.com/questions/13010354/chunking-websocket-transmission

So, the issue is resolved, but two questions left:

  • why Gatling default value is so small? Why not increase the default size? Is there any drawbacks to that?
  • where I can see the details of the exceptions (log, stack trace, etc…)?
5

- why Gatling default value is so small? Why not increase the default size?

I guess we could set this limit to Long.MaxValue. The current value comes
historically from AsyncHttpClient, no idea where it comes from itself.

Is there any drawbacks to that?

The larger the frames, the larger the allocations and memory pressure.
WebSockets are more intended to deal with lots of small messages/frames
than a few large ones.

- where I can see the details of the exceptions (log, stack trace, etc...)?

I would expect you to see a CorruptedFrameException in the logs.
If you don't, it's probably swallowed somewhere, probably in AHC rather
than in Gatling. When such exception occurs, Netty automatically closes the
connection.
Could you please open an issue then?

6

I would expect you to see a CorruptedFrameException in the logs.
If you don't, it's probably swallowed somewhere, probably in AHC rather
than in Gatling. When such exception occurs, Netty automatically closes the
connection.

Which log? Where can I find it?

7

stdout, or wherever you output logback logs.

8

So, you are talking about console.

The only thing I see in console is:

9

Are you sure you have a logback.xml file?

10

Yes,

I have following logback.xml:

<?xml version="1.0" encoding="UTF-8"?> %d{HH:mm:ss.SSS} [%-5level] %logger{15} - %msg%n%rEx true

And I do not see anything in the log:

  • no requests or responses are logged
  • no exception details

I’m using Gatling 2.1.7

11

Hi,

you should get as much as log as we can provide by changing the WARN in the root part to DEBUG.

Cheers,

Pierre

12
13

Those logger only control “classic” HTTP requests or protocols using HTTP as the transport, which doesn’t fit Websockets.

14

Hello Everyone,

I am facing the same issue which is given on this mail chain.

My simulation is something like below -

 login(lrs_login_url, lrs_auth_token_url, credentials_file, rememberMe)
    .exec(
      ws("Open Websocket").open("open")

    ).pause(1)
    .exec(
      ws("Connect to Websocket")
        .sendText(session => "connect").check(wsListen.within(30).until(1).regex("""CONNECTED"""))
    ).pause(1)
    .exec(
      ws("Subscribe")
        .sendText(session => "subscribe")
    )
    .exec(BookingHelper.getSpaceGuid(lrs_query_space_guid)).foreach("${SpaceGuid}", Constants.SPACE_GUID) {
     exec(BookingHelper.getWaitlist(lrs_get_waitlist1, lrs_get_waitlist2))
      .exec(BookingHelper.getAllBookings(lrs_get_bookings1, lrs_get_bookings2))
      .foreach("${bookingidlist}", Constants.BOOKING_ID) {
          pause(30).
          exec(http(Constants.NOTIFY_ALL_BOOKING)
            .post(StringBody(lrs_notify_bookings1 + "${bookingid}"+ lrs_notify_bookings2))
            .header(Constants.AUTHORIZATION, """${token_type} ${access_token}""").header(Constants.CONTENT_TYPE, Constants.CONTENT_VALUE).body(StringBody(session => "somebody")).check(status.is(202)))
            .exec(ws("Check Websocket")
              .check(wsListen.within(60).until(1).regex("""NOTIFIED""")))

      }
  }

}



When I checked the log file, here is the error - 



Get Token	129491809211402198-0	REQUEST		Check Websocket	1535439248818	1535439276209	1535439276209	1535439276209	KO	Websocket 'gatling.http.webSocket' was unexpectedly closed with status 1006 and message Connection was closed abnormally (that is, with no close frame being sent).




I found below on console -



12:24:36.208 [New I/O worker #14][DEBUG] c.n.h.c.p.n.h.Processor - Channel Closed: [id: 0x3bf1e500, /192.168.2.12:55190 :> devconnect.lrsus.com/35.170.43.64:443] with attribute NettyResponseFuture{currentRetry=2,
        isDone=true,
        isCancelled=false,
        asyncHandler=com.ning.http.client.ws.WebSocketUpgradeHandler@476e929b,
        nettyRequest=com.ning.http.client.providers.netty.request.NettyRequest@7f30e4de,
        content=NettyWebSocket{channel=[id: 0x3bf1e500, /192.168.2.12:55190 :> devconnect.lrsus.com/35.170.43.64:443]},
        uri=wss://devconnect.lrsus.com/gs-guide-websocket/888/0ufnkstq/websocket,
        keepAlive=true,
        httpHeaders=org.jboss.netty.handler.codec.http.DefaultHttpHeaders@2cc9011,
        exEx=null,
        redirectCount=0,
        timeoutsHolder=null,
        inAuth=false,
        statusReceived=false,
        touch=496358570}
12:24:36.210 [New I/O worker #14][DEBUG] c.n.h.c.p.n.c.ChannelManager - Closing Channel [id: 0x3bf1e500, /192.168.2.12:55190 :> devconnect.lrsus.com/35.170.43.64:443]
12:24:36.211 [GatlingSystem-akka.actor.default-dispatcher-2][DEBUG] i.g.h.a.w.WsActor - Websocket 'gatling.http.webSocket' closed by the server




I tried to change below parameters in Gatling.conf but no luck