doveadm backup -R -m -s not picking up a new message
Daniel Shahaf
danielsh at apache.org
Thu Feb 6 05:37:08 EET 2020
Good morning,
I use «doveadm backup -R -m foo -s $state» to create a local mirror of
an imapc remote folder. When I run that command, wait for it to finish,
deliver a new message to the remote folder, and run that command again,
the new message does not get downloaded from the remote.
I'll attach the rawlog, doveconf, etc at the end. Allow me first to
summarize what I've already checked:
- I used «openssl s_client» to issue EXAMINE on the remote mailbox
before and after delivering a mail to the remote mailbox, and
HIGHESTMODSEQ does increase.
- I looked at rawlog for both runs. doveadm issues a «STATUS foo
(UIDNEXT UIDVALIDITY)» and receives a correct response (UIDNEXT in the
second run is one larger than in the first run).
- Other than that STATUS command, doveadm only issues LOGIN, LOGOUT,
LIST, and LSUB commands. The remote server's responses do not report
the new HIGHESTMODSEQ value for the folder.
- The message does get mirrored locally when I run without the -s flag.
I'm running dovecot 2.3.9.2 from FreeBSD ports. I've reviewed the
FreeBSD port¹; it does have some patches, but none of them seem relevant
to this issue.
The remote server runs Cyrus.
Debug output, etc follow:
[[[
% doveconf -n
# 2.3.9.2 (cf2918cac): /usr/local/etc/dovecot/dovecot.conf
# OS: FreeBSD 12.1-RELEASE amd64
# Hostname: imapmirror.v.shahaf.local2
disable_plaintext_auth = no
first_valid_uid = 1000
imapc_features = " rfc822.size fetch-headers modseq"
imapc_host = imap.fastmail.com
imapc_password = # hidden, use -P to show it
imapc_port = 993
imapc_ssl = imaps
imapc_user = ...
last_valid_uid = 65500
mail_location = maildir:~/Maildir:UTF-8
mail_prefetch_count = 99
namespace {
inbox = yes
location =
prefix =
separator = /
}
passdb {
driver = pam
}
protocols = imap lmtp
service imap {
drop_priv_before_exec = yes
}
service lmtp {
unix_listener /var/spool/postfix/private/dovecot-lmtp {
group = postfix
mode = 0600
user = postfix
}
}
ssl_cert = </usr/local/etc/dovecot/cert.pem
ssl_key = # hidden, use -P to show it
userdb {
driver = passwd
}
protocol lmtp {
auth_username_format = %n
}
]]]
[[[
# Baseline
% rm -rf /home/fmsync/Maildir
% rm -rf /home/fmsync/imapcdir
% rm -rf /mnt/rawlog
% mkdir /mnt/rawlog
% mdmfs -s 1024m auto /mnt/rawlog # mount a tmpfs
% chown fmsync /mnt/rawlog
# doveadm -o mail_fsync=never backup -u fmsync -s "" -l 15 -R -m lists/zsh imapc:/home/fmsync/imapcdir | sponge state.out
dsync(fmsync): Info: imapc(imap.fastmail.com:993): Connected to 66.111.4.135:993 (local 192.168.122.253:56226)
# doveadm -o mail_fsync=never backup -u fmsync -s "$(cat state.out)" -l 15 -R -m lists/zsh imapc:/home/fmsync/imapcdir | sponge state.out
dsync(fmsync): Info: imapc(imap.fastmail.com:993): Connected to 66.111.4.136:993 (local 192.168.122.253:39150)
% openssl s_client -verify_return_error -connect imap.fastmail.com:imaps
⋮
b EXAMINE lists/zsh
* 24117 EXISTS
* 1 RECENT
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen $X-ME-Annot-2 $IsMailingList $IsNotification $HasAttachment $HasTD hasnoatt hasnotd hasatt $X-ME-Annot-1 Old $NotJunk $Junk $Forwarded)
* OK [PERMANENTFLAGS ()] Ok
* OK [UNSEEN 1759] Ok
* OK [UIDVALIDITY 1529153257] Ok
* OK [UIDNEXT 24289] Ok
* OK [HIGHESTMODSEQ 4910711] Ok
* OK [URLMECH INTERNAL] Ok
* OK [ANNOTATIONS 65536] Ok
b OK [READ-ONLY] Completed
c CLOSE
c OK Completed
]]]
[[[
# In another terminal
% swaks -t lists.zsh@…
⋮
<- 250 2.0.0 Ok: queued as 48CjYx6xvmzWp
⋮
]]]
[[[
# Back in s_client
d EXAMINE lists/zsh
* 24118 EXISTS
* 2 RECENT
* FLAGS (\Answered \Flagged \Draft \Deleted \Seen $X-ME-Annot-2 $IsMailingList $IsNotification $HasAttachment $HasTD hasnoatt hasnotd hasatt $X-ME-Annot-1 Old $NotJunk $Junk $Forwarded)
* OK [PERMANENTFLAGS ()] Ok
* OK [UNSEEN 1759] Ok
* OK [UIDVALIDITY 1529153257] Ok
* OK [UIDNEXT 24290] Ok
* OK [HIGHESTMODSEQ 4910779] Ok
* OK [URLMECH INTERNAL] Ok
* OK [ANNOTATIONS 65536] Ok
d OK [READ-ONLY] Completed
e CLOSE
e OK Completed
]]]
[[[
# doveadm -o imapc_rawlog_dir=/mnt/rawlog -Dv backup -u fmsync -s "$(cat state.out)" -l 15 -R -m lists/zsh imapc:/home/fmsync/imapcdir | sponge state.out
Debug: Loading modules from directory: /usr/local/lib/dovecot/doveadm
Debug: Skipping module doveadm_acl_plugin, because dlopen() failed: /usr/local/lib/dovecot/doveadm/lib10_doveadm_acl_plugin.so: Undefined symbol "acl_user_module" (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_expire_plugin, because dlopen() failed: /usr/local/lib/dovecot/doveadm/lib10_doveadm_expire_plugin.so: Undefined symbol "expire_set_init" (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_quota_plugin, because dlopen() failed: /usr/local/lib/dovecot/doveadm/lib10_doveadm_quota_plugin.so: Undefined symbol "quota_user_module" (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_fts_plugin, because dlopen() failed: /usr/local/lib/dovecot/doveadm/lib20_doveadm_fts_plugin.so: Undefined symbol "fts_list_backend" (this is usually intentional, so just ignore this message)
Debug: Skipping module doveadm_mail_crypt_plugin, because dlopen() failed: /usr/local/lib/dovecot/doveadm/libdoveadm_mail_crypt_plugin.so: Undefined symbol "mail_crypt_user_get_public_key" (this is usually intentional, so just ignore this message)
doveadm(fmsync)<966><>: Debug: auth-master: userdb lookup(fmsync): Started userdb lookup
doveadm(fmsync)<966><>: Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb: Connecting
doveadm(fmsync)<966><>: Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (uid=0): Client connected (fd=10)
doveadm(fmsync)<966><>: Debug: auth-master: userdb lookup(fmsync): auth USER input: fmsync system_groups_user=fmsync uid=1002 gid=1002 home=/home/fmsync
doveadm(fmsync)<966><>: Debug: auth-master: userdb lookup(fmsync): Finished userdb lookup (username=fmsync system_groups_user=fmsync uid=1002 gid=1002 home=/home/fmsync)
doveadm(fmsync): Debug: Effective uid=1002, gid=1002, home=/home/fmsync
doveadm(fmsync): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=maildir:~/Maildir:UTF-8
doveadm(fmsync): Debug: maildir++: root=/home/fmsync/Maildir, index=, indexpvt=, control=, inbox=/home/fmsync/Maildir, alt=
doveadm(fmsync): Debug: brain M: Imported mailbox states:
doveadm(fmsync): Debug: brain M: Mailbox $guid1 state: uidvalidity=1529153257 uid=24288 modseq=4910711 pvt_modseq=0 messages=24117 changes_during_sync=0
doveadm(fmsync): Debug: brain M: Namespace has location maildir:~/Maildir:UTF-8
doveadm(fmsync): Debug: Namespace : Using permissions from /home/fmsync/Maildir: mode=0700 gid=default
dsync(fmsync): Debug: Effective uid=1002, gid=1002, home=/home/fmsync
dsync(fmsync): Debug: Namespace : type=private, prefix=, sep=/, inbox=yes, hidden=no, list=yes, subscriptions=yes location=imapc:/home/fmsync/imapcdir
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Created new connection
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Looking up IP address (reconnect_ok=true, last_connect=1580957435)
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Connecting to 66.111.4.135:993
dsync(fmsync): Info: imapc(imap.fastmail.com:993): Connected to 66.111.4.135:993 (local 192.168.122.253:59074)
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Starting SSL handshake
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): SSL handshake successful
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Server capabilities: IMAP4 IMAP4rev1 LITERAL+ ENABLE UIDPLUS SASL-IR NAMESPACE CONDSTORE SORT LIST-EXTENDED QRESYNC MOVE SPECIAL-USE CREATE-SPECIAL-USE IDLE AUTH=PLAIN
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Authenticating as ...
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Server capabilities: IMAP4rev1 LITERAL+ ID ENABLE ACL RIGHTS=kxten QUOTA MAILBOX-REFERRALS NAMESPACE UIDPLUS NO_ATOMIC_RENAME UNSELECT CHILDREN MULTIAPPEND BINARY CATENATE CONDSTORE ESEARCH SEARCH=FUZZY SORT SORT=MODSEQ SORT=DISPLAY SORT=UID THREAD=ORDEREDSUBJECT THREAD=REFERENCES THREAD=REFS ANNOTATE-EXPERIMENT-1 METADATA LIST-EXTENDED LIST-STATUS LIST-MYRIGHTS LIST-METADATA WITHIN QRESYNC SCAN XLIST XMOVE MOVE SPECIAL-USE CREATE-SPECIAL-USE DIGEST=SHA1 X-REPLICATION STATUS=SIZE OBJECTID SAVEDATE X-CREATEDMODSEQ PREVIEW=FUZZY XAPPLEPUSHSERVICE LOGINDISABLED XCONVERSATIONS COMPRESS=DEFLATE X-QUOTA=STORAGE X-QUOTA=MESSAGE X-QUOTA=X-ANNOTATION-STORAGE X-QUOTA=X-NUM-FOLDERS IDLE
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Authenticated successfully
dsync(fmsync): Debug: imapc: root=/home/fmsync/imapcdir, index=, indexpvt=, control=, inbox=, alt=
dsync(fmsync): Debug: maildir++: root=/home/fmsync/imapcdir, index=, indexpvt=, control=, inbox=, alt=
dsync(fmsync): Debug: brain M: Locking done locally in /home/fmsync/.dovecot-sync.lock (local hostname=imapmirror.v.shahaf.local2, remote hostname=imapmirror.v.shahaf.local2)
dsync(fmsync): Debug: brain S: Namespace has location imapc:/home/fmsync/imapcdir
dsync(fmsync): Debug: Namespace : Using permissions from /home/fmsync/imapcdir: mode=0700 gid=default
dsync(fmsync): Debug: brain M: Local mailbox tree: lists guid=00000000000000000000000000000000 uid_validity=0 uid_next=0 subs=no last_change=0 last_subs=0
dsync(fmsync): Debug: brain S: Local mailbox tree: lists guid=00000000000000000000000000000000 uid_validity=0 uid_next=0 subs=no last_change=0 last_subs=0
dsync(fmsync): Debug: brain M: Local mailbox tree: lists/zsh guid=$guid1 uid_validity=1529153257 uid_next=24289 subs=yes last_change=0 last_subs=1580956711
dsync(fmsync): Debug: brain S: Local mailbox tree: lists/zsh guid=$guid1 uid_validity=1529153257 uid_next=24290 subs=yes last_change=0 last_subs=0
dsync(fmsync): Debug: brain M: Remote mailbox tree: lists guid=00000000000000000000000000000000 uid_validity=0 uid_next=0 subs=no last_change=0 last_subs=0
dsync(fmsync): Debug: brain M: Remote mailbox tree: lists/zsh guid=$guid1 uid_validity=1529153257 uid_next=24290 subs=yes last_change=0 last_subs=0
dsync(fmsync): Debug: brain S: Remote mailbox tree: lists guid=00000000000000000000000000000000 uid_validity=0 uid_next=0 subs=no last_change=0 last_subs=0
dsync(fmsync): Debug: brain S: Remote mailbox tree: lists/zsh guid=$guid1 uid_validity=1529153257 uid_next=24289 subs=yes last_change=0 last_subs=1580956711
dsync(fmsync): Debug: brain M: Mailbox lists: local=00000000000000000000000000000000/0/0, remote=00000000000000000000000000000000/0/0: Directory name paths are equal
dsync(fmsync): Debug: brain M: Mailbox lists/zsh: local=$guid1/0/1, remote=$guid1/0/1: Mailboxes are equal
dsync(fmsync): Debug: brain S: Mailbox lists: local=00000000000000000000000000000000/0/0, remote=00000000000000000000000000000000/0/0: Directory name paths are equal
dsync(fmsync): Debug: brain S: Mailbox lists/zsh: local=$guid1/0/1, remote=$guid1/0/1: Mailboxes are equal
dsync(fmsync): Debug: brain M: Skipping mailbox $guid1 with unchanged state uidvalidity=1529153257 uidnext=24289 highestmodseq=4910711 highestpvtmodseq=0 messages=24117
dsync(fmsync): Debug: imapc(imap.fastmail.com:993): Disconnected
dsync(fmsync): Debug: brain M: Exported mailbox states:
dsync(fmsync): Debug: brain M: Mailbox $guid1 state: uidvalidity=1529153257 uid=24288 modseq=4910711 pvt_modseq=0 messages=24117 changes_during_sync=0
dsync(fmsync): Debug: brain M: Unlocked /home/fmsync/.dovecot-sync.lock
dsync(fmsync): Debug: auth-master: conn unix:/var/run/dovecot/auth-userdb (uid=0): Disconnected: Connection closed (fd=10)
% grep -v LOGIN < /mnt/rawlog/20200206-025036.966.1.out
1580957437.093905 1 CAPABILITY
1580957437.403048 3 LIST "" ""
1580957437.550179 4 LIST "" "*"
1580957437.725211 5 STATUS "lists/zsh" (UIDNEXT UIDVALIDITY)
1580957437.874174 6 LSUB "" "*"
1580957438.184244 7 LOGOUT
% grep -w -B 2 5 < /mnt/rawlog/20200206-025036.966.1.in
1580957437.705302 4 OK Completed (...)
1580957437.869540 * STATUS lists/zsh (UIDNEXT 24290 UIDVALIDITY 1529153257)
1580957437.869540 5 OK Completed
% doveadm search -u fmsync mailbox lists/zsh HEADER Received 48CjYx6xvmzWp | wc -l
0
%
]]]
[[[
# Back in s_client:
f EXAMINE lists/zsh
⋮
g UID SEARCH HEADER Received 48CjYx6xvmzWp
* SEARCH 24289
g OK Completed (1 msgs in 5.268 secs)
]]]
So, my question is: Why doesn't «doveadm backup» sync the new message?
(Message number 24118, UID 24289, ESMTP ID 48CjYx6xvmzWp)
Cheers,
Daniel
¹ https://svn.freebsd.org/ports/head/mail/dovecot
More information about the dovecot
mailing list