OL2003 interop problem with POP3 servers that don't support UIDL and TOP

G

Greg Bailey

I have observed severe POP3 mailbox mismanagement by 11.5608.5703 when using
a POP3 server
that refuses to support UIDL and TOP. Our server operates this way as it is
the IETF standard
compliant way to prevent users' leaving messages on the server.

Based on logs from our server as well as OPMLog.log, it is pretty clear that
in its default configuration
(no messages left on server, no header-only downloading enabled), OL2003
becomes quite confused
possibly by its management and interpretation of its "blobs" under these
conditions.

The result is that when STAT and LIST report a set of messages, OL2003 is
capable of reading only
some of the messages and deleting only some of them. The two sets are often
not identical, so that
some messages are never retrieved while others are retrieved multiple times.
Behavior is stateful
and is at least partially based on the results of the most recent preceding
POP3 session.

This is a severe problem for us as a fair number of our customers have been
building new machines
with Office 2003 and finding that they are basically useless with our mail
server. In fact I have just
set one up myself and agree with them.

I postulate that while OL2003 was tested in its default configuration, this
testing was only done
against a POP3 server which supports UIDL and/or TOP. Whatever logic is
intended to produce the
default behavior of simply reading all messages LIST reports, then deleting
all of them, when these
commands are not supported is pretty clearly broken. Indeed, according to
the OPMLog.log file,
"blobs" are still being calculated and saved, and decisions made upon them.

It is clearly a regression since no previous version of Outlook has had any
trouble interoperating
with our server. Since our server is compliant with both RFC's and also
with what Outlook
clearly *thinks* it can interoperate with, I would consider this a severe
interoperability
problem that should be fixed aggressively.

I'm in a position to supply logs and a test platform and manual insertion of
messages to facilitate
reproduction and solution of this problem if Microsoft is interested. If
anyone from the company
reviews this posting, please at minimum let me know if there is likely to be
any action on this
issue and at maximum take me up on my offer to help from the server end.

Thanks in advance - Greg
 
J

Jeff Stephenson [MSFT]

Can you post complete logs from serveral successive downloads in which this
happens? The log snippet you posted earlier didn't include any of the blob
information.

The reason for Outlook storing a blob even when nothing is to be left on the
server is to deal with situations such as a connection to the server being
dropped before the POP3 session has completed. In that case, Outlook can't
issue the QUIT command, and the server thus is not allowed to delete any
messages. If Outlook didn't keep the blob, it would not know which messages
it had already downloaded and would just download everything again.
 
G

Greg Bailey

Jeff Stephenson said:
Can you post complete logs from serveral successive downloads in which this
happens? The log snippet you posted earlier didn't include any of the blob
information.

The reason for Outlook storing a blob even when nothing is to be left on the
server is to deal with situations such as a connection to the server being
dropped before the POP3 session has completed. In that case, Outlook can't
issue the QUIT command, and the server thus is not allowed to delete any
messages. If Outlook didn't keep the blob, it would not know which messages
it had already downloaded and would just download everything again.
Click to expand...

While I understand what you are saying there, POP3 servers are supposed to
do
their deletion thing upon seeing QUIT and before issuing +OK. Note that in
all
the cases I'm sending the +OK was sent by me and received/logged by OL2003.
Certainly if you don't see +OK (or -ERR) you can't be certain that the QUIT
was parsed and processed, but if you *do* see +OK you may be certain any
compliant server has done its deletions. See excerpt of RFC1939 way below.
I do not see any justification for retaining a message length after a +OK to
a
quit and using it as decision to discard a message from the mailbox in a
subsequent session, and certainly can see this leading to lost real
messages.
I would strongly urge that after getting +OK to a QUIT, OL should return to
the state wherein it believes that the mailbox is empty and that no
previously
read messages can possibly be there, at least when not using UIDL. Even
when
a +OK is not received, I'd personally rather receive a copy of a message
than
to lose a message just because it had an unfortunate length in sequence.

As to the strange behavior here is a fully logged example.

I'll just include the OPMLog.log content. In all cases it agrees with my
logs so
no need to be redundant.

Initial conditions: Mailbox is empty, and was previously seen empty by OL.
Outlook stopped and restarted. Send/receive of empty mailbox:

2004.01.20 00:52:49 <<<< Logging Started (level is LTF_TRACE) >>>>
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:52:49 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:52:49 Bozo on left: Synch operation completed
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:52:49 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 00:52:49 POP3 (left.minerva.com): Begin execution
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Finding host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connecting to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK 0 0
2004.01.20 00:52:49 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:52:49 POP3 (left.minerva.com):
==========================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): End execution
2004.01.20 00:52:49 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:52:49 Bozo on left: Synch operation completed

Now insert four messages into mailbox. Send/receive again:

2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:59:16 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:59:16 Bozo on left: Synch operation completed
2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:59:16 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 00:59:16 POP3 (left.minerva.com): Begin execution
2004.01.20 00:59:16 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:59:16 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:16 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:59:16 POP3 (left.minerva.com): Finding host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] UIDL
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR UIDL Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] LIST
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 1 2965
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 2 507
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 3 3001
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 4 2922
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> .
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] TOP 1 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR TOP Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
==========================================
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 2
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 4
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:17 POP3 (left.minerva.com): End execution
2004.01.20 00:59:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:59:17 Bozo on left: Synch operation completed

