doveadm backup -R -m -s not picking up a new message
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 =
[[[ # 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
Daniel Shahaf wrote on Thu, 06 Feb 2020 03:37 +0000:
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. ⋮ dsync(fmsync): Debug: brain M: Skipping mailbox $guid1 with unchanged state uidvalidity=1529153257 uidnext=24289 highestmodseq=4910711 highestpvtmodseq=0 messages=24117 ⋮ 1580957437.725211 5 STATUS "lists/zsh" (UIDNEXT UIDVALIDITY) 1580957437.869540 * STATUS lists/zsh (UIDNEXT 24290 UIDVALIDITY 1529153257) 1580957437.869540 5 OK Completed ⋮ ]]]
So, my question is: Why doesn't «doveadm backup» sync the new message? (Message number 24118, UID 24289, ESMTP ID 48CjYx6xvmzWp)
I've grepped around and found two potentially relevant bits of code:
dsync_mailbox_tree_get_selectable() calls mailbox_get_status(…, STATUS_UIDVALIDITY | STATUS_UIDNEXT, …) without STATUS_HIGHESTMODSEQ.
imapc_mailbox_get_selected_status() silently ignores the STATUS_HIGHESTMODSEQ flag.
Could either of these be related?
(I haven't had time to do a debug build to investigate further myself.)
Cheers,
Daniel
Daniel Shahaf wrote on Fri, 07 Feb 2020 07:36 +0000:
Daniel Shahaf wrote on Thu, 06 Feb 2020 03:37 +0000:
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.
⋮ dsync(fmsync): Debug: brain M: Skipping mailbox $guid1 with unchanged state uidvalidity=1529153257 uidnext=24289 highestmodseq=4910711 highestpvtmodseq=0 messages=24117
⋮ 1580957437.725211 5 STATUS "lists/zsh" (UIDNEXT UIDVALIDITY) 1580957437.869540 * STATUS lists/zsh (UIDNEXT 24290 UIDVALIDITY 1529153257) 1580957437.869540 5 OK Completed
⋮ ]]]So, my question is: Why doesn't «doveadm backup» sync the new message? (Message number 24118, UID 24289, ESMTP ID 48CjYx6xvmzWp)
I've grepped around and found two potentially relevant bits of code:
dsync_mailbox_tree_get_selectable() calls mailbox_get_status(…, STATUS_UIDVALIDITY | STATUS_UIDNEXT, …) without STATUS_HIGHESTMODSEQ.
imapc_mailbox_get_selected_status() silently ignores the STATUS_HIGHESTMODSEQ flag.
Could either of these be related?
(I haven't had time to do a debug build to investigate further myself.)
Is there any additional information I can provide or debugging I can do?
Cheers,
Daniel
participants (1)
-
Daniel Shahaf