Updated Dovecot 2.3.0 now getting 2 strange log errors
tony
tony at kode.email
Sat Dec 30 07:47:26 EET 2017
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
More information about the dovecot
mailing list