How best to confirm that dovecot LDA logging is working correctly?

[Ben Johnson]

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 at 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 at 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 at localhost.com): Debug: Effective uid=5000, gid=5000,
home=/var/vmail/localhost.com/sa-training
lda(sa-training at localhost.com): Debug: Quota root: name=user
backend=dict args=:file:/var/vmail/localhost.com/sa-training/.quotausage
lda(sa-training at localhost.com): Debug: Quota rule: root=user mailbox=*
bytes=0 messages=0
lda(sa-training at localhost.com): Debug: Quota rule: root=user
mailbox=Trash bytes=+104857600 messages=0
lda(sa-training at localhost.com): Debug: Quota rule: root=user
mailbox=Junk ignored
lda(sa-training at localhost.com): Debug: Quota rule: root=user
mailbox=INBOX bytes=+104857600 messages=0
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (100%)
messages=0 reverse=no command=quota-reached 100
sa-training at localhost.com localhost.com
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (95%)
messages=0 reverse=no command=quota-warning 95 sa-training at localhost.com
localhost.com
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (80%)
messages=0 reverse=no command=quota-warning 80 sa-training at localhost.com
localhost.com
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (100%)
messages=0 reverse=yes command=quota-below below
sa-training at localhost.com localhost.com
lda(sa-training at localhost.com): Debug: Quota grace: root=user bytes=0 (10%)
lda(sa-training at localhost.com): Debug: dict quota:
user=sa-training at localhost.com,
uri=file:/var/vmail/localhost.com/sa-training/.quotausage, noenforcing=0
lda(sa-training at 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 at localhost.com): Debug: Quota root: name=user
backend=dict args=:file:/var/vmail//raw mail user/.quotausage
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (100%)
messages=0 reverse=no command=quota-reached 100 raw mail user
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (95%)
messages=0 reverse=no command=quota-warning 95 raw mail user
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (80%)
messages=0 reverse=no command=quota-warning 80 raw mail user
lda(sa-training at localhost.com): Debug: Quota warning: bytes=0 (100%)
messages=0 reverse=yes command=quota-below below raw mail user
lda(sa-training at localhost.com): Debug: Quota grace: root=user bytes=0 (10%)
lda(sa-training at localhost.com): Debug: dict quota: user=raw mail user,
uri=file:/var/vmail//raw mail user/.quotausage, noenforcing=0
lda(sa-training at localhost.com): Debug: none: root=, index=, indexpvt=,
control=, inbox=, alt=
lda(sa-training at localhost.com): Debug: Destination address:
sa-training at localhost.com (source: user at hostname)
lda(sa-training at localhost.com): Debug: sieve: Pigeonhole version 0.4.2
initializing
lda(sa-training at localhost.com): Debug: sieve: include: sieve_global_dir
is not set; it is currently not possible to include `:global' scripts.
lda(sa-training at 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 at localhost.com): Debug: sieve: loading script
/var/vmail/localhost.com/sa-training/.sieve;name=main script
lda(sa-training at localhost.com): Debug: sieve: script binary
/var/vmail/localhost.com/sa-training/.sieve.svbin successfully loaded
lda(sa-training at 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 at localhost.com): Debug: sieve: executing script from
/var/vmail/localhost.com/sa-training/.sieve.svbin
lda(sa-training at localhost.com): sieve:
msgid=<20141003110532.045EE6060D at 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