dovecot - Jan 2018 - Updated Dovecot 2.3.0 now getting 2 strange log errors

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

As you can see, Dovecot waits for it to finish for 30 seconds (override
with submission_timeout setting).

Can you try invoking sendmail manually from command line? Does it work?
Is it hanging for more than 30s?

Regards,

Stephan.

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

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(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?
> 
> 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.