search

nextcloud / mail

💌 Mail app for Nextcloud
https://apps.nextcloud.com/apps/mail
GNU Affero General Public License v3.0
818 stars 255 forks source link

Mail not fetched from dovecot #5720

Closed StCyr closed 1 day ago

StCyr commented 2 years ago

Expected behavior

Mail should fetch all messages from the IMAP server

Actual behavior

A specific messages is not fetched

Additional details

On my mail server, I can see the message in the list of current messages (This is message 1636713879.M180672P32163.bollu.be,S=6462,W=6593:2,Se):

root@bollu:/home/debian# ls -lht /var/vmail/cyrille/Maildir/cur/ | head
total 33M
-rw------- 1 vmail vmail 9.1K Nov 12 13:32 1636723939.M753366P1299.bollu.be,S=9315,W=9524:2,
-rw------- 1 vmail vmail 6.4K Nov 12 10:44 1636713879.M180672P32163.bollu.be,S=6462,W=6593:2,Se
-rw------- 1 vmail vmail  19K Nov 12 08:29 1636705781.M462418P30716.bollu.be,S=18852,W=19341:2,S
-rw------- 1 vmail vmail  41K Nov 11 09:46 1636623978.M592776P19222.bollu.be,S=41609,W=42223:2,S

On my nextcloud server, there's no reference to that message in the DB:

MariaDB [nextcloud]> select subject,sent_at from oc_mail_messages order by sent_at desc limit 4;
+----------------------------------------------------------------------+------------+
| subject                                                              | sent_at    |
+----------------------------------------------------------------------+------------+
| [Nextcloud community] [🎁 Releases] NC 22.2.1 performance warning!    | 1636723939 |
| Zapytanie ofertowe                                                   | 1636707975 |
| *****SPAM***** charity donation                                      | 1636707957 |
| deck-react-native | Failed pipeline for master | fa5ee77b            | 1636705781 |
+----------------------------------------------------------------------+------------+

Look at the name of the 3 latest messages in the cur directory:

1636723939.M753366P1299.bollu.be 1636713879.M180672P32163.bollu.be 1636705781.M462418P30716.bollu.be

The first field is a timestamp that matches the sent_at field in the DB.

We can find a reference to messages 1636705781.M462418P30716.bollu.be and 1636723939.M753366P1299.bollu.be in the output of the select here above but there's no reference to message 1636713879.M180672P32163.bollu.be

Mail app

Mail app version: 1.10.5

Mailserver or service: Personal hosted mail server (postfix+dovecot)

Server configuration

Operating system: Debian 10

Web server: Apache 2.4.38-3 Database: Mariadb 10.3.31-0

PHP version: 7,3 Nextcloud Version: 22.2.0

Client configuration

Browser: Firefox 94.0.1 Operating system: Windows 10

StCyr commented 2 years ago

I should also add that Apple's Mail iOS app fetches the message without issue.

miaulalala commented 2 years ago

Are you able to attach a debugger and step through the code? Also, do you have anything in your nextcloud.log or horde_imap.log file for this?

StCyr commented 2 years ago

Everything looks normal in my horde_imap.log. Though, I can see that Mail doesn't request that message:

------------------------------
>> Sat, 13 Nov 2021 10:56:16 +0000
>> Connection to: imap://acme.org:993/
>> Server connection took 0.0148 seconds.
S: * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ AUTH=PLAIN AUTH=LOGIN] Dovecot (Debian) ready.
C: 1 AUTHENTICATE PLAIN [INITIAL CLIENT RESPONSE (username: cyrille@acme.org)]
S: 1 OK [CAPABILITY IMAP4rev1 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 BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE] Logged in
>> Command 1 took 0.1986 seconds.
C: 2 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY)
S: * STATUS INBOX (MESSAGES 170 UIDNEXT 11762 UIDVALIDITY 1604093540)
S: 2 OK Status completed (0.001 + 0.000 secs).
>> Command 2 took 0.0011 seconds.
C: 3 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY)
S: * STATUS INBOX (MESSAGES 170 UIDNEXT 11762 UIDVALIDITY 1604093540)
S: 3 OK Status completed (0.001 + 0.000 secs).
>> Command 3 took 0.0009 seconds.
C: 4 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY)
S: * STATUS INBOX (MESSAGES 170 UIDNEXT 11762 UIDVALIDITY 1604093540)
S: 4 OK Status completed (0.001 + 0.000 secs).
>> Command 4 took 0.0006 seconds.
C: 5 EXAMINE INBOX
S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MailFlagBit0 $Forwarded Forwarded $important $label1)
S: * OK [PERMANENTFLAGS ()] Read-only mailbox.
S: * 170 EXISTS
S: * 0 RECENT
S: * OK [UIDVALIDITY 1604093540] UIDs valid
S: * OK [UIDNEXT 11762] Predicted next UID
S: * OK [HIGHESTMODSEQ 27659] Highest
S: 5 OK [READ-ONLY] Examine completed (0.001 + 0.000 secs).
>> Command 5 took 0.0006 seconds.
C: 6 UID FETCH 10337,10811,11037:11038,11310,11374,11416,11418,11450,11468,11551,11573,11584,11587,11670,11676,11679,11693,11731,11753 (ENVELOPE FLAGS INTERNALDATE BODY.PEEK[HEADER])

