Updated Dovecot 2.3.0 now getting 2 strange log errors
Stephan Bosch
stephan at rename-it.nl
Tue Jan 2 03:07:14 EET 2018
Op 12/30/2017 om 6:47 AM schreef tony:
> On 2017-12-29 18:35, tony wrote:
>> I did some more digging around and found this is reproducible on
>> multiple hosts running the same version of Dovecot/Pigeonhole/Postfix.
>> The problem resurfaces on any host to an account with enabled
>> Vacation/OOO response. The Vacation/OOO reply filter was created in
>> Roundcubemail, but has been fine for years. One thing to note is in
>> Dovecot 2.3.0 I did enable UTF8, but even if I disable UTF8 the issue
>> remains. What I have discovered after digging around is..
>>
>> * After a fresh postfix restart all expected processes are running
>> without any postdrop process.
>>
>> postgrey 13080 0.0 0.2 73036 21108 ? Ss 17:23 0:00
>> postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid
>> --group=postgrey --user=postgrey --daemonize
>> --greylist-text=Greylisted for %s seconds --auto-whitelist-clients
>> root 13107 0.0 0.0 385700 108 ? Ssl 17:23 0:00
>> /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid
>> -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org
>> root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00
>> /usr/lib/postfix/bin/master -w
>> postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00
>> pickup -l -t unix -u
>> postfix 13194 0.0 0.1 138572 9088 ? S 17:23 0:00 qmgr
>> -l -t unix -u
>> postfix 13320 0.0 0.1 163908 9832 ? S 17:24 0:00
>> proxymap -t unix -u
>> postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00
>> tlsmgr -l -t unix -u
>> postfix 13322 0.0 0.1 138524 9280 ? S 17:24 0:00 anvil
>> -l -t unix -u
>> postfix 13352 0.0 0.1 168896 13520 ? S 17:24 0:00 smtpd
>> -n smtp -t inet -u -o stress= -s 2 -o content_filter=spamassassin
>> postfix 13539 0.0 0.1 163920 10156 ? S 17:24 0:00
>> trivial-rewrite -n rewrite -t unix -u
>> postfix 14369 0.0 0.1 164300 10340 ? S 17:26 0:00
>> cleanup -z -t unix -u
>> postfix 14370 0.0 0.1 124180 8844 ? S 17:26 0:00 pipe
>> -n spamassassin -t unix user=spamd argv=/usr/bin/vendor_perl/spamc -f
>> -e /usr/sbin/sendmail -oi -f ${sender} ${recipient}
>> postfix 14375 0.0 0.1 142856 9344 ? S 17:26 0:00 lmtp
>> -t unix -u
>> vmail 14446 0.0 0.0 44008 7496 ? S 17:26 0:00
>> dovecot/quota-status -p postfix
>>
>>
>> * During the problem where the logs are complaining about permission
>> denied and sendmail exiting with signal 15 (caused by inbound email to
>> an address with enabled Vacation notice filter) there is a running
>> postdrop process and several expected processes are not running.
>>
>> postgrey 13080 0.0 0.2 73036 21132 ? Ss 17:23 0:00
>> postgrey --inet=127.0.0.1:10030 --pidfile=/run/postgrey/postgrey.pid
>> --group=postgrey --user=postgrey --daemonize
>> --greylist-text=Greylisted for %s seconds --auto-whitelist-clients
>> root 13107 0.0 0.0 461572 408 ? Ssl 17:23 0:00
>> /usr/local/bin/pwhois_milter -i /run/pwhois_milter/pwhois_milter.pid
>> -l /var/log/mail/mail.log -u postfix -g postfix -w global.pwhois.org
>> root 13192 0.0 0.0 122536 5856 ? Ss 17:23 0:00
>> /usr/lib/postfix/bin/master -w
>> postfix 13193 0.0 0.1 138524 8996 ? S 17:23 0:00
>> pickup -l -t unix -u
>> postfix 13194 0.0 0.1 138644 9128 ? S 17:23 0:00 qmgr
>> -l -t unix -u
>> postfix 13321 0.0 0.1 142756 9632 ? S 17:24 0:00
>> tlsmgr -l -t unix -u
>> postfix 20793 0.0 0.1 138524 9092 ? S 17:39 0:00 anvil
>> -l -t unix -u
>> vmail 25340 0.0 0.0 44108 7664 ? S 17:46 0:00
>> dovecot/quota-status -p postfix
>> vmail 26298 0.0 0.1 122088 8536 ? S 17:49 0:00
>> /usr/bin/postdrop -r
>> ——
>>
>> * When the issue is not present, an email TO any address with a
>> disabled Vacation/OOO response filter is processed with no issues and
>> stored in the respective folder moved by an existing filter not
>> related to Vacation/OOO. Expected processes are still running (no
>> postdrop process which when running seems to be causing the problem)
>>
>> * When the issue is not present, an email TO an address with a enabled
>> Vacation/OOO response filter is processed and stored in the Inbox, but
>> an auto-response fails to send. The result are these errors with the
>> permission denied being repeated every ~minute.
>>
>> Dec 29 17:49:58
>> lmtp(jsomeone at domain.email)<26296><qbe8H6jwRlq4ZgAAUXb6+w>: Error:
>> sieve:
>> msgid=<CAE2c3QaGTiFDt5rdHEy2YeoSe+XBcB9Q5SGeOtknWKf2wgXZhQ at mail.gmail.com>:
>>
>> failed to send vacation response to someone at gmail.com: <Failed to
>> execute sendmail> (temporary error)
>> Dec 29 17:50:08 lmtp: Error: postdrop: warning: mail_queue_enter:
>> create file maildrop/569031.26298: Permission denied
>>
>> * After the problem starts again with the errors shown in the logs a
>> postdrop process stays running in the background. After a short while
>> the number of postfix processes decreases.
>>
>> * If I kill the postdrop process then the logged errors stop and the
>> expected processes all show up again.
>>
>> I am running out of ideas on why this has suddenly surfaced.
>>
>> -
>> TC
>
>
> I think I am getting closer. Investigated further and the issue first
> surfaced:
> Dec 26 07:54:49 lmtp: Error: postdrop: warning: mail_queue_enter:
> create file maildrop/600085.6655: Permission denied
>
> #1 upgrade
> [2017-12-25 03:18] [ALPM] upgraded dovecot (2.2.33.2-2 -> 2.3.0-1)
> [2017-12-25 03:18] [ALPM] upgraded pigeonhole (0.4.21-1 -> 0.5.0-1)
>
> #2 upgrade
> [2017-12-26 16:44] [ALPM] upgraded pigeonhole (0.5.0-1 -> 0.5.0-2)
>
> According to the upgrade timestamps it looks like ever since going
> from pigeonhole 0.4.21 to 0.5.0 is when the issue first surfaced. Here
> is a recent debug I collected:
>
> ---
> Dec 29 21:21:38
> lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug:
> program `/usr/sbin/sendmail'(17336) execution timed out after 30000
> milliseconds: sending TERM signal
> Dec 29 21:21:38
> lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Debug:
> Mailbox <lmtp DATA local>: Opened mail UID=1 because: virtual size
> (Cache file is unusable)
> Dec 29 21:21:38 lmtp(17187): Info: Disconnect from local: Client has
> quit the connection (state = READY)
> Dec 29 21:21:38 venus.domain.net postfix/lmtp[17186]: B95004640E:
> to=<recipient at domain.net>,
> relay=mail.domain.net[private/dovecot-lmtp], delay=30,
> delays=0.06/0/0/30, dsn=2.0.0, status=sent (250 2.0.0
> <recipient at domain.net> UA2fMEQiR1ojQwAAUXb6+w Saved)
> Dec 29 21:21:38 venus.domain.net postfix/qmgr[16952]: B95004640E: removed
> Dec 29 21:21:38 doveadm(recipient at domain.net): Debug: auth PASS input:
> user=recipient at domain.net
> Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: auth
> USER input: recipient at domain.net
> home=/home/vmail/domain.net/recipient at domain.net
> mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> uid=5000 gid=5000
> Dec 29 21:21:38 doveadm(recipient at domain.net)<17661><>: Debug: Added
> userdb setting:
> mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): auth PASS input:
> user=recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): auth USER input:
> recipient at domain.net home=/home/vmail/domain.net/recipient at domain.net
> mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> uid=5000 gid=5000
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Added userdb setting:
> mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Effective uid=5000, gid=5000,
> home=/home/vmail/domain.net/recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): acl: No acl setting - ACLs are disabled
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota root: name=User quota
> backend=maildir args=
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota rule: root=User quota
> mailbox=* bytes=2147483648 messages=0
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota rule: root=User quota
> mailbox=Trash bytes=+214748364 (10%) messages=0
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota rule: root=User quota
> mailbox=Spam bytes=+429496729 (20%) messages=0
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648
> (100%) messages=0 reverse=no command=quota-warning +100
> recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=2040109465
> (95%) messages=0 reverse=no command=quota-warning +95
> recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=1717986918
> (80%) messages=0 reverse=no command=quota-warning +80
> recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota warning: bytes=2147483648
> (100%) messages=0 reverse=yes command=quota-warning -100
> recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Quota grace: root=User quota
> bytes=214748364 (10%)
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): Namespace inbox: type=private,
> prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes
> location=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): maildir++:
> root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=,
> indexpvt=, control=,
> inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt=
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug:
> remote(orbitron.domain.net:4343): quota: quota_over_flag check:
> quota_over_script unset - skipping
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Effective
> uid=5000, gid=5000, home=/home/vmail/domain.net/recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: acl: No acl
> setting - ACLs are disabled
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota root:
> name=User quota backend=maildir args=
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule:
> root=User quota mailbox=* bytes=2147483648 messages=0
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule:
> root=User quota mailbox=Trash bytes=+214748364 (10%) messages=0
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota rule:
> root=User quota mailbox=Spam bytes=+429496729 (20%) messages=0
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning:
> bytes=2147483648 (100%) messages=0 reverse=no command=quota-warning
> +100 recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning:
> bytes=2040109465 (95%) messages=0 reverse=no command=quota-warning +95
> recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning:
> bytes=1717986918 (80%) messages=0 reverse=no command=quota-warning +80
> recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota warning:
> bytes=2147483648 (100%) messages=0 reverse=yes command=quota-warning
> -100 recipient at domain.net
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Quota grace:
> root=User quota bytes=214748364 (10%)
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace inbox:
> type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes,
> subscriptions=yes
> location=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: maildir++:
> root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=,
> indexpvt=, control=,
> inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt=
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: quota:
> quota_over_flag check: quota_over_script unset - skipping
> Dec 29 21:21:39 doveadm(recipient at domain.net): Debug: Namespace :
> Using permissions from
> /home/vmail/domain.net/recipient at domain.net/Maildir: mode=0700
> gid=default
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> doveadm-sieve: Iterating Sieve mailbox attributes
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: Pigeonhole version 0.5.0 (d68c23a1) initializing
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: include: sieve_global is not set; it is currently not possible
> to include `:global' scripts.
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Using active Sieve script path:
> /home/vmail/domain.net/recipient at domain.net/.dovecot.sieve
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Using script storage path:
> /home/vmail/domain.net/recipient at domain.net/.sieve
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Using permissions from
> /home/vmail/domain.net/recipient at domain.net/.sieve: mode=0700 gid=-1
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: Relative path to sieve storage in active link:
> .sieve/
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> sieve: file storage: sync: Synchronization active
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> doveadm-sieve: Iterating Sieve mailbox attribute:
> vendor/vendor.dovecot/pvt/server/sieve/files/managesieve
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> doveadm-sieve: Iterating Sieve mailbox attribute:
> vendor/vendor.dovecot/pvt/server/sieve/default
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because:
> prefetch
> Dec 29 21:21:39
> dsync-local(recipient at domain.net)<eKG9NGIiR1r9RAAAUXb6+w>: Debug:
> Mailbox Virtual Domains.domain.email: Opened mail UID=1416 because:
> mail stream
> Dec 29 21:21:39 doveadm: Debug: auth PASS input:
> user=recipient at domain.net
> Dec 29 21:21:39 doveadm: Debug: auth USER input: recipient at domain.net
> home=/home/vmail/domain.net/recipient at domain.net
> mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> uid=5000 gid=5000
> Dec 29 21:21:39 doveadm: Debug: Added userdb setting:
> mail=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> Dec 29 21:21:39 doveadm: Debug: Effective uid=5000, gid=5000,
> home=/home/vmail/domain.net/recipient at domain.net
> Dec 29 21:21:39 doveadm: Debug: acl: No acl setting - ACLs are disabled
> Dec 29 21:21:39 doveadm: Debug: Quota root: name=User quota
> backend=maildir args=
> Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota mailbox=*
> bytes=2147483648 messages=0
> Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota
> mailbox=Trash bytes=+214748364 (10%) messages=0
> Dec 29 21:21:39 doveadm: Debug: Quota rule: root=User quota
> mailbox=Spam bytes=+429496729 (20%) messages=0
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%)
> messages=0 reverse=no command=quota-warning +100 recipient at domain.net
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2040109465 (95%)
> messages=0 reverse=no command=quota-warning +95 recipient at domain.net
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=1717986918 (80%)
> messages=0 reverse=no command=quota-warning +80 recipient at domain.net
> Dec 29 21:21:39 doveadm: Debug: Quota warning: bytes=2147483648 (100%)
> messages=0 reverse=yes command=quota-warning -100 recipient at domain.net
> Dec 29 21:21:39 doveadm: Debug: Quota grace: root=User quota
> bytes=214748364 (10%)
> Dec 29 21:21:39 doveadm: Debug: Namespace inbox: type=private,
> prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes
> location=maildir:/home/vmail/domain.net/recipient at domain.net/Maildir
> Dec 29 21:21:39 doveadm: Debug: maildir++:
> root=/home/vmail/domain.net/recipient at domain.net/Maildir, index=,
> indexpvt=, control=,
> inbox=/home/vmail/domain.net/recipient at domain.net/Maildir, alt=
> Dec 29 21:21:39 doveadm: Debug: quota: quota_over_flag check:
> quota_over_script unset - skipping
> Dec 29 21:21:39 doveadm: Debug: Namespace : Using permissions from
> /home/vmail/domain.net/recipient at domain.net/Maildir: mode=0700
> gid=default
>
>
> I can see 21:21:38 is when the below errors showed up with the above
> 21:21:38 timestamps:
>
> Dec 29 21:21:38
> lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
> program `/usr/sbin/sendmail' was forcibly terminated with signal 15
> Dec 29 21:21:38
> lmtp(recipient at domain.net)<17187><UA2fMEQiR1ojQwAAUXb6+w>: Error:
> sieve: msgid=<470c210f-bd19-f63f-45ed-bfef59322be9 at domain.email>:
> failed to send vacation response to sender at domain.email: <Failed to
> execute sendmail> (temporary error)
> Dec 29 21:21:38 lmtp: Error: postdrop: warning: mail_queue_enter:
> create file maildrop/868503.17337: Permission denied
>
> It still isn't really clear to me why this is going on.
I am wondering what that sendmail process is doing.
As you can see, Dovecot waits for it to finish for 30 seconds (override
with submission_timeout setting).
Can you try invoking sendmail manually from command line? Does it work?
Is it hanging for more than 30s?
Regards,
Stephan.
More information about the dovecot
mailing list