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(a)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(a)mydomain.example>, method=PLAIN, rip=<redacted>, lip=<redacted>, mpid=35651, TLS, session=<Qw4fYiet/uEKKCgK>
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Loading modules from directory: /usr/lib/dovecot/modules
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)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(a)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(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: Effective uid=113, gid=122, home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)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(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: fs: root=/var/vmail/user(a)mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: Pigeonhole version 0.5.4 () initializing
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)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(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using active Sieve script path: /var/vmail/user(a)mydomain.example/.sieve
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using script storage path: /var/vmail/user(a)mydomain.example/sieve
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using permissions from /var/vmail/user(a)mydomain.example/sieve: mode=0700 gid=-1
Aug 18 16:05:49 serverA dovecot[60776]: managesieve(user(a)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(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: sync: Synchronization active
Aug 18 16:05:54 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using Sieve script path: /var/vmail/user@mydomain.example/sieve/tmp/lists_1597759554.M792097P35651.serverA.mydomain.example.sieve
Aug 18 16:05:54 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file script: Opened script `lists' from `/var/vmail/user@mydomain.example/sieve/tmp/lists_1597759554.M792097P35651.serverA.mydomain.example.sieve'
Aug 18 16:05:54 serverA dovecot[60776]: managesieve(user(a)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(a)mydomain.example): Debug: auth PASS input: user=user(a)mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)mydomain.example)<35652><>: Debug: auth USER input: user(a)mydomain.example uid=113 gid=122 home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: remote(serverB.mydomain.example): auth PASS input: user=user(a)mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: remote(serverB.mydomain.example): auth USER input: user(a)mydomain.example uid=113 gid=122 home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: remote(serverB.mydomain.example): Effective uid=113, gid=122, home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)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(a)mydomain.example): Debug: remote(serverB.mydomain.example): fs: root=/var/vmail/user(a)mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: Effective uid=113, gid=122, home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)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(a)mydomain.example): Debug: fs: root=/var/vmail/user(a)mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:55 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: Namespace : Using permissions from /var/vmail/user(a)mydomain.example/mail: mode=0700 gid=default
Aug 18 16:05:58 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file storage: Using Sieve script path: /var/vmail/user@mydomain.example/sieve/tmp/autosave_1597759558.M923011P35651.serverA.mydomain.example.sieve
Aug 18 16:05:58 serverA dovecot[60776]: managesieve(user(a)mydomain.example)<35651><Qw4fYiet/uEKKCgK>: Debug: sieve: file script: Opened script `autosave' from `/var/vmail/user@mydomain.example/sieve/tmp/autosave_1597759558.M923011P35651.serverA.mydomain.example.sieve'
Aug 18 16:05:58 serverA dovecot[60776]: managesieve(user(a)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(a)mydomain.example): Debug: auth PASS input: user=user(a)mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)mydomain.example)<35653><>: Debug: auth USER input: user(a)mydomain.example uid=113 gid=122 home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: remote(serverB.mydomain.example): auth PASS input: user=user(a)mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: remote(serverB.mydomain.example): auth USER input: user(a)mydomain.example uid=113 gid=122 home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: remote(serverB.mydomain.example): Effective uid=113, gid=122, home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)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(a)mydomain.example): Debug: remote(serverB.mydomain.example): fs: root=/var/vmail/user(a)mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: Effective uid=113, gid=122, home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)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(a)mydomain.example): Debug: fs: root=/var/vmail/user(a)mydomain.example/mail, index=, indexpvt=, control=, inbox=, alt=
Aug 18 16:05:59 serverA dovecot[60776]: doveadm(user(a)mydomain.example): Debug: Namespace : Using permissions from /var/vmail/user(a)mydomain.example/mail: mode=0700 gid=default
Aug 18 16:06:00 serverA dovecot[60776]: managesieve(user(a)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(a)mydomain.example
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: auth USER input: user(a)mydomain.example uid=113 gid=122 home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:55 serverB dovecot[30215]: doveadm: Debug: Effective uid=113, gid=122, home=/var/vmail/user(a)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(a)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(a)mydomain.example/mail: mode=0700 gid=default
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: auth PASS input: user=user(a)mydomain.example
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: auth USER input: user(a)mydomain.example uid=113 gid=122 home=/var/vmail/user(a)mydomain.example
Aug 18 16:05:59 serverB dovecot[30215]: doveadm: Debug: Effective uid=113, gid=122, home=/var/vmail/user(a)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(a)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(a)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(a)lastname.net