881829 - Gloda Indexing stalls indefinitely on Sent folder (activity manager) in POP with EFS file encryption enabled

Status: RESOLVED WORKSFORME

(MailNews Core :: Database, defect)

Description

[David Taber]

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:21.0) Gecko/20100101 Firefox/21.0 (Beta/Release)
Build ID: 20130511120803

Steps to reproduce:

Normal email usage pattern, nothing special.  Running Windows 7 pro 64 bit with all the latest patches.  All files on local disk.
Sent mailbox has about a thousand messages in it.


Actual results:

Search through the Sent mailbox isn't very quick.  Probably running at brute-force speeds.  
Activity Manager shows Ïndexing Messages" with progress stalled maybe 20% of the way through the Sent folder...no change for days.
Have restarted TB and rebooted Windows.


Expected results:

Indexer should be able to go through 1000 messages in a few minutes, even under load.

Comment 1

[David Lechner (:dlech)]

Are there any errors in the error console? Tools > Error Console

Also, you could try logging gloda to see where it is hanging.
https://wiki.mozilla.org/Thunderbird:Debugging_Gloda

I am pretty sure that gloda is what is doing the indexing
https://developer.mozilla.org/en-US/docs/Thunderbird/gloda

Comment 2

[David Taber]

Hi David,

There is one error in the error console, totally related to chrome (a null attribute in the theme I'm running for the UI).

When I turn on logging for gloda, I get endless streams of drivel in the console window.  What am I supposed to do with this??  Is there a way to pipe the -console output to a file??

And yes, gloda is absolutely doing the indexing...except it's getting stuck about 7% of the way through the file.

>>>>>>>>>>>>>>Log info cut/pasted from the console at the time gloda gets stuck>>>>
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors raw: Message:852,Messa
ge:853,Message:854,Message:162396
2013-06-12 17:25:21     gloda.index_msg DEBUG   ref len: 4 anc len: 4
2013-06-12 17:25:21     gloda.index_msg DEBUG   references: 0 = 36B8E7EB51932A4B
[e-mail],1 = 7584FA4F04756F4D8322A8F5E2E
[e-mail],2 = [e-mail],3 =
 [e-mail]
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors: 0 = Message:852,1 = M
essage:853,2 = Message:854,3 = Message:162396
2013-06-12 17:25:21     gloda.index_msg DEBUG   1 candidate messages
2013-06-12 17:25:21     gloda.index_msg DEBUG   candidate folderID: 691 messageK
ey: 60606933
2013-06-12 17:25:21     gloda.NS        INFO     ** grokNounItem: message
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.fundattr
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND
 (value IN ('[e-mail]','[e-mail]','lchapman@rroysel
aw.com')))) ARGS:
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'SalesLogist
ix' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Lisa Chapma
n' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Cheryl Kell
ey' ([e-mail])
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.explattr
2013-06-12 17:25:21     gloda.NS        INFO      * optimizer: gloda.fundattr
2013-06-12 17:25:21     gloda.NS        INFO     ** done with providers.
2013-06-12 17:25:21     gloda.NS        DEBUG     json text: {"43":2,"44":[160,2
17],"45":[],"46":[],"50":false,"51":[],"58":false,"59":true,"60":false,"61":fals
e,"57":[],"52":[2,160,217],"53":[160,217],"54":[[2,160],[2,217]]}
2013-06-12 17:25:21     gloda.NS        DEBUG    updating item
2013-06-12 17:25:21     gloda.datastore DEBUG   in _updateMessageText, skipping
update because body matches
2013-06-12 17:25:21     gloda.NS        DEBUG    adjusting attributes, add:  rem
:
2013-06-12 17:25:21     gloda.NS        DEBUG    done grokking.
2013-06-12 17:25:21     gloda.index_msg DEBUG   <<<  back from _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   >>>  calling _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   *** Indexing message: 47618829 :
 whatever happened to...
2013-06-12 17:25:21     gloda.index_msg DEBUG     * Got message, subject whateve
r happened to...
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
messages LEFT JOIN messagesText ON messages.id = messagesText.rowid WHERE (id IN
 (SELECT id FROM messages WHERE (headerMessageID IN ('5186B898.8050309@saleslogi
stix.com')))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
conversations WHERE (id IN (84957)) ARGS:
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   getting results...
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   query completed, notifyi
ng... Message:162382
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors raw: Message:162382
2013-06-12 17:25:21     gloda.index_msg DEBUG   ref len: 1 anc len: 1
2013-06-12 17:25:21     gloda.index_msg DEBUG   references: 0 = 5186B898.8050309
@saleslogistix.com
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors: 0 = Message:162382
2013-06-12 17:25:21     gloda.index_msg DEBUG   1 candidate messages
2013-06-12 17:25:21     gloda.index_msg DEBUG   candidate folderID: 691 messageK
ey: 60603090
2013-06-12 17:25:21     gloda.NS        INFO     ** grokNounItem: message
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.fundattr
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND
 (value IN ('[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'SalesLogist
ix' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Roger Solin
' ([e-mail])
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.explattr
2013-06-12 17:25:21     gloda.NS        INFO      * optimizer: gloda.fundattr
2013-06-12 17:25:21     gloda.NS        INFO     ** done with providers.
2013-06-12 17:25:21     gloda.NS        DEBUG     json text: {"43":2,"44":[18],"
45":[],"46":[],"50":false,"51":[],"58":false,"59":true,"60":false,"61":false,"57
":[],"52":[2,18],"53":[18],"54":[[2,18]]}
2013-06-12 17:25:21     gloda.NS        DEBUG    updating item
2013-06-12 17:25:21     gloda.datastore DEBUG   in _updateMessageText, skipping
update because body matches
2013-06-12 17:25:21     gloda.NS        DEBUG    adjusting attributes, add:  rem
:
2013-06-12 17:25:21     gloda.NS        DEBUG    done grokking.
2013-06-12 17:25:21     gloda.index_msg DEBUG   <<<  back from _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   >>>  calling _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   *** Indexing message: 47615052 :
 Elan financial dead?
2013-06-12 17:25:21     gloda.index_msg DEBUG     * Got message, subject Elan fi
nancial dead?
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
messages LEFT JOIN messagesText ON messages.id = messagesText.rowid WHERE (id IN
 (SELECT id FROM messages WHERE (headerMessageID IN ('5186B54D.5070902@saleslogi
stix.com')))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
conversations WHERE (id IN (84958)) ARGS:
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   getting results...
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   query completed, notifyi
ng... Message:162383
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors raw: Message:162383
2013-06-12 17:25:21     gloda.index_msg DEBUG   ref len: 1 anc len: 1
2013-06-12 17:25:21     gloda.index_msg DEBUG   references: 0 = 5186B54D.5070902
@saleslogistix.com
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors: 0 = Message:162383
2013-06-12 17:25:21     gloda.index_msg DEBUG   1 candidate messages
2013-06-12 17:25:21     gloda.index_msg DEBUG   candidate folderID: 691 messageK
ey: 60599313
2013-06-12 17:25:21     gloda.NS        INFO     ** grokNounItem: message
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.fundattr
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND
 (value IN ('[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'SalesLogist
ix' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Wayne Giffo
rd' ([e-mail])
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.explattr
2013-06-12 17:25:21     gloda.NS        INFO      * optimizer: gloda.fundattr
2013-06-12 17:25:21     gloda.NS        INFO     ** done with providers.
2013-06-12 17:25:21     gloda.NS        DEBUG     json text: {"43":2,"44":[64],"
45":[],"46":[],"50":false,"51":[],"58":false,"59":true,"60":false,"61":false,"57
":[],"52":[2,64],"53":[64],"54":[[2,64]]}
2013-06-12 17:25:21     gloda.NS        DEBUG    updating item
2013-06-12 17:25:21     gloda.datastore DEBUG   in _updateMessageText, skipping
update because body matches
2013-06-12 17:25:21     gloda.NS        DEBUG    adjusting attributes, add:  rem
:
2013-06-12 17:25:21     gloda.NS        DEBUG    done grokking.
2013-06-12 17:25:21     gloda.index_msg DEBUG   <<<  back from _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   >>>  calling _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   *** Indexing message: 47607476 :
 GE: next steps/update
2013-06-12 17:25:21     gloda.index_msg DEBUG     * Got message, subject GE: nex
t steps/update
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
messages LEFT JOIN messagesText ON messages.id = messagesText.rowid WHERE (id IN
 (SELECT id FROM messages WHERE (headerMessageID IN ('72994E40-878B-492C-A25A-19
[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
conversations WHERE (id IN (2381)) ARGS:
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   getting results...
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   query completed, notifyi
ng... Message:6476,Message:162384
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors raw: Message:6476,Mess
age:162384
2013-06-12 17:25:21     gloda.index_msg DEBUG   ref len: 2 anc len: 2
2013-06-12 17:25:21     gloda.index_msg DEBUG   references: 0 = 72994E40-878B-49
[e-mail],1 = [e-mail]
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors: 0 = Message:6476,1 =
Message:162384
2013-06-12 17:25:21     gloda.index_msg DEBUG   1 candidate messages
2013-06-12 17:25:21     gloda.index_msg DEBUG   candidate folderID: 691 messageK
ey: 60591737
2013-06-12 17:25:21     gloda.NS        INFO     ** grokNounItem: message
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.fundattr
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND
 (value IN ('[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'SalesLogist
ix' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Roger Solin
' ([e-mail])
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.explattr
2013-06-12 17:25:21     gloda.NS        INFO      * optimizer: gloda.fundattr
2013-06-12 17:25:21     gloda.NS        INFO     ** done with providers.
2013-06-12 17:25:21     gloda.NS        DEBUG     json text: {"43":2,"44":[18],"
45":[],"46":[],"50":false,"51":[],"58":false,"59":true,"60":false,"61":false,"57
":[],"52":[2,18],"53":[18],"54":[[2,18]]}
2013-06-12 17:25:21     gloda.NS        DEBUG    updating item
2013-06-12 17:25:21     gloda.datastore DEBUG   in _updateMessageText, skipping
update because body matches
2013-06-12 17:25:21     gloda.NS        DEBUG    adjusting attributes, add:  rem
:
2013-06-12 17:25:21     gloda.NS        DEBUG    done grokking.
2013-06-12 17:25:21     gloda.index_msg DEBUG   <<<  back from _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   >>>  calling _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   *** Indexing message: 47582249 :
 GE: Ring Lead for existing dupes?
2013-06-12 17:25:21     gloda.index_msg DEBUG     * Got message, subject GE: Rin
g Lead for existing dupes?
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
messages LEFT JOIN messagesText ON messages.id = messagesText.rowid WHERE (id IN
 (SELECT id FROM messages WHERE (headerMessageID IN ('5182F56E.5080602@saleslogi
stix.com','[e-mail]','5186A867.906
[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
conversations WHERE (id IN (17)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (34)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
contacts WHERE (id IN (23)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (contactID IN (23)))) A
RGS:
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   getting results...
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   query completed, notifyi
ng... Message:81,Message:6472,Message:162385
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors raw: Message:81,Messag
e:6472,Message:162385
2013-06-12 17:25:21     gloda.index_msg DEBUG   ref len: 3 anc len: 3
2013-06-12 17:25:21     gloda.index_msg DEBUG   references: 0 = 5182F56E.5080602
@saleslogistix.com,1 = [e-mail],2
= [e-mail]
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors: 0 = Message:81,1 = Me
ssage:6472,2 = Message:162385
2013-06-12 17:25:21     gloda.index_msg DEBUG   1 candidate messages
2013-06-12 17:25:21     gloda.index_msg DEBUG   candidate folderID: 691 messageK
ey: 60566510
2013-06-12 17:25:21     gloda.NS        INFO     ** grokNounItem: message
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.fundattr
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND
 (value IN ('[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'SalesLogist
ix' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Roger Solin
' ([e-mail])
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.explattr
2013-06-12 17:25:21     gloda.NS        INFO      * optimizer: gloda.fundattr
2013-06-12 17:25:21     gloda.NS        INFO     ** done with providers.
2013-06-12 17:25:21     gloda.NS        DEBUG     json text: {"43":2,"44":[18],"
45":[],"46":[],"50":false,"51":[],"58":false,"59":true,"60":false,"61":false,"57
":[],"52":[2,18],"53":[18],"54":[[2,18]]}
2013-06-12 17:25:21     gloda.NS        DEBUG    updating item
2013-06-12 17:25:21     gloda.datastore DEBUG   in _updateMessageText, skipping
update because body matches
2013-06-12 17:25:21     gloda.NS        DEBUG    adjusting attributes, add:  rem
:
2013-06-12 17:25:21     gloda.NS        DEBUG    done grokking.
2013-06-12 17:25:21     gloda.index_msg DEBUG   <<<  back from _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   >>>  calling _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   *** Indexing message: 47577564 :
 Ring Lead dupe catcher in place now in production
2013-06-12 17:25:21     gloda.index_msg DEBUG     * Got message, subject Ring Le
ad dupe catcher in place now in production
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
messages LEFT JOIN messagesText ON messages.id = messagesText.rowid WHERE (id IN
 (SELECT id FROM messages WHERE (headerMessageID IN ('8A7423F9-C0A8-424B-A74D-6D
[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
conversations WHERE (id IN (2379)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (105,159)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
contacts WHERE (id IN (93,147)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (contactID IN (93,147))
)) ARGS:
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   getting results...
2013-06-12 17:25:21     gloda.index_msg.mbm     DEBUG   query completed, notifyi
ng... Message:6470,Message:162386
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors raw: Message:6470,Mess
age:162386
2013-06-12 17:25:21     gloda.index_msg DEBUG   ref len: 2 anc len: 2
2013-06-12 17:25:21     gloda.index_msg DEBUG   references: 0 = 8A7423F9-C0A8-42
[e-mail],1 = [e-mail]
2013-06-12 17:25:21     gloda.index_msg DEBUG   ancestors: 0 = Message:6470,1 =
Message:162386
2013-06-12 17:25:21     gloda.index_msg DEBUG   1 candidate messages
2013-06-12 17:25:21     gloda.index_msg DEBUG   candidate folderID: 691 messageK
ey: 60561825
2013-06-12 17:25:21     gloda.NS        INFO     ** grokNounItem: message
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.fundattr
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND
 (value IN ('[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'SalesLogist
ix' ([e-mail])
2013-06-12 17:25:21     gloda.NS        DEBUG    found identity for 'Roger Solin
' ([e-mail])
2013-06-12 17:25:21     gloda.NS        INFO      * provider: gloda.explattr
2013-06-12 17:25:21     gloda.NS        INFO      * optimizer: gloda.fundattr
2013-06-12 17:25:21     gloda.NS        INFO     ** done with providers.
2013-06-12 17:25:21     gloda.NS        DEBUG     json text: {"43":2,"44":[18],"
45":[],"46":[],"50":false,"51":[],"58":false,"59":true,"60":false,"61":false,"57
":[],"52":[2,18],"53":[18],"54":[[2,18]]}
2013-06-12 17:25:21     gloda.NS        DEBUG    updating item
2013-06-12 17:25:21     gloda.datastore DEBUG   in _updateMessageText, skipping
update because body matches
2013-06-12 17:25:21     gloda.NS        DEBUG    adjusting attributes, add:  rem
:
2013-06-12 17:25:21     gloda.NS        DEBUG    done grokking.
2013-06-12 17:25:21     gloda.index_msg DEBUG   <<<  back from _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   >>>  calling _indexMessage
2013-06-12 17:25:21     gloda.index_msg DEBUG   *** Indexing message: 47487277 :
 Extole - Salesforce Additional Field in Program:Referral
2013-06-12 17:25:21     gloda.index_msg DEBUG     * Got message, subject Extole
- Salesforce Additional Field in Program:Referral
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
messages LEFT JOIN messagesText ON messages.id = messagesText.rowid WHERE (id IN
 (SELECT id FROM messages WHERE (headerMessageID IN ('0A05A613-6427-4A64-9362-EA
[e-mail]','[e-mail]')))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
conversations WHERE (id IN (2378)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (73,74,227)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
contacts WHERE (id IN (61,62,215)) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
identities WHERE (id IN (SELECT id FROM identities WHERE (contactID IN (61,62,21
5)))) ARGS:
2013-06-12 17:25:21     gloda.datastore DEBUG   QUERY FROM QUERY: SELECT * FROM
contacts WHERE (id IN (61)) ARGS:

Comment 3

[David Lechner (:dlech)]

(In reply to David Taber from comment #2)
> When I turn on logging for gloda, I get endless streams of drivel in the
> console window.  What am I supposed to do with this??  Is there a way to
> pipe the -console output to a file??

if you append " > gloda.log" (without quotes) to the command line, then the output will get piped into a file. I the future, please add the log to the bug as an attachment using the link above (saves on scrolling alot).

> 
> And yes, gloda is absolutely doing the indexing...except it's getting stuck
> about 7% of the way through the file.

I don't know much about gloda, but I know someone who does.

Jonathan, any ideas on what is going on here?

Comment 4

[David Taber]

Attachment: log file of T'bird indexer that stalls

Comment 5

[Jonathan Protzenko [:protz]]

I see nothing suspicious that jumps out at me from the debug logs. We have had a history of malformed messages driving Gloda off the rails, which *may* explain why the indexing is stuck and not moving forward.

The next step here is installing GlodaQuilla, an addon that enables extra columns in the thread pane. These columns will tell you whether a messages has been properly indexed (gloda id >= 32), or has been flagged as invalid (gloda id < 32) or hasn't been indexed at all (no value).

Could you please install the addon, enable all the extra columns, and tell us whether you find something suspicious in your sent folder?

Thanks!

jonathan

Comment 6

[Jonathan Protzenko [:protz]]

https://addons.mozilla.org/en-us/thunderbird/addon/glodaquilla-search-indexing-en/ has more information on the meaning of the various extra columns, as well as a link to download the addon.

Comment 7

[David Taber]

OK, installed the plugin and looked at the new columns in the Sent folder where Gloda is stuck.

The column marked # is completely blank.

The column marked ?? is completely blank except for two messages both marked as 0.  Those two messages are completely uninteresting:  no attachments, nothing unusual about them.

The activity manager claims that it is trying to index message number 44 of 946 in the Sent folder.  But clearly nothing has been successfully indexed there, and the Sent folder has 1787 messages in it.

The disk I/O is near zero and thunderbird is consuming 1% of my CPU.  I don't think gloda is actually doing anything.

Comment 8

[Jonathan Protzenko [:protz]]

Does repairing the folder help?

Comment 9

[David Taber]

I'm sorry, I don't understand what "repairing the folder" means.  Just for fun, I have just compacted the folder and it made no difference.

One footnote that I hope is irrelevant:  everything that Thunderbird is working on in the folders is stored in Windows' Encrypted File System.  This should make absolutely no difference, but some very low-level access methods to files get confused by encryption.  It's supposed to be totally transparent, but I have come across some raw-access code that doesn't like it.  Hopefully, Gloda isn't doing any of that kind of thing.

Another footnote:  further evidence that the Activity Manager or Gloda are quite confused--now the activity manager reports that there are 905 messages in the Sent folder to be indexed, but there are in fact 1800+

Comment 10

[Jonathan Protzenko [:protz]]

You can repair the folder by right-clicking on it, then hitting "Properties".

I'll try to see if any other of the symptoms you describe rings a bell.

Comment 11

[David Taber]

Oh--news to me about Repair button.
Pushed repair button:  "can't start that because something is using the folder" -- gloda, of course.
Go to Options to turn off indexing, but that didn't stop gloda in real time.
Restarted T'bird and confirmed that gloda not running.
Repaired folder.
Re-enabled indexing.
Restarted T'bird.
Gloda got a little further (all the way to 13% of the messages) but the activity manager still has the wrong message count for the folder and when looking at the special gloda columns in the message list all the ?? and # entries are still blank.

In other words--nah.

Comment 12

[David Taber]

Here's another possible clue...
This instance of T'bird has GB of mail going back 10 years, all on local disk and stored as windows Encrypted Files (which are supposed to be totally transparent to all applications.
I went through the cycle of opening each and every mail folder in the tree to make sure that there was a nice quick list view (MSF file works fine).  I then used T'Bird for several days.  No crashes or other icky stuff
Now, all of the folders are having to re-MSF themselves ("building summary file...") whenever I go looking at them in the list view. Once I've MSF'd them, the lists pop up instantly...for a few days....  Seems like the MSFs are somehow suffering from data rot or some sort of access problem.
No other processes in the system are touching the folders where the mail lives, so there shouldn't be any problem of lock management or access control.  
This doesn't seem like sensible behavior.

Comment 13

[David Taber]

Amendment to prior email:  this problem is NOT occurring everywhere in the folder tree.  Only in the areas where there is some activity nearby.  Large folders seem to be much more effected than small ones.

Is it possible gloda is somehow stepping on the MSFs when it does its crawling??

Comment 14

[Wayne Mery (:wsmwk)]

gloda doesn't directly touch msf as far as I know.

If you are seeing "building summary file..." then I suspect it's something else. Perhaps something related to timestamp

Comment 15

[David Taber]

Wayne--
Yeah, I suspect it's something to do with the timestamp of the MSF as well...but nothing other than T'Bird is touching those files. And essentially none of the affected files are being written into because of user activity.

Comment 16

[Wayne Mery (:wsmwk)]

Is your profile on a network drive?

Comment 17

[David Taber]

Hi Wayne,
No, all the files that T'bird uses are on a local drive.  Sorry, should have said that.  Not that it makes any difference, but the particular directories in question are encrypted using the windows Encrypted File System feature.  This is totally transparent to any user application, but for the sake of thoroughness/testing I thought I should mention it.

Note I'm now running T'bird 24.2.0 on Win7 64-bit Pro edition and the symptom continues.

Comment 18

[David Taber]

Additional info (don't know if this is the same bug, or a different one):
* Indexes seem to "age out" after a while, (In reply to David Taber from comment #12)
> Here's another possible clue...
> This instance of T'bird has GB of mail going back 10 years, all on local
> disk and stored as windows Encrypted Files (which are supposed to be totally
> transparent to all applications.
> I went through the cycle of opening each and every mail folder in the tree
> to make sure that there was a nice quick list view (MSF file works fine).  I
> then used T'Bird for several days.  No crashes or other icky stuff
> Now, all of the folders are having to re-MSF themselves ("building summary
> file...") whenever I go looking at them in the list view. Once I've MSF'd
> them, the lists pop up instantly...for a few days....  Seems like the MSFs
> are somehow suffering from data rot or some sort of access problem.
> No other processes in the system are touching the folders where the mail
> lives, so there shouldn't be any problem of lock management or access
> control.  
> This doesn't seem like sensible behavior.


Note that this part of the symptom continues, and I just noticed two key things that happen with the "data rot" MSFs.  

1.  Something is autonomously DELETING MSFs after a few weeks of their being built!!  I have yet to understand the pattern of this, but it's definitely an interaction between Gloda and T'bird (nothing else touches those directories).

2.  When the missing MSFs are rebuilt, many messages in the summary list are now tagged with bogus tags (that were never part of the message)

Comment 19

[David Taber]

Update on "data rot" MSFs...the autonomous deletion of MSFs seems to happen to *all* the MSF files in a particular directory, but adjacent directories' MSFs are left in tact.

I have some MSFs that are years old, but all the big ones seem to get wiped out within a year or so of their creation **even if I've done nothing to that area of the underlying mail files.**

Since I'm running Windows' Encrypted File System, it's conceivable this is some sort of nasty locking behavior...as an experiment, I'm turning the encryption off in some of the mail directories to see if there is any difference in this symptom.

Comment 20

[Wayne Mery (:wsmwk)]

(In reply to David Taber from comment #19)
> Update on "data rot" MSFs...the autonomous deletion of MSFs seems to happen
> to *all* the MSF files in a particular directory, but adjacent directories'
> MSFs are left in tact.
> 
> I have some MSFs that are years old, but all the big ones seem to get wiped
> out within a year or so of their creation **even if I've done nothing to
> that area of the underlying mail files.**

yeah, it's not unheard of. I've seen it myself

> Since I'm running Windows' Encrypted File System, it's conceivable this is
> some sort of nasty locking behavior...as an experiment, I'm turning the
> encryption off in some of the mail directories to see if there is any
> difference in this symptom.

What'd you find?

Comment 21

[David Taber]

I don't have conclusive evidence, but the coincidences are just too strong.

I believe there is some interaction between locks that T'bird puts on msf files and locks that windows EFS puts on any files under its control.  Both sets of locks are temporary, but when they conflict eventually T'bird gets very confused and sometimes locks up.  After one of these lock-ups, most of the MSFs are gone or have 0 length.

My suspicion is that EFS does not put locks on files for long, but in doing its housekeeping it has to do that (and you can't control it, if the file is encrypted).  My other suspicion is that T'bird puts locks on MSFs for quite a while...and the Glodia indexer may do so as well.  Either shortening these lock durations or checking that the OS hasn't locked the files first would help.

Comment 22

[David Taber]

Oh...forgot the punch line.  When I turned encryption off on a bunch of T'bird's email directories, the symptom stopped for the mail files/MSFs they contained.

Comment 23

[Wayne Mery (:wsmwk)]

Does it behave any better or worse with beta version from http://www.mozilla.org/en-US/thunderbird/channel/ ?

Comment 24

[David Taber]

Hi Wayne,
It's been a long time since I looked at any of this.  My system configuration is still Win7 Pro 64bit using EFS on all relevant mail folders.  Currently running T'bird 31.2.0 and GlodaQuilla 0.3.3.  Gloda is enabled at a global level (options>advanced>general>enable global search and indexer) and on all folders (properties>general information>include messages in Global Search results).  SQLite database is about 600 MB...but...

* when I actually look at the GlodaQuilla ids in message folders, none of the ids is populated.

* the activity manager doesn't show any Gloda events in its history, and there's no "stalling" of the indexing process indicated

So...I'm not sure that I'm still experiencing this bug.  But the lack of GlodaQuilla ID numbers is weird...

Comment 25

[Wayne Mery (:wsmwk)]

Perhaps Chiaki will have some insight into whether encryption might have an impact

Comment 26

[ISHIKAWA, Chiaki]

(In reply to Wayne Mery (:wsmwk, use Needinfo for questions) from comment #25)
> Perhaps Chiaki will have some insight into whether encryption might have an
> impact

Hi, I have never used encryption file system myself before.
I thought file system recovery after a partial crash or bad sector would have been very difficult under such a file system.

But I assume that we can run file check (a la chkdsk or whatver is called under Windows these days) against encryption file system. 
Can David run it against the file system in question?

But, come to think of it, yes I am suspicious something is fishy about David's observation that when encryption is disabled for a certain directory, MSF files there would survive.
I did not realize that encryption can be enabled on an individual directory basis.

What happens when one disables the encryption on a directory and we have had an existing encrypted file there. Is that decrypted immediately or is it possible that only newly created files are stored in plain text and read/write to the existing encrypted file are done still in an encrypted manner?

I hate encryption file system because getting these API behavior consistent is a nightmare for a designer and when it comes to implementation, we get more chances for screwups than the original designer. Go figure :-)

Anyway, once I get the current I/O error check mess under control, 
I will surely take a look assuming windows 8.1 and eventually Windows 10 have the same functionality.
If encryption file system is decent, I would certainly want to use it on a mobile device.

TIA

Comment 27

[David Taber]

Hi everyone,
It is critical to make the distinction between biglocker and other encryption schemes and the Encrypted File System that has been in windows pro for over a decade.  This file system behaves like a very weird driver, dynamically (but transparently) encrypting/decrypting files under its control.  Yes, it is available on a file-by-file basis, although of course you can encrypt as large a file tree as you like. To all applications, there are no API differences.  

However, there is an interesting amount of kernel-level housekeeping that goes on with EFS, and for reasons I don't understand the system will update files occasionally all by itself.  Who knows why, it just happens "invisibly".  And that invisibility is likely to be the problem:  a file (or group of files) may be locked momentarily by EFS or by the windows Indexer at any time.  I don't know if the indexer/encrypter sets the explicit flag saying "file locked", but I would be expect that to be the case.

My suspicion is that Gloda may not be paying attention to that flag, or may not be setting it when needing to operate on the MSF files.  At some point, the Gloda process may be colliding with the windows goodies, and when that happens it's likely that Gloda hits a timeout and just leaves all MFS files empty.

But of course, this is all just speculation.

Comment 28

[Wayne Mery (:wsmwk)]

Chaiki, what bug number do you suggest we set as dependency?

(In reply to David Taber from comment #27)
> Hi everyone,
> It is critical to make the distinction between biglocker and other

I think you mean bitlocker.

> encryption schemes and the Encrypted File System that has been in windows
> pro for over a decade.  This file system behaves like a very weird driver,
> dynamically (but transparently) encrypting/decrypting files under its
> control.  Yes, it is available on a file-by-file basis, although of course
> you can encrypt as large a file tree as you like. To all applications, there
> are no API differences.  

regarding slowness, xref 
- bug 715714  - Adapt cache based on io rates
- http://windows.microsoft.com/en-us/windows7/whats-the-difference-between-bitlocker-drive-encryption-and-encrypting-file-system
- bug 729057 - mainthread IO
- bug 483192

Comment 29

[ISHIKAWA, Chiaki]

(In reply to Wayne Mery (:wsmwk, use Needinfo for questions) from comment #28)
> Chaiki, what bug number do you suggest we set as dependency?
> 

Hi, please let me think about it. But, frankly speaking, it is very difficult to set a dependency since use of encryption function that can be done per file-basis
seems to be a rare usage: correct me here, maybe it *IS* used by many in enterprise setting for many documents, but maybe not many are enabling this feature on mail store.

I just came back from a family business: this has been a long weekend and monday is a holiday here, so let me think about this while I get up to date with mail back log.

TIA

Comment 30

[David Taber]

Hi all,
You bring up an interesting question about the use-case for encrypting mail files.
I'm a consultant, with about 100 clients in 6 countries.  With each consulting contract I sign, I have to show that I am applying "commercially reasonable efforts" to protect my client's information.  
Since most of the information I exchange with clients is done via email, and most of the really interesting stuff is in attachments, I must encrypt the mail files.  Any consultant will have this requirement, and most employees of security-conscious companies do as well.
I do NOT need to encrypt the MSF files, but unfortunately the only way to make sure that all my clients' mail files are encrypted is to set the encryption flag at the directory level...but the result of that is all the files created within that directory get encrypted.  
With bitlocker, the situation is even worse: if I were to use that, I'd have to encrypt the entire partition.  I know of no way to exclude certain file types from the encryption scheme.

Comment 31

[Wayne Mery (:wsmwk)]

perhaps bug 1279344 is related

Comment 32

[David Taber]

I'm the original bug reporter, and the symptoms I had been experiencing stopped long ago.
May be worth closing this one.

Comment 33

[Wayne Mery (:wsmwk)]

WFM per reporter

Comment 34

[David Taber]

Confirming that this symptom does not seem to exist anymore, at least on my system..