[tpop3d-discuss] Outlook Clients not Removing mail from the server

[Matthew Trent]

On Tuesday 09 December 2003 11:53 am, Chris Lightfoot wrote:
> On Tue, Dec 09, 2003 at 10:55:31AM -0800, Matthew Trent wrote:
> > I have heard reports of that same thing, but I've dismissed them as
> > misconfigured clients or something. Today I got one from an employee at
> > our other office using Outlook. She sent a message from home to herself
> > and then got it like 7 times at work. In the tpop3d logs I saw...
> >
> > Dec  9 09:26:52 mail2 tpop3d[11193]: net_loop: timed out client
> > [6]username(69.10.xx.xx)
> >
> > ... repeated many times for her username. In the logs I saw a few other
> > users with the same error repeated.
>
> Any chance of more information on that? In particular, log
> entries with -v enabled?

Ok, here it is. The user received this message like 7 times again, yet there 
was only one copy of it in his 'new' directory, and it was not moved to 
'cur'.

Dec 10 11:56:36 mail2 tpop3d[11880]: fork_child: 
[6]ribberbeach(69.10.203.151): began session for `ribberbeach' with mysql; 
child PID is 11924
Dec 10 11:56:36 mail2 tpop3d[11924]: maildir_new: scanned maildir /var/spool/
store/SERVERS/localaccess.com/ribberbeach (1 messages) in 0.002s
Dec 10 11:56:36 mail2 tpop3d[11924]: connection_sendresponse: client 
[6]ribberbeach(69.10.203.151): sent `+OK Welcome aboard! You have exactly one 
message.'
Dec 10 11:56:36 mail2 tpop3d[11924]: connection_parsecommand: client 
[6]ribberbeach(69.10.203.151): received `STAT'
Dec 10 11:56:36 mail2 tpop3d[11924]: connection_sendresponse: client 
[6]ribberbeach(69.10.203.151): sent `+OK 1 3834533'
Dec 10 11:56:37 mail2 tpop3d[11924]: connection_parsecommand: client 
[6]ribberbeach(69.10.203.151): received `LIST'
Dec 10 11:56:37 mail2 tpop3d[11924]: connection_sendresponse: client 
[6]ribberbeach(69.10.203.151): sent `+OK Scan list follows:'
Dec 10 11:56:37 mail2 tpop3d[11924]: do_list: client 
[6]ribberbeach(69.10.203.151): sent 2-line scan list
Dec 10 11:56:37 mail2 tpop3d[11924]: connection_parsecommand: client 
[6]ribberbeach(69.10.203.151): received `RETR 1'
Dec 10 11:56:37 mail2 tpop3d[11924]: do_retr: client 
[6]ribberbeach(69.10.203.151): sending message 1 (3834533 bytes)
Dec 10 11:56:37 mail2 tpop3d[11924]: connection_sendresponse: client 
[6]ribberbeach(69.10.203.151): sent `+OK Message follows'
Dec 10 11:56:38 mail2 tpop3d[11924]: do_retr: client 
[6]ribberbeach(69.10.203.151): sent message 1

Before I got the call and had -v turned on, this was in the log (his previous 
attempt):
Dec 10 11:21:49 mail2 tpop3d[29814]: fork_child: 
[6]ribberbeach(69.10.202.167): began session for `ribberbeach' with mysql; 
child PID is 29745
Dec 10 11:21:49 mail2 tpop3d[29745]: maildir_new: scanned maildir /var/spool/
store/SERVERS/localaccess.com/ribberbeach (4 messages) in 0.003s
Dec 10 11:36:14 mail2 tpop3d[29745]: net_loop: timed out client 
[6]ribberbeach(69.10.202.167)
Dec 10 11:36:15 mail2 tpop3d[29745]: net_loop: timed out client 
[6]ribberbeach(69.10.202.167)
Dec 10 11:36:15 mail2 tpop3d[29745]: connections_post_select: client 
[6]ribberbeach(69.10.202.167): finished session for `ribberbeach' with mysql
Dec 10 11:36:15 mail2 tpop3d[29745]: connections_post_select: client 
[6]ribberbeach(69.10.202.167): disconnected; 65/3892034 bytes read/written

> > The message she was trying to retrieve was like 2.5mb of pictures. I
> > looked in her maildir and it was still in her 'new' folder (versus
> > 'cur'), even though she'd received it several times. I think perhaps the
> > connection keeps timing out right at the end, so she gets the message,
> > but tpop3d gets an error and keeps the message in 'new'.

The message corresponding to the log above was another big one, 3834533 bytes 
with an mpg attachment. The user was on a dialup connection, yet the tpop3d 
log said the message was sent after only a few seconds. The client program 
(Outlook Express) just hung, the progress bar did not advance. I waited with 
him on the phone for several minutes and it didn't return an error before I 
let him go.

Ok, now after going back and re-looking at the logs, I see this (the finish to 
the first log snippet, 14 minutes later):
Dec 10 12:10:02 mail2 tpop3d[11924]: connection_parsecommand: client 
[6]ribberbeach(69.10.203.151): received `DELE 1'
Dec 10 12:10:02 mail2 tpop3d[11924]: connection_sendresponse: client 
[6]ribberbeach(69.10.203.151): sent `+OK Done.'
Dec 10 12:10:02 mail2 tpop3d[11924]: connection_parsecommand: client 
[6]ribberbeach(69.10.203.151): received `QUIT'
Dec 10 12:10:03 mail2 tpop3d[11924]: connection_sendresponse: client 
[6]ribberbeach(69.10.203.151): sent `+OK Done'
Dec 10 12:10:03 mail2 tpop3d[11924]: connections_post_select: client 
[6]ribberbeach(69.10.203.151): finished session for `ribberbeach' with mysql
Dec 10 12:10:03 mail2 tpop3d[11924]: connections_post_select: client 
[6]ribberbeach(69.10.203.151): disconnected; 63/3884622 bytes read/written

This is after I told him to cancel the download and hung up. It's possible he 
was confused and this is a false alarm. This still doesn't seem right, 
though. tpop said the message was sent way too quick. I saved a copy of the 
message and it'll be up at ftp://alderaan.localaccess.com/ for a while.
-- 
Matt
Systems Administrator
Local Access Communications
360.330.5535