glassfish
  1. glassfish
  2. GLASSFISH-19567

non-blocking IO input with large file test failed

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 4.0_b75
    • Component/s: web_container
    • Labels:
      None
    • Environment:

      linux oel6
      jdk1.7.0_03

      Description

      Build: 01/18 nightly build

      This test case is to test non-blocking IO with a large file ( javax.servlet.jsp.jar, file size 537532). Test description:

      • client sends the large file javax.servlet.jsp.jar to the server
      • In the server side, set input.setReadListener(readListener), invokes onDataAvailable() on the readListener, then reads the data and writes/sends response back to the client.
      • client receives the response and writes the data to a temp file, and then, I compare the original file size with the response file size. If the file sizes are the same, the test pass.

      Steps to reproduce the bug:
      1. Install GF4.0, start domain
      2. Checkout SQE workspace cvs co appserver-sqe/bootstrap.xml
      (CVSROOT: :pserver:<your cvs user name>@sunsw.us.oracle.com:/m/jws
      cd appserver-sqe
      ant -f bootstrap.xml co-tomcat
      3.set env. variables
      S1AS_HOME <GF install dir>, for example: /export/sonia/v4/glassfish3/glassfish
      SPS_HOME <appserver-sqe>, for example: /export/sonia/appserver-sqe
      ANT_HOME <ant location>, for example: /export/sonia/ant-1.7.1
      JAVA_HOME <java location>, for example: /export/sonia/jdk1.7.0
      4. cd /export/sonia/appserver-sqe/pe/tomcat/servlet/product_test/servlet3_1/nonBlockingInputFile, run
      ant build setup deploy run
      5. The test failed and I found that only partial of the data sent back to the client side (please see the base.length and file.length difference below):

      [java] base.length 537532
      [java] file.length 277984
      [java] Generating report at /export/sonia/appserver-sqe/test_results.xml
      [java]
      [java]
      [java] -----------------------------------------
      [java] - non-blocking-Input-bigfile: FAIL -
      [java] -----------------------------------------
      [java] Total PASS: 0
      [java] Total FAIL: 1
      [java] Total DNR: 0
      [java] -----------------------------------------

      --------And the server.log showed the following exception: ---------
      --------------------------------------------------------------------------

      [#|2013-01-22T09:52:19.086-0800|INFO|glassfish 4.0|javax.enterprise.logging.stdout|_ThreadID=17;_ThreadName=http-listener-1(1);_TimeMillis=1358877139086;_LevelValue=800;|total bytes read 277984|#]

      [#|2013-01-22T09:52:49.088-0800|WARNING|glassfish 4.0|javax.enterprise.web.core|_ThreadID=17;_ThreadName=http-listener-1(1);_TimeMillis=1358877169088;_LevelValue=900;_MessageID=AS-WEB-CORE-00353;|Error in invoking ReadListener.onDataAvailable
      java.lang.IllegalStateException: java.io.IOException: java.util.concurrent.TimeoutException
      at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onDataAvailable(TestServlet.java:70)
      at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.processDataAvailable(InputBuffer.java:456)
      at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.onDataAvailable(InputBuffer.java:438)
      at org.apache.catalina.connector.InputBuffer.setReadListener(InputBuffer.java:310)
      at org.apache.catalina.connector.CoyoteInputStream.setReadListener(CoyoteInputStream.java:312)
      at com.sun.s1wsqe.tomcat.servlet31.TestServlet.service(TestServlet.java:34)
      at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
      at org.apache.catalina.core.StandardWrapper.service(StandardWrapper.java:1682)
      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:342)
      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:160)
      at org.apache.catalina.core.StandardPipeline.doInvoke(StandardPipeline.java:734)
      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:673)
      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:176)
      at org.apache.catalina.connector.CoyoteAdapter.doService(CoyoteAdapter.java:357)
      at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:260)
      at com.sun.enterprise.v3.services.impl.ContainerMapper.service(ContainerMapper.java:188)
      at org.glassfish.grizzly.http.server.HttpHandler.doHandle(HttpHandler.java:164)
      at org.glassfish.grizzly.http.server.HttpServerFilter.handleRead(HttpServerFilter.java:175)
      at org.glassfish.grizzly.filterchain.ExecutorResolver$9.execute(ExecutorResolver.java:119)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeFilter(DefaultFilterChain.java:273)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.executeChainPart(DefaultFilterChain.java:200)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.execute(DefaultFilterChain.java:134)
      at org.glassfish.grizzly.filterchain.DefaultFilterChain.process(DefaultFilterChain.java:112)
      at org.glassfish.grizzly.ProcessorExecutor.execute(ProcessorExecutor.java:77)
      at org.glassfish.grizzly.nio.transport.TCPNIOTransport.fireIOEvent(TCPNIOTransport.java:818)
      at org.glassfish.grizzly.strategies.AbstractIOStrategy.fireIOEvent(AbstractIOStrategy.java:112)
      at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.run0(WorkerThreadIOStrategy.java:115)
      at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy.access$100(WorkerThreadIOStrategy.java:55)
      at org.glassfish.grizzly.strategies.WorkerThreadIOStrategy$WorkerThreadRunnable.run(WorkerThreadIOStrategy.java:135)
      at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.doWork(AbstractThreadPool.java:562)
      at org.glassfish.grizzly.threadpool.AbstractThreadPool$Worker.run(AbstractThreadPool.java:542)
      at java.lang.Thread.run(Thread.java:722)
      Caused by: java.io.IOException: java.util.concurrent.TimeoutException
      at org.glassfish.grizzly.utils.Exceptions.makeIOException(Exceptions.java:62)
      at org.glassfish.grizzly.http.server.io.OutputBuffer.blockAfterWriteIfNeeded(OutputBuffer.java:959)
      at org.glassfish.grizzly.http.server.io.OutputBuffer.write(OutputBuffer.java:690)
      at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:351)
      at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:338)
      at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:161)
      at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onDataAvailable(TestServlet.java:64)
      ... 31 more
      Caused by: java.util.concurrent.TimeoutException
      at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:258)
      at java.util.concurrent.FutureTask.get(FutureTask.java:119)
      at org.glassfish.grizzly.http.server.io.OutputBuffer.blockAfterWriteIfNeeded(OutputBuffer.java:952)
      ... 36 more

      #]

      6. If I modify the test to use a small size file (file size 630) for testing, the test passed without any test code change.
      7. I did some debug and here is what I found:
      In the onDataAvailable() method, I have the following code:
      public void onDataAvailable() {
      try {
      System.out.println("It's in onDataAvailable");

      int bytesRead = -1;
      long total = 0;
      byte[] buf = new byte[4 * 1024];
      //while (input.isReady()
      // && (bytesRead = input.read(buf)) != -1) {
      while ((bytesRead = input.read(buf)) != -1)

      { total += bytesRead; System.out.println("total bytes read " + total); output.write(buf, 0, bytesRead); }

      output.close();
      input.close();
      } catch(Exception ex)

      { throw new IllegalStateException(ex); }

      If I un-comment out the following code:
      while (input.isReady()
      && (bytesRead = input.read(buf)) != -1)

      { ... }

      And comment out the while ((bytesRead = input.read(buf)) != -1) {
      I saw the test went to onDataAvailable(), printed out "It's in onDataAvailable" and went to the while (input.isReady()... loop, after read 4088 data, it came out from the while loop and back to print out "It's in onDataAvailable" and went to the while loop again, and so on... See the server.log output below:

      [#|2013-01-22T09:33:23.175-0800|INFO|glassfish 4.0|javax.enterprise.logging.stdout|_ThreadID=16;_ThreadName=http-listener-1(1);_TimeMillis=1358876003175;_LevelValue=800;|It's in onDataAvailable|#]

      [#|2013-01-22T09:33:23.175-0800|INFO|glassfish 4.0|javax.enterprise.logging.stdout|_ThreadID=16;_ThreadName=http-listener-1(1);_TimeMillis=1358876003175;_LevelValue=800;|total bytes read 4088|#]

      [#|2013-01-22T09:33:23.192-0800|INFO|glassfish 4.0|javax.enterprise.logging.stdout|_ThreadID=66;_ThreadName=glassfish-web-async-thread-1;_TimeMillis=1358876003192;_LevelValue=800;|It's in onDataAvailable|#]

      In the client side, the client only received 4088 size data in this case.

        Activity

        Hide
        sonialiu added a comment -

        add component

        Show
        sonialiu added a comment - add component
        Hide
        Shing Wai Chan added a comment -

        After updating WebTest.java, the test passes in my local machine as follows:

        [java] WS HOME appserver-sqe
        [java] The url is http://localhost:8080//tomcat-servlet31-nonblockinginput-bigfile/nonBlockingInputBigfile
        [java] Start writing data...
        [java] Done writing data
        [java] Got response
        [java] Sleeping 30 sec
        [java] Finished reading and generating file
        [java] base.length 547458
        [java] file.length 547458
        [java] Generating report at /export/gf4/sqe/appserver-sqe/test_results.xml
        [java]
        [java]
        [java] -----------------------------------------
        [java] - non-blocking-Input-bigfile: PASS -
        [java] -----------------------------------------
        [java] Total PASS: 1
        [java] Total FAIL: 0
        [java] Total DNR: 0
        [java] -----------------------------------------

        In testing machine, I observe the following:

        java.lang.IllegalStateException: java.io.IOException: java.util.concurrent.TimeoutException
        	at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onDataAvailable(TestServlet.java:64)
        	at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.processDataAvailable(InputBuffer.java:456)
        	at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.access$200(InputBuffer.java:427)
        	at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl$1.run(InputBuffer.java:443)
        	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110)
        	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
        	at java.lang.Thread.run(Thread.java:722)
        Caused by: java.io.IOException: java.util.concurrent.TimeoutException
        	at org.glassfish.grizzly.utils.Exceptions.makeIOException(Exceptions.java:62)
        	at org.glassfish.grizzly.http.server.io.OutputBuffer.blockAfterWriteIfNeeded(OutputBuffer.java:959)
        	at org.glassfish.grizzly.http.server.io.OutputBuffer.write(OutputBuffer.java:690)
        	at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:351)
        	at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:338)
        	at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:161)
        	at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onDataAvailable(TestServlet.java:60)
        	... 6 more
        Caused by: java.util.concurrent.TimeoutException
        	at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:258)
        	at java.util.concurrent.FutureTask.get(FutureTask.java:119)
        	at org.glassfish.grizzly.http.server.io.OutputBuffer.blockAfterWriteIfNeeded(OutputBuffer.java:952)
        	... 11 more
        
        Show
        Shing Wai Chan added a comment - After updating WebTest.java, the test passes in my local machine as follows: [java] WS HOME appserver-sqe [java] The url is http://localhost:8080//tomcat-servlet31-nonblockinginput-bigfile/nonBlockingInputBigfile [java] Start writing data... [java] Done writing data [java] Got response [java] Sleeping 30 sec [java] Finished reading and generating file [java] base.length 547458 [java] file.length 547458 [java] Generating report at /export/gf4/sqe/appserver-sqe/test_results.xml [java] [java] [java] ----------------------------------------- [java] - non-blocking-Input-bigfile: PASS - [java] ----------------------------------------- [java] Total PASS: 1 [java] Total FAIL: 0 [java] Total DNR: 0 [java] ----------------------------------------- In testing machine, I observe the following: java.lang.IllegalStateException: java.io.IOException: java.util.concurrent.TimeoutException at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onDataAvailable(TestServlet.java:64) at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.processDataAvailable(InputBuffer.java:456) at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl.access$200(InputBuffer.java:427) at org.apache.catalina.connector.InputBuffer$ReadHandlerImpl$1.run(InputBuffer.java:443) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1110) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603) at java.lang. Thread .run( Thread .java:722) Caused by: java.io.IOException: java.util.concurrent.TimeoutException at org.glassfish.grizzly.utils.Exceptions.makeIOException(Exceptions.java:62) at org.glassfish.grizzly.http.server.io.OutputBuffer.blockAfterWriteIfNeeded(OutputBuffer.java:959) at org.glassfish.grizzly.http.server.io.OutputBuffer.write(OutputBuffer.java:690) at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:351) at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:338) at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:161) at com.sun.s1wsqe.tomcat.servlet31.TestServlet$ReadListenerImpl.onDataAvailable(TestServlet.java:60) ... 6 more Caused by: java.util.concurrent.TimeoutException at java.util.concurrent.FutureTask$Sync.innerGet(FutureTask.java:258) at java.util.concurrent.FutureTask.get(FutureTask.java:119) at org.glassfish.grizzly.http.server.io.OutputBuffer.blockAfterWriteIfNeeded(OutputBuffer.java:952) ... 11 more
        Hide
        Shing Wai Chan added a comment -

        I have run the test in Oracle Linux 6.3 with the latest jdk 7 (u11). The test passes.

        Show
        Shing Wai Chan added a comment - I have run the test in Oracle Linux 6.3 with the latest jdk 7 (u11). The test passes.
        Hide
        Shing Wai Chan added a comment -

        The timeout configuration issue has been filed in http://java.net/jira/browse/GRIZZLY-1420 .
        We are waiting for a Grizzly integration.

        On the other hand, per discussion with Alexey, there is a potential issue in the test case.
        In client/WebTest.java, it has sent the whole file before reading any data.
        In web/TestServlet.java, it read the data and sent back immediately.
        With the above, the test will work if the underlying socket can buffer the whole file.

        I recommend to change the test as either one of the following way:
        (a) Don't send back the whole file. Just send the a digest of the byte back.
        (b) The TestServlet saves the bytes in a temp file and then send it back once the whole file is written.

        Show
        Shing Wai Chan added a comment - The timeout configuration issue has been filed in http://java.net/jira/browse/GRIZZLY-1420 . We are waiting for a Grizzly integration. On the other hand, per discussion with Alexey, there is a potential issue in the test case. In client/WebTest.java, it has sent the whole file before reading any data. In web/TestServlet.java, it read the data and sent back immediately. With the above, the test will work if the underlying socket can buffer the whole file. I recommend to change the test as either one of the following way: (a) Don't send back the whole file. Just send the a digest of the byte back. (b) The TestServlet saves the bytes in a temp file and then send it back once the whole file is written.
        Hide
        Shing Wai Chan added a comment -

        The configuration of timeout is fixed in
        http://java.net/jira/browse/GRIZZLY-1420

        It can be configured in admin console as follows:
        Network Config > Transports > tcp > Read Timeout, Write Timeout

        Show
        Shing Wai Chan added a comment - The configuration of timeout is fixed in http://java.net/jira/browse/GRIZZLY-1420 It can be configured in admin console as follows: Network Config > Transports > tcp > Read Timeout, Write Timeout

          People

          • Assignee:
            Shing Wai Chan
            Reporter:
            sonialiu
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: