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+xbcb9q5sgeotknwkf2wgx...@mail.gmail.com>:
failed to send vacation response to some...@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(recipi...@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(recipi...@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=<recipi...@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
<recipi...@domain.net> UA2fMEQiR1ojQwAAUXb6+w Saved)
Dec 29 21:21:38 venus.domain.net postfix/qmgr[16952]: B95004640E:
removed
Dec 29 21:21:38 doveadm(recipi...@domain.net): Debug: auth PASS input:
user=recipi...@domain.net
Dec 29 21:21:38 doveadm(recipi...@domain.net)<17661><>: Debug: auth USER
input: recipi...@domain.net
home=/home/vmail/domain.net/recipi...@domain.net
mail=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
uid=5000 gid=5000
Dec 29 21:21:38 doveadm(recipi...@domain.net)<17661><>: Debug: Added
userdb setting:
mail=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): auth PASS input:
user=recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): auth USER input: recipi...@domain.net
home=/home/vmail/domain.net/recipi...@domain.net
mail=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
uid=5000 gid=5000
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Added userdb setting:
mail=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000,
home=/home/vmail/domain.net/recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are
disabled
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota root: name=User quota
backend=maildir args=
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota rule: root=User quota mailbox=*
bytes=2147483648 messages=0
Dec 29 21:21:39 doveadm(recipi...@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(recipi...@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(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%)
messages=0 reverse=no command=quota-warning +100 recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 (95%)
messages=0 reverse=no command=quota-warning +95 recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 (80%)
messages=0 reverse=no command=quota-warning +80 recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%)
messages=0 reverse=yes command=quota-warning -100 recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): Quota grace: root=User quota
bytes=214748364 (10%)
Dec 29 21:21:39 doveadm(recipi...@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/recipi...@domain.net/Maildir
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): maildir++:
root=/home/vmail/domain.net/recipi...@domain.net/Maildir, index=,
indexpvt=, control=,
inbox=/home/vmail/domain.net/recipi...@domain.net/Maildir, alt=
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug:
remote(orbitron.domain.net:4343): quota: quota_over_flag check:
quota_over_script unset - skipping
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Effective
uid=5000, gid=5000, home=/home/vmail/domain.net/recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: acl: No acl
setting - ACLs are disabled
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota root:
name=User quota backend=maildir args=
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota rule:
root=User quota mailbox=* bytes=2147483648 messages=0
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota rule:
root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota rule:
root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota warning:
bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100
recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota warning:
bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95
recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota warning:
bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80
recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota warning:
bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning
-100 recipi...@domain.net
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Quota grace:
root=User quota bytes=214748364 (10%)
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Namespace inbox:
type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes,
subscriptions=yes
location=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: maildir++:
root=/home/vmail/domain.net/recipi...@domain.net/Maildir, index=,
indexpvt=, control=,
inbox=/home/vmail/domain.net/recipi...@domain.net/Maildir, alt=
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: quota:
quota_over_flag check: quota_over_script unset - skipping
Dec 29 21:21:39 doveadm(recipi...@domain.net): Debug: Namespace : Using
permissions from /home/vmail/domain.net/recipi...@domain.net/Maildir:
mode=0700 gid=default
Dec 29 21:21:39
dsync-local(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
doveadm-sieve: Iterating Sieve mailbox attributes
Dec 29 21:21:39
dsync-local(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
Pigeonhole version 0.5.0 (d68c23a1) initializing
Dec 29 21:21:39
dsync-local(recipi...@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(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Using active Sieve script path:
/home/vmail/domain.net/recipi...@domain.net/.dovecot.sieve
Dec 29 21:21:39
dsync-local(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Using script storage path:
/home/vmail/domain.net/recipi...@domain.net/.sieve
Dec 29 21:21:39
dsync-local(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Using permissions from
/home/vmail/domain.net/recipi...@domain.net/.sieve: mode=0700 gid=-1
Dec 29 21:21:39
dsync-local(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: Relative path to sieve storage in active link: .sieve/
Dec 29 21:21:39
dsync-local(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve:
file storage: sync: Synchronization active
Dec 29 21:21:39
dsync-local(recipi...@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(recipi...@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(recipi...@domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because:
prefetch
Dec 29 21:21:39
dsync-local(recipi...@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=recipi...@domain.net
Dec 29 21:21:39 doveadm: Debug: auth USER input: recipi...@domain.net
home=/home/vmail/domain.net/recipi...@domain.net
mail=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
uid=5000 gid=5000
Dec 29 21:21:39 doveadm: Debug: Added userdb setting:
mail=maildir:/home/vmail/domain.net/recipi...@domain.net/Maildir
Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000,
home=/home/vmail/domain.net/recipi...@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 recipi...@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%)
messages=0 reverse=no command=quota-warning +95 recipi...@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%)
messages=0 reverse=no command=quota-warning +80 recipi...@domain.net
Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%)
messages=0 reverse=yes command=quota-warning -100 recipi...@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/recipi...@domain.net/Maildir
Dec 29 21:21:39 doveadm: Debug: maildir++:
root=/home/vmail/domain.net/recipi...@domain.net/Maildir, index=,
indexpvt=, control=,
inbox=/home/vmail/domain.net/recipi...@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/recipi...@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(recipi...@domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
program `/usr/sbin/sendmail' was forcibly terminated with signal 15
Dec 29 21:21:38
lmtp(recipi...@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
