Ben Johnson
2014-Oct-06 17:09 UTC
How best to confirm that dovecot LDA logging is working correctly?
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, altlda(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=, altlda(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
Seemingly Similar Threads
- antispam plugin pipe script seems not to be called when it "should be"
- Problems with dovecot 2.1.7, spamassassin 3.3.2 and antispam plugin
- plugin antispam sa-learn run program failed with exit code -1
- Need a bit of help with the antispam plugin
- Need a bit of help with the antispam plugin