Duplicate message when email is moved while dsync is running

While experimenting with dsync over SSH instead of TCP(S), I noticed a issue when a email client immediately moves a messages to a separate folder while Dovecot is syncing, where the message is seen twice in the folder (with the exact same headers/content).

For example, I have set a filter in my email client, Thunderbird, to immediately move all emails coming from this list to a separate folder.
When opening that folder, I do not see one, but two unread messages, both identical to each other.

When checking the directories on the server, I see this:
mx1:
/var/vmail/example.com/joe/Maildir/.Subdir.Subdir/cur/1652615808.M190190P990486.mx2,S=19089,W=19384:2,S
/var/vmail/example.com/joe/Maildir/.Subdir.Subdir/cur/1652615811.M180050P1376677.mx1,S=19089,W=19384:2,S

mx2:
/var/vmail/example.com/joe/Maildir/.Subdir.Subdir/cur/1652615811.M981426P990530.mx2,S=19089,W=19384:2,S
/var/vmail/example.com/joe/Maildir/.Subdir.Subdir/cur/1652615808.M190190P990486.mx2,S=19089,W=19384:2,S

Note the difference: on mx1, one indicates mx1, and one mx2, while on the other server, both indicate mx2/

Any users here that have any idea (other then telling end-users not to use such filters) how we could prevent these duplicate messages?

Already posted to the dovecot mailing list, but no useful solution found so far....

 

Still experiencing this and still no resolution. After this post, I was inspired to dive into it again: https://forum.howtoforge.com/threads/lmtp-sporadically-twice.89743/

Relevant log lines of message that came in as duplicate today:

Code:

Nov 27 13:11:08 mx2 postfix/smtpd[2994666]: connect from cloud2.howtoforge.com[168.119.187.99]
Nov 27 13:11:08 mx2 postfix/smtpd[2994666]: 3D16160051: client=cloud2.howtoforge.com[168.119.187.99]
Nov 27 13:11:08 mx2 postfix/cleanup[2996952]: 3D16160051: message-id=<[email protected]>
Nov 27 13:11:09 mx2 postfix/qmgr[1269316]: 3D16160051: from=<[email protected]>, size=10094, nrcpt=1 (queue active)
Nov 27 13:11:09 mx2 postfix/smtpd[2994666]: disconnect from cloud2.howtoforge.com[168.119.187.99] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov 27 13:11:09 mx2 dovecot: lmtp(2996956): Connect from local
Nov 27 13:11:09 mx2 dovecot: lmtp([email protected])<2996956><DFNqGd1Tg2Pcui0AQ9Mayg>: sieve: msgid=<[email protected]>: stored mail into mailbox 'INBOX'
Nov 27 13:11:09 mx2 dovecot: lmtp(2996956): Disconnect from local: Client has quit the connection (state=READY)
Nov 27 13:11:09 mx2 postfix/lmtp[2996955]: 3D16160051: to=<[email protected]>, relay=mx2.example.net[private/dovecot-lmtp], delay=1.3, delays=1.2/0.01/0.01/0.06, dsn=2.0.0, status=sent (250 2.0.0 <[email protected]> DFNqGd1Tg2Pcui0AQ9Mayg Saved)
Nov 27 13:11:09 mx2 postfix/qmgr[1269316]: 3D16160051: removed

And one that was not:

Code:

Nov 27 14:03:22 mx2 postfix/smtpd[2997488]: connect from cloud2.howtoforge.com[168.119.187.99]
Nov 27 14:03:22 mx2 postfix/smtpd[2997488]: E372860051: client=cloud2.howtoforge.com[168.119.187.99]
Nov 27 14:03:22 mx2 postfix/cleanup[2999986]: E372860051: message-id=<[email protected]>
Nov 27 14:03:23 mx2 postfix/qmgr[1269316]: E372860051: from=<[email protected]>, size=10939, nrcpt=1 (queue active)
Nov 27 14:03:23 mx2 postfix/smtpd[2997488]: disconnect from cloud2.howtoforge.com[168.119.187.99] ehlo=1 mail=1 rcpt=1 data=1 quit=1 commands=5
Nov 27 14:03:23 mx2 dovecot: lmtp(2999990): Connect from local
Nov 27 14:03:23 mx2 dovecot: lmtp([email protected])<2999990><dO3MJhtgg2O2xi0AQ9Mayg>: sieve: msgid=<[email protected]>: stored mail into mailbox 'INBOX'
Nov 27 14:03:23 mx2 postfix/lmtp[2999989]: E372860051: to=<[email protected]>, relay=mx2.example.net[private/dovecot-lmtp], delay=0.83, delays=0.74/0.01/0.01/0.06, dsn=2.0.0, status=sent (250 2.0.0 <[email protected]> dO3MJhtgg2O2xi0AQ9Mayg Saved)
Nov 27 14:03:23 mx2 dovecot: lmtp(2999990): Disconnect from local: Client has quit the connection (state=READY)
Nov 27 14:03:23 mx2 postfix/qmgr[1269316]: E372860051: removed

