Re: "ERR POP EOF or I/O Error" messages have begun appearing in the maillog file

Randall Gellens <[email protected]> Mon, 21 Dec 2009 18:47:33 -0800
Newsgroups gmane.mail.qpopper
Message-ID <[email protected]>
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'.