Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
13 messages Options
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Tony-2
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([hidden email])<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error:
sieve:
msgid=<[hidden email]>:
failed to send vacation response to [hidden email]: <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




Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

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








Reply | Threaded
Open this post in threaded view
|

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

Tony-2
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([hidden email])<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error:
>> sieve:
>> msgid=<[hidden email]>:
>> failed to send vacation response to [hidden email]: <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([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug:
> program `/usr/sbin/sendmail'(17336) execution timed out after 30000
> milliseconds: sending TERM signal
> Dec 29 21:21:38
> lmtp([hidden email])<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=<[hidden email]>,
> 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
> <[hidden email]> UA2fMEQiR1ojQwAAUXb6+w Saved)
> Dec 29 21:21:38 venus.domain.net postfix/qmgr[16952]: B95004640E:
> removed
> Dec 29 21:21:38 doveadm([hidden email]): Debug: auth PASS input:
> user=[hidden email]
> Dec 29 21:21:38 doveadm([hidden email])<17661><>: Debug: auth
> USER input: [hidden email]
> home=/home/vmail/domain.net/[hidden email]
> mail=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> uid=5000 gid=5000
> Dec 29 21:21:38 doveadm([hidden email])<17661><>: Debug: Added
> userdb setting:
> mail=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): auth PASS input:
> user=[hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): auth USER input:
> [hidden email] home=/home/vmail/domain.net/[hidden email]
> mail=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> uid=5000 gid=5000
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Added userdb setting:
> mail=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000,
> home=/home/vmail/domain.net/[hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are
> disabled
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota root: name=User quota
> backend=maildir args=
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota rule: root=User quota
> mailbox=* bytes=2147483648 messages=0
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota rule: root=User quota
> mailbox=Trash bytes=+214748364 (10%) messages=0
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota rule: root=User quota
> mailbox=Spam bytes=+429496729 (20%) messages=0
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648
> (100%) messages=0 reverse=no command=quota-warning +100
> [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465
> (95%) messages=0 reverse=no command=quota-warning +95
> [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918
> (80%) messages=0 reverse=no command=quota-warning +80
> [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648
> (100%) messages=0 reverse=yes command=quota-warning -100
> [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): Quota grace: root=User quota
> bytes=214748364 (10%)
> Dec 29 21:21:39 doveadm([hidden email]): 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/[hidden email]/Maildir
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): maildir++:
> root=/home/vmail/domain.net/[hidden email]/Maildir, index=,
> indexpvt=, control=,
> inbox=/home/vmail/domain.net/[hidden email]/Maildir, alt=
> Dec 29 21:21:39 doveadm([hidden email]): Debug:
> remote(orbitron.domain.net:4343): quota: quota_over_flag check:
> quota_over_script unset - skipping
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Effective
> uid=5000, gid=5000, home=/home/vmail/domain.net/[hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug: acl: No acl
> setting - ACLs are disabled
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota root:
> name=User quota backend=maildir args=
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota rule:
> root=User quota mailbox=* bytes=2147483648 messages=0
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota rule:
> root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota rule:
> root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota warning:
> bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning
> +100 [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota warning:
> bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95
> [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota warning:
> bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80
> [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota warning:
> bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning
> -100 [hidden email]
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Quota grace:
> root=User quota bytes=214748364 (10%)
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Namespace inbox:
> type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes,
> subscriptions=yes
> location=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> Dec 29 21:21:39 doveadm([hidden email]): Debug: maildir++:
> root=/home/vmail/domain.net/[hidden email]/Maildir, index=,
> indexpvt=, control=,
> inbox=/home/vmail/domain.net/[hidden email]/Maildir, alt=
> Dec 29 21:21:39 doveadm([hidden email]): Debug: quota:
> quota_over_flag check: quota_over_script unset - skipping
> Dec 29 21:21:39 doveadm([hidden email]): Debug: Namespace :
> Using permissions from
> /home/vmail/domain.net/[hidden email]/Maildir: mode=0700
> gid=default
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> doveadm-sieve: Iterating Sieve mailbox attributes
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing
> Dec 29 21:21:39
> dsync-local([hidden email])<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([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Using active Sieve script path:
> /home/vmail/domain.net/[hidden email]/.dovecot.sieve
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Using script storage path:
> /home/vmail/domain.net/[hidden email]/.sieve
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Using permissions from
> /home/vmail/domain.net/[hidden email]/.sieve: mode=0700 gid=-1
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Relative path to sieve storage in active link:
> .sieve/
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: sync: Synchronization active
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> doveadm-sieve: Iterating Sieve mailbox attribute:
> vendor/vendor.dovecot/pvt/server/sieve/files/managesieve
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> doveadm-sieve: Iterating Sieve mailbox attribute:
> vendor/vendor.dovecot/pvt/server/sieve/default
> Dec 29 21:21:39
> dsync-local([hidden email])<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because:
> prefetch
> Dec 29 21:21:39
> dsync-local([hidden email])<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=[hidden email]
> Dec 29 21:21:39 doveadm: Debug: auth USER input: [hidden email]
> home=/home/vmail/domain.net/[hidden email]
> mail=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> uid=5000 gid=5000
> Dec 29 21:21:39 doveadm: Debug: Added userdb setting:
> mail=maildir:/home/vmail/domain.net/[hidden email]/Maildir
> Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000,
> home=/home/vmail/domain.net/[hidden email]
> 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 [hidden email]
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%)
> messages=0 reverse=no command=quota-warning +95 [hidden email]
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%)
> messages=0 reverse=no command=quota-warning +80 [hidden email]
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%)
> messages=0 reverse=yes command=quota-warning -100 [hidden email]
> 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/[hidden email]/Maildir
> Dec 29 21:21:39 doveadm: Debug: maildir++:
> root=/home/vmail/domain.net/[hidden email]/Maildir, index=,
> indexpvt=, control=,
> inbox=/home/vmail/domain.net/[hidden email]/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/[hidden email]/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([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
> Dec 29 21:21:38
> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
> sieve: msgid=<[hidden email]>:
> failed to send vacation response to [hidden 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" "[hidden email]"
{
   vacation :days 1 :addresses "[hidden email]" :subject "My Subject
Line" :from "[hidden 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 = [hidden email]
}
protocol lda {
   mail_plugins = sieve quota
   postmaster_address = [hidden 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
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

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

Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Peter Ajamian
On 02/01/18 14:07, Stephan Bosch wrote:

>> I can see 21:21:38 is when the below errors showed up with the above
>> 21:21:38 timestamps:
>>
>> Dec 29 21:21:38
>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
>> Dec 29 21:21:38
>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>> sieve: msgid=<[hidden email]>:
>> failed to send vacation response to [hidden email]: <Failed to
>> execute sendmail> (temporary error)
>> Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter:
>> create file maildrop/868503.17337: Permission denied
>>
>> It still isn't really clear to me why this is going on.
>
> I am wondering what that sendmail process is doing.
>
> As you can see, Dovecot waits for it to finish for 30 seconds (override
> with submission_timeout setting).
>
> Can you try invoking sendmail manually from command line? Does it work?
> Is it hanging for more than 30s?

I think the real error here is the postdrop one (sendmail is a wrapper
around postdrop).  It's a permission denied error which leads me to
believe it may be an selinux (or similar) issue.  I wouldn't be
surprised if sendmail works from the command line but fails when
executed from sieve because selinux has it blocked for sieve.

If you're running selinux or apparmour or similar, check your logs for
that (audit log for selinux) and look for denials.  You cna also try
setting selinux to permissive and trying the operation (setenforce 0).


Peter
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Tony-2
On 2018-01-01 17:26, Peter wrote:

> On 02/01/18 14:07, Stephan Bosch wrote:
>>> I can see 21:21:38 is when the below errors showed up with the above
>>> 21:21:38 timestamps:
>>>
>>> Dec 29 21:21:38
>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
>>> Dec 29 21:21:38
>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>> sieve: msgid=<[hidden email]>:
>>> failed to send vacation response to [hidden email]: <Failed to
>>> execute sendmail> (temporary error)
>>> Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter:
>>> create file maildrop/868503.17337: Permission denied
>>>
>>> It still isn't really clear to me why this is going on.
>>
>> I am wondering what that sendmail process is doing.
>>
>> As you can see, Dovecot waits for it to finish for 30 seconds
>> (override
>> with submission_timeout setting).
>>
>> Can you try invoking sendmail manually from command line? Does it
>> work?
>> Is it hanging for more than 30s?
>
> I think the real error here is the postdrop one (sendmail is a wrapper
> around postdrop).  It's a permission denied error which leads me to
> believe it may be an selinux (or similar) issue.  I wouldn't be
> surprised if sendmail works from the command line but fails when
> executed from sieve because selinux has it blocked for sieve.
>
> If you're running selinux or apparmour or similar, check your logs for
> that (audit log for selinux) and look for denials.  You cna also try
> setting selinux to permissive and trying the operation (setenforce 0).
>
>
> Peter

> I am wondering what that sendmail process is doing.
>
> As you can see, Dovecot waits for it to finish for 30 seconds (override
> with submission_timeout setting).
>
> Can you try invoking sendmail manually from command line? Does it work?
> Is it hanging for more than 30s?
>
> Regards,
>
> Stephan.

Thanks for the responses. Running sendmail from the command line is
successful, which strikes me as odd. So it is only failing when sendmail
is invoked from sieve, but I don't yet understand why. I haven't made
any recent significant changes to the mail environment. I haven't
updated from postfix 3.2.4-2 since 12-16-17 when my distribution
released the packaged updated, but I didn't notice the issue at that
time until around 12-27 when I started getting emails about the reported
permission denied error and sendmail timeout.



Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Stephan Bosch-2
Op 1/3/2018 om 1:37 AM schreef tony:

> On 2018-01-01 17:26, Peter wrote:
>> On 02/01/18 14:07, Stephan Bosch wrote:
>>>> I can see 21:21:38 is when the below errors showed up with the above
>>>> 21:21:38 timestamps:
>>>>
>>>> Dec 29 21:21:38
>>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>>> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
>>>> Dec 29 21:21:38
>>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>>> sieve: msgid=<[hidden email]>:
>>>> failed to send vacation response to [hidden email]: <Failed to
>>>> execute sendmail> (temporary error)
>>>> Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter:
>>>> create file maildrop/868503.17337: Permission denied
>>>>
>>>> It still isn't really clear to me why this is going on.
>>>
>>> I am wondering what that sendmail process is doing.
>>>
>>> As you can see, Dovecot waits for it to finish for 30 seconds (override
>>> with submission_timeout setting).
>>>
>>> Can you try invoking sendmail manually from command line? Does it work?
>>> Is it hanging for more than 30s?
>>
>> I think the real error here is the postdrop one (sendmail is a wrapper
>> around postdrop).  It's a permission denied error which leads me to
>> believe it may be an selinux (or similar) issue.  I wouldn't be
>> surprised if sendmail works from the command line but fails when
>> executed from sieve because selinux has it blocked for sieve.
>>
>> If you're running selinux or apparmour or similar, check your logs for
>> that (audit log for selinux) and look for denials.  You cna also try
>> setting selinux to permissive and trying the operation (setenforce 0).
>>
>>
>> Peter
>
>> I am wondering what that sendmail process is doing.
>>
>> As you can see, Dovecot waits for it to finish for 30 seconds (override
>> with submission_timeout setting).
>>
>> Can you try invoking sendmail manually from command line? Does it work?
>> Is it hanging for more than 30s?
>>
>> Regards,
>>
>> Stephan.
>
> Thanks for the responses. Running sendmail from the command line is
> successful, which strikes me as odd. So it is only failing when
> sendmail is invoked from sieve, but I don't yet understand why. I
> haven't made any recent significant changes to the mail environment. I
> haven't updated from postfix 3.2.4-2 since 12-16-17 when my
> distribution released the packaged updated, but I didn't notice the
> issue at that time until around 12-27 when I started getting emails
> about the reported permission denied error and sendmail timeout.

Did you consider Peter's suggestion about selinux and the like? Is the
sendmail binary even executable from the same uid/gid as Sieve would be
using during deliver?

Regards,

Stephan.

Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Tony-2
In reply to this post by Tony-2
On 2018-01-02 16:37, tony wrote:

> On 2018-01-01 17:26, Peter wrote:
>> On 02/01/18 14:07, Stephan Bosch wrote:
>>>> I can see 21:21:38 is when the below errors showed up with the above
>>>> 21:21:38 timestamps:
>>>>
>>>> Dec 29 21:21:38
>>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>>> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
>>>> Dec 29 21:21:38
>>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>>> sieve: msgid=<[hidden email]>:
>>>> failed to send vacation response to [hidden email]: <Failed to
>>>> execute sendmail> (temporary error)
>>>> Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter:
>>>> create file maildrop/868503.17337: Permission denied
>>>>
>>>> It still isn't really clear to me why this is going on.
>>>
>>> I am wondering what that sendmail process is doing.
>>>
>>> As you can see, Dovecot waits for it to finish for 30 seconds
>>> (override
>>> with submission_timeout setting).
>>>
>>> Can you try invoking sendmail manually from command line? Does it
>>> work?
>>> Is it hanging for more than 30s?
>>
>> I think the real error here is the postdrop one (sendmail is a wrapper
>> around postdrop).  It's a permission denied error which leads me to
>> believe it may be an selinux (or similar) issue.  I wouldn't be
>> surprised if sendmail works from the command line but fails when
>> executed from sieve because selinux has it blocked for sieve.
>>
>> If you're running selinux or apparmour or similar, check your logs for
>> that (audit log for selinux) and look for denials.  You cna also try
>> setting selinux to permissive and trying the operation (setenforce 0).
>>
>>
>> Peter
>
>> I am wondering what that sendmail process is doing.
>>
>> As you can see, Dovecot waits for it to finish for 30 seconds
>> (override
>> with submission_timeout setting).
>>
>> Can you try invoking sendmail manually from command line? Does it
>> work?
>> Is it hanging for more than 30s?
>>
>> Regards,
>>
>> Stephan.
>
> Thanks for the responses. Running sendmail from the command line is
> successful, which strikes me as odd. So it is only failing when
> sendmail is invoked from sieve, but I don't yet understand why. I
> haven't made any recent significant changes to the mail environment. I
> haven't updated from postfix 3.2.4-2 since 12-16-17 when my
> distribution released the packaged updated, but I didn't notice the
> issue at that time until around 12-27 when I started getting emails
> about the reported permission denied error and sendmail timeout.

Apologies for sending too early. I meant to hit save and not sent. I
wanted to point out that I am not using SELinux or AppArmor. The hosts
just use some iptables rules, but traffic is permitted to and from these
hosts, so I don't think that is the issue. There are several places that
talk about correcting permissions, but when I verify the permissions on
/var/lib/postfix everything is as it should be.

postfix set-permissions
postfix check

The above results in no output reporting any problems. I enabled sieve
tracing but did not see anything that stood out apart from the usual
reported errors. If I invoke sendmail from the vmail user I am able to
send no problem. It doesn't make sense why sieve in general not related
to Vacation auto-replies works fine, but auto-replies do not.

-
TC
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Tony-2
On 2018-01-02 17:21, tony wrote:

> On 2018-01-02 16:37, tony wrote:
>> On 2018-01-01 17:26, Peter wrote:
>>> On 02/01/18 14:07, Stephan Bosch wrote:
>>>>> I can see 21:21:38 is when the below errors showed up with the
>>>>> above
>>>>> 21:21:38 timestamps:
>>>>>
>>>>> Dec 29 21:21:38
>>>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>>>> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
>>>>> Dec 29 21:21:38
>>>>> lmtp([hidden email])<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
>>>>> sieve: msgid=<[hidden email]>:
>>>>> failed to send vacation response to [hidden email]: <Failed to
>>>>> execute sendmail> (temporary error)
>>>>> Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter:
>>>>> create file maildrop/868503.17337: Permission denied
>>>>>
>>>>> It still isn't really clear to me why this is going on.
>>>>
>>>> I am wondering what that sendmail process is doing.
>>>>
>>>> As you can see, Dovecot waits for it to finish for 30 seconds
>>>> (override
>>>> with submission_timeout setting).
>>>>
>>>> Can you try invoking sendmail manually from command line? Does it
>>>> work?
>>>> Is it hanging for more than 30s?
>>>
>>> I think the real error here is the postdrop one (sendmail is a
>>> wrapper
>>> around postdrop).  It's a permission denied error which leads me to
>>> believe it may be an selinux (or similar) issue.  I wouldn't be
>>> surprised if sendmail works from the command line but fails when
>>> executed from sieve because selinux has it blocked for sieve.
>>>
>>> If you're running selinux or apparmour or similar, check your logs
>>> for
>>> that (audit log for selinux) and look for denials.  You cna also try
>>> setting selinux to permissive and trying the operation (setenforce
>>> 0).
>>>
>>>
>>> Peter
>>
>>> I am wondering what that sendmail process is doing.
>>>
>>> As you can see, Dovecot waits for it to finish for 30 seconds
>>> (override
>>> with submission_timeout setting).
>>>
>>> Can you try invoking sendmail manually from command line? Does it
>>> work?
>>> Is it hanging for more than 30s?
>>>
>>> Regards,
>>>
>>> Stephan.
>>
>> Thanks for the responses. Running sendmail from the command line is
>> successful, which strikes me as odd. So it is only failing when
>> sendmail is invoked from sieve, but I don't yet understand why. I
>> haven't made any recent significant changes to the mail environment. I
>> haven't updated from postfix 3.2.4-2 since 12-16-17 when my
>> distribution released the packaged updated, but I didn't notice the
>> issue at that time until around 12-27 when I started getting emails
>> about the reported permission denied error and sendmail timeout.
>
> Apologies for sending too early. I meant to hit save and not sent. I
> wanted to point out that I am not using SELinux or AppArmor. The hosts
> just use some iptables rules, but traffic is permitted to and from
> these hosts, so I don't think that is the issue. There are several
> places that talk about correcting permissions, but when I verify the
> permissions on /var/lib/postfix everything is as it should be.
>
> postfix set-permissions
> postfix check
>
> The above results in no output reporting any problems. I enabled sieve
> tracing but did not see anything that stood out apart from the usual
> reported errors. If I invoke sendmail from the vmail user I am able to
> send no problem. It doesn't make sense why sieve in general not
> related to Vacation auto-replies works fine, but auto-replies do not.
>
> -
> TC

I downgraded dovecot to 2.2.33.2 and pigeonhole 0.4.21 and can confirm
the reported problem does not exist with "permission denied" and
sendmail getting hung up/timing out.

-
Cheers,
TC
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Florian Pritz
On 03.01.2018 18:14, Tony wrote:
> I downgraded dovecot to 2.2.33.2 and pigeonhole 0.4.21 and can confirm
> the reported problem does not exist with "permission denied" and
> sendmail getting hung up/timing out.

The issue is that sendmail/maildrop/postdrop uses setgid to change to
the maildrop group (`stat $(which postdrop)`) and the
NoNewPrivileges=true setting in the service file explicitly disables
this (look in man systemd.exec). This settings appears to be new in 2.3[1].

What is somewhat infuriating is that this behaviour change is not
mentioned in the release notes/upgrade notes and the commit that
introduces the change changes multiple things and it doesn't explain why
things are changed. I'm happy to see service files that try to improve
security in an upstream repository though.

Does pigeonhole have any options to configure how mail is send when
using "redirect :copy" (possibly more commands, this is just what
triggered it here)? If not, support for injecting mail back via smtp
would be lovely. I'd like to reenable NoNewPrivileges at some point.

[1]
https://github.com/dovecot/core/commit/563c1e3b45bbb69bc67b75ff7a899699bea18e88#diff-5bbec0a0006d92d441b5c8fa72690f95

Florian


signature.asc (875 bytes) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Stephan Bosch-2
Op 1/6/2018 om 7:42 PM schreef Florian Pritz:

> On 03.01.2018 18:14, Tony wrote:
>> I downgraded dovecot to 2.2.33.2 and pigeonhole 0.4.21 and can confirm
>> the reported problem does not exist with "permission denied" and
>> sendmail getting hung up/timing out.
> The issue is that sendmail/maildrop/postdrop uses setgid to change to
> the maildrop group (`stat $(which postdrop)`) and the
> NoNewPrivileges=true setting in the service file explicitly disables
> this (look in man systemd.exec). This settings appears to be new in 2.3[1].
>
> What is somewhat infuriating is that this behaviour change is not
> mentioned in the release notes/upgrade notes and the commit that
> introduces the change changes multiple things and it doesn't explain why
> things are changed. I'm happy to see service files that try to improve
> security in an upstream repository though.
>
> Does pigeonhole have any options to configure how mail is send when
> using "redirect :copy" (possibly more commands, this is just what
> triggered it here)? If not, support for injecting mail back via smtp
> would be lovely. I'd like to reenable NoNewPrivileges at some point.
>
> [1]
> https://github.com/dovecot/core/commit/563c1e3b45bbb69bc67b75ff7a899699bea18e88#diff-5bbec0a0006d92d441b5c8fa72690f

The submission_host setting should do what you need:

https://github.com/dovecot/core/blob/master/doc/example-config/conf.d/15-lda.conf#L20

Regards,

Stephan.

Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Tony-2
On 2018-01-07 00:08, Stephan Bosch wrote:

> Op 1/6/2018 om 7:42 PM schreef Florian Pritz:
>> What is somewhat infuriating is that this behaviour change is not
>> mentioned in the release notes/upgrade notes and the commit that
>> introduces the change changes multiple things and it doesn't explain
>> why
>> things are changed. I'm happy to see service files that try to improve
>> security in an upstream repository though.
>>
>> Does pigeonhole have any options to configure how mail is send when
>> using "redirect :copy" (possibly more commands, this is just what
>> triggered it here)? If not, support for injecting mail back via smtp
>> would be lovely. I'd like to reenable NoNewPrivileges at some point.
>>
>> [1]
>> https://github.com/dovecot/core/commit/563c1e3b45bbb69bc67b75ff7a899699bea18e88#diff-5bbec0a0006d92d441b5c8fa72690f
>
> The submission_host setting should do what you need:
>
> https://github.com/dovecot/core/blob/master/doc/example-config/conf.d/15-lda.conf#L20
>
> Regards,
>
> Stephan.

Thank you both. I didn't realize `NoNewPrivileges=true` was a new
addition, but it all makes sense now. Adding `submission_host` seems to
have gotten around the issue.

Cheers,
tc
Reply | Threaded
Open this post in threaded view
|

Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

Florian Pritz
In reply to this post by Stephan Bosch-2
On 07.01.2018 09:08, Stephan Bosch wrote:
> The submission_host setting should do what you need:
>
> https://github.com/dovecot/core/blob/master/doc/example-config/conf.d/15-lda.conf#L20

Thanks!

Florian


signature.asc (875 bytes) Download Attachment