POP3 server dies every hour

[jdossey7]

I hope someone can help me with this. At about 11am this morning, the POP3 server in Zimbra 4.5.6 started dieing about every hour. IMAP still works, along with everything else. It's just POP3 that isn't working.

Where would I start to look to find the problem?

We are running Zimbra 4.5.6 Open Source Edition on CentOS 4.4.

[jholder]

Can you post your logs?

Specifically:
/opt/zimbra/log/mailbox.log

[jdossey7]

Here is mailbox.log - I've stripped out a lot of the entries that don't pertain to the Pop3 server:
Here are the last few entries just before it stopped working

2007-09-27 14:02:04,467 INFO  [Pop3Server-527] [name=debbie@bgs.cc;ip=192.168.101.36;] pop - connected
2007-09-27 14:02:04,752 INFO  [Pop3Server-527] [name=debbie@bgs.cc;ip=192.168.101.36;] pop - quit from client
2007-09-27 14:02:04,753 INFO  [Pop3Server-527] [name=debbie@bgs.cc;ip=192.168.101.36;] ProtocolHandler - Handler exiting normally
2007-09-27 14:02:06,165 INFO  [Pop3Server-527] [name=debbie@bgs.cc;ip=192.168.101.36;] pop - connected
2007-09-27 14:02:06,448 INFO  [Pop3Server-527] [name=sue@bgs.cc;ip=192.168.101.46;] pop - quit from client
2007-09-27 14:02:06,449 INFO  [Pop3Server-527] [name=sue@bgs.cc;ip=192.168.101.46;] ProtocolHandler - Handler exiting normally
2007-09-27 14:02:08,222 INFO  [Pop3Server-527] [name=sue@bgs.cc;ip=192.168.101.46;] pop - connected
2007-09-27 14:02:10,251 INFO  [Pop3Server-527] [name=kim@bgs.cc;ip=68.101.92.251;] pop - quit from client
2007-09-27 14:02:10,252 INFO  [Pop3Server-527] [name=kim@bgs.cc;ip=68.101.92.251;] ProtocolHandler - Handler exiting normally
2007-09-27 14:02:19,129 INFO  [Pop3Server-527] [name=kim@bgs.cc;ip=68.101.92.251;] pop - connected
2007-09-27 14:02:19,403 INFO  [Pop3Server-527] [name=jim@bgs.cc;ip=192.168.101.40;] pop - quit from client
2007-09-27 14:02:19,403 INFO  [Pop3Server-527] [name=jim@bgs.cc;ip=192.168.101.40;] ProtocolHandler - Handler exiting normally
2007-09-27 14:02:27,576 INFO  [Pop3Server-527] [name=jim@bgs.cc;ip=192.168.101.40;] pop - connected

And then here is what happened when I rebooted Zimbra:

2007-09-27 14:29:06,699 INFO  [SIGTERM handler] [] StatsImageServlet - Servlet StatsImageServlet shutting down
2007-09-27 14:29:06,703 INFO  [SIGTERM handler] [] soap - Servlet AdminServlet shutting down
2007-09-27 14:29:06,704 INFO  [SIGTERM handler] [] TcpServer/7025 - LmtpServer initiating shutdown
2007-09-27 14:29:06,704 INFO  [LmtpServer] [] TcpServer/7025 - finished accept loop
2007-09-27 14:29:06,770 INFO  [SIGTERM handler] [] TcpServer/7025 - LmtpServer shutting down idle thread pool
2007-09-27 14:29:06,771 INFO  [SIGTERM handler] [] TcpServer/110 - Pop3Server initiating shutdown
2007-09-27 14:29:06,772 INFO  [Pop3Server] [] TcpServer/110 - finished accept loop
2007-09-27 14:29:06,772 INFO  [SIGTERM handler] [] ProtocolHandler - graceful shutdown requested
2007-09-27 14:29:06,772 INFO  [SIGTERM handler] [] TcpServer/110 - Pop3Server waiting 10 seconds for thread pool shutdown
2007-09-27 14:29:16,784 INFO  [SIGTERM handler] [] ProtocolHandler - hard shutdown requested
2007-09-27 14:29:16,785 INFO  [SIGTERM handler] [] TcpServer/110 - Pop3Server shutdown complete
2007-09-27 14:29:16,785 INFO  [SIGTERM handler] [] TcpServer/995 - Pop3Server initiating shutdown
2007-09-27 14:29:16,787 INFO  [Pop3Server-2] [ip=192.168.101.53;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,789 INFO  [Pop3Server] [] TcpServer/995 - finished accept loop
2007-09-27 14:29:16,789 INFO  [SIGTERM handler] [] ProtocolHandler - graceful shutdown requested
2007-09-27 14:29:16,791 INFO  [Pop3Server-361] [] ProtocolHandler - Exception occurred while handling connection
java.net.SocketException: Socket closed
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
    at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:723)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1030)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:622)
    at com.sun.net.ssl.internal.ssl.AppOutputStream.write(AppOutputStream.java:59)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
    at com.zimbra.cs.pop3.Pop3Handler.sendLine(Pop3Handler.java:382)
    at com.zimbra.cs.pop3.Pop3Handler.sendResponse(Pop3Handler.java:371)
    at com.zimbra.cs.pop3.Pop3Handler.sendOK(Pop3Handler.java:354)
    at com.zimbra.cs.pop3.Pop3Handler.setupConnection(Pop3Handler.java:115)
    at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:196)
    at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:595)
