Here is the slightly compressed log; edited private info out.
It's still long though, sorry everyone...
mail_open
=======================
2008-05-01 15:41:58,718 Mail - Login -
Mailbox/Server[{<server-ip>:993/ssl/novalidate-cert}INBOX],
username[path], OpenOptions[1]
2008-05-01 15:41:58,796 Mail - [IMAP] - [Trying IP address
[<server-ip>]]
2008-05-01 15:41:59,187 Mail - [IMAP] - [mm_dlog - Message: * OK
Microsoft Exchange Server 2007 IMAP4 service ready]
2008-05-01 15:41:59,203 Mail - [IMAP] - [mm_notify - StreamMailbox:
{<server-ip>:993/ssl/novalidate-cert}INBOX - Message: Microsoft Exchange
Server 2007 IMAP4 service ready]
2008-05-01 15:41:59,218 Mail - [IMAP] - [mm_dlog - Message: 00000000
CAPABILITY]
2008-05-01 15:41:59,234 Mail - [IMAP] - [mm_dlog - Message: * CAPABILITY
IMAP4 IMAP4rev1 AUTH=NTLM AUTH=GSSAPI IDLE NAMESPACE LITERAL+]
2008-05-01 15:41:59,234 Mail - [IMAP] - [mm_dlog - Message: 00000000 OK
CAPABILITY completed.]
2008-05-01 15:41:59,281 Mail - [IMAP] - [mm_login - NetMailbox, user,
pwd, trial: 0]
2008-05-01 15:41:59,281 Mail - [IMAP] - [mm_dlog - Message:
<suppressed>]
2008-05-01 15:41:59,703 Mail - [IMAP] - [mm_dlog - Message: 00000003
SELECT INBOX]
2008-05-01 15:41:59,734 Mail - [IMAP] - [mm_dlog - Message: * 1 EXISTS]
2008-05-01 15:41:59,734 Mail - [IMAP] - [mm_exists - StreamMailbox:
{<server-ip>:993/ssl/novalidate-cert}INBOX, MsgNumber: 1]
2008-05-01 15:41:59,734 Mail - [IMAP] - [mm_dlog - Message: * 0 RECENT]
2008-05-01 15:41:59,734 Mail - [IMAP] - [mm_dlog - Message: * FLAGS
(\Seen \Answered \Flagged \Deleted \Draft $MDNSent)]
2008-05-01 15:41:59,750 Mail - [IMAP] - [mm_dlog - Message: * OK
[PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)]
Permanent flags]
2008-05-01 15:41:59,750 Mail - [IMAP] - [mm_dlog - Message: * OK
[UIDVALIDITY 472] UIDVALIDITY value]
2008-05-01 15:41:59,750 Mail - [IMAP] - [mm_dlog - Message: * OK
[UIDNEXT 7] The next unique identifier value]
2008-05-01 15:41:59,750 Mail - [IMAP] - [mm_dlog - Message: 00000003 OK
[READ-WRITE] SELECT completed.]
2008-05-01 15:41:59,750 Mail - Login - Login Success, setting up active
session
1st mail_ping
=======================
NOTE: message is not new in this run, but same effect observed. I added
mail_debug around the mail_ping
this is the "message list setup" before the MAPI client access to
the message.
2008-05-01 15:42:00,390 - [IMAP] - [mm_dlog - Message: 00000005 NOOP]
2008-05-01 15:42:00,421 - [IMAP] - [mm_dlog - Message: 00000005 OK NOOP
completed.]
2008-05-01 15:42:00,828 - [IMAP] - [mm_flags - StreamMailbox:
{<server-ip>:993/ssl/novalidate-cert}INBOX, MsgNumber: 1]
2nd mail_ping & following mail_status [SA_MESSAGE only]
=======================
NOTE: about a minutes after the MAPI client accessed the message
triggering the UID change on server
the mail_status is something I added for fun and giggles while
exploring solutions.
2008-05-01 15:43:07,187 - [IMAP] - [mm_dlog - Message: 0000000a NOOP]
2008-05-01 15:43:07,218 - [IMAP] - [mm_dlog - Message: * 1 RECENT]
2008-05-01 15:43:07,218 - [IMAP] - [mm_dlog - Message: * 1 EXISTS]
2008-05-01 15:43:07,218 - [IMAP] - [mm_exists - StreamMailbox:
{<server-ip>:993/ssl/novalidate-cert}INBOX, MsgNumber: 1]
2008-05-01 15:43:07,218 - [IMAP] - [mm_dlog - Message: * 1 EXPUNGE]
2008-05-01 15:43:07,218 - [IMAP] - [mm_expunged - StreamMailbox:
{<server-ip>:993/ssl/novalidate-cert}INBOX, MsgNumber: 1]
2008-05-01 15:43:07,234 - [IMAP] - [mm_dlog - Message: 0000000a OK NOOP
completed.]
--- The mail_status logs
2008-05-01 15:43:11,078 - [IMAP] - [mm_dlog - Message: 0000000b STATUS
INBOX (MESSAGES)]
2008-05-01 15:43:11,109 - [IMAP] - [mm_dlog - Message: * STATUS INBOX
(MESSAGES 1) ]
2008-05-01 15:43:11,109 - [IMAP] - [mm_dlog - Message: 0000000b OK
STATUS completed.]
3rd mail_ping & mail_status [SA_MESSAGE only]
=======================
NOTE: this becomes my final state until I close the stream, flush my
list and start over.
2008-05-01 15:44:13,734 - [IMAP] - [mm_dlog - Message: 0000000c NOOP]
2008-05-01 15:44:13,765 - [IMAP] - [mm_dlog - Message: 0000000c OK NOOP
completed.]
-- mail_status logs
2008-05-01 15:44:13,765 - Refresh- IMAP cache out of whack - Recent[1]
while NMsgs[0]
2008-05-01 15:44:16,937 - [IMAP] - [mm_dlog - Message: 0000000d STATUS
INBOX (MESSAGES)]
2008-05-01 15:44:16,968 - [IMAP] - [mm_dlog - Message: * STATUS INBOX
(MESSAGES 1) ]
2008-05-01 15:44:16,968 - [IMAP] - [mm_dlog - Message: 0000000d OK
STATUS completed.]
The stream->nmsgs remains == 0 and stream->recent remains == 1,
stream->uid_validity is unchanged on restart.
My first hunch looking at the 2nd mail_ping; when the Exchange 'expunge'
notification comes in is that the order should be reversed. Of course
I'm no expert. What I mean is, if the "1 EXPUNGE" was processed first
and the "1 EXISTS" was processed second; I might not get into this
non-updating "MESSAGES" state.
Thanks
PatH
-----Original Message-----
From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED]
On Behalf Of Mark Crispin
Sent: Thursday, May 01, 2008 2:13 PM
To: Patrick Hamel (path)
Cc: [email protected]
Subject: Re: [Imap-uw] mail_ping issue with Exchange 2007
It would probably be more useful if you set OP_DEBUG in your mail_open()
calls and collect the mm_dlog() events; this will show a protocol
telemetry of what the server is actually doing.
With that in mind, I agree that this seems to be bad behavior on the
part of the server and your surmises appear correct. There isn't much
that you can do other than work around the problem. As far as I can
tell, c-client is performing correctly.
On Thu, 1 May 2008, Patrick Hamel (path) wrote:
> Hi,
>
> This might be a really specific one; looking for guidelines on doing
> the right thing with the API c-client offers.
>
> Here's the setup:
> o Server: Exchange 2007, with IMAP ports enabled
> o Client #1: simplistic client implementation using c-client (I'll
> give you a better idea in later)
> o Client #2: MAPI client
>
> I have single AND new (un-seen) message in the inbox mailbox and
> everyone is happy.
>
> The c-client based client does a simple:
>
> - mail_ping(stream)
> - loop from 1 to stream->nmsgs
> mail_uid( msgno ) <-- from the loop iterator decide to "do nothing"
> or "get details" on the message
> - done
>
> Now when the message is opened by the MAPI client, the next time the
> c-client client goes through the motion I see this:
>
> - mail_ping(stream)
> ** At this point:
> -> trace shows callback mm_exists gets called; did not see that in
> other iteration; trace is:: msg [1] exists mailbox -> trace shows
> callback mm_expunged gets called; did not see that in other
> iteration; trace is:: expunge msg [1]
>
> ** At this point
> -> stream->nmsgs == 0
> - loop ... is skipped
>
>> From this point stream->nmsgs stays == 0.
> and I flush the list a message since nmsgs == 0 ...
>
>
>> From what I gathered, Exchange 2007 will expunge the message when
> attributes are changed and assign a new UID to the message in the
> mailbox.
> I'm pretty sure I'm missing an important piece to have the
> stream->nmsgs value refresh to "1";
>
> I mean outside of "mail_close_full" and a new "mail_open" how would
> one break that cycle?
> NOTE:: Have not tried mail_close<->mail_open yet, (it's a guess) I'm
> looking for a better solution; or guidance that that's the way to go.
>
> Other Exchange version this works nicely with this simplistic
approach.
>
> Oh yeah, using imap 2007 from last October-December.
>
> Thank,
>
> PatH
>
>
-- Mark --
http://staff.washington.edu/mrc
Science does not emerge from voting, party politics, or public debate.
Si vis pacem, para bellum.
_______________________________________________
Imap-uw mailing list
[email protected]
https://mailman1.u.washington.edu/mailman/listinfo/imap-uw