The missing message as an UID of 11749 according to my dovecot-uidlist file:

root@bollu:/var/vmail/cyrille/Maildir# grep 1636713879.M180672P32163.bollu.be dovecot-uidlist
11749 :1636713879.M180672P32163.bollu.be,S=6462,W=6593

However, I suspect that it's normal that Mail doesn't request that message since it's not in its database. I might have to investigate why this message's uid didn't reach Mail's database in the first place...

StCyr commented 2 years ago

Ok, I've probably found the logs corresponding to the time when the initial fetch failed:

------------------------------
>> Fri, 12 Nov 2021 10:44:38 +0000
>> Connection to: imap://acme.org:993/
>> Server connection took 0.0126 seconds.
S: * OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE LITERAL+ AUTH=PLAIN AUTH=LOGIN] Dovecot (Debian) ready.
C: 1 AUTHENTICATE PLAIN [INITIAL CLIENT RESPONSE (username: cyrille@acme.org)]
S: 1 OK [CAPABILITY IMAP4rev1 SASL-IR LOGIN-REFERRALS ID ENABLE IDLE SORT SORT=DISPLAY THREAD=REFERENCES THREAD=REFS THREAD=ORDEREDSUBJECT MULTIAPPEND UR
L-PARTIAL CATENATE UNSELECT CHILDREN NAMESPACE UIDPLUS LIST-EXTENDED I18NLEVEL=1 CONDSTORE QRESYNC ESEARCH ESORT SEARCHRES WITHIN CONTEXT=SEARCH LIST-STA
TUS BINARY MOVE SNIPPET=FUZZY LITERAL+ NOTIFY SPECIAL-USE] Logged in
>> Command 1 took 0.1975 seconds.
C: 2 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY)
S: * STATUS INBOX (MESSAGES 177 UIDNEXT 11749 UIDVALIDITY 1604093540)
S: 2 OK Status completed (0.001 + 0.000 secs).
>> Command 2 took 0.0009 seconds.
C: 3 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY)
S: * STATUS INBOX (MESSAGES 178 UIDNEXT 11750 UIDVALIDITY 1604093540)
S: 3 OK Status completed (0.004 + 0.000 + 0.003 secs).
>> Command 3 took 0.0043 seconds.
C: 4 STATUS INBOX (MESSAGES UIDNEXT UIDVALIDITY)
S: * STATUS INBOX (MESSAGES 178 UIDNEXT 11750 UIDVALIDITY 1604093540)
S: 4 OK Status completed (0.001 + 0.000 secs).
>> Command 4 took 0.0009 seconds.
C: 5 EXAMINE INBOX
S: * FLAGS (\Answered \Flagged \Deleted \Seen \Draft $MailFlagBit0 $Forwarded Forwarded $important $label1)
S: * OK [PERMANENTFLAGS ()] Read-only mailbox.
S: * 178 EXISTS
S: * 1 RECENT
S: * OK [UNSEEN 153] First unseen.
S: * OK [UIDVALIDITY 1604093540] UIDs valid
S: * OK [UIDNEXT 11750] Predicted next UID
S: * OK [HIGHESTMODSEQ 27616] Highest
S: 5 OK [READ-ONLY] Examine completed (0.002 + 0.000 + 0.001 secs).
>> Command 5 took 0.0021 seconds.
C: 6 UID FETCH 10337,10811,11037:11038,11310,11374,11416,11418,11450,11468,11493,11551,11573,11584,11587,11670,11676,11679,11693,11698,11706,11731,11744:
11745,11747:11748 (ENVELOPE FLAGS INTERNALDATE BODY.PEEK[HEADER])

Could it be that Mail always issues 3 STATUS INBOX commands in a row and that the message got delivered between the 1st and 2nd call and therefore went ignored by Mail's next UID FETCH command?

StCyr commented 2 years ago

Hmmm... the message has been retrieved on my dev box, which is running Mail 1.11.0-alpha.2

ChristophWurst commented 1 day ago

Sounds like it was resolved.