At 12:09 PM -0700 12/20/09, Keith Christian wrote:
Qpopper has been performing very well for us but lately (within the
last month) we've begun seeing quite a few (50 or more per day) of
these type of messages in the /var/log/maillog file (times, usernames,
and IP's have been changed.)
Dec 14 HH:MM:50 mailserver14414 popper[20830]: (v4.0.8) Servicing
request from "www.xxx.yyy.zzz" at www.xxx.yyy.zzz
Dec 14 HH:MM:50 mailserver14414 popper[20830]: (null) at
www.xxx.yyy.zzz (www.xxx.yyy.zzz): -ERR POP EOF or I/O Error
Dec 14 HH:MM:50 mailserver14414 popper[20831]: (v4.0.8) Servicing
request from "www.xxx.yyy.zzz" at www.xxx.yyy.zzz
Dec 14 HH:MM:50 mailserver14414 popper[20831]: (null) at
www.xxx.yyy.zzz (www.xxx.yyy.zzz): -ERR POP EOF or I/O Error
Dec 14 HH:MM:37 mailserver14414 popper[5619]: someuser15357 at
www.xxx.yyy.zzz (www.xxx.yyy.zzz): -ERR POP EOF or I/O Error
Dec 15 HH:MM:10 mailserver14414 popper[29457]: someuser1383 at
www.xxx.yyy.zzz (www.xxx.yyy.zzz): -ERR POP EOF or I/O Error
Dec 15 HH:MM:10 mailserver14414 popper[29457]: Stats: someuser1383 0 0
4 471851 www.xxx.yyy.zzz www.xxx.yyy.zzz
These occur anytime of day or night, and this behavior lasts anywhere
from a few minutes to a few hours. We had an eposode that ran for
about 2-1/2 hours yesterday.
Strangely, some of these occur with a user account (e.g. someuser15357
and/or someuser1383) are in the -ERR POP EOF or I/O Error line, but
the vast majority of these -ERR POP EOF or I/O Error lines have
"(null)" as the username.
Would appreciate any ideas. No other issues with the version of
Qpopper we're running, even though it's a bit older (v4.0.8) so I'm
not inclined to think it's the age of the build. OS is RHEL4 WS
Linux.
The error message indicates that the connection with the client ended
abruptly; Qpopper got an error trying to read data from the client.
The presence or absence of a user account tells you if the
disconnection occurred before or after the user authenticated.
So, I think the question is: Why are you getting more of these now,
and why do you get these in flurries, instead of sporadically?
The error could be the client timing out and closing the connection
without sending a QUIT, or something in between the client and the
server (a NAT box maybe) sending a TCP RST to close the connection.
The client could be timing out because of network problems (for
example, congestion or other problems causing high packet loss,
forcing retransmission of packets and high latency), or server
problems delaying the Qpopper response, or client problems or
misconfiguration (such as a too-short timeout).
The log snippets above suggest that the error happens immediately
(same second) as the initial connection. Is this happening
generally? If so, it would tend to rule out the timeout situation,
suggesting instead a network box or problem with the client.
There are several things you can do to get more information and track
it down further. One would be to enable Qpopper debugging/trace
records, and another would be packet sniffing. If you can identify
certain clients or connections that tend to show the problem, you can
use Qpopper tracing or packet sniffing for those, to reduce the
amount of data.
To enable tracing in Qpopper:
1. Do a 'make clean'
2. Re-run ./configure, adding '--enable-debugging'.
If Qpopper is run from inetd/xinetd:
3. Edit the inetd.conf line for Qpopper, adding '-d' or '-t <tracefile-path>'.
4. Send inetd (or xinetd) a HUP signal.
If Qpopper is run in standalone mode:
3. Add '-d' or '-t <tracefile-path>' to the command line
or
If you use a configuration file (in either inetd/xinetd or
standalone), you can instead:
3. Add 'set debug' or 'set tracefile = /some/path/tracefile' to
either a global or user-specific configuration file.
This causes detailed tracing to be written to the syslog or to the
file specified as 'tracefile'.