Interesting, huh? We read all three but deleted only the first.
Try send/receive again with old messages 2, 3, 4 in mailbox as 1,2,3:

2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:02:07 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:02:07 Bozo on left: Synch operation completed
2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:02:07 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 01:02:07 POP3 (left.minerva.com): Begin execution
2004.01.20 01:02:07 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:02:07 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:07 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:07 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:02:07 POP3 (left.minerva.com): Finding host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 1 507
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 2 3001
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 3 2922
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> .
2004.01.20 01:02:07 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
==========================================
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 2
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:08 POP3 (left.minerva.com): End execution
2004.01.20 01:02:08 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:02:08 Bozo on left: Synch operation completed

Now we retrieve messages 1 and 3 (both of which were retrieved before, 2 and
4 from the earlier
session) but for some reason we don't retrieve 2 (the old 3). Then for
equally mystifying reasons
we delete 1 and 2 but not 3. Once more:

2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:05:17 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:05:17 Bozo on left: Synch operation completed
2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:05:17 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 01:05:17 POP3 (left.minerva.com): Begin execution
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:05:17 POP3 (left.minerva.com): Finding host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> .
2004.01.20 01:05:17 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:05:17 POP3 (left.minerva.com):
==========================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): End execution
2004.01.20 01:05:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:05:17 Bozo on left: Synch operation completed

.... so we delete message 3 from previous session, #4 from the original try
on these four
messages, which we should have deleted last session (not to mention the
first session).

I hope this is enough to set the hook and will be happy to run more
examples. BTW I've
never seen it delete more than two messages per session, even with 100
messages read. The
un-read messages have seemed to be only #1 or #2 of a mailbox in any case
that I have
observed... messages 3 and onward if present have always been read... and
re-read and re-read.

Thanks for taking an interest in this. Looking forward to some code
changes - Greg

Excerpt from RFC1939 in which it is clearly stated that POP3 servers do
their deletions
BEFORE replying to the QUIT command:

6. The UPDATE State

When the client issues the QUIT command from the TRANSACTION state,
the POP3 session enters the UPDATE state. (Note that if the client
issues the QUIT command from the AUTHORIZATION state, the POP3
session terminates but does NOT enter the UPDATE state.)

If a session terminates for some reason other than a client-issued
QUIT command, the POP3 session does NOT enter the UPDATE state and
MUST not remove any messages from the maildrop.

QUIT

Arguments: none

Restrictions: none

Discussion:
The POP3 server removes all messages marked as deleted
from the maildrop and replies as to the status of this
operation. If there is an error, such as a resource
shortage, encountered while removing messages, the
maildrop may result in having some or none of the messages
marked as deleted be removed. In no case may the server
remove any messages not marked as deleted.

Whether the removal was successful or not, the server
then releases any exclusive-access lock on the maildrop
and closes the TCP connection.

Possible Responses:
+OK
-ERR some deleted messages not removed

Examples:
C: QUIT
S: +OK dewey POP3 server signing off (maildrop empty)
...
C: QUIT
 
J

Jeff Stephenson [MSFT]

First of all, Outlook does not use message lengths to identify messages if
UIDL is not supported - it uses a hash of the headers retrieved by TOP. If
TOP is not supported either, we don't support the "leave on server" option.
The reason that you see the LIST command issued is that one of the MAPI
properties used by the Outlook store is the "remote size" (i.e. the size on
the server), so we fill that in from the result of LIST.

While Outlook should indeed handle the case when neither UIDL nor TOP is
supported, it's been a long time since I've seen a server that did not
support them. I don't know that any of the servers we have available
in-house for testing allows these commands to be turned off, and I don't
know of any ISP that doesn't support them (they just put a quota on mailbox
size, rather than forcing download by disabling the commands). So while I'm
disappointed that we appear to have shipped with this bug, I'm not shocked -
I'm not sure how testing could have caught it.

I'll enter a bug on this. I suspect that we'll just make a quick code
change to force Outlook to think that neither command is supported and go
from there...

--
Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


Greg Bailey said:
Can you post complete logs from serveral successive downloads in which this
happens? The log snippet you posted earlier didn't include any of the blob
information.

The reason for Outlook storing a blob even when nothing is to be left on the
server is to deal with situations such as a connection to the server being
dropped before the POP3 session has completed. In that case, Outlook can't
issue the QUIT command, and the server thus is not allowed to delete any
messages. If Outlook didn't keep the blob, it would not know which messages
it had already downloaded and would just download everything again.
Click to expand...

While I understand what you are saying there, POP3 servers are supposed to
do
their deletion thing upon seeing QUIT and before issuing +OK. Note that in
all
the cases I'm sending the +OK was sent by me and received/logged by OL2003.
Certainly if you don't see +OK (or -ERR) you can't be certain that the QUIT
was parsed and processed, but if you *do* see +OK you may be certain any
compliant server has done its deletions. See excerpt of RFC1939 way below.
I do not see any justification for retaining a message length after a +OK to
a
quit and using it as decision to discard a message from the mailbox in a
subsequent session, and certainly can see this leading to lost real
messages.
I would strongly urge that after getting +OK to a QUIT, OL should return to
the state wherein it believes that the mailbox is empty and that no
previously
read messages can possibly be there, at least when not using UIDL. Even
when
a +OK is not received, I'd personally rather receive a copy of a message
than
to lose a message just because it had an unfortunate length in sequence.

