Trying to understand error message in logs

classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Trying to understand error message in logs

angelo

Hi, I am building new server RHEL7 and Postfix 2.10

 

The log file is constantly outputting this…

 

Oct 11 11:15:08 mail6 postfix/master[3266]: warning: process /usr/libexec/postfix/smtpd pid 18008 exit status 1

Oct 11 11:15:08 mail6 postfix/master[3266]: warning: /usr/libexec/postfix/smtpd: bad command startup -- throttling

Oct 11 11:16:08 mail6 postfix/submission/smtpd[18091]: fatal: open lock file pid/inet.submission: cannot open file: Permission denied

Oct 11 11:16:09 mail6 postfix/master[3266]: warning: process /usr/libexec/postfix/smtpd pid 18091 exit status 1

Oct 11 11:16:09 mail6 postfix/master[3266]: warning: /usr/libexec/postfix/smtpd: bad command startup -- throttling

Oct 11 11:17:09 mail6 postfix/submission/smtpd[18161]: fatal: open lock file pid/inet.submission: cannot open file: Permission denied

Oct 11 11:17:10 mail6 postfix/master[3266]: warning: process /usr/libexec/postfix/smtpd pid 18161 exit status 1

Oct 11 11:17:10 mail6 postfix/master[3266]: warning: /usr/libexec/postfix/smtpd: bad command startup – throttling

 

TESTING:

This fails:  openssl s_client -starttls smtp -connect mail6.its.uconn.edu:587

 

I have supposedly identical server and this works :

openssl s_client -starttls smtp -connect mail5.its.uconn.edu:587

 

Thank you.

 

[root@mail6 pid]# postconf -n

alias_database = hash:/etc/aliases

alias_maps = hash:/etc/aliases

command_directory = /usr/sbin

config_directory = /etc/postfix

daemon_directory = /usr/libexec/postfix

data_directory = /var/lib/postfix

debug_peer_level = 2

debugger_command = PATH=/bin:/usr/bin:/usr/local/bin:/usr/X11R6/bin ddd $daemon_directory/$process_name $process_id & sleep 5

header_checks = regexp:/etc/postfix/header_checks

html_directory = no

inet_interfaces = all

inet_protocols = all

mail_owner = postfix

mailq_path = /usr/bin/mailq.postfix

manpage_directory = /usr/share/man

milter_default_action = accept

milter_protocol = 6

mydestination = $myhostname, localhost.$mydomain, localhost

mynetworks = 137.99.28.110 137.99.28.117 137.99.28.90 137.99.28.116 137.99.188.202 10.3.28.90 10.3.28.116 10.4.25.183 10.4.40.212 10.4.40.194 10.4.40.189 66.29.212.37 137.99.25.0/24

newaliases_path = /usr/bin/newaliases.postfix

non_smtpd_milters = $smtpd_milters

queue_directory = /var/spool/postfix

readme_directory = /usr/share/doc/postfix-2.10.1/README_FILES

sample_directory = /usr/share/doc/postfix-2.10.1/samples

sendmail_path = /usr/sbin/sendmail.postfix

setgid_group = postdrop

slowaol_destination_concurrency_limit = 2

slowaol_destination_rate_delay = 30s

slowaol_destination_recipient_limit = 10

slowhot_destination_concurrency_limit = 2

slowhot_destination_rate_delay = 10s

slowhot_destination_recipient_limit = 10

smtpd_milters = inet:127.0.0.1:8891

smtpd_recipient_restrictions = permit_mynetworks, permit_sasl_authenticated, reject_unauth_destination

smtpd_tls_cert_file = /etc/pki/tls/certs/massmail_uconn_edu_cert_interm.cer

smtpd_tls_key_file = /etc/pki/tls/private/massmail_key.key

smtpd_tls_mandatory_protocols = !SSLv2,!SSLv3

unknown_local_recipient_reject_code = 550

virtual_alias_maps = hash:/etc/postfix/virtual

 

-ANGELO FAZZINA

 

[hidden email]

University of Connecticut,  ITS, SSG, Server Systems

860-486-9075

 

Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand error message in logs

Marty Lee
> Oct 11 11:16:08 mail6 postfix/submission/smtpd[18091]: fatal: open lock file pid/inet.submission: cannot open file: Permission denied

This would be the clue, and according to the docs, pid files are written to the
queue directory by default.

> queue_directory = /var/spool/postfix

so - is there a directory /var/spool/postfix/pid and is it writeable by the
postfix user?

marty

Reply | Threaded
Open this post in threaded view
|

RE: Trying to understand error message in logs

angelo
Hi, thank you for trying to help.
I hope this answers your question.

