Sieve scripts replication not working

[Piotr Auksztulewicz]

Hi all!

I am a long-time dovecot user/admin on my home server, but only recently
tried to configure replication. Everything seems to work except sieve
scripts replication. When I upload new one on the server A, it does not
replicate to server B, even if it seemingly tries to, according to debug
logs. The log antry says: Replication requested by
'sieve_storage_sync_transaction_begin', priority=1 on server A, but
nothing like that on server B. Server B logs show that server A is
connecting to doveadm service but little else. Any ideas what could be
wrong?

Please see the logs below. Users and domains have been anonymized.

----- Upload -------------
$ sieve-connect -s serverA.mydomain.example -p sieve -u user at mydomain.example --notlsverify
Sieve/IMAP Password:
ReadLine support enabled.
> put lists
> put autosave

----- Server A log -------
Aug 18 16:05:49 serverA dovecot[60776]: managesieve-login: Login: user=<user at mydomain.example>, method=PLAIN, rip=<redacted>, lip=<redacted>, mpid=35651, TLS, session=<Qw4fYiet/uEKKCgK>
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Loading modules from directory: /usr/lib/dovecot/modules
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Module loaded: /usr/lib/dovecot/modules/lib15_notify_plugin.so
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Module loaded: /usr/lib/dovecot/modules/lib20_replication_plugin.so
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: Pigeonhole version 0.5.4 () initializing
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: include: sieve_global is not set; it is currently not possible to include `:global' scripts.
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using active Sieve script path: /var/vmail/user at mydomain.example/.sieve
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using script storage path: /var/vmail/user at mydomain.example/sieve
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using permissions from /var/vmail/user at mydomain.example/sieve: mode=0700 gid=-1
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Relative path to sieve storage in active link: sieve/
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: sync: Synchronization active
Aug 18 16:05:54 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using Sieve script path: /var/vmail/user at mydomain.example/sieve/tmp/lists_1597759554.M792097P35651.serverA.mydomain.example.sieve
Aug 18 16:05:54 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file script: Opened script `lists' from `/var/vmail/user at mydomain.example/sieve/tmp/lists_1597759554.M792097P35651.serverA.mydomain.example.sieve'
Aug 18 16:05:54 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: replication: Replication requested by 'sieve_storage_sync_transaction_begin', priority=1
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: auth PASS input: user=user at mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example)<35652><>: Debug: auth USER input: user at mydomain.example uid=113 gid=122 home=/var/vmail/user at mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): auth PASS input: user=user at mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): auth USER input: user at mydomain.example uid=113 gid=122 home=/var/vmail/user at mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: Namespace : Using permissions from /var/vmail/user at mydomain.example/mail: mode=0700 gid=default
Aug 18 16:05:58 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using Sieve script path: /var/vmail/user at mydomain.example/sieve/tmp/autosave_1597759558.M923011P35651.serverA.mydomain.example.sieve
Aug 18 16:05:58 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file script: Opened script `autosave' from `/var/vmail/user at mydomain.example/sieve/tmp/autosave_1597759558.M923011P35651.serverA.mydomain.example.sieve'
Aug 18 16:05:58 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: replication: Replication requested by 'sieve_storage_sync_transaction_begin', priority=1
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: auth PASS input: user=user at mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example)<35653><>: Debug: auth USER input: user at mydomain.example uid=113 gid=122 home=/var/vmail/user at mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): auth PASS input: user=user at mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): auth USER input: user at mydomain.example uid=113 gid=122 home=/var/vmail/user at mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: remote(serverB.mydomain.example): fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user at mydomain.example): Debug: Namespace : Using permissions from /var/vmail/user at mydomain.example/mail: mode=0700 gid=default
Aug 18 16:06:00 serverA dovecot[60776]: managesieve(user at mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Disconnected: Logged out bytes=3748/95

----- Server B log -------
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: auth PASS input: user=user at mydomain.example
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: auth USER input: user at mydomain.example uid=113 gid=122 home=/var/vmail/user at mydomain.example
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: Namespace : Using permissions from /var/vmail/user at mydomain.example/mail: mode=0700 gid=default
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: auth PASS input: user=user at mydomain.example
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: auth USER input: user at mydomain.example uid=113 gid=122 home=/var/vmail/user at mydomain.example
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: Effective uid=113, gid=122, home=/var/vmail/user at mydomain.example
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: Namespace inbox: type=private, prefix=, sep=, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: fs: root=/var/vmail/user at mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: Namespace : Using permissions from /var/vmail/user at mydomain.example/mail: mode=0700 gid=default

----- doveconf -n -------
# 2.3.4.1 (f79e8e7e4): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.4 ()
# OS: Linux 4.19.0-8-amd64 x86_64 Debian 10.4
# Hostname: serverA.mydomain.example
auth_failure_delay = 3 secs
auth_verbose = yes
auth_worker_max_count = 5
deliver_log_format = msgid=%m; from=%f: %$
disable_plaintext_auth = no
doveadm_password = # hidden, use -P to show it
doveadm_port = 4551
first_valid_uid = 100
login_greeting = <redacted>
mail_attribute_dict = file:mail/dovecot-attributes
mail_debug = yes
mail_location = maildir:~/mail:LAYOUT=fs:DIRNAME=.MailDir:UTF-8
mail_plugins = " notify replication"
mail_privileged_group = vmail
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 mime foreverypart extracttext editheader vnd.dovecot.debug
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 =
}
passdb {
  args = /etc/dovecot/dovecot-sql.conf.ext.local
  driver = sql
}
plugin {
  mail_replica = tcp:serverB.mydomain.example
  sieve = ~/.sieve
  sieve_dir = ~/sieve
  sieve_extensions = +vnd.dovecot.debug +editheader
  sieve_user_log = ~/log/sieve.log
}
pop3_fast_size_lookups = yes
pop3_lock_session = yes
pop3_no_flag_updates = yes
pop3_save_uidl = yes
protocols = " imap lmtp sieve pop3"
replication_max_conns = 5
service aggregator {
  fifo_listener replication-notify-fifo {
    group = root
    mode = 0660
    user = vmail
  }
  unix_listener replication-notify {
    group = root
    mode = 0660
    user = vmail
  }
}
service auth-worker {
  chroot = /etc/dovecot/db
  process_limit = 10
  unix_listener auth-worker {
    mode = 0600
    user = doveauth
  }
  user = doveauth
}
service auth {
  client_limit = 64
  inet_listener sasl {
    address = serverA.mydomain.example
    port = 9192
  }
  unix_listener auth-userdb {
    group = vmail
    mode = 0660
    user = doveauth
  }
  user = doveauth
}
service dict-async {
  protocol = none
}
service dict {
  protocol = none
}
service director {
  protocol = none
}
service doveadm {
  inet_listener doveadm {
    address = serverA.mydomain.example
    port = 4551
  }
}
service imap-hibernate {
  protocol = none
}
service imap-login {
  inet_listener imap {
    address = serverA.mydomain.example
    port = 143
  }
  process_limit = 25
  service_count = 1
}
service imap-urlauth-login {
  protocol = none
}
service imap-urlauth-worker {
  protocol = none
}
service imap-urlauth {
  protocol = none
}
service imap {
  chroot = /var/vmail
  client_limit = 15
  process_limit = 25
  service_count = 32
  user = vmail
}
service indexer-worker {
  process_limit = 3
  user = vmail
}
service indexer {
  chroot = $base_dir
}
service lmtp {
  client_limit = 1
  extra_groups =
  group = vmail
  inet_listener lmtp {
    address = serverA.mydomain.example
    port = 2306
  }
  process_limit = 5
  user = vmail
}
service log {
  user = $default_internal_user
}
service managesieve-login {
  inet_listener sieve {
    address = serverA.mydomain.example
    port = 4190
  }
  process_limit = 3
  service_count = 1
}
service managesieve {
  chroot = /var/vmail
  process_limit = 3
  service_count = 1
  user = vmail
}
service pop3-login {
  inet_listener pop3 {
    port = 0
  }
  process_limit = 3
  service_count = 1
}
service pop3 {
  chroot = /var/vmail
  process_limit = 3
  service_count = 1
  user = vmail
}
service replicator {
  unix_listener replicator-doveadm {
    group = root
    mode = 0600
    user = vmail
  }
}
service submission-login {
  protocol = none
}
service tcpwrap {
  protocol = none
}
ssl_cert = </etc/dovecot/private/dovecot.pem
ssl_client_ca_dir = /etc/ssl/certs
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
userdb {
  args = /etc/dovecot/dovecot-sql.conf.ext.local
  driver = sql
}
valid_chroot_dirs = /var/vmail /etc/dovecot/db
verbose_proctitle = yes
protocol lmtp {
  mail_plugins = " notify replication sieve"
}
protocol imap {
  imap_metadata = yes
}

-- 
Piotr "Malgond" Auksztulewicz                     firstname at lastname.net