Closed Bug 564703 Opened 9 years ago Closed 9 years ago

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

Categories

(MailNews Core :: Database, defect)

x86
Linux
defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
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: 9 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.