Closed Bug 659478 Opened 13 years ago Closed 10 years ago

test_generate_static_docs_does_not_smoke failure on Windows

Categories

(Add-on SDK Graveyard :: General, defect, P1)

Product:
Add-on SDK Graveyard
Component:
General
Platform:
x86
Windows 7
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INVALID

People

(Reporter: warner, Unassigned)

References

Details

Attachments

(5 files)

output of cfx testall -v
250.56 KB, text/plain
Details
close files in generate_static_docs() instead of relying upon auto-close
3.35 KB, patch
myk
: review-
Details | Diff | Splinter Review
improve "Package not found" error to mention which package
721 bytes, patch
Details | Diff | Splinter Review
add diagnostic printfs
6.18 KB, patch
Details | Diff | Splinter Review
log w/shutil.rmtree() instrumentation patch applied
5.56 KB, text/plain
Details 
in bug 658964, alexp and myk noticed an occasional failure in the sdocs test. (this has occurred and been fixed before: bugzilla's "possible duplicates" list is telling me about bug 568165 and bug 635959. This test is just fragile, I guess).

It doesn't happen on my OS-X box at all, and I have reports from windows boxes on which it doesn't happen.

Here's alexp's traceback:

.................................................E.......................F......
..................................
======================================================================
ERROR: test_generate_static_docs_does_not_smoke (cuddlefish.tests.test_server.Se
rverTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\Users\Coup2Bambou\Desktop\mozilla\jetpack\python-lib\cuddlefish\tests
\test_server.py", line 13, in test_generate_static_docs_does_not_smoke
    server.generate_static_docs(env_root, tgz_filename=filename)
  File "C:\Users\Coup2Bambou\Desktop\mozilla\jetpack\python-lib\cuddlefish\serve
r.py", line 357, in generate_static_docs
    package_doc_html = web_docs.create_package_page(src_dir)
  File "C:\Users\Coup2Bambou\Desktop\mozilla\jetpack\python-lib\cuddlefish\webdo
cs.py", line 89, in create_package_page
    package_content = self._create_package_detail(package_name)
  File "C:\Users\Coup2Bambou\Desktop\mozilla\jetpack\python-lib\cuddlefish\webdo
cs.py", line 175, in _create_package_detail
    raise IOError(errno.ENOENT, 'Package not found')
IOError: [Errno 2] Package not found
And myk saw:

ERROR: test_create_example_doc (cuddlefish.tests.test_webdocs.WebDocTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\Users\myk\Projects\addon-sdk\python-lib\cuddlefish\tests\test_webdocs.py", line 87, in test_create_example_doc
    doc = web_docs.create_examples_page()
  File "c:\Users\myk\Projects\addon-sdk\python-lib\cuddlefish\webdocs.py", line 94, in create_examples_page
    examples_content = self._create_examples_listing(examples_dir)
  File "c:\Users\myk\Projects\addon-sdk\python-lib\cuddlefish\webdocs.py", line 195, in _create_examples_listing
    for dirname in os.listdir(examples_dir):
WindowsError: [Error 3] The system cannot find the path specified: 'c:\\Users\\myk\\Projects\\addon-sdk/python-lib/cuddlefish/tests/static-files\\examples/*.*'


and alexp also saw:

ERROR: test_generate_static_docs_does_not_smoke (cuddlefish.tests.test_server.Se
rverTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\Users\Coup2Bambou\Desktop\mozilla\jetpack\python-lib\cuddlefish\tests
\test_server.py", line 13, in test_generate_static_docs_does_not_smoke
    server.generate_static_docs(env_root, tgz_filename=filename)
  File "C:\Users\Coup2Bambou\Desktop\mozilla\jetpack\python-lib\cuddlefish\serve
r.py", line 424, in generate_static_docs
    shutil.rmtree(staging_dir)
  File "C:\Python27\lib\shutil.py", line 253, in rmtree
    onerror(os.rmdir, path, sys.exc_info())
  File "C:\Python27\lib\shutil.py", line 251, in rmtree
    os.rmdir(path)
WindowsError: [Error 145] Folder is not empty: 'C:\\Users\\Coup2Bambou\
\Desktop\\mozilla\\jetpack\\addon-sdk-docs'

Alexp, myk, can you both reproduce this with a fresh checkout of the SDK? I'm wondering if there's a leftover file in one of your directories that's confusing the docs generator. I'm not seeing either of these on my OS-X box, and I find it pretty weird that you aren't seeing each other's failure on your own boxes.
I ran "cfx testcfx" three times each on my usual clone (which is actually fairly new, since I recently changed computers) and a fresh one.  Both times, the third test run threw error 145:

Usual Checkout:

WindowsError: [Error 145] The directory is not empty: 'c:\\Users\\myk\\Projects\\addon-sdk\\addon-sdk-docs\\dev-guide\\addon-development'

Fresh Checkout:

WindowsError: [Error 145] The directory is not empty: 'c:\\Users\\myk\\addon-sdk\\addon-sdk-docs\\dev-guide'


I ran the tests about ten more times each on the two clones and saw two more such failures (both with my usual clone).
Hrm, so one of the problems (let's call it the rmtree() problem) feels like a
race condition, and that something is preventing the shutil.rmtree() from
succeeding.

I've seen reports that various windows tools like virus scanners and indexers
can randomly prevent files from being deleted by having the file open at the
exact moment some other program tries to delete it. The Tahoe-LAFS project
has some ancient code to work around this:

  https://github.com/warner/tahoe-lafs/blob/master/src/allmydata/util/fileutil.py

Another possibility is that some random program is dropping temporary files
into the temporary addon-sdk-docs/ directory in the middle of the rmtree(),
and manages to do it just after all the normal files were deleted from a
directory, but just before the directory itself was deleted. An unlikely
race, but possible.

myk: on a tree that has just failed with that "directory is not empty" error,
what are the contents of $SDK/addon-sdk-docs/ ? I'm expecting to see some
file, and a chain of parent directories down to it, but only the file is
important.

This doesn't explain the other two errors seen ("Package not found" and the
tests/static-files\\examples/*.* one).. still pondering those.
I was sent here from bug 647126 comment 41. Just to note that I am on Linux (Fedora 15 actually).
Whoa, on linux? *That*'s surprising.. that points to an entirely different sort of race. How frequently does it occur? And can you reproduce it by running just that one test file ("python python-lib/cuddlefish/tests/test_server.py") or that one test case ("python python-lib/cuddlefish/tests/test_server.py ServerTests.test_generate_static_docs_does_not_smoke") ?
(In reply to comment #5)
> Whoa, on linux? *That*'s surprising.. that points to an entirely different
> sort of race. How frequently does it occur? And can you reproduce it by
> running just that one test file ("python
> python-lib/cuddlefish/tests/test_server.py") or that one test case ("python
> python-lib/cuddlefish/tests/test_server.py
> ServerTests.test_generate_static_docs_does_not_smoke") ?

bradford:~ $ cd repos/jetpack/
bradford:jetpack (master) $ python python-lib/cuddlefish/tests/test_server.py 
E..........
======================================================================
ERROR: test_generate_static_docs_does_not_smoke (__main__.ServerTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "python-lib/cuddlefish/tests/test_server.py", line 13, in test_generate_static_docs_does_not_smoke
    server.generate_static_docs(env_root, tgz_filename=filename)
  File "/home/matej/repos/jetpack/python-lib/cuddlefish/server.py", line 357, in generate_static_docs
    package_doc_html = web_docs.create_package_page(src_dir)
  File "/home/matej/repos/jetpack/python-lib/cuddlefish/webdocs.py", line 89, in create_package_page
    package_content = self._create_package_detail(package_name)
  File "/home/matej/repos/jetpack/python-lib/cuddlefish/webdocs.py", line 175, in _create_package_detail
    raise IOError(errno.ENOENT, 'Package not found')
IOError: [Errno 2] Package not found

----------------------------------------------------------------------
Ran 11 tests in 0.854s

FAILED (errors=1)
bradford:jetpack (master) $ find . -name Server\*
bradford:jetpack (master) $ python python-lib/cuddlefish/tests/test_server.py ServerTests.test_generate_static_docs_does_not_smoke
bradford:jetpack (master) $ python python-lib/cuddlefish/tests/test_server.py ServerTests.test_generate_static_docs_does_not_smoke
E
======================================================================
ERROR: test_generate_static_docs_does_not_smoke (__main__.ServerTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "python-lib/cuddlefish/tests/test_server.py", line 13, in test_generate_static_docs_does_not_smoke
    server.generate_static_docs(env_root, tgz_filename=filename)
  File "/home/matej/repos/jetpack/python-lib/cuddlefish/server.py", line 357, in generate_static_docs
    package_doc_html = web_docs.create_package_page(src_dir)
  File "/home/matej/repos/jetpack/python-lib/cuddlefish/webdocs.py", line 89, in create_package_page
    package_content = self._create_package_detail(package_name)
  File "/home/matej/repos/jetpack/python-lib/cuddlefish/webdocs.py", line 175, in _create_package_detail
    raise IOError(errno.ENOENT, 'Package not found')
IOError: [Errno 2] Package not found

----------------------------------------------------------------------
Ran 1 test in 0.082s

FAILED (errors=1)
bradford:jetpack (master) $ git log|head -n 1
commit 98a413b540963aea871bbe3068b439bd11249079
bradford:jetpack (master) $ python -V
Python 2.7.1
bradford:jetpack (master) $
Just for the sake of completness ... log of complete tests.
Priority: -- → P1
Target Milestone: --- → 1.0
(In reply to comment #3)
> myk: on a tree that has just failed with that "directory is not empty" error,
> what are the contents of $SDK/addon-sdk-docs/ ? I'm expecting to see some
> file, and a chain of parent directories down to it, but only the file is
> important.

$ ls -R addon-sdk-docs
addon-sdk-docs:
packages  syntaxhighlighter

addon-sdk-docs/packages:
api-utils  development-mode  index.json  test-harness

addon-sdk-docs/packages/api-utils:

addon-sdk-docs/packages/development-mode:
README.md  development-mode.html  docs

addon-sdk-docs/packages/development-mode/docs:
bootstrap.html  bootstrap.md  bootstrap.md.div  bootstrap.md.json  main.html  main.md  main.md.div  main.md.json

addon-sdk-docs/packages/test-harness:
README.md  docs  test-harness.html

addon-sdk-docs/packages/test-harness/docs:
harness.html  harness.md  harness.md.div  harness.md.json  run-tests.html  run-tests.md  run-tests.md.div  run-tests.md.json

addon-sdk-docs/syntaxhighlighter:
MIT-LICENSE  scripts  styles

addon-sdk-docs/syntaxhighlighter/scripts:
shBrushCss.js  shBrushJScript.js  shBrushXml.js  shCore.js

addon-sdk-docs/syntaxhighlighter/styles:
shCore.css  shThemeDefault.css
This patch might help the unable-to-delete aspect of this bug.

generate_static_docs() has a lot of "open(filename).write(contents)" calls,
which is a nicely succinct way to create a small file. Python file objects
(as returned by open()) are automatically closed when the object is
destroyed, so it's common to not explicitly close them. However, object
destruction is not always immediate: if there's some internal reference cycle
that includes the filehandle, it may stick around until the next GC pass,
which could be an arbitrary time in the future. So this:

 open(filename).write(contents)
 shutil.rmtree(parentdir)

usually behaves like:

 f = open(filename)
 f.write(contents)
 f.close()
 shutil.rmtree(parentdir)

but could sometimes behave like this:

 f = open(filename)
 f.write(contents)
 shutil.rmtree(parentdir)
 f.close()

On unix, this rarely matters, because there can be plenty of open handles on
a given file, and they don't interfere with each other, or with other
operations on that file. But on windows, if anyone has an open handle on a
file, you'll get an error when you try to delete it.

So it's conceivable that the open/write/rmtree/close ordering could cause the
rmtree() to fail. It seems unlikely, because:

 1: shutil.rmtree()'s default behavior is to raise exceptions immediately, so
    I'd expect to see a cannot-delete-because-file-is-in-use OSError rather
    than the directory-is-not-empty error that we're seeing. (rmtree has a
    flag to ignore errors, but as far as I can tell we're not setting it)

 2: Python tends to be pretty good about destroying simply-referenced objects
    as soon as they go out of scope (which would be on the very same line, as
    soon as the write() call returns), so I'd be surprised if those
    filehandles were sticking around long enough to cause problems with
    rmtree().

But, it seems plausible, and the fix is easy (I replaced those open().write()
sequences with a separate function that explicitly closes the filehandle). So
it's worth a shot. If anyone has an environment in which the "Folder is not
empty" error is reproducible, please apply this patch and see if it goes
away.

I still don't understand the "Package not found" error, nor the
os.listdir(*.*) problem. Neither seems related to this specfic issue.
here's a patch to improve the "Package not found" error message, to mention exactly *which* package wasn't found. This should help us learn more about that one aspect of this bug.
I'm now looking at the "The system cannot find the path specified" error.
Have we ever seen this with a modern codebase? The "test_create_example_doc"
doesn't exist anywhere, the line numbers don't make sense, the
create_examples_page() function doesn't exist anywhere, and the "for dirname
in os.listdir" line isn't even in webdocs.py (it's in __init__.py, in the
test_examples code). Is anyone able to reproduce it?
Comment on attachment 536725 [details] [diff] [review]
close files in generate_static_docs() instead of relying upon auto-close

Without this patch, I got the "directory is not empty" error twice in 20 consecutive test runs.  With the patch, I got it once in the same number of runs.

That's a 50% drop in test failures!  But sadly not statistically significant.
Attachment #536725 - Flags: review-
here's a patch to instrument a copy of shutil.rmtree(), to find out what exactly it's complaining about.
Flagging for triage because the bug's been dead for almost three months, and it's targeted at the already-shipped SDK 1.0.

Myk/Mossop/dcm: You guys know anything about this? Did it land?
Whiteboard: [triage:followup]
Target Milestone: 1.0 → ---
A fix for this has not landed.  And it's still happening.  And not just in test_generate_static_docs_does_not_smoke:

--------------------------------------------------------------------------------
$ cfx testcfx
...............................E...........................................................................................
======================================================================
ERROR: test_strip (cuddlefish.tests.test_linker.Contents)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\Users\myk\Dropbox\addon-sdk-win\python-lib\cuddlefish\tests\test_linker.py", line 200, in test_strip
    self.run_in_subdir("x", _test)
  File "c:\Users\myk\Dropbox\addon-sdk-win\python-lib\cuddlefish\tests\test_linker.py", line 128, in run_in_subdir
    shutil.rmtree(basedir)
  File "c:\Python27\lib\shutil.py", line 253, in rmtree
    onerror(os.rmdir, path, sys.exc_info())
  File "c:\Python27\lib\shutil.py", line 251, in rmtree
    os.rmdir(path)
WindowsError: [Error 145] The directory is not empty: 'c:\\Users\\myk\\Dropbox\\addon-sdk-win\\.test_tmp\\cuddlefish.tests.test_linker.Contents.test_strip\\x'

----------------------------------------------------------------------
Ran 123 tests in 16.146s

FAILED (errors=1)
(addon-sdk-win)
myk@MYKPAD ~/Dropbox/addon-sdk-win (master)
$ cfx testcfx
.....................................................E.....................................................................
======================================================================
ERROR: test_generate_static_docs_does_not_smoke (cuddlefish.tests.test_server.ServerTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "c:\Users\myk\Dropbox\addon-sdk-win\python-lib\cuddlefish\tests\test_server.py", line 13, in test_generate_static_docs_does_not_smoke
    server.generate_static_docs(env_root, tgz_filename=filename)
  File "c:\Users\myk\Dropbox\addon-sdk-win\python-lib\cuddlefish\server.py", line 424, in generate_static_docs
    shutil.rmtree(staging_dir)
  File "c:\Python27\lib\shutil.py", line 244, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "c:\Python27\lib\shutil.py", line 244, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "c:\Python27\lib\shutil.py", line 244, in rmtree
    rmtree(fullname, ignore_errors, onerror)
  File "c:\Python27\lib\shutil.py", line 253, in rmtree
    onerror(os.rmdir, path, sys.exc_info())
  File "c:\Python27\lib\shutil.py", line 251, in rmtree
    os.rmdir(path)
WindowsError: [Error 145] The directory is not empty: 'c:\\Users\\myk\\Dropbox\\addon-sdk-win\\addon-sdk-docs\\packages\\development-mode\\docs'

----------------------------------------------------------------------
Ran 123 tests in 6.918s

FAILED (errors=1)
--------------------------------------------------------------------------------


I'll test with Brian's patch and post the output.
Removing the triage flag.

How goes the bug, though, Myk?
Whiteboard: [triage:followup]
(In reply to Wes Kocher (:KWierso) (Jetpack Bugmaster) from comment #17)
> Removing the triage flag.
> 
> How goes the bug, though, Myk?

That's more of a question for Brian!

Brian: can you take a look at the log in attachment 559602 [details] and see if it gives you any ideas about the source of this bug?
I am on OSX Snow Leopard and experiencing the same issue.
Here is the output when running "cfx docs"

Traceback (most recent call last):
  File "/Users/SaraJChipps/development/Tout/Firefox/addon-sdk-1.2.1/bin/cfx", line 29, in <module>
    cuddlefish.run()
  File "/Users/SaraJChipps/development/Tout/Firefox/addon-sdk-1.2.1/python-lib/cuddlefish/__init__.py", line 468, in run
    docs_home = generate.generate_docs(env_root)
  File "/Users/SaraJChipps/development/Tout/Firefox/addon-sdk-1.2.1/python-lib/cuddlefish/docs/generate.py", line 52, in generate_docs
    generate_docs_from_scratch(env_root, base_url, docs_dir)
  File "/Users/SaraJChipps/development/Tout/Firefox/addon-sdk-1.2.1/python-lib/cuddlefish/docs/generate.py", line 145, in generate_docs_from_scratch
    package_doc_html = web_docs.create_package_page(src_dir)
  File "/Users/SaraJChipps/development/Tout/Firefox/addon-sdk-1.2.1/python-lib/cuddlefish/docs/webdocs.py", line 94, in create_package_page
    package_content = self._create_package_detail(package_name)
  File "/Users/SaraJChipps/development/Tout/Firefox/addon-sdk-1.2.1/python-lib/cuddlefish/docs/webdocs.py", line 180, in _create_package_detail
    raise IOError(errno.ENOENT, 'Package not found')
IOError: [Errno 2] Package not found
I wonder if recent changes to the way we build docs might be causing this problem. cc:ing wbamberg.
So the way this bit of the code works:

1) generate.py uses 'packaging.build_pkg_cfg' to build 'pkg_cfg' which is a kind of model of all the packages:

https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/docs/generate.py#L126

2)...then it iterates through them by name:

https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/docs/generate.py#L132

3)...and passes each name into webdocs.create_package_page:

https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/docs/generate.py#L146

4)...webdocs.create_package_page passes that name through to _create_package_detail, which isn't able to find it in its "packages_json" attribute, and throws:

https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/docs/webdocs.py#L174

5)...webdocs.packages_json comes from a previous call to 'packaging.build_pkg_cfg', this time in webdocs' constructor:

https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/docs/webdocs.py#L69

So there are 2 calls to 'packaging.build_pkg_cfg', made at different times. 
(but note that webdocs then calls "packaging.build_pkg_index" to get a json representation of the packages, and it is this representation that it uses) 

So I can think of a couple of possible problems that would cause this. First, there's definitely a potential race in here, because the index generated in "packaging.build_pkg_cfg" need to match, and here they are generated at different times. The code would be more robust if generate.py passed in the index. Second, perhaps in the translation to json https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/docs/webdocs.py#L70, a package is getting removed for some reason (unfortunately I'm not at all familiar with the packaging module, but I can't see anything in there: https://github.com/mozilla/addon-sdk/blob/master/python-lib/cuddlefish/packaging.py#L355 to indicate a problem)?

I can't right now think of any other possibilities. If Sara's problem is permanent then it's probably not a race. Sara, do you have any extra directories under "packages" which might be confusing "build_pkg_index"? Do you see this occur with a clean unzip of the SDK? Would you be willing to help by getting some logs of the index structures, that I could compare?
Oh, also, I just remembered.

Bug 691795 would cause the behaviour you are seeing if you have a package under packages/ in which the name of the directory is not the name of the package (as specified by the "name" key in the package.json file). Unfortunately this will be the case if, for example, you've downloaded a third party package from Github and saved it there. That bug is fixed now, but the fix did not make it into 1.2.1.

If this is the case, could you try either:
- using the latest SDK build
- renaming the package so the directory name matches the package name
Blocks: 739030
nullified when bug 903032 landed..
Status: NEW → RESOLVED
Closed: 10 years ago
Resolution: --- → INVALID
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: