Boot time log: 'Failed to start Postfix Mail Transport Agent'

Question

centos 7.1
postfix 2.10.1

After restarting server in /var/log/messages during boot time Postfix noted only in these 4 lines (all actions during 1 second):

systemd: Starting Postfix Mail Transport Agent...
systemd: postfix.service: control process exited, code=exited status=1
systemd: Failed to start Postfix Mail Transport Agent.
systemd: Unit postfix.service entered failed state.

At the same time (during the SAME one second) in /var/log/maillog only 1 line:

postfix/postfix-script[2069]: fatal: the Postfix mail system is already running

1). Where is possible to find additional information about this error?
2). How it is possible is already running if in system log before this time no any records about Postfix?

UPDATE
If I run Postfix by hand - it is all perfect! Problem is only during boot time.

systemctl start postfix
journalctl -xe

May 30 17:41:58 CentOS-70-64-minimal systemd[1]: Starting Postfix Mail Transport Agent...
-- Subject: Unit postfix.service has begun with start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit postfix.service has begun starting up.
May 30 17:41:59 CentOS-70-64-minimal postfix/postfix-script[6524]: starting the Postfix mail system
May 30 17:41:59 CentOS-70-64-minimal postfix/master[6526]: daemon started -- version 2.10.1, configuration /etc/postfix
May 30 17:41:59 CentOS-70-64-minimal systemd[1]: Started Postfix Mail Transport Agent.
-- Subject: Unit postfix.service has finished start-up
-- Defined-By: systemd
-- Support: http://lists.freedesktop.org/mailman/listinfo/systemd-devel
-- 
-- Unit postfix.service has finished starting up.
-- 
-- The start-up result is done.
May 30 17:42:06 CentOS-70-64-minimal postfix/postfix-script[6538]: the Postfix mail system is running: PID: 6526

UPDATE 2

Wow, not perfect at the end.... I try to send email:

php -a
mail('[email protected]','subject','text');

And get errors.

/var/log/maillog

May 30 17:41:59  postfix/postfix-script[6524]: starting the Postfix mail system
May 30 17:41:59  postfix/master[6526]: daemon started -- version 2.10.1, configuration /etc/postfix
May 30 17:42:06  postfix/postfix-script[6538]: the Postfix mail system is running: PID: 6526
May 30 17:51:35  postfix/pickup[6527]: A4DC31180305: uid=0 from=<root>
May 30 17:51:35  postfix/cleanup[6554]: A4DC31180305: message-id=<[email protected]>
May 30 17:51:35  postfix/qmgr[6528]: A4DC31180305: from=<[email protected]>, size=411, nrcpt=2 (queue active)
May 30 17:51:35  postfix/smtp[6556]: fatal: open lock file pid/unix.smtp: cannot open file: Permission denied
May 30 17:51:35  postfix/cleanup[6554]: C483211802E1: message-id=<[email protected]>
May 30 17:51:35  postfix/qmgr[6528]: C483211802E1: from=<[email protected]>, size=579, nrcpt=1 (queue active)
May 30 17:51:35  postfix/local[6557]: A4DC31180305: to=<[email protected]>, relay=local, delay=0.28, delays=0.17/0.04/0/0.07, dsn=2.0.0, status=sent (forwarded as C483211802E1)
May 30 17:51:36  postfix/master[6526]: warning: process /usr/libexec/postfix/smtp pid 6556 exit status 1
May 30 17:51:36  postfix/master[6526]: warning: /usr/libexec/postfix/smtp: bad command startup -- throttling
May 30 17:52:36  postfix/smtp[6558]: fatal: open lock file pid/unix.smtp: cannot open file: Permission denied

netstat -nlap | grep ':25'

tcp        0      0 127.0.0.1:25            0.0.0.0:*               LISTEN      6526/master

postfix status

postfix/postfix-script: the Postfix mail system is running: PID: 6526

UPDATE 3

Good day again!
Something not obviously and strange are presents in system :)
I'm not changed any settings, restarted server again and saw that all works as must.
Just two line in /var/log/messages during boot time and Postfix is simply started:

systemd: Starting Postfix Mail Transport Agent...
systemd: Started Postfix Mail Transport Agent.

Thank You for advice!!

Solution

For the 2nd question: it's possible for the logfiles to have been rotated since the service started (meaning the logs are now in some other files).

For the issue: it's possible for the "is already running" message to be misleading: usually it takes a rather long time (tens of seconds) between when a server process exits without cleanly closing the sockets/ports it listens to until another server instance can successfully bind and listen to the same port. I'd say it's plausible that the message simply indicates such binding failure (same failure is also seen if another server instance is insdeed still running).

I'd check if another instance is actually running and try againt to start the service if not.

In general I suggest stopping a service, waiting a bit and then starting it (as opposed to simply restarting it), unless the service explicitly supports a graceful restart.

Comments

[squareborg]

Try starting postfix when the system is up systemctl start postfix then see if it starts, if it doesn;t then do a journalctl -xe and see what it says.

[Sergey Serov]

@Shutupsquare Thank You for this good advice with journalctl! May be anywhere else is present information for diagnostic?

[Sergey Serov]

The most interesting and problematic for me here that all this actions were at the same time (with sharp to ONE second). And there are no any other records about Postfix (or just Mail Agent) in both logs. About log rotation - both logs contents previous records (before restart) and after restart.

[Dan Cornilescu]

No mistery there: the 4 msgs indicate 4 very rapid events from systemd's prospective: attempt to start postfix process, process fails (immediately returns -1), complaint about inability to get postfix process running, declaration of the postfix service failed. The other message is from the postfix process itself - inability to bind to the port - thus it exits with -1 (which triggers the 2nd systemd event).