You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by Martin Alderson <Ma...@salfordsoftware.co.uk> on 2007/09/18 12:42:05 UTC

WriteTimeoutException immediately following write

Hi all,

I don't know too much about Mina so forgive me if I say anything stupid!

I have hit a problem with my own hacked about version of ApacheDS.  ApacheDS is an LDAP server which uses Mina 1.1.2 for its replication service.

The problem I am experiencing is that I have a replication (write) scheduled to occur every 60 seconds, and occasionally when this occurs I will immediately get a WriteTimeoutException.  I understand the default write timeout is also 60 seconds.  The strange thing is the two servers are running on the same machine and looking at the logs it seems that all previous messages were sent.

I am wondering if it is possible that when my new write is attempted the timeout is checked at the same time - so Mina thinks there is a write pending and sees that the last message was sent more than 60 seconds ago (which would be possible depending on the thread timing!)

Has anyone experienced something like this before?  Does this sound like a possible scenario?

Thanks,

Martin



Re: WriteTimeoutException immediately following write

Posted by "이희승 (Trustin Lee)" <tr...@gmail.com>.
2007-11-04 (일), 13:40 -0800, Seth Pollack 쓰시길:
> 
> > Whenever something is
> > written, lastWriteTime is updated automatically, and
> > WriteTimeoutException is raised only when lastWriteTime has not been
> > updated for a certain amount of time.  Looking into
> > SocketIoProcessor.java, it attempts to write first (i.e. doFlush())
> > and then check timeout (i.e. notifyIdleness()).  
> 
> I have a related question. 
> 
> Is it possible to ever get a WriteTimeoutException because of something
> moving very slowly on the writing app side, or can this only be caused by
> the receiving app side moving slowly (i.e. not accepting any bytes for more
> than the writeTimeout period)? In the code I saw the comment "// Kernel
> buffer is full" in the case where there are bytes to write that can't be
> written. What are the possible causes of this condition?

It's thrown only when the receiving party is not receiving the data fast enough, which lead the full kernel send buffer.
-- 
what we call human nature is actually human habit
--
http://gleamynode.net/

Re: WriteTimeoutException immediately following write

Posted by Seth Pollack <se...@pollackphoto.com>.

> Whenever something is
> written, lastWriteTime is updated automatically, and
> WriteTimeoutException is raised only when lastWriteTime has not been
> updated for a certain amount of time.  Looking into
> SocketIoProcessor.java, it attempts to write first (i.e. doFlush())
> and then check timeout (i.e. notifyIdleness()).  

I have a related question. 

Is it possible to ever get a WriteTimeoutException because of something
moving very slowly on the writing app side, or can this only be caused by
the receiving app side moving slowly (i.e. not accepting any bytes for more
than the writeTimeout period)? In the code I saw the comment "// Kernel
buffer is full" in the case where there are bytes to write that can't be
written. What are the possible causes of this condition?

-- 
View this message in context: http://www.nabble.com/WriteTimeoutException-immediately-following-write-tf4473340s16868.html#a13578097
Sent from the Apache MINA Support Forum mailing list archive at Nabble.com.


Re: WriteTimeoutException immediately following write

Posted by Martin Alderson <Ma...@salfordsoftware.co.uk>.
Hi Trustin,

I just returned to this problem and have figured out why you couldn't reproduce it - you fixed the problem just before you tested it!

