dovecot - Jun 2009 - dovecot-antispam plugin and "Failed to call dspam" message

Hi,

I had this working until I recently upgraded Dovecot, and now I'm getting a
message back from
Thunderbird of "Failed to call dspam." when I attempt to move a
message into one of the designated
spam folders.

However, I know from looking at the dspam system.log file, the retraining
actually happens - so it
-does- appear to be calling dspam. It appears that the 'move' operation
fails.

Here's my configuration:
  dovecot 1.1.16 (built from ports)
  dovecot-antispam 1.1  (tried from ports as well as unmodified source)
  dspam 3.6.8 (built from ports)
  FreeBSD 7.1

Relevant sections from dovecot.conf:

protocol imap {
  mail_plugins = antispam
  mail_plugin_dir = /usr/local/lib/dovecot/imap
  ...
}

plugin {
  antispam_signature = X-DSPAM-Signature
  antispam_spam = SPAM;spam;Junk
  antispam_trash = Deleted Messages;Trash;INBOX.Trash
  antispam_dspam_binary = /usr/local/bin/dspam
  antispam_dspam_args = --deliver=;--user;%u
  ...
}

.config used by dovecot-antispam:
DOVECOT=/usr/ports/mail/dovecot/work/dovecot-1.1.16
BACKEND=dspam-exec
PLUGINNAME=antispam
DEBUG=syslog
DEBUG_VERBOSE=1

(I've tried it both with and without the DEBUG lines present in .config)

Plugin debug log when I attempt to move a message:
Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_unsure(SPAM): 0
Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_trash(INBOX): 0
Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_trash(SPAM): 0
Jun 13 09:29:07 stelleri imap: antispam: mail copy: from trash: 0, to trash: 0
Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_spam(INBOX): 0
Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_spam(SPAM): 1
Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_unsure(INBOX): 0
Jun 13 09:29:07 stelleri imap: antispam: mail copy: src spam: 0, dst spam: 1,
src unsure: 0
Jun 13 09:29:07 stelleri imap: antispam: /usr/local/bin/dspam --source=error
--class=spam
--signature=4a339984859385209328925 --deliver= --user frysco

Associated log from dspam system.log:
1244903347      M       <None Specified>        4a339984859385209328925
<None Specified>
0.066815        frysco  Retrained


Any help appreciated,

Thanks,
-jcd

Sat, Jun 13, 2009 at 07:34:49AM -0700, Jeremy Doran
wrote:
> Hi,
> 
> I had this working until I recently upgraded Dovecot, and now I'm
getting a message back from
> Thunderbird of "Failed to call dspam." when I attempt to move a
message into one of the designated
> spam folders.
>
> However, I know from looking at the dspam system.log file, the retraining
actually happens - so it
> -does- appear to be calling dspam. It appears that the 'move'
operation fails.
> [...]
Hi Jeremy,
i've tried to figure it out some time ago. As you mentioned, dspam is
called ok, however error is still reported.
I'm applying following patch to avoid reporting error and all is working
great for me. I'm using dspam-devel version, but it should not make no
difference.

#v+
--- dspam-exec.c.orig	2008-11-11 16:02:20.000000000 +0100
+++ dspam-exec.c	2008-11-11 16:02:30.000000000 +0100
@@ -178,13 +178,14 @@
 	int ret = 0;
 
 	while (item) {
-		if (call_dspam(item->sig, item->wanted)) {
+	/*	if (call_dspam(item->sig, item->wanted)) {
 			ret = -1;
 			mail_storage_set_error(ctx->box->storage,
 					       ME(NOTPOSSIBLE)
 					       "Failed to call dspam");
 			break;
-		}
+		} */
+		call_dspam(item->sig, item->wanted);
 		item = item->next;
 	}
 
#v-

Cheers,

-- 
Marcin Rzepecki
m.rzepecki(at)iem.pw.edu.pl

Hi,
> However, I know from looking at the dspam system.log file, the retraining
actually happens - so it
> -does- appear to be calling dspam. It appears that the 'move'
operation fails.
> Plugin debug log when I attempt to move a message:
> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_unsure(SPAM): 0
> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_trash(INBOX): 0
> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_trash(SPAM): 0
> Jun 13 09:29:07 stelleri imap: antispam: mail copy: from trash: 0, to
trash: 0
> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_spam(INBOX): 0
> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_spam(SPAM): 1
> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_unsure(INBOX): 0
> Jun 13 09:29:07 stelleri imap: antispam: mail copy: src spam: 0, dst spam:
1, src unsure: 0
> Jun 13 09:29:07 stelleri imap: antispam: /usr/local/bin/dspam
--source=error --class=spam
> --signature=4a339984859385209328925 --deliver= --user frysco
> 
> Associated log from dspam system.log:
> 1244903347      M       <None Specified>       
4a339984859385209328925 <None Specified>
> 0.066815        frysco  Retrained
I have no idea what's going on, obviously, but please verify that the
above dspam command line
 1) exits with exit code 0
 2) doesn't print anything to stderr

