Re: [Dovecot] Index error copying compressed message

2013-09-27 Thread Richard Platel

On 2013-09-22, at 12:35 AM, Timo Sirainen t...@iki.fi wrote:

 On 19.9.2013, at 23.59, Richard Platel rpla...@tucows.com wrote:
 
 Dovecot 2.2, with the zlib plugin, I think we're getting bad index entries 
 on IMAP COPY.
 
 On copying a message to an empty folder, in the dovecot error log I see:
 
 Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: Cached 
 message size smaller than expected (615  971)
 Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: 
 Corrupted index cache file 
 /mail/index01/434/860/gr...@rp-auth-test.com/.Bup/dovecot.index.cache: 
 Broken physical size for mail UID 0
 Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: read() 
 failed: Invalid argument (uid=0)
 
 (Note this happens from the copy operation, not a subsequent access.  Also 
 note the UID is always 0).
 
 UID=0 means that it's trying to get the size for the mail that is still being 
 saved (so not the copy source mail). You mean you can easily reproduce this 
 simply by copying a mail to a newly created folder? I couldn't. Try if you 
 can still reproduce it with a smaller config, especially removing non-zlib 
 plugins.
 

This was indeed a plugin configuration problem, thanks.



Re: [Dovecot] Index error copying compressed message

2013-09-21 Thread Timo Sirainen
On 19.9.2013, at 23.59, Richard Platel rpla...@tucows.com wrote:

 Dovecot 2.2, with the zlib plugin, I think we're getting bad index entries on 
 IMAP COPY.
 
 On copying a message to an empty folder, in the dovecot error log I see:
 
 Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: Cached 
 message size smaller than expected (615  971)
 Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: 
 Corrupted index cache file 
 /mail/index01/434/860/gr...@rp-auth-test.com/.Bup/dovecot.index.cache: Broken 
 physical size for mail UID 0
 Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: read() 
 failed: Invalid argument (uid=0)
 
 (Note this happens from the copy operation, not a subsequent access.  Also 
 note the UID is always 0).

UID=0 means that it's trying to get the size for the mail that is still being 
saved (so not the copy source mail). You mean you can easily reproduce this 
simply by copying a mail to a newly created folder? I couldn't. Try if you can 
still reproduce it with a smaller config, especially removing non-zlib plugins.



[Dovecot] Index error copying compressed message

2013-09-19 Thread Richard Platel
Hi.

Dovecot 2.2, with the zlib plugin, I think we're getting bad index entries on 
IMAP COPY.

On copying a message to an empty folder, in the dovecot error log I see:

Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: Cached 
message size smaller than expected (615  971)
Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: Corrupted 
index cache file 
/mail/index01/434/860/gr...@rp-auth-test.com/.Bup/dovecot.index.cache: Broken 
physical size for mail UID 0
Sep 19 20:34:25 imap01 dovecot: imap(gr...@rp-auth-test.com): Error: read() 
failed: Invalid argument (uid=0)

(Note this happens from the copy operation, not a subsequent access.  Also note 
the UID is always 0).

The filename for the message is:
-rw--- 2862 mail mail 615 Aug 29 15:38 
1379622865.M228140P11548.imap01,S=971,W=988:2,S

S= size looks correct:

$ zcat 1379622865.M228140P11548.imap01\,S\=971\,W\=988\:2\,S |wc
 17  51 971


