Closed Bug 564703 Opened 15 years ago Closed 14 years ago

Intermittent failure in test_index_compaction.js | test failed (with xpcshell return code: 0)

Categories

(MailNews Core :: Database, defect)

Product:
MailNews Core
Component:
Database
Platform:
x86
Linux
Type:
defect
Priority:
Not set
Severity:
normal

Tracking

(Not tracked)

Status:
RESOLVED FIXED
Milestone:
Thunderbird 5.0b1

People

(Reporter: philor, Assigned: asuth)

References

Details

(Keywords: intermittent-failure, Whiteboard: [frequent])

http://tinderbox.mozilla.org/showlog.cgi?log=Thunderbird/1273437473.1273439673.27229.gz Linux comm-central check on 2010/05/09 13:37:53 TEST-UNEXPECTED-FAIL | /buildbot/linux-comm-central-check/build/objdir/mozilla/_tests/xpcshell/test_mailnewsglobaldb/unit/test_index_compaction.js | test failed (with xpcshell return code: 0), see following log: >>>>>>> ### XPCOM_MEM_LEAK_LOG defined -- logging leaks to /tmp/tmpbF5hzE/runxpcshelltests_leaks.log 2010-05-09 14:08:19 gloda.NS INFO Logging Initialized 2010-05-09 14:08:19 gloda.datastore DEBUG Beginning datastore initialization. 2010-05-09 14:08:19 gloda.datastore DEBUG Creating database because it does't exist. 2010-05-09 14:08:19 gloda.datastore INFO Creating table: folderLocations 2010-05-09 14:08:19 gloda.datastore INFO Creating table: conversations 2010-05-09 14:08:19 gloda.datastore INFO Creating fulltext table: CREATE VIRTUAL TABLE conversationsText USING fts3(tokenize mozporter, subject TEXT) 2010-05-09 14:08:19 gloda.datastore INFO Creating table: messages 2010-05-09 14:08:19 gloda.datastore INFO Creating fulltext table: CREATE VIRTUAL TABLE messagesText USING fts3(tokenize mozporter, subject TEXT, body TEXT, attachmentNames TEXT, author TEXT, recipients TEXT) 2010-05-09 14:08:19 gloda.datastore INFO Creating table: attributeDefinitions 2010-05-09 14:08:19 gloda.datastore INFO Creating table: messageAttributes 2010-05-09 14:08:19 gloda.datastore INFO Creating table: contacts 2010-05-09 14:08:19 gloda.datastore INFO Creating table: contactAttributes 2010-05-09 14:08:19 gloda.datastore INFO Creating table: identities 2010-05-09 14:08:19 gloda.datastore DEBUG Initializing folder mappings. 2010-05-09 14:08:19 gloda.datastore DEBUG Populating managed id counters. 2010-05-09 14:08:19 gloda.datastore DEBUG Completed datastore initialization. 2010-05-09 14:08:19 gloda.NS INFO Defining noun: bool 2010-05-09 14:08:19 gloda.NS INFO Defining noun: number 2010-05-09 14:08:19 gloda.NS INFO Defining noun: string 2010-05-09 14:08:19 gloda.NS INFO Defining noun: date 2010-05-09 14:08:19 gloda.NS INFO Defining noun: fulltext 2010-05-09 14:08:19 gloda.NS INFO Defining noun: folder 2010-05-09 14:08:19 gloda.NS INFO Defining noun: conversation 2010-05-09 14:08:19 gloda.NS INFO Defining noun: message 2010-05-09 14:08:19 gloda.NS INFO Defining noun: contact 2010-05-09 14:08:19 gloda.NS INFO Defining noun: identity 2010-05-09 14:08:19 gloda.NS INFO Defining noun: parameterized-identity 2010-05-09 14:08:19 gloda.datastore INFO loading all attribute defs 2010-05-09 14:08:19 gloda.datastore INFO done loading all attribute defs 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/fundattr.js 2010-05-09 14:08:19 gloda.NS INFO Defining noun: mime-type 2010-05-09 14:08:19 gloda.datastore INFO Creating table: ext_mimeTypes 2010-05-09 14:08:19 gloda.noun.mimetype DEBUG loading MIME types 2010-05-09 14:08:19 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM ext_mimeTypes ARGS: 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/fundattr.js 2010-05-09 14:08:19 gloda.everybody INFO +++ inited resource:///modules/gloda/fundattr.js 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/explattr.js 2010-05-09 14:08:19 gloda.NS INFO Defining noun: tag 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/explattr.js 2010-05-09 14:08:19 gloda.everybody INFO +++ inited resource:///modules/gloda/explattr.js 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/noun_tag.js 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/noun_tag.js 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/noun_freetag.js 2010-05-09 14:08:19 gloda.NS INFO Defining noun: freetag 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/noun_freetag.js 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/noun_mimetype.js 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/noun_mimetype.js 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/index_msg.js 2010-05-09 14:08:19 gloda.indexer INFO Registering indexer: index_msg 2010-05-09 14:08:19 gloda.index_msg INFO Event-Driven Indexing is now true 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/index_msg.js 2010-05-09 14:08:19 gloda.everybody INFO ... loading resource:///modules/gloda/index_ab.js 2010-05-09 14:08:19 gloda.indexer INFO Registering indexer: index_ab 2010-05-09 14:08:19 gloda.everybody INFO +++ loaded resource:///modules/gloda/index_ab.js 2010-05-09 14:08:19 gloda.everybody INFO +++ inited resource:///modules/gloda/index_ab.js TEST-INFO | (xpcshell/head.js) | test 1 pending Directory request for: MailD that we (mailDirService.js) are not handling, leaving it to another handler. Directory request for: MFCaF that we (mailDirService.js) are not handling, leaving it to another handler. Directory request for: DefRt that we (mailDirService.js) are not handling, leaving it to another handler. 2010-05-09 14:08:19 gloda.datastore DEBUG !! mapped 1 from mailbox://nobody@Local%20Folders/Inbox 2010-05-09 14:08:19 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: undefined TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | running event loop 2010-05-09 14:08:19 test.test INFO [Context: test.test:1 state: started] Starting test: test_compaction_indexing_pass, none pending commit TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished 2010-05-09 14:08:19 gloda.datastore DEBUG !! mapped 2 from mailbox://nobody@Local%20Folders/gabba0 2010-05-09 14:08:19 gloda.index_msg DEBUG msgsClassified notification 2010-05-09 14:08:19 gloda.indexer INFO Queue-ing job for indexing: message 2010-05-09 14:08:19 gloda.indexer INFO +++ Indexing Queue Processing Commencing TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:19 gloda.indexer DEBUG Hired job of type: message 2010-05-09 14:08:19 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:19 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba0 2010-05-09 14:08:19 gloda.index_msg DEBUG *** Indexing message: 0 : Big Meeting Today 2010-05-09 14:08:19 gloda.index_msg DEBUG * Got message, subject Big Meeting Today 2010-05-09 14:08:19 gloda.index_msg DEBUG * Got Mime Message: Big Meeting Today 1 Body: text/plain (17 bytes) 2010-05-09 14:08:19 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 ('0@made.up')))) ARGS: 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:20 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:20 gloda.index_msg DEBUG references: 0 = 0@made.up 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:20 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:20 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:20 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('andy@anway.nul','bob@bell.nul')))) ARGS: 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Andy Anway' (andy@anway.nul) 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Bob Bell' (bob@bell.nul) 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:20 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:20 gloda.NS INFO ** done with providers. 2010-05-09 14:08:20 gloda.NS DEBUG json text: {"42":1,"43":[2],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[1,2],"50":[2]} 2010-05-09 14:08:20 gloda.NS DEBUG inserting item 2010-05-09 14:08:20 gloda.NS DEBUG adjusting attributes, add: 42,1,43,2,55,0,56,0,57,0,58,0,1,54,49,1,49,2,50,2 rem: 2010-05-09 14:08:20 gloda.NS DEBUG done grokking. 2010-05-09 14:08:20 gloda.index_msg DEBUG *** Indexing message: 263 : Huge Shindig Yesterday 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got message, subject Huge Shindig Yesterday 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got Mime Message: Huge Shindig Yesterday 1 Body: text/plain (22 bytes) 2010-05-09 14:08:20 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 ('2@made.up')))) ARGS: 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:20 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:20 gloda.index_msg DEBUG references: 0 = 2@made.up 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:20 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:20 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:20 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('emily@ekberg.nul','felix@flowers.nul')))) ARGS: 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Emily Ekberg' (emily@ekberg.nul) 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Felix Flowers' (felix@flowers.nul) 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:20 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:20 gloda.NS INFO ** done with providers. 2010-05-09 14:08:20 gloda.NS DEBUG json text: {"42":3,"43":[4],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[3,4],"50":[4]} 2010-05-09 14:08:20 gloda.NS DEBUG inserting item 2010-05-09 14:08:20 gloda.NS DEBUG adjusting attributes, add: 42,3,43,4,55,0,56,0,57,0,58,0,1,54,49,3,49,4,50,4 rem: 2010-05-09 14:08:20 gloda.NS DEBUG done grokking. 2010-05-09 14:08:20 gloda.index_msg DEBUG *** Indexing message: 552 : Tiny Wedding In a Fortnight 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got message, subject Tiny Wedding In a Fortnight 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got Mime Message: Tiny Wedding In a Fortnight 1 Body: text/plain (19 bytes) 2010-05-09 14:08:20 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 ('3@made.up')))) ARGS: 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:20 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:20 gloda.index_msg DEBUG references: 0 = 3@made.up 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:20 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:20 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:20 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('gillian@gilbert.nul','helen@hook.nul')))) ARGS: 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Gillian Gilbert' (gillian@gilbert.nul) 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Helen Hook' (helen@hook.nul) 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:20 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:20 gloda.NS INFO ** done with providers. 2010-05-09 14:08:20 gloda.NS DEBUG json text: {"42":5,"43":[6],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[5,6],"50":[6]} 2010-05-09 14:08:20 gloda.NS DEBUG inserting item 2010-05-09 14:08:20 gloda.NS DEBUG adjusting attributes, add: 42,5,43,6,55,0,56,0,57,0,58,0,1,54,49,5,49,6,50,6 rem: 2010-05-09 14:08:20 gloda.NS DEBUG done grokking. 2010-05-09 14:08:20 gloda.index_msg DEBUG *** Indexing message: 846 : Small Party Tomorrow 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got message, subject Small Party Tomorrow 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got Mime Message: Small Party Tomorrow 1 Body: text/plain (20 bytes) 2010-05-09 14:08:20 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 ('1@made.up')))) ARGS: 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:20 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:20 gloda.index_msg DEBUG references: 0 = 1@made.up 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:20 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:20 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:20 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('chris@clarke.nul','david@davol.nul')))) ARGS: 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Chris Clarke' (chris@clarke.nul) 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'David Davol' (david@davol.nul) 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:20 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:20 gloda.NS INFO ** done with providers. 2010-05-09 14:08:20 gloda.NS DEBUG json text: {"42":7,"43":[8],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[7,8],"50":[8]} 2010-05-09 14:08:20 gloda.NS DEBUG inserting item 2010-05-09 14:08:20 gloda.NS DEBUG adjusting attributes, add: 42,7,43,8,55,0,56,0,57,0,58,0,1,54,49,7,49,8,50,8 rem: 2010-05-09 14:08:20 gloda.NS DEBUG done grokking. 2010-05-09 14:08:20 gloda.index_msg DEBUG *** Indexing message: 1127 : Red Document Needs Attention 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got message, subject Red Document Needs Attention 2010-05-09 14:08:20 gloda.index_msg DEBUG * Got Mime Message: Red Document Needs Attention 1 Body: text/plain (21 bytes) 2010-05-09 14:08:20 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 ('4@made.up')))) ARGS: 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:20 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:20 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:20 gloda.index_msg DEBUG references: 0 = 4@made.up 2010-05-09 14:08:20 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:20 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:20 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:20 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('idina@ivarsson.nul','johnny@jones.nul')))) ARGS: 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Idina Ivarsson' (idina@ivarsson.nul) 2010-05-09 14:08:20 gloda.NS DEBUG creating contact for 'Johnny Jones' (johnny@jones.nul) 2010-05-09 14:08:20 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:20 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:20 gloda.NS INFO ** done with providers. 2010-05-09 14:08:20 gloda.NS DEBUG json text: {"42":9,"43":[10],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[9,10],"50":[10]} 2010-05-09 14:08:20 gloda.NS DEBUG inserting item 2010-05-09 14:08:20 gloda.NS DEBUG adjusting attributes, add: 42,9,43,10,55,0,56,0,57,0,58,0,1,54,49,9,49,10,50,10 rem: 2010-05-09 14:08:20 gloda.NS DEBUG done grokking. 2010-05-09 14:08:20 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:20 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:20 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:20 gloda.datastore DEBUG !! mapped 3 from mailbox://nobody@Local%20Folders/gabba1 TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:20 gloda.index_msg DEBUG MoveCopy notification. Move: true TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:20 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:20 gloda.indexer INFO +++ Indexing Queue Processing Commencing 2010-05-09 14:08:20 gloda.indexer INFO Queue-ing job for indexing: folder TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:20 gloda.indexer DEBUG Hired job of type: folderCompact 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba0 2010-05-09 14:08:21 gloda.indexer DEBUG Hired job of type: folder 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba0 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:21 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:21 test.test INFO [Context: test.test:1 state: finished] Finished test: test_compaction_indexing_pass, none pending commit 2010-05-09 14:08:21 test.test INFO [Context: test.test:2 state: started] Starting test: test_compaction_indexing_pass, all pending commit TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished 2010-05-09 14:08:21 gloda.datastore DEBUG !! mapped 4 from mailbox://nobody@Local%20Folders/gabba2 2010-05-09 14:08:21 gloda.index_msg DEBUG msgsClassified notification 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: message 2010-05-09 14:08:21 gloda.indexer INFO +++ Indexing Queue Processing Commencing TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.indexer DEBUG Hired job of type: message 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba2 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 0 : Green Report Very Important 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject Green Report Very Important 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: Green Report Very Important 1 Body: text/plain (19 bytes) 2010-05-09 14:08: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 ('5@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 5@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('kate@kurtz.nul','lilia@lowe.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Kate Kurtz' (kate@kurtz.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Lilia Lowe' (lilia@lowe.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":11,"43":[12],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[11,12],"50":[12]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,11,43,12,55,0,56,0,57,0,58,0,1,54,49,11,49,12,50,12 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 279 : My Hovercraft Full Of Eels 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject My Hovercraft Full Of Eels 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: My Hovercraft Full Of Eels 1 Body: text/plain (19 bytes) 2010-05-09 14:08: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 ('7@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 7@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('olof@orzabal.nul','pete@price.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Olof Orzabal' (olof@orzabal.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Pete Price' (pete@price.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":13,"43":[14],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[13,14],"50":[14]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,13,43,14,55,0,56,0,57,0,58,0,1,54,49,13,49,14,50,14 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 563 : Happy Aardvark In The Lobby 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject Happy Aardvark In The Lobby 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: Happy Aardvark In The Lobby 1 Body: text/plain (24 bytes) 2010-05-09 14:08: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 ('8@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 8@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('quinn@quinn.nul','rasmus@rolinski.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Quinn Quinn' (quinn@quinn.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Rasmus Rolinski' (rasmus@rolinski.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":15,"43":[16],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[15,16],"50":[16]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,15,43,16,55,0,56,0,57,0,58,0,1,54,49,15,49,16,50,16 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 860 : Blue Spreadsheet Highest Priority 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject Blue Spreadsheet Highest Priority 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: Blue Spreadsheet Highest Priority 1 Body: text/plain (19 bytes) 2010-05-09 14:08: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 ('6@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 6@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('martin@morris.nul','neil@nagel.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Martin Morris' (martin@morris.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Neil Nagel' (neil@nagel.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":17,"43":[18],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[17,18],"50":[18]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,17,43,18,55,0,56,0,57,0,58,0,1,54,49,17,49,18,50,18 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 1154 : Sad Giraffe On Your Desk 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject Sad Giraffe On Your Desk 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: Sad Giraffe On Your Desk 1 Body: text/plain (23 bytes) 2010-05-09 14:08: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 ('9@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 9@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('sarah@stanley.nul','troels@tennant.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Sarah Stanley' (sarah@stanley.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Troels Tennant' (troels@tennant.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":19,"43":[20],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[19,20],"50":[20]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,19,43,20,55,0,56,0,57,0,58,0,1,54,49,19,49,20,50,20 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:21 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:21 gloda.datastore DEBUG !! mapped 5 from mailbox://nobody@Local%20Folders/gabba3 TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.index_msg DEBUG MoveCopy notification. Move: true TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:21 gloda.indexer INFO +++ Indexing Queue Processing Commencing 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: folder TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.indexer DEBUG Hired job of type: folderCompact 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba2 2010-05-09 14:08:21 gloda.indexer DEBUG Hired job of type: folder 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba2 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:21 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:21 test.test INFO [Context: test.test:2 state: finished] Finished test: test_compaction_indexing_pass, all pending commit 2010-05-09 14:08:21 test.test INFO [Context: test.test:3 state: started] Starting test: test_sweep_performs_compaction TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished 2010-05-09 14:08:21 gloda.datastore DEBUG !! mapped 6 from mailbox://nobody@Local%20Folders/gabba4 2010-05-09 14:08:21 gloda.index_msg DEBUG msgsClassified notification 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: message 2010-05-09 14:08:21 gloda.indexer INFO +++ Indexing Queue Processing Commencing TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.indexer DEBUG Hired job of type: message 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:21 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba4 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 0 : Grumpy Llama In Your Car 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject Grumpy Llama In Your Car 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: Grumpy Llama In Your Car 1 Body: text/plain (23 bytes) 2010-05-09 14:08: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 ('10@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 10@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('ulf@ulvaeus.nul','vince@vannucci.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Ulf Ulvaeus' (ulf@ulvaeus.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Vince Vannucci' (vince@vannucci.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":21,"43":[22],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[21,22],"50":[22]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,21,43,22,55,0,56,0,57,0,58,0,1,54,49,21,49,22,50,22 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.index_msg DEBUG *** Indexing message: 292 : Angry Velociraptor Hiding Behind The Door 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got message, subject Angry Velociraptor Hiding Behind The Door 2010-05-09 14:08:21 gloda.index_msg DEBUG * Got Mime Message: Angry Velociraptor Hiding Behind The Door 1 Body: text/plain (22 bytes) 2010-05-09 14:08: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 ('11@made.up')))) ARGS: 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:21 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:21 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:21 gloda.index_msg DEBUG references: 0 = 11@made.up 2010-05-09 14:08:21 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:21 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:21 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:21 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('will@wiggs.nul','xavier@xavier.nul')))) ARGS: 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Will Wiggs' (will@wiggs.nul) 2010-05-09 14:08:21 gloda.NS DEBUG creating contact for 'Xavier Xavier' (xavier@xavier.nul) 2010-05-09 14:08:21 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:21 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:21 gloda.NS INFO ** done with providers. 2010-05-09 14:08:21 gloda.NS DEBUG json text: {"42":23,"43":[24],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[23,24],"50":[24]} 2010-05-09 14:08:21 gloda.NS DEBUG inserting item 2010-05-09 14:08:21 gloda.NS DEBUG adjusting attributes, add: 42,23,43,24,55,0,56,0,57,0,58,0,1,54,49,23,49,24,50,24 rem: 2010-05-09 14:08:21 gloda.NS DEBUG done grokking. 2010-05-09 14:08:21 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:21 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:21 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:21 gloda.datastore DEBUG !! mapped 7 from mailbox://nobody@Local%20Folders/gabba5 TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.index_msg DEBUG MoveCopy notification. Move: true TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:21 gloda.indexer INFO +++ Indexing Queue Processing Commencing 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: folder TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-PASS | /buildbot/linux-comm-central-check/build/objdir/mozilla/_tests/xpcshell/test_mailnewsglobaldb/unit/test_index_compaction.js | [test_sweep_performs_compaction : 162] true == true 2010-05-09 14:08:21 gloda.indexer INFO Queue-ing job for indexing: folderSweep TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderSweep 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.datastore DEBUG !! mapped 8 from mailbox://nobody@Local%20Folders/Trash 2010-05-09 14:08:22 gloda.datastore DEBUG !! mapped 9 from mailbox://nobody@Local%20Folders/Unsent%20Messages 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folder 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderSweep 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderCompact 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba4 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folder 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba4 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderSweep 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: delete 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: delete 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG There are currently 0 messages awaiting deletion processing. 2010-05-09 14:08:22 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 (deleted IN (1)))) LIMIT ? ARGS: 32 2010-05-09 14:08:22 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:22 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:22 test.test INFO [Context: test.test:3 state: finished] Finished test: test_sweep_performs_compaction 2010-05-09 14:08:22 test.test INFO [Context: test.test:4 state: started] Starting test: test_moves_and_deletions_on_compacted_folder_edge_case TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished 2010-05-09 14:08:22 gloda.datastore DEBUG !! mapped 10 from mailbox://nobody@Local%20Folders/gabba6 2010-05-09 14:08:22 gloda.index_msg DEBUG msgsClassified notification 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: message 2010-05-09 14:08:22 gloda.indexer INFO +++ Indexing Queue Processing Commencing TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: message 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba6 2010-05-09 14:08:22 gloda.index_msg DEBUG *** Indexing message: 0 : Awesome Laser Today 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got message, subject Awesome Laser Today 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got Mime Message: Awesome Laser Today 1 Body: text/plain (16 bytes) 2010-05-09 14:08:22 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 ('12@made.up')))) ARGS: 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:22 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:22 gloda.index_msg DEBUG references: 0 = 12@made.up 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:22 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:22 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:22 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('yoko@young.nul','zig@zig.nul')))) ARGS: 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Yoko Young' (yoko@young.nul) 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Zig Zig' (zig@zig.nul) 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:22 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:22 gloda.NS INFO ** done with providers. 2010-05-09 14:08:22 gloda.NS DEBUG json text: {"42":25,"43":[26],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[25,26],"50":[26]} 2010-05-09 14:08:22 gloda.NS DEBUG inserting item 2010-05-09 14:08:22 gloda.NS DEBUG adjusting attributes, add: 42,25,43,26,55,0,56,0,57,0,58,0,1,54,49,25,49,26,50,26 rem: 2010-05-09 14:08:22 gloda.NS DEBUG done grokking. 2010-05-09 14:08:22 gloda.index_msg DEBUG *** Indexing message: 263 : Fun Ray-Gun Tomorrow 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got message, subject Fun Ray-Gun Tomorrow 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got Mime Message: Fun Ray-Gun Tomorrow 1 Body: text/plain (19 bytes) 2010-05-09 14:08:22 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 ('13@made.up')))) ARGS: 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:22 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:22 gloda.index_msg DEBUG references: 0 = 13@made.up 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:22 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:22 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:22 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('andy@bell.nul','bob@clarke.nul')))) ARGS: 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Andy Bell' (andy@bell.nul) 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Bob Clarke' (bob@clarke.nul) 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:22 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:22 gloda.NS INFO ** done with providers. 2010-05-09 14:08:22 gloda.NS DEBUG json text: {"42":27,"43":[28],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[27,28],"50":[28]} 2010-05-09 14:08:22 gloda.NS DEBUG inserting item 2010-05-09 14:08:22 gloda.NS DEBUG adjusting attributes, add: 42,27,43,28,55,0,56,0,57,0,58,0,1,54,49,27,49,28,50,28 rem: 2010-05-09 14:08:22 gloda.NS DEBUG done grokking. 2010-05-09 14:08:22 gloda.index_msg DEBUG *** Indexing message: 533 : Lame Pen Yesterday 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got message, subject Lame Pen Yesterday 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got Mime Message: Lame Pen Yesterday 1 Body: text/plain (21 bytes) 2010-05-09 14:08:22 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 ('14@made.up')))) ARGS: 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:22 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:22 gloda.index_msg DEBUG references: 0 = 14@made.up 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:22 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:22 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:22 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('chris@davol.nul','david@ekberg.nul')))) ARGS: 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Chris Davol' (chris@davol.nul) 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'David Ekberg' (david@ekberg.nul) 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:22 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:22 gloda.NS INFO ** done with providers. 2010-05-09 14:08:22 gloda.NS DEBUG json text: {"42":29,"43":[30],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[29,30],"50":[30]} 2010-05-09 14:08:22 gloda.NS DEBUG inserting item 2010-05-09 14:08:22 gloda.NS DEBUG adjusting attributes, add: 42,29,43,30,55,0,56,0,57,0,58,0,1,54,49,29,49,30,50,30 rem: 2010-05-09 14:08:22 gloda.NS DEBUG done grokking. 2010-05-09 14:08:22 gloda.index_msg DEBUG *** Indexing message: 813 : Funky Sword In a Fortnight 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got message, subject Funky Sword In a Fortnight 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got Mime Message: Funky Sword In a Fortnight 1 Body: text/plain (22 bytes) 2010-05-09 14:08:22 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 ('15@made.up')))) ARGS: 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG query completed, notifying... 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors raw: 2010-05-09 14:08:22 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:22 gloda.index_msg DEBUG references: 0 = 15@made.up 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors: 0 = 2010-05-09 14:08:22 gloda.index_msg DEBUG 0 candidate messages 2010-05-09 14:08:22 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:22 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('emily@flowers.nul','felix@gilbert.nul')))) ARGS: 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Emily Flowers' (emily@flowers.nul) 2010-05-09 14:08:22 gloda.NS DEBUG creating contact for 'Felix Gilbert' (felix@gilbert.nul) 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:22 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:22 gloda.NS INFO ** done with providers. 2010-05-09 14:08:22 gloda.NS DEBUG json text: {"42":31,"43":[32],"44":[],"45":[],"55":false,"56":false,"57":false,"58":false,"54":[],"49":[31,32],"50":[32]} 2010-05-09 14:08:22 gloda.NS DEBUG inserting item 2010-05-09 14:08:22 gloda.NS DEBUG adjusting attributes, add: 42,31,43,32,55,0,56,0,57,0,58,0,1,54,49,31,49,32,50,32 rem: 2010-05-09 14:08:22 gloda.NS DEBUG done grokking. 2010-05-09 14:08:22 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true 2010-05-09 14:08:22 gloda.test DEBUG kicking driver... TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:22 gloda.datastore DEBUG !! mapped 11 from mailbox://nobody@Local%20Folders/gabba7 TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:22 gloda.index_msg DEBUG MoveCopy notification. Move: true TEST-INFO | (xpcshell/head.js) | test 2 pending TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:22 gloda.indexer INFO +++ Indexing Queue Processing Commencing 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folder TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:22 gloda.index_msg DEBUG msgsDeleted notification TEST-INFO | (xpcshell/head.js) | test 3 pending TEST-INFO | (xpcshell/head.js) | test 3 finished TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:22 gloda.index_msg DEBUG MoveCopy notification. Move: true 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderSweep TEST-INFO | (xpcshell/head.js) | test 2 pending 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderSweep 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: false 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folder 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderSweep 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderCompact 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: false 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba6 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderSweep TEST-INFO | (xpcshell/head.js) | test 2 finished 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderSweep 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderCompact 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folder 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderSweep 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderCompact 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba6 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folder 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba6 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderSweep 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folder 2010-05-09 14:08:22 gloda.indexer INFO Queue-ing job for indexing: folderSweep 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folder 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG Entering folder: mailbox://nobody@Local%20Folders/gabba7 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.index_msg DEBUG >>> _indexMessage 2010-05-09 14:08:22 gloda.index_msg DEBUG *** Indexing message: 263 : Fun Ray-Gun Tomorrow 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got message, subject Fun Ray-Gun Tomorrow 2010-05-09 14:08:22 gloda.index_msg DEBUG * Got Mime Message: Fun Ray-Gun Tomorrow 1 Body: text/plain (19 bytes) 2010-05-09 14:08:22 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 ('13@made.up')))) ARGS: 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG getting results... 2010-05-09 14:08:22 gloda.index_msg.mbm DEBUG query completed, notifying... Message:45 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors raw: Message:45 2010-05-09 14:08:22 gloda.index_msg DEBUG ref len: 1 anc len: 1 2010-05-09 14:08:22 gloda.index_msg DEBUG references: 0 = 13@made.up 2010-05-09 14:08:22 gloda.index_msg DEBUG ancestors: 0 = Message:45 2010-05-09 14:08:22 gloda.index_msg DEBUG 1 candidate messages 2010-05-09 14:08:22 gloda.index_msg DEBUG candidate folderID: null messageKey: null 2010-05-09 14:08:22 gloda.NS INFO ** grokNounItem: message 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.fundattr 2010-05-09 14:08:22 gloda.datastore DEBUG QUERY FROM QUERY: SELECT * FROM identities WHERE (id IN (SELECT id FROM identities WHERE (kind IN ('email')) AND (value IN ('andy@bell.nul','bob@clarke.nul')))) ARGS: 2010-05-09 14:08:22 gloda.NS DEBUG found identity for 'Andy Bell' (andy@bell.nul) 2010-05-09 14:08:22 gloda.NS DEBUG found identity for 'Bob Clarke' (bob@clarke.nul) 2010-05-09 14:08:22 gloda.NS INFO * provider: gloda.explattr 2010-05-09 14:08:22 gloda.NS INFO * optimizer: gloda.fundattr 2010-05-09 14:08:22 gloda.NS INFO ** done with providers. 2010-05-09 14:08:22 gloda.NS DEBUG json text: {"55":false,"56":false,"57":false,"58":false,"54":[],"42":27,"43":[28],"44":[],"45":[],"49":[27,28,27,28],"50":[28,28]} 2010-05-09 14:08:22 gloda.NS DEBUG updating item 2010-05-09 14:08:22 gloda.datastore DEBUG in _updateMessageText, skipping update because body matches 2010-05-09 14:08:22 gloda.NS DEBUG adjusting attributes, add: 55,0,56,0,57,0,58,0,1,54,42,27,43,28,49,27,49,28,49,27,49,28,50,28,50,28 rem: 2010-05-09 14:08:22 gloda.NS DEBUG done grokking. 2010-05-09 14:08:22 gloda.index_msg DEBUG <<< _indexMessage 2010-05-09 14:08:22 gloda.indexer DEBUG Hired job of type: folderSweep 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 1 waiting: true 2010-05-09 14:08:22 gloda.indexer INFO --- Done indexing, disabling timer renewal. 2010-05-09 14:08:22 gloda.test DEBUG ((( Index listener notified! aStatus = 0 waiting: true TEST-UNEXPECTED-FAIL | resources/glodaTestHelper.js | Expected worker-cleaned-up count did not match actual! Expected 0 actual 1 - See following stack: JS frame :: /buildbot/linux-comm-central-check/build/mozilla/testing/xpcshell/head.js :: do_throw :: line 257 JS frame :: ../../mailnews/resources/logHelper.js :: mark_failure :: line 557 JS frame :: resources/glodaTestHelper.js :: _indexMessageState_assertExpectedMessagesIndexed :: line 554 JS frame :: resources/glodaTestHelper.js :: anonymous :: line 640 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: gloda_index_notifyListeners :: line 773 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: gloda_index_workBatch :: line 1230 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: gloda_index_callbackDriver :: line 856 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: anonymous :: line 988 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/collection.js :: gloda_coll_onQueryCompleted :: line 660 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/datastore.js :: anonymous :: line 180 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/datastore.js :: gloda_ds_qfq_handleCompletion :: line 417 TEST-INFO | (xpcshell/head.js) | exiting test 2010-05-09 14:08:22 gloda.indexer ERROR 2147500036 TEST-UNEXPECTED-FAIL | file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js | 2010-05-09 14:08:22 gloda.indexer ERROR 2147500036 - See following stack: JS frame :: /buildbot/linux-comm-central-check/build/mozilla/testing/xpcshell/head.js :: do_throw :: line 257 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: TApp_doAppend :: line 852 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: App_append :: line 576 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: Logger_log :: line 356 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: Logger_error :: line 366 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: gloda_index_notifyListeners :: line 776 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: gloda_index_workBatch :: line 1230 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: gloda_index_callbackDriver :: line 856 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/indexer.js :: anonymous :: line 988 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/collection.js :: gloda_coll_onQueryCompleted :: line 660 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/datastore.js :: anonymous :: line 180 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/datastore.js :: gloda_ds_qfq_handleCompletion :: line 417 TEST-INFO | (xpcshell/head.js) | exiting test 2010-05-09 14:08:22 gloda.ds.qfq ERROR Exception: 2147500036 TEST-UNEXPECTED-FAIL | file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js | 2010-05-09 14:08:22 gloda.ds.qfq ERROR Exception: 2147500036 - See following stack: JS frame :: /buildbot/linux-comm-central-check/build/mozilla/testing/xpcshell/head.js :: do_throw :: line 257 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: TApp_doAppend :: line 852 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: App_append :: line 576 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: Logger_log :: line 356 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/log4moz.js :: Logger_error :: line 366 JS frame :: file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/datastore.js :: gloda_ds_qfq_handleCompletion :: line 422 TEST-INFO | (xpcshell/head.js) | exiting test TEST-UNEXPECTED-FAIL | ../../mailnews/resources/logHelper.js | Error console says [JavaScript Error: "2147500036" {file: "file:///buildbot/linux-comm-central-check/build/objdir/mozilla/dist/bin/modules/gloda/datastore.js" line: 421}] - See following stack: JS frame :: /buildbot/linux-comm-central-check/build/mozilla/testing/xpcshell/head.js :: do_throw :: line 257 JS frame :: ../../mailnews/resources/logHelper.js :: mark_failure :: line 557 JS frame :: ../../mailnews/resources/logHelper.js :: anonymous :: line 71 TEST-INFO | (xpcshell/head.js) | exiting test TEST-UNEXPECTED-FAIL | ../../mailnews/resources/logHelper.js | Error console says [JavaScript Error: "[Exception... "'Abort' when calling method: [mozIStorageStatementCallback::handleCompletion]" nsresult: "0x80004004 (NS_ERROR_ABORT)" location: "<unknown>" data: no]"] - See following stack: JS frame :: /buildbot/linux-comm-central-check/build/mozilla/testing/xpcshell/head.js :: do_throw :: line 257 JS frame :: ../../mailnews/resources/logHelper.js :: mark_failure :: line 557 JS frame :: ../../mailnews/resources/logHelper.js :: anonymous :: line 71 TEST-INFO | (xpcshell/head.js) | exiting test before 3510272, after 2633728, break 093f1000 2010-05-09 14:08:22 gloda.indexer INFO Shutting Down 2010-05-09 14:08:22 gloda.index_msg INFO Event-Driven Indexing is now false 2010-05-09 14:08:22 gloda.datastore INFO Closing pending transaction out for shutdown. 2010-05-09 14:08:22 gloda.datastore INFO Closing db connection <<<<<<<
Blocks: 438871
This is one of our most frequent Linux failures I believe, assigning to asuth as I think he probably wrote it in the first place.
Assignee: nobody → bugmail
Whiteboard: [orange] → [orange][frequent]
Yeah, there was definitely a race in here. The race is now guarded against and I've enhanced the logging output slightly to help make the phenomenon that caused this problem more obvious. pushed to trunk: http://hg.mozilla.org/comm-central/rev/d2cd63699d7f note: I declared this r=test-only because I thought that was a thing because I saw Standard8 do it recently, but it appears that was more of a one-off thing that was even more tightly constrained (just changing some sleep timeouts). This was also a highly constrained orange fix that passed local xpcshell runs, but arguably more complex in nature. The flip-side is that the complexity is the kind of thing that means a review would tend to be cursory or actively understanding a fair amount of gloda mechanics. I've used one-off/time-limited provisional rubber stamps previously for these types of things previously. Anywho, my point is I'm going to go double check that we already don't have something on the books for this and then go make a proposal to tb-planning about formalizing looser constraints for very targeted orange fixes assuming we don't.
Status: NEW → RESOLVED
Closed: 14 years ago
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 3.3a4
Whiteboard: [orange][frequent] → [frequent]
You need to log in before you can comment on or make changes to this bug.