[Dovecot] infinite loop deleting ~160'000 mails (was Re: Unexpected behaviour when deleteing a big mailbox)

Steffen Kaiser skdovecot at smail.inf.fh-bonn-rhein-sieg.de
Fri Mar 30 16:39:32 EEST 2007


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

On Thu, 29 Mar 2007, Steffen Kaiser wrote:

I let run "imaptest blablah copybox=box1" half a day. It ran through, no 
cores, no crashes, it still ran when I came back this morning.

There tons of:

dovecot: Mar 30 08:49:27 Error: IMAP(dvtest2) [12578]: Transaction log 
file /var/cache/dovecot/31022/index/.box1/dovecot.index.log: marked 
corrupted
dovecot: Mar 30 08:49:28 Error: IMAP(dvtest2) [12581]: Corrupted 
transaction log file 
/var/cache/dovecot/31022/index/.box1/dovecot.index.log: Append with UID 
168554, but next_uid = 168555
dovecot: Mar 30 08:49:28 Error: IMAP(dvtest2) [12488]: Transaction log 
file /var/cache/dovecot/31022/index/.box1/dovecot.index.log: marked 
corrupted

All in the copybox, no error related to the work-in box.

=============

box1 (the copybox) contains 168778 messages.
When I first selected the box1, there were some 
"Fixed a duplicate link" Warnings, then Thunderbird tried to download all 
the message headers. It never returned to something useful state.
straceing the imap process I saw that Dovecot reads all messages fully, 
header & body, then sends the client:

* 49136 FETCH (UID 49235 RFC822.SIZE 7426 FLAGS (\Recent) 
BODY[HEADER.FIELDS (FROM TO CC SUBJECT DATE MESSAGE-ID PRIORITY X-PRIORITY 
REFERENCES NEWSGROUPS IN-REPLY-TO CONTENT-TYPE)] {668}
And the headers.

I killed thunderbird, eventually, re-opend the mailbox and tried to delete 
the mails all at once.

=============

When I tried to delete all the messages through the "Trashbox", the 
copy-to-Trash process fails with (see end of mail).
Then the process starts again with uid=1, again the same error is issued 
at the same uid.
After the first "Out-of-mem" condition, I see "delete uid 1" in the log, 
but the messages are still there and the COPY is still performed again.

There is no Time-out during this situation ;-)

Dunno, I simply suggest that the admin may limit the number
of items a COPY command may be performed for.  I mean, one can
move/copy/delete-to-trash mails in chunks of 50'000 messages - nobody
sane has that many message in one mailbox, hasn't one?

============

# ulimit -a
core file size          (blocks, -c) unlimited
data seg size           (kbytes, -d) unlimited
max nice                        (-e) 0
file size               (blocks, -f) unlimited
pending signals                 (-i) 16383
max locked memory       (kbytes, -l) 32
max memory size         (kbytes, -m) unlimited
open files                      (-n) 1024
pipe size            (512 bytes, -p) 8
POSIX message queues     (bytes, -q) 819200
max rt priority                 (-r) 0
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 16383
virtual memory          (kbytes, -v) unlimited
file locks                      (-x) unlimited


dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15131]: copy -> Trash: 
uid=159985, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15131]: copy -> Trash: 
uid=159986, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15131]: copy -> Trash: 
uid=159987, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15131]: copy -> Trash: 
uid=159988, msgid=<xxxxxxxx.xxxxxxx at xx-xxxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 30 15:01:45 Error: IMAP(dvtest2) [15131]: block_alloc(): Out 
of memory
dovecot: Mar 30 15:01:45 Error: child 15131 (imap) returned error 83 (Out 
of memory)
dovecot: Mar 30 15:01:45 Info: auth(default): client in: AUTH   1 
PLAIN   service=IMAP    lip=10.20.10.166        rip=10.20.10.63
dovecot: Mar 30 15:01:45 Info: auth(default): client out: CONT  1
dovecot: Mar 30 15:01:45 Info: auth(default): client in: CONT<hidden>
dovecot: Mar 30 15:01:45 Info: auth(default): cache(dvtest2,10.20.10.63): 
hit
dovecot: Mar 30 15:01:45 Info: auth(default): cache(dvtest2,10.20.10.63): 
User unknown
dovecot: Mar 30 15:01:45 Info: auth(default): cache(dvtest2,10.20.10.63): 
hit
dovecot: Mar 30 15:01:45 Info: auth(default): client out: OK    1 
user=dvtest2
dovecot: Mar 30 15:01:45 Info: auth(default): master in: REQUEST        34 
15132   1
dovecot: Mar 30 15:01:45 Info: auth(default): 
prefetch(dvtest2,10.20.10.63): passdb didn't return userdb entries
dovecot: Mar 30 15:01:45 Info: auth(default): ldap(dvtest2,10.20.10.63): 
user search: base=dc=fh-bonn-rhein-sieg,dc=de scope=subtree filte
r=(&(objectClass=fhMailAlias)(uid=dvtest2)) 
fields=homeDirectory,uidNumber,gidNumber,mailLocationDovecot,uid
dovecot: Mar 30 15:01:45 Error: auth(default): ldap(dvtest2,10.20.10.63): 
Authenticated user not found
dovecot: Mar 30 15:01:45 Info: auth(default): master out: USER  34 
dvtest2 uid=31022       gid=1003        home=/home/dvtest2
dovecot: Mar 30 15:01:45 Info: imap-login: Login: 15132:, user=<dvtest2>, 
method=PLAIN, rip=10.20.10.63, lip=10.20.10.166
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Loading modules from 
directory: /usr/local/dovecot.rc28_patched/lib/dovecot/imap
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Module loaded: 
/usr/local/dovecot.rc28_patched/lib/dovecot/imap/lib10_quota_plugin.s
o
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Module loaded: 
/usr/local/dovecot.rc28_patched/lib/dovecot/imap/lib11_imap_quota_plu
gin.so
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Module loaded: 
/usr/local/dovecot.rc28_patched/lib/dovecot/imap/lib20_mail_log_plugi
n.so
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Module loaded: 
/usr/local/dovecot.rc28_patched/lib/dovecot/imap/lib20_zlib_plugin.so
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Effective uid=31022, 
gid=1003, home=/home/dvtest2
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: Namespace: 
type=private, prefix=, sep=., inbox=yes, hidden=yes, subscriptions=no
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: maildir: 
data=/home/dvtest2/MailDir:CONTROL=/var/cache/dovecot/31022/control:INDEX=/
var/cache/dovecot/31022/index
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: maildir: 
root=/home/dvtest2/MailDir, index=/var/cache/dovecot/31022/index, 
control=/
var/cache/dovecot/31022/control, inbox=
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: fs quota add storage 
dir = /home/dvtest2/MailDir
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: fs quota block 
device = /dev/mapper/mailstud-mailstud
dovecot: Mar 30 15:01:45 Info: IMAP(dvtest2) [15133]: fs quota mount point 
= /home
dovecot: Mar 30 15:01:48 Info: IMAP(dvtest2) [15133]: copy -> Trash: 
uid=1, msgid=<xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx at xxx-xxx.xxx.xx-x
xxx-xxxxx-xxxx.xx>, box=box1
dovecot: Mar 30 15:01:48 Warning: IMAP(dvtest2) [15133]: Fixed a duplicate 
link: /home/dvtest2/MailDir/.box1/cur/1175202599.P10595Q0M55318
7.ux-2s11-9:2, -> 
/home/dvtest2/MailDir/.box1/cur/1175202599.P10595Q0M553187.ux-2s11-9:2,a
dovecot: Mar 30 15:01:48 Warning: IMAP(dvtest2) [15133]: Fixed a duplicate 
link: /home/dvtest2/MailDir/.box1/cur/1175234953.P18264Q0M95709
8.ux-2s11-9:2, -> 
/home/dvtest2/MailDir/.box1/cur/1175234953.P18264Q0M957098.ux-2s11-9:2,Fe
dovecot: Mar 30 15:01:48 Warning: IMAP(dvtest2) [15133]: Fixed a duplicate 
link: /home/dvtest2/MailDir/.box1/cur/1175206465.P9628Q0M401201
.ux-2s11-9:2,FSe -> 
/home/dvtest2/MailDir/.box1/cur/1175206465.P9628Q0M401201.ux-2s11-9:2,DFSae
dovecot: Mar 30 15:01:48 Warning: IMAP(dvtest2) [15133]: Fixed a duplicate 
link: /home/dvtest2/MailDir/.box1/cur/1175194240.P27391Q0M69691
6.ux-2s11-9:2,F -> 
/home/dvtest2/MailDir/.box1/cur/1175194240.P27391Q0M696916.ux-2s11-9:2,FRd

===