As to the strange behavior here is a fully logged example.

I'll just include the OPMLog.log content. In all cases it agrees with my
logs so
no need to be redundant.

Initial conditions: Mailbox is empty, and was previously seen empty by OL.
Outlook stopped and restarted. Send/receive of empty mailbox:

2004.01.20 00:52:49 <<<< Logging Started (level is LTF_TRACE) >>>>
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:52:49 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:52:49 Bozo on left: Synch operation completed
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:52:49 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 00:52:49 POP3 (left.minerva.com): Begin execution
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Finding host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connecting to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK 0 0
2004.01.20 00:52:49 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:52:49 POP3 (left.minerva.com):
==========================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): End execution
2004.01.20 00:52:49 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:52:49 Bozo on left: Synch operation completed

Now insert four messages into mailbox. Send/receive again:

2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:59:16 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:59:16 Bozo on left: Synch operation completed
2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:59:16 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 00:59:16 POP3 (left.minerva.com): Begin execution
2004.01.20 00:59:16 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:59:16 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:16 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:59:16 POP3 (left.minerva.com): Finding host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] UIDL
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR UIDL Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] LIST
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 1 2965
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 2 507
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 3 3001
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 4 2922
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> .
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] TOP 1 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR TOP Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
==========================================
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 2
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 4
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:17 POP3 (left.minerva.com): End execution
2004.01.20 00:59:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:59:17 Bozo on left: Synch operation completed

Interesting, huh? We read all three but deleted only the first.
Try send/receive again with old messages 2, 3, 4 in mailbox as 1,2,3:

2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:02:07 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:02:07 Bozo on left: Synch operation completed
2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:02:07 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 01:02:07 POP3 (left.minerva.com): Begin execution
2004.01.20 01:02:07 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:02:07 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:07 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:07 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:02:07 POP3 (left.minerva.com): Finding host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 1 507
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 2 3001
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 3 2922
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> .
2004.01.20 01:02:07 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
==========================================
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 2
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:08 POP3 (left.minerva.com): End execution
2004.01.20 01:02:08 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:02:08 Bozo on left: Synch operation completed

Now we retrieve messages 1 and 3 (both of which were retrieved before, 2 and
4 from the earlier
session) but for some reason we don't retrieve 2 (the old 3). Then for
equally mystifying reasons
we delete 1 and 2 but not 3. Once more:

2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:05:17 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:05:17 Bozo on left: Synch operation completed
2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:05:17 Bozo on left: DoPOPDownload(flags = 00000030, max msg =
ffffffff): full items
2004.01.20 01:05:17 POP3 (left.minerva.com): Begin execution
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:05:17 POP3 (left.minerva.com): Finding host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> .
2004.01.20 01:05:17 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:05:17 POP3 (left.minerva.com):
==========================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): End execution
2004.01.20 01:05:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:05:17 Bozo on left: Synch operation completed

... so we delete message 3 from previous session, #4 from the original try
on these four
messages, which we should have deleted last session (not to mention the
first session).

I hope this is enough to set the hook and will be happy to run more
examples. BTW I've
never seen it delete more than two messages per session, even with 100
messages read. The
un-read messages have seemed to be only #1 or #2 of a mailbox in any case
that I have
observed... messages 3 and onward if present have always been read... and
re-read and re-read.

Thanks for taking an interest in this. Looking forward to some code
changes - Greg

Excerpt from RFC1939 in which it is clearly stated that POP3 servers do
their deletions
BEFORE replying to the QUIT command:

6. The UPDATE State

When the client issues the QUIT command from the TRANSACTION state,
the POP3 session enters the UPDATE state. (Note that if the client
issues the QUIT command from the AUTHORIZATION state, the POP3
session terminates but does NOT enter the UPDATE state.)

If a session terminates for some reason other than a client-issued
QUIT command, the POP3 session does NOT enter the UPDATE state and
MUST not remove any messages from the maildrop.

QUIT

Arguments: none

Restrictions: none

Discussion:
The POP3 server removes all messages marked as deleted
from the maildrop and replies as to the status of this
operation. If there is an error, such as a resource
shortage, encountered while removing messages, the
maildrop may result in having some or none of the messages
marked as deleted be removed. In no case may the server
remove any messages not marked as deleted.

Whether the removal was successful or not, the server
then releases any exclusive-access lock on the maildrop
and closes the TCP connection.

Possible Responses:
+OK
-ERR some deleted messages not removed

Examples:
C: QUIT
S: +OK dewey POP3 server signing off (maildrop empty)
...
C: QUIT

Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


it clear
that
Click to expand...
according
to had
any insertion to
Click to expand...
Click to expand...
 
G

Greg Bailey

Thanks, Jeff. Look for email from me identifying a mailbox you folks may
use for testing if you wish.

Jeff Stephenson said:
First of all, Outlook does not use message lengths to identify messages if
UIDL is not supported - it uses a hash of the headers retrieved by TOP. If
TOP is not supported either, we don't support the "leave on server" option.
The reason that you see the LIST command issued is that one of the MAPI
properties used by the Outlook store is the "remote size" (i.e. the size on
the server), so we fill that in from the result of LIST.

