Hello!
I've posted to the list several times about a strange issue I'm having with dovecot LDA. When dovecot-lda is called in the context of a pipe script that is executed as the "vmail" user via the Dovecot Antispam plugin, dovecot-lda exits prematurely with status code 134.
The dovecot deliver manual at http://wiki2.dovecot.org/LDA#logging states very clearly, "If dovecot-lda fails to write to log files it exits with temporary failure." That's a curious note, because I believe that a "temporary failure" exit code may be what I'm dealing with here.
When I drag an email from Inbox to SPAM to trigger Antispam, I see only this (and no further output beyond the last line) in syslog, which is the configured logging destination for LDA:
imap: antispam: mailbox_is_unsure(Junk): 0 imap: antispam: mailbox_is_trash(INBOX): 0 imap: antispam: mailbox_is_trash(Junk): 0 imap: antispam: mail copy: from trash: 0, to trash: 0 imap: antispam: mailbox_is_spam(INBOX): 0 imap: antispam: mailbox_is_spam(Junk): 1 imap: antispam: mailbox_is_unsure(INBOX): 0 imap: antispam: mail copy: src spam: 0, dst spam: 1, src unsure: 0 imap: antispam: running mailtrain backend program /bin/bash imap: antispam: running mailtrain backend program /bin/bash imap: antispam: running mailtrain backend program parameter 1 /usr/local/bin/sa-learn-pipe.sh imap: antispam: running mailtrain backend program parameter 2 --spam
By contrast, if I "su" to the "vmail" user and call the LDA executable with the same arguments that my pipe script does, I see all of the expected output in syslog, AND the message is delivered successfully:
/usr/lib/dovecot/deliver -d "sa-training@localhost.com" -m "Training.SPAM" -p "/tmp/sendmail-msg-25169.txt"
lda: Debug: Loading modules from directory: /usr/lib/dovecot/modules lda: Debug: Module loaded: /usr/lib/dovecot/modules/lib10_quota_plugin.so lda: Debug: Module loaded: /usr/lib/dovecot/modules/lib90_sieve_plugin.so lda: Debug: auth input: sa-training@localhost.com home=/var/vmail/localhost.com/sa-training mail=maildir:/var/vmail/localhost.com/sa-training/Maildir uid=5000 gid=5000 quota_rule=*:storage=0B sieve=/var/vmail/localhost.com/sa-training/.sieve lda: Debug: Added userdb setting: mail=maildir:/var/vmail/localhost.com/sa-training/Maildir lda: Debug: Added userdb setting: plugin/quota_rule=*:storage=0B lda: Debug: Added userdb setting: plugin/sieve=/var/vmail/localhost.com/sa-training/.sieve lda(sa-training@localhost.com): Debug: Effective uid=5000, gid=5000, home=/var/vmail/localhost.com/sa-training lda(sa-training@localhost.com): Debug: Quota root: name=user backend=dict args=:file:/var/vmail/localhost.com/sa-training/.quotausage lda(sa-training@localhost.com): Debug: Quota rule: root=user mailbox=* bytes=0 messages=0 lda(sa-training@localhost.com): Debug: Quota rule: root=user mailbox=Trash bytes=+104857600 messages=0 lda(sa-training@localhost.com): Debug: Quota rule: root=user mailbox=Junk ignored lda(sa-training@localhost.com): Debug: Quota rule: root=user mailbox=INBOX bytes=+104857600 messages=0 lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (100%) messages=0 reverse=no command=quota-reached 100 sa-training@localhost.com localhost.com lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95 sa-training@localhost.com localhost.com lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (80%) messages=0 reverse=no command=quota-warning 80 sa-training@localhost.com localhost.com lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (100%) messages=0 reverse=yes command=quota-below below sa-training@localhost.com localhost.com lda(sa-training@localhost.com): Debug: Quota grace: root=user bytes=0 (10%) lda(sa-training@localhost.com): Debug: dict quota: user=sa-training@localhost.com, uri=file:/var/vmail/localhost.com/sa-training/.quotausage, noenforcing=0 lda(sa-training@localhost.com): Debug: maildir++: root=/var/vmail/localhost.com/sa-training/Maildir, index=, indexpvt=, control=, inbox=/var/vmail/localhost.com/sa-training/Maildir, alt= lda(sa-training@localhost.com): Debug: Quota root: name=user backend=dict args=:file:/var/vmail//raw mail user/.quotausage lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (100%) messages=0 reverse=no command=quota-reached 100 raw mail user lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (95%) messages=0 reverse=no command=quota-warning 95 raw mail user lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (80%) messages=0 reverse=no command=quota-warning 80 raw mail user lda(sa-training@localhost.com): Debug: Quota warning: bytes=0 (100%) messages=0 reverse=yes command=quota-below below raw mail user lda(sa-training@localhost.com): Debug: Quota grace: root=user bytes=0 (10%) lda(sa-training@localhost.com): Debug: dict quota: user=raw mail user, uri=file:/var/vmail//raw mail user/.quotausage, noenforcing=0 lda(sa-training@localhost.com): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt= lda(sa-training@localhost.com): Debug: Destination address: sa-training@localhost.com (source: user@hostname) lda(sa-training@localhost.com): Debug: sieve: Pigeonhole version 0.4.2 initializing lda(sa-training@localhost.com): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:global' scripts. lda(sa-training@localhost.com): Debug: sieve: using the following location for user's Sieve script: /var/vmail/localhost.com/sa-training/.sieve;name=main script lda(sa-training@localhost.com): Debug: sieve: loading script /var/vmail/localhost.com/sa-training/.sieve;name=main script lda(sa-training@localhost.com): Debug: sieve: script binary /var/vmail/localhost.com/sa-training/.sieve.svbin successfully loaded lda(sa-training@localhost.com): Debug: sieve: binary save: not saving binary /var/vmail/localhost.com/sa-training/.sieve.svbin, because it is already stored lda(sa-training@localhost.com): Debug: sieve: executing script from /var/vmail/localhost.com/sa-training/.sieve.svbin lda(sa-training@localhost.com): sieve: msgid=<20141003110532.045EE6060D@localhost.com>: stored mail into mailbox 'Training.SPAM'
I'm trying to make sense of this behavior; the implication seems to be that dovecot-lda is crashes immediately, before it can log anything, when it's triggered via Antispam.
Is there some way to determine what's happening? I've posted coredump and trace information previously, and nobody replied.
Thanks for any help!
-Ben