You are viewing a plain text version of this content. The canonical link for it is here.
Posted to server-dev@james.apache.org by Jerry Malcolm <te...@malcolms.com> on 2019/10/31 17:35:04 UTC

Re: Moving Servers Wipes Out iPhone's Mail Accounts (IMAP Trace attached)

(I'm moving this thread to the dev forum since it appears now to not be 
a user problem)....

More data now... Since iPhone doesn't load the correct email list and 
TBird does, I traced the precise same scenario with the same email 
account with TBird as the previous iPhone trace in the post below.  As I 
suspected, in order to do an initial full sync on a folder, TBird is 
asking for the list of UIDs in a different way. Note from the two traces:

TBird: UID fetch 1:* (FLAGS)
     Response: 1 FETCH (FLAGS (\\Seen) UID 5801)  (...followed by many 
other UIDs including the ones in iPhone search below)
---
iPhone: UID SEARCH RETURN (COUNT) 1:* NOT DELETED
      Response: ESEARCH (TAG "39") UID ALL 7776,7955:7970,7975:8033

The two queries above are for the same email account/folder. Again, I'm 
not an IMAP expert.  But it appears that both should return the same 
list of UIDs even though they ask for it differently.

Summary... the TBird query gets all UIDs for the folder starting at 5801 
as expected.  The iPhone query gets a subset of UIDs starting at 7776.  
This continues to support my current theory that the code that processes 
UID SEARCH RETURN (COUNT) 1:*.... is not correct.

If someone knows what class processes these imap queries, please let me 
know.  I'm going to dig into the code now.  But a few pointers to the 
package/classes would be helpful.

Thunderbird trace:

127 Request: 19 select "INBOX"
129,Response: * FLAGS (\\Answered \\Deleted \\Draft \\Flagged \\Seen 
"MailFlagBit1 "MailFlagBit0 NonJunk "label3 "label1 "Forwarded)
130,Response: 19 OK [READ-WRITE] SELECT completed.
132 Request: 20 getquotaroot "INBOX"
134 Response: * QUOTAROOT "INBOX" #private&jerry@malcolms.com
135,Response: 20 OK GETQUOTAROOT completed.
137,Request: 21 UID fetch 1:* (FLAGS)
139,Response: * 1 FETCH (FLAGS (\\Seen) UID 5801)
140,Response: * 2 FETCH (FLAGS (\\Seen) UID 5802)
141,Response: * 4 FETCH (FLAGS (\\Seen) UID 5804)

On 10/29/2019 3:12 PM, Jerry Malcolm wrote:
> Ok, I need an IMAP expert.... Below is a very brief trace of the 
> communications between iPhone mail and JAMES (3.4).  I completely 
> deleted an account on my iPhone, then recreated it while in airplane 
> mode to make sure I didn't miss any communications in my trace.  I 
> started the trace, exited airplane mode and let the iPhone do an 
> initial sync with the account.  The inbox folder in this account has 
> over 1000 emails going back to early 2019.
>
> I'm not an expert in IMAP.  But it appears that the iPhone mail app 
> requests all of the emails 1:* (see line 812), but JAMES returns a 
> single id plus two ranges (line 813).  But the total count JAMES 
> reports is nowhere near the full 1000.  Subsequently (line 822), 
> iPhone requests the emails JAMES told it about in line 813.  From what 
> I can tell, the problem is in line 813.  JAMES did not report all of 
> the actual mail that is in the INBOX, which is exactly what I'm seeing 
> on the phone.  Shouldn't JAMES return all 1000+ email ids that exist 
> in INBOX?  Or am I reading the IMAP trace incorrectly?
>
> Note that the only emails JAMES reports came in AFTER I migrated to 
> the new server and to the James 3.4 from v3b5.  It appears that there 
> is something different about pre-existing emails in the mailbox folder 
> that is causing JAMES not to recognize them.  But this problem ONLY 
> exists on the iPhone mail app.  Thunderbird gets all of the mail for 
> the inbox.  So is iPhone must be sending a slightly different request 
> command syntax than other clients do (??)  Just speculating....
>
>  798 IMAP Request: 37 SELECT INBOX
>  802 IMAP Response: 37 OK [READ-WRITE] SELECT completed.
>  806 IMAP Request: 38 UID SEARCH RETURN (COUNT) 1:* NOT DELETED
>  808 IMAP Response: * ESEARCH (TAG "38") UID COUNT 76
>  809 IMAP Response: 38 OK SEARCH completed.
>  812 IMAP Request: 39 UID SEARCH RETURN (ALL) 1:* NOT DELETED
>  813 IMAP Response: * ESEARCH (TAG "39") UID ALL 7776,7955:7970,7975:8033
>  814 IMAP Response: 39 OK SEARCH completed.
>  817 IMAP Request: 40 UID SEARCH RETURN (ALL) 929:* NOT DELETED
>  818 IMAP Response: * ESEARCH (TAG "40") UID ALL 7955:7970,7975:8033
>  819 IMAP Response: 40 OK SEARCH completed.
>  822 IMAP Request: 41 UID FETCH 7955:7970,7975:8033 (INTERNALDATE UID 
> RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from 
> content-type to cc bcc message-id in-reply-to references list-id 
> x-universally-unique-identifier)])
>
> On 10/22/2019 3:07 AM, Matthieu Baechler wrote:
>> Hi Jerry,
>>
>> I don't think trying to guess what happen will help you much. I would
>> rather try to capture the IMAP session.
>>
>> I see two ways to do that:
>>
>> 1. you write a IMAP session logger in James (it should be really easy,
>> I don't know why it's not already there)
>>
>> 2. you disable SSL on the phone and do a tcpdump on the server
>>
>> Once you'll have the IMAP session capture, it will be easier to
>> diagnose your problem.
>>
>> Cheers,
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
> For additional commands, e-mail: server-user-help@james.apache.org
>

