Sieve-test working but actual filter is just working sometimes with dovecot

dovecotsieve

i just migrated from an old Ubuntu 10.4 VPS to a shiny new Ubuntu 14.04.

After a little work i got everything running besides dovecot with sieve.

This question is about sieve filtering messages delivered to dovecot via exim

Expected behavior:
Exim gets a mail spam-checks it, and delivers it to dovecot via /var/run/dovecot/deliver…
Dovecot then applies the sieve filtering rules on that message and sieves stores the mail into the appropriate folder, defined by the filtering script.

Actual behavior:
Exim delivers the mail to dovecot…. The sieve filter is applied to the mail

Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:global' scripts.
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: using the following location for user's Sieve script: /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: loading script /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: script binary /var/mail/timmeey/sieve/.dovecot.svbin successfully loaded
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: binary save: not saving binary /var/mail/timmeey/sieve/.dovecot.svbin, because it is already stored
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): Debug: sieve: executing script from /var/mail/timmeey/sieve/.dovecot.svbin
Sep 25 18:41:57 myHostxxx dovecot: lda(timmeey): sieve: msgid=<CAPCXxMrefumm9oXpt9hOWVMRj1=2zS0-T9sCMEFK=JBSWSwcCg@xxxxxxx.xx>: stored mail into mailbox 'INBOX'

but in the end it seems like it is ignoring my rules and just stores the message into the inbox.
BUT sometimes it applies a filter and the message is stored into the appropriate folder. but until now, i did not find a deterministic rule for when it worked and when not.

Normally i would think maybe my rules are broken.
But when i test the filters with sieve-test

