Closed Bug 1384461 Opened 3 years ago Closed 3 years ago

C-C TB: Unreliable test: mailnews/jsaccount/test/unit/test_jaMsgFolder.js (it repeats pass/fail/pass/fail if executed individually)

Categories

(Thunderbird :: General, defect)

defect
Not set

Tracking

(Not tracked)

RESOLVED FIXED
Thunderbird 57.0

People

(Reporter: ishikawa, Assigned: ishikawa)

References

(Blocks 1 open bug)

Details

Attachments

(2 files, 1 obsolete file)

(This was found while investigating the test failure caused by a patch in
Bug 1307085 - C-C TB: Tigher checking of InitWithFile and friends )

C-C TB
xpcshell test  mailnews/jsaccount/test/unit/test_jaMsgFolder.js is buggy in the sense that when it is individually executed repeatedly its results are like this:
pass
fail
pass
fail
pass 
fail
...

That is, its result alternates between pass and fail.

The relevant log from the success case:
mach xpcshell-test $*
+ mach xpcshell-test mailnews/jsaccount/test/unit/test_jaMsgFolder.js
Elapsed: 1.57s; From _tests: Kept 30394 existing; Added/updated 0; Removed 0 files and 0 directories.
 0:00.07 LOG: MainThread WARNING MOZ_NODE_PATH environment variable not set. Tests requiring http/2 will fail.
 0:00.30 LOG: MainThread INFO Running tests sequentially.
 0:00.30 SUITE_START: MainThread 1
 0:00.30 LOG: Thread-1 INFO profile dir is /tmp/firefox/xpcshellprofile
 0:00.30 TEST_START: Thread-1 mailnews/jsaccount/test/unit/test_jaMsgFolder.js
 0:00.75 TEST_END: Thread-1 PASS
 0:00.75 LOG: MainThread INFO INFO | Result summary:
 0:00.75 LOG: MainThread INFO INFO | Passed: 1
 0:00.75 LOG: MainThread INFO INFO | Failed: 0
 0:00.75 LOG: MainThread INFO INFO | Todo: 0
 0:00.75 LOG: MainThread INFO INFO | Retried: 0
 0:00.75 SUITE_END: MainThread 
Summary
=======

Ran 1 tests
Expected results: 1
Unexpected results: 0

OK

I attach a relevant log from the failure case.

My patch in bug 1307085 does a tighter check on low-level file I/O error issues and thus seems to fail this particular xpcshell test ALWAYS instead of failing it every two trials.

