Duplicate message when email is moved while dsync is running

Discussion in 'Installation/Configuration' started by Th0m, Jun 2, 2022.

  1. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    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....
     
    ahrasis likes this.
  2. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    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=<6f14309effbd5b368c9e9efc87ebd2[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 ;)
     
  3. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    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.
     
  4. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    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]
    }
     
  5. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

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

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    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?
     
  7. michelangelo

    michelangelo Member

    Dovecot 2.3.13 is quiet old to be honest plenty of replication issues have been fixed in upstream since the release of this version.

    I know it's the version that ships with the operating system, but certain software like Postfix, web server daemons, or Dovecot better be using a more current version than the one the distribution ships with.
     
  8. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

    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 :D
     
    ahrasis likes this.
  9. Th0m

    Th0m ISPConfig Developer Staff Member ISPConfig Developer

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

    [​IMG]
     
  10. michelangelo

    michelangelo Member

    No, I don't.
    I'm using my own custom Dovecot packages (RHEL rpm) that I patch with security fixes, since it is a customized 2.2.36.4 package.
    However, the replication works fine here as far as I can tell but I'm using mdbox instead of maildir. Even in the storage format could be minor differences in how well the replication works.

    Also I fully understand your concerns. I was also often worried that a new Dovecot release may screw up the replication but within the branch of a release version, it is unlikely to run into problems. However, I often wait a little, like one, two months after the release of a new Dovecot version so that I can observe the feedback of other Dovecot users at the Dovecot mailling list and depending on the feedback I update Dovecot to the newest release or I simply don't and wait for a new release.

    Dovecot 2.3 is known to definitely have replication issues, issues that I did not see with Dovecot 2.2 but the latest Dovecot 2.3.19.1 release should have a better working replication than older Dovecot 2.3 releases.

    If you want to be 100% sure not to mess up your production system, then you need to mirror your current production system to a test environment and run the update on the test system and see if the replication issues disappear.
     
    ahrasis likes this.

Share This Page