[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 <Error reading address 0x83: Invalid argument>, flags=0, move_to_memory=false) at index-storage.c:366 storage = (struct mail_storage *) 0x87ec1438 index_flags = 41 lock_method = MAIL_INDEX_LOCK_FLOCK ret = 131 #9 0x1c01ae9b in maildir_open (storage=0x87ec1438, name=0x3c002056 "INBOX", flags=0) at maildir-storage.c:548 mbox = (struct maildir_mailbox *) 0x87ec1838 index = (struct mail_index *) 0x8b20a300 path = 0x87ec14f0 "/home/regular/test/Maildir" index_dir = 0x13c <Error reading address 0x13c: Invalid argument> control_dir = 0x87ec14f0 "/home/regular/test/Maildir" st = {st_dev = 1174041675, st_ino = 795541000, st_mode = 1174041675, st_nlink = 795541000, st_uid = 1174041675, st_gid = 795541000, st_rdev = 512, st_lspare0 = 0, st_atimespec = {tv_sec = 4, tv_nsec = 0}, st_mtimespec = { tv_sec = 16384, tv_nsec = 0}, st_ctimespec = {tv_sec = 0, tv_nsec = -799543376}, st_size = 2018082489208909584, st_blocks = -8652517760780462832, st_blksize = 1007603712, st_flags = 1, st_gen = 1007599432, st_lspare1 = -1, __st_birthtimespec = {tv_sec = 0, tv_nsec = -2014571464}, st_qspare = {4323491224065152056, 2018083833114276360}} shared = 0 pool = 0x87ec1810 #10 0x1c01afb7 in maildir_mailbox_open (_storage=0x87ec1438, name=0x3c002056 "INBOX", input=0x0, flags=0) at maildir-storage.c:597 path = 0x3c00205c "NAMESPACE_%u_HIDDEN" st = {st_dev = -2014572480, st_ino = 3485217516, st_mode = 3485217384, st_nlink = 469867939, st_uid = 2217791736, st_gid = 1006641238, st_rdev = 5, st_lspare0 = -1993314240, st_atimespec = {tv_sec = 1, tv_nsec = -809749780}, st_mtimespec = {tv_sec = -809749896, tv_nsec = 17135864}, st_ctimespec = {tv_sec = 0, tv_nsec = 0}, st_size = -8385860524382826248, st_blocks = -3477848820700712960, st_blksize = 3485217416, st_flags = 469868303, st_gen = 2280394816, st_lspare1 = -809749780, __st_birthtimespec = {tv_sec = 1, tv_nsec = 469836456}, st_qspare = { 6596620352, 2017942159323050664}} #11 0x1c053472 in mailbox_open (storage=0x83, name=0x3c002056 "INBOX", input=0x0, flags=0) at mail-storage.c:365 No locals. #12 0x1c010cfe in _cmd_select_full (cmd=0x8b9f7048, readonly=false) at cmd-select.c:32 client = (struct client *) 0x8b9f7000 storage = (struct mail_storage *) 0x87ec1438 box = (struct mailbox *) 0x2d32fcc0 status = {messages = 1, recent = 2211005072, unseen = 3485217576, uidvalidity = 221532759, uidnext = 2279792712, first_unseen_seq = 1006636590, keywords = 0x8b9f7000, keywords__type = 0xcfbc3368} mailbox = 0x3c002056 "INBOX" #13 0x1c010ea4 in cmd_select (cmd=0x8b9f7048) at cmd-select.c:92 No locals. #14 0x1c0125f6 in client_handle_input (cmd=0x8b9f7048) at client.c:332 client = (struct client *) 0x8b9f7000 #15 0x1c012570 in client_handle_input (cmd=0x8b9f7048) at client.c:389 client = (struct client *) 0x8b9f7000 #16 0x1c0126de in _client_input (context=0x8b9f7000) at client.c:432 client = (struct client *) 0x8b9f7000 cmd = (struct client_command_context *) 0x8b9f7048 ret = 2 #17 0x1c064ab8 in io_loop_handler_run (ioloop=0x89307000) at ioloop-kqueue.c:153 ctx = (struct ioloop_handler_context *) 0x87b84100 events = (struct kevent *) 0x2 tv = {tv_sec = 9, tv_usec = 997652} ts = {tv_sec = 9, tv_nsec = 997652000} io = (struct io *) 0x87b842a0 events_count = 3 t_id = 2 ret = 1 i = 0 #18 0x1c0641ad in io_loop_run (ioloop=0x89307000) at ioloop.c:323 No locals. #19 0x1c019823 in main (argc=3, argv=0xcfbc34ac, envp=0xcfbc34bc) at main.c:287 No locals. (gdb) detach Detaching from program: , process 31971 (gdb) quit
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