You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@mina.apache.org by Matt Mehalso <me...@gmail.com> on 2007/09/26 18:08:41 UTC
Environment switch causing strange SocketExceptions
All -
We've just recently deployed a Mina-based server (using mina-core-1.0.3) to
production that had been in testing for some time. We are now getting a
strange error that we had never seen during testing.
The server is a fairly simple request / response multi-threaded server that
uses our own custom protocol codec for encoding and decoding messages. The
codec uses a line length to separate initialization messages, and then a
delimiter for all subsequent messages. We use a
edu.emory.mathcs.backport.java.util.concurrent.Executors.newCachedThreadPoolexecutor
with an ExecutorFilter to handle requests in different threads.
The max # of threads is set using the # of processors + 1, as in the mina
tutorial.
We are getting a strange socket connection that is always paired with a
strange java.lang.Integer / java.lang.String mismatch? Additionally, we've
noticed that a new thread is being spawned for each incoming request and
that these threads are no longer returning to the thread pool as they were
during the testing phase. The server runs as a windows service using
JavaService and we are continuously restarting as the memory usage climbs
above 500 MB or so.
We are now getting the following exceptions, sometimes after a single
request, sometimes after 10-15, as extracted from our log files:
2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3] INFO
<package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] EXCEPTION:
java.net.SocketException: Connection reset by peer: Read failed
at sun.nio.ch.SocketDispatcher.read0(Native Method)
at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:42)
at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:265)
at sun.nio.ch.IOUtil.read(IOUtil.java:238)
at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:223)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(
SocketIoProcessor.java:267)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(
SocketIoProcessor.java:241)
at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(
SocketIoProcessor.java:44)
at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run(
SocketIoProcessor.java:563)
at org.apache.mina.util.NamePreservingRunnable.run(
NamePreservingRunnable.java:43)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker(
ThreadPoolExecutor.java:987)
at
edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run
(ThreadPoolExecutor.java:528)
at java.lang.Thread.run(Thread.java:832)
2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3] INFO
<package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] CLOSED
2007-09-25 10:28:07,821 [pool-1-thread-32] ERROR
<package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] Connection with
client closed abnormally. Exception: Connection reset by peer: Read failed
2007-09-25 10:28:07,836 [pool-1-thread-32] ERROR
<package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] Connection with
client closed abnormally. Exception: java/lang/Integer incompatible with
java/lang/String
As you can see, this is on the 32nd thread spawned and is the 32nd message
received since the server started. We currently only have a single client
connected to the server.
Has anyone ever seen anything like this before? Any ideas? Thanks in
advance for your help!
Best,
Matt
Re: Environment switch causing strange SocketExceptions
Posted by Matt Mehalso <me...@gmail.com>.
Thanks, Trustin. I took a look at the thread pool stuff and think i was
just a little confused when i wrote up the question. I debugged the server
and found my threads were returning to the pool as they should. We are
seeing this exception a lot, but will now assume it is an issue w/ the
network and/or client.
Thanks,
Matt
On 9/28/07, Trustin Lee <tr...@gmail.com> wrote:
>
> Hi Matt,
>
> You can simply ignore 'Connection reset by peer' error. It's a little
> bit different from normal close, it anyways means the connection has
> been closed.
>
> And ExecutorFilter doesn't do anything related with choosing a thread.
> It just calls execute() method on the Executor you specified. If you
> didn't specify any executor, it uses a new ThreadPoolExecutorFilter
> instance. Therefore, if you want to control how threads are pulled
> from a pool, you need to provide an Executor instance that behaves as
> you expect.
>
> HTH,
> Trustin
>
> On 9/26/07, Matt Mehalso <me...@gmail.com> wrote:
> > Also noticed during testing in my own dev environment that if I wait for
> a
> > few minutes between sending messages to the server, a new thread is
> always
> > used by the executor filter.
> >
> > For example, if I connect and send three requests one after the other,
> the
> > executor filter uses thread-1 for each request. If i wait five minutes
> and
> > send the same request again on the same connection, the log shows
> thread-2
> > being used.
> >
> > Looking at my task manager, I can confirm that a new thread is indeed
> being
> > launched after every increment.
> >
> > Thanks,
> >
> > Matt
> >
> > On 9/26/07, Matt Mehalso <me...@gmail.com> wrote:
> > >
> > > All -
> > >
> > > We've just recently deployed a Mina-based server (using
> mina-core-1.0.3)
> > > to production that had been in testing for some time. We are now
> getting a
> > > strange error that we had never seen during testing.
> > >
> > > The server is a fairly simple request / response multi-threaded server
> > > that uses our own custom protocol codec for encoding and decoding
> messages.
> > > The codec uses a line length to separate initialization messages, and
> then a
> > > delimiter for all subsequent messages. We use a
> > >
> edu.emory.mathcs.backport.java.util.concurrent.Executors.newCachedThreadPoolexecutorwith an ExecutorFilter to handle requests in different threads.
> > > The max # of threads is set using the # of processors + 1, as in the
> mina
> > > tutorial.
> > >
> > > We are getting a strange socket connection that is always paired with
> a
> > > strange java.lang.Integer / java.lang.String mismatch? Additionally,
> > > we've noticed that a new thread is being spawned for each incoming
> request
> > > and that these threads are no longer returning to the thread pool as
> they
> > > were during the testing phase. The server runs as a windows service
> using
> > > JavaService and we are continuously restarting as the memory usage
> climbs
> > > above 500 MB or so.
> > >
> > > We are now getting the following exceptions, sometimes after a single
> > > request, sometimes after 10-15, as extracted from our log files:
> > >
> > > 2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3] INFO
> > > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630]
> EXCEPTION:
> > > java.net.SocketException: Connection reset by peer: Read failed
> > > at sun.nio.ch.SocketDispatcher.read0(Native Method)
> > > at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:42)
> > > at sun.nio.ch.IOUtil.readIntoNativeBuffer (IOUtil.java:265)
> > > at sun.nio.ch.IOUtil.read(IOUtil.java:238)
> > > at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:223)
> > > at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(
> > > SocketIoProcessor.java :267)
> > > at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(
> > > SocketIoProcessor.java:241)
> > > at
> org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(
> > > SocketIoProcessor.java:44)
> > > at
> org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run (
> > > SocketIoProcessor.java:563)
> > > at org.apache.mina.util.NamePreservingRunnable.run(
> > > NamePreservingRunnable.java:43)
> > > at
> > >
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker
> > > (ThreadPoolExecutor.java :987)
> > > at
> > >
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run
> > > (ThreadPoolExecutor.java:528)
> > > at java.lang.Thread.run(Thread.java:832)
> > > 2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3 ] INFO
> > > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] CLOSED
> > > 2007-09-25 10:28:07,821 [pool-1-thread-32] ERROR
> > > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630]
> Connection with
> > > client closed abnormally. Exception: Connection reset by peer: Read
> failed
> > > 2007-09-25 10:28:07,836 [pool-1-thread-32] ERROR
> > > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630]
> Connection with
> > > client closed abnormally. Exception: java/lang/Integer incompatible
> with
> > > java/lang/String
> > >
> > > As you can see, this is on the 32nd thread spawned and is the 32nd
> message
> > > received since the server started. We currently only have a single
> client
> > > connected to the server.
> > >
> > > Has anyone ever seen anything like this before? Any ideas? Thanks in
> > > advance for your help!
> > >
> > > Best,
> > >
> > > Matt
> > >
> > >
> > >
> >
>
>
> --
> what we call human nature is actually human habit
> --
> http://gleamynode.net/
> --
> PGP Key ID: 0x0255ECA6
>
Re: Environment switch causing strange SocketExceptions
Posted by Trustin Lee <tr...@gmail.com>.
Hi Matt,
You can simply ignore 'Connection reset by peer' error. It's a little
bit different from normal close, it anyways means the connection has
been closed.
And ExecutorFilter doesn't do anything related with choosing a thread.
It just calls execute() method on the Executor you specified. If you
didn't specify any executor, it uses a new ThreadPoolExecutorFilter
instance. Therefore, if you want to control how threads are pulled
from a pool, you need to provide an Executor instance that behaves as
you expect.
HTH,
Trustin
On 9/26/07, Matt Mehalso <me...@gmail.com> wrote:
> Also noticed during testing in my own dev environment that if I wait for a
> few minutes between sending messages to the server, a new thread is always
> used by the executor filter.
>
> For example, if I connect and send three requests one after the other, the
> executor filter uses thread-1 for each request. If i wait five minutes and
> send the same request again on the same connection, the log shows thread-2
> being used.
>
> Looking at my task manager, I can confirm that a new thread is indeed being
> launched after every increment.
>
> Thanks,
>
> Matt
>
> On 9/26/07, Matt Mehalso <me...@gmail.com> wrote:
> >
> > All -
> >
> > We've just recently deployed a Mina-based server (using mina-core-1.0.3)
> > to production that had been in testing for some time. We are now getting a
> > strange error that we had never seen during testing.
> >
> > The server is a fairly simple request / response multi-threaded server
> > that uses our own custom protocol codec for encoding and decoding messages.
> > The codec uses a line length to separate initialization messages, and then a
> > delimiter for all subsequent messages. We use a
> > edu.emory.mathcs.backport.java.util.concurrent.Executors.newCachedThreadPoolexecutor with an ExecutorFilter to handle requests in different threads.
> > The max # of threads is set using the # of processors + 1, as in the mina
> > tutorial.
> >
> > We are getting a strange socket connection that is always paired with a
> > strange java.lang.Integer / java.lang.String mismatch? Additionally,
> > we've noticed that a new thread is being spawned for each incoming request
> > and that these threads are no longer returning to the thread pool as they
> > were during the testing phase. The server runs as a windows service using
> > JavaService and we are continuously restarting as the memory usage climbs
> > above 500 MB or so.
> >
> > We are now getting the following exceptions, sometimes after a single
> > request, sometimes after 10-15, as extracted from our log files:
> >
> > 2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3] INFO
> > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] EXCEPTION:
> > java.net.SocketException: Connection reset by peer: Read failed
> > at sun.nio.ch.SocketDispatcher.read0(Native Method)
> > at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:42)
> > at sun.nio.ch.IOUtil.readIntoNativeBuffer (IOUtil.java:265)
> > at sun.nio.ch.IOUtil.read(IOUtil.java:238)
> > at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:223)
> > at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(
> > SocketIoProcessor.java :267)
> > at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(
> > SocketIoProcessor.java:241)
> > at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(
> > SocketIoProcessor.java:44)
> > at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run (
> > SocketIoProcessor.java:563)
> > at org.apache.mina.util.NamePreservingRunnable.run(
> > NamePreservingRunnable.java:43)
> > at
> > edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker
> > (ThreadPoolExecutor.java :987)
> > at
> > edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run
> > (ThreadPoolExecutor.java:528)
> > at java.lang.Thread.run(Thread.java:832)
> > 2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3 ] INFO
> > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] CLOSED
> > 2007-09-25 10:28:07,821 [pool-1-thread-32] ERROR
> > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] Connection with
> > client closed abnormally. Exception: Connection reset by peer: Read failed
> > 2007-09-25 10:28:07,836 [pool-1-thread-32] ERROR
> > <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] Connection with
> > client closed abnormally. Exception: java/lang/Integer incompatible with
> > java/lang/String
> >
> > As you can see, this is on the 32nd thread spawned and is the 32nd message
> > received since the server started. We currently only have a single client
> > connected to the server.
> >
> > Has anyone ever seen anything like this before? Any ideas? Thanks in
> > advance for your help!
> >
> > Best,
> >
> > Matt
> >
> >
> >
>
--
what we call human nature is actually human habit
--
http://gleamynode.net/
--
PGP Key ID: 0x0255ECA6
Re: Environment switch causing strange SocketExceptions
Posted by Matt Mehalso <me...@gmail.com>.
Also noticed during testing in my own dev environment that if I wait for a
few minutes between sending messages to the server, a new thread is always
used by the executor filter.
For example, if I connect and send three requests one after the other, the
executor filter uses thread-1 for each request. If i wait five minutes and
send the same request again on the same connection, the log shows thread-2
being used.
Looking at my task manager, I can confirm that a new thread is indeed being
launched after every increment.
Thanks,
Matt
On 9/26/07, Matt Mehalso <me...@gmail.com> wrote:
>
> All -
>
> We've just recently deployed a Mina-based server (using mina-core-1.0.3)
> to production that had been in testing for some time. We are now getting a
> strange error that we had never seen during testing.
>
> The server is a fairly simple request / response multi-threaded server
> that uses our own custom protocol codec for encoding and decoding messages.
> The codec uses a line length to separate initialization messages, and then a
> delimiter for all subsequent messages. We use a
> edu.emory.mathcs.backport.java.util.concurrent.Executors.newCachedThreadPoolexecutor with an ExecutorFilter to handle requests in different threads.
> The max # of threads is set using the # of processors + 1, as in the mina
> tutorial.
>
> We are getting a strange socket connection that is always paired with a
> strange java.lang.Integer / java.lang.String mismatch? Additionally,
> we've noticed that a new thread is being spawned for each incoming request
> and that these threads are no longer returning to the thread pool as they
> were during the testing phase. The server runs as a windows service using
> JavaService and we are continuously restarting as the memory usage climbs
> above 500 MB or so.
>
> We are now getting the following exceptions, sometimes after a single
> request, sometimes after 10-15, as extracted from our log files:
>
> 2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3] INFO
> <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] EXCEPTION:
> java.net.SocketException: Connection reset by peer: Read failed
> at sun.nio.ch.SocketDispatcher.read0(Native Method)
> at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:42)
> at sun.nio.ch.IOUtil.readIntoNativeBuffer (IOUtil.java:265)
> at sun.nio.ch.IOUtil.read(IOUtil.java:238)
> at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:223)
> at org.apache.mina.transport.socket.nio.SocketIoProcessor.read(
> SocketIoProcessor.java :267)
> at org.apache.mina.transport.socket.nio.SocketIoProcessor.process(
> SocketIoProcessor.java:241)
> at org.apache.mina.transport.socket.nio.SocketIoProcessor.access$500(
> SocketIoProcessor.java:44)
> at org.apache.mina.transport.socket.nio.SocketIoProcessor$Worker.run (
> SocketIoProcessor.java:563)
> at org.apache.mina.util.NamePreservingRunnable.run(
> NamePreservingRunnable.java:43)
> at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor.runWorker
> (ThreadPoolExecutor.java :987)
> at
> edu.emory.mathcs.backport.java.util.concurrent.ThreadPoolExecutor$Worker.run
> (ThreadPoolExecutor.java:528)
> at java.lang.Thread.run(Thread.java:832)
> 2007-09-25 10:28:07,821 [SocketAcceptorIoProcessor-0.3 ] INFO
> <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] CLOSED
> 2007-09-25 10:28:07,821 [pool-1-thread-32] ERROR
> <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] Connection with
> client closed abnormally. Exception: Connection reset by peer: Read failed
> 2007-09-25 10:28:07,836 [pool-1-thread-32] ERROR
> <package>.handler.ReceiptTaskHandler - [/56.116.73.225:4630] Connection with
> client closed abnormally. Exception: java/lang/Integer incompatible with
> java/lang/String
>
> As you can see, this is on the 32nd thread spawned and is the 32nd message
> received since the server started. We currently only have a single client
> connected to the server.
>
> Has anyone ever seen anything like this before? Any ideas? Thanks in
> advance for your help!
>
> Best,
>
> Matt
>
>
>