---------------------------------------------------------------------
To unsubscribe, e-mail: server-dev-unsubscribe@james.apache.org
For additional commands, e-mail: server-dev-help@james.apache.org


(Resolved): Moving Servers Wipes Out iPhone's Mail Accounts

Posted by Jerry Malcolm <te...@malcolms.com>.
Finally, after 2 weeks, iPhones have all of their mail.  The problem was 
that my Lucene index was corrupted. Or to be more precise, only emails 
from the last two weeks since I first started up James on the new 
environment were indexed. Even after renaming (effectively removing) the 
/var/store/lucene folder, the index would not fully rebuild.  Same 
problem... but worse now... now it showed only mail that came in over 
the last 10 minutes since I cleaned the lucene index folder and lost the 
last 2 weeks' mail that actually was indexed.  On a whim, I changed 
indexer.xml to use lazyIndex instead of luceneIndex... voila.... all of 
the folders were fully indexed, and iPhone has all of the mail for each 
folder.  Couldn't find much documentation on lazyIndex vs. luceneIndex.  
But at this point, I think I'll take having mail back on my client's 
iPhones over any downside to using lazyIndex. But.... educate me if 
there are serious downsides to using lazyIndex.

Thunderbird populates folders using a different imap command which, 
apparently, goes straight to the JPA database instead of using the 
Lucene index.  So that's why the problem didn't appear in TBird.

I'm going to start another thread in the dev group specifically to 
discuss the Lucene issue.

Jerry