2007-09-27 14:29:16,793 INFO  [SIGTERM handler] [] ProtocolHandler - graceful shutdown requested
2007-09-27 14:29:16,795 INFO  [Pop3Server-378] [] ProtocolHandler - Exception occurred while handling connection
java.net.SocketException: Socket closed
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
    at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:723)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1030)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:622)
    at com.sun.net.ssl.internal.ssl.AppOutputStream.write(AppOutputStream.java:59)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
    at com.zimbra.cs.pop3.Pop3Handler.sendLine(Pop3Handler.java:382)
    at com.zimbra.cs.pop3.Pop3Handler.sendResponse(Pop3Handler.java:371)
    at com.zimbra.cs.pop3.Pop3Handler.sendOK(Pop3Handler.java:354)
    at com.zimbra.cs.pop3.Pop3Handler.setupConnection(Pop3Handler.java:115)
    at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:196)
    at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:595)

That SocketException error repeats several times followed by this:

2007-09-27 14:29:16,832 INFO  [SIGTERM handler] [] ProtocolHandler - graceful shutdown requested
2007-09-27 14:29:16,833 INFO  [Pop3Server-527] [name=jim@bgs.cc;ip=192.168.101.40;] ProtocolHandler - Exception occurred while handling connection
java.net.SocketException: Socket closed
    at java.net.SocketInputStream.socketRead0(Native Method)
    at java.net.SocketInputStream.read(SocketInputStream.java:129)
    at com.sun.net.ssl.internal.ssl.InputRecord.readFully(InputRecord.java:293)
    at com.sun.net.ssl.internal.ssl.InputRecord.read(InputRecord.java:331)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.readRecord(SSLSocketImpl.java:723)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.performInitialHandshake(SSLSocketImpl.java:1030)
    at com.sun.net.ssl.internal.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:622)
    at com.sun.net.ssl.internal.ssl.AppOutputStream.write(AppOutputStream.java:59)
    at java.io.BufferedOutputStream.flushBuffer(BufferedOutputStream.java:65)
    at java.io.BufferedOutputStream.flush(BufferedOutputStream.java:123)
    at com.zimbra.cs.pop3.Pop3Handler.sendLine(Pop3Handler.java:382)
    at com.zimbra.cs.pop3.Pop3Handler.sendResponse(Pop3Handler.java:371)
    at com.zimbra.cs.pop3.Pop3Handler.sendOK(Pop3Handler.java:354)
    at com.zimbra.cs.pop3.Pop3Handler.setupConnection(Pop3Handler.java:115)
    at com.zimbra.cs.tcpserver.ProtocolHandler.run(ProtocolHandler.java:196)
    at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:595)