You committed a fix on the 5/11/2007 for DIRMINA-469 with comment: "Fixed as described in the issue tracker; removed the problematic if statement and added another sanity check code that doesn't cause the problem."  This problematic if statement (if (key.isWritable()) around the write in SocketIoProcessor#doFlush) was also causing the WriteTimeoutExceptions I was experiencing.

The fix is included in MINA 1.1.5 so I'll upgrade to that.

Thanks for fixing the problem (even if you didn't mean to!) and thanks for trying to reproduce the problem.

Martin



>>> "Trustin Lee" <tr...@gmail.com> 06/11/2007 05:01 >>>
Hi Martin,

Unfortunately, I simply can't reproduce the problem.  The chat client
and server are running more than 30 minutes now... :-(

Thanks anyway!
Trustin

On 10/30/07, Martin Alderson <ma...@salfordsoftware.co.uk> wrote:
> Hi Trustin,
>
> I've only just noticed you replied!
>
> Thanks for getting back to me on this.  I put some effort into creating
> a reproducible example of this problem today.  I couldn't find any
> existing tests that could be used for this so I just hijacked the chat
> example.  I managed to get this example to give some
> WriteTimeoutExceptions with just the following code added to the login
> method of the ChatClientSupport class:
>
>          final int PERIOD_SECONDS = 3;
>          session.getConfig().setWriteTimeout(PERIOD_SECONDS);
>          Timer timer = new Timer();
>          timer.scheduleAtFixedRate(new TimerTask() {
>              public void run () {
>                  session.write("BROADCAST testJob");
>              }
>          }, 0, PERIOD_SECONDS * 1000);
>
> I've attached the full modified copy of the ChatClientSupport class
> (originally from trunk).  I hope that's OK - it's only 4K.
>
> To reproduce the problem just start up the server and client with this
> modification, press the connect button and wait for a
> WriteTimeoutException to show up.  I've not had to wait more than a
> minute for it on my machine.
>
> The log output shows that all previous messages were sent and received.
>
> Thanks,
>
> Martin
>
>
>
> Trustin Lee wrote:
> > Hi Martin,
> >
> > Apologies for the late response....
> >
> > On 9/18/07, Martin Alderson <Ma...@salfordsoftware.co.uk> wrote:
> >> Hi all,
> >>
> >> I don't know too much about Mina so forgive me if I say anything stupid!
> >>
> >> I have hit a problem with my own hacked about version of ApacheDS.  ApacheDS is an LDAP server which uses Mina 1.1.2 for its replication service.
> >>
> >> The problem I am experiencing is that I have a replication (write) scheduled to occur every 60 seconds, and occasionally when this occurs I will immediately get a WriteTimeoutException.  I understand the default write timeout is also 60 seconds.  The strange thing is the two servers are running on the same machine and looking at the logs it seems that all previous messages were sent.
> >>
> >> I am wondering if it is possible that when my new write is attempted the timeout is checked at the same time - so Mina thinks there is a write pending and sees that the last message was sent more than 60 seconds ago (which would be possible depending on the thread timing!)
> >>
> >> Has anyone experienced something like this before?  Does this sound like a possible scenario?
> >
> > I think it can happen, but it shouldn't happen.  Whenever something is
> > written, lastWriteTime is updated automatically, and
> > WriteTimeoutException is raised only when lastWriteTime has not been
> > updated for a certain amount of time.  Looking into
> > SocketIoProcessor.java, it attempts to write first (i.e. doFlush())
> > and then check timeout (i.e. notifyIdleness()).  Are you sure the
> > caught WriteTimeoutException is for the successfully written message?
> > Any simplified test case would be appreciated.
> >
> > Thanks,
> > Trustin
>
>
> /*
>  *  Licensed to the Apache Software Foundation (ASF) under one
>  *  or more contributor license agreements.  See the NOTICE file
>  *  distributed with this work for additional information
>  *  regarding copyright ownership.  The ASF licenses this file
>  *  to you under the Apache License, Version 2.0 (the
>  *  "License"); you may not use this file except in compliance
>  *  with the License.  You may obtain a copy of the License at
>  *
>  *    http://www.apache.org/licenses/LICENSE-2.0 
>  *
>  *  Unless required by applicable law or agreed to in writing,
>  *  software distributed under the License is distributed on an
>  *  "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
>  *  KIND, either express or implied.  See the License for the
>  *  specific language governing permissions and limitations
>  *  under the License.
>  *
>  */
> package org.apache.mina.example.chat.client;
>
> import java.net.SocketAddress;
> import java.util.Timer;
> import java.util.TimerTask;
>
> import javax.net.ssl.SSLContext;
>
> import org.apache.mina.common.ConnectFuture;
> import org.apache.mina.common.IoHandler;
> import org.apache.mina.common.IoSession;
> import org.apache.mina.example.echoserver.ssl.BogusSslContextFactory;
> import org.apache.mina.filter.ssl.SslFilter;
> import org.apache.mina.transport.socket.nio.NioSocketConnector;
>
> /**
>  * A simple chat client for a given user.
>  *
>  * @author The Apache MINA Project (dev@mina.apache.org)
>  * @version $Rev$, $Date$
>  */
> public class ChatClientSupport {
>     private final IoHandler handler;
>
>     private final String name;
>
>     private IoSession session;
>
>     public ChatClientSupport(String name, IoHandler handler) {
>         if (name == null) {
>             throw new IllegalArgumentException("Name can not be null");
>         }
>         this.name = name;
>         this.handler = handler;
>     }
>
>     public boolean connect(NioSocketConnector connector, SocketAddress address,
>             boolean useSsl) {
>         if (session != null && session.isConnected()) {
>             throw new IllegalStateException(
>                     "Already connected. Disconnect first.");
>         }
>
>         try {
>
>             if (useSsl) {
>                 SSLContext sslContext = BogusSslContextFactory
>                         .getInstance(false);
>                 SslFilter sslFilter = new SslFilter(sslContext);
>                 sslFilter.setUseClientMode(true);
>                 connector.getFilterChain().addLast("sslFilter", sslFilter);
>             }
>
>             connector.setHandler(handler);
>             ConnectFuture future1 = connector.connect(address);
>             future1.awaitUninterruptibly();
>             if (!future1.isConnected()) {
>                 return false;
>             }
>             session = future1.getSession();
>             login();
>
>             return true;
>         } catch (Exception e) {
>             return false;
>         }
>     }
>
>     public void login() {
>         session.write("LOGIN " + name);
>
>         //MGA// Test write timeout problem.
>         final int PERIOD_SECONDS = 3;
>         session.getConfig().setWriteTimeout(PERIOD_SECONDS);
>         Timer timer = new Timer();
>         timer.scheduleAtFixedRate(new TimerTask() {
>             public void run () {
>                 session.write("BROADCAST testJob");
>             }
>         }, 0, PERIOD_SECONDS * 1000);
>     }
>
>     public void broadcast(String message) {
>         session.write("BROADCAST " + message);
>     }
>
>     public void quit() {
>         if (session != null) {
>             if (session.isConnected()) {
>                 session.write("QUIT");
>                 // Wait until the chat ends.
>                 session.getCloseFuture().awaitUninterruptibly();
>             }
>             session.close();
>         }
>     }
>
> }
>
>


-- 
what we call human nature is actually human habit
--
http://gleamynode.net/ 
--
PGP Key ID: 0x0255ECA6

Re: WriteTimeoutException immediately following write

Posted by Trustin Lee <tr...@gmail.com>.
Hi Martin,

Unfortunately, I simply can't reproduce the problem.  The chat client
and server are running more than 30 minutes now... :-(

Thanks anyway!
Trustin

On 10/30/07, Martin Alderson <ma...@salfordsoftware.co.uk> wrote:
> Hi Trustin,
>
> I've only just noticed you replied!
>
> Thanks for getting back to me on this.  I put some effort into creating
> a reproducible example of this problem today.  I couldn't find any
> existing tests that could be used for this so I just hijacked the chat
> example.  I managed to get this example to give some
> WriteTimeoutExceptions with just the following code added to the login
> method of the ChatClientSupport class:
>
>          final int PERIOD_SECONDS = 3;
>          session.getConfig().setWriteTimeout(PERIOD_SECONDS);
>          Timer timer = new Timer();
>          timer.scheduleAtFixedRate(new TimerTask() {
>              public void run () {
>                  session.write("BROADCAST testJob");
>              }
>          }, 0, PERIOD_SECONDS * 1000);
>
> I've attached the full modified copy of the ChatClientSupport class
> (originally from trunk).  I hope that's OK - it's only 4K.
>
> To reproduce the problem just start up the server and client with this
> modification, press the connect button and wait for a
> WriteTimeoutException to show up.  I've not had to wait more than a
> minute for it on my machine.
>
> The log output shows that all previous messages were sent and received.
>
> Thanks,
>
> Martin
>
>
>
> Trustin Lee wrote:
> > Hi Martin,
> >
> > Apologies for the late response....
> >
> > On 9/18/07, Martin Alderson <Ma...@salfordsoftware.co.uk> wrote:
> >> Hi all,
> >>
> >> I don't know too much about Mina so forgive me if I say anything stupid!
> >>
> >> I have hit a problem with my own hacked about version of ApacheDS.  ApacheDS is an LDAP server which uses Mina 1.1.2 for its replication service.
> >>
> >> The problem I am experiencing is that I have a replication (write) scheduled to occur every 60 seconds, and occasionally when this occurs I will immediately get a WriteTimeoutException.  I understand the default write timeout is also 60 seconds.  The strange thing is the two servers are running on the same machine and looking at the logs it seems that all previous messages were sent.
> >>
> >> I am wondering if it is possible that when my new write is attempted the timeout is checked at the same time - so Mina thinks there is a write pending and sees that the last message was sent more than 60 seconds ago (which would be possible depending on the thread timing!)
> >>
> >> Has anyone experienced something like this before?  Does this sound like a possible scenario?
> >
> > I think it can happen, but it shouldn't happen.  Whenever something is
> > written, lastWriteTime is updated automatically, and
> > WriteTimeoutException is raised only when lastWriteTime has not been
> > updated for a certain amount of time.  Looking into
> > SocketIoProcessor.java, it attempts to write first (i.e. doFlush())
> > and then check timeout (i.e. notifyIdleness()).  Are you sure the
> > caught WriteTimeoutException is for the successfully written message?
> > Any simplified test case would be appreciated.
> >
> > Thanks,
> > Trustin
>
>
> /*
>  *  Licensed to the Apache Software Foundation (ASF) under one
>  *  or more contributor license agreements.  See the NOTICE file
>  *  distributed with this work for additional information
>  *  regarding copyright ownership.  The ASF licenses this file
>  *  to you under the Apache License, Version 2.0 (the
>  *  "License"); you may not use this file except in compliance
>  *  with the License.  You may obtain a copy of the License at
>  *
>  *    http://www.apache.org/licenses/LICENSE-2.0
>  *
>  *  Unless required by applicable law or agreed to in writing,
>  *  software distributed under the License is distributed on an
>  *  "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY
>  *  KIND, either express or implied.  See the License for the
>  *  specific language governing permissions and limitations
>  *  under the License.
>  *
>  */
> package org.apache.mina.example.chat.client;
>
> import java.net.SocketAddress;
> import java.util.Timer;
> import java.util.TimerTask;
>
> import javax.net.ssl.SSLContext;
>
> import org.apache.mina.common.ConnectFuture;
> import org.apache.mina.common.IoHandler;
> import org.apache.mina.common.IoSession;
> import org.apache.mina.example.echoserver.ssl.BogusSslContextFactory;
> import org.apache.mina.filter.ssl.SslFilter;
> import org.apache.mina.transport.socket.nio.NioSocketConnector;
>
> /**
>  * A simple chat client for a given user.
>  *
>  * @author The Apache MINA Project (dev@mina.apache.org)
>  * @version $Rev$, $Date$
>  */
> public class ChatClientSupport {
>     private final IoHandler handler;
>
>     private final String name;
>
>     private IoSession session;
>
>     public ChatClientSupport(String name, IoHandler handler) {
>         if (name == null) {
>             throw new IllegalArgumentException("Name can not be null");
>         }
>         this.name = name;
>         this.handler = handler;
>     }
>
>     public boolean connect(NioSocketConnector connector, SocketAddress address,
>             boolean useSsl) {
>         if (session != null && session.isConnected()) {
>             throw new IllegalStateException(
>                     "Already connected. Disconnect first.");
>         }
>
>         try {
>
>             if (useSsl) {
>                 SSLContext sslContext = BogusSslContextFactory
>                         .getInstance(false);
>                 SslFilter sslFilter = new SslFilter(sslContext);
>                 sslFilter.setUseClientMode(true);
>                 connector.getFilterChain().addLast("sslFilter", sslFilter);
>             }
>
>             connector.setHandler(handler);
>             ConnectFuture future1 = connector.connect(address);
>             future1.awaitUninterruptibly();
>             if (!future1.isConnected()) {
>                 return false;
>             }
>             session = future1.getSession();
>             login();
>
>             return true;
>         } catch (Exception e) {
>             return false;
>         }
>     }
>
>     public void login() {
>         session.write("LOGIN " + name);
>
>         //MGA// Test write timeout problem.
>         final int PERIOD_SECONDS = 3;
>         session.getConfig().setWriteTimeout(PERIOD_SECONDS);
>         Timer timer = new Timer();
>         timer.scheduleAtFixedRate(new TimerTask() {
>             public void run () {
>                 session.write("BROADCAST testJob");
>             }
>         }, 0, PERIOD_SECONDS * 1000);
>     }
>
>     public void broadcast(String message) {
>         session.write("BROADCAST " + message);
>     }
>
>     public void quit() {
>         if (session != null) {
>             if (session.isConnected()) {
>                 session.write("QUIT");
>                 // Wait until the chat ends.
>                 session.getCloseFuture().awaitUninterruptibly();
>             }
>             session.close();
>         }
>     }
>
> }
>
>


-- 
what we call human nature is actually human habit
--
http://gleamynode.net/
--
PGP Key ID: 0x0255ECA6

Re: WriteTimeoutException immediately following write

Posted by Martin Alderson <ma...@salfordsoftware.co.uk>.
Hi Trustin,

I've only just noticed you replied!

Thanks for getting back to me on this.  I put some effort into creating 
a reproducible example of this problem today.  I couldn't find any 
existing tests that could be used for this so I just hijacked the chat 
example.  I managed to get this example to give some 
WriteTimeoutExceptions with just the following code added to the login 
method of the ChatClientSupport class:

         final int PERIOD_SECONDS = 3;
         session.getConfig().setWriteTimeout(PERIOD_SECONDS);
         Timer timer = new Timer();
         timer.scheduleAtFixedRate(new TimerTask() {
             public void run () {
                 session.write("BROADCAST testJob");
             }
         }, 0, PERIOD_SECONDS * 1000);

I've attached the full modified copy of the ChatClientSupport class 
(originally from trunk).  I hope that's OK - it's only 4K.

To reproduce the problem just start up the server and client with this 
modification, press the connect button and wait for a 
WriteTimeoutException to show up.  I've not had to wait more than a 
minute for it on my machine.

The log output shows that all previous messages were sent and received.

Thanks,

Martin



Trustin Lee wrote:
> Hi Martin,
> 
> Apologies for the late response....
> 
> On 9/18/07, Martin Alderson <Ma...@salfordsoftware.co.uk> wrote:
>> Hi all,
>>
>> I don't know too much about Mina so forgive me if I say anything stupid!
>>
>> I have hit a problem with my own hacked about version of ApacheDS.  ApacheDS is an LDAP server which uses Mina 1.1.2 for its replication service.
>>
>> The problem I am experiencing is that I have a replication (write) scheduled to occur every 60 seconds, and occasionally when this occurs I will immediately get a WriteTimeoutException.  I understand the default write timeout is also 60 seconds.  The strange thing is the two servers are running on the same machine and looking at the logs it seems that all previous messages were sent.
>>
>> I am wondering if it is possible that when my new write is attempted the timeout is checked at the same time - so Mina thinks there is a write pending and sees that the last message was sent more than 60 seconds ago (which would be possible depending on the thread timing!)
>>
>> Has anyone experienced something like this before?  Does this sound like a possible scenario?
> 
> I think it can happen, but it shouldn't happen.  Whenever something is
> written, lastWriteTime is updated automatically, and
> WriteTimeoutException is raised only when lastWriteTime has not been
> updated for a certain amount of time.  Looking into
> SocketIoProcessor.java, it attempts to write first (i.e. doFlush())
> and then check timeout (i.e. notifyIdleness()).  Are you sure the
> caught WriteTimeoutException is for the successfully written message?
> Any simplified test case would be appreciated.
> 
> Thanks,
> Trustin


Re: WriteTimeoutException immediately following write

Posted by Trustin Lee <tr...@gmail.com>.
Hi Martin,

Apologies for the late response....

On 9/18/07, Martin Alderson <Ma...@salfordsoftware.co.uk> wrote:
> Hi all,
>
> I don't know too much about Mina so forgive me if I say anything stupid!
>
> I have hit a problem with my own hacked about version of ApacheDS.  ApacheDS is an LDAP server which uses Mina 1.1.2 for its replication service.
>
> The problem I am experiencing is that I have a replication (write) scheduled to occur every 60 seconds, and occasionally when this occurs I will immediately get a WriteTimeoutException.  I understand the default write timeout is also 60 seconds.  The strange thing is the two servers are running on the same machine and looking at the logs it seems that all previous messages were sent.
>
> I am wondering if it is possible that when my new write is attempted the timeout is checked at the same time - so Mina thinks there is a write pending and sees that the last message was sent more than 60 seconds ago (which would be possible depending on the thread timing!)
>
> Has anyone experienced something like this before?  Does this sound like a possible scenario?

I think it can happen, but it shouldn't happen.  Whenever something is
written, lastWriteTime is updated automatically, and
WriteTimeoutException is raised only when lastWriteTime has not been
updated for a certain amount of time.  Looking into
SocketIoProcessor.java, it attempts to write first (i.e. doFlush())
and then check timeout (i.e. notifyIdleness()).  Are you sure the
caught WriteTimeoutException is for the successfully written message?
Any simplified test case would be appreciated.

Thanks,
Trustin
-- 
what we call human nature is actually human habit
--
http://gleamynode.net/
--
PGP Key ID: 0x0255ECA6