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 at domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>:
Error:
sieve:
msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ at
mail.gmail.com>:
failed to send vacation response to someone at 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 at domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: > sieve: > msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ at mail.gmail.com>: > failed to send vacation response to someone at 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. > > - > TCI 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 at 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 at 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 at 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 at 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 at domain.net): Debug: auth PASS input: user=recipient at domain.net Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: auth USER input: recipient at domain.net home=/home/vmail/domain.net/recipient at domain.net mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): auth PASS input: user=recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): auth USER input: recipient at domain.net home=/home/vmail/domain.net/recipient at domain.net mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Quota root: name=User quota backend=maildir argsDec 29 21:21:39 doveadm(recipient at 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 at 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 at 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 at domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient at 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 at domain.net/Maildir Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: remote(orbitron.domain.net:4343): maildir++: root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, altDec 29 21:21:39 doveadm(recipient at 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 at domain.net): Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: acl: No acl setting - ACLs are disabled Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota root: name=User quota backend=maildir argsDec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: root=User quota mailbox=* bytes=2147483648 messages=0 Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning +100 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient at domain.net Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota grace: root=User quota bytes=214748364 (10%) Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: maildir++: root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, altDec 29 21:21:39 doveadm(recipient at domain.net): Debug: quota: quota_over_flag check: quota_over_script unset - skipping Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace : Using permissions from /home/vmail/domain.net/recipient at domain.net/Maildir: mode=0700 gid=default Dec 29 21:21:39 dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: doveadm-sieve: Iterating Sieve mailbox attributes Dec 29 21:21:39 dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing Dec 29 21:21:39 dsync-local(recipient at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using active Sieve script path: /home/vmail/domain.net/recipient at domain.net/.dovecot.sieve Dec 29 21:21:39 dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using script storage path: /home/vmail/domain.net/recipient at domain.net/.sieve Dec 29 21:21:39 dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: Using permissions from /home/vmail/domain.net/recipient at domain.net/.sieve: mode=0700 gid=-1 Dec 29 21:21:39 dsync-local(recipient at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: sieve: file storage: sync: Synchronization active Dec 29 21:21:39 dsync-local(recipient at 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 at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: prefetch Dec 29 21:21:39 dsync-local(recipient at 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 at domain.net Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient at domain.net home=/home/vmail/domain.net/recipient at domain.net mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir uid=5000 gid=5000 Dec 29 21:21:39 doveadm: Debug: Added userdb setting: mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000, home=/home/vmail/domain.net/recipient at 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 argsDec 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 at domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 recipient at domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 recipient at domain.net Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning -100 recipient at 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 at domain.net/Maildir Dec 29 21:21:39 doveadm: Debug: maildir++: root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, indexpvt=, control=, inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, altDec 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 at 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 at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: program `/usr/sbin/sendmail' was forcibly terminated with signal 15 Dec 29 21:21:38 lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9 at domain.email>: failed to send vacation response to sender at 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
tony
2017-Dec-31 09:53 UTC
Updated Dovecot 2.3.0 and Pigeonhole 0.5.0 now Vacation Auto-Reply is failing
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 at domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: >> sieve: >> msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ at mail.gmail.com>: >> failed to send vacation response to someone at 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 at 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 at 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 at 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 at 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 at domain.net): Debug: auth PASS input: > user=recipient at domain.net > Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: auth > USER input: recipient at domain.net > home=/home/vmail/domain.net/recipient at domain.net > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > uid=5000 gid=5000 > Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: Added > userdb setting: > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): auth PASS input: > user=recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): auth USER input: > recipient at domain.net home=/home/vmail/domain.net/recipient at domain.net > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > uid=5000 gid=5000 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Added userdb setting: > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000, > home=/home/vmail/domain.net/recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are > disabled > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota root: name=User quota > backend=maildir args> Dec 29 21:21:39 doveadm(recipient at 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 at 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 at 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 at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 > (100%) messages=0 reverse=no command=quota-warning +100 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 > (95%) messages=0 reverse=no command=quota-warning +95 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 > (80%) messages=0 reverse=no command=quota-warning +80 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 > (100%) messages=0 reverse=yes command=quota-warning -100 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota grace: root=User quota > bytes=214748364 (10%) > Dec 29 21:21:39 doveadm(recipient at 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 at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): maildir++: > root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, > indexpvt=, control=, > inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt> Dec 29 21:21:39 doveadm(recipient at 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 at domain.net): Debug: Effective > uid=5000, gid=5000, home=/home/vmail/domain.net/recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: acl: No acl > setting - ACLs are disabled > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota root: > name=User quota backend=maildir args> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: > root=User quota mailbox=* bytes=2147483648 messages=0 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: > root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: > root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning > +100 recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning > -100 recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota grace: > root=User quota bytes=214748364 (10%) > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace inbox: > type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, > subscriptions=yes > location=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: maildir++: > root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, > indexpvt=, control=, > inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: quota: > quota_over_flag check: quota_over_script unset - skipping > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace : > Using permissions from > /home/vmail/domain.net/recipient at domain.net/Maildir: mode=0700 > gid=default > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > doveadm-sieve: Iterating Sieve mailbox attributes > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing > Dec 29 21:21:39 > dsync-local(recipient at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: Using active Sieve script path: > /home/vmail/domain.net/recipient at domain.net/.dovecot.sieve > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: Using script storage path: > /home/vmail/domain.net/recipient at domain.net/.sieve > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: Using permissions from > /home/vmail/domain.net/recipient at domain.net/.sieve: mode=0700 gid=-1 > Dec 29 21:21:39 > dsync-local(recipient at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: sync: Synchronization active > Dec 29 21:21:39 > dsync-local(recipient at 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 at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: > prefetch > Dec 29 21:21:39 > dsync-local(recipient at 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 at domain.net > Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient at domain.net > home=/home/vmail/domain.net/recipient at domain.net > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > uid=5000 gid=5000 > Dec 29 21:21:39 doveadm: Debug: Added userdb setting: > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000, > home=/home/vmail/domain.net/recipient at 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 at domain.net > Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%) > messages=0 reverse=no command=quota-warning +95 recipient at domain.net > Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%) > messages=0 reverse=no command=quota-warning +80 recipient at domain.net > Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) > messages=0 reverse=yes command=quota-warning -100 recipient at 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 at domain.net/Maildir > Dec 29 21:21:39 doveadm: Debug: maildir++: > root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, > indexpvt=, control=, > inbox=/home/vmail/domain.net/recipient at 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 at 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 at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: > program `/usr/sbin/sendmail' was forcibly terminated with signal 15 > Dec 29 21:21:38 > lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: > sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9 at domain.email>: > failed to send vacation response to sender at 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, > TCAn important bit I forgot to add was the actual Vacation sieve code. --- require ["fileinto","vacation"]; # rule:[Auto-Response] if header :contains "to" "me at domain.email" { vacation :days 1 :addresses "me at domain.email" :subject "My Subject Line" :from "noreply at 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 at domain.net } protocol lda { mail_plugins = sieve quota postmaster_address = postmaster at 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
Stephan Bosch
2018-Jan-02 01:07 UTC
Updated Dovecot 2.3.0 now getting 2 strange log errors
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 at domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error: >> sieve: >> msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ at mail.gmail.com>: >> >> failed to send vacation response to someone at 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 at 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 at 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 at 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 at 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 at domain.net): Debug: auth PASS input: > user=recipient at domain.net > Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: auth > USER input: recipient at domain.net > home=/home/vmail/domain.net/recipient at domain.net > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > uid=5000 gid=5000 > Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: Added > userdb setting: > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): auth PASS input: > user=recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): auth USER input: > recipient at domain.net home=/home/vmail/domain.net/recipient at domain.net > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > uid=5000 gid=5000 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Added userdb setting: > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000, > home=/home/vmail/domain.net/recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are disabled > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota root: name=User quota > backend=maildir args> Dec 29 21:21:39 doveadm(recipient at 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 at 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 at 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 at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 > (100%) messages=0 reverse=no command=quota-warning +100 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465 > (95%) messages=0 reverse=no command=quota-warning +95 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918 > (80%) messages=0 reverse=no command=quota-warning +80 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648 > (100%) messages=0 reverse=yes command=quota-warning -100 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): Quota grace: root=User quota > bytes=214748364 (10%) > Dec 29 21:21:39 doveadm(recipient at 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 at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: > remote(orbitron.domain.net:4343): maildir++: > root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, > indexpvt=, control=, > inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt> Dec 29 21:21:39 doveadm(recipient at 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 at domain.net): Debug: Effective > uid=5000, gid=5000, home=/home/vmail/domain.net/recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: acl: No acl > setting - ACLs are disabled > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota root: > name=User quota backend=maildir args> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: > root=User quota mailbox=* bytes=2147483648 messages=0 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: > root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule: > root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0 > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning > +100 recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80 > recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning: > bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning > -100 recipient at domain.net > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota grace: > root=User quota bytes=214748364 (10%) > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace inbox: > type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, > subscriptions=yes > location=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: maildir++: > root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, > indexpvt=, control=, > inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: quota: > quota_over_flag check: quota_over_script unset - skipping > Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace : > Using permissions from > /home/vmail/domain.net/recipient at domain.net/Maildir: mode=0700 > gid=default > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > doveadm-sieve: Iterating Sieve mailbox attributes > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing > Dec 29 21:21:39 > dsync-local(recipient at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: Using active Sieve script path: > /home/vmail/domain.net/recipient at domain.net/.dovecot.sieve > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: Using script storage path: > /home/vmail/domain.net/recipient at domain.net/.sieve > Dec 29 21:21:39 > dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: Using permissions from > /home/vmail/domain.net/recipient at domain.net/.sieve: mode=0700 gid=-1 > Dec 29 21:21:39 > dsync-local(recipient at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > sieve: file storage: sync: Synchronization active > Dec 29 21:21:39 > dsync-local(recipient at 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 at 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 at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug: > Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because: > prefetch > Dec 29 21:21:39 > dsync-local(recipient at 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 at domain.net > Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient at domain.net > home=/home/vmail/domain.net/recipient at domain.net > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > uid=5000 gid=5000 > Dec 29 21:21:39 doveadm: Debug: Added userdb setting: > mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir > Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000, > home=/home/vmail/domain.net/recipient at 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 at domain.net > Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%) > messages=0 reverse=no command=quota-warning +95 recipient at domain.net > Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%) > messages=0 reverse=no command=quota-warning +80 recipient at domain.net > Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%) > messages=0 reverse=yes command=quota-warning -100 recipient at 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 at domain.net/Maildir > Dec 29 21:21:39 doveadm: Debug: maildir++: > root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=, > indexpvt=, control=, > inbox=/home/vmail/domain.net/recipient at 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 at 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 at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: > program `/usr/sbin/sendmail' was forcibly terminated with signal 15 > Dec 29 21:21:38 > lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error: > sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9 at domain.email>: > failed to send vacation response to sender at 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.
Reasonably Related Threads
- Updated Dovecot 2.3.0 now getting 2 strange log errors
- Updated Dovecot 2.3.0 now getting 2 strange log errors
- Updated Dovecot 2.3.0 now getting 2 strange log errors
- dovecot: config: Error: BUG: Config client connection sent too much data
- dovecot: config: Error: BUG: Config client connection sent too much data