Jetty
  1. Jetty
  2. JETTY-1306

BayeuxClient EofException when under moderate load

    Details

    • Type: Bug Bug
    • Status: Resolved Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 7.2.0
    • Fix Version/s: 7.5.1
    • Component/s: Bayeux
    • Labels:
      None
    • Environment:
      I am using jetty 7.2.0, cometd 1.1.3, java 1.6.0_22 (Win XP, Mac OS X , Linux all exhibit same problem).
    • Number of attachments :
      2

      Description

      I'm writing a test harness to load test our cometd implementation. Using 1x HttpClient (32 threads) and a configurable number of BayeuxClient. I can readily reproduce the issue with a small number of clients (have seen with only 10 clients, gets worse with more clients). Each client subscribes to < 7 channels, and the server side is generating about 1 message per channel per second. JVM is given 1GB heap.

      I've setup the test harness to create BayeuxClient only once every 5 seconds so it really is being quite gentle. Have seen problem with as few as 10 BayeuxCLient started.

      org.eclipse.jetty.io.EofException
      at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:319)
      at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212)
      at org.eclipse.jetty.client.HttpConnection.handle(HttpConnection.java:262)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:510)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34)
      at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40)
      at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:450)
      at java.lang.Thread.run(Unknown Source)
      Caused by: org.eclipse.jetty.io.EofException
      at org.eclipse.jetty.io.nio.SslSelectChannelEndPoint.unwrap(SslSelectChannelEndPoint.java:693)
      at org.eclipse.jetty.io.nio.SslSelectChannelEndPoint.fill(SslSelectChannelEndPoint.java:323)
      at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:290)
      ... 7 more

      Here are some stats from our test harness showing summary every 30s:
      29/11/10 07:40:04,738 INFO [FelixBasherEventCoordinator] Connection: good/sec=3.17 attempted=95 failed=0 expired=0 exceptions=0
      29/11/10 07:40:34,739 INFO [FelixBasherEventCoordinator] Connection: good/sec=9.43 attempted=284 failed=0 expired=0 exceptions=1
      29/11/10 07:41:04,739 INFO [FelixBasherEventCoordinator] Connection: good/sec=14.53 attempted=436 failed=0 expired=0 exceptions=0
      29/11/10 07:41:34,739 INFO [FelixBasherEventCoordinator] Connection: good/sec=10.03 attempted=311 failed=0 expired=0 exceptions=10
      29/11/10 07:42:04,740 INFO [FelixBasherEventCoordinator] Connection: good/sec=16.43 attempted=493 failed=0 expired=0 exceptions=0
      29/11/10 07:42:34,740 INFO [FelixBasherEventCoordinator] Connection: good/sec=18.13 attempted=553 failed=0 expired=0 exceptions=9
      29/11/10 07:43:04,741 INFO [FelixBasherEventCoordinator] Connection: good/sec=12.20 attempted=395 failed=0 expired=0 exceptions=29
      29/11/10 07:43:34,741 INFO [FelixBasherEventCoordinator] Connection: good/sec=14.40 attempted=443 failed=0 expired=1 exceptions=10
      29/11/10 07:44:04,742 INFO [FelixBasherEventCoordinator] Connection: good/sec=31.17 attempted=935 failed=0 expired=0 exceptions=0
      29/11/10 07:44:34,742 INFO [FelixBasherEventCoordinator] Connection: good/sec=32.77 attempted=983 failed=0 expired=0 exceptions=0
      29/11/10 07:45:04,743 INFO [FelixBasherEventCoordinator] Connection: good/sec=10.70 attempted=350 failed=0 expired=0 exceptions=29
      29/11/10 07:45:34,744 INFO [FelixBasherEventCoordinator] Connection: good/sec=16.40 attempted=513 failed=0 expired=0 exceptions=21
      29/11/10 07:46:04,745 INFO [FelixBasherEventCoordinator] Connection: good/sec=9.03 attempted=313 failed=0 expired=0 exceptions=42
      29/11/10 07:46:34,752 INFO [FelixBasherEventCoordinator] Connection: good/sec=22.49 attempted=684 failed=0 expired=0 exceptions=9
      29/11/10 07:47:04,752 INFO [FelixBasherEventCoordinator] Connection: good/sec=13.03 attempted=402 failed=0 expired=10 exceptions=1

      1. jettyEOFSample.java
        2 kB
        Maxim Veksler
      2. jettyEOFSample.java
        2 kB
        Maxim Veksler

        Activity

        Hide
        Greg Wilkins added a comment -

        Hey Damian!

        Does this exception stop the client working?

        Is the exception reported as a warn or a debug?

        Show
        Greg Wilkins added a comment - Hey Damian! Does this exception stop the client working? Is the exception reported as a warn or a debug?
        Hide
        Greg Wilkins added a comment -

        Also if you could make some test case code available, that would be very helpful

        Show
        Greg Wilkins added a comment - Also if you could make some test case code available, that would be very helpful
        Hide
        Damian Carter added a comment -

        G'day Greg.

        Sorry for late reply. Flat out as usual. You know how it is...
        The client is able to recover from this error. Will check what the log level is.

        Show
        Damian Carter added a comment - G'day Greg. Sorry for late reply. Flat out as usual. You know how it is... The client is able to recover from this error. Will check what the log level is.
        Hide
        Maxim Veksler added a comment -

        Hello,

        I'm also seething exception (logback log format

        14:07:30.315 [qtp1288022528-19] DEBUG org.eclipse.jetty.util.log - EOF
        org.eclipse.jetty.io.EofException: null
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:319) ~[jetty-http-7.2.2.v20101205.jar:7.2.2.v20101205]
        at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212) ~[jetty-http-7.2.2.v20101205.jar:7.2.2.v20101205]
        at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:426) ~[jetty-server-7.2.2.v20101205.jar:7.2.2.v20101205]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:508) [jetty-io-7.2.2.v20101205.jar:7.2.2.v20101205]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34) [jetty-io-7.2.2.v20101205.jar:7.2.2.v20101205]
        at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40) [jetty-io-7.2.2.v20101205.jar:7.2.2.v20101205]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451) [jetty-util-7.2.2.v20101205.jar:7.2.2.v20101205]
        at java.lang.Thread.run(Thread.java:662) [na:1.6.0_22]

        No load. Always reproducible... Not interfering with the reply, client is getting the expected answer.

        Sample code following.

        Show
        Maxim Veksler added a comment - Hello, I'm also seething exception (logback log format 14:07:30.315 [qtp1288022528-19] DEBUG org.eclipse.jetty.util.log - EOF org.eclipse.jetty.io.EofException: null at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:319) ~ [jetty-http-7.2.2.v20101205.jar:7.2.2.v20101205] at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:212) ~ [jetty-http-7.2.2.v20101205.jar:7.2.2.v20101205] at org.eclipse.jetty.server.HttpConnection.handle(HttpConnection.java:426) ~ [jetty-server-7.2.2.v20101205.jar:7.2.2.v20101205] at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:508) [jetty-io-7.2.2.v20101205.jar:7.2.2.v20101205] at org.eclipse.jetty.io.nio.SelectChannelEndPoint.access$000(SelectChannelEndPoint.java:34) [jetty-io-7.2.2.v20101205.jar:7.2.2.v20101205] at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:40) [jetty-io-7.2.2.v20101205.jar:7.2.2.v20101205] at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:451) [jetty-util-7.2.2.v20101205.jar:7.2.2.v20101205] at java.lang.Thread.run(Thread.java:662) [na:1.6.0_22] No load. Always reproducible... Not interfering with the reply, client is getting the expected answer. Sample code following.
        Hide
        Maxim Veksler added a comment -

        Production code that is causing the problem, obscured.

        Show
        Maxim Veksler added a comment - Production code that is causing the problem, obscured.
        Maxim Veksler made changes -
        Field Original Value New Value
        Attachment jettyEOFSample.java [ 53423 ]
        Hide
        Maxim Veksler added a comment - - edited

        sorry, please ignore/delete.

        Show
        Maxim Veksler added a comment - - edited sorry, please ignore/delete.
        Maxim Veksler made changes -
        Attachment jettyEOFSample.java [ 53424 ]
        Greg Wilkins made changes -
        Assignee Simone Bordet [ sbordet ]
        Hide
        Simone Bordet added a comment -

        The latest versions of Jetty have improved half closes and idle timeout handling, which could have been causes of the errors reported.

        Also SSL has been substantially refactored, especially in the upcoming Jetty 7.5.2 version.

        I have been running SSL tests with recent CometD versions without problems, so I think this bug has been fixed by code improvements present in recent Jetty versions.

        I am closing this bug, but by all means please reopen it if latest Jetty versions still produce the error, along with exact steps to reproduce.

        Show
        Simone Bordet added a comment - The latest versions of Jetty have improved half closes and idle timeout handling, which could have been causes of the errors reported. Also SSL has been substantially refactored, especially in the upcoming Jetty 7.5.2 version. I have been running SSL tests with recent CometD versions without problems, so I think this bug has been fixed by code improvements present in recent Jetty versions. I am closing this bug, but by all means please reopen it if latest Jetty versions still produce the error, along with exact steps to reproduce.
        Simone Bordet made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Fix Version/s 7.5.1 [ 17834 ]
        Resolution Fixed [ 1 ]

          People

          • Assignee:
            Simone Bordet
            Reporter:
            Damian Carter
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: