Sieve script replication glitches

Wed Dec 9 15:12:54 UTC 2015

Hi,

I'm running a replicated setup on Debian with Dovecot 2.2.18 and 
Pigeonhole 0.4.8 and run into some glitches with sieve script syncing.  
Replication is implemented via DSync/doveadm over SSL.

While e-mail replication works as expected, sieve script replication is 
not always successful. In general I have observed the following 
behaviour re. sieve script replication:

 - Sometimes sieve scripts are replicated but have an mtime of 0 (Jan 1 
   1970) on the destination.

 - Subsequent updates to these "bad" scripts are not replicated at all.

 - Sometimes after creating *another* sieve script (which may or may not 
   get the correct timestamp), the "bad" script's timestamp/contents are 
   corrected on the receiving side.

The following is a minimal real-world example of what happens (including
transaction log entries):

1. On the master create a new sieve script:
    cat test.sieve | doveadm sieve put -u user at example.com test1

   Sieve storage on the master:
    -rw------- 1 vmail vmail 2001 Dec  9 15:53 test1.sieve

   Transaction log on the master:
    record: offset=44756, type=attribute-update (ext), size=72, modseq=514
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test1 : timestamp=2015-12-09 15:53:28 value_len=0
    record: offset=44828, type=modseq-update (ext), size=20
     - uid=0 modseq=723

   Sieve storage on the slave:
    -rw------- 1 vmail vmail 2001 Jan  1  1970 test1.sieve

   Transaction log on the slave:
    record: offset=55356, type=attribute-update (ext), size=72, modseq=597
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test1 : timestamp=2015-12-09 15:53:29 value_len=0
    record: offset=55428, type=attribute-update (sync), size=72, modseq=598
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test1 : timestamp=2015-12-09 15:53:29 value_len=0

2. Create a new script on the master:
    cat test.sieve | doveadm sieve put -u user at example.com test2

   Sieve storage on the master:
    -rw------- 1 vmail vmail 2001 Dec  9 15:53 test1.sieve
    -rw------- 1 vmail vmail 2001 Dec  9 15:57 test2.sieve

   Transaction log on the master:
    record: offset=44848, type=attribute-update (ext), size=72, modseq=515
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test2 : timestamp=2015-12-09 15:57:14 value_len=0
    record: offset=44920, type=modseq-update (ext), size=20
     - uid=0 modseq=725
    record: offset=44940, type=modseq-update (ext), size=20
     - uid=0 modseq=728

   Sieve storage on the slave:
    -rw------- 1 vmail vmail 2001 Dec  9 15:53 test1.sieve
    -rw------- 1 vmail vmail 2001 Dec  9 15:57 test2.sieve

   Transaction log on the slave:
    record: offset=55500, type=attribute-update (ext), size=72, modseq=599
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test2 : timestamp=2015-12-09 15:57:14 value_len=0
    record: offset=55572, type=attribute-update (sync), size=72, modseq=600
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test2 : timestamp=2015-12-09 15:57:14 value_len=0
    record: offset=55644, type=attribute-update (ext), size=72, modseq=601
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test1 : timestamp=2015-12-09 15:57:14 value_len=0
    record: offset=55716, type=attribute-update (ext), size=72, modseq=602
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test2 : timestamp=2015-12-09 15:57:14 value_len=0
    record: offset=55788, type=attribute-update (sync), size=132, modseq=603
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test1 : timestamp=2015-12-09 15:53:28 value_len=0
     - add: private/vendor/vendor.dovecot/pvt/server/sieve/files/test2 : timestamp=2015-12-09 15:57:14 value_len=0

Apparently something gets messed up on the receiving side and strange 
things appear in the transaction log (e.g. test1 with a timestamp of 
15:57:14 which it never had). The fact that it happens sometimes (around 
30-40% of the time) likely indicates a race condition somewhere.  Also 
I'm not at all sure sieve transactions should appear twice on the 
receiving side (ext and then sync); I see other entries (e.g.  
ext-intro) as a single "(ext) (sync)" record.

Any ideas?

Thanks,
Apollon

doveconf -n output follows:

# 2.2.18: /etc/dovecot/dovecot.conf
# Pigeonhole version 0.4.8 (0c4ae064f307+)
# OS: Linux 3.16.0-4-amd64 x86_64 Debian 8.2 
auth_mechanisms = plain login
default_vsz_limit = 320 M
mail_location = mdbox:~/mdbox:ALT=/srv/mail/alt/%d/%n
mail_plugins = " acl notify replication acl"
managesieve_notify_capability = mailto
managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date index ihave duplicate
namespace {
  location = maildir:/home/vmail/example.com/staging/Maildir:INDEX=/home/vmail/%d/%n/staging at example.com
  prefix = Staging.
  subscriptions = no
  type = public
}
namespace inbox {
  inbox = yes
  location = 
  mailbox Drafts {
    special_use = \Drafts
  }
  mailbox Junk {
    special_use = \Junk
  }
  mailbox Sent {
    special_use = \Sent
  }
  mailbox "Sent Messages" {
    special_use = \Sent
  }
  mailbox Trash {
    special_use = \Trash
  }
  prefix = 
  separator = .
  type = private
}
passdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
plugin {
  acl = vfile
  sieve = ~/.dovecot.sieve
  sieve_before = /home/vmail/global.sieve
  sieve_default = /home/vmail/global.sieve
  sieve_dir = ~/sieve
}
protocols = " imap sieve"
service aggregator {
  fifo_listener replication-notify-fifo {
    user = vmail
  }
  unix_listener replication-notify {
    user = vmail
  }
}
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener auth-userdb {
    group = vmail
    mode = 0777
  }
}
service doveadm {
  inet_listener {
    port = 12345
    ssl = yes
  }
  vsz_limit = 1 G
}
service imap-login {
  process_limit = 500
  process_min_avail = 5
}
service imap-postlogin {
  executable = script-login /usr/local/sbin/ldap-postlogin
  user = $default_internal_user
}
service imap {
  executable = imap imap-postlogin
  process_limit = 1024
}
service replicator {
  process_min_avail = 1
  unix_listener replicator-doveadm {
    mode = 0600
    user = vmail
  }
}
ssl_cert = </etc/ssl/certs/dovecot.crt
ssl_client_ca_dir = /etc/ssl/certs
ssl_key = </etc/ssl/private/dovecot.key
userdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocol lda {
  log_path = /var/log/dovecot/deliver.log
  mail_plugins = sieve replication notify
}
protocol imap {
  mail_max_userip_connections = 500
}