# sbin/dovecot -n
# /usr/local/dovecot.rc28_patched/etc/dovecot.conf
base_dir: /var/run/dovecot/
log_path: /var/log/dovecot/dovecot.log
protocols: imap imaps pop3 pop3s
ssl_ca_file: /etc/ssl/certs/ca.crt
ssl_cert_file(default): /etc/ssl/certs/imap.pem
ssl_cert_file(imap): /etc/ssl/certs/imap.pem
ssl_cert_file(pop3): /etc/ssl/certs/pop3.pem
ssl_key_file(default): /etc/ssl/private/imap.key
ssl_key_file(imap): /etc/ssl/private/imap.key
ssl_key_file(pop3): /etc/ssl/private/pop3.key
disable_plaintext_auth: no
verbose_ssl: yes
login_dir: /var/run/dovecot//login
login_executable(default): 
/usr/local/dovecot.rc28_patched/libexec/dovecot/imap-login
login_executable(imap): 
/usr/local/dovecot.rc28_patched/libexec/dovecot/imap-login
login_executable(pop3): 
/usr/local/dovecot.rc28_patched/libexec/dovecot/pop3-login
login_log_format_elements: %p: user=<%u> method=%m rip=%r lip=%l %c
verbose_proctitle: yes
first_valid_uid: 1000
mail_location: 
maildir:%h/MailDir:CONTROL=/var/cache/dovecot/%i/control:INDEX=/var/cache/dovecot/%i/index
mail_debug: yes
dotlock_use_excl: yes
maildir_copy_with_hardlinks: yes
maildir_copy_preserve_filename: yes
mail_drop_priv_before_exec: yes
mail_executable(default): /usr/local/dovecot.rc28/libexec/dovecot/rawlog 
/usr/local/dovecot.rc28/libexec/dovecot/imap
mail_executable(imap): /usr/local/dovecot.rc28/libexec/dovecot/rawlog 
/usr/local/dovecot.rc28/libexec/dovecot/imap
mail_executable(pop3): 
/usr/local/dovecot.rc28_patched/libexec/dovecot/pop3
mail_plugins(default): quota imap_quota mail_log zlib
mail_plugins(imap): quota imap_quota mail_log zlib
mail_plugins(pop3): quota mail_log
mail_plugin_dir(default): /usr/local/dovecot.rc28_patched/lib/dovecot/imap
mail_plugin_dir(imap): /usr/local/dovecot.rc28_patched/lib/dovecot/imap
mail_plugin_dir(pop3): /usr/local/dovecot.rc28_patched/lib/dovecot/pop3
mail_log_prefix: %Us(%u) [%p]:
mail_log_max_lines_per_sec: 0
pop3_uidl_format(default):
pop3_uidl_format(imap):
pop3_uidl_format(pop3): %u
pop3_client_workarounds(default):
pop3_client_workarounds(imap):
pop3_client_workarounds(pop3): oe-ns-eoh
namespace:
   type: private
   separator: .
   inbox: yes
   hidden: yes
auth default:
   mechanisms: plain login
   cache_size: 10
   username_chars: 
abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ01234567890
   verbose: yes
   debug: yes
   passdb:
     driver: ldap
     args: /usr/local/dovecot.rc26/etc/dovecot-ldap.conf
   passdb:
     driver: shadow
   userdb:
     driver: prefetch
   userdb:
     driver: ldap
     args: /usr/local/dovecot.rc26/etc/dovecot-ldap.conf
   userdb:
     driver: passwd-file
     args: /etc/passwd
   socket:
     type: listen
     client:
       path: /var/run/dovecot/auth-client
       mode: 432
     master:
       path: /var/run/dovecot/auth-master
       mode: 432
       group: mail
plugin:
   quota: fs

- -- 
Steffen Kaiser
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)

iQEVAwUBRg0TFi9SORjhbDpvAQIy4Qf+JZmYsgVmApeowTm9vz4WKYNgMiixR6FI
9PailHkZv/Nmxt12hxVXKAtV3iaNIY4E7bdy1CahvojuFav0GD66wjCHcHeyiUop
G7wFWRPqd5AP9aEEFXF8h+FitXO4OV5CSSQl25Ssg/ZwtCf9JnYsXnCgQOTc3fot
MOp6sczv4FPXotagNsmQHvy929WQqoS+Erv/vFfZiFLt/xN/uE3zorVNHftybo62
xW/7FqbPiUXfw7jhB3y7Xd7A3sxHa7sRMzoWv+KQtFpxZpecY/NkWMzeLB0t3z4l
G5xQEVxB4GCbyOniXC/xZMWqAmi+HPz9I18aqbsI0b4SzTOnSKryiQ==
=NlFU
-----END PGP SIGNATURE-----


More information about the dovecot mailing list