IDLE not working with Exchange 2010 about s22.imap HOT 14 OPEN

Another observation - something is happening when a new message is received, but the NewMessage event handler is not fired. If I send an email to the monitored mailbox my debug log shows the following:

The thread '' (0x3160) has exited with code 0 (0x0).

from s22.imap.

The IDLE detection in current master makes many assumptions and have some possible race conditions. I have a few workarounds in my implementation but nothing that I'm really happy with.

To help more we need to know what the server is sending you. The trace log described in part at #45 should be able to provide the information if you would like to give it a go.

And there is multiple threads handling work in the background. so the Thread exit do not give much more than that some data or command was sent.

from s22.imap.

Thanks for the help Nikize

Here is my trace log -

S22.Imap Information: 0 : S -> * OK The Microsoft Exchange IMAP4 service is ready.
S22.Imap Information: 0 : C -> xm001 LOGIN "_" "_"
S22.Imap Information: 0 : S -> xm001 OK LOGIN completed.
S22.Imap Information: 0 : C -> xm002 CAPABILITY
S22.Imap Information: 0 : S -> * CAPABILITY IMAP4 IMAP4rev1 AUTH=NTLM AUTH=GSSAPI AUTH=PLAIN UIDPLUS CHILDREN IDLE NAMESPACE LITERAL+
S22.Imap Information: 0 : S -> xm002 OK CAPABILITY completed.
S22.Imap Information: 0 : C -> xm003 SELECT "INBOX"
S22.Imap Information: 0 : S -> * 12 EXISTS
S22.Imap Information: 0 : S -> * 0 RECENT
S22.Imap Information: 0 : S -> * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
S22.Imap Information: 0 : S -> * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
S22.Imap Information: 0 : S -> * OK [UNSEEN 1] Is the first unseen message
S22.Imap Information: 0 : S -> * OK [UIDVALIDITY 10533] UIDVALIDITY value
S22.Imap Information: 0 : S -> * OK [UIDNEXT 14] The next unique identifier value
S22.Imap Information: 0 : S -> xm003 OK [READ-WRITE] SELECT completed.
S22.Imap Information: 0 : C -> xm004 IDLE
S22.Imap Information: 0 : S -> + IDLE accepted, awaiting DONE command.
S22.Imap Information: 0 : S -> * 1 RECENT
S22.Imap Information: 0 : S -> * 13 EXISTS
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm004 OK IDLE completed.
S22.Imap Information: 0 : C -> xm005 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS INBOX (UIDNEXT 14)
S22.Imap Information: 0 : S -> xm005 OK STATUS completed.
S22.Imap Information: 0 : C -> xm006 IDLE
S22.Imap Information: 0 : S -> + IDLE accepted, awaiting DONE command.
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm006 OK IDLE completed.
S22.Imap Information: 0 : C -> xm007 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS INBOX (UIDNEXT 14)
S22.Imap Information: 0 : S -> xm007 OK STATUS completed.
S22.Imap Information: 0 : C -> xm008 IDLE
S22.Imap Information: 0 : S -> + IDLE accepted, awaiting DONE command.

from s22.imap.

Here is the trace log when I use the same code with a gmail account instead of Exchange. This is working fine and calling the NewMessage event handler.

