MTA and Mailbox die periodically...

[andreturpin]

I'm not sure why I keep getting the MTA and Mailbox services dieing periodically on one of my servers. I've looked at a couple of other posts that look like the same or similar issue and didn't get much out of them. Seems like it dies around 11:45 at nite on a fairly regular basis. I found an error in the logs awhile back and thought it was the root of the problem, but still seems to be happening (sorry, can't remember the exact details of the error...strong case for keeping a log of everything I work on and details).

I've included a snip of the events that occur just before the services quit working...

Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: antispam: Running
Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: antivirus: Running
Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: imapproxy: Running
Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: mailbox: Running
Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: mta: Running
Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: snmp: Running
Jun 8 23:40:08 yk zimbramon[14935]: 14935:info: 2006-06-08 23:40:02, STATUS: yk.kinglandford.com: spell: Running
Jun 8 23:42:15 yk zimbramon[15370]: 15370:info: 2006-06-08 23:42:02, STATUS: : Cannot: determine
Jun 8 23:42:21 yk postfix/postfix-script: refreshing the Postfix mail system
Jun 8 23:42:22 yk postfix/master[30858]: reload configuration /opt/zimbra/postfix-2.2.9/conf
Jun 8 23:43:49 yk postfix/postfix-script: refreshing the Postfix mail system
Jun 8 23:43:49 yk postfix/master[30858]: reload configuration /opt/zimbra/postfix-2.2.9/conf
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: antispam: Running
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: antivirus: Running
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: imapproxy: Running
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: mailbox: Stopped
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: mta: Stopped
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: snmp: Running
Jun 8 23:44:07 yk zimbramon[15639]: 15639:info: 2006-06-08 23:44:01, STATUS: yk.kinglandford.com: spell: Running
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: antispam: Running
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: antivirus: Running
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: imapproxy: Running
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: mailbox: Stopped
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: mta: Stopped
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: snmp: Running
Jun 8 23:46:07 yk zimbramon[15949]: 15949:info: 2006-06-08 23:46:01, STATUS: yk.kinglandford.com: spell: Running
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: antispam: Running
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: antivirus: Running
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: imapproxy: Running
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: mailbox: Stopped
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: mta: Stopped
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: snmp: Running
Jun 8 23:48:07 yk zimbramon[16329]: 16329:info: 2006-06-08 23:48:01, STATUS: yk.kinglandford.com: spell: Running
Jun 8 23:50:01 yk zimbramon[16725]: 16725:info: 2006-06-08 23:50:01, QUEUE: 0 0

It seems like zimbramon is doing it's usual polling of services, it finds it can't communicate with the mta, so it tries to refresh the postfix configuration. No idea on this one. Posting configuration notes here...