Both of these are taken by the plugin as an indication that something
went wrong, because dspam's error reporting was _severely_ lacking at
the time I wrote the plugin. It might have improved in the meantime, I
have no idea.

johannes
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 801 bytes
Desc: This is a digitally signed message part
URL:
<http://dovecot.org/pipermail/dovecot/attachments/20090614/70303625/attachment-0002.bin>

Johannes Berg wrote:
> Hi,
> 
>> However, I know from looking at the dspam system.log file, the
retraining actually happens - so it
>> -does- appear to be calling dspam. It appears that the 'move'
operation fails.
> 
>> Plugin debug log when I attempt to move a message:
>> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_unsure(SPAM): 0
>> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_trash(INBOX): 0
>> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_trash(SPAM): 0
>> Jun 13 09:29:07 stelleri imap: antispam: mail copy: from trash: 0, to
trash: 0
>> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_spam(INBOX): 0
>> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_spam(SPAM): 1
>> Jun 13 09:29:07 stelleri imap: antispam: mailbox_is_unsure(INBOX): 0
>> Jun 13 09:29:07 stelleri imap: antispam: mail copy: src spam: 0, dst
spam: 1, src unsure: 0
>> Jun 13 09:29:07 stelleri imap: antispam: /usr/local/bin/dspam
--source=error --class=spam
>> --signature=4a339984859385209328925 --deliver= --user frysco
>>
>> Associated log from dspam system.log:
>> 1244903347      M       <None Specified>       
4a339984859385209328925 <None Specified>
>> 0.066815        frysco  Retrained
> 
> I have no idea what's going on, obviously, but please verify that the
> above dspam command line
>  1) exits with exit code 0
>  2) doesn't print anything to stderr
> 
> Both of these are taken by the plugin as an indication that something
> went wrong, because dspam's error reporting was _severely_ lacking at
> the time I wrote the plugin. It might have improved in the meantime, I
> have no idea.
It certainly seems to be the 'verbose debug' information that DSpam
prints to stderr that triggers this.

After testing with the patches from Marcin Rzepecki and Harlan Stenn, I
managed completely disabled these kind of lines from being sent:
> Jun 13 15:35:18 stelleri imap: antispam: error: dspam returned <57397:
[06/13/2009 15:35:18] query error: VERBOSE DEBUG (INFO ONLY - NOT AN ERROR): see
sql.errors for more details >
I then put in the unaltered FreeBSD ports version of the plugin, and no
longer got the "Failed to call dspam" messages.

Since these messages - even though non-zero and stating that they aren't
an error - are just informational, I'd think that it might be an idea to
have the plugin detect and ignore that.

Turning on DSpam debugging should not (I should think) break the plugin
from working.

Thanks,
-jcd