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

[Slavik Fursov]

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))

[Stéphane LANDELLE]

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

Stéphane Landelle

Lead developer

slan...@gatling.io

--
You received this message because you are subscribed to the Google Groups "Gatling User Group" group.
To unsubscribe from this group and stop receiving emails from it, send an email to gatling+u...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Slavik Fursov]

Actually, 

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

[Slavik Fursov]

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...)?

[Stéphane LANDELLE]

- 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?

[Slavik Fursov]

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?

[Stéphane LANDELLE]

stdout, or wherever you output logback logs.

Stéphane Landelle

Lead developer

slan...@gatling.io

--

[Slavik Fursov]

So, you are talking about console.

The only thing I see in console is:

================================================================================

2015-08-25 17:25:33                                           5s elapsed

---- WebSocket -----------------------------------------------------------------

[--------------------------------------------------------------------------]  0%

          waiting: 0      / active: 1      / done:0     

---- Requests ------------------------------------------------------------------

> Global                                                   (OK=2      KO=1     )

> Connect WS                                               (OK=1      KO=0     )

> Sending query                                            (OK=1      KO=0     )

> Sending query Check                                      (OK=0      KO=1     )

---- Errors --------------------------------------------------------------------

> Websocket 'gatling.http.webSocket' was unexpectedly closed wit      1 (100.0%)

h status 1006 and message Connection was closed abnormally (th...

================================================================================

So, what I'm saying, is that Gatling really lacks detailed logging: I can't even see full message above - it is truncated.

And of course, it would be helpful to get more details - what was the cause, ...

[Stéphane LANDELLE]

Are you sure you have a logback.xml file?

Stéphane Landelle

Lead developer

slan...@gatling.io

--

[Slavik Fursov]

Yes,

I have following  logback.xml:

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">

<encoder>

<pattern>%d{HH:mm:ss.SSS} [%-5level] %logger{15} - %msg%n%rEx</pattern>

<immediateFlush>true</immediateFlush>

</encoder>

</appender>

   <logger name="io.gatling.http.ahc" level="TRACE" /> 

   <logger name="io.gatling.http.response" level="TRACE" /> 

<root level="WARN">

<appender-ref ref="CONSOLE" />

</root>

</configuration>

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

--
You received this message because you are subscribed to a topic in the Google Groups "Gatling User Group" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/gatling/6P0FBC_zdpg/unsubscribe.
To unsubscribe from this group and all its topics, send an email to gatling+u...@googlegroups.com.

[Pierre DAL-PRA]

Hi, 

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

Cheers,

Pierre 

[Slavik Fursov]

Thank you, Pierre!

That's what I was missing...

Yep.

Now, I see it:

12:49:16.566 [DEBUG] c.n.h.c.p.n.h.Processor - Unexpected I/O exception on channel [id: 0xc0a104e1, /10.20.40.16:56635 :> lassift02v.netiq.dmz/10.88.20.76:8080]

org.jboss.netty.handler.codec.frame.CorruptedFrameException: Max frame length of 10240 has been exceeded.

Seems like logback.xml is little inconsistent: even though, when I set 

logger name="io.gatling.http.ahc" level="TRACE"

It had no effect until I set:

root level="DEBUG"

Thank you.

[Pierre DAL-PRA]

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

On Wednesday, August 26, 2015, Slavik Fursov <slav...@gmail.com> wrote:

--

[Vrushali Pathrikar]

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

webSocketTimeout = 120000  # Timeout when a used websocket connection stays idle
webSocketMaxFrameSize = 163840 # Maximum frame payload size

My logback.xml

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
      <encoder>

         <pattern>%d{HH:mm:ss.SSS} [%thread{10}][%-5level] %logger{15} - %msg%n%rEx</pattern>
         <immediateFlush>false</immediateFlush>
      </encoder>
   </appender>


   <logger name="io.gatling.http.ahc" level="DEBUG" />
   <logger name="io.gatling.http.response" level="DEBUG" />

   <logger name="io.swagger.models.parameters.AbstractSerializableParameter" level="ERROR" />

   <root level="DEBUG">

      <appender-ref ref="CONSOLE" />
   </root>

</configuration>

Anything wrong with my simulation, configuration? What can be added in configuration so that I can troubleshoot the problem. 

thanks,
Vrushalee Ajotikar