I have been having a strange issue with authdaemond ever since it
split into a seperate auth port. I am running FreeBSD 5.4, net-
qmail, vpopmail, Courier-IMAP, and using a mysql backend to
vpopmail. The only authentication package I use or need is the
vchkpw. Most or all of these are pretty late versions of these
programs.
Well, what seems to be the problem is during a server *reboot*
1. authdaemond boots up, using an rc.d script (FreeBSD's autoexec
files)
2. I think this is before mysql is loaded.
3. auth requests come in to the IMAP server almost immediately.
4. ALL AUTHs FAIL until I do the following.
When I get to the root shell a few hours later, I can get AUTHs
working by restarting the daemons (I frantically restart imap,
authdaemond, and mysql). But, by the way, the authdaemond script
is broken, and I have to stop and start it (typing /usr/local/etc/
rc.d/courier-authdaemond.sh restart only stops the daemon).
At this stage, all AUTHs now work! Yeah! But what is going on?
During the AUTH failures, nobody can login, and everyone has to
retype their mail passwords (Mozilla, for example, resets the IMAP
password)
Here is what mysql logs said. Notice, it appears that mysql
started *AFTER* the first AUTH attempt.
050601 02:28:45 mysqld started
050601 2:28:49 InnoDB: Started; log sequence number 0 43740
/usr/local/libexec/mysqld: ready for connections.
Version: '4.1.11' socket: '/tmp/mysql.sock' port: 3306 FreeBSD
port: mysql-server-4.1.11_1
Here is my mail and debug log. I tried to put in spaces just to
show different user login attempts.
Jun 1 02:28:40 ibm authdaemond: modules="authvchkpw", daemons=5
Jun 1 02:28:40 ibm authdaemond: Installing libauthvchkpw
Jun 1 02:28:40 ibm authdaemond: Installation complete: authvchkpw
Jun 1 02:28:41 ibm imapd: Connection, ip=[192.168.0.11]
Jun 1 02:28:41 ibm authdaemond: received auth request,
service=imap, authtype=login
Jun 1 02:28:41 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:41 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:41 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:41 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:41 ibm imapd: LOGIN FAILED, user=test, ip=[192.168.0.11]
Jun 1 02:28:42 ibm pop3d: Connection, ip=[192.168.0.18]
Jun 1 02:28:42 ibm authdaemond: received auth request,
service=pop3, authtype=login
Jun 1 02:28:42 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:42 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:42 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:42 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:42 ibm pop3d: LOGIN FAILED, user=tester, ip=
[192.168.0.18]
Jun 1 02:28:44 ibm pop3d: Connection, ip=[192.168.0.17]
Jun 1 02:28:44 ibm authdaemond: received auth request,
service=pop3, authtype=login
Jun 1 02:28:44 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:44 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:44 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:44 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:44 ibm pop3d: LOGIN FAILED, user=ppp, ip=[192.168.0.17]
Jun 1 02:28:44 ibm imapd: Connection, ip=[127.0.0.1]
Jun 1 02:28:44 ibm imapd: LOGOUT, ip=[127.0.0.1]
Jun 1 02:28:45 ibm pop3d: Connection, ip=[192.168.0.9]
Jun 1 02:28:45 ibm authdaemond: received auth request,
service=pop3, authtype=login
Jun 1 02:28:45 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:45 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:45 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:45 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:45 ibm pop3d: LOGIN FAILED, user=gggg, ip=[192.168.0.9]
Jun 1 02:28:46 ibm imapd: Disconnected, ip=[192.168.0.11], time=5
Jun 1 02:28:46 ibm pop3d: Connection, ip=[192.168.0.6]
Jun 1 02:28:46 ibm authdaemond: received auth request,
service=pop3, authtype=login
Jun 1 02:28:46 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:46 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:46 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:46 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:46 ibm authdaemond: vmysql: sql error[3]: MySQL server
has gone away
Jun 1 02:28:46 ibm pop3d: LOGIN FAILED, user=jjj, ip=[192.168.0.6]
Jun 1 02:28:47 ibm pop3d: Disconnected, ip=[192.168.0.18]
Jun 1 02:28:49 ibm pop3d: Disconnected, ip=[192.168.0.17]
Jun 1 02:28:50 ibm pop3d: Disconnected, ip=[192.168.0.9]
Jun 1 02:28:51 ibm pop3d: Connection, ip=[192.168.0.21]
Jun 1 02:28:51 ibm authdaemond: received auth request,
service=pop3, authtype=login
Jun 1 02:28:51 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:51 ibm authdaemond: authvchkpw: sysusername=<null>,
sysuserid=89, sysgroupid=89, homedir=/usr/local/vpopmail/domains/
aaa.com/ccc, [EMAIL PROTECTED], fullname=ccc, maildir=<null>,
quota=<null>, options=disablewebmail=0,disablepop3=0,disableimap=0
Jun 1 02:28:51 ibm authdaemond: password matches successfully
Jun 1 02:28:51 ibm authdaemond: Authenticated: sysusername=<null>,
sysuserid=89, sysgroupid=89, homedir=/usr/local/vpopmail/domains/
aaa.com/ccc, [EMAIL PROTECTED], fullname=CCC CCC, maildir=<null>,
quota=<null>, options=disablewebmail=0,disablepop3=0,disableimap=0
Jun 1 02:28:51 ibm pop3d: LOGIN, [EMAIL PROTECTED], ip=[192.168.0.21]
Jun 1 02:28:51 ibm pop3d: LOGOUT, [EMAIL PROTECTED], ip=
[192.168.0.21], top=0,
Jun 1 02:28:51 ibm pop3d: Disconnected, ip=[192.168.0.6]
Jun 1 02:28:53 ibm imapd: Connection, ip=[192.168.0.18]
Jun 1 02:28:53 ibm authdaemond: received auth request,
service=imap, authtype=login
Jun 1 02:28:53 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:53 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:53 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:53 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:53 ibm authdaemond: vmysql: sql error[3]: MySQL server
has gone away
Jun 1 02:28:53 ibm imapd: LOGIN FAILED, user=jee, ip=[192.168.0.18]
Jun 1 02:28:53 ibm imapd: Connection, ip=[192.168.0.6]
Jun 1 02:28:53 ibm authdaemond: received auth request,
service=imap, authtype=login
Jun 1 02:28:53 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:53 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:53 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:53 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:53 ibm authdaemond: vmysql: sql error[3]: MySQL server
has gone away
Jun 1 02:28:53 ibm imapd: LOGIN FAILED, user=jjj, ip=[192.168.0.6]
Jun 1 02:28:53 ibm imapd: Connection, ip=[192.168.0.6]
Jun 1 02:28:53 ibm authdaemond: received auth request,
service=imap, authtype=login
Jun 1 02:28:53 ibm authdaemond: authvchkpw: trying this module
Jun 1 02:28:53 ibm authdaemond: vchkpw: user does not exist
Jun 1 02:28:53 ibm authdaemond: authvchkpw: REJECT - try next module
Jun 1 02:28:53 ibm authdaemond: FAIL, all modules rejected
Jun 1 02:28:53 ibm authdaemond: vmysql: sql error[3]: MySQL server
has gone away
Jun 1 02:28:53 ibm imapd: LOGIN FAILED, user=c11, ip=[192.1068.0.6]
Jun 1 02:28:53 ibm authdaemond: vmysql: sql error[3]: MySQL server
has gone away
Thanks for your help,
Billy
