http://www.python.org/dev/buildbot/all/builders/AMD64%20FreeBSD%208.2%203.x/builds/1845/steps/test/logs/stdio

======================================================================
FAIL: test_package___file__ (test.test_imp.PEP3147Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/usr/home/buildbot/buildarea/3.x.krah-freebsd/build/Lib/test/test_imp.py", line 333, in test_package___file__
    os.sep.join(('.', 'pep3147', '__init__.py')))
AssertionError: 'pep3147/__init__.py' != './pep3147/__init__.py'
- pep3147/__init__.py
+ ./pep3147/__init__.py
? ++

Updated build URL (the buildbot changed name):
http://www.python.org/dev/buildbot/all/builders/AMD64%20FreeBSD%209.0%203.x/builds/1845/steps/test/logs/stdio

I think the test is bogus. It would do better to either use str.endswith() or splitting off the various parts of __file__ to verify the filename is correct as is the directory. Otherwise it shouldn't matter if the directory is relative or absolute.

> Otherwise it shouldn't matter if the directory is relative or absolute.

That's not really the issue here, both are relative.
I am still baffled at that failure, I don't see why "" would be chosen over "." (which is inserted at the beginning of sys.path by the test).

Well, if you execute test_imp w/ importlib (-m importlib.test.regrtest test_imp) it still passes. So there is something very odd going on that probably relies on some other test doing something weird. And this might be hard to diagnose until the error triggers again to show the error arguments that are in the file now (the traceback below doesn't match what is in the default branch ATM).

OK, on FreeBSD the failure occurs reliably when test_sqlite and
test_imp are chained, perhaps because of the import failure
of sqlite3:

[stefan@freebsd-amd64 ~/hg/cpython]$ ./python -m test -uall test_sqlite test_imp
[1/2] test_sqlite
test_sqlite skipped -- No module named '_sqlite3'
[2/2] test_imp
test test_imp failed -- Traceback (most recent call last):
  File "/usr/home/stefan/hg/cpython/Lib/test/test_imp.py", line 330, in test_package___file__
    self.assertEqual(m.__file__, expected___file__, (m.__file__, m.__path__))
AssertionError: 'pep3147/__init__.py' != './pep3147/__init__.py'
- pep3147/__init__.py
+ ./pep3147/__init__.py
? ++
 : ('pep3147/__init__.py', ['pep3147'])

1 test failed:
    test_imp
1 test skipped:
    test_sqlite
Those skips are all expected on freebsd9.
[109902 refs]


On Linux I cannot reproduce it under the same conditions:

$ ./python -m test -uall test_sqlite test_imp
[1/2] test_sqlite
test_sqlite skipped -- No module named _sqlite3
[2/2] test_imp
1 test OK.
1 test skipped:
    test_sqlite
Those skips are all expected on linux2.
[94195 refs]

> OK, on FreeBSD the failure occurs reliably when test_sqlite and
> test_imp are chained, perhaps because of the import failure
> of sqlite3:

Mmh, funny, I can't trigger it here. Is there anything special in your
sys.path?

No, this is sys.path after sys.path.insert(0, os.curdir):

['.', '', '/usr/local/lib/python33.zip', '/usr/home/stefan/hg/cpython/Lib', '/usr/home/stefan/hg/cpython/Lib/plat-freebsd9', '/usr/home/stefan/hg/cpython/build/lib.freebsd-9.0-RELEASE-amd64-3.3-pydebug']


It is also possible to trigger the failure by adding this to the top of 
test_imp.py:

try:
    importlib.import_module("_sqlite3")
except ImportError:
    pass


Then it's sufficient to run only test_imp (and not test_sqlite).

I can confirm the failure when an import fails prior to running test_imp (i.e. trying importing some non-existent module like Stefan did at the top of test_imp). Luckily importlib doesn't fail in this case. =)

> I can confirm the failure when an import fails prior to running
> test_imp (i.e. trying importing some non-existent module like Stefan
> did at the top of test_imp). Luckily importlib doesn't fail in this
> case. =)

I can't reproduce :( Can either of you two try to debut it?

I'd rather get importlib working fast enough that you are okay with bootstrapping it so we can delete the offending code. =)

Here's a minimal test case for now. It only fails if called as -m test:


$ ./python Lib/test/test_dot.py          # OK 


$ ./python Lib/test/regrtest.py test_dot # OK
[1/1] test_dot
Warning -- sys.path was modified by test_dot