While Outlook should indeed handle the case when neither UIDL nor TOP is
supported, it's been a long time since I've seen a server that did not
support them. I don't know that any of the servers we have available
in-house for testing allows these commands to be turned off, and I don't
know of any ISP that doesn't support them (they just put a quota on mailbox
size, rather than forcing download by disabling the commands). So while I'm
disappointed that we appear to have shipped with this bug, I'm not shocked -
I'm not sure how testing could have caught it.

I'll enter a bug on this. I suspect that we'll just make a quick code
change to force Outlook to think that neither command is supported and go
from there...

--
Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


Greg Bailey said:
on
the

While I understand what you are saying there, POP3 servers are supposed to
do
their deletion thing upon seeing QUIT and before issuing +OK. Note that in
all
the cases I'm sending the +OK was sent by me and received/logged by OL2003.
Certainly if you don't see +OK (or -ERR) you can't be certain that the QUIT
was parsed and processed, but if you *do* see +OK you may be certain any
compliant server has done its deletions. See excerpt of RFC1939 way below.
I do not see any justification for retaining a message length after a
Click to expand...
+OK
to
a
quit and using it as decision to discard a message from the mailbox in a
subsequent session, and certainly can see this leading to lost real
messages.
I would strongly urge that after getting +OK to a QUIT, OL should return to
the state wherein it believes that the mailbox is empty and that no
previously
read messages can possibly be there, at least when not using UIDL. Even
when
a +OK is not received, I'd personally rather receive a copy of a message
than
to lose a message just because it had an unfortunate length in sequence.

As to the strange behavior here is a fully logged example.

I'll just include the OPMLog.log content. In all cases it agrees with my
logs so
no need to be redundant.

Initial conditions: Mailbox is empty, and was previously seen empty by OL.
Outlook stopped and restarted. Send/receive of empty mailbox:

2004.01.20 00:52:49 <<<< Logging Started (level is LTF_TRACE) >>>>
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:52:49 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:52:49 Bozo on left: Synch operation completed
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:52:49 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 00:52:49 POP3 (left.minerva.com): Begin execution
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Finding host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connecting to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK 0 0
2004.01.20 00:52:49 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:52:49 POP3 (left.minerva.com):
==========================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): End execution
2004.01.20 00:52:49 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:52:49 Bozo on left: Synch operation completed

Now insert four messages into mailbox. Send/receive again:

2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:59:16 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:59:16 Bozo on left: Synch operation completed
2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:59:16 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 00:59:16 POP3 (left.minerva.com): Begin execution
2004.01.20 00:59:16 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:59:16 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:16 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:59:16 POP3 (left.minerva.com): Finding host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] UIDL
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR UIDL Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] LIST
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 1 2965
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 2 507
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 3 3001
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 4 2922
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> .
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] TOP 1 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR TOP Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
==========================================
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 2
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 4
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:17 POP3 (left.minerva.com): End execution
2004.01.20 00:59:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:59:17 Bozo on left: Synch operation completed

Interesting, huh? We read all three but deleted only the first.
Try send/receive again with old messages 2, 3, 4 in mailbox as 1,2,3:

2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:02:07 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:02:07 Bozo on left: Synch operation completed
2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:02:07 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 01:02:07 POP3 (left.minerva.com): Begin execution
2004.01.20 01:02:07 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:02:07 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:07 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:07 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:02:07 POP3 (left.minerva.com): Finding host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 1 507
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 2 3001
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 3 2922
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> .
2004.01.20 01:02:07 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
==========================================
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 2
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:08 POP3 (left.minerva.com): End execution
2004.01.20 01:02:08 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:02:08 Bozo on left: Synch operation completed

Now we retrieve messages 1 and 3 (both of which were retrieved before, 2 and
4 from the earlier
session) but for some reason we don't retrieve 2 (the old 3). Then for
equally mystifying reasons
we delete 1 and 2 but not 3. Once more:

2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:05:17 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:05:17 Bozo on left: Synch operation completed
2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:05:17 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 01:05:17 POP3 (left.minerva.com): Begin execution
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:05:17 POP3 (left.minerva.com): Finding host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> .
2004.01.20 01:05:17 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:05:17 POP3 (left.minerva.com):
==========================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): End execution
2004.01.20 01:05:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:05:17 Bozo on left: Synch operation completed

... so we delete message 3 from previous session, #4 from the original try
on these four
messages, which we should have deleted last session (not to mention the
first session).

I hope this is enough to set the hook and will be happy to run more
examples. BTW I've
never seen it delete more than two messages per session, even with 100
messages read. The
un-read messages have seemed to be only #1 or #2 of a mailbox in any case
that I have
observed... messages 3 and onward if present have always been read... and
re-read and re-read.

Thanks for taking an interest in this. Looking forward to some code
changes - Greg

Excerpt from RFC1939 in which it is clearly stated that POP3 servers do
their deletions
BEFORE replying to the QUIT command:

6. The UPDATE State

When the client issues the QUIT command from the TRANSACTION state,
the POP3 session enters the UPDATE state. (Note that if the client
issues the QUIT command from the AUTHORIZATION state, the POP3
session terminates but does NOT enter the UPDATE state.)

If a session terminates for some reason other than a client-issued
QUIT command, the POP3 session does NOT enter the UPDATE state and
MUST not remove any messages from the maildrop.

QUIT

Arguments: none

Restrictions: none

