[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