On 10/31/2019 12:35 PM, Jerry Malcolm wrote:
> (I'm moving this thread to the dev forum since it appears now to not 
> be a user problem)....
>
> More data now... Since iPhone doesn't load the correct email list and 
> TBird does, I traced the precise same scenario with the same email 
> account with TBird as the previous iPhone trace in the post below.  As 
> I suspected, in order to do an initial full sync on a folder, TBird is 
> asking for the list of UIDs in a different way. Note from the two traces:
>
> TBird: UID fetch 1:* (FLAGS)
>     Response: 1 FETCH (FLAGS (\\Seen) UID 5801)  (...followed by many 
> other UIDs including the ones in iPhone search below)
> ---
> iPhone: UID SEARCH RETURN (COUNT) 1:* NOT DELETED
>      Response: ESEARCH (TAG "39") UID ALL 7776,7955:7970,7975:8033
>
> The two queries above are for the same email account/folder. Again, 
> I'm not an IMAP expert.  But it appears that both should return the 
> same list of UIDs even though they ask for it differently.
>
> Summary... the TBird query gets all UIDs for the folder starting at 
> 5801 as expected.  The iPhone query gets a subset of UIDs starting at 
> 7776.  This continues to support my current theory that the code that 
> processes UID SEARCH RETURN (COUNT) 1:*.... is not correct.
>
> If someone knows what class processes these imap queries, please let 
> me know.  I'm going to dig into the code now.  But a few pointers to 
> the package/classes would be helpful.
>
> Thunderbird trace:
>
> 127 Request: 19 select "INBOX"
> 129,Response: * FLAGS (\\Answered \\Deleted \\Draft \\Flagged \\Seen 
> "MailFlagBit1 "MailFlagBit0 NonJunk "label3 "label1 "Forwarded)
> 130,Response: 19 OK [READ-WRITE] SELECT completed.
> 132 Request: 20 getquotaroot "INBOX"
> 134 Response: * QUOTAROOT "INBOX" #private&jerry@malcolms.com
> 135,Response: 20 OK GETQUOTAROOT completed.
> 137,Request: 21 UID fetch 1:* (FLAGS)
> 139,Response: * 1 FETCH (FLAGS (\\Seen) UID 5801)
> 140,Response: * 2 FETCH (FLAGS (\\Seen) UID 5802)
> 141,Response: * 4 FETCH (FLAGS (\\Seen) UID 5804)
>
> On 10/29/2019 3:12 PM, Jerry Malcolm wrote:
>> Ok, I need an IMAP expert.... Below is a very brief trace of the 
>> communications between iPhone mail and JAMES (3.4).  I completely 
>> deleted an account on my iPhone, then recreated it while in airplane 
>> mode to make sure I didn't miss any communications in my trace.  I 
>> started the trace, exited airplane mode and let the iPhone do an 
>> initial sync with the account.  The inbox folder in this account has 
>> over 1000 emails going back to early 2019.
>>
>> I'm not an expert in IMAP.  But it appears that the iPhone mail app 
>> requests all of the emails 1:* (see line 812), but JAMES returns a 
>> single id plus two ranges (line 813).  But the total count JAMES 
>> reports is nowhere near the full 1000.  Subsequently (line 822), 
>> iPhone requests the emails JAMES told it about in line 813.  From 
>> what I can tell, the problem is in line 813. JAMES did not report all 
>> of the actual mail that is in the INBOX, which is exactly what I'm 
>> seeing on the phone.  Shouldn't JAMES return all 1000+ email ids that 
>> exist in INBOX?  Or am I reading the IMAP trace incorrectly?
>>
>> Note that the only emails JAMES reports came in AFTER I migrated to 
>> the new server and to the James 3.4 from v3b5.  It appears that there 
>> is something different about pre-existing emails in the mailbox 
>> folder that is causing JAMES not to recognize them. But this problem 
>> ONLY exists on the iPhone mail app. Thunderbird gets all of the mail 
>> for the inbox.  So is iPhone must be sending a slightly different 
>> request command syntax than other clients do (??)  Just speculating....
>>
>>  798 IMAP Request: 37 SELECT INBOX
>>  802 IMAP Response: 37 OK [READ-WRITE] SELECT completed.
>>  806 IMAP Request: 38 UID SEARCH RETURN (COUNT) 1:* NOT DELETED
>>  808 IMAP Response: * ESEARCH (TAG "38") UID COUNT 76
>>  809 IMAP Response: 38 OK SEARCH completed.
>>  812 IMAP Request: 39 UID SEARCH RETURN (ALL) 1:* NOT DELETED
>>  813 IMAP Response: * ESEARCH (TAG "39") UID ALL 
>> 7776,7955:7970,7975:8033
>>  814 IMAP Response: 39 OK SEARCH completed.
>>  817 IMAP Request: 40 UID SEARCH RETURN (ALL) 929:* NOT DELETED
>>  818 IMAP Response: * ESEARCH (TAG "40") UID ALL 7955:7970,7975:8033
>>  819 IMAP Response: 40 OK SEARCH completed.
>>  822 IMAP Request: 41 UID FETCH 7955:7970,7975:8033 (INTERNALDATE UID 
>> RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from 
>> content-type to cc bcc message-id in-reply-to references list-id 
>> x-universally-unique-identifier)])
>>
>> On 10/22/2019 3:07 AM, Matthieu Baechler wrote:
>>> Hi Jerry,
>>>
>>> I don't think trying to guess what happen will help you much. I would
>>> rather try to capture the IMAP session.
>>>
>>> I see two ways to do that:
>>>
>>> 1. you write a IMAP session logger in James (it should be really easy,
>>> I don't know why it's not already there)
>>>
>>> 2. you disable SSL on the phone and do a tcpdump on the server
>>>
>>> Once you'll have the IMAP session capture, it will be easier to
>>> diagnose your problem.
>>>
>>> Cheers,
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
>> For additional commands, e-mail: server-user-help@james.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-dev-unsubscribe@james.apache.org
> For additional commands, e-mail: server-dev-help@james.apache.org
>