sieve-test  /var/mail/timmeey/sieve/.dovecot.sieve ./mail1 -D
sieve-test(timmeey): Debug: Effective uid=1000, gid=1000, home=/home/timmeey
sieve-test(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
sieve-test(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently    not possible to include `:global' scripts.
debug: script binary /var/mail/timmeey/sieve/.dovecot.svbin successfully loaded.
debug: binary save: not saving binary /var/mail/timmeey/sieve/.dovecot.svbin, because it is already stored.
sieve-test(timmeey): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt=
Performed actions: 
* store message in folder: pool/wichtig
Implicit keep:
(none)
sieve-test(timmeey): Info: final result: success

the test says everything is okay. (i copied the source of the mail from thunderbird into the textfile "mail1"

Here an example of when it worked

Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:gl
obal' scripts.
Sep 25 18:24:41 h2339537 dovecot: lda(timmeey): Debug: sieve: using the following location for user's Sieve script: /var/mail/timmeey/sieve/.dov
ecot.sieve;name=main script
Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): Debug: sieve: loading script /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): Debug: sieve: script binary /var/mail/timmeey/sieve/.dovecot.svbin successfully loaded
Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): Debug: sieve: binary save: not saving binary /var/mail/timmeey/sieve/.dovecot.svbin, because it 
is already stored
Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): Debug: sieve: executing script from /var/mail/timmeey/sieve/.dovecot.svbin
Sep 25 18:24:41 myHostxxx dovecot: lda(timmeey): sieve: msgid=<542441A1.9080009@owncloud.com>: stored mail into mailbox 'listen/owncloud-user'

Dovecot 2.2.9
Ubuntu 14.04

I'm really out of ideas here…
On my old VPS everything worked fine.
I even rebooted the server…

Thanks in advance.

EDIT:
This will get quite verbose, sorry.

Here at first the header on which the filter should trigger. (I removed all the other noise from the mail, and obviously removed some personal information because i already get enough spam 😛 But this should not affect the filters

NOT WORKING MAIL

So the first mail triggers the filter when i run test-sieve on it. It would store it into 'pool/wichtig'

Return-path: <myAccount@campus.tu-berlin.de>
Envelope-to: pool@myServer.de
Delivery-date: Sat, 27 Sep 2014 01:46:12 +0200
[...]


> $ sieve-test  /var/mail/timmeey/sieve/.dovecot.sieve ./poolMail -D -t -Tlevel=tests                                                                                                                       
sieve-test(timmeey): Debug: Effective uid=1000, gid=1000, home=/home/timmeey
sieve-test(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
sieve-test(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:global' scripts.
debug: script binary /var/mail/timmeey/sieve/.dovecot.svbin successfully loaded.
debug: binary save: not saving binary /var/mail/timmeey/sieve/.dovecot.svbin, because it is already stored.
sieve-test(timmeey): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt=

Performed actions:

 * store message in folder: pool/wichtig

Implicit keep:

  (none)

sieve-test(timmeey): Info: final result: success

And here we have the logoutput from when i actually received the mail. It didn't trigger for whatever reason. (The filter is set right

lrwxrwxrwx 1 timmeey timmeey   21 Sep 27 01:45 .dovecot.sieve -> serverFaultTest.sieve

)

Sep 27 01:46:12 h6666666 dovecot: lda: Debug: Loading modules from directory: /usr/lib/dovecot/modules
Sep 27 01:46:12 h6666666 dovecot: lda: Debug: Module loaded: /usr/lib/dovecot/modules/lib90_sieve_plugin.so 
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: Effective uid=1000, gid=1000, home=/home/timmeey
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: mbox: INBOX defaulted to /var/mail/timmeey/timmeey/inbox
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: fs: root=/var/mail/timmeey/timmeey, index=, indexpvt=, control=, inbox=/var/mail/timmeey/timmeey/inbox, alt=
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: userdb lookup skipped, username taken from USER environment
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt=
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: Destination address: timmeey@h6666666.stratoserver.net (source: user@hostname) 
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:global' scripts.
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: using the following location for user's Sieve script: /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: loading script /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: script binary /var/mail/timmeey/sieve/.dovecot.svbin is not up-to-date
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: script `main script' from /var/mail/timmeey/sieve/.dovecot.sieve;name=main script successfully compiled
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): Debug: sieve: executing script from /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 27 01:46:12 h6666666 dovecot: lda(timmeey): sieve: msgid=<5425FAAE.2040001@campus.tu-berlin.de>: stored mail into mailbox 'INBOX'

MAIL THAT DID WORK

AND here we have a facebook mail which worked and triggered the filter while testing AND when i received the actual mail

Return-path: <xxx@xxx>
Envelope-to: gmx@myServer.de
Delivery-date: Fri, 26 Sep 2014 20:52:30 +0200
Received: from facebook.com (ugG7XsRqKzRYl9dQStMUIo10vkuNI1jSm7GtZghIpww+XBdr3TIkc02H/roiAJF9 10.158.104.67)
 by facebook.com with Thrift id 3bd81b8845ae11e483660002c9550d78-92fed3e0;
 Fri, 26 Sep 2014 11:52:15 -0700
X-Facebook: from 10.88.41.65 ([MTI3LjAuMC4x]) 
    by async.facebook.com with HTTP (ZuckMail);
Date: Fri, 26 Sep 2014 11:52:15 -0700
To: Kurdistan Charity Minigolf-Turnier im Bunker <xxx@xxx>
From: "XXXX XXXXX" <notification+zj4ocz0csf2c@facebookmail.com>
Reply-to: Reply to comment <g+40tymmuw000zg3h03tug003o44m2mbkn000000gpc3xb2qd46@groups.facebook.com>    





> $ sieve-test  /var/mail/timmeey/sieve/.dovecot.sieve ./facebookMail -D -t -Tlevel=tests                                                                                                                   
sieve-test(timmeey): Debug: Effective uid=1000, gid=1000, home=/home/timmeey
sieve-test(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
sieve-test(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:global' scripts.
debug: script binary /var/mail/timmeey/sieve/.dovecot.svbin successfully loaded.
debug: binary save: not saving binary /var/mail/timmeey/sieve/.dovecot.svbin, because it is already stored.
sieve-test(timmeey): Debug: none: root=, index=, indexpvt=, control=, inbox=, alt=

Performed actions:

 * store message in folder: facebook

Implicit keep:

  (none)

sieve-test(timmeey): Info: final result: success

See? This mail triggerd while TESTING

Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: Pigeonhole version 0.4.2 initializing
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: include: sieve_global_dir is not set; it is currently not possible to include `:global' scripts.
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: using the following location for user's Sieve script: /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: loading script /var/mail/timmeey/sieve/.dovecot.sieve;name=main script
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: script binary /var/mail/timmeey/sieve/.dovecot.svbin successfully loaded
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: binary save: not saving binary /var/mail/timmeey/sieve/.dovecot.svbin, because it is already stored
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): Debug: sieve: executing script from /var/mail/timmeey/sieve/.dovecot.svbin
Sep 26 20:52:30 h6666666 dovecot: lda(timmeey): sieve: msgid=<72dc28622cc1889240a83228bd509830@async.facebook.com>: stored mail into mailbox 'facebook'

AND it triggered while receiving the actual mail (stored it into 'facebook'

And here we have the test filter

require ["fileinto","envelope"];    

if address :domain :contains ["From"] "facebookmail.com"
    {
        fileinto "facebook";
    }    

if envelope :contains ["To"] "pool@myServer.de"
    {
        fileinto "pool/wichtig";
        stop;

    }

EDIT 2:
I guess i found a rule here.
When i check for addresses like

address :contains ["To"] "timmeey@someOtherServer.de"

it works while testing AND with actual mails.

But testing for some envelope condition

envelope :contains ["To"] "pool@myServer.de"

it just works while sieve-test but not with actual mail.

I have no idea why. This is still unsolved, but i may found a way to build around this.
Does anybody use the envelope contetn for filtering?
Is it just broken?

Best Answer

I've seen the same thing. I was using envelope :contains "To" and it matched using sieve-test but not live. If I change it to address :contains "To" as you suggest, it works live too. This looks like a sieve bug.

Related Topic