I've been running qpopper 4.0.3 for months now with little to no problems. However, a couple of hours ago we started have significant problems with POP sessions hanging during the middle of a download. When I look at the log file, I see lots of error messages like the following:
Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: I/O error flushing output to client USERNAME at IP.impulse.net [207.154.0.0]: Operation not permitted (1) Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: USERNAME at IP.dia.impulse.net (207.154.0.0): -ERR SIGHUP or SIGPIPE flagged Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: I/O error flushing output to client USERNAME at IP.dia.impulse.net [207.154.0.0]: Operation not permitted (1) Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: USERNAME at IP.dia.impulse.net (207.154.0.0): -ERR POP hangup from red.impulse.net Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: I/O error flushing output to client USERNAME at IP.dia.impulse.net [207.154.0.0]: Operation not permitted (1) Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: Stats: USERNAME 0 0 7 114185 IP.dia.impulse.net 207.154.0.0 Mar 18 21:35:45 red /usr/local/libexec/qpopper[5913]: I/O error flushing output to client USERNAME at IP.dia.impulse.net [207.154.0.0]: Operation not permitted (1) Over the last week, we'd usually see ~20-30 of these messages each day. However, we've seen over 200 of these errors today. I tried a trace on the qpopper server running on an alternate port in with --enable-low-debug compiled in and got the following messages (IPs and usernames have been masked for privacy): Mar 18 20:41:39.320 2002 [75954] Opened trace file "/tmp/qpopper.debug" as 4 Mar 18 20:41:39.320 2002 Mar 18 20:41:39.320 2002 [75954] opened stream socket; sockfd = 6 Mar 18 20:41:39.320 2002 Mar 18 20:41:39.320 2002 [75954] set stream socket options; sockfd = 6 Mar 18 20:41:39.320 2002 Mar 18 20:41:39.320 2002 [75954] did bind on stream socket; sockfd = 6 Mar 18 20:41:39.320 2002 Mar 18 20:41:39.320 2002 [75954] popper: Server: listening on 0.0.0.0:8765 Mar 18 20:41:39.320 2002 Mar 18 20:41:39.320 2002 [75954] listening using socket fd 6 Mar 18 20:41:39.320 2002 Mar 18 20:41:39.320 2002 [75954] set fd 6 non-blocking (0x6) Mar 18 20:41:39.320 2002 Mar 18 20:55:51.969 2002 [75954] accept=7; sockfd=6; clilen=16; cli_addr=207.154.0.0:3010 Mar 18 20:55:51.969 2002 Mar 18 20:55:51.986 2002 [75954] new connection; fd=7 Mar 18 20:55:51.986 2002 Mar 18 20:55:51.986 2002 [75954] newsockfd (7) flags: 0x6 Mar 18 20:55:51.986 2002 Mar 18 20:55:51.986 2002 [75954] set fd 7 blocking (0x2) Mar 18 20:55:51.986 2002 Mar 18 20:55:51.997 2002 [75954] Set downcase-user to true Mar 18 20:55:51.997 2002 Mar 18 20:55:51.997 2002 [75954] Set fast-update to true Mar 18 20:55:51.997 2002 Mar 18 20:55:51.997 2002 [75954] Set reverse-lookup to false Mar 18 20:55:51.997 2002 Mar 18 20:55:51.997 2002 [75954] Set mail-command to "/usr/sbin/sendmail" Mar 18 20:55:51.997 2002 Mar 18 20:55:51.998 2002 [75954] Set statistics to true Mar 18 20:55:51.998 2002 Mar 18 20:55:51.998 2002 [75954] Set user-options to true Mar 18 20:55:51.998 2002 Mar 18 20:55:52.420 2002 [75954] (v4.0.3_DEBUG) POP login by user "USERNAME" at (* _DEBUG *) * _DEBUG * Mar 18 20:55:52.420 2002 Mar 18 20:55:52.721 2002 [75954] ...FillMangleInfo; commandline(10)= ugar.cane Mar 18 20:55:52.721 2002 Mar 18 20:58:39.126 2002 [75954] I/O error flushing output to client USERNAME at * _DEBUG * [* _DEBUG *]: Operation not permitted (1) Mar 18 20:58:39.126 2002 Mar 18 20:58:39.126 2002 [75954] USERNAME at localhost: -ERR SIGHUP or SIGPIPE flagged Mar 18 20:58:39.126 2002 Mar 18 20:58:39.126 2002 [75954] I/O error flushing output to client USERNAME at * _DEBUG * [* _DEBUG *]: Operation not permitted (1) Mar 18 20:58:39.126 2002 Mar 18 20:58:39.126 2002 [75954] USERNAME at localhost: -ERR POP hangup from DEBUG Mar 18 20:58:39.126 2002 Mar 18 20:58:39.126 2002 [75954] I/O error flushing output to client USERNAME at * _DEBUG * [* _DEBUG *]: Operation not permitted (1) Mar 18 20:58:39.126 2002 Mar 18 20:58:39.126 2002 [75954] Stats: USERNAME 0 0 10 439419 * _DEBUG * * _DEBUG * Mar 18 20:58:39.126 2002 Mar 18 20:58:39.127 2002 [75954] I/O error flushing output to client USERNAME at * _DEBUG * [* _DEBUG *]: Operation not permitted (1) Mar 18 20:58:39.127 2002 Mar 18 20:58:39.127 2002 [75954] exiting after Qpopper returned Mar 18 20:58:39.127 2002 Any thoughts? The debug log seems rather empty. Did I miss a command line argument? I used ./qpopper -t -f <path to normal config file> If necessary, I can rerun the debugging run again, but not until the morning, when I can get a holf of a user who knows enough to change his POP port. I'd appreciate any input you all have. Thanks. --Ted Cabeen