From the patch in Bug 1307085 (and putting some additional printf statements), I know that during a test a strange directory is created WITHOUT X bit under linux, meaning that the directory cannot be searched (its directory entries can't be read, I think.) That certainly caused the tight check in my patch in bug 1307085 to fail this test, but it does NOT explain why test_jaMsgFolder.js succeeds and fails alternatively withtout the patch in bug 1307085. It seems that the test relies on a certain environmental factor that is not properly managed/initialized  by the test harness and test itself.

The strange directory created by the test:

ls -l /tmp/firefox/xpcshellprofile/TestFoo
ls: cannot access /tmp/firefox/xpcshellprofile/TestFoo/.: Permission denied
ls: cannot access /tmp/firefox/xpcshellprofile/TestFoo/..: Permission denied
total 0
d????????? ? ? ? ?            ? ./
d????????? ? ? ? ?            ? ../
ishikawa@debian-hp-note:/home/ishikawa/TB-SRC/comm-central$ ls -l /tmp/firefox/xpcshellprofile        
total 88
drwxr-xr-x 5 ishikawa ishikawa  4096 Jul 26 16:44 ./
drwxr-xr-x 3 ishikawa ishikawa  4096 Jul 26 16:44 ../
drw------- 2 ishikawa ishikawa  4096 Jul 26 16:44 TestFoo/ <- No X bit
drwx------ 4 ishikawa ishikawa  4096 Jul 26 16:44 cache2/
-rw------- 1 ishikawa ishikawa 65536 Jul 26 16:44 cert8.db
-rw------- 1 ishikawa ishikawa 16384 Jul 26 16:44 key3.db
-rw-r--r-- 1 ishikawa ishikawa   821 Jul 26 16:44 mozinfo.json
-rw-r--r-- 1 ishikawa ishikawa   160 Jul 26 16:44 panacea.dat
-rw------- 1 ishikawa ishikawa 16384 Jul 26 16:44 secmod.db
drwxr-xr-x 2 ishikawa ishikawa  4096 Jul 26 16:44 startupCache/

As I said the patch in 1307085 performs very tight I/O error checking and thus
causes TB to fail this test always because of non-searchable directory: so we have an underlying I/O error issue.
However, it does not explain the alternative nature of success/fail when this particular issue is ignored in the un-patched source tree. Something in the environment is flipped at each invocation of the test, and the next test is affected by this change.
But I don't know what the change is.


I will put the following bug as related since the file in question seems to have been created as part of the following bugzilla:
Bug 430716 - Develop a scriptable, plug-able protocol layer sample (Experimental)

TIA
I found something disturbing under linux.

Trying to find what is causing this strange permission bit, I called the test under strace -ff and see where mkdir is called, etc.

A good news and a bad news.

Good news is that I find that TB calls mkdir with 0600 mode parameter
under linux (don't know about OSX and Windows): This explains why we
have this TestFoo directory without 'X' permission (at least under linux where I test locally).  I can probably
pursue where this call is invoked done to fix this issue.

grep mkdir /tmp/t.bad* /tmp/t.good* | grep TestFoo
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo", 0600) = 0 <=== Suspect
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo", 0755) = -1 EEXIST (File exists)
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.bad.19874:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo", 0600) = 0  <=== Suspect 
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo", 0755) = -1 EEXIST (File exists)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)
/tmp/t.good.19985:mkdir("/tmp/firefox/xpcshellprofile/TestFoo/foohost", 0755) = -1 EACCES (Permission denied)

Bad news is there are strange |chmod| calls.
TB calls chmod with a very strange second mode parameter.
I marked such calls with "*" at the beginning of the line in the dump below.

There are lines such as
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/startupCache", 040755) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/TestFoo", 040700) = 0

Note the 040xxx values. From what I understand there ought to be only 4 octets (excluding the leading 0) 
in this |mode| parameter.
It looks to me that functions screw up the call to chmod and instead of 
simply ORing the values of the following, it does strange shift?
Or maybe the constant definition is wrong somewhere?

       S_ISUID  (04000)  set-user-ID   (set   process  effective  user  ID  on
                         execve(2))
       S_ISGID  (02000)  set-group-ID  (set  process  effective  group  ID  on
                         execve(2);   mandatory   locking,   as  described  in
                         fcntl(2); take a new file's group from parent  direc-
                         tory, as described in chown(2) and mkdir(2))
       S_ISVTX  (01000)  sticky bit (restricted deletion flag, as described in
                         unlink(2))

040700 ought to be either 04700, 02700, or 01700.


fgrep "chmod(" /tmp/t.bad* /tmp/t.good*
/tmp/t.bad.19794:chmod("/NREF-COMM-CENTRAL/comm-central/hg-checkexec-DQD910", 0711) = 0
/tmp/t.bad.19795:fchmod(3, 02700)                        = 0
/tmp/t.bad.19795:fchmod(3, 02700)                        = 0
/tmp/t.bad.19795:fchmod(3, 02700)                        = 0
/tmp/t.bad.19798:chmod("/NREF-COMM-CENTRAL/comm-central/hg-checkexec-9ITWfJ", 0711) = 0
/tmp/t.bad.19799:fchmod(3, 02700)                        = 0
/tmp/t.bad.19799:fchmod(3, 02700)                        = 0
/tmp/t.bad.19799:fchmod(3, 02700)                        = 0
/tmp/t.bad.19803:chmod("/NREF-COMM-CENTRAL/comm-central/mozilla/hg-checkexec-IUvITj", 0711) = 0
/tmp/t.bad.19804:fchmod(3, 02700)                        = 0
/tmp/t.bad.19804:fchmod(3, 02700)                        = 0
/tmp/t.bad.19804:fchmod(3, 02700)                        = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile", 040755) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/startupCache", 040755) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/TestFoo", 040700) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/cache2", 040700) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/key3.db", 0100600) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/cert8.db", 0100600) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/mozinfo.json", 0100644) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/secmod.db", 0100600) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/panacea.dat", 0100644) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/startupCache/startupCache.8.little", 0100644) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/cache2/entries", 040700) = 0
*/tmp/t.bad.19872:chmod("/tmp/firefox/xpcshellprofile/cache2/doomed", 040700) = 0
/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnptest.so", 0755) = 0
/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnptestjava.so", 0755) = 0
/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnpthirdtest.so", 0755) = 0
/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnpsecondtest.so", 0755) = 0
/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnpswftest.so", 0755) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-other-3kdU5T", 040700) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k", 040700) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnptest.so", 0100755) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnptestjava.so", 0100755) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnpthirdtest.so", 0100755) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnpsecondtest.so", 0100755) = 0
*/tmp/t.bad.19872:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-b0xp2k/libnpswftest.so", 0100755) = 0
/tmp/t.good.19907:chmod("/NREF-COMM-CENTRAL/comm-central/hg-checkexec-vOFPT7", 0711) = 0
/tmp/t.good.19908:fchmod(3, 02700)                        = 0
/tmp/t.good.19908:fchmod(3, 02700)                        = 0
/tmp/t.good.19908:fchmod(3, 02700)                        = 0
/tmp/t.good.19911:chmod("/NREF-COMM-CENTRAL/comm-central/hg-checkexec-1nkxfl", 0711) = 0
/tmp/t.good.19912:fchmod(3, 02700)                        = 0
/tmp/t.good.19912:fchmod(3, 02700)                        = 0
/tmp/t.good.19912:fchmod(3, 02700)                        = 0
/tmp/t.good.19916:chmod("/NREF-COMM-CENTRAL/comm-central/mozilla/hg-checkexec-yWVl21", 0711) = 0
/tmp/t.good.19917:fchmod(3, 02700)                        = 0
/tmp/t.good.19917:fchmod(3, 02700)                        = 0
/tmp/t.good.19917:fchmod(3, 02700)                        = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile", 040755) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/startupCache", 040755) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/TestFoo", 040700) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/cache2", 040700) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/key3.db", 0100600) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/cert8.db", 0100600) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/mozinfo.json", 0100644) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/secmod.db", 0100600) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/panacea.dat", 0100644) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/startupCache/startupCache.8.little", 0100644) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/cache2/entries", 040700) = 0
*/tmp/t.good.19983:chmod("/tmp/firefox/xpcshellprofile/cache2/doomed", 040700) = 0
/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnptest.so", 0755) = 0
/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnptestjava.so", 0755) = 0
/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnpthirdtest.so", 0755) = 0
/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnpsecondtest.so", 0755) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnpswftest.so", 0755) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-other-qjT1eB", 040700) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ", 040700) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnptest.so", 0100755) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnptestjava.so", 0100755) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnpthirdtest.so", 0100755) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnpsecondtest.so", 0100755) = 0
*/tmp/t.good.19983:chmod("/NREF-COMM-CENTRAL/objdir-tb3/temp/xpc-plugins-Ro5AAZ/libnpswftest.so", 0100755) = 0

