Re: Updated Dovecot 2.3.0 now getting 2 strange log errors

On 2017-12-29 18:35, tony wrote:

I did some more digging around and found this is reproducible on multiple hosts running the same version of Dovecot/Pigeonhole/Postfix. The problem resurfaces on any host to an account with enabled Vacation/OOO response. The Vacation/OOO reply filter was created in Roundcubemail, but has been fine for years. One thing to note is in Dovecot 2.3.0 I did enable UTF8, but even if I disable UTF8 the issue remains. What I have discovered after digging around is..

• After a fresh postfix restart all expected processes are running without any postdrop process.

postgrey 13080 0.0 0.2 73036 21108 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 385700 108 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138572 9088 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13320 0.0 0.1 163908 9832 ? S 17:24 0:00 proxymap -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 13322 0.0 0.1 138524 9280 ? S 17:24 0:00 anvil -l -t unix -u postfix 13352 0.0 0.1 168896 13520 ? S 17:24 0:00 smtpd -n smtp -t inet -u -o stress= -s 2 -o content_filter=spamassassin postfix 13539 0.0 0.1 163920 10156 ? S 17:24 0:00 trivial-rewrite -n rewrite -t unix -u postfix 14369 0.0 0.1 164300 10340 ? S 17:26 0:00 cleanup -z -t unix -u postfix 14370 0.0 0.1 124180 8844 ? S 17:26 0:00 pipe -n spamassassin -t unix user=spamd argv=/usr/bin/vendor_perl/spamc -f -e /usr/sbin/sendmail -oi -f ${sender} ${recipient} postfix 14375 0.0 0.1 142856 9344 ? S 17:26 0:00 lmtp -t unix -u vmail 14446 0.0 0.0 44008 7496 ? S 17:26 0:00 dovecot/quota-status -p postfix

• During the problem where the logs are complaining about permission denied and sendmail exiting with signal 15 (caused by inbound email to an address with enabled Vacation notice filter) there is a running postdrop process and several expected processes are not running.

postgrey 13080 0.0 0.2 73036 21132 ? Ss 17:23 0:00 postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid --group=postgrey --user=postgrey --daemonize --greylist-text=Greylisted for %s seconds --auto-whitelist-clients root 13107 0.0 0.0 461572 408 ? Ssl 17:23 0:00 /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00 /usr/lib/postfix/bin/master -w postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00 pickup -l -t unix -u postfix 13194 0.0 0.1 138644 9128 ? S 17:23 0:00 qmgr -l -t unix -u postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00 tlsmgr -l -t unix -u postfix 20793 0.0 0.1 138524 9092 ? S 17:39 0:00 anvil -l -t unix -u vmail 25340 0.0 0.0 44108 7664 ? S 17:46 0:00 dovecot/quota-status -p postfix vmail 26298 0.0 0.1 122088 8536 ? S 17:49 0:00 /usr/bin/postdrop -r ——

• When the issue is not present, an email TO any address with a disabled Vacation/OOO response filter is processed with no issues and stored in the respective folder moved by an existing filter not related to Vacation/OOO. Expected processes are still running (no postdrop process which when running seems to be causing the problem)

• When the issue is not present, an email TO an address with a enabled Vacation/OOO response filter is processed and stored in the Inbox, but an auto-response fails to send. The result are these errors with the permission denied being repeated every ~minute.

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

It still isn't really clear to me why this is going on.

-- Cheers, TC