S22.Imap Information: 0 : S -> * OK Gimap ready for requests from 207.71.50.147 y4if7729291oax.292
S22.Imap Information: 0 : C -> xm001 LOGIN "" ""
S22.Imap Information: 0 : S -> * CAPABILITY IMAP4rev1 UNSELECT IDLE NAMESPACE QUOTA ID XLIST CHILDREN X-GM-EXT-1 UIDPLUS COMPRESS=DEFLATE ENABLE MOVE CONDSTORE ESEARCH
S22.Imap Information: 0 : S -> xm001 OK **@gmail.com ** authenticated (Success)
S22.Imap Information: 0 : C -> xm002 SELECT "INBOX"
S22.Imap Information: 0 : S -> * FLAGS (\Answered \Flagged \Draft \Deleted \Seen $Forwarded)
S22.Imap Information: 0 : S -> * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen $Forwarded *)] Flags permitted.
S22.Imap Information: 0 : S -> * OK [UIDVALIDITY 623500725] UIDs valid.
S22.Imap Information: 0 : S -> * 11439 EXISTS
S22.Imap Information: 0 : S -> * 0 RECENT
S22.Imap Information: 0 : S -> * OK [UIDNEXT 16485] Predicted next UID.
S22.Imap Information: 0 : S -> * OK [HIGHESTMODSEQ 1505469]
S22.Imap Information: 0 : S -> xm002 OK [READ-WRITE] INBOX selected. (Success)
S22.Imap Information: 0 : C -> xm003 IDLE
S22.Imap Information: 0 : S -> + idling
S22.Imap Information: 0 : S -> * 11440 EXISTS
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm003 OK IDLE terminated (Success)
S22.Imap Information: 0 : C -> xm004 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS "INBOX" (UIDNEXT 16486)
S22.Imap Information: 0 : S -> xm004 OK Success
S22.Imap Information: 0 : C -> xm005 IDLE
S22.Imap Information: 0 : S -> + idling
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm005 OK IDLE terminated (Success)
S22.Imap Information: 0 : C -> xm006 UID FETCH 16485 (BODY[HEADER])
S22.Imap Information: 0 : S -> * 11440 FETCH (UID 16485 FLAGS (\Seen) BODY[HEADER] {835}
S22.Imap Information: 0 : S -> )
S22.Imap Information: 0 : S -> xm006 OK Success
S22.Imap Information: 0 : C -> xm007 IDLE
S22.Imap Information: 0 : S -> + idling

from s22.imap.

Maybe issue #31 is related or the same?
If I understand what happens correctly you should get a newMessage event. (but it depends on the value of lastUid in the EventDispatcher function)
I believe something goes wrong in the handling of UIDNEXT, with Exchange you get UIDNEXT 14 multiple times.
But with gmail the value changes so it works...
I'm not sure if this can be set before the first IDLE call, I can't find it does so you should have gotten a event for the first IDLE.

Now this became quite long, maybe you can find a solution that works you based on this.

My own solution for a similar issue have been to first separate the IDLE handling and the data handling to 2 separate connections. (modifying EventDispatcher in ImapClient.cs to not make the GetHighestUID call and just send raw imap data on to the client application instead.)
The reason for the separate connections is to not miss events, lets say 2 or more mails come at the same time, then only one event is raised.

The next step I do is to get the full list... Client.Search(SearchCondition.All), loop thru them but skip all UIDs that are less or equal to the last known UID.
This then handles the few remaining messages. and finally sets the LastKnownUID to the new value.
(Instead the SearchCondition should be changed. and before that the values for EXISTS, RECENT, and EXPUNGE should be compared to previous values, and also handled and acted upon regardless if they are in IDLE mode or not.)
The "" responses from the server only gives some meta info about what have changed and not a list of changed messages, Based on this it does not really make sense to send on a "guessed" UID in the NewMessage event.
If there was a RECENT "" data from the server, a search for recent flag could instead be used.

There is big room for improvements here, but I have a hard time to see a One-fits-all solution and that prevents me from creating a fix.
I would like to trace how other clients (ex.Outlook and Thunderbird) handle this by using wireshark or similar, to find the best way to keep track of IDLE modes.

That's as far as I have gotten.

from s22.imap.

Thanks again for your help here.

I'm a bit out of my depth here but stepping through ImapClient.cs, I may have located the problem in the EventDispatcher method. The method switches the m.Groups[2].Value and looks for "EXISTS" or "EXPUNGE".

When connecting to GMail, m.Groups[2].Value = "EXISTS".

When connecting ot Exchange, m.Groups[2].Value = "RECENT".

