Zimbra offers Open Source email server software and shared calendar for Linux and the Mac
  #1 (permalink)  
Old 09-27-2007, 11:38 AM
jdossey7 jdossey7 is offline
Member
 
Join Date: Aug 2007
Posts: 17
jdossey7 is on a distinguished road
Default POP3 server dies every hour

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.
Reply With Quote
  #2 (permalink)  
Old 09-27-2007, 11:39 AM
jholder's Avatar
jholder jholder is offline
Zimbra Employee
 
Join Date: Oct 2005
Location: San Mateo, CA
ZCS Version: 5.0.5 RHEL4 64-bit GA
Posts: 5,428
jholder is on a distinguished road
Send a message via Yahoo to jholder
Default

Can you post your logs?

Specifically:
/opt/zimbra/log/mailbox.log
__________________
Reply With Quote
  #3 (permalink)  
Old 09-27-2007, 11:55 AM
jdossey7 jdossey7 is offline
Member
 
Join Date: Aug 2007
Posts: 17
jdossey7 is on a distinguished road
Default

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
Code:
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:

Code:
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:

Code:
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
Reply With Quote
  #4 (permalink)  
Old 09-27-2007, 11:59 AM
jholder's Avatar
jholder jholder is offline
Zimbra Employee
 
Join Date: Oct 2005
Location: San Mateo, CA
ZCS Version: 5.0.5 RHEL4 64-bit GA
Posts: 5,428
jholder is on a distinguished road
Send a message via Yahoo to jholder
Default

Shot in the dark here, but can you look to see if you have another pop3 server running on your box?
__________________
Reply With Quote
  #5 (permalink)  
Old 09-27-2007, 12:13 PM
jdossey7 jdossey7 is offline
Member
 
Join Date: Aug 2007
Posts: 17
jdossey7 is on a distinguished road
Default

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.
Reply With Quote
  #6 (permalink)  
Old 09-27-2007, 12:17 PM
jholder's Avatar
jholder jholder is offline
Zimbra Employee
 
Join Date: Oct 2005
Location: San Mateo, CA
ZCS Version: 5.0.5 RHEL4 64-bit GA
Posts: 5,428
jholder is on a distinguished road
Send a message via Yahoo to jholder
Default

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

Thanks
jh
__________________
Reply With Quote
  #7 (permalink)  
Old 09-27-2007, 12:23 PM
mmorse's Avatar
mmorse mmorse is offline
Zimbra Employee
 
Join Date: May 2006
Location: USA
ZCS Version: NE & OS - in the many flavors of 4.5 & 5.0
Posts: 4,455
mmorse is on a distinguished road
Send a message via AIM to mmorse Send a message via MSN to mmorse Send a message via Yahoo to mmorse Send a message via Skype™ to mmorse
Default

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.

Last edited by mmorse : 09-27-2007 at 12:53 PM.
Reply With Quote
  #8 (permalink)  
Old 09-27-2007, 12:33 PM
jdossey7 jdossey7 is offline
Member
 
Join Date: Aug 2007
Posts: 17
jdossey7 is on a distinguished road
Default

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'.
Reply With Quote
  #9 (permalink)  
Old 09-27-2007, 12:40 PM
mmorse's Avatar
mmorse mmorse is offline
Zimbra Employee
 
Join Date: May 2006
Location: USA
ZCS Version: NE & OS - in the many flavors of 4.5 & 5.0
Posts: 4,455
mmorse is on a distinguished road
Send a message via AIM to mmorse Send a message via MSN to mmorse Send a message via Yahoo to mmorse Send a message via Skype™ to mmorse
Default

- 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)

Last edited by mmorse : 09-27-2007 at 12:54 PM.
Reply With Quote
  #10 (permalink)  
Old 09-27-2007, 12:49 PM
jdossey7 jdossey7 is offline
Member
 
Join Date: Aug 2007
Posts: 17
jdossey7 is on a distinguished road
Default

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.
Reply With Quote
Reply


Thread Tools
Display Modes

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

vB code is On
Smilies are On
[IMG] code is On
HTML code is Off
Trackbacks are On
Pingbacks are On
Refbacks are On


Similar Threads
Thread Thread Starter Forum Replies Last Post
Daily mail report always reports "No messages found" McPringle Installation 40 04-13-2008 04:52 PM
need advice on configuring zimbra to work with fax server pheonix1t Administrators 0 07-11-2007 07:46 PM
Server/Disk Statistics revisited phoenix Administrators 16 03-07-2006 02:18 PM
No data in server statistics zap Administrators 63 02-13-2006 10:39 AM
Zimbra fails after working for 2 weeks Linsys Administrators 9 10-20-2005 01:26 PM


freshmeat.net sourceforge.net The best Java IDE



 

Search Engine Optimization by vBSEO 3.0.0