classification
Title: test_regexp() of test_compileall fails occassionally
Type: behavior Stage: resolved
Components: Tests Versions: Python 3.2, Python 3.3
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: Nosy List: eric.araujo, jcea, ncoghlan, python-dev, r.david.murray, skrah, thomas.holmes, vstinner
Priority: normal Keywords:

Created on 2011-04-19 08:12 by vstinner, last changed 2011-07-01 19:41 by r.david.murray. This issue is now closed.

Messages (25)
msg134019 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-04-19 08:12
Trace:
----------------------------------------------------------------------
[ 30/354] test_compileall
test test_compileall failed -- Traceback (most recent call last):
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_compileall.py", line 253, in test_regexp
    self.assertCompiled(self.initfn)
  File "/export/home/buildbot/32bits/3.x.cea-indiana-x86/build/Lib/test/test_compileall.py", line 149, in assertCompiled
    self.assertTrue(os.path.exists(imp.cache_from_source(fn)))
AssertionError: False is not true
----------------------------------------------------------------------
http://www.python.org/dev/buildbot/all/builders/x86%20OpenIndiana%203.x/builds/1097/steps/test/logs/stdio
msg134150 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-04-20 13:45
It failed also on "AMD64 FreeBSD 8.2 3.x" buildbot:
-----------------
test test_compileall failed -- Traceback (most recent call last):
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/test/test_compileall.py", line 253, in test_regexp
    self.assertCompiled(self.initfn)
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/test/test_compileall.py", line 149, in assertCompiled
    self.assertTrue(os.path.exists(imp.cache_from_source(fn)))
AssertionError: False is not true
-----------------
http://www.python.org/dev/buildbot/all/builders/AMD64%20FreeBSD%208.2%203.x/builds/102/steps/test/logs/stdio
msg134272 - (view) Author: Éric Araujo (eric.araujo) * (Python committer) Date: 2011-04-22 16:53
How do we debug this?  Does someone have access to a similar box to see whether the pyc files do get created and where?
msg134279 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-04-22 19:53
Given that it happens randomly I suspect a timing issue, but without having reviewed the code in question.  I'm not sure when I'll have time to look at this.
msg134895 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-04-30 23:49
The failing test is launching a subprocess to compile python code, waiting for the subprocess to exit, and then checking to see if the file was created.  So the timing issue would appear to be that the file created by the subprocess doesn't appear to exist to the main program even after the subprocess has exited.  Stefan, Jesus, do either of you know of anything about the file systems used on your buildbots that might give rise to this problem?  Is there some sort of file system sync call we need to make to make sure different processes have the same view of the file system?

However, if my theory is true I would expect that other tests in test_compileall would also fail randomly.  Does anyone know if it is always test_regexp?
msg134902 - (view) Author: Stefan Krah (skrah) * (Python committer) Date: 2011-05-01 08:39
R. David Murray <report@bugs.python.org> wrote:
> The failing test is launching a subprocess to compile python code, waiting
> for the subprocess to exit, and then checking to see if the file was
> created.  So the timing issue would appear to be that the file created by
> the subprocess doesn't appear to exist to the main program even after the
> subprocess has exited.  Stefan, Jesus, do either of you know of anything
> about the file systems used on your buildbots that might give rise to this
> problem?  Is there some sort of file system sync call we need to make to
> make sure different processes have the same view of the file system?

The FreeBSD bot has a UFS filesystem with no soft updates:

$ mount
/dev/ad0s1a on / (ufs, local)

If the main process waits for the subprocess to finish, I can't think of
a reason to do any kind of synchronization.
msg135016 - (view) Author: Jesús Cea Avión (jcea) * (Python committer) Date: 2011-05-03 03:26
Same here. I am using a standard ZFS configuration. If the child finish doing its job, the file should be there. Are we sure no errors happens in the child?.
msg135048 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-05-03 16:11
Running test_compileall with -F it failed on iteration 588 on my linux box.  So this isn't platform specific.  No idea why that particular test should be fragile, but I'll look in to it when I get some time if nobody beats me to it.
msg135114 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2011-05-04 11:09
A quick eyeball of the test doesn't reveal anything obvious:

