Issue

• As our customer encountered the problem that sending/receiving mail became unsteady or authentication for mail-send failed, and many following messages were logged in /var/log/messages.

dovecot: auth(default): userdb( USER_NAME , IP_ADDER ): user not found from userdb

• Checking /var/log/maillog furthermore, the target user of above message succeeded in login around the time. So, it looks that it was not in a situation which "user not found from userdb" shows. Here is excerpt of /var/log/maillog:

(1)Apr 16 21:48:46 server dovecot: pop3-login: Login: user=<xxx>, method=PLAIN, rip=::ffff:172.24.200.15, lip=::ffff:172.25.5.6, TLS
   Apr 16 21:48:46 server dovecot: POP3(xxx): Disconnected: Logged out top=0/0, retr=1/1650, del=0/500, size=77683062
    :  : <snip>
(2)Apr 16 21:49:30 server dovecot: auth(default): userdb(xxx,::ffff:172.24.200.2): user not found from userdb
   Apr 16 21:49:30 server dovecot: pop3-login: Internal login failure: user=<xxx>, method=PLAIN, rip=::ffff:172.24.200.2, lip=::ffff:172.25.5.6, TLS
    :  : <snip>
(3)Apr 16 21:49:32 server dovecot: pop3-login: Login: user=<xxx>, method=PLAIN, rip=::ffff:172.24.200.2, lip=::ffff:172.25.5.6, TLS
   Apr 16 21:49:32 server dovecot: POP3(xxx): Disconnected: Logged out top=0/0, retr=1/6595, del=0/501, size=77689640

• Authentication of xxx user succeeded at place of (1), but it failed at place of (2), and it succeeded again at place of (3).

• Also, checking /var/log/secure, pam_winbind logged the same log as normal status and any errors were not found. Here is /var/log/secure:

(1)Apr 16 21:48:46 server dovecot-auth: pam_winbind(dovecot:auth): getting password (0x00000000)
(1)Apr 16 21:48:46 server dovecot-auth: pam_winbind(dovecot:auth): user 'xxx' granted access
(1)Apr 16 21:48:46 server dovecot-auth: pam_winbind(dovecot:account): user 'xxx' granted access
(2)Apr 16 21:49:30 server dovecot-auth: pam_winbind(dovecot:auth): getting password (0x00000000)
(2)Apr 16 21:49:30 server dovecot-auth: pam_winbind(dovecot:auth): user 'xxx' granted access
(2)Apr 16 21:49:30 server dovecot-auth: pam_winbind(dovecot:account): user 'xxx' granted access
(3)Apr 16 21:49:32 server dovecot-auth: pam_winbind(dovecot:auth): getting password (0x00000000)
(3)Apr 16 21:49:32 server dovecot-auth: pam_winbind(dovecot:auth): user 'xxx' granted access
(3)Apr 16 21:49:32 server dovecot-auth: pam_winbind(dovecot:account): user 'xxx' granted access

• Any errors are not logged around Apr 16 21:49:30.

• The customer tried to change /etc/pam.d/dovecot as the following and since that the symptom has disappeared. This configuration is valid?

  • Before change:

    auth sufficient /lib/security/pam_winbind.so
    

  • After change:

    auth sufficient /lib/security/pam_winbind.so cached_login use_first_pass