$ ./python -m test test_dot
[1/1] test_dot
Warning -- sys.path was modified by test_dot
test test_dot crashed -- Traceback (most recent call last):
  File "/home/stefan/pydev/cpython/Lib/test/regrtest.py", line 1214, in runtest_inner
    the_package = __import__(abstest, globals(), locals(), [])
  File "/home/stefan/pydev/cpython/Lib/test/test_dot.py", line 20, in <module>
    assert m.__file__ == expected___file__
AssertionError

1 test failed:
    test_dot

Antoine, what is your gcc version? The test case I posted fails
with Debian/gcc-4.3.2 and Ubuntu/gcc-4.4.3. The two affected
buildbots have gcc-4.2.x.

But the test case passes on Fedora/gcc-4.6.

> Antoine, what is your gcc version? The test case I posted fails
> with Debian/gcc-4.3.2 and Ubuntu/gcc-4.4.3. The two affected
> buildbots have gcc-4.2.x.

Mageia/gcc-4.5.2 here. It also passes with Debian/gcc-4.4.5.

I've trouble debugging this: Is the new version of importlib already
being used? I'm stepping through the offending pep3147 import, which
should correspond to this line in test_dot.py:

   m = __import__('pep3147')
   

Until here Python/import.c is used:

find_module_path (fullname='pep3147', name='pep3147', path='.', path_hooks=[<type at remote 0x843020>], 
    path_importer_cache=
    {'/home/stefan/pydev/cpython-imp/Lib/collections': None, '': None, '/home/stefan/pydev/cpython-imp/Lib/unittest': None, '/home/stefan/pydev/cpython-imp/Lib/multiprocessing': None, '/usr/local/lib/python3.3/site-packages/setuptools-0.6c11-py3.3.egg-info': <imp.NullImporter at remote 0x7ffff7f6f0b0>, '/home/stefan/pydev/cpython-imp/Lib/importlib': None, '/home/stefan/pydev/cpython-imp/Lib/plat-linux': <_FileFinder(_cache_refresh=0, _path_cache={'TYPES.py', 'regen', 'DLFCN.py', 'IN.py', 'CDROM.py'}, path='/home/stefan/pydev/cpython-imp/Lib/plat-linux', _path_mtime=<float at remote 0xa6a838>, modules=[('.cpython-33m.so', <type at remote 0xab5450>), ('.abi3.so', <type at remote 0xab5450>), ('.so', <type at remote 0xab5450>), ('.py', <type at remote 0xab4a40>), ('.pyc', <type at remote 0xab4dc0>)], packages=[('.py', <type at remote 0xab4a40>), ('.pyc', <type at remote 0xab4dc0>)], _relaxed_path_cache={'types.py', 'regen', 'dlfcn.py', 'in.py', 'cdrom.py'}) at remote 0x7ffff37d8b50>, '.': <_FileFinder(_cache_refresh=...(truncated), p_path=0x7fffffff7f80, 
    p_loader=0x7fffffff80b8, p_fd=0x7fffffff7f98) at Python/import.c:1811
1811            if (importer == NULL) {
(gdb) n
1816            if (importer != Py_None) {
(gdb) n
1818                loader = _PyObject_CallMethodId(importer,



After descending further and further into the eval loop, all
of a sudden this appears:


3426        retval = PyEval_EvalFrameEx(f,0);
(gdb) s
PyEval_EvalFrameEx (f=
    Frame 0xafec40, for file /home/stefan/pydev/cpython-imp/Lib/importlib/_bootstrap.py, line 773, in find_module (self=<_FileFinder(_cache_refresh=0, _path_cache=set(), path='.', _path_mtime=<float at remote 0xa6a8b0>, modules=[('.cpython-33m.so', <type at remote 0xab5450>), ('.abi3.so', <type at remote 0xab5450>), ('.so', <type at remote 0xab5450>), ('.py', <type at remote 0xab4a40>), ('.pyc', <type at remote 0xab4dc0>)], packages=[('.py', <type at remote 0xab4a40>), ('.pyc', <type at remote 0xab4dc0>)], _relaxed_path_cache=set()) at remote 0x7ffff4128390>, fullname='pep3147'), 
    throwflag=0) at Python/ceval.c:808


Is this expected?

> Is this expected?

Looks rather strange to me, it means we have importlib importers on
sys.path_importer_cache. Still, the fact that path == '.' above (in
_FileFinder as well as find_module_path) makes it difficult to
understand the later failure.

OK, I stepped in parallel through the non-failing and the failing
versions. The first divergence is when _path_mtime is compared.
The comparison in the good version returns 'False', the one in the
bad version returns 'True':

Good version (Fedora 16):

(gdb) p w
$148 = '_path_mtime'
(gdb) n
2278                x = PyObject_GetAttr(v, w);
(gdb) p v
$149 = 
    <_FileFinder(_relaxed_path_cache=set(), path='.', packages=[('.py', <type at remote 0xab4bc0>), ('.pyc', <type at remote 0xab4f40>)], _path_cache=set(), _cache_refresh=0, _path_mtime=<float at remote 0xa6a7d0>, modules=[('.cpython-33m.so', <type at remote 0xab55d0>), ('.abi3.so', <type at remote 0xab55d0>), ('.so', <type at remote 0xab55d0>), ('.py', <type at remote 0xab4bc0>), ('.pyc', <type at remote 0xab4f40>)]) at remote 0x7ffff4128310>
(gdb) n
2279                Py_DECREF(v);
(gdb) p x
$150 = <float at remote 0xa6a7d0>
(gdb) n
2280                SET_TOP(x);
(gdb) n
2281                if (x != NULL) DISPATCH();
(gdb) n
2284            TARGET(COMPARE_OP)
(gdb) n
2285                w = POP();
(gdb) n
2286                v = TOP();
(gdb) n
2287                x = cmp_outcome(oparg, v, w);
(gdb) n
2288                Py_DECREF(v);
(gdb) p w
$151 = <float at remote 0xa6a7d0>
(gdb) p v
$152 = <float at remote 0xa6a6f8>
(gdb) p x
$153 = False
(gdb) 


Bad version (Ubuntu):

(gdb) p w
$154 = '_path_mtime'
(gdb) p v
$155 = <float at remote 0xa66090>
(gdb) n
2278                x = PyObject_GetAttr(v, w);
(gdb) p v
$156 = 
    <_FileFinder(_relaxed_path_cache=set(), packages=[('.py', <type at remote 0xaaff60>), ('.p
yc', <type at remote 0xab02e0>)], _path_mtime=<float at remote 0xa66120>, modules=[('.cpython-
33m.so', <type at remote 0xab0970>), ('.abi3.so', <type at remote 0xab0970>), ('.so', <type at
 remote 0xab0970>), ('.py', <type at remote 0xaaff60>), ('.pyc', <type at remote 0xab02e0>)], 
path='.', _cache_refresh=0, _path_cache=set()) at remote 0x7ffff2b7f6d0>
(gdb) n
2279                Py_DECREF(v);
(gdb) p x
$157 = <float at remote 0xa66120>
(gdb) n
2280                SET_TOP(x);
(gdb) n
2281                if (x != NULL) DISPATCH();
(gdb) n
2284            TARGET(COMPARE_OP)
(gdb) n
2285                w = POP();
(gdb) n
2286                v = TOP();
(gdb) n
2287                x = cmp_outcome(oparg, v, w);
(gdb) n
2288                Py_DECREF(v);
(gdb) p w
$158 = <float at remote 0xa66120>
(gdb) p v
$159 = <float at remote 0xa66090>
(gdb) p x
$160 = True

So I think the good version proceeds to refresh the _path_cache:

<_FileFinder(_relaxed_path_cache={'pep3147'}, packages=[('.py', <type at remote 0xaaff60>), ('.pyc', <type at remote 0xab02e0>)], _path_mtime=<float at remote 0xa66120>, modules=[('.cpython-33m.so', <type at remote 0xab0970>), ('.abi3.so', <type at remote 0xab0970>), ('.so', <type at remote 0xab0970>), ('.py', <type at remote 0xaaff60>), ('.pyc', <type at remote 0xab02e0>)], path='.', _cache_refresh=0, _path_cache={'pep3147'}) at remote 0x7ffff2b7f6d0>


And the bad version still contains an empty set:
  
<_FileFinder(_relaxed_path_cache=set(), path='.', packages=[('.py', <type at remote 0xab4bc0>), ('.pyc', <type at remote 0xab4f40>)], _path_cache=set(), _cache_refresh=0, _path_mtime=<float at remote 0xa6a7d0>, modules=[('.cpython-33m.so', <type at remote 0xab55d0>), ('.abi3.so', <type at remote 0xab55d0>), ('.so', <type at remote 0xab55d0>), ('.py', <type at remote 0xab4bc0>), ('.pyc', <type at remote 0xab4f40>)]) at remote 0x7ffff4128310>



This probably means that the case split occurs in  Lib/importlib/_bootstrap.py:780 ...


    if mtime != self._path_mtime or _cache_refresh != self._cache_refresh:
            self._fill_cache()
            self._path_mtime = mtime
            self._cache_refresh = _cache_refresh

And indeed, with this patch ...

diff --git a/Lib/importlib/_bootstrap.py b/Lib/importlib/_bootstrap.py
--- a/Lib/importlib/_bootstrap.py
+++ b/Lib/importlib/_bootstrap.py
@@ -777,6 +777,8 @@
             mtime = _os.stat(self.path).st_mtime
         except OSError:
             mtime = -1
+        if fullname == 'pep3147':
+            print(mtime, self._path_mtime)
         if mtime != self._path_mtime or _cache_refresh != self._cache_refresh:
             self._fill_cache()
             self._path_mtime = mtime


Good version:

[stefan@fedora-16-amd64 cpython]$ ./python -m test test_dot
[1/1] test_dot
1330188705.3170006 1330188705.3100004
Warning -- sys.path was modified by test_dot


Bad version:

$ ./python -m test test_dot
[1/1] test_dot
1330188676.0 1330188676.0
Warning -- sys.path was modified by test_dot
test test_dot crashed -- Traceback (most recent call last):
  File "/home/stefan/pydev/cpython-imp/Lib/test/regrtest.py", line 1214, in runtest_inner
    the_package = __import__(abstest, globals(), locals(), [])
  File "/home/stefan/pydev/cpython-imp/Lib/test/test_dot.py", line 20, in <module>
    assert m.__file__ == expected___file__
AssertionError

1 test failed:
    test_dot



It looks like os.stat.st_mtime returns full seconds here on Ubuntu:

Python 3.3.0a0 (default:3f9b3b6f7ff0, Feb 25 2012, 17:42:23) 
[GCC 4.4.3] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import os
>>> os.stat("./python").st_mtime
1330189060.0
>>> 










Nanoseconds, anyone? :)

Le samedi 25 février 2012 à 16:59 +0000, Stefan Krah a écrit :
> Bad version:
> 
> $ ./python -m test test_dot
> [1/1] test_dot
> 1330188676.0 1330188676.0

This might be what triggers the issue, but it's not the cause. Even with
a bad mtime, the __file__ should still be the right one, so there must
be something else.

> It looks like os.stat.st_mtime returns full seconds here on Ubuntu:

It probably depends on the filesystem.

Antoine Pitrou <report@bugs.python.org> wrote:
> This might be what triggers the issue, but it's not the cause. Even with
> a bad mtime, the __file__ should still be the right one, so there must
> be something else.

It definitely triggers the issue because the problem also occurs on Fedora
if I use:

    if fullname != 'pep3147' and (mtime != self._path_mtime or _cache_refresh != self._cache_refresh):
        ...

But you're right, the real problem should be elsewhere. At least with
the line above everyone should be able to reproduce the issue.

What happens is that if self._fill_cache() is called, cache_module='pep3147'
and cache={'pep3147'}. Then 'cache_module in cache' is true and the function
returns:

    loader('pep3147', './pep3147/__init__.py')

Otherwise, find_module() returns None, control is handed back to
find_module_path() ...

    loader = _PyObject_CallMethodId(importer, &PyId_find_module, "O", fullname)

... and then to find_module_path_list(), where the search continues:

    for (i = 0; i < npath; i++) {
        path = PyList_GetItem(search_path_list, i);
        ...

search_path_list = ['.', '', ... ], but now i==1, so the dot is disregarded
and '' is used as the path, leading to the dotless result.

I don't know the contract for importlib's find_module, but it seems to me
that either find_module should handle this case or we have an unwanted
interaction between C and Python code.

> What happens is that if self._fill_cache() is called, cache_module='pep3147'
> and cache={'pep3147'}. Then 'cache_module in cache' is true and the function
> returns:
> 
>     loader('pep3147', './pep3147/__init__.py')
> 
> Otherwise, find_module() returns None, control is handed back to
> find_module_path() ...

Ah, thanks. So the test needs to be fixed to call
importlib.invalidate_caches() after creating the module.

> So the test needs to be fixed to call importlib.invalidate_caches()
> after creating the module.

That works. With issue14080.diff I can run the failing combination
without problems:

$ ./python -m test test_sqlite test_imp
[1/2] test_sqlite
test_sqlite skipped -- No module named '_sqlite3'
[2/2] test_imp
1 test OK.
1 test skipped:
    test_sqlite
Those skips are all expected on linux.
[111339 refs]



Is invalidate_caches() a transitional measure until importlib
is fully integrated?

importlib.invalidate_caches() would become a permanent thing if the directory listdir cache approach stays and importlib gets bootstrapped. But it would be made more general to work for any and all loaders and not be specific to importlib (e.g. 3rd-party importers would also get cleared). It's an unfortunate side-effect of mtime of directories not being granular enough.

New changeset 1d7472b015f0 by Antoine Pitrou in branch 'default':
Issue #14080: fix sporadic test_imp failure.  Patch by Stefan Krah.
http://hg.python.org/cpython/rev/1d7472b015f0

Thanks for diagnosing this :)

I think there's another problem on Windows even after the fix:

http://www.python.org/dev/buildbot/all/builders/x86%20Windows7%203.x/builds/4463


======================================================================
FAIL: test_package___file__ (test.test_imp.PEP3147Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\lib\test\test_imp.py", line 331, in test_package___file__
    self.assertEqual(m.__file__, expected___file__, (m.__file__, m.__path__))
AssertionError: 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows7\\build\\build\\test_pytho [truncated]... != '.\\pep3147\\__init__.py'
- D:\cygwin\home\db3l\buildarea\3.x.bolen-windows7\build\build\test_python_2652\pep3147\__init__.py
+ .\pep3147\__init__.py
 : ('D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows7\\build\\build\\test_python_2652\\pep3147\\__init__.py', ['D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows7\\build\\build\\test_python_2652\\pep3147'])

----------------------------------------------------------------------

This is issue #14052 all over again, just with a different test.

> This is issue #14052 all over again, just with a different test.

I don't think so, because I've whacked the part of importlib that transformed '' into os.getcwd().

Then how do you explain the failure being nothing more than prepending . compared to an absolute file path?

Anyway, the test passes under importlib with ``./python.exe -m importlib.test.regrtest test_imp``, so it requires some special setup to trigger the failure.

Happened again on one of the Windows buildbots:

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


======================================================================
FAIL: test_package___file__ (test.test_imp.PEP3147Tests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "D:\cygwin\home\db3l\buildarea\3.x.bolen-windows\build\lib\test\test_imp.py", line 329, in test_package___file__
    self.assertEqual(m.__file__, expected___file__, (m.__file__, m.__path__, sys.path, sys.path_importer_cache))
AssertionError: 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\build\\test_python [truncated]... != '.\\pep3147\\__init__.py'
- D:\cygwin\home\db3l\buildarea\3.x.bolen-windows\build\build\test_python_3480\pep3147\__init__.py
+ .\pep3147\__init__.py
 : ('D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\build\\test_python_3480\\pep3147\\__init__.py', ['D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\build\\test_python_3480\\pep3147'], ['.', 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\PCbuild\\python33_d.zip', 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\DLLs', 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib', 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\PCbuild', 'C:\\Documents and Settings\\db3l\\Application Data\\Python\\Python33\\site-packages', 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build', 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\site-packages'], {'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\lib2to3\\fixes': <_frozen_importlib.FileFinder object at 0x103CC4D0>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\site-packages': <importlib._bootstrap.FileFinder object at 0x0639DEA8>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\xml\\etree': None, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\lib2to3\\tests\\data\\fixers\\myfixes': <_frozen_importlib.FileFinder object at 0x103CC658>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\test': <_frozen_importlib.FileFinder object at 0x07CAFE38>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\PCbuild\\python33_d.zip': <imp.NullImporter object at 0x04F0A5E8>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib': <importlib._bootstrap.FileFinder object at 0x07CB2150>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\PCbuild': <importlib._bootstrap.FileFinder object at 0x07CB2498>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build': <importlib._bootstrap.FileFinder object at 0x0639D690>, 'C:\\Documents and Settings\\db3l\\Application Data\\Python\\Python33\\site-packages': <importlib._bootstrap.FileFinder object at 0x06561F50>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\lib2to3\\tests': <_frozen_importlib.FileFinder object at 0x09E031C0>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\lib2to3\\tests\\data\\fixers': <_frozen_importlib.FileFinder object at 0x103CC118>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\lib\\lib2to3': <_frozen_importlib.FileFinder object at 0x09E03B60>, 'D:\\cygwin\\home\\db3l\\buildarea\\3.x.bolen-windows\\build\\DLLs': <imp.NullImporter object at 0x04F0A1A8>})

Some entries in sys.path_importer_cache are named _frozen_importlib.FileFinder, and others are named importlib._bootstrap.FileFinder. Isn't that a bit worrying? Two copies of importlib are loaded in memory? (and functioning independently?)

Issue #14657 is tracking the discussion of _frozen_importlib/importlib._bootstrap.

Given that issue14657 wrapped up, I'm closing this issue too.