Looking at the differences between those two, it seems like 2 lines are different.

Duplicated:

Code:

Nov 27 13:11:09 mx2 dovecot: lmtp(2996956): Disconnect from local: Client has quit the connection (state=READY)
Nov 27 13:11:09 mx2 postfix/lmtp[2996955]: 3D16160051: to=<[email protected]>, relay=mx2.example.net[private/dovecot-lmtp], delay=1.3, delays=1.2/0.01/0.01/0.06, dsn=2.0.0, status=sent (250 2.0.0 <[email protected]> DFNqGd1Tg2Pcui0AQ9Mayg Saved)

Not duplicated:

Code:

Nov 27 14:03:23 mx2 postfix/lmtp[2999989]: E372860051: to=<[email protected]>, relay=mx2.example.net[private/dovecot-lmtp], delay=0.83, delays=0.74/0.01/0.01/0.06, dsn=2.0.0, status=sent (250 2.0.0 <[email protected]> dO3MJhtgg2O2xi0AQ9Mayg Saved)
Nov 27 14:03:23 mx2 dovecot: lmtp(2999990): Disconnect from local: Client has quit the connection (state=READY)

But that might be completely irrelevant...

I have searched all around the internet, Dovecot mailing lists, etc. But I have not been able to find a solution.

Dovecot mailing list submission: https://dovecot.org/pipermail/dovecot/2022-May/124681.html / https://dovecot.org/pipermail/dovecot/2022-May/thread.html#124681

If anyone has the solution or even points me in the right direction they will receive a special thanks

 

Dovecot does recognize the duplicates, they can be cleared easily with their deduplicate command. e.g.:

Code:

doveadm -D deduplicate -u [email protected] ALL

But this is not a solution of course.

 

Custom configuration for Dovecot:
/etc/dovecot/conf.d/99-ispconfig-custom-config.conf

Code:

# Custom SSL settings
ssl_min_protocol = TLSv1.2
ssl_prefer_server_ciphers = yes
ssl_cipher_list = kEECDH:+kEECDH+SHA:kEDH:+kEDH+SHA:+kEDH+CAMELLIA:kECDH:+kECDH+SHA:kRSA:+kRSA+SHA:+kRSA+CAMELLIA:!aNULL:!eNULL:!SSLv2:!RC4:!MD5:!DES:!EXP:!SEED:!IDEA:!3DES

# dsync settings
#mail_plugins = $mail_plugins notify replication
protocol imap {
  mail_plugins = $mail_plugins quota notify replication
}
protocol pop3 {
  mail_plugins = $mail_plugins quota notify replication
}
protocol lda {
  mail_plugins = $mail_plugins sieve quota notify replication
}
protocol lmtp {
  mail_plugins = $mail_plugins sieve quota notify replication
}

# Set max connections for replication
replication_max_conns = 50

# Replicator process should be started at startup, so it can start replicating users immediately:
service replicator {
  process_min_avail = 1
}

# The mail processes need to have access to the replication-notify fifo and socket.
service aggregator {
    fifo_listener replication-notify-fifo {
        user = vmail
        mode = 0666
    }

    unix_listener replication-notify {
        user = vmail
        mode = 0666
    }
}

# Enable doveadm replicator commands
service replicator {
    unix_listener replicator-doveadm {
        user = vmail
        mode = 0666
    }
}

# add dsync_remote_command for custom port
dsync_remote_cmd = ssh -p 16 -l%{login} %{host} doveadm dsync-server -u%u
# Set remote host
plugin {
    mail_replica = remote:[email protected]
}

doveconf -n

Code:

