1774952 - Many warnings WARNING: Missing .messageOffset during xpcshell test (--verbose --sequential)

Status: REOPENED

(MailNews Core :: Backend, defect)

Description

[ISHIKAWA, Chiaki]

Attachment: egrep "(TEST-START|TEST_START|.messageOffset)" logfile to show which tests print the warning lines.

(Oops. It is --sequential and not --serialize. I was writing from memory. I am fixing the typo.)

(This ought to be architecture neutral although I test this under Debian GNU/Linux.)

During C-C TB's xpcshell test with "--sequential --verbose" with FULL DEBUG version of C-C TB, I see many warnings such as follows.

00:19.43 TEST_START: comm/mailnews/db/gloda/test/unit/test_index_junk_imap_online.js
00:21.76 pid:148598 [Parent 148598, Main Thread] WARNING: Missing .messageOffset (key=1, storeToken=''): file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgHdr.cpp:438
00:21.76 pid:148598 [Parent 148598, Main Thread] WARNING: Missing .messageOffset (key=2, storeToken=''): file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgHdr.cpp:438
00:22.57 TEST_START: comm/mailnews/db/gloda/test/unit/test_index_junk_local.js
00:25.49 TEST_START: comm/mailnews/db/gloda/test/unit/test_index_messages_imap_offline.js
00:45.77 TEST_START: comm/mailnews/db/gloda/test/unit/test_index_messages_imap_online.js
00:58.37 pid:148801 [Parent 148801, Main Thread] WARNING: Missing .messageOffset (key=3, storeToken=''): file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgHdr.cpp:438
00:58.37 pid:148801 [Parent 148801, Main Thread] WARNING: Missing .messageOffset (key=3, storeToken='12345678'): file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgHdr.cpp:438
00:58.39 pid:148801 [Parent 148801, Main Thread] WARNING: Missing .messageOffset (key=3, storeToken=''): file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgHdr.cpp:438
01:00.61 pid:148801 [Parent 148801, Main Thread] WARNING: Missing .messageOffset (key=1, storeToken=''): file /NEW-SSD/NREF-COMM-CENTRAL/mozilla/comm/mailnews/db/msgdb/src/nsMsgHdr.cpp:438

I mentioned this in bug 1742975
https://bugzilla.mozilla.org/show_bug.cgi?id=1742975#c137
and was advised to post a separate bugzilla.
https://bugzilla.mozilla.org/show_bug.cgi?id=1742975#c143

So here it is.
The tests that caused them are:

 comm/mail/base/test/unit/test_emptyTrash_dbViewWrapper.js
 comm/mail/components/extensions/test/xpcshell/test_ext_messages.js
 comm/mailnews/db/gloda/test/unit/test_index_junk_imap_online.js
 comm/mailnews/db/gloda/test/unit/test_index_messages_imap_online.js
 comm/mailnews/db/gloda/test/unit/test_index_messages_imap_online_to_offline.js
 comm/mailnews/imap/test/unit/test_filterCustomHeaders.js
 comm/mailnews/imap/test/unit/test_imapAutoSync.js
 comm/mailnews/imap/test/unit/test_imapCopyTimeout.js
 comm/mailnews/imap/test/unit/test_imapFilterActionsPostplugin.js
 comm/mailnews/imap/test/unit/test_imapHighWater.js
 comm/mailnews/imap/test/unit/test_imapSearch.js
 comm/mailnews/imap/test/unit/test_imapUndo.js
 comm/mailnews/imap/test/unit/test_nsIMsgFolderListenerIMAP.js
 comm/mailnews/imap/test/unit/test_offlinePlayback.js
 comm/mailnews/imap/test/unit/test_preserveDataOnMove.js
 comm/mailnews/imap/test/unit/test_trustSpamAssassin.js
 comm/mailnews/news/test/unit/test_filter.js

I am attaching the output from the following command that was run against the recent xpchshell log (NOTE --sequential and --verbose MUST be passed to |mach xpcshell-test | so that the warnings are visible even if the tests themselves are deemed to have succeeded.

egrep "(TEST-START|TEST_START|.messageOffset)" /FF-NEW/log1464-xpcshell-check-setting-var.txt

Comment 1

[ISHIKAWA, Chiaki]

(It is not |--serialize| but |--sequential|. Oops. I was writing from memory.)
The log is from a local run. I don't know how to run xpcshell test with --sequential and --verbose on treeherder.

Also, I forgot exactly why, but
here is what I do to test them in sequential manner.

for dir in $TESTDIRS
do
    bash -vx ~ishikawa/bin/nrun-xpcshell-original.sh --sequential --verbose ${dir}
done

where TESTDIRS contain the paths where | xpcshell.*.ini| is stored.

Comment 2

[Ben Campbell]

Haven't dug too far yet, but in terms of working on this...
I've just been looking at a single test (so this might not apply to the others, but I'd suspect it does):

