Dovecot 2.1.7 + Outlook 2007 + Leave messages = Duplicate emails

Discussion in 'Installation/Configuration' started by ircf, Oct 14, 2014.

  1. ircf

    ircf Member

    Hello,

    On end of September 2014, we migrated from 1 mail server running courier, to 2 mirror mail servers running Dovecot to host our 1300 customer mailboxes. We used imapsync.

    Mailboxes are stored via NFS, both servers have same config : ISPConfig 3.0.5.4p3 + Dovecot 2.1.7 + Roundcube Webmail 1.1-git + ISPConfig roundcube plugins. The second mail server is set as "mirror" of the other in ISP Config. Load balancing between mail1 and mail2 is done with multiple DNS A on a single DNS MX, i.e :
    mail.ircf.fr. A <mail1 IP address>
    mail.ircf.fr. A <mail2 IP address>
    MX mail.ircf.fr.

    Each mailbox has 1GB size, most of our customers use POP3 with option "leave message on server".

    Everything is fine, except a bug that reported one of our customer and we can't manage to reproduce nor to fix it : he uses MS Outlook 2007 on 3 desktops with 2 mailboxes + the "leave on server" option. Randomly (about once per week of couple of week) one or many of his machines receive duplicates emails.

    We think this might be due to a bug in UIDL handling in the clients and/or servers, but we didn't find any error or warning in mail logs.

    Right after migration, we had this bug (duplicate emails) on every mailbox/clients. We managed to fix it by changing the UIDL format to courier format and use pop3_reuse_xuidl and pop3_save_uidl. This seems to fix it for any other machine/clients, BUT this one.

    Below is our /etc/dovecot/dovecot.conf (same on both servers)

    EDIT : We tried to reduce leaving period duration (4 weeks -> 1 week), without success. Today we tried to configure inbound server as mail1.ircf.fr (instead of mail.ircf.fr) in case the bug would be caused by load balancing, we are waiting for results, fingers crossed...

    EDIT2 : Thank you for your help.

    Code:
    listen = *,[::]
    protocols = imap pop3 sieve
    auth_mechanisms = plain login
    disable_plaintext_auth = no
    log_timestamp = "%Y-%m-%d %H:%M:%S "
    mail_privileged_group = vmail
    ssl_cert = </opt/ssl/ircf.crt
    ssl_key = </opt/ssl/ircf.key
    passdb {
      args = /etc/dovecot/dovecot-sql.conf
      driver = sql
    }
    userdb {
      args = /etc/dovecot/dovecot-sql.conf
      driver = sql
    }
    plugin {
      quota = dict:user::file:/var/vmail/%d/%n/.quotausage
      sieve=/var/vmail/%d/%n/.sieve
      sieve_dir = /var/vmail/%d/%n/sieve/
      sieve_global_dir = /etc/dovecot/sieve 
      sieve_before = /etc/dovecot/sieve/before.d
      sieve_after = /etc/dovecot/sieve/after.d
    }
    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 = 500
    }
    protocol imap {
      mail_plugins = quota imap_quota
    }
    protocol pop3 {
      #pop3_uidl_format = %08Xu%08Xv
      pop3_uidl_format = UID%u-%v
      mail_plugins = quota
      pop3_reuse_xuidl = yes
      pop3_save_uidl = yes
    }
    protocol lda {
      mail_plugins = sieve quota
    }
    #mail_debug = yes
    
     
    Last edited: Oct 14, 2014
  2. ircf

    ircf Member

    POP3 login and connection closed every second

    Hello,

    Our customer still have the same issue, it now occurs randomly on many mailboxes, even on a mailbox where there is only one computer (Outlook 2007) and an iPhone which both connects with POP3+leave message on server.

    We had the problem that night and we found these logs :
    1.1.1.1 is the iPhone client (GPRS Orange connection)
    2.2.2.2 is our mail server
    3.3.3.3 is the outlook 2007 client (ADSL Orange connection)

    - client 1.1.1.1 login/logout automatically on server 2.2.2.2 every 15 minutes to check mail
    - before 03:27:01, client 3.3.3.3 login/logout automatically on server 2.2.2.2 every 30 minutes to check mail
    - from 03:27:01 to 08:15:00, on every second, client 3.3.3.3 login and then connection is closed, 1sec later client 3.3.3.3 login again...
    - from 08:15:00, client 3.3.3.3 login/logout normally
    - this morning our customer had duplicate emails in his client 3.3.3.3

    It seems that the same scenario occurs each time our customer receive duplicate emails.

    Code:
    ...
    /var/log/mail.log:Oct 24 02:48:11 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=10
    591, session=<38ARiSAGRgBQDCs+>
    /var/log/mail.log:Oct 24 02:48:21 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 02:56:43 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    1053, session=<KZiQpyAGnABQD1zv>
    /var/log/mail.log:Oct 24 02:56:44 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:06:17 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=12
    240, session=<L87NySAGUwBQDCs+>
    /var/log/mail.log:Oct 24 03:06:26 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:24:21 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=13
    831, session=<sNhpCiEGXwBQDCs+>
    /var/log/mail.log:Oct 24 03:24:31 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:27:01 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    3992, session=<7RLtEyEG1gBQD1zv>
    /var/log/mail.log:Oct 24 03:27:02 mail1 dovecot: pop3([email protected]): Connection closed top=0/0, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:42:26 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=15
    395, session=<uWcQSyEGawBQDCs+>
    /var/log/mail.log:Oct 24 03:42:35 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:57:19 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    6750, session=<zxhFgCEG/wBQD1zv>
    /var/log/mail.log:Oct 24 03:57:23 mail1 dovecot: pop3([email protected]): Connection closed top=50/105901, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:57:23 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    6754, session=<GQuLgCEGAABQD1zv>
    /var/log/mail.log:Oct 24 03:57:24 mail1 dovecot: pop3([email protected]): Connection closed top=1/1767, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:57:24 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    6756, session=<3nKSgCEGAQBQD1zv>
    /var/log/mail.log:Oct 24 03:57:24 mail1 dovecot: pop3([email protected]): Connection closed top=1/608, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:57:24 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    6758, session=<lLWZgCEGAgBQD1zv>
    /var/log/mail.log:Oct 24 03:57:24 mail1 dovecot: pop3([email protected]): Connection closed top=1/2218, retr=0/0, del=0/1250, size=244848875
    /var/log/mail.log:Oct 24 03:57:25 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=1
    6760, session=<Ed6ggCEGAwBQD1zv>
    ...
    Oct 24 05:07:13 mail1 dovecot: pop3([email protected]): Connection closed top=1/1938, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:07:13 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=30888, session=<Uml
    LeiIGkABQD1zv>
    Oct 24 05:07:14 mail1 dovecot: pop3([email protected]): Connection closed top=1/2977, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:07:14 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=30890, session=<WN9
    UeiIGkQBQD1zv>
    Oct 24 05:07:15 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=2/43739, del=0/1250, size=244848875
    Oct 24 05:08:23 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:13:40 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=31186, session=<LqZX
    kSIGvQBQDCs+>
    Oct 24 05:13:55 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:19:52 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=32122, session=<b6CA
    pyIGzQBQDCs+>
    Oct 24 05:20:01 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:25:03 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=32427, session=<BegF
    uiIG0ABQDCs+>
    Oct 24 05:26:26 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:28:01 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=32543, session=<gA6
    qxCIGzQBQD1zv>
    Oct 24 05:28:05 mail1 dovecot: pop3([email protected]): Connection closed top=50/105901, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:28:06 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=32547, session=<USn
    txCIG0ABQD1zv>
    Oct 24 05:28:06 mail1 dovecot: pop3([email protected]): Connection closed top=1/1767, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:28:06 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=32551, session=<94b
    0xCIG0QBQD1zv>
    Oct 24 05:28:06 mail1 dovecot: pop3([email protected]): Connection closed top=1/608, retr=0/0, del=0/1250, size=244848875
    Oct 24 05:28:07 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=32553, session=<xKL
    7xCIG0gBQD1zv>
    ...
    /var/log/mail.log:Oct 24 08:17:08 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=3
    05, session=<fjB7ISUGHQBQD1zv>
    /var/log/mail.log:Oct 24 08:17:25 mail1 dovecot: pop3([email protected]): Connection closed: Connection reset by peer top=0/0, retr=1/0, del=0/1256, s
    ize=244975113
    /var/log/mail.log:Oct 24 08:17:34 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=3.3.3.3, lip=2.2.2.2, mpid=3
    19, session=<A0QJIyUGeQBQD1zv>
    /var/log/mail.log:Oct 24 08:17:39 mail1 dovecot: pop3([email protected]): Connection closed top=0/0, retr=1/0, del=0/1256, size=244975113
    /var/log/mail.log:Oct 24 08:20:41 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=60
    8, session=<VrwvLiUGewBQDCs+>
    /var/log/mail.log:Oct 24 08:20:44 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1256, size=244975113
    /var/log/mail.log:Oct 24 08:20:45 mail1 dovecot: pop3-login: Login: user=<[email protected]>, method=PLAIN, rip=1.1.1.1, lip=2.2.2.2, mpid=61
    8, session=<zexjLiUGfgBQDCs+>
    /var/log/mail.log:Oct 24 08:23:37 mail1 dovecot: pop3([email protected]): Disconnected: Logged out top=0/0, retr=0/0, del=0/1256, size=244975113
    ...
    
     

Share This Page