---------------------------------------------------------------------
To unsubscribe, e-mail: server-dev-unsubscribe@james.apache.org
For additional commands, e-mail: server-dev-help@james.apache.org


(Resolved): Moving Servers Wipes Out iPhone's Mail Accounts

Posted by Jerry Malcolm <te...@malcolms.com>.
Finally, after 2 weeks, iPhones have all of their mail.  The problem was 
that my Lucene index was corrupted. Or to be more precise, only emails 
from the last two weeks since I first started up James on the new 
environment were indexed. Even after renaming (effectively removing) the 
/var/store/lucene folder, the index would not fully rebuild.  Same 
problem... but worse now... now it showed only mail that came in over 
the last 10 minutes since I cleaned the lucene index folder and lost the 
last 2 weeks' mail that actually was indexed.  On a whim, I changed 
indexer.xml to use lazyIndex instead of luceneIndex... voila.... all of 
the folders were fully indexed, and iPhone has all of the mail for each 
folder.  Couldn't find much documentation on lazyIndex vs. luceneIndex.  
But at this point, I think I'll take having mail back on my client's 
iPhones over any downside to using lazyIndex. But.... educate me if 
there are serious downsides to using lazyIndex.

Thunderbird populates folders using a different imap command which, 
apparently, goes straight to the JPA database instead of using the 
Lucene index.  So that's why the problem didn't appear in TBird.

I'm going to start another thread in the dev group specifically to 
discuss the Lucene issue.

Jerry

