[tpop3d-discuss] Duplicate emails/client timeouts
Matthew Trent
mtrent at localaccess.com
Fri, 16 Jan 2004 16:29:41 -0800
Still getting a lot of complaints (including one from my boss, which is why
I'm posting about this again <g>) about duplicate emails and "clogs" (as
we've grown to call them). Only happens with MS mail clients. They all seem
to match up with a "net_loop: timed out client" message in the tpop logs.
Sometimes it seems to clear itself up, sometimes we have to go in and delete
emails for users to get email flowing again. It doesn't seem to be
duplicateable, and there isn't any particular pattern (not all messages with
attachments or certain strings in messages or anything I can think of).
I'm running the latest tpop3d CVS.
Yesterday I grepped 300 timeouts in the logs. Seems pretty high... Could some
of you using tpop3d in high-traffic environments (we have 10,000+ email
boxes) grep your logs for timeouts and post how many you find?
I have no doubt it's an MS bug, but that's 99% of our users! :)
I'd be happy to set up an email account on our server for testing.
Another interesting thing is they seem to happen in pairs:
mail1:~# grep "timed out client" /var/log/mail.log
Jan 16 14:14:39 mail1 tpop3d[31476]: net_loop: timed out client
[6]fredsue(69.10.192.145)
Jan 16 14:14:40 mail1 tpop3d[31476]: net_loop: timed out client
[6]fredsue(69.10.192.145)
Jan 16 14:22:24 mail1 tpop3d[4398]: net_loop: timed out client [6]
69.10.192.39/mashell.com
Jan 16 14:22:33 mail1 tpop3d[4398]: net_loop: timed out client [7]
69.10.192.39/mashell.com
Jan 16 14:29:26 mail1 tpop3d[768]: net_loop: timed out client
[7]lenm(69.10.200.187)
Jan 16 14:29:27 mail1 tpop3d[768]: net_loop: timed out client
[7]lenm(69.10.200.187)
Jan 16 14:49:07 mail1 tpop3d[5549]: net_loop: timed out client
[6]centparks(69.10.201.175)
Jan 16 14:49:08 mail1 tpop3d[5549]: net_loop: timed out client
[6]centparks(69.10.201.175)
Jan 16 15:27:20 mail1 tpop3d[1556]: net_loop: timed out client [7]rd0912
(69.10.192.130)
Jan 16 15:27:21 mail1 tpop3d[1556]: net_loop: timed out client [7]rd0912
(69.10.192.130)
Probably duplicate email for each of those pairs of timeouts. Seems like the
client gets the message downloaded, but doesn't correctly finish the POP3
session so it doesn't remember it's seen that message and downloads it again
next time.
Here are some example log entries. The first one (username: jerry) is on the
same ethernet network with the mail server. It's not a dialup disconnecting
and timing out or anything. The "jerry" logs here are different, though, in
that most of the timeouts are after a RETR.
Jan 15 08:03:56 mail2 tpop3d[11880]: connection_sendresponse: client [7]
69.10.194.41/mashell.com: sent `+OK
<c06f4b2d7f29156519e961e38d92ee4d@mashell.com>'
Jan 15 08:49:08 mail2 tpop3d[11880]: fork_child: [6]jerry(69.10.205.98): began
session for `jerry' with mysql; child PID is 15651
Jan 15 08:49:08 mail2 tpop3d[15651]: maildir_new: scanned maildir /var/spool/
store/SERVERS/localaccess.com/jerry (1 messages) in 0.001s
Jan 15 08:49:08 mail2 tpop3d[15651]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK Welcome aboard! You have exactly one
message.'
Jan 15 08:49:09 mail2 tpop3d[15651]: connection_parsecommand: client
[6]jerry(69.10.205.98): received `STAT'
Jan 15 08:49:09 mail2 tpop3d[15651]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK 1 3231'
Jan 15 08:49:09 mail2 tpop3d[15651]: connection_parsecommand: client
[6]jerry(69.10.205.98): received `UIDL 1'
Jan 15 08:49:09 mail2 tpop3d[15651]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK 1 f3cc1a501b62ebcc4b89558354418506'
Jan 15 08:49:09 mail2 tpop3d[15651]: connection_parsecommand: client
[6]jerry(69.10.205.98): received `TOP 1 640'
Jan 15 08:49:09 mail2 tpop3d[15651]: do_top: client [6]jerry(69.10.205.98):
sending headers and up to 640 lines of message 1 (< 3231 bytes)
Jan 15 08:49:09 mail2 tpop3d[15651]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK Message follows'
Jan 15 08:49:09 mail2 tpop3d[15651]: do_top: client [6]jerry(69.10.205.98):
sent headers and up to 640 lines of message 1
Jan 15 08:49:40 mail2 tpop3d[15651]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `-ERR Client has been idle for too long.'
Jan 15 08:49:40 mail2 tpop3d[15651]: net_loop: timed out client
[6]jerry(69.10.205.98)
Jan 15 08:49:40 mail2 tpop3d[15651]: connections_post_select: client
[6]jerry(69.10.205.98): finished session for `jerry' with mysql
Jan 15 08:49:40 mail2 tpop3d[15651]: connections_post_select: client
[6]jerry(69.10.205.98): disconnected; 56/3645 bytes read/written
------------------------------------------------------
Jan 15 12:48:34 mail1 tpop3d[12906]: fork_child: [6]jerry(69.10.205.98): began
session for `jerry' with mysql; child PID is 26663
Jan 15 12:48:34 mail1 tpop3d[26663]: maildir_new: scanned maildir /var/spool/
store/SERVERS/localaccess.com/jerry (1 messages) in 0.003s
Jan 15 12:48:34 mail1 tpop3d[26663]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK Welcome aboard! You have exactly one
message.'
Jan 15 12:48:34 mail1 tpop3d[26663]: connection_parsecommand: client
[6]jerry(69.10.205.98): received `STAT'
Jan 15 12:48:34 mail1 tpop3d[26663]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK 1 3761'
Jan 15 12:48:34 mail1 tpop3d[26663]: connection_parsecommand: client
[6]jerry(69.10.205.98): received `UIDL'
Jan 15 12:48:34 mail1 tpop3d[26663]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `+OK ID list follows:'
Jan 15 12:48:34 mail1 tpop3d[26663]: do_uidl: client [6]jerry(69.10.205.98):
sent 2-line unique ID list
Jan 15 12:49:05 mail1 tpop3d[26663]: connection_sendresponse: client
[6]jerry(69.10.205.98): sent `-ERR Client has been idle for too long.'
Jan 15 12:49:05 mail1 tpop3d[26663]: net_loop: timed out client
[6]jerry(69.10.205.98)
Jan 15 12:49:05 mail1 tpop3d[26663]: connections_post_select: client
[6]jerry(69.10.205.98): finished session for `jerry' with mysql
Jan 15 12:49:05 mail1 tpop3d[26663]: connections_post_select: client
[6]jerry(69.10.205.98): disconnected; 37/249 bytes read/written
--------------------------------------------------------------
Jan 16 15:56:37 mail1 tpop3d[4398]: fork_child: [6]jchorley(69.10.192.67):
began session for `jchorley' with mysql; child PID is 14091
Jan 16 15:56:37 mail1 tpop3d[14091]: maildir_new: scanned maildir /var/spool/
store/SERVERS/mashell.com/jchorley (3 messages) in 0.016s
Jan 16 15:56:37 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `+OK Welcome aboard! You have 3 messages.'
Jan 16 15:56:38 mail1 tpop3d[14091]: connection_parsecommand: client
[6]jchorley(69.10.192.67): received `STAT'
Jan 16 15:56:38 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `+OK 3 9681'
Jan 16 15:56:38 mail1 tpop3d[14091]: connection_parsecommand: client
[6]jchorley(69.10.192.67): received `LIST'
Jan 16 15:56:38 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `+OK Scan list follows:'
Jan 16 15:56:38 mail1 tpop3d[14091]: do_list: client
[6]jchorley(69.10.192.67): sent 4-line scan list
Jan 16 15:56:44 mail1 tpop3d[14091]: connection_parsecommand: client
[6]jchorley(69.10.192.67): received `RETR 1'
Jan 16 15:56:44 mail1 tpop3d[14091]: do_retr: client
[6]jchorley(69.10.192.67): sending message 1 (1289 bytes)
Jan 16 15:56:44 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `+OK Message follows'
Jan 16 15:56:44 mail1 tpop3d[14091]: do_retr: client
[6]jchorley(69.10.192.67): sent message 1
Jan 16 15:56:45 mail1 tpop3d[14091]: connection_parsecommand: client
[6]jchorley(69.10.192.67): received `RETR 2'
Jan 16 15:56:45 mail1 tpop3d[14091]: do_retr: client
[6]jchorley(69.10.192.67): sending message 2 (3109 bytes)
Jan 16 15:56:45 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `+OK Message follows'
Jan 16 15:56:46 mail1 tpop3d[14091]: do_retr: client
[6]jchorley(69.10.192.67): sent message 2
Jan 16 15:56:51 mail1 tpop3d[14091]: connection_parsecommand: client
[6]jchorley(69.10.192.67): received `RETR 3'
Jan 16 15:56:51 mail1 tpop3d[14091]: do_retr: client
[6]jchorley(69.10.192.67): sending message 3 (5283 bytes)
Jan 16 15:56:51 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `+OK Message follows'
Jan 16 15:56:51 mail1 tpop3d[14091]: do_retr: client
[6]jchorley(69.10.192.67): sent message 3
Jan 16 15:57:22 mail1 tpop3d[14091]: connection_sendresponse: client
[6]jchorley(69.10.192.67): sent `-ERR Client has been idle for too long.'
Jan 16 15:57:22 mail1 tpop3d[14091]: net_loop: timed out client
[6]jchorley(69.10.192.67)
Jan 16 15:57:22 mail1 tpop3d[14091]: connections_post_select: client
[6]jchorley(69.10.192.67): finished session for `jchorley' with mysql
Jan 16 15:57:22 mail1 tpop3d[14091]: connections_post_select: client
[6]jchorley(69.10.192.67): disconnected; 64/10182 bytes read/written
------------------------------------------------------
Jan 16 14:04:49 mail1 tpop3d[4398]: fork_child: [6]fredsue(69.10.192.145):
began session for `fredsue' with mysql; child PID is 31476
Jan 16 14:04:49 mail1 tpop3d[31476]: maildir_new: scanned maildir /var/spool/
store/SERVERS/mashell.com/fredsue (3 messages) in 0.055s
Jan 16 14:04:49 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `+OK Welcome aboard! You have 3 messages.'
Jan 16 14:04:50 mail1 tpop3d[31476]: connection_parsecommand: client
[6]fredsue(69.10.192.145): received `STAT'
Jan 16 14:04:50 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `+OK 3 6486989'
Jan 16 14:04:50 mail1 tpop3d[31476]: connection_parsecommand: client
[6]fredsue(69.10.192.145): received `LIST'
Jan 16 14:04:50 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `+OK Scan list follows:'
Jan 16 14:04:50 mail1 tpop3d[31476]: do_list: client
[6]fredsue(69.10.192.145): sent 4-line scan list
Jan 16 14:04:50 mail1 tpop3d[31476]: connection_parsecommand: client
[6]fredsue(69.10.192.145): received `RETR 1'
Jan 16 14:04:50 mail1 tpop3d[31476]: do_retr: client
[6]fredsue(69.10.192.145): sending message 1 (31812 bytes)
Jan 16 14:04:50 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `+OK Message follows'
Jan 16 14:04:50 mail1 tpop3d[31476]: do_retr: client
[6]fredsue(69.10.192.145): sent message 1
Jan 16 14:05:02 mail1 tpop3d[31476]: connection_parsecommand: client
[6]fredsue(69.10.192.145): received `RETR 2'
Jan 16 14:05:02 mail1 tpop3d[31476]: do_retr: client
[6]fredsue(69.10.192.145): sending message 2 (19304 bytes)
Jan 16 14:05:02 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `+OK Message follows'
Jan 16 14:05:03 mail1 tpop3d[31476]: do_retr: client
[6]fredsue(69.10.192.145): sent message 2
Jan 16 14:05:09 mail1 tpop3d[31476]: connection_parsecommand: client
[6]fredsue(69.10.192.145): received `RETR 3'
Jan 16 14:05:09 mail1 tpop3d[31476]: do_retr: client
[6]fredsue(69.10.192.145): sending message 3 (6435873 bytes)
Jan 16 14:05:09 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `+OK Message follows'
Jan 16 14:05:10 mail1 tpop3d[31476]: do_retr: client
[6]fredsue(69.10.192.145): sent message 3
Jan 16 14:14:39 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `-ERR Client has been idle for too long.'
Jan 16 14:14:39 mail1 tpop3d[31476]: net_loop: timed out client
[6]fredsue(69.10.192.145)
Jan 16 14:14:40 mail1 tpop3d[31476]: connection_sendresponse: client
[6]fredsue(69.10.192.145): sent `-ERR Client has been idle for too long.'
Jan 16 14:14:40 mail1 tpop3d[31476]: net_loop: timed out client
[6]fredsue(69.10.192.145)
Jan 16 14:14:40 mail1 tpop3d[31476]: connections_post_select: client
[6]fredsue(69.10.192.145): finished session for `fredsue' with mysql
Jan 16 14:14:40 mail1 tpop3d[31476]: connections_post_select: client
[6]fredsue(69.10.192.145): disconnected; 63/1557475 bytes read/written
Jan 16 14:56:27 mail1 tpop3d[17526]: do_retr: client [6]Gduby(69.10.201.168):
sending message 8 (231476 bytes)
Jan 16 15:35:36 mail1 tpop3d[4398]: connection_sendresponse: client [6]
69.10.204.74/localaccess.com: sent `+OK
<d457798708abd5694346e4d31476ea26@localaccess.com>'
--
Matt
Systems Administrator
Local Access Communications
360.330.5535