doveadm dump says:
$ sudo -u mail doveadm -c /he/dovecot/conf/dovecot.conf dump 
/mail/index01/434/860/gr...@rp-auth-test.com/.Bup/
Detected file type: index
-- INDEX: /mail/index01/434/860/gr...@rp-auth-test.com/.Bup//dovecot.index
version .. = 7.3
base header size . = 120
header size .. = 208
record size .. = 12
compat flags . = 1
index id . = 1379605150 (2013-09-19 15:39:10)
flags  = 0
uid validity . = 1377629137 (2013-08-27 18:45:37)
next uid . = 14309
messages count ... = 1
seen messages count .. = 1
deleted messages count ... = 0
first recent uid . = 14308
first unseen uid lowwater  = 14309
first deleted uid lowwater = 14308
log file seq . = 6
log file tail offset . = 204
log file head offset . = 204
day stamp  = 1379548800 (2013-09-19 00:00:00)
day first uid[0] . = 1
day first uid[1] . = 0
day first uid[2] . = 0
day first uid[3] . = 0
day first uid[4] . = 0
day first uid[5] . = 0
day first uid[6] . = 0
day first uid[7] . = 0
-- Extension 0 --
name  = maildir
hdr_size  = 36
reset_id  = 0
record_offset = 0
record_size . = 0
record_align  = 0
header
 - new_check_time  = 2013-09-19 20:34:10
 - new_mtime . = 2013-09-19 20:08:51
 - new_mtime_nsecs ... = 79253
 - cur_check_time  = 2013-09-19 20:35:38
 - cur_mtime . = 2013-09-19 20:35:38
 - cur_mtime_nsecs = 22771
 - uidlist_mtime . = 2013-09-19 20:35:38
 - uidlist_mtime_nsecs = 254613000
 - uidlist_size .. = 1025178
-- Extension 1 --
name  = cache
hdr_size  = 0
reset_id  = 1379605174
record_offset = 8
record_size . = 4
record_align  = 4
-- Keywords --

-- CACHE: /mail/index01/434/860/gr...@rp-auth-test.com/.Bup//dovecot.index.cache
major version  = 1
minor version  = 1
indexid .. = 1379605150 (2013-09-19 15:39:10)
file_seq . = 1379605174 (2013-09-19 15:39:34) (24 compressions)
continued_record_count = 0
record_count . = 0
used_file_size (old) . = 108
deleted_record_count . = 0
field_header_offset .. = 32 (0x88808080 nontranslated)
-- Cache fields --
 #  Name Type Size Dec  Last used
 0: flagsbit 4 tmp  2013-09-19 20:07
 1: hdr.Message-ID   hdr - tmp  2013-09-19 20:07
 2: hdr.X-HE-Tag hdr - tmp  2013-09-19 20:07

-- RECORDS: 1
RECORD: seq=1, uid=14308, flags=0x08 (Seen)
 - ext 3 cache :  0 ()



$ sudo -u mail dovecot -c /he/dovecot/conf/dovecot.conf -n
# 2.2.4.3 (12e60e803a54+): /he/dovecot/conf/dovecot.conf
# OS: Linux 3.4.46-dom0-2.0.0 x86_64 Debian 7.0
debug_log_path = syslog
disable_plaintext_auth = no
first_valid_uid = 8
info_log_path = syslog
lock_method = dotlock
log_path = /var/run/dovecot/log-fifo
log_timestamp =
mail_fsync = always
mail_gid = mail
mail_nfs_index = yes
mail_nfs_storage = yes
mail_plugins = zlib quota tc_mail_log notify tc_proc stats
mail_uid = mail
maildir_very_dirty_syncs = yes
mmap_disable = yes
namespace inbox {
  inbox = yes
  location =
  prefix =
}
passdb {
  args = host=localhost port=1143 
username=%L{user}::%L{service}::%L{rip}::%L{session}
  driver = imap
}
plugin {
  mail_log_events = delete undelete expunge copy mailbox_delete mailbox_rename 
flag_change append
  mail_log_fields = uid box msgid flags hetag
  memcached_servers = 10.5.47.223,10.5.47.222
  quota = dict:User quota::proxy:/var/run/auth_proxy_dovecot/quotasocket:quota
  stats_command_min_time = 1 mins
  stats_domain_min_time = 12 hours
  stats_ip_min_time = 12 hours
  stats_memory_limit = 16 M
  stats_refresh = 30 secs
  stats_session_min_time = 15 mins
  stats_track_cmds = yes
  stats_user_min_time = 1 hours
  zlib_save = gz
  zlib_save_level = 6
}
protocols = imap pop3
service anvil {