[Dovecot] POP3: Message ordering changed unexpectedly
Hi,
I think I'm having a problem with simultaneous pop3 connections on the same mailbox with one connection deleting a message.
Jan 29 14:36:30 imap1 dovecot: pop3-login: Login: user=<riki@domain.com>, method=PLAIN, rip=82.xx.xx.xx, lip=-----, pip=------, mpid=7703, secured, session=<1A+8DiHxfABSUCCH> Jan 29 14:36:30 imap1 dovecot: pop3-login: Login: user=<riki@domain.com>, method=PLAIN, rip=69.xx.xx.xx, lip=-----, pip=------, mpid=7709, secured, session=<7iLADiHx7wBFdoaw> Jan 29 14:36:30 imap1 dovecot: pop3(riki@domain.com): Disconnected: Logged out top=0/0, retr=0/0, del=1/1227, size=51548362 Jan 29 14:36:33 imap1 dovecot: pop3(riki@domain.com): Error: Message ordering changed unexpectedly (msg #1: storage seq 1 -> 2) Jan 29 14:36:33 imap1 dovecot: pop3(riki@domain.com): Disconnected: POP3 UIDLs couldn't be listed top=3/2662, retr=0/0, del=0/1227, size=51548362
and again:
Feb 3 12:43:16 imap1 dovecot: pop3-login: Login: user=<riki@domain.com>, method=PLAIN, rip=82.xx.xx.xx, lip=-------, pip=-------, mpid=31095, secured, session=<ae74DoTxtABSUCCU> Feb 3 12:43:17 imap1 dovecot: pop3-login: Login: user=<riki@domain.com>, method=PLAIN, rip=69.xx.xx.xx, lip=-------, pip=-------, mpid=31119, secured, session=<GvQMD4TxrwBFdoaw> Feb 3 12:43:17 imap1 dovecot: pop3(riki@domain.com): Disconnected: Logged out top=0/0, retr=1/80835, del=2/1192, size=48287015 Feb 3 12:43:18 imap1 dovecot: pop3(riki@domain.com): Error: Message ordering changed unexpectedly (msg #1: storage seq 1 -> 3) Feb 3 12:43:18 imap1 dovecot: pop3(riki@domain.com): Disconnected: POP3 UIDLs couldn't be listed top=3/2898, retr=0/0, del=0/1192, size=48287015
Running Dovecot 2.2.10+hg-6018854c8c91 Mailboxes were migrated recently using dsync with pop3 migration plugin.
Is there a better way to handle this without logging an error? Am I doing something wrong?
Any help is appreciated.
Thanks,
Gedalya
# dovecot -n # 2.2.10: /etc/dovecot/dovecot.conf # OS: Linux 3.2.0-4-amd64 x86_64 Debian 7.3 auth_mechanisms = plain login cram-md5 auth_verbose = yes auth_verbose_passwords = plain dict { expire = mysql:/etc/dovecot/dovecot-dict-sql.conf.ext quota = mysql:/etc/dovecot/dovecot-dict-sql.conf.ext } disable_plaintext_auth = no imapc_features = rfc822.size fetch-headers login_greeting = Dovecot ready login_log_format_elements = user=<%u> method=%m rip=%r lip=%l pip=%{real_rip} mpid=%e %c session=<%{session}> login_trusted_networks = xx.xx.xx.2 mail_gid = vmail mail_location = /nowhere mail_plugins = quota expire listescape mail_uid = vmail managesieve_sieve_capability = fileinto envelope encoded-character subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables mailbox date ihave namespace { hidden = yes list = no location = pop3c: prefix = POP3-MIGRATION-NS/ } namespace inbox { inbox = yes location = mailbox Drafts { auto = subscribe special_use = \Drafts } mailbox Junk { auto = subscribe special_use = \Junk } mailbox Sent { auto = subscribe special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { auto = subscribe special_use = \Trash } prefix = separator = / type = private } passdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } plugin { antispam_backend = pipe antispam_pipe_program = /usr/bin/ssh antispam_pipe_program_args = -l;spamd;-i;/etc/dovecot/sareport.key;mx.domain.com antispam_pipe_program_notspam_arg = revoke antispam_pipe_program_spam_arg = report antispam_pipe_tmpdir = /tmp antispam_spam = Junk antispam_trash_pattern_ignorecase = trash;Deleted * expire = Trash expire2 = Trash/* expire3 = Junk expire_dict = proxy::expire pop3_migration_mailbox = POP3-MIGRATION-NS/INBOX quota = dict:user::proxy::quota quota_rule = *:storage=2G quota_rule2 = Trash:storage=+250M quota_rule3 = Junk:ignore quota_warning = storage=99%% quota-warning 99 %u quota_warning2 = storage=95%% quota-warning 95 %u sieve = ~/.dovecot.sieve sieve_before = /etc/dovecot/sieve-global/fileinto-spam.sieve sieve_dir = ~/sieve sieve_extensions = -vacation -body -reject -enotify -environment -virustest -spamtest sieve_max_actions = 32 sieve_max_redirects = 4 sieve_max_script_size = 10K sieve_quota_max_scripts = 100 sieve_quota_max_storage = 4M } pop3_no_flag_updates = yes postmaster_address = postmaster@domain.com protocols = imap pop3 lmtp sieve service auth-worker { user = $default_internal_user } service auth { client_limit = 2448 unix_listener auth-userdb { group = root mode = 0600 user = vmail } } service dict { unix_listener dict { group = root mode = 0600 user = vmail } } service imap-login { process_min_avail = 4 service_count = 0 vsz_limit = 192 M } service imap-postlogin { executable = script-login /usr/local/bin/postlogin unix_listener imap-postlogin { group = root mode = 0600 user = vmail } user = root } service imap { executable = imap imap-postlogin process_limit = 1024 vsz_limit = 128 M } service lmtp { inet_listener lmtp { address = 10.44.23.1 port = 7025 } } service managesieve-login { inet_listener sieve { port = 4190 } service_count = 0 vsz_limit = 64 M } service managesieve { process_limit = 20 } service pop3-login { process_min_avail = 4 service_count = 0 vsz_limit = 192 M } service pop3 { executable = pop3 imap-postlogin process_limit = 1024 } service quota-warning { executable = script /usr/local/bin/quota-warning unix_listener quota-warning { user = vmail } user = dovecot } ssl_cert = </etc/dovecot/dovecot.pem ssl_key = </etc/dovecot/private/dovecot.pem userdb { driver = prefetch } userdb { args = /etc/dovecot/dovecot-sql.conf.ext driver = sql } verbose_proctitle = yes protocol lmtp { mail_plugins = quota expire listescape sieve plugin { quota = dict:user::noenforcing:proxy::quota } } protocol lda { mail_plugins = quota expire listescape sieve } protocol imap { mail_max_userip_connections = 12 mail_plugins = quota expire listescape imap_quota antispam ssl_cert = </etc/dovecot/imap.domain.com.crt ssl_key = </etc/dovecot/private/imap.domain.com.key } protocol sieve { mail_max_userip_connections = 5 } protocol pop3 { mail_max_userip_connections = 10 ssl_cert = </etc/dovecot/pop.domain.com.crt ssl_key = </etc/dovecot/private/pop.domain.com.key } protocol doveadm { mail_plugins = quota expire listescape pop3_migration }
On 3.2.2014, at 17.19, Gedalya <gedalya@gedalya.net> wrote:
I think I'm having a problem with simultaneous pop3 connections on the same mailbox with one connection deleting a message. .. Jan 29 14:36:33 imap1 dovecot: pop3(riki@domain.com): Error: Message ordering changed unexpectedly (msg #1: storage seq 1 -> 2) Jan 29 14:36:33 imap1 dovecot: pop3(riki@domain.com): Disconnected: POP3 UIDLs couldn't be listed top=3/2662, retr=0/0, del=0/1227, size=51548362
Running Dovecot 2.2.10+hg-6018854c8c91 Mailboxes were migrated recently using dsync with pop3 migration plugin.
What mailbox format is this with? I can only reproduce this by forcibly making sure that pop3.order field doesn't go into dovecot.index.cache field. Anyway .. this should help: http://hg.dovecot.org/dovecot-2.2/rev/59decc957b39
So also add something like "uidls=%u" to your pop3_logout_format. This will use up a little bit more memory by storing all the UIDLs in memory. The %u output can sometimes be used to debug why POP3 clients are redownloading messages.
On 02/07/2014 03:04 PM, Timo Sirainen wrote:
On 3.2.2014, at 17.19, Gedalya <gedalya@gedalya.net> wrote:
I think I'm having a problem with simultaneous pop3 connections on the same mailbox with one connection deleting a message. .. Jan 29 14:36:33 imap1 dovecot: pop3(riki@domain.com): Error: Message ordering changed unexpectedly (msg #1: storage seq 1 -> 2) Jan 29 14:36:33 imap1 dovecot: pop3(riki@domain.com): Disconnected: POP3 UIDLs couldn't be listed top=3/2662, retr=0/0, del=0/1227, size=51548362
Running Dovecot 2.2.10+hg-6018854c8c91 Mailboxes were migrated recently using dsync with pop3 migration plugin. What mailbox format is this with? I can only reproduce this by forcibly making sure that pop3.order field doesn't go into dovecot.index.cache field. Anyway .. this should help: http://hg.dovecot.org/dovecot-2.2/rev/59decc957b39 Ah sorry, yes. All mailboxes are maildir. Forgot to include the SQL configs. I guess I can send you the uidlist. This is happening when she is deleting a message that is still from the old server, i.e. a migrated message, which has the O field set in dovecot-uidlist. Presumably it would stop happening when the last of those is gone.
I'll read through that commit now..
So also add something like "uidls=%u" to your pop3_logout_format. This will use up a little bit more memory by storing all the UIDLs in memory. The %u output can sometimes be used to debug why POP3 clients are redownloading messages.
Your commit message says: "..can be completely avoided by using either pop3_lock_session=yes or adding %u to pop3_logout_format." If I understand you correctly, this is a setting for formatting the entry in the log file, and by using %u I'm forced to save the UIDLs in memory and as a side effect I circumvent the problem of colliding with another simultaneous pop3 client? So using %u would not help troubleshoot the problem but actually fix it?
On 7.2.2014, at 15.16, Gedalya <gedalya@gedalya.net> wrote:
So also add something like "uidls=%u" to your pop3_logout_format. This will use up a little bit more memory by storing all the UIDLs in memory. The %u output can sometimes be used to debug why POP3 clients are redownloading messages.
Your commit message says: "..can be completely avoided by using either pop3_lock_session=yes or adding %u to pop3_logout_format." If I understand you correctly, this is a setting for formatting the entry in the log file, and by using %u I'm forced to save the UIDLs in memory and as a side effect I circumvent the problem of colliding with another simultaneous pop3 client? So using %u would not help troubleshoot the problem but actually fix it?
Yeah, as a side effect of %u it'll also fix your problem entirely. I first thought about adding a new setting but then I realized this can be used without adding any settings.
On 02/07/2014 03:20 PM, Timo Sirainen wrote:
On 7.2.2014, at 15.16, Gedalya <gedalya@gedalya.net> wrote:
So also add something like "uidls=%u" to your pop3_logout_format. This will use up a little bit more memory by storing all the UIDLs in memory. The %u output can sometimes be used to debug why POP3 clients are redownloading messages.
Your commit message says: "..can be completely avoided by using either pop3_lock_session=yes or adding %u to pop3_logout_format." If I understand you correctly, this is a setting for formatting the entry in the log file, and by using %u I'm forced to save the UIDLs in memory and as a side effect I circumvent the problem of colliding with another simultaneous pop3 client? So using %u would not help troubleshoot the problem but actually fix it? Yeah, as a side effect of %u it'll also fix your problem entirely. I first thought about adding a new setting but then I realized this can be used without adding any settings.
Cool ;-) Thank you!!! Much appreciated.
participants (2)
-
Gedalya
-
Timo Sirainen