Failed to start Postfix Mail Transport Agent

Pioneer Support
1

It is unfortunate that there isn’t any warning when postfix did not start, I only found out by sending email to myself and seeing that I wasn’t receiving it.

I see the following in journalctl:

Nov 06 18:27:11 fbox systemd[1]: postfix@-.service: start-pre operation timed out. Terminating.
Nov 06 18:27:11 fbox systemd[1]: postfix@-.service: Control process exited, code=killed, status=15/TERM
Nov 06 18:27:14 fbox systemd[1]: postfix@-.service: Failed with result ‘timeout’.
Nov 06 18:27:14 fbox rspamd[729]: ; map; rspamd_map_read_http_cached_file: read cached data for https://maps.rspamd.com/rspamd/redirectors.inc.zst from /var/lib/rspamd/f3933e67d5f9574a9eaf78cd0a8e99140ecc502e.map, 1034>
Nov 06 18:27:14 fbox rspamd[729]: ; map; rspamd_kv_list_fin: read hash of 1071 elements from https://maps.rspamd.com/rspamd/redirectors.inc.zst
Nov 06 18:27:14 fbox systemd[1]: Failed to start Postfix Mail Transport Agent (instance -).
Nov 06 18:27:14 fbox rspamd[729]: <48y7dd>; map; read_map_file: /etc/rspamd/local.d/maps.d/redirectors.inc: map file is not found; it will be read automatically if created
Nov 06 18:27:14 fbox rspamd[729]: <48y7dd>; map; read_map_file: /etc/rspamd/local.d/redirectors.inc: map file is not found; it will be read automatically if created
Nov 06 18:27:14 fbox systemd[1]: postfix@-.service: Consumed 13.410s CPU time.
Nov 06 18:27:14 fbox systemd[1]: Starting Postfix Mail Transport Agent…
Nov 06 18:27:14 fbox rspamd[729]: ; map; rspamd_map_read_http_cached_file: read cached data for https://maps.rspamd.com/freemail/disposable.txt.zst from /var/lib/rspamd/ea942f35f2c82e84bdb7b8ceb34537f7dbe986eb.map, 591>
Nov 06 18:27:14 fbox rspamd[729]: ; map; rspamd_kv_list_fin: read hash of 427 elements from https://maps.rspamd.com/freemail/disposable.txt.zst
Nov 06 18:27:14 fbox systemd[1]: Finished Postfix Mail Transport Agent.