So there is no case for "RECENT" and it skips the newMessageEvent.Raise call.

    private void EventDispatcher() {
        uint lastUid = 0;
        while (true) {
            string response = idleEvents.Dequeue();
            Match m = Regex.Match(response, @"\*\s+(\d+)\s+(\w+)");
            if (!m.Success)
                continue;
            uint numberOfMessages = Convert.ToUInt32(m.Groups[1].Value),
                uid = GetHighestUID();
                            switch (m.Groups[2].Value.ToUpper()) {
                case "EXISTS":
                    if (lastUid != uid) {
                        newMessageEvent.Raise(this,
                            new IdleMessageEventArgs(numberOfMessages, uid, this));
                    }
                    break;
                case "EXPUNGE":
                    messageDeleteEvent.Raise(
                        this, new IdleMessageEventArgs(numberOfMessages, uid, this));
                    break;
            }
            lastUid = uid;
        }
    }

Should I add case "RECENT" that calls newMessageEvent?

from s22.imap.

This appears to be working now with the following changes:

1. Modify the SelectMailbox method as described in issue #31 as follows:

    private void SelectMailbox(string mailbox) {
        if (!Authed)
            throw new NotAuthenticatedException();
        if (mailbox == null)
            mailbox = defaultMailbox;
        // The requested mailbox is already selected.
        //if (selectedMailbox == mailbox)
            //return;
        lock (sequenceLock) {
            string tag = GetTag();
            string response = SendCommandGetResponse(tag + "SELECT " +
                Util.UTF7Encode(mailbox).QuoteString());
            // Fixme: evaluate untagged data?
            while (response.StartsWith("*"))
                response = GetResponse();
            if (!IsResponseOK(response, tag))
                throw new BadServerResponseException(response);
            selectedMailbox = mailbox;
        }
    }

2. Modify the EventDispatcher method as follows:

    private void EventDispatcher() {
        uint lastUid = 0;
        while (true) {
            string response = idleEvents.Dequeue();
            Match m = Regex.Match(response, @"\*\s+(\d+)\s+(\w+)");
            if (!m.Success)
                continue;
            uint numberOfMessages = Convert.ToUInt32(m.Groups[1].Value),
                uid = GetHighestUID();
            switch (m.Groups[2].Value.ToUpper()) {
                case "EXISTS":
                case "RECENT":
                    if (lastUid != uid)
                    {
                        newMessageEvent.Raise(this,
                            new IdleMessageEventArgs(numberOfMessages, uid, this));
                    }
                    break;
                case "EXPUNGE":
                    messageDeleteEvent.Raise(
                        this, new IdleMessageEventArgs(numberOfMessages, uid, this));
                    break;
            }
            lastUid = uid;
        }
    }

Do you see any problems with making these changes?

from s22.imap.

No, You have EXISTS as well in the server reply so the RECENT could and should be ignored in your case.
I would instead remove all references to lastUid, an probably also the uid = GetHighestUID();

Instead fetching a new complete list of uids in your NewMessage event handler, comparing that to previous list and take appropriate action if there is a new uid or a missing uid in the newely fetched list.