I will dig more.
Component: Untriaged → General
I found a couple of problems on the particular issue of |mkdir| being called without owner X-bit.

The test mailnews/jsaccount/test/unit/test_jaMsgFolder.js itself calls directory creation routine withtout X-bit for the owner. I am uplading patch for this.

However, that is not enough. There is a routine under M-C tree under ./mozilla subdirectory, which also calls directory creation routine without owner X-bit (and in that case we seem to need group/other X-bits as well.).
I have filed a bugzilla about it. 

Bug 1385816 - nsFileStreamBase::DoOpen() should call directory creation with 0755 permission instead of 0644.

With the patch in bug 1385816, and this patch here, I no longer see the failure (and strange flip flop of pass/fail/pass/fail/...) of  mailnews/jsaccount/test/unit/test_jaMsgFolder.js.

I took the liberty of assigning rkent for this since he created the original test program as part of Bug 430716 - Develop a scriptable, plug-able protocol layer sample (Experimental)

TIA
Assignee: nobody → ishikawa
Attachment #8891943 - Flags: review?(rkent)
Comment on attachment 8891943 [details] [diff] [review]
Use correct permission with X-bit for directory creation.

Review of attachment 8891943 [details] [diff] [review]:
-----------------------------------------------------------------

Yep, that's the right permission. r+=me
Attachment #8891943 - Flags: review?(rkent) → review+
Thank you for the review.
I will recreate the patch with proper description line with r=rkent, and
upload it.

(I guess I have to file a bugzilla regarding |chmod()| call with strange argument value.)

TIA
Updated patch.

Strange. Somehow, with Firefox 54.0.1 (32-bit), I cannot list content of 
".hg" directory when a file chooser appears for selecting the file to be uploaded.

So I copy & pasted the patch.
I hope that won't cause a problem.

I am putting in check-needed keyword.
Attachment #8891943 - Attachment is obsolete: true
Attachment #8894803 - Flags: review+
Pushed by mozilla@jorgk.com:
https://hg.mozilla.org/comm-central/rev/24b7d9867639
use correct permission with X-bit for directory creation. r=rkent
Status: NEW → RESOLVED
Closed: 3 years ago
Keywords: checkin-needed
Resolution: --- → FIXED
Target Milestone: --- → Thunderbird 57.0
You need to log in before you can comment on or make changes to this bug.