799532 - Try to find the source of IOError when removing profile directory

Status: RESOLVED FIXED

(Testing :: XPCShell Harness, defect)

Description

[Gregory Szorc [:gps]]

Attachment: Dump directory listing on profile removal failure, v1

+++ This bug was initially created as a clone of Bug #793855 +++

I'm getting sick of these IOError's and want to try to find the problem. This patch dumps an |ls -a| like output for the profile directory if we get an IOError when deleting it. It will probably need some refining once we uncover what's actually happening, but it's a start.

Yes, I known the redundant lookups to getpwuid and friends are wasteful. This isn't critical path code: I'm not worried about perf.

Sample output (with mach prepending times):

14.13 TEST-INFO | (xpcshell/head.js) | No (+ 0) checks actually run
14.13 <<<<<<<
14.13 >>>>>>>
14.13 Traceback (most recent call last):
14.13   File "/Users/gps/src/mozilla-central-hg/testing/xpcshell/runxpcshelltests.py", line 896, in runTests
14.14     self.removeDir(self.profileDir)
14.14   File "/Users/gps/src/mozilla-central-hg/testing/xpcshell/runxpcshelltests.py", line 339, in removeDir
14.14     shutil.rmtree(dirname)
14.14   File "/usr/local/Cellar/python/2.7.3/lib/python2.7/shutil.py", line 245, in rmtree
14.14     rmtree(fullname, ignore_errors, onerror)
14.14   File "/usr/local/Cellar/python/2.7.3/lib/python2.7/shutil.py", line 250, in rmtree
14.14     onerror(os.remove, fullname, sys.exc_info())
14.14   File "/usr/local/Cellar/python/2.7.3/lib/python2.7/shutil.py", line 248, in rmtree
14.14     os.remove(fullname)
14.14 OSError: [Errno 13] Permission denied: '/var/folders/sz/9xx9hkm53_q6sgt3k50nwffc0000gn/T/tmpBwWvtS/startupCache/startupCache.8.little'
14.14 <<<<<<<
14.14 >>>>>>>
14.14 Files in profile directory:
14.14 <<<<<<<
14.14 40700 gps staff /var/folders/sz/9xx9hkm53_q6sgt3k50nwffc0000gn/T/tmpBwWvtS/
14.14 40755 root wheel /var/folders/sz/9xx9hkm53_q6sgt3k50nwffc0000gn/T/tmpBwWvtS/startupCache/
14.14 100644 gps staff /var/folders/sz/9xx9hkm53_q6sgt3k50nwffc0000gn/T/tmpBwWvtS/startupCache/startupCache.8.little

Comment 1

[Gregory Szorc [:gps]]

Let's get some samples...

https://tbpl.mozilla.org/?tree=Try&rev=a655451be5ee
https://tbpl.mozilla.org/?tree=Try&rev=2443aa1470ba
https://tbpl.mozilla.org/?tree=Try&rev=5098e19054d6
https://tbpl.mozilla.org/?tree=Try&rev=56bcd0da18c0

Comment 2

[Gregory Szorc [:gps]]

Finally got a Try build to repro!

From https://tbpl.mozilla.org/php/getParsedLog.php?id=16184085&tree=Try&full=1:

Traceback (most recent call last):
  File "xpcshell/runxpcshelltests.py", line 895, in runTests
    self.removeDir(self.profileDir)
  File "xpcshell/runxpcshelltests.py", line 339, in removeDir
    shutil.rmtree(dirname)
  File "/home/cltbld/lib/python2.5/shutil.py", line 175, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "/home/cltbld/lib/python2.5/shutil.py", line 167, in rmtree
    onerror(os.listdir, path, sys.exc_info())
  File "/home/cltbld/lib/python2.5/shutil.py", line 165, in rmtree
    names = os.listdir(path)
