[Dovecot] 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
It is probably a good idea to figure out the underlying problem instead of ignoring it.
I use the following patch...
H
Harlan Stenn wrote:
It is probably a good idea to figure out the underlying problem instead of ignoring it.
I use the following patch...
Oh, I agree.
The extra logging only produced these extra lines in the logs:
Jun 13 15:35:18 stelleri imap: antispam: mailbox_is_unsure(SPAM): 0 Jun 13 15:35:18 stelleri imap: antispam: mailbox_is_trash(INBOX): 0 Jun 13 15:35:18 stelleri imap: antispam: mailbox_is_trash(SPAM): 0 Jun 13 15:35:18 stelleri imap: antispam: mail copy: from trash: 0, to trash: 0 Jun 13 15:35:18 stelleri imap: antispam: mailbox_is_spam(INBOX): 0 Jun 13 15:35:18 stelleri imap: antispam: mailbox_is_spam(SPAM): 1 Jun 13 15:35:18 stelleri imap: antispam: mailbox_is_unsure(INBOX): 0 Jun 13 15:35:18 stelleri imap: antispam: mail copy: src spam: 0, dst spam: 1, src unsure: 0 Jun 13 15:35:18 stelleri imap: antispam: /usr/local/bin/dspam --source=error --class=spam --signature=4a339984859385209328925 --deliver= --user frysco 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 > 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 >
Could the plugin be getting hung up on the 'verbose debug' messages that dspam seems to be insistent upon producing? (I'm not sure how to disable the writing to sql.errors)
Thanks, -jcd
Marcin Rzepecki wrote:
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.
This did suppress the error and the move to the 'spam' mailbox succeeded.
Though, it would be good to know why it trips over.
Thanks, -jcd
Note that according to dspam-exec.c, and info sent to stderr by dspam is treated by the antispam plugin as a fatal error.
All my patch does is to provide enough information to see what the problem is.
H
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
- exits with exit code 0
- 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
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
- exits with exit code 0
- 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
On Mon, 2009-06-15 at 13:27 -0700, Jeremy Doran wrote:
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.
Ok.
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.
Well, that's not trivial. I guess if dspam has now been fixed to always exit with a non-zero exit code we could remove the stderr checking code, or make it depend on a configuration option. But as it was when I wrote the code, dspam was broken enough for this to be absolutely necessary.
johannes
participants (4)
-
Harlan Stenn
-
Jeremy Doran
-
Johannes Berg
-
Marcin Rzepecki