av_notify_user = admin@kinglandford.com
ldap_connect_pool_debug = false
ldap_connect_pool_initsize = 1
ldap_connect_pool_maxsize = 25
ldap_connect_pool_prefsize = 0
ldap_connect_pool_timeout = 120000
ldap_connect_timeout = 10000
ldap_host =
ldap_is_master = false
ldap_log_level = 0
ldap_master_url = ldap://hr.kinglandford.com:389
ldap_port =
ldap_root_password = *
ldap_url = ldap://hr.kinglandford.com
localized_msgs_directory = ${zimbra_home}/conf/msgs
logger_mysql_bind_address = localhost
logger_mysql_data_directory = ${zimbra_home}/logger/db/data
logger_mysql_directory = ${zimbra_home}/logger/mysql
logger_mysql_mycnf = ${zimbra_home}/conf/my.logger.cnf
logger_mysql_pidfile = ${zimbra_home}/logger/db/mysql.pid
logger_mysql_port = 7307
logger_mysql_socket = ${zimbra_home}/logger/db/mysql.sock
mysql_bind_address = localhost
mysql_data_directory = ${zimbra_db_directory}/data
mysql_directory = ${zimbra_home}/mysql
mysql_innodb_log_buffer_size = 8388608
mysql_innodb_log_file_size = 104857600
mysql_logger_root_password = *
mysql_memory_percent = 40
mysql_mycnf = ${zimbra_home}/conf/my.cnf
mysql_pidfile = ${zimbra_db_directory}/mysql.pid
mysql_port = 7306
mysql_read_buffer_size = 1048576
mysql_root_password = *
mysql_socket = ${zimbra_db_directory}/mysql.sock
mysql_sort_buffer_size = 1048576
mysql_table_cache = 500
nio_imap_enable = false
nio_imap_log_buffers = false
postfix_alias_maps = hash:/etc/aliases
postfix_broken_sasl_auth_clients = yes
postfix_command_directory = /opt/zimbra/postfix-${postfix_version}/sbin
postfix_daemon_directory = /opt/zimbra/postfix-${postfix_version}/libexec
postfix_header_checks = pcre:/opt/zimbra/conf/postfix_header_checks
postfix_mailq_path = /opt/zimbra/postfix-${postfix_version}/sbin/mailq
postfix_manpage_directory = /opt/zimbra/postfix-${postfix_version}/man
postfix_newaliases_path = /opt/zimbra/postfix-${postfix_version}/sbin/newaliases
postfix_queue_directory = /opt/zimbra/postfix-${postfix_version}/spool
postfix_sender_canonical_maps = ldap:/opt/zimbra/conf/ldap-scm.cf
postfix_sendmail_path = /opt/zimbra/postfix-${postfix_version}/sbin/sendmail
postfix_smtpd_client_restrictions = reject_unauth_pipelining
postfix_smtpd_data_restrictions = reject_unauth_pipelining
postfix_smtpd_helo_required = yes
postfix_smtpd_tls_cert_file = ${zimbra_home}/conf/smtpd.crt
postfix_smtpd_tls_key_file = ${zimbra_home}/conf/smtpd.key
postfix_smtpd_tls_loglevel = 3
postfix_transport_maps = ldap:/opt/zimbra/conf/ldap-transport.cf
postfix_version = 2.2.9
postfix_virtual_alias_domains = ldap://opt/zimbra/conf/ldap-vad.cf
postfix_virtual_alias_maps = ldap:/opt/zimbra/conf/ldap-vam.cf
postfix_virtual_mailbox_domains = ldap:/opt/zimbra/conf/ldap-vmd.cf
postfix_virtual_mailbox_maps = ldap:/opt/zimbra/conf/ldap-vmm.cf
postfix_virtual_transport = error
smtp_destination = admin@kinglandford.com
smtp_notify = yes
smtp_source = admin@kinglandford.com
snmp_notify = yes
snmp_trap_host = yk.kinglandford.com
ssl_allow_untrusted_certs = TRUE
stats_img_folder = ${zimbra_home}/zimbramon/rrdtool/work
tomcat_directory = ${zimbra_home}/tomcat
tomcat_java_heap_memory_percent = 30
tomcat_java_home = ${zimbra_java_home}
tomcat_java_options = -client -XX:NewRatio=2
tomcat_keystore = ${tomcat_directory}/conf/keystore
tomcat_pidfile = ${zimbra_log_directory}/tomcat.pid
wiki_enabled = false
wiki_user = wiki
zimbra_auth_always_send_refer = false
zimbra_db_directory = ${zimbra_home}/db
zimbra_extension_directory = ${zimbra_home}/lib/ext
zimbra_gid = 501
zimbra_home = /opt/zimbra
zimbra_index_directory = ${zimbra_home}/index
zimbra_index_idle_flush_time = 600
zimbra_index_lru_size = 100
zimbra_index_max_uncommitted_operations = 200
zimbra_java_home = ${zimbra_home}/java
zimbra_ldap_password = *
zimbra_ldap_userdn = uid=zimbra,cn=admins,cn=zimbra
zimbra_log4j_properties = ${zimbra_home}/conf/log4j.properties
zimbra_log_directory = ${zimbra_home}/log
zimbra_logger_mysql_password = *
zimbra_mtareport_max_recipients = 50
zimbra_mtareport_max_senders = 50
zimbra_mysql_connector_maxActive = 10
zimbra_mysql_password = *
zimbra_mysql_user = zimbra
zimbra_server_hostname = yk.kinglandford.com
zimbra_spam_report_queue_size = 100
zimbra_store_directory = ${zimbra_home}/store
zimbra_store_sweeper_max_age = 480
zimbra_tmp_directory = /tmp/zimbra
zimbra_uid = 501
zimbra_user = zimbra
zimlet_directory = ${tomcat_directory}/webapps/service/zimlet

[zimbra@yk log]$ zmmtactl status
cat: /opt/zimbra/cyrus-sasl-2.1.21.ZIMBRA/state/saslauthd.pid: No such file or directory
zmsaslauthdctl is not running

[zimbra@yk log]$ zmmailboxctl status
tomcat is not running

[bobby]

what's in /opt/zimbra/log/zimbra.log around/before the same time?

[andreturpin]

I had a look at the log inside the /opt/zimbra/log directory from that day around the same time, and was looking for something right at or shortly before when the service decided to konk out...and pasted below what I found...