Discussion:
The POP3 server removes all messages marked as deleted
from the maildrop and replies as to the status of this
operation. If there is an error, such as a resource
shortage, encountered while removing messages, the
maildrop may result in having some or none of the messages
marked as deleted be removed. In no case may the server
remove any messages not marked as deleted.

Whether the removal was successful or not, the server
then releases any exclusive-access lock on the maildrop
and closes the TCP connection.

Possible Responses:
+OK
-ERR some deleted messages not removed

Examples:
C: QUIT
S: +OK dewey POP3 server signing off (maildrop empty)
...
C: QUIT

Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


I have observed severe POP3 mailbox mismanagement by 11.5608.5703 when
using
a POP3 server
that refuses to support UIDL and TOP. Our server operates this way
Click to expand...
as
it
is
the IETF standard
compliant way to prevent users' leaving messages on the server.

Based on logs from our server as well as OPMLog.log, it is pretty clear
that
in its default configuration
(no messages left on server, no header-only downloading enabled), OL2003
becomes quite confused
possibly by its management and interpretation of its "blobs" under these
conditions.

The result is that when STAT and LIST report a set of messages,
Click to expand...
OL2003
is
capable of reading only
some of the messages and deleting only some of them. The two sets are
often
not identical, so that
some messages are never retrieved while others are retrieved multiple
times.
Behavior is stateful
and is at least partially based on the results of the most recent
preceding
POP3 session.

This is a severe problem for us as a fair number of our customers have
been
building new machines
with Office 2003 and finding that they are basically useless with
Click to expand...
our
mail
server. In fact I have just
set one up myself and agree with them.

I postulate that while OL2003 was tested in its default configuration,
this
testing was only done
against a POP3 server which supports UIDL and/or TOP. Whatever
Click to expand...
Click to expand...
logic
is according interested.
If likely
to
Click to expand...
Click to expand...
 
G

Greg Bailey

Oops... online.microsoft.com does not exist. If you want to test with my
server send email to me.
Thanks again, Jeff.
 
J

Jeff Stephenson [MSFT]

Yeah, I need to be able to control what I deal with, rather than letting
people flood my inbox. I've got a day job writing Outlook code ;-).
 
G

Greg Bailey

Jeff, any prognosis on this? Thanks - Greg

Jeff Stephenson said:
First of all, Outlook does not use message lengths to identify messages if
UIDL is not supported - it uses a hash of the headers retrieved by TOP. If
TOP is not supported either, we don't support the "leave on server" option.
The reason that you see the LIST command issued is that one of the MAPI
properties used by the Outlook store is the "remote size" (i.e. the size on
the server), so we fill that in from the result of LIST.

While Outlook should indeed handle the case when neither UIDL nor TOP is
supported, it's been a long time since I've seen a server that did not
support them. I don't know that any of the servers we have available
in-house for testing allows these commands to be turned off, and I don't
know of any ISP that doesn't support them (they just put a quota on mailbox
size, rather than forcing download by disabling the commands). So while I'm
disappointed that we appear to have shipped with this bug, I'm not shocked -
I'm not sure how testing could have caught it.

I'll enter a bug on this. I suspect that we'll just make a quick code
change to force Outlook to think that neither command is supported and go
from there...

--
Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


Greg Bailey said:
on
the

While I understand what you are saying there, POP3 servers are supposed to
do
their deletion thing upon seeing QUIT and before issuing +OK. Note that in
all
the cases I'm sending the +OK was sent by me and received/logged by OL2003.
Certainly if you don't see +OK (or -ERR) you can't be certain that the QUIT
was parsed and processed, but if you *do* see +OK you may be certain any
compliant server has done its deletions. See excerpt of RFC1939 way below.
I do not see any justification for retaining a message length after a
Click to expand...
+OK
to
a
quit and using it as decision to discard a message from the mailbox in a
subsequent session, and certainly can see this leading to lost real
messages.
I would strongly urge that after getting +OK to a QUIT, OL should return to
the state wherein it believes that the mailbox is empty and that no
previously
read messages can possibly be there, at least when not using UIDL. Even
when
a +OK is not received, I'd personally rather receive a copy of a message
than
to lose a message just because it had an unfortunate length in sequence.

As to the strange behavior here is a fully logged example.

I'll just include the OPMLog.log content. In all cases it agrees with my
logs so
no need to be redundant.

Initial conditions: Mailbox is empty, and was previously seen empty by OL.
Outlook stopped and restarted. Send/receive of empty mailbox:

2004.01.20 00:52:49 <<<< Logging Started (level is LTF_TRACE) >>>>
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:52:49 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:52:49 Bozo on left: Synch operation completed
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:52:49 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 00:52:49 POP3 (left.minerva.com): Begin execution
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Finding host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connecting to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK 0 0
2004.01.20 00:52:49 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:52:49 POP3 (left.minerva.com):
==========================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): End execution
2004.01.20 00:52:49 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:52:49 Bozo on left: Synch operation completed

Now insert four messages into mailbox. Send/receive again:

2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:59:16 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:59:16 Bozo on left: Synch operation completed
2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:59:16 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 00:59:16 POP3 (left.minerva.com): Begin execution
2004.01.20 00:59:16 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:59:16 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:16 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 00:59:16 POP3 (left.minerva.com): Finding host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] UIDL
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR UIDL Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] LIST
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 1 2965
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 2 507
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 3 3001
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 4 2922
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> .
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] TOP 1 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR TOP Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
==========================================
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 2
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 4
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:17 POP3 (left.minerva.com): End execution
2004.01.20 00:59:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:59:17 Bozo on left: Synch operation completed

