deltachat-core-rust
deltachat-core-rust copied to clipboard
Published
20 hours ago •
deltachat
deltachat
Fix flaky test_fetch_existing test
For some reason UID SEARCH command sometimes return no results when we run it from add_all_recipients_as_contacts, but the message is immediately fetched afterwards with UID FETCH:
29.21 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:914: Started fetching existing contacts.
29.34 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:672: Folder "Sent" is empty.
29.47 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:2368: Collected no contacts from folder Sent
29.75 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:2368: Collected no contacts from folder INBOX
29.75 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:918: Done fetching existing contacts.
29.75 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:921: Started fetching existing messages.
29.89 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
30.03 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:98: Receiving message, seen=true...
30.04 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:120: received message has Message-Id: [email protected]
30.04 [events-ac3] DC_EVENT_INFO data1=0 data2=src/contact.rs:624: added contact id=10 [email protected]
30.04 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1921: not creating ad-hoc group: too few contacts
30.05 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1148: Message has 1 parts and is assigned to chat #Chat#12.
30.05 [events-ac3] DC_EVENT_MSGS_CHANGED data1=12 data2=12
30.06 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:896: 1 mails read from "INBOX".
cc @Hocuri @r10s
Here is a log with IMAP tracing enabled:
2022-06-26T15:22:45.553Z TRACE async_imap::imap_stream > decode: input: Ok("A0016 OK [READ-WRITE] Select completed (0.001 + 0.068 + 0.068 secs).\r\n")
30.70 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:672: Folder "Sent" is empty.
2022-06-26T15:22:45.555Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0017")), Ok("UID SEARCH FROM \"[email protected]\"")
2022-06-26T15:22:45.705Z TRACE async_imap::imap_stream > decode: input: Ok("* SEARCH\r\nA0017 OK Search completed (0.004 + 0.083 secs).\r\n")
2022-06-26T15:22:45.706Z TRACE async_imap::imap_stream > decode: input: Ok("A0017 OK Search completed (0.004 + 0.083 secs).\r\n")
2022-06-26T15:22:45.707Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0018")), Ok("SELECT \"INBOX\" (CONDSTORE)")
30.85 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:2368: Collected no contacts from folder Sent
2022-06-26T15:22:45.839Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [CLOSED] Previous mailbox closed.\r\n* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft \\*)] Flags permitted.\r\n* 1 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256940] UIDs valid\r\n* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.840Z TRACE async_imap::imap_stream > decode: input: Ok("* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft \\*)] Flags permitted.\r\n* 1 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256940] UIDs valid\r\n* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.840Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft \\*)] Flags permitted.\r\n* 1 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256940] UIDs valid\r\n* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.841Z TRACE async_imap::imap_stream > decode: input: Ok("* 1 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256940] UIDs valid\r\n* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.841Z TRACE async_imap::imap_stream > decode: input: Ok("* 0 RECENT\r\n* OK [UIDVALIDITY 1656256940] UIDs valid\r\n* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.841Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [UIDVALIDITY 1656256940] UIDs valid\r\n* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.841Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [UIDNEXT 2] Predicted next UID\r\n* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.841Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [HIGHESTMODSEQ 3] Highest\r\nA0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.842Z TRACE async_imap::imap_stream > decode: input: Ok("A0018 OK [READ-WRITE] Select completed (0.001 + 0.069 + 0.068 secs).\r\n")
2022-06-26T15:22:45.843Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0019")), Ok("UID SEARCH FROM \"[email protected]\"")
2022-06-26T15:22:45.990Z TRACE async_imap::imap_stream > decode: input: Ok("* SEARCH\r\nA0019 OK Search completed (0.003 + 0.073 secs).\r\n")
2022-06-26T15:22:45.990Z TRACE async_imap::imap_stream > decode: input: Ok("A0019 OK Search completed (0.003 + 0.073 secs).\r\n")
31.14 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:2368: Collected no contacts from folder INBOX
2022-06-26T15:22:45.992Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0020")), Ok("FETCH 1:* (UID RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)])")
31.14 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:918: Done fetching existing contacts.
31.14 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:921: Started fetching existing messages.
2022-06-26T15:22:46.127Z TRACE async_imap::imap_stream > decode: input: Ok("* 1 FETCH (UID 1 RFC822.SIZE 2099 BODY[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)] {163}\r\nFrom: <[email protected]>\r\nMessage-ID: <[email protected]>\r\nReferences: <[email protected]>\r\nChat-Version: 1.0\r\n\r\n)\r\nA0020 OK Fetch completed (0.001 + 0.070 secs).\r\n")
2022-06-26T15:22:46.128Z TRACE async_imap::imap_stream > decode: input: Ok("A0020 OK Fetch completed (0.001 + 0.070 secs).\r\n")
2022-06-26T15:22:46.132Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0021")), Ok("UID FETCH 1 (FLAGS BODY.PEEK[])")
31.28 [events-ac3] DC_EVENT_CONNECTIVITY_CHANGED data1=0 data2=0
2022-06-26T15:22:46.278Z TRACE async_imap::imap_stream > decode: input: Ok("* 1 FETCH (UID 1 FLAGS (\\Seen) BODY[] {2099}\r\nReturn-Path: <[email protected]>\r\nReceived: from testrun.org ([172.22.1.253])\r\n\tby afde54d32cc1 with LMTP\r\n\tid yMqvK795uGKwPTsA4buD8Q\r\n\t(envelope-from <[email protected]>); Sun, 26 Jun 2022 17:22:39 +0200\r\nReceived: from [127.0.0.1] (localhost [127.0.0.1]) by localhost (Mailerdaemon) with ESMTPSA id 0F60044851;\r\n\tSun, 26 Jun 2022 17:22:38 +0200 (CEST)\r\nDKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=testrun.org; s=dkim;\r\n\tt=1656256959;\r\n\th=from:subject:date:message-id:to:mime-version:content-type:references:autocrypt;\r\n\tbh=7TX9m8yenjwLE9lyFTXDEmSuLTNWZy1yBryvNsL0Xvo=;\r\n\tb=J76aOLFXNXm4Vn/wZrpm9s/7zknN+X+Y8d6RdgVBm6ma7IVzHisEiOynMyots+H8s2jCDr\r\n\t6jouwjMkxQPghQeseozjTWSQUNM1NaYjSug7dv6Xv7uXDYa1qiIXpYxGVA/wuRkN5VzCCj\r\n\tkoIwsGH/0D0zriKwNaebtp0+4R3Iv0BVcdZTacXQ7kpw4tokfu/0BYP74r9F2uVDNinlbG\r\n\tdhGGmkSYZjDV0H9FOJKSr6u7q/koYBRvyRzhFum7QIApa4SAFrbNaE5u4ljjRV2bU/aOwx\r\n\ttgJ5awXm0iMR0n2oGyc2KJXhUnguIRMYD0ZNk5j0PxPbU/kaFqyaSFmAxh6CYQ==\r\nContent-Type: text/plain; charset=utf-8; format=flowed; delsp=no\r\nSubject: =?utf-8?q?Message_from_tmp-ci=2E2napk=40testrun=2Eorg?=\r\nChat-Disposition-Notification-To: [email protected]\r\nFrom: <[email protected]>\r\nTo: <[email protected]>\r\nDate: Sun, 26 Jun 2022 15:22:39 +0000\r\nMessage-ID: <[email protected]>\r\nReferences: <[email protected]>\r\nChat-Version: 1.0\r\nAutocrypt: [email protected]; prefer-encrypt=mutual;\r\n\tkeydata=mDMEXlh13RYJKwYBBAHaRw8BAQdAzfVIAleCXMJrq8VeLlEVof6ITCviMktKjmcBKAu4m5\r\n\tC0GUFsaWNlIDxhbGljZUBleGFtcGxlLm9yZz6IkAQTFggAOBYhBC5vossjtTLXKGNLWGSwj2Gp7ZRD\r\n\tBQJeWHXdAhsDBQsJCAcCBhUKCQgLAgQWAgMBAh4BAheAAAoJEGSwj2Gp7ZRDE3oA/i4MCyDMTsjWqD\r\n\tZoQwX/A/GoTO2/V0wKPhjJJy/8m2pMAPkBjOnGOtx2SZpQvJGTa9h804RY6iDrRuI8A/8tEEXAA7g4\r\n\tBF5Ydd0SCisGAQQBl1UBBQEBB0AG7cjWy2SFAU8KnltlubVW67rFiyfp01JrRe6Xqy22HQMBCAeIeA\r\n\tQYFggAIBYhBC5vossjtTLXKGNLWGSwj2Gp7ZRDBQJeWHXdAhsMAAoJEGSwj2Gp7ZRDLo8BAObE8Gns\r\n\tGVwKzNqCvHeWgJsqhjS3C6gvSlV3tEm9XmF6AQDXucIyVfoBwoyMh2h6cSn/ATn5QJb35pgo+ivp3j\r\n\tsMAg==\r\nMIME-Version: 1.0\r\nX-Last-TLS-Session-Version: TLSv1.3\r\n\r\nmessage text\r\n\r\n)\r\n")
31.43 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:98: Receiving message, seen=true...
31.44 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:120: received message has Message-Id: [email protected]
31.45 [events-ac3] DC_EVENT_INFO data1=0 data2=src/contact.rs:624: added contact id=10 [email protected]
31.45 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1921: not creating ad-hoc group: too few contacts
31.45 [events-ac3] DC_EVENT_INFO data1=0 data2=src/dc_receive_imf.rs:1148: Message has 1 parts and is assigned to chat #Chat#12.
2022-06-26T15:22:46.305Z TRACE async_imap::imap_stream > decode: input: Ok("A0021 OK Fetch completed (0.004 + 0.078 + 0.003 secs).\r\n")
31.45 [events-ac3] DC_EVENT_MSGS_CHANGED data1=12 data2=12
2022-06-26T15:22:46.309Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0022")), Ok("SELECT \"Sent\" (CONDSTORE)")
31.46 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:896: 1 mails read from "INBOX".
2022-06-26T15:22:46.445Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [CLOSED] Previous mailbox closed.\r\n* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft \\*)] Flags permitted.\r\n* 0 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256941] UIDs valid\r\n* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.446Z TRACE async_imap::imap_stream > decode: input: Ok("* FLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft)\r\n* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft \\*)] Flags permitted.\r\n* 0 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256941] UIDs valid\r\n* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.446Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [PERMANENTFLAGS (\\Answered \\Flagged \\Deleted \\Seen \\Draft \\*)] Flags permitted.\r\n* 0 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256941] UIDs valid\r\n* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.446Z TRACE async_imap::imap_stream > decode: input: Ok("* 0 EXISTS\r\n* 0 RECENT\r\n* OK [UIDVALIDITY 1656256941] UIDs valid\r\n* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.447Z TRACE async_imap::imap_stream > decode: input: Ok("* 0 RECENT\r\n* OK [UIDVALIDITY 1656256941] UIDs valid\r\n* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.447Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [UIDVALIDITY 1656256941] UIDs valid\r\n* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.447Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [UIDNEXT 1] Predicted next UID\r\n* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.447Z TRACE async_imap::imap_stream > decode: input: Ok("* OK [HIGHESTMODSEQ 1] Highest\r\nA0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.447Z TRACE async_imap::imap_stream > decode: input: Ok("A0022 OK [READ-WRITE] Select completed (0.001 + 0.073 + 0.072 secs).\r\n")
2022-06-26T15:22:46.449Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0023")), Ok("FETCH 1:* (UID RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)])")
2022-06-26T15:22:46.584Z TRACE async_imap::imap_stream > decode: input: Ok("A0023 BAD Error in IMAP command FETCH: Invalid messageset (0.001 + 0.071 + 0.070 secs).\r\n")
31.73 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:896: 0 mails read from "Sent".
31.73 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:933: Done fetching existing messages.
Search on the inbox is successful and returns no results:
2022-06-26T15:22:45.843Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0019")), Ok("UID SEARCH FROM \"[email protected]\"")
2022-06-26T15:22:45.990Z TRACE async_imap::imap_stream > decode: input: Ok("* SEARCH\r\nA0019 OK Search completed (0.003 + 0.073 secs).\r\n")
2022-06-26T15:22:45.990Z TRACE async_imap::imap_stream > decode: input: Ok("A0019 OK Search completed (0.003 + 0.073 secs).\r\n")
31.14 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:2368: Collected no contacts from folder INBOX
Immediately after, we fetch the message with the From field we searched for:
2022-06-26T15:22:45.992Z TRACE async_imap::imap_stream > encode: input: Some(RequestId("A0020")), Ok("FETCH 1:* (UID RFC822.SIZE BODY.PEEK[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)])")
31.14 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:918: Done fetching existing contacts.
31.14 [events-ac3] DC_EVENT_INFO data1=0 data2=src/imap.rs:921: Started fetching existing messages.
2022-06-26T15:22:46.127Z TRACE async_imap::imap_stream > decode: input: Ok("* 1 FETCH (UID 1 RFC822.SIZE 2099 BODY[HEADER.FIELDS (MESSAGE-ID X-MICROSOFT-ORIGINAL-MESSAGE-ID FROM IN-REPLY-TO REFERENCES CHAT-VERSION AUTOCRYPT-SETUP-MESSAGE)] {163}\r\nFrom: <[email protected]>\r\nMessage-ID: <[email protected]>\r\nReferences: <[email protected]>\r\nChat-Version: 1.0\r\n\r\n)\r\nA0020 OK Fetch completed (0.001 + 0.070 secs).\r\n")
2022-06-26T15:22:46.128Z TRACE async_imap::imap_stream > decode: input: Ok("A0020 OK Fetch completed (0.001 + 0.070 secs).\r\n")
There is no such flakiness at the moment and rebasing the PR is not straightforward, closing it for now. If we encounter flakiness in this test, we can find this PR later.