OSError: [Errno 13] Permission denied: '/tmp/tmpktTCyH/Cache.Trash949609424'
<<<<<<<
Files in profile directory:
40700 cltbld cltbld /tmp/tmpktTCyH/
100664 cltbld cltbld /tmp/tmpktTCyH/runxpcshelltests_leaks.log
100600 cltbld cltbld /tmp/tmpktTCyH/secmod.db
100600 cltbld cltbld /tmp/tmpktTCyH/key3.db
100600 cltbld cltbld /tmp/tmpktTCyH/cert8.db
100600 cltbld cltbld /tmp/tmpktTCyH/_CACHE_CLEAN_
OS Error while performing os.walk!
Traceback (most recent call last):
  File "/home/cltbld/lib/python2.5/os.py", line 286, in walk
    names = listdir(top)
OSError: [Errno 13] Permission denied: '/tmp/tmpktTCyH/Cache.Trash949609424'

40775 cltbld cltbld /tmp/tmpktTCyH/Cache/
100600 cltbld cltbld /tmp/tmpktTCyH/Cache/_CACHE_001_
100600 cltbld cltbld /tmp/tmpktTCyH/Cache/_CACHE_MAP_
100600 cltbld cltbld /tmp/tmpktTCyH/Cache/_CACHE_002_
100600 cltbld cltbld /tmp/tmpktTCyH/Cache/_CACHE_003_
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/D/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/3/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/1/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/7/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/0/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/5/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/B/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/2/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/A/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/6/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/E/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/C/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/F/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/4/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/9/
40700 cltbld cltbld /tmp/tmpktTCyH/Cache/8/
40755 cltbld cltbld /tmp/tmpktTCyH/webapps/
100644 cltbld cltbld /tmp/tmpktTCyH/webapps/webapps.json

So, what is "Cache.Trash949609424"?

Comment 3

[Gregory Szorc [:gps]]

Perhaps some Necko folk can explain where "Cache.Trash949609424" comes from.

Comment 4

[(not currently active) Ted Mielczarek]

Comment on attachment 669577 [details] [diff] [review]
Dump directory listing on profile removal failure, v1

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

r=me since this is just diagnostic code and we'll remove it eventually.

Comment 5

[Gregory Szorc [:gps]]

Digging through source code, it appears the Necko cache has a "trash compartment." It appears that old cache directories get renamed to Cache.Trash<random> and are then deleted on a background thread after some delay. Makes sense.

I suspect that permissions are getting "corrupted" as part of the move. From nsDeleteDir.cpp:

    // Important: must rename directory w/o changing parent directory: else on
    // NTFS we'll wait (with cache lock) while nsIFile's ACL reset walks file
    // tree: was hanging GUI for *minutes* on large cache dirs.
    rv = dir->MoveToNative(nullptr, leaf);

dir is just an nsIFile. I suspect we are running into some kind of race condition where the OS or filesystem is attempting to "reparent" directory entries in the directory as part of the move and we try to delete the directory before this has finished. But, that's just speculation.

Comment 6

[Gregory Szorc [:gps]]

https://hg.mozilla.org/integration/mozilla-inbound/rev/9fcf07b50922

Comment 7

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/9fcf07b50922

Comment 8

[Jason Duell]

> I suspect we are running into some kind of race condition where the OS or
> filesystem is attempting to "reparent" directory entries in the directory as
> part of the move and we try to delete the directory before this has finished

I'm not much of an expert on NTFS, but AFAIK that shouldn't be happening:  when nsDeleteDir renames the file we pass null for the parent directory, which winds up resolving to "skipNtfsAclReset" here: 

  http://mxr.mozilla.org/mozilla-central/source/xpcom/io/nsLocalFileWin.cpp#1862

But perhaps there's some race condition even without doing the ACL resets.  The diagnostic output will hopefully give us a clue.

Comment 9

[Gregory Szorc [:gps]]

So, what's the easiest way for me to enable diagnostic output on try builds?