Postfix Start-up Error

[fizi]

CentOS 4.4 Server CD Install
All Updates installed
Zimbra 4.5.3


When I start Zimbra I get the following:

[zimbra@phoenix sbin]$ zmcontrol start
Host phoenix.ditidahtschool.ca
        Starting ldap...Done.
        Starting logger...Done.
        Starting mailbox...Done.
        Starting antispam...Done.
        Starting antivirus...Done.
        Starting snmp...Done.
        Starting spell...Done.
        Starting mta...Done.

I then login to the Webadmin and check the status and the MTA has failed to start. I then attempt to manually start Postfix and get this error:

[zimbra@phoenix sbin]$ postfix start
postfix/postfix-script: warning: not owned by root: /opt/zimbra/postfix-2.2.9/conf/main.cf
postfix/postfix-script: starting the Postfix mail system

I ran the zmfixperms and then tried to start Postfix again and got the same error. If I manually change the perms to root owns the conf file it still doesn't start. Any ideas?

[jholder]

Take a look in /opt/zimbra/log/mailbox.log and see if there's anything in there.

[fizi]

On a normal 'service zimbra start' I got the following in the log

2007-04-08 21:35:28,316 INFO  [SIGTERM handler] [] StatsImageServlet - Servlet StatsImageServlet shutting down
2007-04-08 21:35:28,317 INFO  [SIGTERM handler] [] soap - Servlet AdminServlet shutting down
2007-04-08 21:35:28,317 INFO  [SIGTERM handler] [] TcpServer/7025 - LmtpServer initiating shutdown
2007-04-08 21:35:28,318 INFO  [LmtpServer] [] TcpServer/7025 - finished accept loop
2007-04-08 21:35:28,326 INFO  [SIGTERM handler] [] TcpServer/7025 - LmtpServer shutting down idle thread pool
2007-04-08 21:35:28,326 INFO  [SIGTERM handler] [] TcpServer/995 - Pop3Server initiating shutdown
2007-04-08 21:35:28,326 INFO  [SIGTERM handler] [] TcpServer/995 - Pop3Server shutting down idle thread pool
2007-04-08 21:35:28,326 INFO  [SIGTERM handler] [] TcpServer/993 - ImapSSLServer initiating shutdown
2007-04-08 21:35:28,326 INFO  [Pop3Server] [] TcpServer/995 - finished accept loop
2007-04-08 21:35:28,327 INFO  [ImapSSLServer] [] TcpServer/993 - finished accept loop
2007-04-08 21:35:28,327 INFO  [SIGTERM handler] [] TcpServer/993 - ImapSSLServer shutting down idle thread pool
2007-04-08 21:35:28,330 INFO  [NOTIFY-7035-Server] [] misc - spurious wakeup [1] [no attachment] interest=ACCEPT ready= key=19d3b3a poolSize=0 queueSize=0
2007-04-08 21:35:28,330 INFO  [NOTIFY-7035-Server] [] misc - shutting down thread pool
2007-04-08 21:35:28,330 INFO  [NOTIFY-7035-Server] [] misc - waiting for thread pool to shutdown
2007-04-08 21:35:28,330 INFO  [NOTIFY-7035-Server] [] misc - done waiting for thread pool to shutdown
2007-04-08 21:35:28,330 INFO  [NOTIFY-7035-Server] [] misc - closing all selection keys
2007-04-08 21:35:28,331 INFO  [NOTIFY-7035-Server] [] misc - closed selector
2007-04-08 21:35:28,331 INFO  [NOTIFY-7035-Server] [] misc - ended server loop
2007-04-08 21:35:28,332 INFO  [SIGTERM handler] [] session - shutdown: clearing SessionCache
2007-04-08 21:35:28,332 INFO  [IndexWritersSweeper] [] MailboxIndex - IndexWritersSweeper thread exiting
2007-04-08 21:35:28,332 INFO  [SIGTERM handler] [] MailboxIndex - Flushing all open index writers
2007-04-08 21:35:28,356 INFO  [SIGTERM handler] [] RedoLogManager - Logged: 0 items, 0.0ms/item
2007-04-08 21:35:28,357 INFO  [IncomingDirectorySweeper] [] FileBlobStore - IncomingDirectorySweeper thread exiting
2007-04-08 21:35:28,357 INFO  [SIGTERM handler] [] extensions - Destroying extensions
2007-04-08 21:35:28,367 INFO  [SIGTERM handler] [] extensions - Destroyed extension clamscanner: com.zimbra.clam.ClamScanner@com.zimb...extension.ZimbraExtensionClassLoader@1b48392
2007-04-08 21:35:28,368 INFO  [SIGTERM handler] [] ContentServlet - Servlet ContentServlet shutting down
2007-04-08 21:35:28,368 INFO  [SIGTERM handler] [] PublicICalServlet - Servlet PublicICalServlet shutting down
2007-04-08 21:35:28,369 INFO  [SIGTERM handler] [] soap - Servlet SoapServlet shutting down
2007-04-08 21:35:28,370 INFO  [SIGTERM handler] [] account - Servlet PreAuthServlet shutting down
2007-04-08 21:35:28,370 INFO  [SIGTERM handler] [] mailbox - Servlet UserServlet shutting down
2007-04-08 21:35:28,371 INFO  [SIGTERM handler] [] FileUploadServlet - Servlet FileUploadServlet shutting down
2007-04-08 21:36:22,124 INFO  [main] [] soap - Servlet SoapServlet starting up
2007-04-08 21:36:22,168 INFO  [main] [] soap - Adding service AccountService to SoapServlet
2007-04-08 21:36:22,308 INFO  [main] [] soap - Adding service MailService to SoapServlet
2007-04-08 21:36:22,639 INFO  [main] [] soap - Adding service IMService to SoapServlet
2007-04-08 21:36:22,648 INFO  [main] [] misc - version=4.5.3_GA_733.RHEL4 release=20070228110021 builddate=20070228-1101 buildhost=build.liquidsys.com
2007-04-08 21:36:22,650 INFO  [main] [] misc - LANG environment is set to: en_US.UTF-8
2007-04-08 21:36:22,680 INFO  [main] [] DbPool - Setting mysql connector property: maxActive=12
2007-04-08 21:36:23,199 WARN  [main] [] misc - LC.get(debug_calendar_force_utc) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_validate_outgoing_icalendar) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_conversation) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_filter) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_message_analysis) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_mime_part_extraction) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_indexing) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_objects) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_indexing_attachments_separately) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_indexing_attachments_together) was null, returning empty string
2007-04-08 21:36:23,200 WARN  [main] [] misc - LC.get(debug_disable_mailbox_group) was null, returning empty string
2007-04-08 21:36:23,214 INFO  [main] [] extensions - Loading extensions from /opt/zimbra/lib/ext
2007-04-08 21:36:23,217 INFO  [main] [] extensions - extension com.zimbra.clam.ClamScanner found in /opt/zimbra/lib/ext/clamscanner/clamscanner.jar
2007-04-08 21:36:23,218 INFO  [main] [] extensions - Initializing extensions
2007-04-08 21:36:23,227 INFO  [main] [] ClamScanner - attachment scan is disabled
2007-04-08 21:36:23,369 INFO  [main] [] extensions - Initialized extension clamscanner: com.zimbra.clam.ClamScanner@com.zimb...extension.ZimbraExtensionClassLoader@1b48392
2007-04-08 21:36:23,389 INFO  [IndexWritersSweeper] [] MailboxIndex - IndexWritersSweeper thread starting
2007-04-08 21:36:23,421 INFO  [main] [] RedoLogManager - Starting pre-startup crash recovery
2007-04-08 21:36:23,438 INFO  [main] [] RedoPlayer - No uncommitted transactions to redo
2007-04-08 21:36:23,447 INFO  [main] [] RedoLogManager - Finished pre-startup crash recovery
2007-04-08 21:36:23,488 INFO  [NOTIFY-7035-Server] [] misc - starting server loop
2007-04-08 21:36:23,514 INFO  [LmtpServer] [] TcpServer/7025 - starting accept loop
2007-04-08 21:36:23,520 INFO  [Pop3Server] [] TcpServer/995 - starting accept loop
2007-04-08 21:36:23,539 INFO  [ImapSSLServer] [] TcpServer/993 - starting accept loop
2007-04-08 21:36:23,559 INFO  [main] [] soap - Servlet AdminServlet starting up
2007-04-08 21:36:23,714 INFO  [main] [] soap - Adding service AdminService to AdminServlet
2007-04-08 21:36:23,744 INFO  [main] [] soap - Adding service AccountService to AdminServlet
2007-04-08 21:36:23,744 INFO  [main] [] soap - Adding service MailService to AdminServlet
2007-04-08 21:36:23,745 INFO  [main] [] soap - Adding service IMService to AdminServlet
2007-04-08 21:36:23,752 INFO  [main] [] ContentServlet - Servlet ContentServlet starting up
2007-04-08 21:36:23,756 INFO  [main] [] PublicICalServlet - Servlet PublicICalServlet starting up
2007-04-08 21:36:23,759 INFO  [main] [] account - Servlet PreAuthServlet starting up
2007-04-08 21:36:23,838 INFO  [main] [] mailbox - Servlet UserServlet starting up
2007-04-08 21:36:23,853 INFO  [main] [] FileUploadServlet - Servlet FileUploadServlet starting up
2007-04-08 21:36:23,858 INFO  [main] [] StatsImageServlet - Servlet StatsImageServlet starting up

