My mail server consumed all of its configured file table slots and
started returning ENFILE ("Too many open files in system") for many
operations. This wreaked havoc with dovecot-1.1.13. Here are some
areas where dovecot should detect and more gracefully handle ENFILE
error returns:
1. Deliver should report an error more helpful than "Unknown internal
error" when fdatasync_path fails:
deliver(user): Apr 10 14:53:20 Error: fdatasync_path(/Volumes/MailData/
user/new) failed: Too many open files in system
deliver(user): Apr 10 14:53:20 Info: msgid=<...>: save failed to
INBOX: BUG: Unknown internal error
2. Index files should not be fscked when they could not be opened due
to ENFILE:
Error: IMAP(user): open() failed with index file /Volumes/MailData/
user/.Deleted Messages/dovecot.index: Too many open files in system
Warning: IMAP(user): fscking index file /Volumes/MailData/
user/.Deleted Messages/dovecot.index
3. Dovecot should not crash when mail transaction logs become
corrupt, or appear to have become corrupt due to ENFILE. Here is a
sequence of error messages from the log but I can't tell whether the
IMAP ones up through the panic in the middle are all from the same
process, or from different processes.
deliver(user): Apr 10 14:55:32 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:55:54 Error: open() failed with index file /
Volumes/MailData/user/dovecot.index: Too many open files in system
deliver(user): Apr 10 14:55:54 Error: open() failed with file /Volumes/
MailData/user/dovecot.index.log.2: Too many open files in system
deliver(user): Apr 10 14:55:57 Error: open() failed with index cache
file /Volumes/MailData/user/dovecot.index.cache: Too many open files
in system
dovecot: Apr 10 14:56:08 Warning: IMAP(user): fscking index file /
Volumes/MailData/user/dovecot.index
dovecot: Apr 10 14:56:16 Error: IMAP(user): Fixed index file /Volumes/
MailData/user/dovecot.index: log_file_seq 15 -> 2
deliver(user): Apr 10 14:56:19 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:56:20 Error: Corrupted transaction log file /
Volumes/MailData/user/dovecot.index.log seq 2: record size too small
(type=0x0, offset=23088, size=0) (sync_offset=36848)
deliver(user): Apr 10 14:56:20 Warning: fscking index file (in-memory
index)
deliver(user): Apr 10 14:56:21 Info: msgid=<...>: save failed to
INBOX: Internal error occurred. Refer to server log for more
information. [2009-04-10 14:56:20]
dovecot: Apr 10 14:56:40 Panic: IMAP(user): file mail-transaction-log-
view.c: line 103 (mail_transaction_log_view_set): assertion failed:
(min_file_seq <= max_file_seq)
dovecot: Apr 10 14:56:40 Error: IMAP(user): Raw backtrace: [see below
for better backtrace]
deliver(user): Apr 10 14:56:45 Error: Transaction log file /Volumes/
MailData/user/dovecot.index.log: marked corrupted
deliver(user): Apr 10 14:57:04 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:57:23 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:57:49 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:58:21 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:58:41 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:59:09 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:59:28 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 14:59:43 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 15:00:57 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 15:03:01 Info: msgid=<...>: saved mail to INBOX
deliver(user): Apr 10 15:03:27 Info: msgid=<...>: saved mail to INBOX
dovecot: Apr 10 15:21:41 Error: IMAP(user): Corrupted transaction log
file /Volumes/MailData/user/dovecot.index.log seq 2: Invalid
transaction log size (36848 vs 23088): /Volumes/MailData/user/
dovecot.index.log (sync_offset=36848)
dovecot: Apr 10 15:21:42 Info: imap-login: Login: user=<user>,
method=CRAM-MD5, rip=..., lip=..., TLS
The backtrace for the assertion failure was:
0 libSystem.B.dylib 0x00007fff8007c102 __kill + 10
1 libSystem.B.dylib 0x00007fff800f7ffc abort + 83
2 imap 0x000000010006a22e
default_fatal_finish + 70
3 imap 0x000000010006a27c
i_syslog_fatal_handler + 0
4 imap 0x00000001000699db i_info + 0
5 imap 0x0000000100058542
mail_transaction_log_view_set + 104
6 imap 0x0000000100053b4c
view_sync_set_log_view_range + 125
7 imap 0x0000000100053fc5
mail_index_view_sync_begin + 378
8 imap 0x000000010003c26e
index_mailbox_sync_init + 129
9 imap 0x0000000100018457
maildir_storage_sync_init + 229
10 imap 0x000000010000c6bb imap_sync_init +
132
11 imap 0x000000010000c90d cmd_sync_delayed
+ 477
12 imap 0x000000010000716a
client_handle_input + 409
13 imap 0x0000000100007244 client_input + 148
14 imap 0x0000000100071228
io_loop_handler_run + 272
15 imap 0x00000001000705ed io_loop_run + 55
16 imap 0x000000010000e219 main + 1635
17 imap 0x00000001000016c0 start + 52
I have since configured more open files, and enabled core dumps and
added the pid to the mail_log_prefix for better tracking, but this is
all I have to work with for now.
Too bad the values of min_file_seq and max_file_seq are not logged in
the panic.