Mailing List SIMS@mail.stalker.com Message #14781
From: Charles Mangin <option8@option8.com>
Subject: outlook pop timeout logs
Date: Fri, 1 Oct 2004 10:08:51 -0400
To: SIMS Discussions <SIMS@mail.stalker.com>
X-Mailer: Apple Mail (2.619)
here is a log, as promised, of the outlook pop timeout in action (inaction):

(i apologize for the really long lines and extent of this, but this is what happens when you turn up SIMS logging all the way. ip numbers and usernames munged to protect the innocent)


14:29:52 4 POP(tcp) Connection request from [xx.xxx.x.xxx:3507],seq=32874, 2/3
14:29:52 5 POP-867() Stream Created
14:29:52 4 POP Line 32867 created for answering
14:29:52 4 POP-867() Got connection from [xx.xxx.x.xxx:3507]
14:29:52 4 POP(tcp) Connection accepted from [xx.xxx.x.xxx:3507], seq=32874, 2/3
14:29:52 4 POP-867([xx.xxx.x.xxx]) Sending +OK Stalker POP3 Server 1.8b9d14 at mail.option8.com ready <32867.3179154592@mail.option8.com>\r\n
14:29:52 5 POP-867([xx.xxx.x.xxx]) OT 96 of 96 bytes sent, Flags=0
14:29:52 5 POP-867([xx.xxx.x.xxx]) *Status=5
14:29:54 5 POP-867([xx.xxx.x.xxx]) Received 10 bytes
14:29:54 4 POP-867([xx.xxx.x.xxx]) Input Line: USER xxxuserxxx\r
14:29:54 4 POP-867([xx.xxx.x.xxx]) Sending +OK please send PASS command\r\n
14:29:54 5 POP-867([xx.xxx.x.xxx]) OT 30 of 30 bytes sent, Flags=0
14:29:54 5 POP-867([xx.xxx.x.xxx]) *Status=6
14:29:54 5 POP-867([xx.xxx.x.xxx]) Received 17 bytes
14:29:54 4 POP-867([xx.xxx.x.xxx]) Input Line: PASS xxxpassxxx\r
14:29:54 5 POP-867([xx.xxx.x.xxx]) *Status=7
14:29:54 4 POP-867([xx.xxx.x.xxx]) Sending +OK 1 messages in queue\r\n
14:29:54 5 POP-867([xx.xxx.x.xxx]) OT 25 of 25 bytes sent, Flags=0
14:29:54 5 POP-867([xx.xxx.x.xxx]) *Status=8
14:29:54 5 POP-867([xx.xxx.x.xxx]) Received 6 bytes
14:29:54 4 POP-867([xx.xxx.x.xxx]) Input Line: STAT\r
14:29:54 4 POP-867([xx.xxx.x.xxx]) Sending +OK 1 565813\r\n
14:29:54 5 POP-867([xx.xxx.x.xxx]) OT 14 of 14 bytes sent, Flags=0
14:29:54 5 POP-867([xx.xxx.x.xxx]) Received 6 bytes
14:29:54 4 POP-867([xx.xxx.x.xxx]) Input Line: LIST\r
14:29:54 4 POP-867([xx.xxx.x.xxx]) Sending +OK 1 565813\r\n
14:29:54 5 POP-867([xx.xxx.x.xxx]) OT 14 of 14 bytes sent, Flags=1
14:29:54 5 POP-867([xx.xxx.x.xxx]) *Status=9
14:29:54 4 POP-867([xx.xxx.x.xxx]) Sending 1 565813\r\n
14:29:54 5 POP-867([xx.xxx.x.xxx]) OT 10 of 10 bytes sent, Flags=1
14:29:54 4 POP-867([xx.xxx.x.xxx]) Sending .\r\n
14:29:54 5 POP-867([xx.xxx.x.xxx]) OT 3 of 3 bytes sent, Flags=0
14:29:54 5 POP-867([xx.xxx.x.xxx]) *Status=8
14:29:54 5 POP-867([xx.xxx.x.xxx]) Received 8 bytes