Interesting, huh? We read all three but deleted only the first.
Try send/receive again with old messages 2, 3, 4 in mailbox as 1,2,3:

2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:02:07 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:02:07 Bozo on left: Synch operation completed
2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:02:07 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 01:02:07 POP3 (left.minerva.com): Begin execution
2004.01.20 01:02:07 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:02:07 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:07 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:07 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:02:07 POP3 (left.minerva.com): Finding host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 1 507
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 2 3001
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 3 2922
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> .
2004.01.20 01:02:07 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
==========================================
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 2
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:08 POP3 (left.minerva.com): End execution
2004.01.20 01:02:08 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:02:08 Bozo on left: Synch operation completed

Now we retrieve messages 1 and 3 (both of which were retrieved before, 2 and
4 from the earlier
session) but for some reason we don't retrieve 2 (the old 3). Then for
equally mystifying reasons
we delete 1 and 2 but not 3. Once more:

2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:05:17 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:05:17 Bozo on left: Synch operation completed
2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:05:17 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 01:05:17 POP3 (left.minerva.com): Begin execution
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Port: 110, Secure: no, SPA: no
2004.01.20 01:05:17 POP3 (left.minerva.com): Finding host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> .
2004.01.20 01:05:17 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:05:17 POP3 (left.minerva.com):
==========================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): End execution
2004.01.20 01:05:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:05:17 Bozo on left: Synch operation completed

... so we delete message 3 from previous session, #4 from the original try
on these four
messages, which we should have deleted last session (not to mention the
first session).

I hope this is enough to set the hook and will be happy to run more
examples. BTW I've
never seen it delete more than two messages per session, even with 100
messages read. The
un-read messages have seemed to be only #1 or #2 of a mailbox in any case
that I have
observed... messages 3 and onward if present have always been read... and
re-read and re-read.

Thanks for taking an interest in this. Looking forward to some code
changes - Greg

Excerpt from RFC1939 in which it is clearly stated that POP3 servers do
their deletions
BEFORE replying to the QUIT command:

6. The UPDATE State

When the client issues the QUIT command from the TRANSACTION state,
the POP3 session enters the UPDATE state. (Note that if the client
issues the QUIT command from the AUTHORIZATION state, the POP3
session terminates but does NOT enter the UPDATE state.)

If a session terminates for some reason other than a client-issued
QUIT command, the POP3 session does NOT enter the UPDATE state and
MUST not remove any messages from the maildrop.

QUIT

Arguments: none

Restrictions: none

Discussion:
The POP3 server removes all messages marked as deleted
from the maildrop and replies as to the status of this
operation. If there is an error, such as a resource
shortage, encountered while removing messages, the
maildrop may result in having some or none of the messages
marked as deleted be removed. In no case may the server
remove any messages not marked as deleted.

Whether the removal was successful or not, the server
then releases any exclusive-access lock on the maildrop
and closes the TCP connection.

Possible Responses:
+OK
-ERR some deleted messages not removed

Examples:
C: QUIT
S: +OK dewey POP3 server signing off (maildrop empty)
...
C: QUIT

Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


I have observed severe POP3 mailbox mismanagement by 11.5608.5703 when
using
a POP3 server
that refuses to support UIDL and TOP. Our server operates this way
Click to expand...
as
it
is
the IETF standard
compliant way to prevent users' leaving messages on the server.

Based on logs from our server as well as OPMLog.log, it is pretty clear
that
in its default configuration
(no messages left on server, no header-only downloading enabled), OL2003
becomes quite confused
possibly by its management and interpretation of its "blobs" under these
conditions.

The result is that when STAT and LIST report a set of messages,
Click to expand...
OL2003
is
capable of reading only
some of the messages and deleting only some of them. The two sets are
often
not identical, so that
some messages are never retrieved while others are retrieved multiple
times.
Behavior is stateful
and is at least partially based on the results of the most recent
preceding
POP3 session.

This is a severe problem for us as a fair number of our customers have
been
building new machines
with Office 2003 and finding that they are basically useless with
Click to expand...
our
mail
server. In fact I have just
set one up myself and agree with them.

I postulate that while OL2003 was tested in its default configuration,
this
testing was only done
against a POP3 server which supports UIDL and/or TOP. Whatever
Click to expand...
Click to expand...
logic
is according interested.
If likely
to
Click to expand...
Click to expand...
 
J

Jeff Stephenson [MSFT]

I've opened a bug on this targetted to Outlook 2003 SP-1. No guarantees
that it will be fixed though, as I'm not the decision-maker for which
bug-fixes are taken for SPs. I'll certainly argue for it to be taken,
though.

--
Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


Greg Bailey said:
Jeff, any prognosis on this? Thanks - Greg

First of all, Outlook does not use message lengths to identify messages if
UIDL is not supported - it uses a hash of the headers retrieved by TOP. If
TOP is not supported either, we don't support the "leave on server" option.
The reason that you see the LIST command issued is that one of the MAPI
properties used by the Outlook store is the "remote size" (i.e. the size on
the server), so we fill that in from the result of LIST.