You might also want to do a pauseidleing call first in your event handler and then resumeidleing last, to avoid it going in and out of IDLE mode several times.
(First changing the declaration of those functions from private to public, otherwise you will need to remove your eventhandler and then re-adding to get that functionallity, don't forget try {} catch so it is resumed regardles of what happens in your handler)

from s22.imap.

I have mentioned some of my concerns above about not getting all messages by only relying on the NewMessage and its uid. (that, as proven, can in some cases have nothing to do with the email raising the event)

The GetHighestUID is called multiple times, once for every line that gets to the EventDispatcher and matches the pattern. (So this is a additional reason for removing this call)

But if you only have a message come in once in a while and not in "chunks" you will be fine with the changes you've done so far.

from s22.imap.

Thanks for the advice. I will look into removing references to uid in the EventDispatcher and handling it my NewMessage event handler.

from s22.imap.

Exchange sure is a strange beast, it's been causing nothing but trouble :-) Will do some experimenting when I get around to it.

cheers,
smiley22

from s22.imap.

I've been trying to re-produce this but haven't had much luck. I only have access to an Exchange 2003 server though, so this is something that must have changed with more recent versions of Exchange or it's due to some configuration option...

from s22.imap.

Hi,

have you ever had a chance to look into this?
I'm currently having similar issues with this, but in my case with CommuniGatePro (and Exchange 2010...).

Here are the trace logs for the different systems:

Exchange 2010:
S22.Imap Information: 0 : S -> * OK The Microsoft Exchange IMAP4 service is ready.
S22.Imap Information: 0 : C -> xm001 LOGIN "xxx" "xxx"
S22.Imap Information: 0 : S -> xm001 OK LOGIN completed.
S22.Imap Information: 0 : C -> xm002 CAPABILITY
S22.Imap Information: 0 : S -> * CAPABILITY IMAP4 IMAP4rev1 AUTH=NTLM AUTH=GSSAPI AUTH=PLAIN CHILDREN IDLE NAMESPACE LITERAL+
S22.Imap Information: 0 : S -> xm002 OK CAPABILITY completed.
S22.Imap Information: 0 : C -> xm003 SELECT "INBOX"
S22.Imap Information: 0 : S -> * 0 EXISTS
S22.Imap Information: 0 : S -> * 0 RECENT
S22.Imap Information: 0 : S -> * FLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)
S22.Imap Information: 0 : S -> * OK [PERMANENTFLAGS (\Seen \Answered \Flagged \Deleted \Draft $MDNSent)] Permanent flags
S22.Imap Information: 0 : S -> * OK [UIDVALIDITY 2047275] UIDVALIDITY value
S22.Imap Information: 0 : S -> * OK [UIDNEXT 1] The next unique identifier value
S22.Imap Information: 0 : S -> xm003 OK [READ-WRITE] SELECT completed.
S22.Imap Information: 0 : C -> xm004 IDLE
S22.Imap Information: 0 : S -> + IDLE accepted, awaiting DONE command.
S22.Imap Information: 0 : S -> * 1 RECENT
S22.Imap Information: 0 : S -> * 1 EXISTS
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm004 OK IDLE completed.
S22.Imap Information: 0 : C -> xm005 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS INBOX (UIDNEXT 1)
S22.Imap Information: 0 : S -> xm005 OK STATUS completed.
S22.Imap Information: 0 : C -> xm006 IDLE
S22.Imap Information: 0 : S -> + IDLE accepted, awaiting DONE command.
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm006 OK IDLE completed.
S22.Imap Information: 0 : C -> xm007 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS INBOX (UIDNEXT 1)
S22.Imap Information: 0 : S -> xm007 OK STATUS completed.
S22.Imap Information: 0 : C -> xm008 IDLE
S22.Imap Information: 0 : S -> + IDLE accepted, awaiting DONE command.

For CommuniGatePro:
S22.Imap Information: 0 : S -> * OK IMAP Server ready
S22.Imap Information: 0 : C -> xm001 LOGIN "xxx" "xxx"
S22.Imap Information: 0 : S -> xm001 OK connected to the backend server
S22.Imap Information: 0 : C -> xm002 CAPABILITY
S22.Imap Information: 0 : S -> * CAPABILITY IMAP4 IMAP4REV1 ACL NAMESPACE UIDPLUS IDLE LITERAL+ QUOTA ID MULTIAPPEND LISTEXT CHILDREN BINARY ESEARCH LOGIN-REFERRALS UNSELECT SASL-IR AUTH=LOGIN AUTH=PLAIN AUTH=CRAM-MD5 AUTH=DIGEST-MD5 AUTH=GSSAPI AUTH=MSN AUTH=NTLM
S22.Imap Information: 0 : S -> xm002 OK completed
S22.Imap Information: 0 : C -> xm003 SELECT "INBOX"
S22.Imap Information: 0 : S -> * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent $Hidden $Media $Forwarded Junk $Label1 $Label2 $Label3)
S22.Imap Information: 0 : S -> * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft $MDNSent $Hidden $Media $Forwarded Junk $Label1 $Label2 $Label3)] limited
S22.Imap Information: 0 : S -> * 3 EXISTS
S22.Imap Information: 0 : S -> * 0 RECENT
S22.Imap Information: 0 : S -> * OK [UIDNEXT 4] predicted next UID
S22.Imap Information: 0 : S -> * OK [UIDVALIDITY 350602722] UIDs valid
S22.Imap Information: 0 : S -> * OK [UNSEEN 3] message 3 is first unseen
S22.Imap Information: 0 : S -> xm003 OK [READ-WRITE] SELECT completed
S22.Imap Information: 0 : C -> xm004 IDLE
S22.Imap Information: 0 : S -> + idling
S22.Imap Information: 0 : S -> * 4 EXISTS
S22.Imap Information: 0 : S -> * 0 RECENT
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm004 OK completed