(up to this point, everything looks normal to me. hi there, any messages? yes, one. it's 550k. okay, send it along.)

14:29:55 4 POP-867([xx.xxx.x.xxx]) Input Line: RETR 1\r
14:29:55 5 POP-867([xx.xxx.x.xxx]) *Status=10
14:29:55 4 POP-867([xx.xxx.x.xxx]) Sending +OK Message follows\r\n
14:29:55 5 POP-867([xx.xxx.x.xxx]) OT 21 of 21 bytes sent, Flags=1
14:29:55 5 POP-867([xx.xxx.x.xxx]) Sending 728 bytes: Return-Path: xxx@yyy.com\r\nReceived: from [xx.yy.zz.nn] (HELO yyy.com)\r\n  by mail.option8.com (Stalker SMTP Server 1.8b9d14)\r\n  with ESMTP id S.0000258344 for <r
14:29:55 5 POP-867([xx.xxx.x.xxx]) OT 728 of 728 bytes sent, Flags=1
14:29:55 5 POP-867([xx.xxx.x.xxx]) Sending 3475 bytes: \r\n--____LPHMXLZMXOMRLFKSEJCW____\r\nContent-Type: multipart/alternative; boundary="____WHPEPQYSAQXEHDGESJXG____"\r\n\r\n\r\n--____WHPEPQYSAQXEHDGESJXG____\r\nContent-Type: text/plain; charset
...

(lots of "sending X bytes" lines follow)

14:30:21 5 POP-867([xx.xxx.x.xxx]) OT Sending Flow Control

(not sure about this, but it seems normal to me. error checking and whatnot?)

...
14:30:27 5 POP-867([xx.xxx.x.xxx]) Sending 1456 bytes: AwNmYwMDQ3MDAyZjAwMzAwMDM0MDAzMDAwMzcwMDMxMDAzNTAwMmYw\r\nMDQ0MDA1NDAwNTMwMDMyMDAzNzAwMzEwMDJlMDA2ODAwNzQwMDZkMDAyMDAwMmQwMDIwMDA0ZDAw\r\nNjkwMDYzMDA3MjAwNmYwMDczMDA2ZjAwNjYwMDc0MDAyMDAwNDkwMDZ
14:30:27 5 POP-867([xx.xxx.x.xxx]) OT 1456 of 1456 bytes sent, Flags=1
14:30:27 4 POP-867([xx.xxx.x.xxx]) {xxxuserxxx} message 1 retrieved
14:30:27 4 POP-867([xx.xxx.x.xxx]) Sending .\r\n
14:30:27 5 POP-867([xx.xxx.x.xxx]) OT 3 of 3 bytes sent, Flags=0
14:30:27 5 POP-867([xx.xxx.x.xxx]) *Status=8

(message sent. yay. we should be all done and ready to clean up, right? what is status 8, anyway?)

...

(note the timestamp five minutes later - when this first happened, i asked the client to set his timeout to 300 seconds instead of 60 to see if it helped. it didn't)

14:35:27 3 POP-867([xx.xxx.x.xxx]) Time-Out. Read:
14:35:27 5 POP-867([xx.xxx.x.xxx]) *Status=3
14:35:27 4 POP-867([xx.xxx.x.xxx]) Aborting
14:35:27 5 POP-867([xx.xxx.x.xxx]) *Status=2
14:35:27 5 POP-867([xx.xxx.x.xxx]) Disconnect Completed
14:35:27 4 POP {xxxuserxxx} account updated, newSize=558563
14:35:27 4 POP disposing line 32867
14:35:27 5 POP-867([xx.xxx.x.xxx]) Stream Disposed

(timeout, dead in the water. mark the message as not received.... why is the new mailbox size different than how it began?)

note, no QUIT, no "Disconnect Received; Disconnect Confirmed" etc.

rinse and repeat every 15 minutes or so, throughout the day as the client attempts to retreive mail. he gets his half meg  email sent to him, but the client never acknowledges it's done...

bill, et al, does this help at all? for what it's worth, i've asked this and the other client that are having the same troubles to send me as much as they can about their email client, OS, and firewall settings, in case there's a magic bullet in there somewhere.


             charles mangin | Alpha Geek and Chief Mental Hygienist
        option8@option8.com | What's that watermelon doing there?
     http://niftee-tron.com | http://mentalhygiene.com

Subscribe (FEED) Subscribe (DIGEST) Subscribe (INDEX) Unsubscribe Mail to Listmaster