Tags are not persistent in Inbox only(imap), lost after restart

RESOLVED INCOMPLETE

Status

RESOLVED INCOMPLETE
4 years ago
2 years ago

People

(Reporter: susan.abraham, Unassigned)

Tracking

31 Branch
x86_64
Windows 7

Firefox Tracking Flags

(Not tracked)

Details

(Whiteboard: [needs new log])

(Reporter)

Description

4 years ago
User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/40.0.2214.111 Safari/537.36

Steps to reproduce:

Tag a mail as important. restart thunderbird


Actual results:

Tag got removed automatically. 


Expected results:

The mail should have the tag even after restart
(Reporter)

Updated

4 years ago
Priority: -- → P2

Comment 1

4 years ago
Is the tag still there if you switch folders?
Is this an imap account?
Flags: needinfo?(susan.abraham)
Priority: P2 → --
Summary: Tags are not persistent → Tags are not persistent, lost after restart
(Reporter)

Comment 2

4 years ago
Yes. Tags are still there if I just switch the folders. It gets removed after a restart

And yes. This is a IMAP account
Flags: needinfo?(susan.abraham)
(In reply to Susan from comment #2)
> And yes. This is a IMAP account

If imap, "tag in Tb" is stored as "imap flag"(imap user defined keyword) by "uid store +Flag($label1)".
It's retrieved from server by "uid fetch NN Flags" after it. (UID of mail is shown in "Order received" column if imap folder).

Was flag(($label1 for Important. see mailnews.tags.########.tag/color in prefs.js) properly passed to server by Tb?
Was flag(($label1 for Important) correctly retrieved from server by Tb?
Get imap log, and check log file content using Text editor by yourself. See Bug 402793 Comment #28 for getting log.
(Reporter)

Comment 4

4 years ago
I got the imap.log as mentioned in https://wiki.mozilla.org/MailNews:Logging. But I'm not able to interpret the data and couldn't find te flags mentioned in the above comment. Is there a way to upload the log file to you , for verification.
(In reply to Susan from comment #4)
> But I'm not able to interpret the data and couldn't find te flags mentioned in the above comment.

If you view Unread mail, \Seen flag is stored. If you change Read mail to Unread, \Seen flag is removed. If you deleted mail \Deleted flag is stored.
These are logged like:
    uid store NN +Flags(\Seen),  uid store NN -Flags(\Seen), uid store NN +Flags(\Deleted)
So, find such logs by "Search function of Text Editor" and see log for "flag store/flag removal first (search for "\Seen", "\Deleted" is sufficient)..
Storing of tag/removal of tag is same as storing/removaal of of \Seen/\Delete. Difference is string only.
   Predefined tag definition in Tb                            Data in log for storing                  Retrievall    
       mailnews.tags.$label1.tag = Important   => uid store NN +Flags($label1)       uid fetch NN Flags -> $label1 in response line
       mailnews.tags.$label2.tag = Work           => uid store NN +Flags($label2)       uid fetch NN Flags -> $label2 in response line
       mailnews.tags.$label3.tag = Personal     => uid store NN +Flags($label3)       uid fetch NN Flags -> $label3 in response line
       mailnews.tags.$label4.tag = To Do         => uid store NN +Flags($label4)       uid fetch NN Flags -> $label4 in response line
       mailnews.tags.$label5.tag = Later          => uid store NN +Flags($label5)       uid fetch NN Flags -> $label5 in response line
No such string in log(search for "\Seen", "\Deleted", "$label" is sufficient)
"Currently processed Mbox name" is writen in header part of a log line. So, check with Test folder is better.
1. Create folder under the IMAP account. Call FolderX.
2. Copy several mails to FolderX.
3. Mark mails ar Read, Unread, Read, Read => log for \Seen flag change at FolderX is obtained 
4. Add tag(any of $label1 to $label5), and remove tag. Repeat several times  => log for $labelN change at FolderX is obtained.
Because opertion is done at FolderX, searching log for FolderX is sufficient,and number of log lines for FolderX is small, so you can read logs.
(Reporter)

Comment 7

4 years ago
Thanks for the details. I couldnt make put much from the logs, but observed something relevant (i feel so):

1. the tags in folders other than inbox is intact even after a restart.
2. The tags are reset only for the mails in inbox folder
3. I see messages like 'Inbox downloading message header 50 of 8909' everytime I restart thunderbird. Is this relevant (like resetting everything)
4. If I open a message from a folder other than inbox, its persistent even after restart. But this is not the case for a mail from inbox.

I feel, all these are interrelated and may be some problem with the setting. can anyone please help ..

Thanks in advance..

Regards,
Susan
Thanks for looking into imap log by yourself and your observation.

(In reply to Susan from comment #7)
> 1. the tags in folders other than inbox is intact even after a restart.
> 2. The tags are reset only for the mails in inbox folder
> 3. I see messages like 'Inbox downloading message header 50 of 8909' everytime I restart thunderbird.
> Is this relevant (like resetting everything)
> 4. If I open a message from a folder other than inbox, its persistent even after restart. But this is not the case for a mail from inbox.

It's funny, and intereting.

If ordinal,following should occur.
  SELECT Inbox, uid fetch 1:* Flags => flag state(\Seen, \Deleted, $labelN, ...) of each UID is returned
  After it, uid fetch a:b,c:d, ... BODY.PEEK[ HEADER.FIELDS(Subject From Date ...) ]  is issued to et message header dat.
  This "selective header fetch of all existent messaages" should complete while Tb is running.
  After it, if auto-sync is enabled, entire message data is downloaded to Offline-Store file if Offline-Use=On folder.
  This auto-sync may take long, because "download of entire mail data of 8909 message" takes long.

When did you start to use Tb with the Inbox folder?
Do you terminate Tb pretty quickly after each restart of Tb?
What is shown in Activity Manager panel?

Is there log line like 'UID fetch 1:* (FLAGS) (CHANGEDSINCE ...)',  'SELECT "Inbox" (CONDSTORE) ' in your imap log?

Do you define "Body contains"condition in message filter rule for the imap account which is applied upon new mail fetch?
> 3. I see messages like 'Inbox downloading message header 50 of 8909' everytime I restart thunderbird.

This indicates that "messaage header fetch" is in progress at Inbox on 50-th message of 8909 messges in Inbox.

Possible phenomenon:
  Body condition is used, so "uid fetch 1:* body.peek[]" is issued upon 1st access of the Inbox before filter aapplicaation on all new mails.
  Because connection for Inbox is busy(uid fetch 1:* body.peek[] is in progress), nothing can do on Inbox.
  So, "uid store NN +Flag($label1)" can't be sent to mail in Inbox.
  Tb is terminated. Tb is restarted. Because flag of  $label1 is not stored yet, it's not returned to "uid fetch 1:* Flags".
  Because "fetch of all messages in Inbox" is not completed yet, same thing happens again.

Look into imap log file, and check log for Inbox which starts from 'Select "Inbox" ...' line.
Summary: Tags are not persistent, lost after restart → Tags are not persistent in Inbox only(imap), lost after restart
(Reporter)

Comment 10

4 years ago
Is it possible to upload the imap.log to you, for troubleshooting.
(In reply to Susan from comment #10)
> Is it possible to upload the imap.log to you, for troubleshooting.

Trouble shooting is your job. There is no evidence of "Tb's bug" yet.
Because Inbox only phenomenon, as you discovered, checking "what is occuring at Inbox" only is sufficient.
And because of IMAP, flow is pretty simple.
   At a cached connection, SELECT "Inbox", and, simply repeats "send imap command to server, then receive response from server".
   Because an Mbox can be selected at only one connection, all activity on Inbox is executed at one connection.
   In heading part of each log line, Mbox name is written if command/response, so "checking log for Inbox only" is easy.

"Attach data to bug report of bugzilla.mozilla.org" is always possible, although size limitatin exists. See all fields of bug in b.m.o, please.
However, imap log is usually pretty huge because mail data is also logged. So, "extracting required lines or part only" is usually needed. And, mail data usually contains sensitive data, and mail data itself is not needed for problem analysis, so such data should be removed. These are your job. Not my job.

No answer to my questions?
Because this is problem on Tag, it's pretty simple.
  Tag of Important is sent to server by (a) uid store NN +Flags($label1)", and is retriieved by (b) uid fetch NN Flags.
   So, only one of next 4 can occur.
     (1) Tb did (a) for mail of UID=NN in Inbox, and $label1 is returned to (b) for mail of UID=NN in Inbox when Tb is restarted.
     (2) Tb did (a) for mail of UID=NN in Inbox, but $label1 is not returned to (b) for mail of UID=NN in Inbox when Tb is restarted.
     (3) Tb did not do (a) for mail of UID=NN in Inbox, but $label1 is returned to (b) for mail of UID=NN in Inbox when Tb is restarted.
     (4) Tb did not do (a) for mail of UID=NN in Inbox, and $label1 is not returned to (b) for mail of UID=NN in Inbox when Tb is restarted.
"Which one" is pretty easily known merely by looking imap log. "Search $label1 by Text Editor" is impossible in your environment?
You already looked log for simple testing at FolderX, didn't you? 

Which actually occurred in your environment?
(Reporter)

Comment 13

4 years ago
When did you start to use Tb with the Inbox folder?

==> From last 7 years (atleast). And this used to work fine before. I can see tags on older mails (ie, till Jan 2014). Does this mean, something changed with the latest versions of Thunderbird?

Do you terminate Tb pretty quickly after each restart of Tb?

Ans ===> Not everytime. But yes, during the testing.

What is shown in Activity Manager panel?

ANS: Where is this? I'm not aware.


Is there log line like 'UID fetch 1:* (FLAGS) (CHANGEDSINCE ...)',  'SELECT "Inbox" (CONDSTORE) ' in your imap log?

ANS: No. Its not there. There s only one entry with 'Select Inbox'

"
8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:A:SendData: 10 select "INBOX"

8728[1b0c16d0]: ReadNextLine [stream=1e727848 nb=35 needmore=0]
8728[1b0c16d0]: 1e758800:stbeehive.oracle.com:S-12c:CreateNewLineFromSocket: * 1 FETCH (FLAGS (\Seen) UID 716)

8728[1b0c16d0]: ReadNextLine [stream=1e727848 nb=45 needmore=0]
8728[1b0c16d0]: 1e758800:stbeehive.oracle.com:S-12c:CreateNewLineFromSocket: * 2 FETCH (FLAGS (\Seen \Answered) UID 717
"

Do you define "Body contains"condition in message filter rule for the imap account which is applied upon new mail fetch?

ANS: No. I haven't
(Reporter)

Comment 14

4 years ago
++ I tested again. Opened Thunderbird , set tags for aouple of mails in Inbox.

++ Searched for $label1 in the imap.log

"
Line 448248: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:CreateNewLineFromSocket:   Tag of Important is sent to server by (a) uid store NN +Flags($label1)", =
	Line 448260: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:CreateNewLineFromSocket:      (1) Tb did (a) for mail of UID=3DNN in Inbox, and $label1 is returned =
	Line 448269: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:CreateNewLineFromSocket:      (2) Tb did (a) for mail of UID=3DNN in Inbox, but $label1 is not retur=
	Line 448278: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:CreateNewLineFromSocket:      (3) Tb did not do (a) for mail of UID=3DNN in Inbox, but $label1 is re=
	Line 448287: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:CreateNewLineFromSocket:      (4) Tb did not do (a) for mail of UID=3DNN in Inbox, and $label1 is not
	Line 448381: 0[c0f140]: queuing url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448382: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448383: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448385: 0[c0f140]: failed creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448551: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448552: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448554: 0[c0f140]: playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80070>$label1>
	Line 448556: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:ProcessCurrentURL:imap://susan%2Eabraham%40oracle%2Ecom@stbeehive.oracle.com:993/customKeywords%3EUID%3E/INBOX%3E80070%3E$label1%3E:  = currentUrl
	Line 448643: 0[c0f140]: queuing url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448644: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448645: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448647: 0[c0f140]: failed creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448944: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448945: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448947: 0[c0f140]: playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80065>$label1>
	Line 448949: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:ProcessCurrentURL:imap://susan%2Eabraham%40oracle%2Ecom@stbeehive.oracle.com:993/customKeywords%3EUID%3E/INBOX%3E80065%3E$label1%3E:  = currentUrl
	Line 448981: 0[c0f140]: queuing url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 448982: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 448983: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 448985: 0[c0f140]: failed creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 448988: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 448989: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 448991: 0[c0f140]: failed creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 449157: 0[c0f140]: considering playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 449158: 0[c0f140]: creating protocol instance to play queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 449160: 0[c0f140]: playing queued url:imap://susan.abraham@oracle.com@stbeehive.oracle.com:993/customKeywords>UID>/INBOX>80064>$label1>
	Line 449162: 8412[1b0c1ac0]: 1e8ec000:stbeehive.oracle.com:S-INBOX:ProcessCurrentURL:imap://susan%2Eabraham%40oracle%2Ecom@stbeehive.oracle.com:993/customKeywords%3EUID%3E/INBOX%3E80064%3E$label1%3E:  = currentUrl
"

++ Restarted Thunderbird and now there are no tags and no '$label1'
All are log for "request of $label1 for UID=80064 etc." is queed and is waiting for scheduling.
If sent to server, log should be  SendData: 100 uid store 80064 +Flags(label1), as seen in log of  SendData: 10 select "INBOX".

It indicates connection for Inbox is busy for other job.
What kind of job is being executed for Inbox after 10 select "INBOX" before queuing.../customKeywords>UID>/INBOX>80064 etc.>$label1?
(In reply to Susan from comment #13)
> What is shown in Activity Manager panel?
> ANS: Where is this? I'm not aware.

Tools -> Activity Manager, if en-US version.

imap command failure, NN mails are copied/deleted, folder XXX is sync'ed state, etc is reported.

If auto-sync is done again from scratch, "busy for long time to do first download of all mails" can occur.
This can occur if pancea.dat is deleted or crrupted, Inbox.msf is deleted by someone, ...
FYI.
Phenomenon itself is simple.
   While request for "store $label1" is waiting for scheduling, you terminated Tb, 
   so flag named $label1 is not returned from server after restart of Tb.
FYI.
"initial auto-sync" can occur if UIDVALIDITy is changed at server(eg. Mbox reorganization is done)

A possible workaround if initial auto-sync takes long.
   Gmail IMAP example.
     Gmail IMAP folder can be accessed via two different FQDN with same userID(=mailaddr).
     In Tb, required unique name = type + hostname + userName, so two accounts can be defined in Tb for same Mbox.
        account1 : type=imap, hostname = imap.gmail.com,         userName=abc@gmail.com  : For daily use
        account2 : type=imap, hostname = imap.googlemail.com, userName=abc@gmail.com  : For d-hoc access
              No new mail check, no auto-sync, no filtering, ...
    While auto-sync of Inbox is being execurted at account1,
    access Inbox via account2. Mail can be viewed, and tag can be added to mail,
    because imap server supports multiple client's access.
"hostname of account2" can be IP address, or FQDN defined in hosts file.
FYI.
Bug 1143519 is external phenomenon when "newsgroup of 100,000.artivcles" is subscribed and download of all headers is requested upon first open.
When big newsgroup, "high CPU" and "high memory consumption" occurs at same time and it continues for long time, external sympto is "UI freeze for long time", so phenomenon is simple.
    (1) Subscribe newsgroup of  100,000  aarticles, and request header download of all articles.
    (2) XOVEr for 100,000 articles by single NNTP command => freeze => kill Tb
    (3) restart Tb => XOVEr for remaining articles 100,000 by single NNTP command => freeze => kill Tb
    (4) (3) was repeted multiple times.
          Because Tb was killed after a while due to freeze, multiple restarts were neeeded to download heder of all 100,000 articles.
    (5) When header download of all 100,000 articles completed, problem of "UI feeze withhigh CPU and high memory usge" ended.
    I was't aware of "what had aappened" until UI freeze disappeared at step (5) :-) 

If IMAP, such severe/critical performance proble is not exposed. However, from perspective of "connection for Inbox", "connection busy continues for lo---ng time" can occur. Even when CPU 100%, high memory usage, UI freeze, won't occur, "100% connection urilization" can continue for long time.
(In reply to Susan from comment #14)
> Line 448248: S-INBOX:CreateNewLineFromSocket:   Tag of Important is sent to server by (a) uid store NN +Flags($label1)" ...
> Line 448381:  queuing url:imap:// ... /customKeywords>UID>/INBOX>80070>$label1>

Line 448248 is text of my comment to this bug, so it's message body data of bug mail from b.m.o to you.
i.e. New mail's messaage body data was downloaded in your environment, then you added tag Important to a mail in Inbox.
This indicates  that it is not "download of all mails from scratch is in progress".
If so, it may be "download by auto-sync" takes far longer than before.
   Before : When you added tag then terminated Tb, tag was always sent to sever.
   Now    : When you add tag, and if you terminate Tb after a while,  tag is usually not sent to server yet.

It may be performance problem. Add timestamp to log data for ease of problem analysis.
   imap:5 -> timestamp,imap:5
FYI. A technique to put eye catcher in log.
  Define tags : X1, X2, X3, .... Just before do something, add tag X# to mail of UID=ZZ in FolderX.
  => request/command of "at FolderX, add tag X# for UID=ZZ" is logged.

Comment 22

3 years ago
Susan, please add timestamp to log and other information per comment 20 and 21.
Thanks!
Flags: needinfo?(susan.abraham)

Updated

2 years ago
Whiteboard: [closeme 2016-06-10][needs new log]

Comment 23

2 years ago
Resolved per whiteboard
Status: UNCONFIRMED → RESOLVED
Last Resolved: 2 years ago
Flags: needinfo?(susan.abraham)
Resolution: --- → INCOMPLETE
Whiteboard: [closeme 2016-06-10][needs new log] → [needs new log]
You need to log in before you can comment on or make changes to this bug.