- if the subprocess is failing, it is doing so in such a way that it is still returning a 0 error code and isn't writing anything to stdout (as those assertions are before the check that the expected compiled file exists)
- the invocation of script_helper looks sensible
- if the directory creation fails, it won't get as far as running the subprocess

To instrument this, I would suggest starting by adding an assertion message on the failing assertion that includes "fn". My guess is that with the random directory name in there, the regex is triggering on the directory name and hence excluding the __init__.py file as well.
msg135116 - (view) Author: Nick Coghlan (ncoghlan) * (Python committer) Date: 2011-05-04 11:14
Hmm, I probably should have revised the first half of my comment after I had the thought about "simple regex" + "random directory name" being potentially problematic. I don't think that theory really counts as obvious, though...
msg135198 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-05-05 13:34
Ah ah, this bug is funny :-) test_regexp doesn't fail because of a race condition or a file system issue, but because of the regex!

The regex "ba.*" is applied on the fullname, not only on the basename. If the temporary contains "ba", the test fails :-) Replace tempfile.mkdtemp() by tempfile.mkdtemp(prefix='bar') in CommandLineTests.setUp() to always reproduce this bug.
msg135217 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-05-05 16:19
New changeset 76bd26565cc7 by R David Murray in branch '3.2':
#11873: Improve test regex so random directory names don't cause test to fail
http://hg.python.org/cpython/rev/76bd26565cc7

New changeset 83e069281810 by R David Murray in branch 'default':
Merge: #11873: Improve test regex so random directory names don't cause test to fail
http://hg.python.org/cpython/rev/83e069281810
msg135218 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-05-05 16:20
I ran the patched version 2945 times without failure.
msg135219 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-05-05 16:23
+        self.assertRunOK('-q', '-x', 'ba[^\/]*$', self.pkgdir)