2007-09-27 14:29:16,834 INFO  [SIGTERM handler] [] TcpServer/995 - Pop3Server waiting 10 seconds for thread pool shutdown
2007-09-27 14:29:16,834 INFO  [Pop3Server-413] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,834 INFO  [Pop3Server-476] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,835 INFO  [Pop3Server-522] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,835 INFO  [Pop3Server-523] [name=kim@bgs.cc;ip=68.101.92.251;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,835 INFO  [Pop3Server-525] [name=sue@bgs.cc;ip=192.168.101.46;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,836 INFO  [Pop3Server-524] [name=jessica@bgs.cc;ip=192.168.101.37;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,836 INFO  [Pop3Server-526] [name=dave@bgs.cc;ip=70.121.191.0;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,836 INFO  [Pop3Server-520] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,837 INFO  [Pop3Server-504] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,837 INFO  [Pop3Server-498] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,837 INFO  [Pop3Server-484] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,838 INFO  [Pop3Server-472] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,838 INFO  [Pop3Server-461] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,838 INFO  [Pop3Server-420] [name=chris@bgs.cc;ip=192.168.101.34;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,839 INFO  [Pop3Server-419] [name=chris@bgs.cc;ip=192.168.101.34;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,839 INFO  [Pop3Server-389] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,840 INFO  [Pop3Server-388] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,840 INFO  [Pop3Server-378] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,840 INFO  [Pop3Server-361] [] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,841 INFO  [Pop3Server-527] [name=jim@bgs.cc;ip=192.168.101.40;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,841 INFO  [SIGTERM handler] [] TcpServer/995 - Pop3Server thread pool terminated
2007-09-27 14:29:16,841 INFO  [SIGTERM handler] [] TcpServer/143 - ImapServer initiating shutdown
2007-09-27 14:29:16,842 INFO  [ImapServer] [] TcpServer/143 - finished accept loop
2007-09-27 14:29:16,842 INFO  [SIGTERM handler] [] TcpServer/143 - ImapServer shutting down idle thread pool
2007-09-27 14:29:16,842 INFO  [SIGTERM handler] [] TcpServer/993 - ImapSSLServer initiating shutdown
2007-09-27 14:29:16,843 INFO  [ImapSSLServer] [] TcpServer/993 - finished accept loop
2007-09-27 14:29:16,843 INFO  [SIGTERM handler] [] ProtocolHandler - graceful shutdown requested
2007-09-27 14:29:16,844 INFO  [ImapSSLServer-1] [name=jfd@bgs.cc;ip=71.52.10.255;] ProtocolHandler - Handler exiting normally
2007-09-27 14:29:16,845 INFO  [SIGTERM handler] [] TcpServer/993 - ImapSSLServer shutting down idle thread pool
2007-09-27 14:29:16,890 INFO  [NOTIFY-7035-Server] [] misc - spurious wakeup [1] [no attachment] interest=ACCEPT ready= key=1f217ec poolSize=0 queueSize=0

[jholder]

Shot in the dark here, but can you look to see if you have another pop3 server running on your box?

[jdossey7]

I thought about that too, but there isn't even another pop3 server installed.

I used lsof to track down which process was listening on ports 110 and 995 and it does appear to be tomcat.

[jholder]

Can you upload your whole log as a txt attachment? Be sure to wipe your server name.

Thanks
jh

[mmorse]

while your doing that-just out of curiosity-what's your max allowed pop threads set at?
(yes I know that shows as a different error-usually a direct refused or timeout) I just want to get a feel for the number of users you have, etc.

[jdossey7]

It's funny. The number of pop threads field is blank in Global Settings. I entered '200' and clicked Save, but it just goes blank again. When I go to the server to set it, it comes up with '20'. I changed it to '200' and clicked Save, and it seems to save it. But if I click the "Reset to Global value" button, it changes to '20'.

[mmorse]

- that '20' in global settings issue may already be an open bug...

-you could set it using zmprov/zmlocalconfig on the global & server levels, then restart to be sure it applies properly
zmprov ms servername zimbraPop3NumThreads 200

(This was the RFE for increasing the initial/default # of zimbraPop3NumThreads to something more than 20: Bug 18388 - increase default value of POP3 threads)

(The reason I asked before is because I knew the logs wouldn't tell us your max threads value: Bug 7928 - add # of threads for log info)

[jdossey7]

I used zmprov to change it to 200 since I couldn't be sure what the Global value was in the UI. I'm going to let it run like that for awhile and see what happens.