thr3ads.net - dovecot - Updated Dovecot 2.3.0 now getting 2 strange log errors [Dec 2017]

If this information is useful, please help other people find it:
Share via:

tony

2017-Dec-30 02:35 UTC

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 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

tony

2017-Dec-30 05:47 UTC

head link

Updated Dovecot 2.3.0 now getting 2 strange log errors

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 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

head link

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,
> 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 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

head link

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.

Maybe Matching Threads

Search for more reasonably related threads

dovecot - Dec 2017 - 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

Updated Dovecot 2.3.0 and Pigeonhole 0.5.0 now Vacation Auto-Reply is failing

Updated Dovecot 2.3.0 now getting 2 strange log errors

Maybe Matching Threads