# 2.3.13 (89f716dc2): /etc/dovecot/dovecot.conf
# Pigeonhole version 0.5.13 (cdd19fe3)
# OS: Linux 5.10.0-18-cloud-amd64 x86_64 Debian 11.5
# Hostname: mx1.example.net
auth_mechanisms = plain login
disable_plaintext_auth = no
dsync_remote_cmd = ssh -p 16 -l%{login} %{host} doveadm dsync-server -u%u
imap_capability = +SPECIAL-USE XLIST
listen = *,[::]
lmtp_rcpt_check_quota = yes
log_timestamp = "%Y-%m-%d %H:%M:%S "
mail_max_userip_connections = 100
mail_plugins = quota
mail_privileged_group = vmail
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 = .
}
passdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
plugin {
  mail_replica = remote:[email protected]
  quota = dict:user::file:/var/vmail/%d/%n/.quotausage
  quota_status_nouser = DUNNO
  quota_status_overquota = 552 5.2.2 Mailbox is full
  quota_status_success = DUNNO
  sieve = /var/vmail/%d/%n/.sieve
  sieve_after = /var/vmail/%d/%n/.ispconfig.sieve
  sieve_before = /var/vmail/%d/%n/.ispconfig-before.sieve
  sieve_max_actions = 100
  sieve_max_redirects = 25
  sieve_max_script_size = 2M
}
protocols = imap pop3 lmtp
replication_max_conns = 50
service aggregator {
  fifo_listener replication-notify-fifo {
    mode = 0666
    user = vmail
  }
  unix_listener replication-notify {
    mode = 0666
    user = vmail
  }
}
service auth {
  unix_listener /var/spool/postfix/private/auth {
    group = postfix
    mode = 0660
    user = postfix
  }
  unix_listener auth-userdb {
    group = vmail
    mode = 0600
    user = vmail
  }
  user = root
}
service imap-login {
  client_limit = 1000
  process_limit = 512
}
service lmtp {
  unix_listener /var/spool/postfix/private/dovecot-lmtp {
    group = postfix
    mode = 0600
    user = postfix
  }
}
service quota-status {
  client_limit = 1
  executable = quota-status -p postfix
  unix_listener /var/spool/postfix/private/quota-status {
    group = postfix
    mode = 0660
    user = postfix
  }
}
service replicator {
  process_min_avail = 1
  unix_listener replicator-doveadm {
    mode = 0666
    user = vmail
  }
}
service stats {
  unix_listener stats-reader {
    group = vmail
    mode = 0660
    user = vmail
  }
  unix_listener stats-writer {
    group = vmail
    mode = 0660
    user = vmail
  }
}
ssl_cert = </etc/postfix/smtpd.cert
ssl_cipher_list = kEECDH:+kEECDH+SHA:kEDH:+kEDH+SHA:+kEDH+CAMELLIA:kECDH:+kECDH+SHA:kRSA:+kRSA+SHA:+kRSA+CAMELLIA:!aNULL:!eNULL:!SSLv2:!RC4:!MD5:!DES:!EXP:!SEED:!IDEA:!3DES
ssl_dh = # hidden, use -P to show it
ssl_key = # hidden, use -P to show it
ssl_min_protocol = TLSv1.2
ssl_prefer_server_ciphers = yes
userdb {
  driver = prefetch
}
userdb {
  args = /etc/dovecot/dovecot-sql.conf
  driver = sql
}
protocol imap {
  auth_verbose = yes
  mail_plugins = quota quota imap_quota quota notify replication
}
protocol pop3 {
  auth_verbose = yes
  mail_plugins = quota quota quota notify replication
  pop3_uidl_format = %08Xu%08Xv
}
protocol lda {
  mail_plugins = quota sieve quota sieve quota notify replication
  postmaster_address = [email protected]
}
protocol lmtp {
  mail_plugins = quota quota sieve sieve quota notify replication
  postmaster_address = [email protected]
}

 

Note that this problem did not exist when using syncing over TCPS, it started when I switched it over to use SSH...

 

Interesting, found this in mail.warn on mx1 (mail was received on mx2):

Code:

Nov 27 13:11:12 mx1 dovecot: imap([email protected])<3054914><vhILYXLuit0tX+zY>: Warning: /var/vmail/example.nl/thom/Maildir/dovecot-uidlist: Duplicate file entry at line 6239: 1669551069.M429649P2996956.mx2,S=13356,W=13572 (uid 25691 -> 25692) - retrying by re-reading from beginning
Nov 27 13:11:13 mx1 dovecot: imap([email protected])<3054089><OP3JMXLu/MUtX+zY>: Warning: Maildir /var/vmail/example.nl/thom/Maildir: Expunged message reappeared, giving a new UID (old uid=25691, file=1669551069.M429649P2996956.mx2,S=13356,W=13572:2,)

I do not see any of such messages on mx2, which would probably mean that this problem only exists on mx1... But what causes it?

 

I was indeed looking into Dovecot's own repo: https://repo.dovecot.org/ - might try use that and install the software from there, though I'd rather not mess around too much on a production system

 

PS: @michelangelo do you use the Dovecot repo with a ISPConfig system? No issues?