1. You don't need the the --verbose flag to see the warning
2. The warning only appears when running the mbox variant of the test, so you can add --tag mbox (the maildir ones are --tag maildir).
3. the --tag mbox flag allows me to run gdb (when both mbox and maildir tests are being run, mach seems to be a bit odd about how it invokes gdb for me anyway).

So, this works for me:

./mach xpcshell-test --tag mbox --sequential comm/mailnews/imap/test/unit/test_nsIMsgFolderListenerIMAP.js

(adding the extra flags --debugger gdb --debugger-interactive if I want to run through gdb).

Comment 3

[Ben Campbell]

Sorry, I forgot: you do need the --verbose flag if you're running more than one test.
If you only run a single test --verbose seems to be implied.

Comment 4

[Ben Campbell]

OK, seems like these warnings are due to careless handling of offline/local msghdr fields (.messageOffset and storeToken, .messageSize and .offlineMessageSize, and the Offline message flag).
There are a few places to blame. I don't think any of them cause bigger issues, but it'd be nice to tighten it up - the warning is legitimate.
There'll probably be a few patches.

I thought these warnings appeared after the fix in Bug 1742975, but after looking at some of them I'm not sure they weren't already present. They might have been there but unnoticed (I added the warning a while back, in Bug 1720047).

Comment 5

[Ben Campbell]

Attachment: Bug 1774952 - Don't attempt to read non-offline messages in nsImapMailFolder::CopyMessagesOffline(). r=mkmelin

nsImapMailFolder::CopyMessagesOffline() was calling GetMsgInputStream() for
for non-offline messages, even if the message wasn't marked offline.

This patch also:

• moves a few local vars closer to where they are used
• tightens error checking and recovery

Comment 6

[Ben Campbell]

try run to go with the first patch:
https://treeherder.mozilla.org/#/jobs?repo=try-comm-central&revision=2b33039cbbacd1441f0cf61749c135596dc37857

Comment 7

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/71882424b430
Don't attempt to read non-offline messages in nsImapMailFolder::CopyMessagesOffline(). r=mkmelin

Comment 8

[ISHIKAWA, Chiaki]

Thank you for taking care of the issue.
I have a question, though.

(In reply to Ben Campbell from comment #2)

Haven't dug too far yet, but in terms of working on this...
I've just been looking at a single test (so this might not apply to the others, but I'd suspect it does):

1. You don't need the the --verbose flag to see the warning
2. The warning only appears when running the mbox variant of the test, so you can add --tag mbox (the maildir ones are --tag maildir).

I have not been aware of this |--tag| feature.
If I run xpcshell-test without |--tag option|, will I run the test under both settings (mbox and maildir)?
I was assuming I would all these months, but now I am not so sure.
If |--tag option| is omitted, will I be running only mbox version?

... omission ...

Comment 9

[Ben Campbell]

