[Dovecot] PAM timed out, kill failed, auth SEGV

[Thomas Arnett]

My log is full of blocks like this:
auth(default): pam(?): PAM child process 13576 timed out, killing it
auth(default): PAM: kill(13576) failed: No such process

Often, this is recorded for several pids at once.

Occasionally, there's a single burst when a virtual user logs in,  
immediately before pam_authenticate() fails and checkpassword is  
executed.  When this happens, pam() contains the username and remote IP.

Usually, it starts 2 minutes after a login attempt (successful or  
not) and repeats every 10 seconds indefinitely.  pam() contains  
something else:
~87%	?
~ 9%	[garbage],master
~ 4%	?,master
< 1%	[empty]

[garbage] varies; it seems to be constant for an instance of auth,  
but I haven't verified this.

Eventually, auth segfaults:
Core was generated by `dovecot-auth'.
Program terminated with signal 11, Segmentation fault.
...
#0  0x08087a68 in str_sanitize_append (dest=0x80a8950, src=0x3d9  
<Address 0x3d9 out of bounds>, max_len=64) at str-sanitize.c:11
         p = 0x3d9 <Address 0x3d9 out of bounds>
#1  0x08057a1d in get_log_str (auth_request=0x80c6a00,  
subsystem=0x808f7cd "pam", format=0x808f9ac "PAM child process %s  
timed out, killing it", va=0x597f8c5c ":\211\n\b?|\t\b?|\t\b?\214\177Y")
     at auth-request.c:1121
         ip = 0xa <Address 0xa out of bounds>
         str = (string_t *) 0x80a8950
#2  0x08057c62 in auth_request_log_error (auth_request=0x80c6a00,  
subsystem=0x808f7cd "pam", format=0x808f9ac "PAM child process %s  
timed out, killing it") at auth-request.c:1177
         va = 0x597f8c5c ":\211\n\b?|\t\b?|\t\b?\214\177Y"
#3  0x080658ee in pam_child_timeout (context=0x0) at passdb-pam.c:537
         request = (struct pam_auth_request *) 0x80c6de8
         iter = (struct hash_iterate_context *) 0x80bcdb0
         key = (void *) 0xa9e
         value = (void *) 0x80c6de8
         timeout = 1182548633
#4  0x08079fc5 in io_loop_handle_timeouts (ioloop=0x80b09b0,  
update_run_now=true) at ioloop.c:294
         t = (struct timeout *) 0x80b4ca8
         called_timeouts = (struct timeout *) 0x80b4ca8
         tv = {tv_sec = 0, tv_usec = 0}
         t_id = 2
#5  0x0807b32e in io_loop_handler_run (ioloop=0x80b09b0) at ioloop- 
epoll.c:175
         ctx = (struct ioloop_handler_context *) 0x80b09d8
         events = (struct epoll_event *) 0x80b0a18
         event = (const struct epoll_event *) 0x80b0a18
         list = (struct io_list *) 0x80c42d8
         io = (struct io *) 0x0
         tv = {tv_sec = 1, tv_usec = 180418}
         events_count = 12
         t_id = 2
         msecs = 1181
         ret = 0
         i = 1
         j = 3
         call = true
#6  0x0807a0a8 in io_loop_run (ioloop=0x80b09b0) at ioloop.c:329
No locals.
#7  0x0805d7ee in main (argc=1, argv=0x597f8ec4) at main.c:321
         foreground = false

My config (Gentoo Linux hardened/x86/2.6):
# 1.0.1: /etc/dovecot/dovecot.conf
listen: [::1]
ssl_listen: [::]
ssl_cert_file: /etc/ssl/misfeature.net/crt
ssl_key_file: /etc/ssl/misfeature.net/key
ssl_cipher_list: HIGH
login_dir: /var/run/dovecot/login
login_executable: /usr/libexec/dovecot/imap-login
login_greeting_capability: yes
verbose_proctitle: yes
first_valid_uid: 1000
first_valid_gid: 100
mail_location: maildir:~/mail
mail_debug: yes
maildir_copy_with_hardlinks: yes
mail_drop_priv_before_exec: yes
imap_client_workarounds: delay-newmail outlook-idle
auth default:
   verbose: yes
   debug: yes
   passdb:
     driver: pam
     args: *
   passdb:
     driver: checkpassword
     args: /usr/local/bin/checkpassword
   userdb:
     driver: passwd
   userdb:
     driver: prefetch
   socket:
     type: listen
     client:
       path: /var/spool/postfix/private/auth
       mode: 432
       user: postfix
       group: postfix

I turned on the various logging options while investigating this  
problem; the messages appear even without.

-- TA