Re: Updated Dovecot 2.3.0 now getting 2 strange log errors
I did some more digging around and found this is reproducible on multiple hosts running the same version of Dovecot/Pigeonhole/Postfix. The problem resurfaces on any host to an account with enabled Vacation/OOO response. The Vacation/OOO reply filter was created in Roundcubemail, but has been fine for years. One thing to note is in Dovecot 2.3.0 I did enable UTF8, but even if I disable UTF8 the issue remains. What I have discovered after digging around is..
- After a fresh postfix restart all expected processes are running without any postdrop process.
postgrey 13080 0.0 0.2 73036 21108 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 385700 108 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138572 9088 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13320 0.0 0.1 163908 9832 ? S 17:24 0:00 proxymap -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 13322 0.0 0.1 138524 9280 ? S 17:24 0:00 anvil -l -t unix -u postfix 13352 0.0 0.1 168896 13520 ? S 17:24 0:00 smtpd -n smtp -t inet -u -o stress= -s 2 -o content_filter=spamassassin postfix 13539 0.0 0.1 163920 10156 ? S 17:24 0:00 trivial-rewrite -n rewrite -t unix -u postfix 14369 0.0 0.1 164300 10340 ? S 17:26 0:00 cleanup -z -t unix -u postfix 14370 0.0 0.1 124180 8844 ? S 17:26 0:00 pipe -n spamassassin -t unix user=spamd argv=/usr/bin/vendor_perl/spamc -f -e /usr/sbin/sendmail -oi -f ${sender} ${recipient} postfix 14375 0.0 0.1 142856 9344 ? S 17:26 0:00 lmtp -t unix -u vmail 14446 0.0 0.0 44008 7496 ? S 17:26 0:00 dovecot/quota-status -p postfix
- During the problem where the logs are complaining about permission denied and sendmail exiting with signal 15 (caused by inbound email to an address with enabled Vacation notice filter) there is a running postdrop process and several expected processes are not running.
postgrey 13080 0.0 0.2 73036 21132 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 461572 408 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138644 9128 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 20793 0.0 0.1 138524 9092 ? S 17:39 0:00 anvil -l -t unix -u vmail 25340 0.0 0.0 44108 7664 ? S 17:46 0:00 dovecot/quota-status -p postfix vmail 26298 0.0 0.1 122088 8536 ? S 17:49 0:00 /usr/bin/postdrop -r ——
When the issue is not present, an email TO any address with a disabled Vacation/OOO response filter is processed with no issues and stored in the respective folder moved by an existing filter not related to Vacation/OOO. Expected processes are still running (no postdrop process which when running seems to be causing the problem)
When the issue is not present, an email TO an address with a enabled Vacation/OOO response filter is processed and stored in the Inbox, but an auto-response fails to send. The result are these errors with the permission denied being repeated every ~minute.
Dec 29 17:49:58 lmtp(jsomeone@domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: sieve: msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ@mail.gmail.com>: failed to send vacation response to someone@gmail.com: <Failed to execute sendmail> (temporary error) Dec 29 17:50:08 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/569031.26298: Permission denied
After the problem starts again with the errors shown in the logs a postdrop process stays running in the background. After a short while the number of postfix processes decreases.
If I kill the postdrop process then the logged errors stop and the expected processes all show up again.
I am running out of ideas on why this has suddenly surfaced.
- TC
On 2017-12-29 18:35, tony wrote:
I did some more digging around and found this is reproducible on multiple hosts running the same version of Dovecot/Pigeonhole/Postfix. The problem resurfaces on any host to an account with enabled Vacation/OOO response. The Vacation/OOO reply filter was created in Roundcubemail, but has been fine for years. One thing to note is in Dovecot 2.3.0 I did enable UTF8, but even if I disable UTF8 the issue remains. What I have discovered after digging around is..
- After a fresh postfix restart all expected processes are running without any postdrop process.
postgrey 13080 0.0 0.2 73036 21108 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 385700 108 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138572 9088 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13320 0.0 0.1 163908 9832 ? S 17:24 0:00 proxymap -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 13322 0.0 0.1 138524 9280 ? S 17:24 0:00 anvil -l -t unix -u postfix 13352 0.0 0.1 168896 13520 ? S 17:24 0:00 smtpd -n smtp -t inet -u -o stress= -s 2 -o content_filter=spamassassin postfix 13539 0.0 0.1 163920 10156 ? S 17:24 0:00 trivial-rewrite -n rewrite -t unix -u postfix 14369 0.0 0.1 164300 10340 ? S 17:26 0:00 cleanup -z -t unix -u postfix 14370 0.0 0.1 124180 8844 ? S 17:26 0:00 pipe -n spamassassin -t unix user=spamd argv=/usr/bin/vendor_perl/spamc -f -e /usr/sbin/sendmail -oi -f ${sender} ${recipient} postfix 14375 0.0 0.1 142856 9344 ? S 17:26 0:00 lmtp -t unix -u vmail 14446 0.0 0.0 44008 7496 ? S 17:26 0:00 dovecot/quota-status -p postfix
- During the problem where the logs are complaining about permission denied and sendmail exiting with signal 15 (caused by inbound email to an address with enabled Vacation notice filter) there is a running postdrop process and several expected processes are not running.
postgrey 13080 0.0 0.2 73036 21132 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 461572 408 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138644 9128 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 20793 0.0 0.1 138524 9092 ? S 17:39 0:00 anvil -l -t unix -u vmail 25340 0.0 0.0 44108 7664 ? S 17:46 0:00 dovecot/quota-status -p postfix vmail 26298 0.0 0.1 122088 8536 ? S 17:49 0:00 /usr/bin/postdrop -r ——
When the issue is not present, an email TO any address with a disabled Vacation/OOO response filter is processed with no issues and stored in the respective folder moved by an existing filter not related to Vacation/OOO. Expected processes are still running (no postdrop process which when running seems to be causing the problem)
When the issue is not present, an email TO an address with a enabled Vacation/OOO response filter is processed and stored in the Inbox, but an auto-response fails to send. The result are these errors with the permission denied being repeated every ~minute.
Dec 29 17:49:58 lmtp(jsomeone@domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: sieve: msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ@mail.gmail.com>: failed to send vacation response to someone@gmail.com: <Failed to execute sendmail> (temporary error) Dec 29 17:50:08 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/569031.26298: Permission denied
After the problem starts again with the errors shown in the logs a postdrop process stays running in the background. After a short while the number of postfix processes decreases.
If I kill the postdrop process then the logged errors stop and the expected processes all show up again.
I am running out of ideas on why this has suddenly surfaced.
- TC
I think I am getting closer. Investigated further and the issue first surfaced: Dec 26 07:54:49 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/600085.6655: Permission denied
#1 upgrade [2017-12-25 03:18] [ALPM] upgraded dovecot (2.2.33.2-2 -> 2.3.0-1) [2017-12-25 03:18] [ALPM] upgraded pigeonhole (0.4.21-1 -> 0.5.0-1)
#2 upgrade [2017-12-26 16:44] [ALPM] upgraded pigeonhole (0.5.0-1 -> 0.5.0-2)
According to the upgrade timestamps it looks like ever since going from pigeonhole 0.4.21 to 0.5.0 is when the issue first surfaced. Here is a recent debug I collected:
Dec 29 21:21:38
lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug:
program /usr/sbin/sendmail'(17336) execution timed out after 30000 milliseconds: sending TERM signal Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: virtual size (Cache file is unusable) Dec 29 21:21:38 lmtp(17187): Info: Disconnect from local: Client has quit the connection (state = READY) Dec 29 21:21:38 venus.domain.net postfix/lmtp[17186]: B95004640E: to=<recipient@domain.net>, relay=mail.domain.net[private/dovecot-lmtp], delay=30, delays=0.06/0/0/30, dsn=2.0.0, status=sent (250 2.0.0 <recipient@domain.net> UA2fMEQiR1ojQwAAUXb6+w Saved) Dec 29 21:21:38 venus.domain.net postfix/qmgr[16952]: B95004640E: removed Dec 29 21:21:38 doveadm(recipient@domain.net): Debug: auth PASS input: user=recipient@domain.net Dec 29 21:21:38 doveadm(recipient@domain.net)<17661><>: Debug: auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:38 doveadm(recipient@domain.net)<17661><>: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): auth PASS input: user=recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Namespace : Using permissions from /home/vmail/domain.net/recipient@domain.net/Maildir: mode=0700 gid=default Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attributes Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include :global' scripts.
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Using active Sieve script path:
/home/vmail/domain.net/recipient@domain.net/.dovecot.sieve
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Using script storage path:
/home/vmail/domain.net/recipient@domain.net/.sieve
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Using permissions from
/home/vmail/domain.net/recipient@domain.net/.sieve: mode=0700 gid=-1
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Relative path to sieve storage in active link: .sieve/
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: sync: Synchronization active
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
doveadm-sieve: Iterating Sieve mailbox attribute:
vendor/vendor.dovecot/pvt/server/sieve/files/managesieve
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
doveadm-sieve: Iterating Sieve mailbox attribute:
vendor/vendor.dovecot/pvt/server/sieve/default
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because:
prefetch
Dec 29 21:21:39
dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: mail
stream
Dec 29 21:21:39 doveadm: Debug: auth PASS input:
user=recipient@domain.net
Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient@domain.net
home=/home/vmail/domain.net/recipient@domain.net
mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir
uid=5000 gid=5000
Dec 29 21:21:39 doveadm: Debug: Added userdb setting:
mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir
Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000,
home=/home/vmail/domain.net/recipient@domain.net
Dec 29 21:21:39 doveadm: Debug: acl: No acl setting - ACLs are disabled
Dec 29 21:21:39 doveadm: Debug: Quota root: name=User quota
backend=maildir args=
Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=*
bytes=2147483648 messages=0
Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota
mailbox=Trash bytes=+214748364 (10%) messages=0
Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=Spam
bytes=+429496729 (20%) messages=0
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%)
messages=0 reverse=no command=quota-warning +100 recipient@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%)
messages=0 reverse=no command=quota-warning +95 recipient@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%)
messages=0 reverse=no command=quota-warning +80 recipient@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%)
messages=0 reverse=yes command=quota-warning -100 recipient@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota grace: root=User quota
bytes=214748364 (10%)
Dec 29 21:21:39 doveadm: Debug: Namespace inbox: type=private, prefix=,
sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes
location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir
Dec 29 21:21:39 doveadm: Debug: maildir++:
root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=,
indexpvt=, control=,
inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt=
Dec 29 21:21:39 doveadm: Debug: quota: quota_over_flag check:
quota_over_script unset - skipping
Dec 29 21:21:39 doveadm: Debug: Namespace : Using permissions from
/home/vmail/domain.net/recipient@domain.net/Maildir: mode=0700
gid=default
I can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
-- Cheers, TC
On 2017-12-29 21:47, tony wrote:
On 2017-12-29 18:35, tony wrote:
I did some more digging around and found this is reproducible on multiple hosts running the same version of Dovecot/Pigeonhole/Postfix. The problem resurfaces on any host to an account with enabled Vacation/OOO response. The Vacation/OOO reply filter was created in Roundcubemail, but has been fine for years. One thing to note is in Dovecot 2.3.0 I did enable UTF8, but even if I disable UTF8 the issue remains. What I have discovered after digging around is..
- After a fresh postfix restart all expected processes are running without any postdrop process.
postgrey 13080 0.0 0.2 73036 21108 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 385700 108 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138572 9088 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13320 0.0 0.1 163908 9832 ? S 17:24 0:00 proxymap -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 13322 0.0 0.1 138524 9280 ? S 17:24 0:00 anvil -l -t unix -u postfix 13352 0.0 0.1 168896 13520 ? S 17:24 0:00 smtpd -n smtp -t inet -u -o stress= -s 2 -o content_filter=spamassassin postfix 13539 0.0 0.1 163920 10156 ? S 17:24 0:00 trivial-rewrite -n rewrite -t unix -u postfix 14369 0.0 0.1 164300 10340 ? S 17:26 0:00 cleanup -z -t unix -u postfix 14370 0.0 0.1 124180 8844 ? S 17:26 0:00 pipe -n spamassassin -t unix user=spamd argv=/usr/bin/vendor_perl/spamc -f -e /usr/sbin/sendmail -oi -f ${sender} ${recipient} postfix 14375 0.0 0.1 142856 9344 ? S 17:26 0:00 lmtp -t unix -u vmail 14446 0.0 0.0 44008 7496 ? S 17:26 0:00 dovecot/quota-status -p postfix
- During the problem where the logs are complaining about permission denied and sendmail exiting with signal 15 (caused by inbound email to an address with enabled Vacation notice filter) there is a running postdrop process and several expected processes are not running.
postgrey 13080 0.0 0.2 73036 21132 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 461572 408 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138644 9128 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 20793 0.0 0.1 138524 9092 ? S 17:39 0:00 anvil -l -t unix -u vmail 25340 0.0 0.0 44108 7664 ? S 17:46 0:00 dovecot/quota-status -p postfix vmail 26298 0.0 0.1 122088 8536 ? S 17:49 0:00 /usr/bin/postdrop -r ——
When the issue is not present, an email TO any address with a disabled Vacation/OOO response filter is processed with no issues and stored in the respective folder moved by an existing filter not related to Vacation/OOO. Expected processes are still running (no postdrop process which when running seems to be causing the problem)
When the issue is not present, an email TO an address with a enabled Vacation/OOO response filter is processed and stored in the Inbox, but an auto-response fails to send. The result are these errors with the permission denied being repeated every ~minute.
Dec 29 17:49:58 lmtp(jsomeone@domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: sieve: msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ@mail.gmail.com>: failed to send vacation response to someone@gmail.com: <Failed to execute sendmail> (temporary error) Dec 29 17:50:08 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/569031.26298: Permission denied
After the problem starts again with the errors shown in the logs a postdrop process stays running in the background. After a short while the number of postfix processes decreases.
If I kill the postdrop process then the logged errors stop and the expected processes all show up again.
I am running out of ideas on why this has suddenly surfaced.
- TC
I think I am getting closer. Investigated further and the issue first surfaced: Dec 26 07:54:49 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/600085.6655: Permission denied
#1 upgrade [2017-12-25 03:18] [ALPM] upgraded dovecot (2.2.33.2-2 -> 2.3.0-1) [2017-12-25 03:18] [ALPM] upgraded pigeonhole (0.4.21-1 -> 0.5.0-1)
#2 upgrade [2017-12-26 16:44] [ALPM] upgraded pigeonhole (0.5.0-1 -> 0.5.0-2)
According to the upgrade timestamps it looks like ever since going from pigeonhole 0.4.21 to 0.5.0 is when the issue first surfaced. Here is a recent debug I collected:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug: program
/usr/sbin/sendmail'(17336) execution timed out after 30000 milliseconds: sending TERM signal Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: virtual size (Cache file is unusable) Dec 29 21:21:38 lmtp(17187): Info: Disconnect from local: Client has quit the connection (state = READY) Dec 29 21:21:38 venus.domain.net postfix/lmtp[17186]: B95004640E: to=<recipient@domain.net>, relay=mail.domain.net[private/dovecot-lmtp], delay=30, delays=0.06/0/0/30, dsn=2.0.0, status=sent (250 2.0.0 <recipient@domain.net> UA2fMEQiR1ojQwAAUXb6+w Saved) Dec 29 21:21:38 venus.domain.net postfix/qmgr[16952]: B95004640E: removed Dec 29 21:21:38 doveadm(recipient@domain.net): Debug: auth PASS input: user=recipient@domain.net Dec 29 21:21:38 doveadm(recipient@domain.net)<17661><>: Debug: auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:38 doveadm(recipient@domain.net)<17661><>: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): auth PASS input: user=recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Namespace : Using permissions from /home/vmail/domain.net/recipient@domain.net/Maildir: mode=0700 gid=default Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attributes Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include:global' scripts. Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using active Sieve script path: /home/vmail/domain.net/recipient@domain.net/.dovecot.sieve Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using script storage path: /home/vmail/domain.net/recipient@domain.net/.sieve Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using permissions from /home/vmail/domain.net/recipient@domain.net/.sieve: mode=0700 gid=-1 Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Relative path to sieve storage in active link: .sieve/ Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: sync: Synchronization active Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attribute: vendor/vendor.dovecot/pvt/server/sieve/files/managesieve Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attribute: vendor/vendor.dovecot/pvt/server/sieve/default Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: prefetch Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: mail stream Dec 29 21:21:39 doveadm: Debug: auth PASS input: user=recipient@domain.net Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm: Debug: acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm: Debug: Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm: Debug: maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm: Debug: Namespace : Using permissions from /home/vmail/domain.net/recipient@domain.net/Maildir: mode=0700 gid=defaultI can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
-- Cheers, TC
An important bit I forgot to add was the actual Vacation sieve code.
require ["fileinto","vacation"]; # rule:[Auto-Response] if header :contains "to" "me@domain.email" { vacation :days 1 :addresses "me@domain.email" :subject "My Subject Line" :from "noreply@domain.email" text:
I am out of the office . ; }
I don't think my very first post containing doveconf -n made it
through, so posting here again.
# 2.3.0 (c8b89eb): /etc/dovecot/dovecot.conf # Pigeonhole version 0.5.0 (d68c23a1) # OS: Linux 4.9.68-x86_64 x86_64 Arch Linux auth_mechanisms = plain login base_dir = /var/run/dovecot/ dict { expire = ldap:/etc/dovecot/dovecot-ldap.conf.ext quota = ldap:/etc/dovecot/dovecot-ldap.conf.ext } doveadm_password = # hidden, use -P to show it doveadm_port = 4343 info_log_path = /var/log/mail/mail.log log_path = /var/log/mail/mail.err mail_attachment_hash = %{sha256} mail_gid = vmail mail_location = maildir:%Lh/Maildir/:INDEX=%Lh/Maildir/:ITERINDEX:UTF-8 mail_plugins = " mailbox_alias acl quota mail_log notify replication mail_crypt" mail_privileged_group = mail mail_uid = vmail maildir_very_dirty_syncs = yes managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate mime foreverypart extracttext vacation-seconds spamtest spamtestplus metric imap_select_no { event_name = imap_command_finished filter { name = SELECT tagged_reply_state = NO } } metric imap_select_no_notfound { event_name = imap_command_finished filter { name = SELECT tagged_reply = NO*Mailbox doesn't exist:* } } metric storage_http_gets { categories = storage event_name = http_request_finished filter { method = get } } namespace inbox { inbox = yes location = mailbox Archive { special_use = \Archive } mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Flagged { special_use = \Flagged } mailbox Junk { special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox "Sent Messages" { auto = subscribe special_use = \Sent } mailbox Spam { auto = subscribe special_use = \Junk } mailbox Trash { auto = subscribe special_use = \Trash } mailbox virtual/All { auto = no special_use = \All } prefix = } passdb { args = /etc/dovecot/dovecot-ldap.conf.ext driver = ldap } plugin { mail_crypt_curve = prime256v1 mail_crypt_global_private_key = </etc/dovecot/mcrypt/ecprivkey.pem mail_crypt_global_public_key = </etc/dovecot/mcrypt/ecpubkey.pem mail_crypt_save_version = 2 mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename mail_log_fields = uid box msgid size mail_replica = tcps:orbitron.domain.net:4343 old_stats_refresh = 30 secs old_stats_track_cmds = yes quota = maildir:User quota quota_grace = 10%% quota_rule = *:storage=2G quota_rule2 = Trash:storage=+10%% quota_rule3 = Spam:storage=+20%% quota_status_nouser = DUNNO quota_status_overquota = 552 5.2.2 Mailbox is full quota_status_success = DUNNO quota_warning = storage=100%% quota-warning +100 %u quota_warning2 = storage=95%% quota-warning +95 %u quota_warning3 = storage=80%% quota-warning +80 %u quota_warning4 = -storage=100%% quota-warning -100 %u sieve = file:~/.sieve;active=~/.dovecot.sieve sieve_extensions = +spamtest +spamtestplus +relational +vacation-seconds +comparator-i;ascii-numeric sieve_vacation_default_period = 10d sieve_vacation_max_period = 0 sieve_vacation_min_period = 1d } protocols = imap pop3 lmtp sieve replication_max_conns = 20 service aggregator { fifo_listener replication-notify-fifo { mode = 0666 user = vmail } unix_listener replication-notify { mode = 0666 user = vmail } } service auth { unix_listener auth-userdb { group = vmail mode = 0660 user = vmail } } service config { unix_listener config { user = vmail } } service dict { unix_listener dict { group = vmail mode = 0660 user = vmail } user = root } service doveadm { inet_listener { port = 4343 ssl = yes } user = vmail } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } } service lmtp { inet_listener lmtp { address = 66.xx.xxx.xxx 192.168.176.128 127.0.0.1 ::1 port = 24 } unix_listener /var/spool/postfix/private/dovecot-lmtp { group = postfix mode = 0600 user = postfix } user = vmail } service managesieve-login { inet_listener sieve { port = 4190 } service_count = 1 vsz_limit = 64 M } service old-stats { fifo_listener old-stats-mail { mode = 0600 user = vmail } } service quota-status { client_limit = 1 executable = quota-status -p postfix inet_listener { port = 12340 } } service quota-warning { executable = script /usr/local/bin/quota-warning.sh unix_listener quota-warning { user = vmail } user = dovecot } service replicator { process_min_avail = 1 unix_listener replicator-doveadm { mode = 0666 } } shutdown_clients = no ssl = required ssl_ca = </etc/ssl/certs/ca-certificates.crt ssl_cert = </etc/dovecot/ssl/STAR_domain_net.crt ssl_cipher_list = ECDHE-RSA-AES128-GCM-SHA256:ECDHE-ECDSA-AES128-GCM-SHA256:ECDHE-RSA-AES256-GCM-SHA384:ECDHE-ECDSA-AES256-GCM-SHA384:DHE-RSA-AES128-GCM-SHA256:DHE-DSS-AES128-GCM-SHA256:kEDH+AESGCM:ECDHE-RSA-AES128-SHA256:ECDHE-ECDSA-AES128-SHA256:ECDHE-RSA-AES128-SHA:ECDHE-ECDSA-AES128-SHA:ECDHE-RSA-AES256-SHA384:ECDHE-ECDSA-AES256-SHA384:ECDHE-RSA-AES256-SHA:ECDHE-ECDSA-AES256-SHA:DHE-RSA-AES128-SHA256:DHE-RSA-AES128-SHA:DHE-DSS-AES128-SHA256:DHE-RSA-AES256-SHA256:DHE-DSS-AES256-SHA:DHE-RSA-AES256-SHA:AES128-GCM-SHA256:AES256-GCM-SHA384:AES128-SHA256:AES256-SHA256:AES128-SHA:AES256-SHA:AES:!CAMELLIA:!DES-CBC3-SHA:!aNULL:!eNULL:!EXPORT:!DES:!RC4:!MD5:!PSK:!aECDH:!EDH-DSS-DES-CBC3-SHA:!EDH-RSA-DES-CBC3-SHA:!KRB5-DES-CBC3-SHA ssl_client_ca_dir = /etc/ssl/certs ssl_client_ca_file = /etc/ssl/certs/ca-certificates.crt ssl_dh = # hidden, use -P to show it ssl_key = # hidden, use -P to show it ssl_prefer_server_ciphers = yes userdb { args = /etc/dovecot/dovecot-ldap.conf.ext default_fields = home=/home/vmail/%d/%u driver = ldap } protocol lmtp { mail_plugins = " mailbox_alias acl quota mail_log notify replication mail_crypt sieve" postmaster_address = postmaster@domain.net } protocol lda { mail_plugins = sieve quota postmaster_address = postmaster@domain.email syslog_facility = mail } protocol imap { mail_max_userip_connections = 100 mail_plugin_dir = /usr/lib/dovecot/modules mail_plugins = " mailbox_alias acl quota mail_log notify replication mail_crypt imap_quota" } protocol sieve { mail_max_userip_connections = 100 managesieve_implementation_string = Dovecot Pigeonhole managesieve_max_line_length = 65536 }
This strange issue is reproducible on more than 2 identical hosts.
Cheers, TC
Op 12/30/2017 om 6:47 AM schreef tony:
On 2017-12-29 18:35, tony wrote:
I did some more digging around and found this is reproducible on multiple hosts running the same version of Dovecot/Pigeonhole/Postfix. The problem resurfaces on any host to an account with enabled Vacation/OOO response. The Vacation/OOO reply filter was created in Roundcubemail, but has been fine for years. One thing to note is in Dovecot 2.3.0 I did enable UTF8, but even if I disable UTF8 the issue remains. What I have discovered after digging around is..
- After a fresh postfix restart all expected processes are running without any postdrop process.
postgrey 13080 0.0 0.2 73036 21108 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 385700 108 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138572 9088 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13320 0.0 0.1 163908 9832 ? S 17:24 0:00 proxymap -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 13322 0.0 0.1 138524 9280 ? S 17:24 0:00 anvil -l -t unix -u postfix 13352 0.0 0.1 168896 13520 ? S 17:24 0:00 smtpd -n smtp -t inet -u -o stress= -s 2 -o content_filter=spamassassin postfix 13539 0.0 0.1 163920 10156 ? S 17:24 0:00 trivial-rewrite -n rewrite -t unix -u postfix 14369 0.0 0.1 164300 10340 ? S 17:26 0:00 cleanup -z -t unix -u postfix 14370 0.0 0.1 124180 8844 ? S 17:26 0:00 pipe -n spamassassin -t unix user=spamd argv=/usr/bin/vendor_perl/spamc -f -e /usr/sbin/sendmail -oi -f ${sender} ${recipient} postfix 14375 0.0 0.1 142856 9344 ? S 17:26 0:00 lmtp -t unix -u vmail 14446 0.0 0.0 44008 7496 ? S 17:26 0:00 dovecot/quota-status -p postfix
- During the problem where the logs are complaining about permission denied and sendmail exiting with signal 15 (caused by inbound email to an address with enabled Vacation notice filter) there is a running postdrop process and several expected processes are not running.
postgrey 13080 0.0 0.2 73036 21132 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 461572 408 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138644 9128 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 20793 0.0 0.1 138524 9092 ? S 17:39 0:00 anvil -l -t unix -u vmail 25340 0.0 0.0 44108 7664 ? S 17:46 0:00 dovecot/quota-status -p postfix vmail 26298 0.0 0.1 122088 8536 ? S 17:49 0:00 /usr/bin/postdrop -r ——
When the issue is not present, an email TO any address with a disabled Vacation/OOO response filter is processed with no issues and stored in the respective folder moved by an existing filter not related to Vacation/OOO. Expected processes are still running (no postdrop process which when running seems to be causing the problem)
When the issue is not present, an email TO an address with a enabled Vacation/OOO response filter is processed and stored in the Inbox, but an auto-response fails to send. The result are these errors with the permission denied being repeated every ~minute.
Dec 29 17:49:58 lmtp(jsomeone@domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: sieve: msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ@mail.gmail.com>:
failed to send vacation response to someone@gmail.com: <Failed to execute sendmail> (temporary error) Dec 29 17:50:08 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/569031.26298: Permission denied
After the problem starts again with the errors shown in the logs a postdrop process stays running in the background. After a short while the number of postfix processes decreases.
If I kill the postdrop process then the logged errors stop and the expected processes all show up again.
I am running out of ideas on why this has suddenly surfaced.
- TC
I think I am getting closer. Investigated further and the issue first surfaced: Dec 26 07:54:49 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/600085.6655: Permission denied
#1 upgrade [2017-12-25 03:18] [ALPM] upgraded dovecot (2.2.33.2-2 -> 2.3.0-1) [2017-12-25 03:18] [ALPM] upgraded pigeonhole (0.4.21-1 -> 0.5.0-1)
#2 upgrade [2017-12-26 16:44] [ALPM] upgraded pigeonhole (0.5.0-1 -> 0.5.0-2)
According to the upgrade timestamps it looks like ever since going from pigeonhole 0.4.21 to 0.5.0 is when the issue first surfaced. Here is a recent debug I collected:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug: program
/usr/sbin/sendmail'(17336) execution timed out after 30000 milliseconds: sending TERM signal Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug: Mailbox <lmtp DATA local>: Opened mail UID=1 because: virtual size (Cache file is unusable) Dec 29 21:21:38 lmtp(17187): Info: Disconnect from local: Client has quit the connection (state = READY) Dec 29 21:21:38 venus.domain.net postfix/lmtp[17186]: B95004640E: to=<recipient@domain.net>, relay=mail.domain.net[private/dovecot-lmtp], delay=30, delays=0.06/0/0/30, dsn=2.0.0, status=sent (250 2.0.0 <recipient@domain.net> UA2fMEQiR1ojQwAAUXb6+w Saved) Dec 29 21:21:38 venus.domain.net postfix/qmgr[16952]: B95004640E: removed Dec 29 21:21:38 doveadm(recipient@domain.net): Debug: auth PASS input: user=recipient@domain.net Dec 29 21:21:38 doveadm(recipient@domain.net)<17661><>: Debug: auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:38 doveadm(recipient@domain.net)<17661><>: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): auth PASS input: user=recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: remote(orbitron.domain.net:4343): quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient@domain.net): Debug: Namespace : Using permissions from /home/vmail/domain.net/recipient@domain.net/Maildir: mode=0700 gid=default Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attributes Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include:global' scripts. Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using active Sieve script path: /home/vmail/domain.net/recipient@domain.net/.dovecot.sieve Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using script storage path: /home/vmail/domain.net/recipient@domain.net/.sieve Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using permissions from /home/vmail/domain.net/recipient@domain.net/.sieve: mode=0700 gid=-1 Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Relative path to sieve storage in active link: .sieve/ Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: sync: Synchronization active Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attribute: vendor/vendor.dovecot/pvt/server/sieve/files/managesieve Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attribute: vendor/vendor.dovecot/pvt/server/sieve/default Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: prefetch Dec 29 21:21:39 dsync-local(recipient@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: mail stream Dec 29 21:21:39 doveadm: Debug: auth PASS input: user=recipient@domain.net Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient@domain.net home=/home/vmail/domain.net/recipient@domain.net mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient@domain.net Dec 29 21:21:39 doveadm: Debug: acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm: Debug: Quota root: name=User quota backend=maildir args= Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient@domain.net Dec 29 21:21:39 doveadm: Debug: Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient@domain.net/Maildir Dec 29 21:21:39 doveadm: Debug: maildir++: root=/home/vmail/domain.net/recipient@domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient@domain.net/Maildir, alt= Dec 29 21:21:39 doveadm: Debug: quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm: Debug: Namespace : Using permissions from /home/vmail/domain.net/recipient@domain.net/Maildir: mode=0700 gid=defaultI can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
Regards,
Stephan.
On 02/01/18 14:07, Stephan Bosch wrote:
I can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
I think the real error here is the postdrop one (sendmail is a wrapper around postdrop). It's a permission denied error which leads me to believe it may be an selinux (or similar) issue. I wouldn't be surprised if sendmail works from the command line but fails when executed from sieve because selinux has it blocked for sieve.
If you're running selinux or apparmour or similar, check your logs for that (audit log for selinux) and look for denials. You cna also try setting selinux to permissive and trying the operation (setenforce 0).
Peter
On 2018-01-01 17:26, Peter wrote:
On 02/01/18 14:07, Stephan Bosch wrote:
I can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
I think the real error here is the postdrop one (sendmail is a wrapper around postdrop). It's a permission denied error which leads me to believe it may be an selinux (or similar) issue. I wouldn't be surprised if sendmail works from the command line but fails when executed from sieve because selinux has it blocked for sieve.
If you're running selinux or apparmour or similar, check your logs for that (audit log for selinux) and look for denials. You cna also try setting selinux to permissive and trying the operation (setenforce 0).
Peter
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
Regards,
Stephan.
Thanks for the responses. Running sendmail from the command line is successful, which strikes me as odd. So it is only failing when sendmail is invoked from sieve, but I don't yet understand why. I haven't made any recent significant changes to the mail environment. I haven't updated from postfix 3.2.4-2 since 12-16-17 when my distribution released the packaged updated, but I didn't notice the issue at that time until around 12-27 when I started getting emails about the reported permission denied error and sendmail timeout.
Op 1/3/2018 om 1:37 AM schreef tony:
On 2018-01-01 17:26, Peter wrote:
On 02/01/18 14:07, Stephan Bosch wrote:
I can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
I think the real error here is the postdrop one (sendmail is a wrapper around postdrop). It's a permission denied error which leads me to believe it may be an selinux (or similar) issue. I wouldn't be surprised if sendmail works from the command line but fails when executed from sieve because selinux has it blocked for sieve.
If you're running selinux or apparmour or similar, check your logs for that (audit log for selinux) and look for denials. You cna also try setting selinux to permissive and trying the operation (setenforce 0).
Peter
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
Regards,
Stephan.
Thanks for the responses. Running sendmail from the command line is successful, which strikes me as odd. So it is only failing when sendmail is invoked from sieve, but I don't yet understand why. I haven't made any recent significant changes to the mail environment. I haven't updated from postfix 3.2.4-2 since 12-16-17 when my distribution released the packaged updated, but I didn't notice the issue at that time until around 12-27 when I started getting emails about the reported permission denied error and sendmail timeout.
Did you consider Peter's suggestion about selinux and the like? Is the sendmail binary even executable from the same uid/gid as Sieve would be using during deliver?
Regards,
Stephan.
On 2018-01-02 16:37, tony wrote:
On 2018-01-01 17:26, Peter wrote:
On 02/01/18 14:07, Stephan Bosch wrote:
I can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
I think the real error here is the postdrop one (sendmail is a wrapper around postdrop). It's a permission denied error which leads me to believe it may be an selinux (or similar) issue. I wouldn't be surprised if sendmail works from the command line but fails when executed from sieve because selinux has it blocked for sieve.
If you're running selinux or apparmour or similar, check your logs for that (audit log for selinux) and look for denials. You cna also try setting selinux to permissive and trying the operation (setenforce 0).
Peter
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
Regards,
Stephan.
Thanks for the responses. Running sendmail from the command line is successful, which strikes me as odd. So it is only failing when sendmail is invoked from sieve, but I don't yet understand why. I haven't made any recent significant changes to the mail environment. I haven't updated from postfix 3.2.4-2 since 12-16-17 when my distribution released the packaged updated, but I didn't notice the issue at that time until around 12-27 when I started getting emails about the reported permission denied error and sendmail timeout.
Apologies for sending too early. I meant to hit save and not sent. I wanted to point out that I am not using SELinux or AppArmor. The hosts just use some iptables rules, but traffic is permitted to and from these hosts, so I don't think that is the issue. There are several places that talk about correcting permissions, but when I verify the permissions on /var/lib/postfix everything is as it should be.
postfix set-permissions postfix check
The above results in no output reporting any problems. I enabled sieve tracing but did not see anything that stood out apart from the usual reported errors. If I invoke sendmail from the vmail user I am able to send no problem. It doesn't make sense why sieve in general not related to Vacation auto-replies works fine, but auto-replies do not.
- TC
On 2018-01-02 17:21, tony wrote:
On 2018-01-02 16:37, tony wrote:
On 2018-01-01 17:26, Peter wrote:
On 02/01/18 14:07, Stephan Bosch wrote:
I can see 21:21:38 is when the below errors showed up with the above 21:21:38 timestamps:
Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9@domain.email>: failed to send vacation response to sender@domain.email: <Failed to execute sendmail> (temporary error) Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter: create file maildrop/868503.17337: Permission denied
It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
I think the real error here is the postdrop one (sendmail is a wrapper around postdrop). It's a permission denied error which leads me to believe it may be an selinux (or similar) issue. I wouldn't be surprised if sendmail works from the command line but fails when executed from sieve because selinux has it blocked for sieve.
If you're running selinux or apparmour or similar, check your logs for that (audit log for selinux) and look for denials. You cna also try setting selinux to permissive and trying the operation (setenforce 0).
Peter
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work? Is it hanging for more than 30s?
Regards,
Stephan.
Thanks for the responses. Running sendmail from the command line is successful, which strikes me as odd. So it is only failing when sendmail is invoked from sieve, but I don't yet understand why. I haven't made any recent significant changes to the mail environment. I haven't updated from postfix 3.2.4-2 since 12-16-17 when my distribution released the packaged updated, but I didn't notice the issue at that time until around 12-27 when I started getting emails about the reported permission denied error and sendmail timeout.
Apologies for sending too early. I meant to hit save and not sent. I wanted to point out that I am not using SELinux or AppArmor. The hosts just use some iptables rules, but traffic is permitted to and from these hosts, so I don't think that is the issue. There are several places that talk about correcting permissions, but when I verify the permissions on /var/lib/postfix everything is as it should be.
postfix set-permissions postfix check
The above results in no output reporting any problems. I enabled sieve tracing but did not see anything that stood out apart from the usual reported errors. If I invoke sendmail from the vmail user I am able to send no problem. It doesn't make sense why sieve in general not related to Vacation auto-replies works fine, but auto-replies do not.
- TC
I downgraded dovecot to 2.2.33.2 and pigeonhole 0.4.21 and can confirm the reported problem does not exist with "permission denied" and sendmail getting hung up/timing out.
- Cheers, TC
On 03.01.2018 18:14, Tony wrote:
I downgraded dovecot to 2.2.33.2 and pigeonhole 0.4.21 and can confirm the reported problem does not exist with "permission denied" and sendmail getting hung up/timing out.
The issue is that sendmail/maildrop/postdrop uses setgid to change to
the maildrop group (stat $(which postdrop)) and the
NoNewPrivileges=true setting in the service file explicitly disables
this (look in man systemd.exec). This settings appears to be new in 2.3[1].
What is somewhat infuriating is that this behaviour change is not mentioned in the release notes/upgrade notes and the commit that introduces the change changes multiple things and it doesn't explain why things are changed. I'm happy to see service files that try to improve security in an upstream repository though.
Does pigeonhole have any options to configure how mail is send when using "redirect :copy" (possibly more commands, this is just what triggered it here)? If not, support for injecting mail back via smtp would be lovely. I'd like to reenable NoNewPrivileges at some point.
[1] https://github.com/dovecot/core/commit/563c1e3b45bbb69bc67b75ff7a899699bea18...
Florian
Op 1/6/2018 om 7:42 PM schreef Florian Pritz:
I downgraded dovecot to 2.2.33.2 and pigeonhole 0.4.21 and can confirm the reported problem does not exist with "permission denied" and sendmail getting hung up/timing out. The issue is that sendmail/maildrop/postdrop uses setgid to change to
On 03.01.2018 18:14, Tony wrote: the maildrop group (
stat $(which postdrop)) and the NoNewPrivileges=true setting in the service file explicitly disables this (look in man systemd.exec). This settings appears to be new in 2.3[1].What is somewhat infuriating is that this behaviour change is not mentioned in the release notes/upgrade notes and the commit that introduces the change changes multiple things and it doesn't explain why things are changed. I'm happy to see service files that try to improve security in an upstream repository though.
Does pigeonhole have any options to configure how mail is send when using "redirect :copy" (possibly more commands, this is just what triggered it here)? If not, support for injecting mail back via smtp would be lovely. I'd like to reenable NoNewPrivileges at some point.
[1] https://github.com/dovecot/core/commit/563c1e3b45bbb69bc67b75ff7a899699bea18...
The submission_host setting should do what you need:
https://github.com/dovecot/core/blob/master/doc/example-config/conf.d/15-lda...
Regards,
Stephan.
On 2018-01-07 00:08, Stephan Bosch wrote:
Op 1/6/2018 om 7:42 PM schreef Florian Pritz:
What is somewhat infuriating is that this behaviour change is not mentioned in the release notes/upgrade notes and the commit that introduces the change changes multiple things and it doesn't explain why things are changed. I'm happy to see service files that try to improve security in an upstream repository though.
Does pigeonhole have any options to configure how mail is send when using "redirect :copy" (possibly more commands, this is just what triggered it here)? If not, support for injecting mail back via smtp would be lovely. I'd like to reenable NoNewPrivileges at some point.
[1] https://github.com/dovecot/core/commit/563c1e3b45bbb69bc67b75ff7a899699bea18...
The submission_host setting should do what you need:
https://github.com/dovecot/core/blob/master/doc/example-config/conf.d/15-lda...
Regards,
Stephan.
Thank you both. I didn't realize NoNewPrivileges=true was a new
addition, but it all makes sense now. Adding submission_host seems to
have gotten around the issue.
Cheers, tc
On 07.01.2018 09:08, Stephan Bosch wrote:
The submission_host setting should do what you need:
https://github.com/dovecot/core/blob/master/doc/example-config/conf.d/15-lda...
Thanks!
Florian
participants (5)
-
Florian Pritz
-
Peter
-
Stephan Bosch
-
tony
-
Tony