When I look at what is before, I noticed some errors with dovecote:
Nov 06 18:26:47 fbox dovecot[971]: master: Dovecot v2.3.13 (89f716dc2) starting up for imap, lmtp, sieve, pop3 (core dumps disabled)
Nov 06 18:26:47 fbox audit[1432]: AVC apparmor=“ALLOWED” operation=“open” profile=“/usr/sbin/ejabberdctl” name=“/sys/fs/cgroup/cgroup.controllers” pid=1432 comm=“beam.smp” requested_mask=“r” denied_mask=“r” fsuid=116 ouid=0
Nov 06 18:26:47 fbox kernel: audit: type=1400 audit(1667759207.906:37): apparmor=“ALLOWED” operation=“open” profile=“/usr/sbin/ejabberdctl” name=“/sys/fs/cgroup/cgroup.controllers” pid=1432 comm=“beam.smp” requested_mask=“r” d>
Nov 06 18:26:47 fbox audit[1432]: AVC apparmor=“ALLOWED” operation=“open” profile=“/usr/sbin/ejabberdctl” name=“/sys/fs/cgroup/cgroup.controllers” pid=1432 comm=“beam.smp” requested_mask=“r” denied_mask=“r” fsuid=116 ouid=0
Nov 06 18:26:47 fbox kernel: audit: type=1400 audit(1667759207.958:38): apparmor=“ALLOWED” operation=“open” profile=“/usr/sbin/ejabberdctl” name=“/sys/fs/cgroup/cgroup.controllers” pid=1432 comm=“beam.smp” requested_mask=“r” d>
Nov 06 18:26:48 fbox apache-error[1407]: [ssl:warn] [pid 987:tid 987] AH01909: fbox.metani.eu:443:0 server certificate does NOT include an ID which matches the server name
Nov 06 18:26:48 fbox apache-error[1407]: [ssl:error] [pid 987:tid 987] AH02217: ssl_stapling_init_cert: can’t retrieve issuer certificate! [subject: CN=freedombox / issuer: CN=freedombox / serial: 75D25E82BEE6E38BD8DD698D010CF>
Nov 06 18:26:48 fbox apache-error[1407]: [ssl:error] [pid 987:tid 987] AH02604: Unable to configure certificate fbox.metani.eu:443:0 for stapling

I had just rebooted the freedombox from plinth. I will reboot again.

2

I managed to start postfix manually from cockpit. At boot, it fails to start.

3

Do you have a valid TLS certificate for your domain? Could you please check the System → Let’s Encrypt app page?

Looks like postfix service failed to start in the ‘start-pre’ operation. This operation run the command /usr/lib/postfix/configure-instance.sh which mostly seems to deal with TLS certificate setup.

4

In System → configure: “machine name” is “fbox”, “domain name” is “metani.eu”.
In System → Let’s encrypt: I have a valid certificate for “metani.eu”.

I noticed in the dovecot log “fbox.metani.eu:443:0 server certificate does NOT include an ID which matches the server name”.

Is there something wrong with my settings?

5
  • In Apps → Postfix/Dovecot, the primary domain is set to ‘metani.eu’, correct?
  • What does running the following two commands show?
    postconf | grep -e mydomain -e mydestination -e myhostname
postconf | grep -e tls_server_sni_maps -e smtpd_tls_chain_files
  • Perhaps the problem is that system startup is slow and postfix fails to start within the timeout period. Try the following:
    $ mkdir /etc/systemd/system.conf.d
$ cat >  /etc/systemd/system.conf.d/mysettings.conf
[Manager]
DefaultTimeoutStartSec=300s
$ systemctl daemon-reload
6

Thanks for the help!

Correct.

$ sudo postconf | grep -e mydomain -e mydestination -e myhostname
append_dot_mydomain = no
lmtp_lhlo_name = $myhostname
local_transport = local:$myhostname
milter_macro_daemon_name = $myhostname
mydestination = $myhostname, fbox.local, localhost, localhost.$mydomain, metani.eu
mydomain = metani.eu
myhostname = metani.eu
myorigin = $myhostname
proxy_read_maps = $local_recipient_maps $mydestination $virtual_alias_maps $virtual_alias_domains $virtual_mailbox_maps $virtual_mailbox_domains $relay_recipient_maps $relay_domains $canonical_maps $sender_canonical_maps $recipient_canonical_maps $relocated_maps $transport_maps $mynetworks $smtpd_sender_login_maps $sender_bcc_maps $recipient_bcc_maps $smtp_generic_maps $lmtp_generic_maps $alias_maps $smtpd_client_restrictions $smtpd_helo_restrictions $smtpd_sender_restrictions $smtpd_relay_restrictions $smtpd_recipient_restrictions $address_verify_sender_dependent_default_transport_maps $address_verify_sender_dependent_relayhost_maps $address_verify_transport_maps $fallback_transport_maps $lmtp_discard_lhlo_keyword_address_maps $lmtp_pix_workaround_maps $lmtp_sasl_password_maps $lmtp_tls_policy_maps $mailbox_command_maps $mailbox_transport_maps $postscreen_discard_ehlo_keyword_address_maps $rbl_reply_maps $sender_dependent_default_transport_maps $sender_dependent_relayhost_maps $smtp_discard_ehlo_keyword_address_maps $smtp_pix_workaround_maps $smtp_sasl_password_maps $smtp_tls_policy_maps $smtpd_discard_ehlo_keyword_address_maps $smtpd_milter_maps $virtual_gid_maps $virtual_uid_maps
relay_domains = ${{$compatibility_level} < {2} ? {$mydestination} : {}}
smtp_helo_name = $myhostname
smtpd_banner = $myhostname ESMTP $mail_name (Debian/GNU)
smtpd_proxy_ehlo = $myhostname
$
</pre>

and

$ sudo postconf | grep -e tls_server_sni_maps -e smtpd_tls_chain_files
smtpd_tls_chain_files = /etc/postfix/letsencrypt/metani.eu/chain.pem
tls_server_sni_maps = inline:{metani.eu=/etc/postfix/letsencrypt/metani.eu/chain.pem,fbox.local=/etc/postfix/letsencrypt/fbox.local/chain.pem}
tlsproxy_tls_chain_files = $smtpd_tls_chain_files
$

Indeed, it takes a while and postfix is at the end. I’ll try that and reboot to see what happens, then I will report.

7

After reboot, postfix was successfully started.

Is there some way of checking in journalctl the time it took to start postfix, so I can see whether the new timeout helped? I can see the line saying it was started but I am not sure what would be the starting point of the timer.

I any case, thanks for the help.

8

postfix was consistently failing to start automatically at boot time on my Pioneer Edition until I set
DefaultTimeoutStartSec=180s. It looks like it needs around two minutes, so a three minute timeout seems reasonable, at least in my case.

Before:

Apr 06 07:38:39 freedombox systemd[1]: Starting Postfix Mail Transport Agent (instance -)...
Apr 06 07:40:18 freedombox systemd[1]: postfix@-.service: start-pre operation timed out. Terminating.
Apr 06 07:40:18 freedombox systemd[1]: postfix@-.service: Control process exited, code=killed, status=15/TERM
Apr 06 07:40:18 freedombox systemd[1]: postfix@-.service: Failed with result 'timeout'.
Apr 06 07:40:18 freedombox systemd[1]: Failed to start Postfix Mail Transport Agent (instance -).

After:

Apr 06 12:41:16 freedombox systemd[1]: Starting Postfix Mail Transport Agent (instance -)...
Apr 06 12:43:16 freedombox postfix/postfix-script[2031]: warning: not owned by postfix: /var/lib/postfix/./freedombox-aliases
Apr 06 12:43:16 freedombox postfix/postfix-script[2032]: warning: not owned by postfix: /var/lib/postfix/./freedombox-aliases/aliases.sqlite3
Apr 06 12:43:21 freedombox postfix/postfix-script[2206]: starting the Postfix mail system
Apr 06 12:43:21 freedombox postfix/master[2208]: daemon started -- version 3.5.17, configuration /etc/postfix
Apr 06 12:43:21 freedombox systemd[1]: Started Postfix Mail Transport Agent (instance -).