Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fetch return result unrelated to fetch command params. #334

Open
inkhey opened this issue Jan 12, 2018 · 9 comments
Open

Fetch return result unrelated to fetch command params. #334

inkhey opened this issue Jan 12, 2018 · 9 comments

Comments

@inkhey
Copy link

inkhey commented Jan 12, 2018

Hello, i'm using imapclient 1.1 (last stable, don't know when 2.0 will be released in pip) .
I discovered a weird bug when using : 

for msgid, data in imapc.fetch(uids, ['BODY.PEEK[]']).items():
    msg = message_from_bytes(data[b'BODY[]'])

sometime data return KeyError due to lack of b'BODY'. So i checked and i found a data object related to what i'm doing with an other IMAP client at the same time (modify flags of messages).

This behaviour is really weird. It should be either explained in doc or results should be correctly filtered to avoid this type of problem.

@NicolasLM
Copy link
Collaborator

Hey, as far as I know the only possibilities for two instances of IMAPClient to interact with each other are:

  • They are the same instance, shared between multiple threads, which is unsafe
  • They interact through the IMAP server, which means it works as intended

Skimming through the code related to the issue, it looks like the 2nd option. Maybe something else is altering the messages while you iterate over them?

It's hard to tell anything more without seeing logs of what happens.

@inkhey
Copy link
Author

inkhey commented Jan 12, 2018

Yes, something alterate the messages : the other imap client : thunderbird.
I was checking if my mail fetcher work correctly. I do have a thunderbird client in one hand and my email fetcher build with imapclient in the other hand.

The imapclient search for unflagged items :
uids = imapc.search(['UNFLAGGED'])

Then it try to get mail content of thoses mail

for msgid, data in imapc.fetch(uids, ['BODY.PEEK[]']).items():
    msg = message_from_bytes(data[b'BODY[]'])

Then it try to do something with those mail and then it marked those mail as flagged :

IMAP_CHECKED_FLAG = imapclient.FLAGGED
imapc.add_flags((mail.uid,), IMAP_CHECKED_FLAG)

That's a daemon so, it's always waiting through IDLE or through polling for new unflagged mail.

When i launch this and modify flagged flag on thunderbird,
i got sometime data value as fetch response like this : 

{b'SEQ': 30, b'FLAGS': (b'\\Flagged', b'NonJunk')}

Which really seems related to thunderbird client action, but isn't what i'm expecting to see when i fetch "body.peek[]".

@NicolasLM
Copy link
Collaborator

I ran a small experiment and indeed the behavior is unexpected:

import getpass
import sys

import imapclient

with imapclient.IMAPClient(host="bar.org") as client:
    client.login("[email protected]", getpass.getpass())
    client.select_folder("INBOX")

    while True:
        uids = client.search(['UNFLAGGED'])
        for msgid, data in client.fetch(uids, ['INTERNALDATE']).items():
            if b'FLAGS' in data:
                print(msgid, data)
            if b'INTERNALDATE' not in data:
                print("PROBLEM FOUND")
                if msgid not in uids:
                    print("msgid not in uids")
                sys.exit()

Running the script while flagging/unflagging random messages in the inbox results in:

12 {b'SEQ': 12, b'FLAGS': (b'\\Flagged', b'\\Seen'), b'INTERNALDATE': datetime.datetime(2017, 11, 6, 11, 10, 42)}
11 {b'SEQ': 11, b'FLAGS': (b'\\Flagged', b'\\Seen'), b'INTERNALDATE': datetime.datetime(2017, 11, 3, 14, 37, 40)}
17 {b'SEQ': 17, b'FLAGS': (b'\\Flagged', b'\\Seen'), b'INTERNALDATE': datetime.datetime(2017, 11, 16, 11, 37, 59)}
11 {b'SEQ': 11, b'FLAGS': (b'\\Seen',)}
PROBLEM FOUND
msgid not in uids

So indeed, we are receiving updates for messages we don't want (tested on ssl0.ovh.net). @mjs Do you know if this is a bug or a feature?

@mjs
Copy link
Owner

mjs commented Jan 13, 2018

Maybe unsolicited responses about other messages are getting mixed in?

Debug logs so we can see the protocol level details would be very helpful.

@NicolasLM
Copy link
Collaborator