And for Dovecot, with which it is actually working:
S22.Imap Information: 0 : S -> * OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE AUTH=PLAIN AUTH=LOGIN AUTH=CRAM-MD5] IMAP ready.
S22.Imap Information: 0 : C -> xm001 LOGIN "xxx" "xxx"
S22.Imap Information: 0 : S -> xm001 OK [CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE COMPRESS=DEFLATE QUOTA ACL RIGHTS=texk] Logged in
S22.Imap Information: 0 : C -> xm002 CAPABILITY
S22.Imap Information: 0 : S -> * CAPABILITY IMAP4rev1 LITERAL+ SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND URL-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STATUS SPECIAL-USE BINARY MOVE COMPRESS=DEFLATE QUOTA ACL RIGHTS=texk
S22.Imap Information: 0 : S -> xm002 OK Capability completed.
S22.Imap Information: 0 : C -> xm003 SELECT "INBOX"
S22.Imap Information: 0 : S -> * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
S22.Imap Information: 0 : S -> * OK [PERMANENTFLAGS (\Answered \Flagged \Deleted \Seen \Draft *)] Flags permitted.
S22.Imap Information: 0 : S -> * 1 EXISTS
S22.Imap Information: 0 : S -> * 1 RECENT
S22.Imap Information: 0 : S -> * OK [UNSEEN 1] First unseen.
S22.Imap Information: 0 : S -> * OK [UIDVALIDITY 1402412138] UIDs valid
S22.Imap Information: 0 : S -> * OK [UIDNEXT 2] Predicted next UID
S22.Imap Information: 0 : S -> * OK [NOMODSEQ] No permanent modsequences
S22.Imap Information: 0 : S -> xm003 OK [READ-WRITE] Select completed (0.000 secs).
S22.Imap Information: 0 : C -> xm004 IDLE
S22.Imap Information: 0 : S -> + idling
S22.Imap Information: 0 : S -> * OK Still here
S22.Imap Information: 0 : S -> * 2 EXISTS
S22.Imap Information: 0 : S -> * 2 RECENT
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm004 OK Idle completed.
S22.Imap Information: 0 : C -> xm005 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS INBOX (UIDNEXT 3)
S22.Imap Information: 0 : S -> xm005 OK [CLIENTBUG] Status on selected mailbox completed.
S22.Imap Information: 0 : C -> xm006 IDLE
S22.Imap Information: 0 : S -> + idling
S22.Imap Information: 0 : C -> DONE
S22.Imap Information: 0 : S -> xm006 OK Idle completed.
S22.Imap Information: 0 : C -> xm007 STATUS "INBOX" (UIDNEXT)
S22.Imap Information: 0 : S -> * STATUS INBOX (UIDNEXT 3)
S22.Imap Information: 0 : S -> xm007 OK [CLIENTBUG] Status on selected mailbox completed.
S22.Imap Information: 0 : C -> xm008 IDLE
S22.Imap Information: 0 : S -> + idling

I can provide you with a test mailbox if needed.

Thanks in advance,
Phil

from s22.imap.

Hmm seems this was swept under the rug

from s22.imap.