This regex matchs 'ba(...)\'. I think that you wanted to write r'[^\\/]'.
msg135223 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-05-05 16:53
You are right that I got the regex wrong (I'm bad at regexes), but in fact it is fine the way it is.  Since there's no r, the regex is actually "ba[^/]$", which is exactly what I meant.
msg135430 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-05-07 09:43
> You are right that I got the regex wrong (I'm bad at regexes), but
> in fact it is fine the way it is.  Since there's no r, the regex
> is actually "ba[^/]$", which is exactly what I meant.

What about Windows? tempfile.mkdtemp(prefix='bar') can generate ...\tmpxxbaxx\... Or compileall does first normalize the path?
msg135916 - (view) Author: Éric Araujo (eric.araujo) * (Python committer) Date: 2011-05-13 15:23
> You are right that I got the regex wrong (I'm bad at regexes), but in
> fact it is fine the way it is.  Since there's no r, the regex is
> actually "ba[^/]$", which is exactly what I meant.

I would edit the string to reflect your meaning, then, otherwise other people may think too that the r was forgotten.
msg138702 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-06-20 12:12
> What about Windows? tempfile.mkdtemp(prefix='bar') can generate
> ...\tmpxxbaxx\... Or compileall does first normalize the path?

@r.david.murray: You reopened the issue, but you didn't answer to this question. And, is there a bug in your regex or not?
msg138717 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-06-20 14:00
I reopened the issue because I don't know the answer to your question but suspect that it is an issue.  So it needs to be checked.  And the regex should be cleaned up regardless, for clarity's sake.
msg139491 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2011-06-30 15:13
> What about Windows? tempfile.mkdtemp(prefix='bar') can generate
> ...\tmpxxbaxx\...

AH! The test failed on "x86 XP-4 x86":

http://www.python.org/dev/buildbot/all/builders/x86%20XP-4%203.x/builds/4874/steps/test/logs/stdio

======================================================================
FAIL: test_regexp (test.test_compileall.CommandLineTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows\build\lib\test\test_compileall.py", line 253, in test_regexp
    self.assertCompiled(self.initfn)
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows\build\lib\test\test_compileall.py", line 149, in assertCompiled
    self.assertTrue(os.path.exists(imp.cache_from_source(fn)))
AssertionError: False is not true

@r.david.murray: would you like to fix the regex?
msg139585 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-07-01 15:54
New changeset f8ece8c93918 by R David Murray in branch '3.2':
#11873: fix test regex so it covers windows os.sep as well.
http://hg.python.org/cpython/rev/f8ece8c93918

New changeset e543c0ddec63 by R David Murray in branch 'default':
merge #11873: fix test regex so it covers windows os.sep as well.
http://hg.python.org/cpython/rev/e543c0ddec63
msg139586 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-07-01 15:55
Yeah, that's why I had reopened the issue...hopefully it is fixed now.
msg139589 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-07-01 17:21
I guess I'm just really bad at regexes.

http://www.python.org/dev/buildbot/all/builders/x86%20XP-4%203.x/builds/4885/steps/test/logs/stdio
msg139594 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2011-07-01 18:57
New changeset 6fdb1f000d36 by R David Murray in branch '3.2':
#11873: another try at fixing the regex, courtesy of Victor Stinner
http://hg.python.org/cpython/rev/6fdb1f000d36

New changeset 775356b583d1 by R David Murray in branch 'default':
merge #11873: another try at fixing the regex, courtesy of Victor Stinner
http://hg.python.org/cpython/rev/775356b583d1
msg139597 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2011-07-01 19:41
I'm going to be an optimist and close this again.
History
Date User Action Args
2011-07-01 19:41:41r.david.murraysetstatus: open -> closed

messages: + msg139597
2011-07-01 18:57:39python-devsetmessages: + msg139594
2011-07-01 17:21:47r.david.murraysetstatus: closed -> open

messages: + msg139589
2011-07-01 15:55:01r.david.murraysetstatus: open -> closed
resolution: fixed
messages: + msg139586
2011-07-01 15:54:04python-devsetmessages: + msg139585
2011-06-30 16:05:40thomas.holmessetnosy: + thomas.holmes
2011-06-30 15:13:24vstinnersetmessages: + msg139491
2011-06-20 14:00:57r.david.murraysetmessages: + msg138717
2011-06-20 12:12:53vstinnersetmessages: + msg138702
2011-06-18 17:54:20r.david.murraysetstatus: open
2011-05-13 15:44:00vstinnersetstatus: closed -> (no value)
resolution: fixed -> (no value)
2011-05-13 15:23:14eric.araujosetmessages: + msg135916
2011-05-07 09:43:45vstinnersetmessages: + msg135430
2011-05-05 16:53:41r.david.murraysetmessages: + msg135223
2011-05-05 16:23:12vstinnersetmessages: + msg135219
2011-05-05 16:20:27r.david.murraysetstatus: open -> closed
type: behavior
messages: + msg135218

resolution: fixed
stage: needs patch -> resolved
2011-05-05 16:19:10python-devsetnosy: + python-dev
messages: + msg135217
2011-05-05 13:34:58vstinnersetmessages: - msg135199
2011-05-05 13:34:41vstinnersetmessages: + msg135199
2011-05-05 13:34:12vstinnersetmessages: + msg135198
2011-05-04 11:14:31ncoghlansetmessages: + msg135116
2011-05-04 11:09:28ncoghlansetnosy: + ncoghlan
messages: + msg135114
2011-05-03 16:11:08r.david.murraysettitle: test_regexp() of test_compileall failure on "x86 OpenIndiana 3.x" -> test_regexp() of test_compileall fails occassionally
stage: needs patch
messages: + msg135048
versions: + Python 3.2
2011-05-03 03:26:02jceasetmessages: + msg135016
2011-05-01 08:39:07skrahsetmessages: + msg134902
2011-04-30 23:49:06r.david.murraysetnosy: + jcea, skrah
messages: + msg134895
2011-04-22 19:53:49r.david.murraysetmessages: + msg134279
2011-04-22 16:53:09eric.araujosetnosy: + eric.araujo
messages: + msg134272
2011-04-20 13:45:01vstinnersetmessages: + msg134150
2011-04-20 00:51:57r.david.murraysetnosy: + r.david.murray
2011-04-19 08:12:21vstinnercreate