(In reply to ISHIKAWA, Chiaki from comment #8)

I have not been aware of this |--tag| feature.
If I run xpcshell-test without |--tag option|, will I run the test under both settings (mbox and maildir)?
I was assuming I would all these months, but now I am not so sure.
If |--tag option| is omitted, will I be running only mbox version?

Without --tag, it runs both the maildir and mbox tests.
I think only some tests have either of those tags set (IMAP, local folders etc etc).
So, for example, if you ran the calendar tests with '--tag mbox' it might not match anything and so no tests would be run (not 100% sure).

Comment 10

[ISHIKAWA, Chiaki]

(In reply to Ben Campbell from comment #9)

(In reply to ISHIKAWA, Chiaki from comment #8)

I have not been aware of this |--tag| feature.
If I run xpcshell-test without |--tag option|, will I run the test under both settings (mbox and maildir)?
I was assuming I would all these months, but now I am not so sure.
If |--tag option| is omitted, will I be running only mbox version?

Without --tag, it runs both the maildir and mbox tests.
I think only some tests have either of those tags set (IMAP, local folders etc etc).
So, for example, if you ran the calendar tests with '--tag mbox' it might not match anything and so no tests would be run (not 100% sure).

Thank you for the clarification.

Ben, the patch removed warnings from some tests. Great.
But somehow other tests still print the warnings after your patch.
Maybe there are some other places that trigger the issue with different causes?
I will upload the excerpt from my latest run.

Comment 11

[ISHIKAWA, Chiaki]

Attachment: Some tests still print warnings AFTER the patch. Output from egrep "(TEST-START|TEST_START|.messageOffset)" /FF-NEW/log1466-xpcshell.txt

After the patch, I still see the warnings printed by some tests.
They are:

Tests that still print the warnings:

 comm/mail/base/test/unit/test_emptyTrash_dbViewWrapper.js
 comm/mail/components/extensions/test/xpcshell/test_ext_messages.js
 comm/mailnews/db/gloda/test/unit/test_index_junk_imap_online.js
 comm/mailnews/db/gloda/test/unit/test_index_messages_imap_online.js
 comm/mailnews/db/gloda/test/unit/test_index_messages_imap_online_to_offline.js
 comm/mailnews/imap/test/unit/test_filterCustomHeaders.js
 comm/mailnews/imap/test/unit/test_imapAutoSync.js
 comm/mailnews/imap/test/unit/test_imapCopyTimeout.js
 comm/mailnews/imap/test/unit/test_imapFilterActionsPostplugin.js
 comm/mailnews/imap/test/unit/test_imapHighWater.js
 comm/mailnews/imap/test/unit/test_imapSearch.js
 comm/mailnews/news/test/unit/test_filter.js

Comparing the list with the previous list, I see the following tests (with "-" at the beginning of lines) no longer printed the warnings. Great.
So there must be other places where some invalid assumptions of being able to fetch |.messageOffset| property still exist.

diff -u /tmp/ttt.tests.{old,new}
--- /tmp/ttt.tests.old	2022-06-23 06:02:30.064502604 +0900
+++ /tmp/ttt.tests.new	2022-06-23 06:01:25.225475458 +0900
@@ -9,9 +9,4 @@
  comm/mailnews/imap/test/unit/test_imapFilterActionsPostplugin.js
  comm/mailnews/imap/test/unit/test_imapHighWater.js
  comm/mailnews/imap/test/unit/test_imapSearch.js
- comm/mailnews/imap/test/unit/test_imapUndo.js
- comm/mailnews/imap/test/unit/test_nsIMsgFolderListenerIMAP.js
- comm/mailnews/imap/test/unit/test_offlinePlayback.js
- comm/mailnews/imap/test/unit/test_preserveDataOnMove.js
- comm/mailnews/imap/test/unit/test_trustSpamAssassin.js
  comm/mailnews/news/test/unit/test_filter.js

Again, I tested above with |mach xpcshell-test --verbose --sequential| locally with DEBUG version of C-C TB with Ben's patch of late.

Some things I noticed.
test_filter.js is related to news server article search.
I see gloda related warnings in many places near .messageOffset warnings, especially
comm/mailnews/db/gloda/test/unit/test_index_junk_imap_online.js
comm/mailnews/db/gloda/test/unit/test_index_messages_imap_online_to_offline.js
but I am not sure if they are related to the warning we see here.
Otherwise, I don't see any prevailing patterns, so I am afraid that each test needs to be carefully analyzed. Oh well.

Comment 12

[Ben Campbell]

Oops - forgot to set the leave-open flag on this bug, so it auto-closed when the first patch landed!
Yes, I'm still working on it - currently got another patch (in nsImapMailFolder::SetPendingAttributes()) which clears a whole bunch of the remaining warnings... but causes another test to fail (mailnews/imap/test/unit/test_imapAttachmentSaves.js). So still debugging/tracing/printfing my way through it all...

Comment 13

[Ben Campbell]

Attachment: Bug 1774952 - Don't access .messageOffset for non-offline messages in nsImapMailFolder::SetPendingAttributes(). r=#thunderbird-reviewers

Comment 14

[Ben Campbell]

Attachment: Bug 1774952 - Remove redundant .messageOffset access in search code. r=#thunderbird-reviewers

Depends on D189901

Comment 15

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/comm-central/rev/bb232e64af21
Don't access .messageOffset for non-offline messages in nsImapMailFolder::SetPendingAttributes(). r=leftmostcat
https://hg.mozilla.org/comm-central/rev/ea2fd2a12013
Remove redundant .messageOffset access in search code. r=leftmostcat