[H-GEN] Strangeness with POP3

[Ewan Edwards]

I haven't been able to figure out what is (not) going on here.  

I have a RH7.3 box set up as a mail server.  The MTA is Postfix 1.1.7 and all 
the clients are serviced by imap and ipop3 daemons from the imap-2001a 
package.  This mail server was brought on line two days ago when the Postfix 
and Mailman configuration was migrated from another RH7.3 box.  Also migrated 
were local user accounts, mail spool directory, and mail lists archives.

Everything seems to be working correctly except for a delay for pop clients.  
It appears there's a delay[1] happening between when xinetd launches a new 
instance of ipop3d and when the pop3 daemon exits.  There wasn't any delay 
noticed on the previous box.

When I started looking in the logs (in particular /var/log/maillog), I didn't 
see anything unusual until I noticed that the time on both /var/log/maillog 
and /var/log/secure was always the current time[2].  At that point I decided 
to tail -f both of them side by side and watch what happened when pop clients 
connected.  That's how I found the where the delay is happening.

Unfortunately, I don't know enough about what is supposed to be happening to 
know where to go from here.  After doing a bit of googling, my best guess is 
that its something to do with pam and authenticating each pop client 
connection.  Can anyone give me some clues or hints about where to look from 
here - please.


[1] The delay is between 16s and 21s.  See extract from /var/log/secure 
attached.
[2] Now that I think about it, this is probably to be expected with any 
reasonable number of mail users.

-------------- next part --------------
Feb 18 14:52:48 mail xinetd[15629]: EXIT: pop3 pid=18773 duration=20(sec)
Feb 18 14:52:49 mail xinetd[15629]: START: pop3 pid=18776 from=172.30.44.134
Feb 18 14:52:50 mail xinetd[15629]: EXIT: pop3 pid=18774 duration=21(sec)
Feb 18 14:52:57 mail xinetd[15629]: EXIT: pop3 pid=18775 duration=20(sec)
Feb 18 14:53:09 mail xinetd[15629]: EXIT: pop3 pid=18776 duration=20(sec)
Feb 18 14:53:28 mail xinetd[15629]: START: pop3 pid=18780 from=172.30.44.47
Feb 18 14:53:40 mail xinetd[15629]: START: pop3 pid=18783 from=172.30.44.114
Feb 18 14:53:45 mail xinetd[15629]: EXIT: pop3 pid=18780 duration=17(sec)
Feb 18 14:53:51 mail xinetd[15629]: START: pop3 pid=18784 from=172.30.44.131
Feb 18 14:53:55 mail xinetd[15629]: START: pop3 pid=18785 from=172.30.44.121
Feb 18 14:54:00 mail xinetd[15629]: EXIT: pop3 pid=18783 duration=20(sec)
Feb 18 14:54:12 mail xinetd[15629]: EXIT: pop3 pid=18784 duration=21(sec)
Feb 18 14:54:16 mail xinetd[15629]: EXIT: pop3 pid=18785 duration=21(sec)
Feb 18 14:54:16 mail xinetd[15629]: START: pop3 pid=18788 from=172.30.44.134
Feb 18 14:54:26 mail xinetd[15629]: START: pop3 pid=18789 from=172.30.44.115
Feb 18 14:54:28 mail xinetd[15629]: START: pop3 pid=18790 from=172.30.44.47
Feb 18 14:54:31 mail xinetd[15629]: START: pop3 pid=18791 from=172.30.44.102
Feb 18 14:54:36 mail xinetd[15629]: EXIT: pop3 pid=18788 duration=20(sec)
Feb 18 14:54:44 mail xinetd[15629]: START: pop3 pid=18792 from=172.30.44.129
Feb 18 14:54:46 mail xinetd[15629]: EXIT: pop3 pid=18789 duration=20(sec)
Feb 18 14:54:49 mail xinetd[15629]: EXIT: pop3 pid=18790 duration=21(sec)
Feb 18 14:54:52 mail xinetd[15629]: EXIT: pop3 pid=18791 duration=21(sec)
Feb 18 14:54:57 mail xinetd[15629]: START: pop3 pid=18794 from=172.30.44.117
Feb 18 14:55:04 mail xinetd[15629]: EXIT: pop3 pid=18792 duration=20(sec)
Feb 18 14:55:18 mail xinetd[15629]: EXIT: pop3 pid=18794 duration=21(sec)
Feb 18 14:55:28 mail xinetd[15629]: START: pop3 pid=18800 from=172.30.44.47
Feb 18 14:55:48 mail xinetd[15629]: EXIT: pop3 pid=18800 duration=20(sec)
Feb 18 14:55:49 mail xinetd[15629]: START: pop3 pid=18801 from=172.30.44.38
Feb 18 14:56:09 mail xinetd[15629]: EXIT: pop3 pid=18801 duration=20(sec)
Feb 18 14:56:12 mail xinetd[15629]: START: pop3 pid=18804 from=172.30.44.131