[Dovecot] flock problems with index files and passwd-file
While experimenting a bit, I found that for some reason, locking indexes with flock is problematic, but only if user is taken from passwd-file. The host system is openbsd 3.9, dovecot's configuration is added at the bottom.
Authentication is from two places - first from mentioned passwd-file, then from passwd file using bsdauth (in this case, there're no problems with flock). So, if a user is i.e.:
test@domain.tld:{plain}test:20000:10::/home/regular/test::userdb_mail=maildir:~/Maildir
Then the mail client will timeout (thunderbird in this case), and dovecot will leave following info in the logs:
Mar 15 11:13:38 rasengan dovecot: IMAP(test@domain.tld): Effective uid=20000, gid=10, home=/home/regular/test Mar 15 11:13:38 rasengan dovecot: IMAP(test@domain.tld): maildir: data=~/Maildir Mar 15 11:13:38 rasengan dovecot: IMAP(test@domain.tld): maildir: root=~/Maildir, index=~/Maildir, control=, inbox= Mar 15 11:15:38 rasengan dovecot: IMAP(test@domain.tld): Timeout while waiting for lock for transaction log file /home/regular/test/Maildir/dovecot.index.log
Happens both if in maildir and mbox (userdb_mail=mbox:~/mail:INBOX=/home/regular/test/mbx) cases.
Locking through dotlocks or fcntl works well in all situations (passwd-file or not).
Dovecot 1.0 rc27 OpenBSD 3.9 (stable), i386
Dovecot config (dovecot -n):
# /etc/dovecot.conf base_dir: /var/dovecot/ protocols: imap imaps pop3 pop3s ssl_listen: * ssl_ca_file: /etc/ssl/cert_bundle.pem ssl_cert_file: /etc/ssl/ca_ppgk/certs/fetch_crt.pem ssl_key_file: /etc/ssl/ca_ppgk/private/fetch_key.pem verbose_ssl: yes login_dir: /var/dovecot/login login_executable(default): /usr/local/libexec/dovecot/imap-login login_executable(imap): /usr/local/libexec/dovecot/imap-login login_executable(pop3): /usr/local/libexec/dovecot/pop3-login login_greeting: Dovecot IMAP server ready. login_greeting_capability(default): yes login_greeting_capability(imap): yes login_greeting_capability(pop3): no valid_chroot_dirs: /var/mail:/home/regular verbose_proctitle: yes first_valid_uid: 1999 first_valid_gid: 10 mail_location: mbox:~/Mail:INBOX=/var/mail/%u mail_debug: yes lock_method: flock maildir_copy_with_hardlinks: yes mbox_read_locks: flock mbox_write_locks: flock mail_executable(default): /usr/local/libexec/dovecot/imap mail_executable(imap): /usr/local/libexec/dovecot/imap mail_executable(pop3): /usr/local/libexec/dovecot/pop3 mail_plugin_dir(default): /usr/local/lib/dovecot/imap mail_plugin_dir(imap): /usr/local/lib/dovecot/imap mail_plugin_dir(pop3): /usr/local/lib/dovecot/pop3 imap_client_workarounds(default): outlook-idle delay-newmail imap_client_workarounds(imap): outlook-idle delay-newmail imap_client_workarounds(pop3): outlook-idle pop3_uidl_format(default): pop3_uidl_format(imap): pop3_uidl_format(pop3): %08Xu%08Xv pop3_client_workarounds(default): pop3_client_workarounds(imap): pop3_client_workarounds(pop3): outlook-no-nuls oe-ns-eoh auth default: verbose: yes debug: yes passdb: driver: passwd-file args: /etc/dovecot.passwd passdb: driver: bsdauth userdb: driver: passwd-file args: /etc/dovecot.passwd userdb: driver: passwd
/etc/dovecot.passwd is just a single line:
test@domain.tld:{plain}test:20000:10::/home/regular/test::userdb_mail=maildir:~/Maildir
On Thu, 2007-03-15 at 12:18 +0100, Michal Soltys wrote:
While experimenting a bit, I found that for some reason, locking indexes with flock is problematic, but only if user is taken from passwd-file. The host system is openbsd 3.9, dovecot's configuration is added at the bottom.
Authentication is from two places - first from mentioned passwd-file, then from passwd file using bsdauth (in this case, there're no problems with flock). So, if a user is i.e.:
test@domain.tld:{plain}test:20000:10::/home/regular/test::userdb_mail=maildir:~/Maildir
It can't be the passwd-file format directly. I'm rather guessing that OpenBSD doesn't like your UID to be as high as 20000. Try with a lower one. If it works, it's an OpenBSD bug.
Timo Sirainen wrote:
It can't be the passwd-file format directly. I'm rather guessing that OpenBSD doesn't like your UID to be as high as 20000. Try with a lower one. If it works, it's an OpenBSD bug.
Lower ones behave in the same way :)
I did a bit of a ktrace though. This is what happens:
- imap process creates .temp file (descriptor 0x7 is returned)
- hardlink is created to that .temp file, as dovecot.index.log.newlock
- .temp file is removed
- attempt to open dovecot.index.log is being made (file doesn't exist)
- imap writes some data to 0x7
- dovecot.index.log.newlock is renamed to dovecot.index.log
- 0x7 is flocked
- dovecot.index.log is opened (descriptor 0x8)
- attempt to flock 0x8 is made, blocking imap forever
Below is the relevant fragment of ktrace:
27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log.newlock" 27588 imap RET lstat -1 errno 2 No such file or directory 27588 imap CALL stat(0x896af328,0xcfbcd710) 27588 imap NAMI "/home/regular/test/Maildir/.temp.rasengan.ppgk.com.pl.27588.7edf2cf58afb1871" 27588 imap RET stat -1 errno 2 No such file or directory 27588 imap CALL open(0x896af328,0xa02,0x1b6) 27588 imap NAMI "/home/regular/test/Maildir/.temp.rasengan.ppgk.com.pl.27588.7edf2cf58afb1871" 27588 imap RET open 7 27588 imap CALL link(0x896af328,0x896af2c0) 27588 imap NAMI "/home/regular/test/Maildir/.temp.rasengan.ppgk.com.pl.27588.7edf2cf58afb1871" 27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log.newlock" 27588 imap RET link 0 27588 imap CALL unlink(0x896af328) 27588 imap NAMI "/home/regular/test/Maildir/.temp.rasengan.ppgk.com.pl.27588.7edf2cf58afb1871" 27588 imap RET unlink 0 27588 imap CALL fstat(0x7,0xcfbcd810) 27588 imap RET fstat 0 27588 imap CALL umask(0x3f) 27588 imap RET umask 54/0x36 27588 imap CALL open(0x8b975280,0x2,0x2d) 27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log" 27588 imap RET open -1 errno 2 No such file or directory 27588 imap CALL write(0x7,0xcfbcd8f0,0x18) 27588 imap GIO fd 7 wrote 24 bytes "\^A\0\^X\0\M-PD\M-yE\^A\0\0\0\0\0\0\0\0\0\0\0\M-PD\M-yE" 27588 imap RET write 24/0x18 27588 imap CALL rename(0x8b975340,0x8b975300) 27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log.newlock" 27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log" 27588 imap RET rename 0 27588 imap CALL gettimeofday(0xcfbcda88,0) 27588 imap RET gettimeofday 0 27588 imap CALL sigprocmask(0x1,0xffffffff) 27588 imap RET sigprocmask 0 27588 imap CALL mprotect(0x3c0ec000,0x1000,0x3) 27588 imap RET mprotect 0 27588 imap CALL mprotect(0x3c0ec000,0x1000,0x1) 27588 imap RET mprotect 0 27588 imap CALL sigprocmask(0x3,0) 27588 imap RET sigprocmask -65793/0xfffefeff 27588 imap CALL sigprocmask(0x1,0xffffffff) 27588 imap RET sigprocmask 0 27588 imap CALL mprotect(0x29a80000,0x2000,0x3) 27588 imap RET mprotect 0 27588 imap CALL mprotect(0x29a80000,0x2000,0x1) 27588 imap RET mprotect 0 27588 imap CALL sigprocmask(0x3,0) 27588 imap RET sigprocmask -65793/0xfffefeff 27588 imap CALL setitimer(0,0xcfbcd9a0,0xcfbcd990) 27588 imap RET setitimer 0 27588 imap CALL sigprocmask(0x1,0xffffffff) 27588 imap RET sigprocmask 0 27588 imap CALL mprotect(0x3c0ec000,0x1000,0x3) 27588 imap RET mprotect 0 27588 imap CALL mprotect(0x3c0ec000,0x1000,0x1) 27588 imap RET mprotect 0 27588 imap CALL sigprocmask(0x3,0) 27588 imap RET sigprocmask -65793/0xfffefeff 27588 imap CALL flock(0x7,0x2) 27588 imap RET flock 0 27588 imap CALL setitimer(0,0xcfbcd9a0,0xcfbcd990) 27588 imap RET setitimer 0 27588 imap CALL stat(0x896af2c0,0xcfbcd9c0) 27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log" 27588 imap RET stat 0 27588 imap CALL open(0x896af2c0,0x2,0) 27588 imap NAMI "/home/regular/test/Maildir/dovecot.index.log" 27588 imap RET open 8 27588 imap CALL fstat(0x8,0xcfbcd8c0) 27588 imap RET fstat 0 27588 imap CALL sigprocmask(0x1,0xffffffff) 27588 imap RET sigprocmask 0 27588 imap CALL mprotect(0x3c0ec000,0x1000,0x3) 27588 imap RET mprotect 0 27588 imap CALL mprotect(0x3c0ec000,0x1000,0x1) 27588 imap RET mprotect 0 27588 imap CALL sigprocmask(0x3,0) 27588 imap RET sigprocmask -65793/0xfffefeff 27588 imap CALL pread(0x8,0x82d1f33c,0x18,0,0,0) 27588 imap GIO fd 8 read 24 bytes "\^A\0\^X\0\M-PD\M-yE\^A\0\0\0\0\0\0\0\0\0\0\0\M-PD\M-yE" 27588 imap RET pread 24/0x18 27588 imap CALL setitimer(0,0xcfbcd9a0,0xcfbcd990) 27588 imap RET setitimer 0 27588 imap CALL flock(0x8,0x2)
Michal Soltys wrote:
Below is the relevant fragment of ktrace:
In addition, here's full backtrace of such "hanged" imap process. If there is anything else that could help, just let me know.
GNU gdb 6.3
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and you are
welcome to change it and/or distribute copies of it under certain conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for details.
This GDB was configured as "i386-unknown-openbsd3.9"...
(gdb) attach 31971
Attaching to process 31971
0x0d352059 in ?? ()
(gdb) bt full
#0 0x0d352059 in ?? ()
No symbol table info available.
#1 0x1c0449fa in mail_index_lock_fd (index=0x8b20a300, path=0x893072c0 "/home/regular/test/Maildir/dovecot.index.log",
fd=8, lock_type=3, timeout_secs=120) at mail-index-lock.c:103
operation = 131
ret = 3
#2 0x1c04c58a in mail_transaction_log_file_lock (file=0x8b9f7300) at mail-transaction-log.c:202
ret = 131
#3 0x1c04e2c8 in mail_transaction_log_lock_head (log=0x8b9f7200) at mail-transaction-log.c:1385
file = (struct mail_transaction_log_file *) 0x8b9f7300
ret = 0
#4 0x1c04e348 in mail_transaction_log_sync_lock (log=0x8b9f7200, file_seq_r=0x83, file_offset_r=0x83)
at mail-transaction-log.c:1417
No locals.
#5 0x1c0435a4 in mail_index_create (index=0x8b20a300, hdr=0xcfbc3040) at mail-index.c:1446
path = 0xcfbc3018 "Ř0ĽĎ89\004\034"
seq = 470075784
offset = 6629139200
ret = -2017967424
#6 0x1c043938 in mail_index_open_files (index=0x8b20a300, flags=41) at mail-index.c:1591
hdr = {major_version = 7 '\a', minor_version = 0 '\0', base_header_size = 120, header_size = 120, record_size = 8,
compat_flags = 1 '\001', unused = "\000\000", indexid = 1174041675, flags = 0, uid_validity = 0, next_uid = 1,
messages_count = 0, recent_messages_count = 0, seen_messages_count = 0, deleted_messages_count = 0,
first_recent_uid_lowwater = 0, first_unseen_uid_lowwater = 0, first_deleted_uid_lowwater = 0, log_file_seq = 0,
log_file_int_offset = 0, log_file_ext_offset = 0, sync_size = 0, sync_stamp = 0, day_stamp = 0, day_first_uid = {0, 0, 0,
0, 0, 0, 0, 0}}
lock_id = 0
ret = 0
create = true
created = false
#7 0x1c043b0b in mail_index_open (index=0x8b20a300, flags=41, lock_method=MAIL_INDEX_LOCK_FLOCK) at mail-index.c:1664
i = 0
ret = -2014570316
#8 0x1c03c829 in index_storage_mailbox_init (ibox=0x87ec1838, name=0x83
On Thu, 2007-03-15 at 14:28 +0100, Michal Soltys wrote:
- imap process creates .temp file (descriptor 0x7 is returned)
- hardlink is created to that .temp file, as dovecot.index.log.newlock
- .temp file is removed
- attempt to open dovecot.index.log is being made (file doesn't exist)
- imap writes some data to 0x7
- dovecot.index.log.newlock is renamed to dovecot.index.log
- 0x7 is flocked
- dovecot.index.log is opened (descriptor 0x8)
- attempt to flock 0x8 is made, blocking imap forever
Fixed: http://dovecot.org/list/dovecot-cvs/2007-March/008217.html
Timo Sirainen wrote:
Fixed: http://dovecot.org/list/dovecot-cvs/2007-March/008217.html
Works perfectly now. Thanks.
participants (2)
-
Michal Soltys
-
Timo Sirainen