On 10/31/2019 12:35 PM, Jerry Malcolm wrote:
> (I'm moving this thread to the dev forum since it appears now to not 
> be a user problem)....
>
> More data now... Since iPhone doesn't load the correct email list and 
> TBird does, I traced the precise same scenario with the same email 
> account with TBird as the previous iPhone trace in the post below.  As 
> I suspected, in order to do an initial full sync on a folder, TBird is 
> asking for the list of UIDs in a different way. Note from the two traces:
>
> TBird: UID fetch 1:* (FLAGS)
>     Response: 1 FETCH (FLAGS (\\Seen) UID 5801)  (...followed by many 
> other UIDs including the ones in iPhone search below)
> ---
> iPhone: UID SEARCH RETURN (COUNT) 1:* NOT DELETED
>      Response: ESEARCH (TAG "39") UID ALL 7776,7955:7970,7975:8033
>
> The two queries above are for the same email account/folder. Again, 
> I'm not an IMAP expert.  But it appears that both should return the 
> same list of UIDs even though they ask for it differently.
>
> Summary... the TBird query gets all UIDs for the folder starting at 
> 5801 as expected.  The iPhone query gets a subset of UIDs starting at 
> 7776.  This continues to support my current theory that the code that 
> processes UID SEARCH RETURN (COUNT) 1:*.... is not correct.
>
> If someone knows what class processes these imap queries, please let 
> me know.  I'm going to dig into the code now.  But a few pointers to 
> the package/classes would be helpful.
>
> Thunderbird trace:
>
> 127 Request: 19 select "INBOX"
> 129,Response: * FLAGS (\\Answered \\Deleted \\Draft \\Flagged \\Seen 
> "MailFlagBit1 "MailFlagBit0 NonJunk "label3 "label1 "Forwarded)
> 130,Response: 19 OK [READ-WRITE] SELECT completed.
> 132 Request: 20 getquotaroot "INBOX"
> 134 Response: * QUOTAROOT "INBOX" #private&jerry@malcolms.com
> 135,Response: 20 OK GETQUOTAROOT completed.
> 137,Request: 21 UID fetch 1:* (FLAGS)
> 139,Response: * 1 FETCH (FLAGS (\\Seen) UID 5801)
> 140,Response: * 2 FETCH (FLAGS (\\Seen) UID 5802)
> 141,Response: * 4 FETCH (FLAGS (\\Seen) UID 5804)
>
> On 10/29/2019 3:12 PM, Jerry Malcolm wrote:
>> Ok, I need an IMAP expert.... Below is a very brief trace of the 
>> communications between iPhone mail and JAMES (3.4).  I completely 
>> deleted an account on my iPhone, then recreated it while in airplane 
>> mode to make sure I didn't miss any communications in my trace.  I 
>> started the trace, exited airplane mode and let the iPhone do an 
>> initial sync with the account.  The inbox folder in this account has 
>> over 1000 emails going back to early 2019.
>>
>> I'm not an expert in IMAP.  But it appears that the iPhone mail app 
>> requests all of the emails 1:* (see line 812), but JAMES returns a 
>> single id plus two ranges (line 813).  But the total count JAMES 
>> reports is nowhere near the full 1000.  Subsequently (line 822), 
>> iPhone requests the emails JAMES told it about in line 813.  From 
>> what I can tell, the problem is in line 813. JAMES did not report all 
>> of the actual mail that is in the INBOX, which is exactly what I'm 
>> seeing on the phone.  Shouldn't JAMES return all 1000+ email ids that 
>> exist in INBOX?  Or am I reading the IMAP trace incorrectly?
>>
>> Note that the only emails JAMES reports came in AFTER I migrated to 
>> the new server and to the James 3.4 from v3b5.  It appears that there 
>> is something different about pre-existing emails in the mailbox 
>> folder that is causing JAMES not to recognize them. But this problem 
>> ONLY exists on the iPhone mail app. Thunderbird gets all of the mail 
>> for the inbox.  So is iPhone must be sending a slightly different 
>> request command syntax than other clients do (??)  Just speculating....
>>
>>  798 IMAP Request: 37 SELECT INBOX
>>  802 IMAP Response: 37 OK [READ-WRITE] SELECT completed.
>>  806 IMAP Request: 38 UID SEARCH RETURN (COUNT) 1:* NOT DELETED
>>  808 IMAP Response: * ESEARCH (TAG "38") UID COUNT 76
>>  809 IMAP Response: 38 OK SEARCH completed.
>>  812 IMAP Request: 39 UID SEARCH RETURN (ALL) 1:* NOT DELETED
>>  813 IMAP Response: * ESEARCH (TAG "39") UID ALL 
>> 7776,7955:7970,7975:8033
>>  814 IMAP Response: 39 OK SEARCH completed.
>>  817 IMAP Request: 40 UID SEARCH RETURN (ALL) 929:* NOT DELETED
>>  818 IMAP Response: * ESEARCH (TAG "40") UID ALL 7955:7970,7975:8033
>>  819 IMAP Response: 40 OK SEARCH completed.
>>  822 IMAP Request: 41 UID FETCH 7955:7970,7975:8033 (INTERNALDATE UID 
>> RFC822.SIZE FLAGS BODY.PEEK[HEADER.FIELDS (date subject from 
>> content-type to cc bcc message-id in-reply-to references list-id 
>> x-universally-unique-identifier)])
>>
>> On 10/22/2019 3:07 AM, Matthieu Baechler wrote:
>>> Hi Jerry,
>>>
>>> I don't think trying to guess what happen will help you much. I would
>>> rather try to capture the IMAP session.
>>>
>>> I see two ways to do that:
>>>
>>> 1. you write a IMAP session logger in James (it should be really easy,
>>> I don't know why it's not already there)
>>>
>>> 2. you disable SSL on the phone and do a tcpdump on the server
>>>
>>> Once you'll have the IMAP session capture, it will be easier to
>>> diagnose your problem.
>>>
>>> Cheers,
>>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
>> For additional commands, e-mail: server-user-help@james.apache.org
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: server-dev-unsubscribe@james.apache.org
> For additional commands, e-mail: server-dev-help@james.apache.org
>

---------------------------------------------------------------------
To unsubscribe, e-mail: server-user-unsubscribe@james.apache.org
For additional commands, e-mail: server-user-help@james.apache.org