[root@mail6 pid]# pwd
/var/spool/postfix/pid
[root@mail6 pid]# ll
total 4
-rw-------. 1 root root  0 Oct  6 22:14 inet.smtp
-rw-------. 1 root root  0 Oct  3 10:00 inet.smtps
-rw-------. 1 root root  0 Oct  6 22:18 inet.submission
-rw-------. 1 root root 33 Oct  9 11:44 master.pid
-rw-------. 1 root root  0 Sep 26 11:18 unix.cleanup
-rw-------. 1 root root  0 Sep 26 11:18 unix.local
-rw-------. 1 root root  0 Oct  9 11:34 unix.showq
-rw-------. 1 root root  0 Sep 26 11:18 unix.smtp

I have not touched this file ever. BTW.
/usr/libexec/postfix/postfix-files

Also config is same on working server mail5.its.uconn.edu

-ANGELO FAZZINA

[hidden email]
University of Connecticut,  ITS, SSG, Server Systems
860-486-9075


-----Original Message-----
From: Marty Lee <[hidden email]>
Sent: Friday, October 11, 2019 11:35 AM
To: Fazzina, Angelo <[hidden email]>
Cc: [hidden email]
Subject: Re: Trying to understand error message in logs

> Oct 11 11:16:08 mail6 postfix/submission/smtpd[18091]: fatal: open lock file pid/inet.submission: cannot open file: Permission denied

This would be the clue, and according to the docs, pid files are written to the
queue directory by default.

> queue_directory = /var/spool/postfix

so - is there a directory /var/spool/postfix/pid and is it writeable by the
postfix user?

marty

Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand error message in logs

Wietse Venema
Fazzina, Angelo:
> Hi, thank you for trying to help.
> I hope this answers your question.
>
> [root@mail6 pid]# pwd
> /var/spool/postfix/pid
> [root@mail6 pid]# ll
> total 4
> -rw-------. 1 root root  0 Oct  6 22:14 inet.smtp
...and so on...

Postfix daemons open lockfiles while running as root. If they can't
do that, then check out
- NFS server configuration (disable the root->nobody mapping)
- Selinux or AppArmor configuration

        Wietse
Reply | Threaded
Open this post in threaded view
|

RE: Trying to understand error message in logs