I can't see any errors in there that could be causing the error.

[jholder]

k-
Nothin in there.
What about /var/log/zimbra.log

[fizi]

The plot thickens. Seems Post fix thinks it's tomorrow yet the server has the correct time.

Apr  8 23:16:03 localhost zmtomcatmgr[28834]: status requested
Apr  8 23:16:03 localhost zmtomcatmgr[28834]: status OK
Apr  9 06:16:03 localhost postfix/postqueue[28851]: fatal: Queue report unavailable - mail system is down
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: antispam: Running
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: antivirus: Running
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: ldap: Running
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: logger: Running
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: mailbox: Running
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: mta: Stopped
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: snmp: Running
Apr  8 23:16:04 localhost zimbramon[28677]: 28677:info: 2007-04-08 23:16:01, STATUS: phoenix.ditidahtschool.ca: spell: Running
Apr  8 23:16:06 localhost su(pam_unix)[28675]: session opened for user root by xxxxxxxxxx(uid=xxxx)
Apr  8 23:18:05 localhost zmtomcatmgr[29349]: status requested
Apr  8 23:18:05 localhost zmtomcatmgr[29349]: status OK
Apr  9 06:18:05 localhost postfix/postqueue[29366]: fatal: Queue report unavailable - mail system is down
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: antispam: Running
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: antivirus: Running
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: ldap: Running
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: logger: Running
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: mailbox: Running
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: mta: Stopped
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: snmp: Running
Apr  8 23:18:06 localhost zimbramon[29142]: 29142:info: 2007-04-08 23:18:01, STATUS: phoenix.ditidahtschool.ca: spell: Running
Apr  9 06:20:01 localhost postfix/postqueue[29701]: fatal: Queue report unavailable - mail system is down

[jholder]

I don't know what's goin on here.

Let's backup:
su - zimbra
zmcontrol stop
su - root
ps auxx | grep zimbra
---------
(**ONLY If you have left over processes, run this: )
kill -9 `ps -u zimbra -o "pid="`
---------
rsync -avr /opt/zimbra /backup/local
cd /install/location/zcs
./install.sh -s

Let's see if that fixes things.

-john

[fizi]

Ha. How embarrasing. I went in and shutdown Zimbra, then shutdown the default install of sendmail that comes with the OS, restarted Zimbra and everything is working fine now. Thanks for the help.

[jholder]

What's even more embarrassing is that I should have known that

Glad it's working!