Centos – Boot time log: ‘Failed to start Postfix Mail Transport Agent’

centosloggingpostfix

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('to@domen.tl','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=<20150530155135.A4DC31180305@.localdomain>
May 30 17:51:35  postfix/qmgr[6528]: A4DC31180305: from=<root@.localdomain>, 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=<20150530155135.A4DC31180305@.localdomain>
May 30 17:51:35  postfix/qmgr[6528]: C483211802E1: from=<root@.localdomain>, size=579, nrcpt=1 (queue active)
May 30 17:51:35  postfix/local[6557]: A4DC31180305: to=<root@.localdomain>, 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!!

Best Answer

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.