DEBUG:imapclient.imapclient:> b'GLLL125 UID SEARCH UNFLAGGED'
DEBUG:imapclient.imaplib:< b'* SEARCH 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 29 33'
DEBUG:imapclient.imaplib:       matched r'b'\\* (?P<type>[A-Z-]+)( (?P<data>.*))?'' => (b'SEARCH', b' 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 29 33', b'1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 29 33')
DEBUG:imapclient.imaplib:untagged_responses[SEARCH] 0 += ["b'1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 29 33'"]
DEBUG:imapclient.imaplib:< b'* 28 FETCH (FLAGS (\\Seen))'
DEBUG:imapclient.imaplib:       matched r'b'\\* (?P<data>\\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?'' => (b'28', b'FETCH', b' (FLAGS (\\Seen))', b'(FLAGS (\\Seen))')
DEBUG:imapclient.imaplib:untagged_responses[FETCH] 0 += ["b'28 (FLAGS (\\Seen))'"]
DEBUG:imapclient.imaplib:< b'GLLL125 OK Search completed (0.000 secs).'
DEBUG:imapclient.imaplib:       matched r'b'(?P<tag>GLLL\\d+) (?P<type>[A-Z]+) (?P<data>.*)'' => (b'GLLL125', b'OK', b'Search completed (0.000 secs).')
DEBUG:imapclient.imaplib:untagged_responses[SEARCH] => [b'1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 29 33']
DEBUG:imapclient.imaplib:> b'GLLL126 UID FETCH 1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20,21,22,23,24,25,26,29,33 (INTERNALDATE)'
DEBUG:imapclient.imaplib:< b'* 1 FETCH (UID 1 INTERNALDATE "08-Sep-2017 14:47:45 +0200")'
DEBUG:imapclient.imaplib:       matched r'b'\\* (?P<data>\\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?'' => (b'1', b'FETCH', b' (UID 1 INTERNALDATE "08-Sep-2017 14:47:45 +0200")', b'(UID 1 INTERNALDATE "08-Sep-2017 14:47:45 +0200")')
DEBUG:imapclient.imaplib:untagged_responses[FETCH] 1 += ["b'1 (UID 1 INTERNALDATE "08-Sep-2017 14:47:45 +0200")'"]
DEBUG:imapclient.imaplib:< b'* 2 FETCH (UID 2 INTERNALDATE "11-Sep-2017 10:22:01 +0200")'
DEBUG:imapclient.imaplib:       matched r'b'\\* (?P<data>\\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?'' => (b'2', b'FETCH', b' (UID 2 INTERNALDATE "11-Sep-2017 10:22:01 +0200")', b'(UID 2 INTERNALDATE "11-Sep-2017 10:22:01 +0200")')
DEBUG:imapclient.imaplib:untagged_responses[FETCH] 2 += ["b'2 (UID 2 INTERNALDATE "11-Sep-2017 10:22:01 +0200")'"]
[...]
DEBUG:imapclient.imaplib:< b'* 29 FETCH (UID 29 INTERNALDATE "09-Jan-2018 13:24:10 +0100")'
DEBUG:imapclient.imaplib:       matched r'b'\\* (?P<data>\\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?'' => (b'29', b'FETCH', b' (UID 29 INTERNALDATE "09-Jan-2018 13:24:10 +0100")', b'(UID 29 INTERNALDATE "09-Jan-2018 13:24:10 +0100")')
DEBUG:imapclient.imaplib:untagged_responses[FETCH] 27 += ["b'29 (UID 29 INTERNALDATE "09-Jan-2018 13:24:10 +0100")'"]
DEBUG:imapclient.imaplib:< b'* 30 FETCH (UID 33 INTERNALDATE "10-Jan-2018 13:17:11 +0100")'
DEBUG:imapclient.imaplib:       matched r'b'\\* (?P<data>\\d+) (?P<type>[A-Z-]+)( (?P<data2>.*))?'' => (b'30', b'FETCH', b' (UID 33 INTERNALDATE "10-Jan-2018 13:17:11 +0100")', b'(UID 33 INTERNALDATE "10-Jan-2018 13:17:11 +0100")')
DEBUG:imapclient.imaplib:untagged_responses[FETCH] 28 += ["b'30 (UID 33 INTERNALDATE "10-Jan-2018 13:17:11 +0100")'"]
DEBUG:imapclient.imaplib:< b'GLLL126 OK Fetch completed.'
DEBUG:imapclient.imaplib:       matched r'b'(?P<tag>GLLL\\d+) (?P<type>[A-Z]+) (?P<data>.*)'' => (b'GLLL126', b'OK', b'Fetch completed.')
DEBUG:imapclient.imaplib:untagged_responses[FETCH] => [b'28 (FLAGS (\\Seen))', b'1 (UID 1 INTERNALDATE "08-Sep-2017 14:47:45 +0200")', b'2 (UID 2 INTERNALDATE "11-Sep-2017 10:22:01 +0200")', b'3 (UID 3 INTERNALDATE "13-Sep-2017 13:13:05 +0200")', b'4 (UID 4 INTERNALDATE "14-Sep-2017 10:59:04 +0200")', b'5 (UID 5 INTERNALDATE "19-Sep-2017 10:38:55 +0200")', b'6 (UID 6 INTERNALDATE "22-Sep-2017 17:25:53 +0200")', b'7 (UID 7 INTERNALDATE "28-Sep-2017 14:24:15 +0200")', b'8 (UID 8 INTERNALDATE "28-Sep-2017 14:38:29 +0200")', b'9 (UID 9 INTERNALDATE "28-Sep-2017 15:31:11 +0200")', b'10 (UID 10 INTERNALDATE "10-Oct-2017 15:44:48 +0200")', b'11 (UID 11 INTERNALDATE "03-Nov-2017 14:37:40 +0100")', b'12 (UID 12 INTERNALDATE "06-Nov-2017 11:10:42 +0100")', b'13 (UID 13 INTERNALDATE "07-Nov-2017 11:07:13 +0100")', b'14 (UID 14 INTERNALDATE "08-Nov-2017 13:11:54 +0100")', b'15 (UID 15 INTERNALDATE "08-Nov-2017 14:12:25 +0100")', b'16 (UID 16 INTERNALDATE "13-Nov-2017 12:09:05 +0100")', b'17 (UID 17 INTERNALDATE "16-Nov-2017 11:37:59 +0100")', b'18 (UID 18 INTERNALDATE "27-Nov-2017 14:57:21 +0100")', b'19 (UID 19 INTERNALDATE "11-Dec-2017 15:39:10 +0100")', b'20 (UID 20 INTERNALDATE "15-Dec-2017 12:40:57 +0100")', b'21 (UID 21 INTERNALDATE "15-Dec-2017 12:50:00 +0100")', b'22 (UID 22 INTERNALDATE "20-Dec-2017 14:36:40 +0100")', b'23 (UID 23 INTERNALDATE "21-Dec-2017 17:32:47 +0100")', b'24 (UID 24 INTERNALDATE "03-Jan-2018 09:48:40 +0100")', b'25 (UID 25 INTERNALDATE "08-Jan-2018 11:27:16 +0100")', b'26 (UID 26 INTERNALDATE "08-Jan-2018 12:17:12 +0100")', b'29 (UID 29 INTERNALDATE "09-Jan-2018 13:24:10 +0100")', b'30 (UID 33 INTERNALDATE "10-Jan-2018 13:17:11 +0100")']

These logs show that message 28 is not in the FETCH query but still returned because it is received as an untagged response before the FETCH query.

@NicolasLM
Copy link
Collaborator

See this bug reported 18 years ago which describes well the problem we're seeing: https://bugzilla.mozilla.org/show_bug.cgi?id=55126

@christian-intra2net
Copy link

Unsolicited responses is actually a nice feature of IMAP, e.g. notifying users that new mail has arrived even whey they do not actively ask for it. Unfortunately, many email clients ignore these or even fail if they encounter these. One hacky way to avoid them is to call imaplib.IMAP.response(code) just before running imaplib.IMAP.uid(code, ...) (e.g. for code in 'SEARCH', 'STATUS', 'FETCH', 'APPEND', 'STORE', ... .)

I would love to use ImapClient in my testing code but unsolicited responses would probably crash my test in unpredictable way, so cannot use it for now... . So if somebody added this, it would be appreciated.

@mjs
Copy link
Owner

mjs commented Nov 11, 2019

Thanks @christian-intreems a2net. It certainly is likely that unprocessed unsocilicted responses are getting incorrectly used as the response to some later command.

I'll take a look at how we can solve this.

@link2xt
Copy link

link2xt commented Aug 7, 2020

Even worse, it seems parse_fetch_response does not check for response type, assuming that all responses to fetch are fetches:

def parse_fetch_response(text, normalise_times=True, uid_is_key=True):

As a workaround, it is possible to execute NOOP before doing FETCH, but if another client is executing commands in the same folder on another connection, it is still possible that unsolicited responses will be returned.

As a solution, FETCH response parser should drop non-FETCH results. As for unexpected FETCH results, it is impossible to filter them out: library user has to do it based on SEQ or UID and drop responses that it did not ask for.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants