MINA
  1. MINA
  2. DIRMINA-734

Regression with flushing in MINA 2.0.0-M7 trunk

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0.0-RC1
    • Fix Version/s: 2.0.0-RC1
    • Component/s: Core
    • Labels:
      None

      Description

      It looks like the present trunk of MINA in the repository
      has a bug. Updating from M7 built on 06.06.2009 to the current trunk
      broke some of our tests.

      I've tried to build it today and ran our application tests, some of
      them failed.

      Reverting back to 06.06.2009 build has fixed the problem.

      At the first look it appears that session.close(false) behaves like
      session.close(true), as a result some messages are truncated (not
      being flushed on session.close(false)).

      If I comment out a call to session.close(false) (i.e. not closing the
      session at all when needed), the problem goes away.

      This behavior is inconsistent, test fails/succeeds randomly. On the
      first run it may pass, on the second run it may fail. Test fails about
      10% of runs. The part which is not flushed is also random. Could be a
      race condition somewhere in MINA introduced in the last 2 months.

      I can't provide a test case yet, but our application is a kind of
      proxy, so it behaves like this:

      1. client connects to the app and send a request
      2. app connects to another server and sends a request
      3. app gets a reply from the server and sends it back to the client
      4. when another server closes the connection, app is closing the
      connection with the client using session.close(false)

      The app may be still flushing data to client when closing the
      connection. As I said it worked fine with previous MINA versions, but
      has broken only recently.

      We are using OrderedThreadPoolExecutor and CumulativeProtocolDecoder
      if that matters.

        Activity

        Hide
        Emmanuel Lecharny added a comment -

        Assuming your system works like that :

        Client <===> Proxy <===> Application

        do you close the session when the Application has sent its last message, or are you expecting some more message to be received ? In other words, do you close here :

        Client ---> proxy ---> Application --+
        Client <--- proxy <* Application<--+

        (when the message is received from the application, '*' being the message)

        or here :
        Client --> proxy -*> Application --+
        Client <--- proxy <--- Application<--+

        (just after having transmitted the message to the application)

        Otherwise, the session code hasn't been changed in this area since last release.

        Show
        Emmanuel Lecharny added a comment - Assuming your system works like that : Client <===> Proxy <===> Application do you close the session when the Application has sent its last message, or are you expecting some more message to be received ? In other words, do you close here : Client ---> proxy ---> Application --+ Client <--- proxy < * Application<--+ (when the message is received from the application, '*' being the message) or here : Client -- > proxy -* > Application --+ Client <--- proxy <--- Application<--+ (just after having transmitted the message to the application) Otherwise, the session code hasn't been changed in this area since last release.
        Hide
        Serge Baranov added a comment - - edited

        The application based on MINA is a proxy by itself, so it would be:

        client <====> our application based on mina <====> some server

        When the server closes connection, application closes connection with the client using session.close(false), same as in the example provided with MINA:
        mina\example\src\main\java\org\apache\mina\example\proxy\AbstractProxyIoHandler.java:

        public void sessionClosed(IoSession session) throws Exception {
        if (session.getAttribute( OTHER_IO_SESSION ) != null)

        { IoSession sess = (IoSession) session.getAttribute(OTHER_IO_SESSION); sess.setAttribute(OTHER_IO_SESSION, null); sess.close(false); session.setAttribute(OTHER_IO_SESSION, null); }

        }

        Show
        Serge Baranov added a comment - - edited The application based on MINA is a proxy by itself, so it would be: client <====> our application based on mina <====> some server When the server closes connection, application closes connection with the client using session.close(false), same as in the example provided with MINA: mina\example\src\main\java\org\apache\mina\example\proxy\AbstractProxyIoHandler.java: public void sessionClosed(IoSession session) throws Exception { if (session.getAttribute( OTHER_IO_SESSION ) != null) { IoSession sess = (IoSession) session.getAttribute(OTHER_IO_SESSION); sess.setAttribute(OTHER_IO_SESSION, null); sess.close(false); session.setAttribute(OTHER_IO_SESSION, null); } }
        Hide
        Emmanuel Lecharny added a comment -

        It's difficult to know what is happening here, without a sample demonstrating the problem. There have been some fixes in the ExecutorFilter since last release, but they were quite necessary.

        I'm trying to list all the important changes since M6.

        Show
        Emmanuel Lecharny added a comment - It's difficult to know what is happening here, without a sample demonstrating the problem. There have been some fixes in the ExecutorFilter since last release, but they were quite necessary. I'm trying to list all the important changes since M6.
        Hide
        Serge Baranov added a comment -

        I've prepared and attached a test for this issue. It's based on the MINA proxy example.
        Please see the instructions inside README.txt.

        This scenario requires an Apache server to reproduce, however you can use some large html page instead hosted on any public server, just change the options used for running the proxy and the client.

        Show
        Serge Baranov added a comment - I've prepared and attached a test for this issue. It's based on the MINA proxy example. Please see the instructions inside README.txt. This scenario requires an Apache server to reproduce, however you can use some large html page instead hosted on any public server, just change the options used for running the proxy and the client.
        Hide
        Emmanuel Lecharny added a comment -

        When I run the sample, I get a NPE :

        [12:06:39] MinaProxyThread WARN [] [] [org.apache.mina.core.service.IoHandlerAdapter] - EXCEPTION, please implement org.apache.mina.example.proxy.ServerToProxyIoHandler.exceptionCaught() for proper handling:
        java.lang.NullPointerException
        at org.apache.mina.example.proxy.AbstractProxyIoHandler.messageReceived(AbstractProxyIoHandler.java:73)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:713)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$5(DefaultIoFilterChain.java:429)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:793)
        at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:71)
        at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63)
        at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(OrderedThreadPoolExecutor.java:780)
        at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(OrderedThreadPoolExecutor.java:772)
        at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThreadPoolExecutor.java:714)
        at java.lang.Thread.run(Thread.java:619)

        This is due to the fact that the OTHER_IO_SESSION attribute is not stored into the session... Can you check on your side ?

        Show
        Emmanuel Lecharny added a comment - When I run the sample, I get a NPE : [12:06:39] MinaProxyThread WARN [] [] [org.apache.mina.core.service.IoHandlerAdapter] - EXCEPTION, please implement org.apache.mina.example.proxy.ServerToProxyIoHandler.exceptionCaught() for proper handling: java.lang.NullPointerException at org.apache.mina.example.proxy.AbstractProxyIoHandler.messageReceived(AbstractProxyIoHandler.java:73) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.messageReceived(DefaultIoFilterChain.java:713) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextMessageReceived(DefaultIoFilterChain.java:434) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$5(DefaultIoFilterChain.java:429) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.messageReceived(DefaultIoFilterChain.java:793) at org.apache.mina.core.filterchain.IoFilterEvent.fire(IoFilterEvent.java:71) at org.apache.mina.core.session.IoEvent.run(IoEvent.java:63) at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTask(OrderedThreadPoolExecutor.java:780) at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.runTasks(OrderedThreadPoolExecutor.java:772) at org.apache.mina.filter.executor.OrderedThreadPoolExecutor$Worker.run(OrderedThreadPoolExecutor.java:714) at java.lang.Thread.run(Thread.java:619) This is due to the fact that the OTHER_IO_SESSION attribute is not stored into the session... Can you check on your side ?
        Hide
        Serge Baranov added a comment -

        You are probably running different sample (or the build-in example), or you have some classpath issue, as the sample I've attached has different package for the proxy example classes, you have

        org.apache.mina.example.proxy.AbstractProxyIoHandler.messageReceived(AbstractProxyIoHandler.java:73)

        while in my test it would be

        foo.AbstractProxyIoHandler.messageReceived.

        I've verified that the attached test case works fine.

        Show
        Serge Baranov added a comment - You are probably running different sample (or the build-in example), or you have some classpath issue, as the sample I've attached has different package for the proxy example classes, you have org.apache.mina.example.proxy.AbstractProxyIoHandler.messageReceived(AbstractProxyIoHandler.java:73) while in my test it would be foo.AbstractProxyIoHandler.messageReceived. I've verified that the attached test case works fine.
        Hide
        Emmanuel Lecharny added a comment -

        The package has been changed just for convenienc : I'm runn ing the test inside the trunk.

        Otherwise, it's all the same test.

        I will run it again, now that I have had some food and coffee

        Show
        Emmanuel Lecharny added a comment - The package has been changed just for convenienc : I'm runn ing the test inside the trunk. Otherwise, it's all the same test. I will run it again, now that I have had some food and coffee
        Hide
        Serge Baranov added a comment -

        Then you have a classpath issue. My example has exceptionCaught implemented and logging commented out. Also, I don't get the NPE you have as it would mean that the example provided with MINA is broken.

        Show
        Serge Baranov added a comment - Then you have a classpath issue. My example has exceptionCaught implemented and logging commented out. Also, I don't get the NPE you have as it would mean that the example provided with MINA is broken.
        Hide
        Emmanuel Lecharny added a comment -

        My bad, I was confusing the Proxy sample and your code

        Let me give it a second run ...

        Show
        Emmanuel Lecharny added a comment - My bad, I was confusing the Proxy sample and your code Let me give it a second run ...
        Hide
        Emmanuel Lecharny added a comment -

        I confirm I have the problem you have :

        ...
        [14:21:44] MinaProxyThread ERROR [] [] [org.apache.mina.example.serge.AbstractProxyIoHandler] - Error
        org.apache.mina.core.write.WriteToClosedSessionException
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.clearWriteRequestQueue(AbstractPollingIoProcessor.java:573)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:525)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:497)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$9(AbstractPollingIoProcessor.java:482)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:974)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
        at java.lang.Thread.run(Thread.java:619)
        ...

        Let's start a debugging session ...

        Show
        Emmanuel Lecharny added a comment - I confirm I have the problem you have : ... [14:21:44] MinaProxyThread ERROR [] [] [org.apache.mina.example.serge.AbstractProxyIoHandler] - Error org.apache.mina.core.write.WriteToClosedSessionException at org.apache.mina.core.polling.AbstractPollingIoProcessor.clearWriteRequestQueue(AbstractPollingIoProcessor.java:573) at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:525) at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:497) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$9(AbstractPollingIoProcessor.java:482) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:974) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) at java.lang.Thread.run(Thread.java:619) ... Let's start a debugging session ...
        Hide
        Emmanuel Lecharny added a comment -

        After having add some logs, I get those traces when the program fails :

        ...
        1 <Client Message received for Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80)
        2 <Client Scheduling session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) for removal, ret < 0 (1)
        3 <Client Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) scheduled for removal
        4 <Client Message received for Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80)
        5 <Client Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) closed
        6 >Server Scheduling session (0x00000030: nio socket, server, /127.0.0.1:39726 => /127.0.0.1:8081) for removal in remove( T )
        7 >Server Session (0x00000030: nio socket, server, /127.0.0.1:39726 => /127.0.0.1:8081) scheduled for removal
        8 >Server Exception caught for session (0x00000030: nio socket, server, /127.0.0.1:39726 => /127.0.0.1:8081)
        [16:27:13] MinaProxyThread ERROR [] [] [org.apache.mina.example.serge.AbstractProxyIoHandler] - Error
        org.apache.mina.core.write.WriteToClosedSessionException

        As you can see, the remote server does not have anything more to send, or seems to have nothing more to sent (line 2). The place where the removal is called is in the read(Session) method, which tries to read bytes from the remote server (http). But strange enough, there is another MessageReceived which is sent (line 4), while the session is being closed...

        May be the initial request was not complete ?

        Show
        Emmanuel Lecharny added a comment - After having add some logs, I get those traces when the program fails : ... 1 <Client Message received for Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) 2 <Client Scheduling session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) for removal, ret < 0 (1) 3 <Client Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) scheduled for removal 4 <Client Message received for Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) 5 <Client Session (0x00000031: nio socket, client, /192.168.0.51:49669 => iktek.com/88.191.29.20:80) closed 6 >Server Scheduling session (0x00000030: nio socket, server, /127.0.0.1:39726 => /127.0.0.1:8081) for removal in remove( T ) 7 >Server Session (0x00000030: nio socket, server, /127.0.0.1:39726 => /127.0.0.1:8081) scheduled for removal 8 >Server Exception caught for session (0x00000030: nio socket, server, /127.0.0.1:39726 => /127.0.0.1:8081) [16:27:13] MinaProxyThread ERROR [] [] [org.apache.mina.example.serge.AbstractProxyIoHandler] - Error org.apache.mina.core.write.WriteToClosedSessionException As you can see, the remote server does not have anything more to send, or seems to have nothing more to sent (line 2). The place where the removal is called is in the read(Session) method, which tries to read bytes from the remote server (http). But strange enough, there is another MessageReceived which is sent (line 4), while the session is being closed... May be the initial request was not complete ?
        Hide
        Emmanuel Lecharny added a comment -

        Ok, it's seriously broken ... I will start with M6, and test it with all the successive patches until I find the one which breaks the test.

        Show
        Emmanuel Lecharny added a comment - Ok, it's seriously broken ... I will start with M6, and test it with all the successive patches until I find the one which breaks the test.
        Hide
        Emmanuel Lecharny added a comment -

        Ok the commit which caused the regression is http://svn.apache.org/viewvc?rev=787043&view=rev

        I have started from revision 781014, svn up revision after revision, running your test for each one of them, and found that this is the one responsible.

        Now I have to understand why...

        PS: It was not as painful as it sounds : just a matter of half an hour, for those interested in the processus. In fact, there were only 16 revisions between M6 and the one which introduce a regression, out of which probably 5 or 6 only were touching the code (the other ones touched tests, or pom.xml)

        Show
        Emmanuel Lecharny added a comment - Ok the commit which caused the regression is http://svn.apache.org/viewvc?rev=787043&view=rev I have started from revision 781014, svn up revision after revision, running your test for each one of them, and found that this is the one responsible. Now I have to understand why... PS: It was not as painful as it sounds : just a matter of half an hour, for those interested in the processus. In fact, there were only 16 revisions between M6 and the one which introduce a regression, out of which probably 5 or 6 only were touching the code (the other ones touched tests, or pom.xml)
        Hide
        Emmanuel Lecharny added a comment -

        Should be fix with http://svn.apache.org/viewvc?rev=801833&view=rev.

        Many thanks Serge for your patience, and for the test case !

        Show
        Emmanuel Lecharny added a comment - Should be fix with http://svn.apache.org/viewvc?rev=801833&view=rev . Many thanks Serge for your patience, and for the test case !
        Hide
        Emmanuel Lecharny added a comment -

        Closing issues

        Show
        Emmanuel Lecharny added a comment - Closing issues

          People

          • Assignee:
            Emmanuel Lecharny
            Reporter:
            Serge Baranov
          • Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development