antispam plugin pipe script seems not to be called when it "should be"

Fri Aug 19 02:26:09 UTC 2016

Hello,

(Full "doveconf -n" output is at the end of this message.)

I'm attempting to recreate a "recipe" I had used successfully for quite
some time (in Ubuntu 12.04 LTS), which allowed me to train
SpamAssassin's Bayes database when someone dragged an email message from
one sub-folder of the account to another.

I later tried to re-implement it (in Ubuntu 14.04 LTS), and core-dumps
resulted. I posted to this list about it several times, but nobody was
ever able to help me solve the problem.

I just tried the same (in Ubuntu 16.04 LTS), hoping that the source had
evolved since then, and while I don't see a core-dump, the pipe script
doesn't seem to be called.

I've booby-trapped the pipe script with quite a bit of debugging output,
which should be written to a file, but I don't see any indication that
the pipe script is ever executed.

When logged-in as an IMAP user, and I drag a message from the user's
Inbox into the "Spam" folder, I do see the following activity in the syslog:

Aug 18 22:12:15 example.com imap: antispam: mailbox_is_unsure(Junk): 0
Aug 18 22:12:15 example.com imap: antispam: mailbox_is_trash(INBOX): 0
Aug 18 22:12:15 example.com imap: antispam: mailbox_is_trash(Junk): 0
Aug 18 22:12:15 example.com imap: antispam: mail copy: from trash: 0, to
trash: 0
Aug 18 22:12:15 example.com imap: antispam: mailbox_is_spam(INBOX): 0
Aug 18 22:12:15 example.com imap: antispam: mailbox_is_spam(Junk): 1
Aug 18 22:12:15 example.com imap: antispam: mailbox_is_unsure(INBOX): 0
Aug 18 22:12:15 example.com imap: antispam: mail copy: src spam: 0, dst
spam: 1, src unsure: 0
Aug 18 22:12:15 example.com imap: antispam: running mailtrain backend
program /bin/bash
Aug 18 22:12:15 example.com imap: antispam: running mailtrain backend
program /bin/bash
Aug 18 22:12:15 example.com imap: antispam: running mailtrain backend
program parameter 1 /usr/local/bin/sa-learn-pipe.sh
Aug 18 22:12:15 example.com imap: antispam: running mailtrain backend
program parameter 2 --spam

But the piped message is never delivered to the target mailbox.
The mail log at /var/log/mail.log does not register any activity when I
move messages (and maybe that's expected).

Here are the contents of the /usr/local/bin/sa-learn-pipe.sh script:

http://pastebin.com/7vm74jmk

The permissions and mode on the script seem appropriate:

$ stat /usr/local/bin/sa-learn-pipe.sh
  File: '/usr/local/bin/sa-learn-pipe.sh'
  Size: 1765            Blocks: 8          IO Block: 4096   regular file
Device: fd01h/64769d    Inode: 669345      Links: 1
Access: (0755/-rwxr-xr-x)  Uid: ( 5000/   vmail)   Gid: ( 5000/   vmail)
Access: 2016-08-18 19:09:47.307392919 -0400
Modify: 2016-08-18 19:09:31.231391749 -0400
Change: 2016-08-18 19:09:31.231391749 -0400
 Birth: -

What might I be doing incorrectly here?

Please let me know if I can provide any other information.

Thank you in advance,

-Ben

Full "doveconf -n" output:

$ doveconf -n
# 2.2.22 (fe789d2): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.13 (7b14904)
# OS: Linux 4.4.0-34-generic x86_64 Ubuntu 16.04.1 LTS
auth_mechanisms = plain login
disable_plaintext_auth = no
listen = *,[::]
log_timestamp = "%Y-%m-%d %H:%M:%S "
mail_max_userip_connections = 100
mail_plugins = " quota"
mail_privileged_group = vmail
passdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
plugin {
  antispam_backend = pipe
  antispam_debug_target = syslog
  antispam_pipe_program = /bin/bash
  antispam_pipe_program_args = /usr/local/bin/sa-learn-pipe.sh
  antispam_pipe_program_notspam_arg = --ham
  antispam_pipe_program_spam_arg = --spam
  antispam_pipe_tmpdir = /tmp
  antispam_spam_pattern_ignorecase = SPAM;JUNK
  antispam_trash_pattern_ignorecase = trash;Deleted *
  antispam_verbose_debug = 1
  quota = dict:user::file:/var/vmail/%d/%n/.quotausage
  quota_rule2 = Trash:storage=+100M
  quota_rule3 = Junk:ignore
  quota_rule4 = INBOX:storage=+100M
  quota_warning = storage=100%% quota-reached 100 %u %d
  quota_warning2 = storage=95%% quota-warning 95 %u %d
  quota_warning3 = storage=80%% quota-warning 80 %u %d
  quota_warning4 = -storage=100%% quota-below below %u %d
  sieve = /var/vmail/%d/%n/.sieve
  sieve_max_redirects = 25
}
postmaster_address = postmaster at example.com
protocols = imap pop3
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener auth-userdb {
    group = vmail
    mode = 0600
    user = vmail
  }
  user = root
}
service imap-login {
  client_limit = 1000
  process_limit = 512
}
service lmtp {
  unix_listener /var/spool/postfix/private/dovecot-lmtp {
    group = postfix
    mode = 0600
    user = postfix
  }
}
service quota-below {
  executable = script /usr/local/bin/quota-below.sh
  unix_listener quota-below {
    group = vmail
    mode = 0666
    user = vmail
  }
  user = vmail
}
service quota-reached {
  executable = script /usr/local/bin/quota-reached.sh
  unix_listener quota-reached {
    group = vmail
    mode = 0666
    user = vmail
  }
  user = vmail
}
service quota-warning {
  executable = script /usr/local/bin/quota-warning.sh
  unix_listener quota-warning {
    group = vmail
    mode = 0666
    user = vmail
  }
  user = vmail
}
ssl_cert = </etc/postfix/smtpd.cert
ssl_key = </etc/postfix/smtpd.key
ssl_protocols = !SSLv2 !SSLv3
userdb {
  driver = prefetch
}
userdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocol imap {
  mail_plugins = quota imap_quota antispam
}
protocol pop3 {
  mail_plugins = quota
  pop3_uidl_format = %08Xu%08Xv
}
protocol lda {
  mail_plugins = sieve quota
}
protocol lmtp {
  mail_plugins = quota sieve
  postmaster_address = webmaster at localhost
}