While Outlook should indeed handle the case when neither UIDL nor TOP is
supported, it's been a long time since I've seen a server that did not
support them. I don't know that any of the servers we have available
in-house for testing allows these commands to be turned off, and I don't
know of any ISP that doesn't support them (they just put a quota on mailbox
size, rather than forcing download by disabling the commands). So while I'm
disappointed that we appear to have shipped with this bug, I'm not shocked -
I'm not sure how testing could have caught it.

I'll enter a bug on this. I suspect that we'll just make a quick code
change to force Outlook to think that neither command is supported and go
from there...
Click to expand...
left
on
Click to expand...
supposed
to
do
their deletion thing upon seeing QUIT and before issuing +OK. Note
Click to expand...
that
in
all
the cases I'm sending the +OK was sent by me and received/logged by OL2003.
Certainly if you don't see +OK (or -ERR) you can't be certain that the QUIT
was parsed and processed, but if you *do* see +OK you may be certain any
compliant server has done its deletions. See excerpt of RFC1939 way below.
I do not see any justification for retaining a message length after a
Click to expand...
+OK
to
a
quit and using it as decision to discard a message from the mailbox in a
subsequent session, and certainly can see this leading to lost real
messages.
I would strongly urge that after getting +OK to a QUIT, OL should
Click to expand...
return
to
the state wherein it believes that the mailbox is empty and that no
previously
read messages can possibly be there, at least when not using UIDL. Even
when
a +OK is not received, I'd personally rather receive a copy of a message
than
to lose a message just because it had an unfortunate length in sequence.

As to the strange behavior here is a fully logged example.

I'll just include the OPMLog.log content. In all cases it agrees with my
logs so
no need to be redundant.

Initial conditions: Mailbox is empty, and was previously seen empty
Click to expand...
by
OL.
Outlook stopped and restarted. Send/receive of empty mailbox:

2004.01.20 00:52:49 <<<< Logging Started (level is LTF_TRACE) >>>>
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:52:49 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:52:49 Bozo on left: Synch operation completed
2004.01.20 00:52:49 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:52:49 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 00:52:49 POP3 (left.minerva.com): Begin execution
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Port: 110, Secure: no,
Click to expand...
SPA:
no
2004.01.20 00:52:49 POP3 (left.minerva.com): Finding host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connecting to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:52:49 POP3 (left.minerva.com): Connected to host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK 0 0
2004.01.20 00:52:49 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:52:49 POP3 (left.minerva.com):
==========================================
2004.01.20 00:52:49 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:52:49 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:52:49 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:52:49 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:52:49 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 00:52:49 POP3 (left.minerva.com):
===================================
2004.01.20 00:52:49 POP3 (left.minerva.com): End execution
2004.01.20 00:52:49 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:52:49 Bozo on left: Synch operation completed

Now insert four messages into mailbox. Send/receive again:

2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 00:59:16 Bozo on left: UploadItems: 0 messages to send
2004.01.20 00:59:16 Bozo on left: Synch operation completed
2004.01.20 00:59:16 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 00:59:16 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 00:59:16 POP3 (left.minerva.com): Begin execution
2004.01.20 00:59:16 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 00:59:16 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:16 POP3 (left.minerva.com): Port: 110, Secure: no,
Click to expand...
SPA:
no
2004.01.20 00:59:16 POP3 (left.minerva.com): Finding host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorizing to server
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:16 POP3 (left.minerva.com): Authorized to host
2004.01.20 00:59:16 POP3 (left.minerva.com): Connected to host
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] STAT
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] UIDL
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR UIDL Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] LIST
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK 4 9395
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 1 2965
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 2 507
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 3 3001
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> 4 2922
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> .
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] TOP 1 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> -ERR TOP Bad Command
2004.01.20 00:59:16 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 00:59:16 POP3 (left.minerva.com):
==========================================
2004.01.20 00:59:16 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 00:59:16 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 2
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] RETR 4
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 00:59:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 00:59:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 00:59:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 00:59:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 00:59:17 POP3 (left.minerva.com):
===================================
2004.01.20 00:59:17 POP3 (left.minerva.com): End execution
2004.01.20 00:59:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 00:59:17 Bozo on left: Synch operation completed

Interesting, huh? We read all three but deleted only the first.
Try send/receive again with old messages 2, 3, 4 in mailbox as 1,2,3:

2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:02:07 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:02:07 Bozo on left: Synch operation completed
2004.01.20 01:02:07 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:02:07 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 01:02:07 POP3 (left.minerva.com): Begin execution
2004.01.20 01:02:07 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:02:07 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:07 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:07 POP3 (left.minerva.com): Port: 110, Secure: no,
Click to expand...
SPA:
no
2004.01.20 01:02:07 POP3 (left.minerva.com): Finding host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:02:07 POP3 (left.minerva.com): Connected to host
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK 3 6430
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 1 507
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 2 3001
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> 3 2922
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> .
2004.01.20 01:02:07 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA : new
2004.01.20 01:02:07 POP3 (left.minerva.com):
==========================================
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 1
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:07 POP3 (left.minerva.com): [tx] RETR 3
2004.01.20 01:02:07 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] DELE 2
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:02:08 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:02:08 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:02:08 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Updates to blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com): ========= Final blob
=========
2004.01.20 01:02:08 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:02:08 POP3 (left.minerva.com):
===================================
2004.01.20 01:02:08 POP3 (left.minerva.com): End execution
2004.01.20 01:02:08 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:02:08 Bozo on left: Synch operation completed

