Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: Trunk
    • Fix Version/s: 3.0-M1
    • Component/s: IMAPServer
    • Labels:
      None
    • Environment:
      Win XP, Thunderbird

      Description

      Quite often when closing Thunderbird I get this exception:

      ERROR 10:56:01,234 | james.imapserver | Error while processing imap request
      java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen *
      at sun.nio.ch.SocketDispatcher.write0(Native Method)
      at sun.nio.ch.SocketDispatcher.write(Unknown Source)
      at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source)
      at sun.nio.ch.IOUtil.write(Unknown Source)
      at sun.nio.ch.SocketChannelImpl.write(Unknown Source)
      at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:208)
      at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:42)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:834)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:764)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61)
      at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973)
      at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
      at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
      at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
      at java.lang.Thread.run(Unknown Source)

      I occurs aprx 200 times per second and basically fills up the hard drive with those lines in the log files (that's why I set this issue to critical). I've no idea how to debug this because I can't see where this is called.

      *) an existing connection has been closed by the remote host

      1. jstack_short.log
        7 kB
        Tim-Christian Mundt
      2. jstack_inifinite.log
        17 kB
        Tim-Christian Mundt

        Activity

        Hide
        Tim-Christian Mundt added a comment -

        If I understand correctly, James tried to close the session with close(false) which caused mina to closeOnFlush() which tried to write to the session which was closed which caused an exception in which James tried to ...

        Show
        Tim-Christian Mundt added a comment - If I understand correctly, James tried to close the session with close(false) which caused mina to closeOnFlush() which tried to write to the session which was closed which caused an exception in which James tried to ...
        Hide
        Norman Maurer added a comment -

        it seems like the started thread in processStreamIo(..) never end even when closing the session with session.close(false); With session.close(true) it seems to work

        Show
        Norman Maurer added a comment - it seems like the started thread in processStreamIo(..) never end even when closing the session with session.close(false); With session.close(true) it seems to work
        Hide
        Emmanuel Lecharny added a comment -

        Pfeww. Now, what I don't get is why you did have an infinite loop?

        Show
        Emmanuel Lecharny added a comment - Pfeww. Now, what I don't get is why you did have an infinite loop?
        Hide
        Norman Maurer added a comment -

        Was fixed in revision 918952

        Show
        Norman Maurer added a comment - Was fixed in revision 918952
        Hide
        Norman Maurer added a comment -

        Upgrade to blocker because it produce a loop

        Show
        Norman Maurer added a comment - Upgrade to blocker because it produce a loop
        Hide
        Norman Maurer added a comment -

        @Emmanuel:

        To be hornest I don't care to much about the org.apache.mina.core.write.WriteToClosedSessionException. Its more the "infinity loop" which concerns me..

        Show
        Norman Maurer added a comment - @Emmanuel: To be hornest I don't care to much about the org.apache.mina.core.write.WriteToClosedSessionException. Its more the "infinity loop" which concerns me..
        Hide
        Tim-Christian Mundt added a comment -

        Hi Emmanuel,

        thanks for having a look on that. I can understand your scenario, should be really good to make MINA more robust concerning that.
        However, I didn't request ANY message when the error occurred. I'm sure the mail client does some syncing before closing but it's not that I even HAVE more than one mail in the mailbox.

        Show
        Tim-Christian Mundt added a comment - Hi Emmanuel, thanks for having a look on that. I can understand your scenario, should be really good to make MINA more robust concerning that. However, I didn't request ANY message when the error occurred. I'm sure the mail client does some syncing before closing but it's not that I even HAVE more than one mail in the mailbox.
        Hide
        Emmanuel Lecharny added a comment -

        Hi from MINA,

        you have to understand the way MINA works : when you have a client connecting to the server, and send a request for, say, the 100 000 messages waiting for this client (this is just an hypothesis), MINA will try to send all those messages by creating buffers stored in a write queue. if the socket is swamped, the buffer will still enqueue, so at some point, with a slow client, you may perfectly have hundred of thousands messages stored in the write queue waiting for the socket to be ready.

        Of course, if you kill the client, suddenly the server thread trying to write the messages to the client will fail pathetically, with a lot of verbosity...

        How to avoid such a scenario ? Well, it would be great if MINA was smart enough to determinate that when the client has closed the socket, then all the messages in the write queue should be discarded (feel free to create a JIRA for this, we probably could fix that). However, you can still kill the server if the client is just a slow reader, as the messages will continue to flow through. In this case, you have to check that the previous message has been correctly sent before sending the next one.

        Now, I tried to have a look at the code, but the twi snippet I got weren't enough to get a clue about what's exactly is going wild in your case.

        Show
        Emmanuel Lecharny added a comment - Hi from MINA, you have to understand the way MINA works : when you have a client connecting to the server, and send a request for, say, the 100 000 messages waiting for this client (this is just an hypothesis), MINA will try to send all those messages by creating buffers stored in a write queue. if the socket is swamped, the buffer will still enqueue, so at some point, with a slow client, you may perfectly have hundred of thousands messages stored in the write queue waiting for the socket to be ready. Of course, if you kill the client, suddenly the server thread trying to write the messages to the client will fail pathetically, with a lot of verbosity... How to avoid such a scenario ? Well, it would be great if MINA was smart enough to determinate that when the client has closed the socket, then all the messages in the write queue should be discarded (feel free to create a JIRA for this, we probably could fix that). However, you can still kill the server if the client is just a slow reader, as the messages will continue to flow through. In this case, you have to check that the previous message has been correctly sent before sending the next one. Now, I tried to have a look at the code, but the twi snippet I got weren't enough to get a clue about what's exactly is going wild in your case.
        Hide
        Norman Maurer added a comment -

        Hi Tim,

        ok I will try to understand if the bug is in james or mina. Will come back to you later.

        Show
        Norman Maurer added a comment - Hi Tim, ok I will try to understand if the bug is in james or mina. Will come back to you later.
        Hide
        Tim-Christian Mundt added a comment -

        No, I didn't. The files are unmodified results of:

        jstack 5784 > jstack_infinite.log

        Show
        Tim-Christian Mundt added a comment - No, I didn't. The files are unmodified results of: jstack 5784 > jstack_infinite.log
        Hide
        Norman Maurer added a comment -

        Did you trim down the stacks ? I would expect to see more ..

        Show
        Norman Maurer added a comment - Did you trim down the stacks ? I would expect to see more ..
        Hide
        Tim-Christian Mundt added a comment -

        Sure, I attached two jstacks. The one after the error that only occurs once and the other during the infinite loop. Tell me if I can be of any further help, whatever I can do for debugging, I'd be glad to do.

        Show
        Tim-Christian Mundt added a comment - Sure, I attached two jstacks. The one after the error that only occurs once and the other during the infinite loop. Tell me if I can be of any further help, whatever I can do for debugging, I'd be glad to do.
        Hide
        Norman Maurer added a comment -

        Hi Tim,

        could you do a jstack on the pid of the server so we say what it is actual doing ?

        First do a jps to see the pid and then jstack $PID$.

        The output while be very long so better redirect it to a file.

        Thx,
        Norman

        Show
        Norman Maurer added a comment - Hi Tim, could you do a jstack on the pid of the server so we say what it is actual doing ? First do a jps to see the pid and then jstack $PID$. The output while be very long so better redirect it to a file. Thx, Norman
        Hide
        Tim-Christian Mundt added a comment -

        (Well, I thought an uncaught exception is worth to be written to error out, that's why I mentioned.)

        To "reproduce" (as said, it's not consistent):

        1. Start James
        2. Open up Thunderbird
        3. Click on the INBOX of an IMAP James account
        4. See the mailbox getting loaded correctly
        5. Close Thunderbird

        Most of the times there is no error at all. If I get errors, then it's mostly this (sorry, for the loads of backtraces here):

        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$600(AbstractPollingIoProcessor.java:61)
        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(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
        ERROR 13:28:54,546 | james.imapserver | Error while processing imap request
        org.apache.mina.core.write.WriteToClosedSessionException
        ... (same again)
        INFO 13:28:54,546 | james.imapserver | The bytes could not be written to the session
        ERROR 13:28:54,562 | james.imapserver | Error while processing imap request
        java.io.IOException: The bytes could not be written to the session
        at org.apache.mina.handler.stream.IoSessionOutputStream.flush(IoSessionOutputStream.java:86)
        at org.apache.mina.handler.stream.IoSessionOutputStream.close(IoSessionOutputStream.java:47)
        at org.apache.mina.handler.stream.StreamIoHandler.sessionClosed(StreamIoHandler.java:127)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.sessionClosed(DefaultIoFilterChain.java:662)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778)
        at org.apache.james.socket.mina.filter.ConnectionFilter.sessionClosed(ConnectionFilter.java:78)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778)
        at org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:95)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:388)
        at org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:210)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:535)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:497)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:61)
        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(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)

        which only appears once and than everything's still working. But sometimes I get this an infinite* number of times:

        ERROR 13:30:56,093 | james.imapserver | Error while processing imap request
        java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen
        at sun.nio.ch.SocketDispatcher.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(Unknown Source)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source)
        at sun.nio.ch.IOUtil.write(Unknown Source)
        at sun.nio.ch.SocketChannelImpl.write(Unknown Source)
        at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:208)
        at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:834)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:764)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)

        *) infinite = a few megabytes of logs in a few seconds with no end within maybe 20-30 seconds, then I canceled it

        Show
        Tim-Christian Mundt added a comment - (Well, I thought an uncaught exception is worth to be written to error out, that's why I mentioned.) To "reproduce" (as said, it's not consistent): 1. Start James 2. Open up Thunderbird 3. Click on the INBOX of an IMAP James account 4. See the mailbox getting loaded correctly 5. Close Thunderbird Most of the times there is no error at all. If I get errors, then it's mostly this (sorry, for the loads of backtraces here): 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$600(AbstractPollingIoProcessor.java:61) 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(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ERROR 13:28:54,546 | james.imapserver | Error while processing imap request org.apache.mina.core.write.WriteToClosedSessionException ... (same again) INFO 13:28:54,546 | james.imapserver | The bytes could not be written to the session ERROR 13:28:54,562 | james.imapserver | Error while processing imap request java.io.IOException: The bytes could not be written to the session at org.apache.mina.handler.stream.IoSessionOutputStream.flush(IoSessionOutputStream.java:86) at org.apache.mina.handler.stream.IoSessionOutputStream.close(IoSessionOutputStream.java:47) at org.apache.mina.handler.stream.StreamIoHandler.sessionClosed(StreamIoHandler.java:127) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.sessionClosed(DefaultIoFilterChain.java:662) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778) at org.apache.james.socket.mina.filter.ConnectionFilter.sessionClosed(ConnectionFilter.java:78) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778) at org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:95) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395) at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:388) at org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:210) at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:535) at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:497) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:61) 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(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) which only appears once and than everything's still working. But sometimes I get this an infinite* number of times: ERROR 13:30:56,093 | james.imapserver | Error while processing imap request java.io.IOException: Eine vorhandene Verbindung wurde vom Remotehost geschlossen at sun.nio.ch.SocketDispatcher.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(Unknown Source) at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source) at sun.nio.ch.IOUtil.write(Unknown Source) at sun.nio.ch.SocketChannelImpl.write(Unknown Source) at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:208) at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:834) at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:764) at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) *) infinite = a few megabytes of logs in a few seconds with no end within maybe 20-30 seconds, then I canceled it
        Hide
        Norman Maurer added a comment -

        yeah I relealized the loop will still be there.. I just thought the logging was not setup right anyway.. that has nothing todo with this issue (thats because I didn't mention the JIRA ID in the svn log). Sorry, maybe it was a bit confusing.

        Anyway how often does it happen ? is reproducable ? I don't see the problems when running james in fbsd

        Show
        Norman Maurer added a comment - yeah I relealized the loop will still be there.. I just thought the logging was not setup right anyway.. that has nothing todo with this issue (thats because I didn't mention the JIRA ID in the svn log). Sorry, maybe it was a bit confusing. Anyway how often does it happen ? is reproducable ? I don't see the problems when running james in fbsd
        Hide
        Tim-Christian Mundt added a comment -

        Thunderbird was idle when I closed it, no new messages. The logging seems to never end. That's why I'm a bit surprised you suppressed the error logging of such exceptions in the latest revision. The loop would still be there just without realizing it, right?

        Actually, the behavior is not quite consistent. Just tried again and got:

        ERROR 13:01:59,875 | james.imapserver | Error while processing imap request
        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$600(AbstractPollingIoProcessor.java:61)
        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(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
        ERROR 13:01:59,875 | james.imapserver | Error while processing imap request
        org.apache.mina.core.write.WriteToClosedSessionException
        ... (same as above)
        ERROR 13:01:59,890 | james.imapserver | Error while processing imap request
        java.io.IOException: Eine bestehende Verbindung wurde softwaregesteuert
        durch den Hostcomputer abgebrochen
        at sun.nio.ch.SocketDispatcher.read0(Native Method)
        at sun.nio.ch.SocketDispatcher.read(Unknown Source)
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source)
        at sun.nio.ch.IOUtil.read(Unknown Source)
        at sun.nio.ch.SocketChannelImpl.read(Unknown Source)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202)
        at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
        ERROR 13:01:59,906 | james.imapserver | Error while processing imap request
        java.io.IOException: Eine bestehende Verbindung wurde softwaregesteuert
        durch den Hostcomputer abgebrochen
        at sun.nio.ch.SocketDispatcher.write0(Native Method)
        at sun.nio.ch.SocketDispatcher.write(Unknown Source)
        at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source)
        at sun.nio.ch.IOUtil.write(Unknown Source)
        at sun.nio.ch.SocketChannelImpl.write(Unknown Source)
        at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:208)
        at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:42)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:834)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:764)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973)
        at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64)
        at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
        ERROR 13:01:59,906 | james.imapserver | Error while processing imap request
        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$600(AbstractPollingIoProcessor.java:61)
        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(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
        INFO 13:01:59,906 | james.imapserver | The bytes could not be written to the session
        ERROR 13:01:59,906 | james.imapserver | Error while processing imap request
        java.io.IOException: The bytes could not be written to the session
        at org.apache.mina.handler.stream.IoSessionOutputStream.flush(IoSessionOutputStream.java:86)
        at org.apache.mina.handler.stream.IoSessionOutputStream.close(IoSessionOutputStream.java:47)
        at org.apache.mina.handler.stream.StreamIoHandler.sessionClosed(StreamIoHandler.java:127)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.sessionClosed(DefaultIoFilterChain.java:662)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778)
        at org.apache.james.socket.mina.filter.ConnectionFilter.sessionClosed(ConnectionFilter.java:78)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778)
        at org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:95)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395)
        at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:388)
        at org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:210)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:535)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:497)
        at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:61)
        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(Unknown Source)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source)
        at java.lang.Thread.run(Unknown Source)
        INFO 13:01:59,906 | james.imapserver | The bytes could not be written to the session
        ERROR 13:01:59,906 | james.imapserver | Error while processing imap request
        org.apache.mina.core.write.WriteToClosedSessionException
        ... (here the last two errors are repeated)

        Also mina, also IOException, also appears when closing Thunderbird, but different anyways.

        Show
        Tim-Christian Mundt added a comment - Thunderbird was idle when I closed it, no new messages. The logging seems to never end. That's why I'm a bit surprised you suppressed the error logging of such exceptions in the latest revision. The loop would still be there just without realizing it, right? Actually, the behavior is not quite consistent. Just tried again and got: ERROR 13:01:59,875 | james.imapserver | Error while processing imap request 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$600(AbstractPollingIoProcessor.java:61) 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(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ERROR 13:01:59,875 | james.imapserver | Error while processing imap request org.apache.mina.core.write.WriteToClosedSessionException ... (same as above) ERROR 13:01:59,890 | james.imapserver | Error while processing imap request java.io.IOException: Eine bestehende Verbindung wurde softwaregesteuert durch den Hostcomputer abgebrochen at sun.nio.ch.SocketDispatcher.read0(Native Method) at sun.nio.ch.SocketDispatcher.read(Unknown Source) at sun.nio.ch.IOUtil.readIntoNativeBuffer(Unknown Source) at sun.nio.ch.IOUtil.read(Unknown Source) at sun.nio.ch.SocketChannelImpl.read(Unknown Source) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:202) at org.apache.mina.transport.socket.nio.NioProcessor.read(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.read(AbstractPollingIoProcessor.java:620) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:598) at org.apache.mina.core.polling.AbstractPollingIoProcessor.process(AbstractPollingIoProcessor.java:587) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$400(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:969) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ERROR 13:01:59,906 | james.imapserver | Error while processing imap request java.io.IOException: Eine bestehende Verbindung wurde softwaregesteuert durch den Hostcomputer abgebrochen at sun.nio.ch.SocketDispatcher.write0(Native Method) at sun.nio.ch.SocketDispatcher.write(Unknown Source) at sun.nio.ch.IOUtil.writeFromNativeBuffer(Unknown Source) at sun.nio.ch.IOUtil.write(Unknown Source) at sun.nio.ch.SocketChannelImpl.write(Unknown Source) at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:208) at org.apache.mina.transport.socket.nio.NioProcessor.write(NioProcessor.java:42) at org.apache.mina.core.polling.AbstractPollingIoProcessor.writeBuffer(AbstractPollingIoProcessor.java:834) at org.apache.mina.core.polling.AbstractPollingIoProcessor.flushNow(AbstractPollingIoProcessor.java:764) at org.apache.mina.core.polling.AbstractPollingIoProcessor.flush(AbstractPollingIoProcessor.java:692) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$500(AbstractPollingIoProcessor.java:61) at org.apache.mina.core.polling.AbstractPollingIoProcessor$Processor.run(AbstractPollingIoProcessor.java:973) at org.apache.mina.util.NamePreservingRunnable.run(NamePreservingRunnable.java:64) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) ERROR 13:01:59,906 | james.imapserver | Error while processing imap request 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$600(AbstractPollingIoProcessor.java:61) 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(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) INFO 13:01:59,906 | james.imapserver | The bytes could not be written to the session ERROR 13:01:59,906 | james.imapserver | Error while processing imap request java.io.IOException: The bytes could not be written to the session at org.apache.mina.handler.stream.IoSessionOutputStream.flush(IoSessionOutputStream.java:86) at org.apache.mina.handler.stream.IoSessionOutputStream.close(IoSessionOutputStream.java:47) at org.apache.mina.handler.stream.StreamIoHandler.sessionClosed(StreamIoHandler.java:127) at org.apache.mina.core.filterchain.DefaultIoFilterChain$TailFilter.sessionClosed(DefaultIoFilterChain.java:662) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778) at org.apache.james.socket.mina.filter.ConnectionFilter.sessionClosed(ConnectionFilter.java:78) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395) at org.apache.mina.core.filterchain.DefaultIoFilterChain.access$900(DefaultIoFilterChain.java:46) at org.apache.mina.core.filterchain.DefaultIoFilterChain$EntryImpl$1.sessionClosed(DefaultIoFilterChain.java:778) at org.apache.mina.core.filterchain.IoFilterAdapter.sessionClosed(IoFilterAdapter.java:95) at org.apache.mina.core.filterchain.DefaultIoFilterChain.callNextSessionClosed(DefaultIoFilterChain.java:395) at org.apache.mina.core.filterchain.DefaultIoFilterChain.fireSessionClosed(DefaultIoFilterChain.java:388) at org.apache.mina.core.service.IoServiceListenerSupport.fireSessionDestroyed(IoServiceListenerSupport.java:210) at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeNow(AbstractPollingIoProcessor.java:535) at org.apache.mina.core.polling.AbstractPollingIoProcessor.removeSessions(AbstractPollingIoProcessor.java:497) at org.apache.mina.core.polling.AbstractPollingIoProcessor.access$600(AbstractPollingIoProcessor.java:61) 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(Unknown Source) at java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source) at java.lang.Thread.run(Unknown Source) INFO 13:01:59,906 | james.imapserver | The bytes could not be written to the session ERROR 13:01:59,906 | james.imapserver | Error while processing imap request org.apache.mina.core.write.WriteToClosedSessionException ... (here the last two errors are repeated) Also mina, also IOException, also appears when closing Thunderbird, but different anyways.
        Hide
        Norman Maurer added a comment -

        So it happens when you close thunderbird while it try to retrieve messages ? Does the messages ever end ? or does it log in a endless loop ?

        Show
        Norman Maurer added a comment - So it happens when you close thunderbird while it try to retrieve messages ? Does the messages ever end ? or does it log in a endless loop ?

          People

          • Assignee:
            Norman Maurer
            Reporter:
            Tim-Christian Mundt
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development