Seems very consistent, then right around the time that I noticed the services offline things started happening in this log (/opt/zimbra/log/zimbra.log for that particular day) but it seems like they occured in this log _after_ I noticed the services offline in /var/log/zimbra.log, so it's hard to point to a cause/effect with this information. I'm not sure what other information I should be looking for. It's been about a day and a half now and the services are fine, but I've noticed this before, that they seem fine then just quit sporadically and I only find out when I go into admin console to do some work (these machines aren't production yet so I don't have users calling to complain...that's next week :P)
===========
2006-06-08 23:34:32,447 INFO [Timer-0] [] stats - 06/08/2006 23:34:32,,,,,,8,0.25,,,,,,,,,,,,,,33.526,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:35:32,447 INFO [Timer-0] [] stats - 06/08/2006 23:35:32,,,,,,8,0.25,,,,,,,,,,,,,,33.526,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:36:32,474 INFO [Timer-0] [] stats - 06/08/2006 23:36:32,,,,,,8,0.38,,,,,,,,,,,,,,35.153,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:37:32,469 INFO [Timer-0] [] stats - 06/08/2006 23:37:32,,,,,,8,0.13,,,,,,,,,,,,,,35.153,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:38:32,464 INFO [Timer-0] [] stats - 06/08/2006 23:38:32,,,,,,8,1.63,,,,,,,,,,,,,,35.153,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:39:32,463 INFO [Timer-0] [] stats - 06/08/2006 23:39:32,,,,,,8,0.13,,,,,,,,,,,,,,35.153,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:40:32,484 INFO [Timer-0] [] stats - 06/08/2006 23:40:32,,,,,,8,2.50,,,,,,,,,,,,,,35.153,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:41:32,486 INFO [Timer-0] [] stats - 06/08/2006 23:41:32,,,,,,8,3.00,,,,,,,,,,,,,,35.153,0,105,66, 1,85,308,,0,0,0,0
2006-06-08 23:42:29,117 INFO [main] [] StatsImageServlet - Servlet StatsImageServlet shutting down
2006-06-08 23:42:29,175 INFO [main] [] soap - Servlet AdminServlet shutting down
2006-06-08 23:42:29,186 INFO [main] [] TcpServer/7025 - LmtpServer initiating shutdown
2006-06-08 23:42:29,288 INFO [LmtpServer] [] TcpServer/7025 - finished accept loop
2006-06-08 23:42:29,969 INFO [main] [] TcpServer/7025 - LmtpServer shutting down idle thread pool
2006-06-08 23:42:29,969 INFO [main] [] TcpServer/7110 - Pop3Server initiating shutdown
2006-06-08 23:42:29,970 INFO [main] [] TcpServer/7110 - Pop3Server shutting down idle thread pool
2006-06-08 23:42:29,970 INFO [main] [] TcpServer/7995 - Pop3Server initiating shutdown
2006-06-08 23:42:29,970 INFO [main] [] TcpServer/7995 - Pop3Server shutting down idle thread pool
2006-06-08 23:42:29,970 INFO [main] [] TcpServer/7143 - ImapServer initiating shutdown
2006-06-08 23:42:29,970 INFO [main] [] TcpServer/7143 - ImapServer shutting down idle thread pool
2006-06-08 23:42:29,974 INFO [Pop3Server] [] TcpServer/7995 - finished accept loop
2006-06-08 23:42:29,993 INFO [main] [] TcpServer/7993 - ImapSSLServer initiating shutdown
2006-06-08 23:42:29,999 INFO [ImapServer] [] TcpServer/7143 - finished accept loop
2006-06-08 23:42:29,986 INFO [Pop3Server] [] TcpServer/7110 - finished accept loop
2006-06-08 23:42:30,000 INFO [ImapSSLServer] [] TcpServer/7993 - finished accept loop
2006-06-08 23:42:30,000 INFO [main] [] TcpServer/7993 - ImapSSLServer shutting down idle thread pool
2006-06-08 23:42:30,537 INFO [main] [] SessionCache - shutdown: clearing SessionCache
2006-06-08 23:42:30,551 INFO [IndexWritersSweeper] [] MailboxIndex - IndexWritersSweeper thread exiting
2006-06-08 23:42:30,551 INFO [main] [] MailboxIndex - Flushing all open index writers
2006-06-08 23:42:31,384 INFO [main] [] RedoLogManager - Logged: 66 items, 13.258ms/item
2006-06-08 23:42:31,384 INFO [IncomingDirectorySweeper] [] FileBlobStore - IncomingDirectorySweeper thread exiting
2006-06-08 23:42:31,418 INFO [main] [] extensions - Destroying extensions
2006-06-08 23:42:31,729 INFO [main] [] extensions - Destroyed extension clamscanner: com.zimbra.clam.ClamScanner@com.zimbra.cs.exte
nsion.ZimbraExtensionClassLoader@17f1841
2006-06-08 23:42:31,730 INFO [main] [] ContentServlet - Servlet ContentServlet shutting down
2006-06-08 23:42:31,732 INFO [main] [] PublicICalServlet - Servlet PublicICalServlet shutting down
2006-06-08 23:42:31,776 INFO [main] [] soap - Servlet SoapServlet shutting down
2006-06-08 23:42:31,776 INFO [main] [] account - Servlet PreAuthServlet shutting down
2006-06-08 23:42:31,796 INFO [main] [] mailbox - Servlet UserServlet shutting down
2006-06-08 23:42:31,797 INFO [main] [] FileUploadServlet - Servlet FileUploadServlet shutting down

(end of log here, I guess with mta and mailbox offline there ain't much activity in the logs)

[bobby]

during the time when mta and mailbox are Stopped, run these to find out which parts are not running:

sh -x ~/bin/zmmtactl status
sh -x ~/bin/zmmailboxctl status

have you injected a bunch of mail to the server? the spam training runs at 11:45. maybe look in /opt/zimbra/log/spamtrain.log. ...though your log shows down at 11:44