Now we retrieve messages 1 and 3 (both of which were retrieved before,
Click to expand...
2
and
4 from the earlier
session) but for some reason we don't retrieve 2 (the old 3). Then for
equally mystifying reasons
we delete 1 and 2 but not 3. Once more:

2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000001)
2004.01.20 01:05:17 Bozo on left: UploadItems: 0 messages to send
2004.01.20 01:05:17 Bozo on left: Synch operation completed
2004.01.20 01:05:17 Bozo on left: Synch operation started (flags = 00000030)
2004.01.20 01:05:17 Bozo on left: DoPOPDownload(flags = 00000030, max
Click to expand...
msg
=
ffffffff): full items
2004.01.20 01:05:17 POP3 (left.minerva.com): Begin execution
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= Initial blob
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
&BAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Port: 110, Secure: no,
Click to expand...
SPA:
no
2004.01.20 01:05:17 POP3 (left.minerva.com): Finding host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK POP3
<[email protected]>
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorizing to server
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] USER left.minerva.com/bozo
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] PASS *****
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Authorized to host
2004.01.20 01:05:17 POP3 (left.minerva.com): Connected to host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] STAT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): Server does not support UIDL.
Falling back on TOP.
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] LIST
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> 1 2922
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> .
2004.01.20 01:05:17 POP3 (left.minerva.com): ==== Comparing server and local
blobs ====
2004.01.20 01:05:17 POP3 (left.minerva.com):
==========================================
2004.01.20 01:05:17 POP3 (left.minerva.com): Do deletions: LoS: no
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] DELE 1
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnecting from host
2004.01.20 01:05:17 POP3 (left.minerva.com): [tx] QUIT
2004.01.20 01:05:17 POP3 (left.minerva.com): <rx> +OK
2004.01.20 01:05:17 POP3 (left.minerva.com): Disconnected from host
2004.01.20 01:05:17 POP3 (left.minerva.com): ========= No blob changes
=========
2004.01.20 01:05:17 POP3 (left.minerva.com):
===================================
2004.01.20 01:05:17 POP3 (left.minerva.com): End execution
2004.01.20 01:05:17 Bozo on left: ReportStatus: RSF_COMPLETED, hr =
0x00000000
2004.01.20 01:05:17 Bozo on left: Synch operation completed

... so we delete message 3 from previous session, #4 from the original try
on these four
messages, which we should have deleted last session (not to mention the
first session).

I hope this is enough to set the hook and will be happy to run more
examples. BTW I've
never seen it delete more than two messages per session, even with 100
messages read. The
un-read messages have seemed to be only #1 or #2 of a mailbox in any case
that I have
observed... messages 3 and onward if present have always been read... and
re-read and re-read.

Thanks for taking an interest in this. Looking forward to some code
changes - Greg

Excerpt from RFC1939 in which it is clearly stated that POP3 servers do
their deletions
BEFORE replying to the QUIT command:

6. The UPDATE State

When the client issues the QUIT command from the TRANSACTION state,
the POP3 session enters the UPDATE state. (Note that if the client
issues the QUIT command from the AUTHORIZATION state, the POP3
session terminates but does NOT enter the UPDATE state.)

If a session terminates for some reason other than a client-issued
QUIT command, the POP3 session does NOT enter the UPDATE state and
MUST not remove any messages from the maildrop.

QUIT

Arguments: none

Restrictions: none

Discussion:
The POP3 server removes all messages marked as deleted
from the maildrop and replies as to the status of this
operation. If there is an error, such as a resource
shortage, encountered while removing messages, the
maildrop may result in having some or none of the messages
marked as deleted be removed. In no case may the server
remove any messages not marked as deleted.

Whether the removal was successful or not, the server
then releases any exclusive-access lock on the maildrop
and closes the TCP connection.

Possible Responses:
+OK
-ERR some deleted messages not removed

Examples:
C: QUIT
S: +OK dewey POP3 server signing off (maildrop empty)
...
C: QUIT


Jeff Stephenson
Outlook Development
This posting is provided "AS IS" with no warranties, and confers no rights


I have observed severe POP3 mailbox mismanagement by 11.5608.5703 when
using
a POP3 server
that refuses to support UIDL and TOP. Our server operates this
Click to expand...
Click to expand...
way
as logic has
had and
also server
end.
Click to expand...
Click to expand...
 

Ask a Question

Want to reply to this thread or ask your own question?

You'll need to choose a username for the site, which only take a couple of moments. After that, you can post your question and our members will help you out.

Ask a Question

Similar Threads

Outlook Desktop (latest) stopped syncing IMAP accpounts from selfowned Mail server. 0
Duplicate Message-ID,UIDL,leave on server,repeated downloads of em 1
Scripting/PRFing POP3 server change to users accross a domain 0
messages aren't deleting from pop3 server after X days 0
POP3 and IMAP message retrieval w/o deletion from server 1
Outlook 2003 "finds server" but cannot connect 2
Outlook 2003 Comcast issue - Maillennium POP3/PROXY server 0
OL 2003: error 0x800408FC - 'The server name you entered can not be found on the network' 16

Top