angelo
Hi, thanks for the tip about checking SELINUX.  Sadly no change when testing openssl command with SELINUX off. :-(


Not sure if this is a hint but  this works on the server
        openssl s_client -connect mail6.its.uconn.edu:465
so I think the SSL cert files are all good, as 465 and 587 use same files.


I have to "control-C" to get back to prompt
[root@mail6 postfix]# openssl s_client -starttls smtp -connect mail6.its.uconn.edu:587
CONNECTED(00000003)
^C


I tried even adding "- v" to this line in master.cf with a restart and logs went up for port 465 but nothing changed for 587
        submission inet n       -       n       -       -       smtpd -v

thanks.


-ANGELO FAZZINA

[hidden email]
University of Connecticut,  ITS, SSG, Server Systems
860-486-9075


-----Original Message-----
From: [hidden email] <[hidden email]> On Behalf Of Wietse Venema
Sent: Friday, October 11, 2019 11:55 AM
To: Postfix users <[hidden email]>
Subject: Re: Trying to understand error message in logs

Fazzina, Angelo:
> Hi, thank you for trying to help.
> I hope this answers your question.
>
> [root@mail6 pid]# pwd
> /var/spool/postfix/pid
> [root@mail6 pid]# ll
> total 4
> -rw-------. 1 root root  0 Oct  6 22:14 inet.smtp
...and so on...

Postfix daemons open lockfiles while running as root. If they can't
do that, then check out
- NFS server configuration (disable the root->nobody mapping)
- Selinux or AppArmor configuration

        Wietse
Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand error message in logs

Viktor Dukhovni
Reboot your system, and try again.

> On Oct 11, 2019, at 2:49 PM, Fazzina, Angelo <[hidden email]> wrote:
>
> Hi, thanks for the tip about checking SELINUX.  Sadly no change when testing openssl command with SELINUX off.

TLS has nothing to with this.  The SMTP server is unable to
lock a file that is used to avoid waking up all the SMTP
listeners every time a new connection arrives.  The lock
file ensures that only listener is waiting to accept new
connections at a time.

The EPERM error is not normal in this context.  On my
system:

  $ ls -ld /var/spool/postfix{,/pid{,/inet.smtp}}
  drwxr-xr-x  16 root  wheel    16 Aug  4 22:46 /var/spool/postfix
  drwxr-xr-x   2 root  postfix  19 Apr 18 04:43 /var/spool/postfix/pid
  -rw-------   1 root  postfix   0 Feb 19  2017 /var/spool/postfix/pid/inet.smtp

which shows that only root can open the lock file, and yet
there are no issues with the lock, because Postfix opens
the file before dropping privs.  So if you're seeing EPERM,
your system is either configured with additional security
restrictions, or has become confused and needs a reboot.

Also, make sure there are no additional extended ACLs on the file,
immutable bits, ...  Good luck.

Don't waste time with TLS, that's entirely irrelevant.

--
        Viktor.

Reply | Threaded
Open this post in threaded view
|

Re: Trying to understand error message in logs

Thilo Molitor
...and check permissions on *all* the directories in the path leading to the
lockfile for proper access (at least eXecute permission) and no conflicting ACLs
(as viktor already wrote).

--tmolitor


Am Freitag, 11. Oktober 2019, 15:00:36 CEST schrieb Viktor Dukhovni:

> Reboot your system, and try again.
>
> > On Oct 11, 2019, at 2:49 PM, Fazzina, Angelo <[hidden email]>
> > wrote:
> >
> > Hi, thanks for the tip about checking SELINUX.  Sadly no change when
> > testing openssl command with SELINUX off.
> TLS has nothing to with this.  The SMTP server is unable to
> lock a file that is used to avoid waking up all the SMTP
> listeners every time a new connection arrives.  The lock
> file ensures that only listener is waiting to accept new
> connections at a time.
>
> The EPERM error is not normal in this context.  On my
> system:
>
>   $ ls -ld /var/spool/postfix{,/pid{,/inet.smtp}}
>   drwxr-xr-x  16 root  wheel    16 Aug  4 22:46 /var/spool/postfix
>   drwxr-xr-x   2 root  postfix  19 Apr 18 04:43 /var/spool/postfix/pid
>   -rw-------   1 root  postfix   0 Feb 19  2017
> /var/spool/postfix/pid/inet.smtp
>
> which shows that only root can open the lock file, and yet
> there are no issues with the lock, because Postfix opens
> the file before dropping privs.  So if you're seeing EPERM,
> your system is either configured with additional security
> restrictions, or has become confused and needs a reboot.
>
> Also, make sure there are no additional extended ACLs on the file,
> immutable bits, ...  Good luck.
>
> Don't waste time with TLS, that's entirely irrelevant.
Reply | Threaded
Open this post in threaded view
|

RE: Trying to understand error message in logs

angelo
Thank you both for the hints, I rebooted and saw no change when testing.
On a guess I used "systemctl stop postfix" and tried to manually start postfix with
"postfix start" at the command line.

Strangely that allows the openssl test command to work perfectly ?!

I am able to repeat the starting and stopping of postfix at will with command "postfix  start/stop" and things seem to work.


        Even used T-bird and sent myself and email.

Oct 11 15:38:36 mail6 postfix/submission/smtpd[3371]: 33C2318002F8: client=angelo.uits.uconn.edu[137.99.80.129], sasl_method=PLAIN, sasl_username=abb17003
Oct 11 15:38:36 mail6 postfix/cleanup[3379]: 33C2318002F8: warning: header Subject: real test mail6 from angelo.uits.uconn.edu[137.99.80.129]; from=<[hidden email]> to=<[hidden email]> proto=ESMTP helo=<[137.99.80.129]>: HEADER_CHECKS(5)


I think I need to research how RHEL7  and systemctl crank up Postfix.

Thanks.

P.S.
In case someone sees something obvious, 1st try fails but strangely 2nd try works fine...and port 465 works 587 no.

1ST TRY
[root@mail6 ~]# systemctl start postfix
Job for postfix.service failed because the control process exited with error code. See "systemctl status postfix.service" and "journalctl -xe" for details.

[root@mail6 ~]# systemctl status postfix.service
â postfix.service - Postfix Mail Transport Agent
   Loaded: loaded (/usr/lib/systemd/system/postfix.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Fri 2019-10-11 15:41:41 EDT; 8s ago
  Process: 3053 ExecStop=/usr/sbin/postfix stop (code=exited, status=0/SUCCESS)
  Process: 3488 ExecStart=/usr/sbin/postfix start (code=exited, status=1/FAILURE)
  Process: 3485 ExecStartPre=/usr/libexec/postfix/chroot-update (code=exited, status=0/SUCCESS)
  Process: 3482 ExecStartPre=/usr/libexec/postfix/aliasesdb (code=exited, status=0/SUCCESS)
 Main PID: 2985 (code=killed, signal=TERM)

Oct 11 15:41:40 mail6.its.uconn.edu systemd[1]: Starting Postfix Mail Transport Agent...
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: postfix.service: control process exited, code=exited status=1
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: Failed to start Postfix Mail Transport Agent.
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: Unit postfix.service entered failed state.
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: postfix.service failed.


2ND TRY
[root@mail6 ~]# systemctl status postfix
â postfix.service - Postfix Mail Transport Agent
   Loaded: loaded (/usr/lib/systemd/system/postfix.service; enabled; vendor preset: disabled)
   Active: failed (Result: exit-code) since Fri 2019-10-11 15:41:41 EDT; 1min 20s ago
  Process: 3053 ExecStop=/usr/sbin/postfix stop (code=exited, status=0/SUCCESS)
  Process: 3488 ExecStart=/usr/sbin/postfix start (code=exited, status=1/FAILURE)
  Process: 3485 ExecStartPre=/usr/libexec/postfix/chroot-update (code=exited, status=0/SUCCESS)
  Process: 3482 ExecStartPre=/usr/libexec/postfix/aliasesdb (code=exited, status=0/SUCCESS)
 Main PID: 2985 (code=killed, signal=TERM)

Oct 11 15:41:40 mail6.its.uconn.edu systemd[1]: Starting Postfix Mail Transport Agent...
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: postfix.service: control process exited, code=exited status=1
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: Failed to start Postfix Mail Transport Agent.
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: Unit postfix.service entered failed state.
Oct 11 15:41:41 mail6.its.uconn.edu systemd[1]: postfix.service failed.
[root@mail6 ~]#
[root@mail6 ~]#
[root@mail6 ~]# systemctl start postfix
[root@mail6 ~]# systemctl status postfix
â postfix.service - Postfix Mail Transport Agent
   Loaded: loaded (/usr/lib/systemd/system/postfix.service; enabled; vendor preset: disabled)
   Active: active (running) since Fri 2019-10-11 15:43:06 EDT; 3s ago
  Process: 3053 ExecStop=/usr/sbin/postfix stop (code=exited, status=0/SUCCESS)
  Process: 3551 ExecStart=/usr/sbin/postfix start (code=exited, status=0/SUCCESS)
  Process: 3548 ExecStartPre=/usr/libexec/postfix/chroot-update (code=exited, status=0/SUCCESS)
  Process: 3545 ExecStartPre=/usr/libexec/postfix/aliasesdb (code=exited, status=0/SUCCESS)
 Main PID: 3623 (master)
    Tasks: 3
   Memory: 2.9M
   CGroup: /system.slice/postfix.service
           ââ3623 /usr/libexec/postfix/master -w
           ââ3624 pickup -l -t unix -u
           ââ3625 qmgr -l -t unix -u

Oct 11 15:43:06 mail6.its.uconn.edu systemd[1]: Starting Postfix Mail Transport Agent...
Oct 11 15:43:06 mail6.its.uconn.edu postfix/master[3623]: daemon started -- version 2.10.1, configuration /etc/postfix
Oct 11 15:43:06 mail6.its.uconn.edu systemd[1]: Started Postfix Mail Transport Agent.


-ANGELO FAZZINA

[hidden email]
University of Connecticut,  ITS, SSG, Server Systems
860-486-9075


-----Original Message-----
From: [hidden email] <[hidden email]> On Behalf Of Thilo Molitor
Sent: Friday, October 11, 2019 3:14 PM
To: Postfix users <[hidden email]>
Subject: Re: Trying to understand error message in logs

...and check permissions on *all* the directories in the path leading to the
lockfile for proper access (at least eXecute permission) and no conflicting ACLs
(as viktor already wrote).

--tmolitor


Am Freitag, 11. Oktober 2019, 15:00:36 CEST schrieb Viktor Dukhovni:

> Reboot your system, and try again.
>
> > On Oct 11, 2019, at 2:49 PM, Fazzina, Angelo <[hidden email]>
> > wrote:
> >
> > Hi, thanks for the tip about checking SELINUX.  Sadly no change when
> > testing openssl command with SELINUX off.
> TLS has nothing to with this.  The SMTP server is unable to
> lock a file that is used to avoid waking up all the SMTP
> listeners every time a new connection arrives.  The lock
> file ensures that only listener is waiting to accept new
> connections at a time.
>
> The EPERM error is not normal in this context.  On my
> system:
>
>   $ ls -ld /var/spool/postfix{,/pid{,/inet.smtp}}
>   drwxr-xr-x  16 root  wheel    16 Aug  4 22:46 /var/spool/postfix
>   drwxr-xr-x   2 root  postfix  19 Apr 18 04:43 /var/spool/postfix/pid
>   -rw-------   1 root  postfix   0 Feb 19  2017
> /var/spool/postfix/pid/inet.smtp
>
> which shows that only root can open the lock file, and yet
> there are no issues with the lock, because Postfix opens
> the file before dropping privs.  So if you're seeing EPERM,
> your system is either configured with additional security
> restrictions, or has become confused and needs a reboot.
>
> Also, make sure there are no additional extended ACLs on the file,
> immutable bits, ...  Good luck.
>
> Don't waste time with TLS, that's entirely irrelevant.