Dovecot auth process repeatedly crashes on OS X Server 10.9
My dovecot/auth process crashes several times a minute, sometimes at the same second, sometimes randomly. I’ve turned on auth_debug and been pouring over everything trying to see if I can see what is going on but I can’t find anything. I’m running OS X Server 10.9 and dovecot 2.2.5. I can’t say for sure, but it looks to me like the crashed process doesn’t even save anything to mail-debug.log before it crashes. It takes about 2 seconds for it to come up. Once it crashed about 10 times in 2 seconds.
Can anyone give me any ideas where I should look?
Here are relevant portions from logs:
mail-info.log
Nov 06 17:19:10 pop3-login: Info: Aborted login (auth process communication failure): user=<>, method=DIGEST-MD5, rip=155.101.106.229, lip=10.0.0.128, TLS
mail-err.log
Nov 06 17:19:10 pop3-login: Warning: Auth connection closed with 1 pending requests (max 0 secs, pid=66114, EOF) Nov 06 17:19:10 auth: Fatal: master: service(auth): child 66100 killed with signal 11 (core dumps disabled)
It looks exactly like what is discussed here:
https://discussions.apple.com/thread/6482632?start=0&tstart=0
I do have clients using Outlook. I haven’t run wireshark or tried to verify it is Outlook by testing different clients.
postconf -n
# 2.2.5: /Library/Server/Mail/Config/dovecot/dovecot.conf # OS: Darwin 13.3.0 x86_64 hfs auth_mechanisms = cram-md5 digest-md5 plain login auth_realms = biomail.biology.utah.edu auth_socket_path = /var/run/dovecot/auth-userdb auth_username_format = %n debug_log_path = /Library/Logs/Mail/mail-debug.log default_internal_user = _dovecot default_login_user = _dovenull first_valid_gid = 6 first_valid_uid = 6 imap_id_log = * imap_id_send = "name" * "version" * imap_urlauth_submit_user = submit info_log_path = /Library/Logs/Mail/mail-info.log log_path = /Library/Logs/Mail/mail-err.log login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c mail_access_groups = mail mail_attribute_dict = file:/Library/Server/Mail/Data/attributes/attributes.dict mail_location = maildir:/Library/Server/Mail/Data/mail/%u mail_log_prefix = "%s(pid %p user %u): " mail_plugins = quota zlib acl fts fts_sk managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave mdbox_rotate_size = 200 M namespace acl-mailboxes { list = children location = maildir:/Library/Server/Mail/Data/mail/users/%%u:INDEX=/Library/Server/Mail/Data/mail/shared/%%u prefix = shared.%%u. separator = . subscriptions = no type = shared } namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } namespace list-archives { list = children location = maildir:/Library/Server/Mail/Data/listserver/messages/archive/lists/%%u:INDEX=/Library/Server/Mail/Data/listserver/messages/archive/shared/%%u prefix = archives.%%u. separator = . subscriptions = no type = shared } passdb { driver = od } passdb { args = /Library/Server/Mail/Config/dovecot/submit.passdb driver = passwd-file } plugin { acl = vfile:/Library/Server/Mail/Config/dovecot/global-acls:cache_secs=300 acl_shared_dict = file:/Library/Server/Mail/Data/shared/shared-mailboxes fts = sk quota = maildir:User quota quota_warning = storage=100%% quota-exceeded %u sieve = /Library/Server/Mail/Data/rules/%u/dovecot.sieve sieve_dir = /Library/Server/Mail/Data/rules/%u stats_refresh = 30 secs stats_track_cmds = yes } postmaster_address = postmaster@biology.utah.edu protocols = imap pop3 lmtp sieve quota_full_tempfail = yes service auth { idle_kill = 15 mins unix_listener auth-userdb { user = _dovecot } } service dns_client { unix_listener dns-client { mode = 0600 } } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } service_count = 0 } service imap { client_limit = 5 process_limit = 200 service_count = 0 } service indexer-worker { user = _dovecot } service lmtp { unix_listener lmtp { mode = 0600 } } service managesieve-login { inet_listener sieve { port = 4190 } } service pop3-login { inet_listener pop3 { port = 110 } inet_listener pop3s { port = 995 ssl = yes } } service pop3 { client_limit = 5 process_limit = 200 service_count = 0 } service quota-exceeded { executable = script /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/quota-exceeded.sh unix_listener quota-exceeded { group = mail mode = 0660 user = _dovecot } user = _dovecot } service quota-warning { executable = script /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/quota-warning.sh unix_listener quota-warning { group = mail mode = 0660 user = _dovecot } user = _dovecot } service stats { fifo_listener stats-mail { mode = 0600 user = _dovecot } } ssl_ca =
Here’s part of a crash report:
Process: auth [60325] Path: /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/auth Identifier: auth Version: 294 Code Type: X86-64 (Native) Parent Process: dovecotd [149] Responsible: dovecotd [149] User ID: 214
Date/Time: 2014-11-06 16:34:20.777 -0700 OS Version: Mac OS X 10.9.4 (13E28) Report Version: 11 Anonymous UUID: 9EB07E95-1536-96FA-A8C7-3784045DCDDE
Crashed Thread: 0 Dispatch queue: com.apple.main-thread
Exception Type: EXC_BAD_ACCESS (SIGSEGV) Exception Codes: KERN_INVALID_ADDRESS at 0x0000000000000000
VM Regions Near 0: --> __TEXT 0000000103b39000-0000000103b6a000 [ 196K] r-x/rwx SM=COW /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/auth
Thread 0 Crashed:: Dispatch queue: com.apple.main-thread 0 libsystem_c.dylib 0x00007fff8a181732 strlen + 18 1 libdovecot.0.dylib 0x0000000103bdc2b8 vstrconcat + 72
Thread 1: 0 libsystem_kernel.dylib 0x00007fff858f9e6a __workq_kernreturn + 10 1 libsystem_pthread.dylib 0x00007fff89901f08 _pthread_wqthread + 330 2 libsystem_pthread.dylib 0x00007fff89904fb9 start_wqthread + 13
Thread 2:: Dispatch queue: com.apple.libdispatch-manager 0 libsystem_kernel.dylib 0x00007fff858fa662 kevent64 + 10 1 libdispatch.dylib 0x00007fff8808f421 _dispatch_mgr_invoke + 239 2 libdispatch.dylib 0x00007fff8808f136 _dispatch_mgr_thread + 52
Thread 3: 0 libsystem_kernel.dylib 0x00007fff858f9e6a __workq_kernreturn + 10 1 libsystem_pthread.dylib 0x00007fff89901f08 _pthread_wqthread + 330 2 libsystem_pthread.dylib 0x00007fff89904fb9 start_wqthread + 13
Thread 0 crashed with X86 Thread State (64-bit): rax: 0x00007fff5c0c6878 rbx: 0x0000000000000001 rcx: 0x0000000000000001 rdx: 0x0000000000000001 rdi: 0x0000000000000000 rsi: 0x0000000103b6354d rbp: 0x00007fff5c0c6800 rsp: 0x00007fff5c0c6800 r8: 0x0000000103b6354e r9: 0x0000000000000000 r10: 0x00007fff8a1c92a8 r11: 0x00007fb60dca54c3 r12: 0x0000000000000028 r13: 0x00007fff5c0c6920 r14: 0x0000000000000028 r15: 0x0000000000000009 rip: 0x00007fff8a181732 rfl: 0x0000000000010246 cr2: 0x0000000000000000
Logical CPU: 0 Error Code: 0x00000004 Trap Number: 14
I’ve isolated the crashes to clients running OS X 10.10 Yosemite and Mail.app. I’ve looked through the source code a little to get familiar with how auth works, but I’m wondering if there is a faster way to figure this out, maybe disabling encryption (tls and force plain text password) and running tcpdump and see how 10.10 is different than 10.9.
I’ve asked someone running dovecot 2.0.x (on Linux) if they have seen this problem with 10.10 clients and he didn’t.
The crash log states it is a EXC_BAD_ACCESS (SIGSEGV) and the 2 functions calls in the backtrace are vstrconcat (libdovecot) and strlen (libsystem_c.dylib). I’m wondering if maybe the username or strings sent by 10.10 are missing nulls at the end (which shouldn’t even be possible afiak) or off by 1 or something. Just a wild guess.
James
On Nov 6, 2014, at 5:26 PM, James Reynolds reynolds@biology.utah.edu wrote:
My dovecot/auth process crashes several times a minute, sometimes at the same second, sometimes randomly. I’ve turned on auth_debug and been pouring over everything trying to see if I can see what is going on but I can’t find anything. I’m running OS X Server 10.9 and dovecot 2.2.5. I can’t say for sure, but it looks to me like the crashed process doesn’t even save anything to mail-debug.log before it crashes. It takes about 2 seconds for it to come up. Once it crashed about 10 times in 2 seconds.
Can anyone give me any ideas where I should look?
Here are relevant portions from logs:
mail-info.log
Nov 06 17:19:10 pop3-login: Info: Aborted login (auth process communication failure): user=<>, method=DIGEST-MD5, rip=155.101.106.229, lip=10.0.0.128, TLS
mail-err.log
Nov 06 17:19:10 pop3-login: Warning: Auth connection closed with 1 pending requests (max 0 secs, pid=66114, EOF) Nov 06 17:19:10 auth: Fatal: master: service(auth): child 66100 killed with signal 11 (core dumps disabled)
It looks exactly like what is discussed here:
https://discussions.apple.com/thread/6482632?start=0&tstart=0
I do have clients using Outlook. I haven’t run wireshark or tried to verify it is Outlook by testing different clients.
postconf -n
# 2.2.5: /Library/Server/Mail/Config/dovecot/dovecot.conf # OS: Darwin 13.3.0 x86_64 hfs auth_mechanisms = cram-md5 digest-md5 plain login auth_realms = biomail.biology.utah.edu auth_socket_path = /var/run/dovecot/auth-userdb auth_username_format = %n debug_log_path = /Library/Logs/Mail/mail-debug.log default_internal_user = _dovecot default_login_user = _dovenull first_valid_gid = 6 first_valid_uid = 6 imap_id_log = * imap_id_send = "name" * "version" * imap_urlauth_submit_user = submit info_log_path = /Library/Logs/Mail/mail-info.log log_path = /Library/Logs/Mail/mail-err.log login_log_format_elements = user=<%u> method=%m rip=%r lip=%l mpid=%e %c mail_access_groups = mail mail_attribute_dict = file:/Library/Server/Mail/Data/attributes/attributes.dict mail_location = maildir:/Library/Server/Mail/Data/mail/%u mail_log_prefix = "%s(pid %p user %u): " mail_plugins = quota zlib acl fts fts_sk managesieve_notify_capability = mailto managesieve_sieve_capability = fileinto reject envelope encoded-character vacation subaddress comparator-i;ascii-numeric relational regex imap4flags copy include variables body enotify environment mailbox date ihave mdbox_rotate_size = 200 M namespace acl-mailboxes { list = children location = maildir:/Library/Server/Mail/Data/mail/users/%%u:INDEX=/Library/Server/Mail/Data/mail/shared/%%u prefix = shared.%%u. separator = . subscriptions = no type = shared } namespace inbox { inbox = yes location = mailbox Drafts { special_use = \Drafts } mailbox Junk { special_use = \Junk } mailbox Sent { special_use = \Sent } mailbox "Sent Messages" { special_use = \Sent } mailbox Trash { special_use = \Trash } prefix = } namespace list-archives { list = children location = maildir:/Library/Server/Mail/Data/listserver/messages/archive/lists/%%u:INDEX=/Library/Server/Mail/Data/listserver/messages/archive/shared/%%u prefix = archives.%%u. separator = . subscriptions = no type = shared } passdb { driver = od } passdb { args = /Library/Server/Mail/Config/dovecot/submit.passdb driver = passwd-file } plugin { acl = vfile:/Library/Server/Mail/Config/dovecot/global-acls:cache_secs=300 acl_shared_dict = file:/Library/Server/Mail/Data/shared/shared-mailboxes fts = sk quota = maildir:User quota quota_warning = storage=100%% quota-exceeded %u sieve = /Library/Server/Mail/Data/rules/%u/dovecot.sieve sieve_dir = /Library/Server/Mail/Data/rules/%u stats_refresh = 30 secs stats_track_cmds = yes } postmaster_address = postmaster@biology.utah.edu protocols = imap pop3 lmtp sieve quota_full_tempfail = yes service auth { idle_kill = 15 mins unix_listener auth-userdb { user = _dovecot } } service dns_client { unix_listener dns-client { mode = 0600 } } service imap-login { inet_listener imap { port = 143 } inet_listener imaps { port = 993 ssl = yes } service_count = 0 } service imap { client_limit = 5 process_limit = 200 service_count = 0 } service indexer-worker { user = _dovecot } service lmtp { unix_listener lmtp { mode = 0600 } } service managesieve-login { inet_listener sieve { port = 4190 } } service pop3-login { inet_listener pop3 { port = 110 } inet_listener pop3s { port = 995 ssl = yes } } service pop3 { client_limit = 5 process_limit = 200 service_count = 0 } service quota-exceeded { executable = script /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/quota-exceeded.sh unix_listener quota-exceeded { group = mail mode = 0660 user = _dovecot } user = _dovecot } service quota-warning { executable = script /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/quota-warning.sh unix_listener quota-warning { group = mail mode = 0660 user = _dovecot } user = _dovecot } service stats { fifo_listener stats-mail { mode = 0600 user = _dovecot } } ssl_ca =
Here’s part of a crash report:
Process: auth [60325] Path: /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/auth Identifier: auth Version: 294 Code Type: X86-64 (Native) Parent Process: dovecotd [149] Responsible: dovecotd [149] User ID: 214
Date/Time: 2014-11-06 16:34:20.777 -0700 OS Version: Mac OS X 10.9.4 (13E28) Report Version: 11 Anonymous UUID: 9EB07E95-1536-96FA-A8C7-3784045DCDDE
Crashed Thread: 0 Dispatch queue: com.apple.main-thread
Exception Type: EXC_BAD_ACCESS (SIGSEGV) Exception Codes: KERN_INVALID_ADDRESS at 0x0000000000000000
VM Regions Near 0: --> __TEXT 0000000103b39000-0000000103b6a000 [ 196K] r-x/rwx SM=COW /Applications/Server.app/Contents/ServerRoot/usr/libexec/dovecot/auth
Thread 0 Crashed:: Dispatch queue: com.apple.main-thread 0 libsystem_c.dylib 0x00007fff8a181732 strlen + 18 1 libdovecot.0.dylib 0x0000000103bdc2b8 vstrconcat + 72
Thread 1: 0 libsystem_kernel.dylib 0x00007fff858f9e6a __workq_kernreturn + 10 1 libsystem_pthread.dylib 0x00007fff89901f08 _pthread_wqthread + 330 2 libsystem_pthread.dylib 0x00007fff89904fb9 start_wqthread + 13
Thread 2:: Dispatch queue: com.apple.libdispatch-manager 0 libsystem_kernel.dylib 0x00007fff858fa662 kevent64 + 10 1 libdispatch.dylib 0x00007fff8808f421 _dispatch_mgr_invoke + 239 2 libdispatch.dylib 0x00007fff8808f136 _dispatch_mgr_thread + 52
Thread 3: 0 libsystem_kernel.dylib 0x00007fff858f9e6a __workq_kernreturn + 10 1 libsystem_pthread.dylib 0x00007fff89901f08 _pthread_wqthread + 330 2 libsystem_pthread.dylib 0x00007fff89904fb9 start_wqthread + 13
Thread 0 crashed with X86 Thread State (64-bit): rax: 0x00007fff5c0c6878 rbx: 0x0000000000000001 rcx: 0x0000000000000001 rdx: 0x0000000000000001 rdi: 0x0000000000000000 rsi: 0x0000000103b6354d rbp: 0x00007fff5c0c6800 rsp: 0x00007fff5c0c6800 r8: 0x0000000103b6354e r9: 0x0000000000000000 r10: 0x00007fff8a1c92a8 r11: 0x00007fb60dca54c3 r12: 0x0000000000000028 r13: 0x00007fff5c0c6920 r14: 0x0000000000000028 r15: 0x0000000000000009 rip: 0x00007fff8a181732 rfl: 0x0000000000010246 cr2: 0x0000000000000000
Logical CPU: 0 Error Code: 0x00000004 Trap Number: 14
participants (1)
-
James Reynolds