classification
Title: intermittence on UnicodeFileTests.test_rename at test_pep277 on MacOS X
Type: Stage: resolved
Components: macOS Versions: Python 3.3
process
Status: closed Resolution: third party
Dependencies: Superseder:
Assigned To: Nosy List: flavio.ribeiro, hltbra, ned.deily, r.david.murray, rafaelcaricio, ronaldoussoren, tati_alchueyr
Priority: normal Keywords:

Created on 2012-07-19 18:33 by flavio.ribeiro, last changed 2014-07-26 19:23 by ned.deily. This issue is now closed.

Messages (17)
msg165849 - (view) Author: Flávio Ribeiro (flavio.ribeiro) * Date: 2012-07-19 18:33
Found a intermittent test on UnicodeFileTests.test_rename method.

Python Version: Python 3.3.0b1
Hg commit hash: 3fbfa61634de
MacOS X version 10.6.8 

How can be reproduced:

bumblebee:~/dev/cpython[] $ for i in {1..10}; do ./python.exe  -m test test_pep277; done
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
test test_pep277 failed -- Traceback (most recent call last):
  File "/Users/flavio.barbosa/dev/cpython/Lib/test/test_pep277.py", line 172, in test_rename
    os.rename("tmp", name)
FileNotFoundError: [Errno 2] No such file or directory: '@test_51143_tmp/8_曨曩曫'

1 test failed:
    test_pep277
[103879 refs]
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
test test_pep277 failed -- Traceback (most recent call last):
  File "/Users/flavio.barbosa/dev/cpython/Lib/test/test_pep277.py", line 172, in test_rename
    os.rename("tmp", name)
FileNotFoundError: [Errno 2] No such file or directory: '@test_51145_tmp/3_Grüß-Gott'

1 test failed:
    test_pep277
[103879 refs]
[1/1] test_pep277
1 test OK.
[103867 refs]
[1/1] test_pep277
test test_pep277 failed -- Traceback (most recent call last):
  File "/Users/flavio.barbosa/dev/cpython/Lib/test/test_pep277.py", line 172, in test_rename
    os.rename("tmp", name)
FileNotFoundError: [Errno 2] No such file or directory: '@test_51147_tmp/6_にぽん'

1 test failed:
    test_pep277
[103879 refs]
msg165851 - (view) Author: Tatiana Al-Chueyr (tati_alchueyr) * Date: 2012-07-19 18:37
I had the same problem here, after running several times...

 $ for i in {1..10}; do ./python.exe  -m test test_pep277; done
[1/1] test_pep277
test test_pep277 failed -- Traceback (most recent call last):
  File "/Users/tatiana/code/cpython/Lib/test/test_pep277.py", line 172, in test_rename
    os.rename("tmp", name)
FileNotFoundError: [Errno 2] No such file or directory: '@test_6002_tmp/2_ascii'

1 test failed:
    test_pep277
[1/1] test_pep277
1 test OK.
[1/1] test_pep277
1 test OK.
[1/1] test_pep277
1 test OK.
[1/1] test_pep277
1 test OK.
[1/1] test_pep277
1 test OK.
[1/1] test_pep277
test test_pep277 failed -- Traceback (most recent call last):
  File "/Users/tatiana/code/cpython/Lib/test/test_pep277.py", line 172, in test_rename
    os.rename("tmp", name)
FileNotFoundError: [Errno 2] No such file or directory: '@test_6033_tmp/6_にぽん'

1 test failed:
    test_pep277
[1/1] test_pep277
1 test OK.
[1/1] test_pep277
test test_pep277 failed -- Traceback (most recent call last):
  File "/Users/tatiana/code/cpython/Lib/test/test_pep277.py", line 172, in test_rename
    os.rename("tmp", name)
FileNotFoundError: [Errno 2] No such file or directory: '@test_6041_tmp/8_曨曩曫'

1 test failed:
    test_pep277
[1/1] test_pep277
1 test OK.
msg165857 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-07-19 19:16
By the way, you can use -F to run the test suite until it fails:

  ./python -m test -F test_pep277
msg165858 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-07-19 19:17
Tatiana, are you on a Mac as well?
msg165864 - (view) Author: Tatiana Al-Chueyr (tati_alchueyr) * Date: 2012-07-19 19:23
r.david.murray: yes, MacOS X 10.6.8

we managed to reproduce this in other 2 MacBook Pro 8.1.
msg165865 - (view) Author: Hugo Lopes Tavares (hltbra) Date: 2012-07-19 19:25
I had no problems after running for a very long time (using -F). I am using Mac OSX 10.6.8.
msg165875 - (view) Author: Flávio Ribeiro (flavio.ribeiro) * Date: 2012-07-19 20:40
For doc purposes:

My first shot is that in my machine the os.rename isn't atomic and this could be generating an overhead somehow. Looking at the code, I found decisions being made on posixmodule.c about what `rename` function should be used:

 #ifdef HAVE_RENAMEAT
     if (dir_fd_specified)
         result = renameat(src_dir_fd, src.narrow, dst_dir_fd, dst.narrow);
     else
 #endif
         result = rename(src.narrow, dst.narrow);
     Py_END_ALLOW_THREADS
 

In my machine the second `rename` is being used.
msg165876 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2012-07-19 20:51
I haven't been able to reproduce this failure on either 10.6 or 10.7 with or without pydebug and either at 3fbfa61634de or the now slightly more current tip.  What filesystem are you running the test under?  What ./configure options did you use?  What compiler did you use?  What environment variables are defined especially LANG or LC_* ones?
msg165877 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2012-07-19 21:00
And OS X doesn't support the *at system calls so HAVE_RENAMEAT will always be false on OS X.  I don't recall every seeing this test fail before.
msg165879 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2012-07-19 21:34
I found this link:

  http://www.weirdnet.nl/apple/rename.html

in issue 8828, which sounds like it is relevant.  (I thought I remembered something about rename not being atomic on OS X.)  I didn't read it through, but maybe Apple fixed the bug.
msg165880 - (view) Author: Flávio Ribeiro (flavio.ribeiro) * Date: 2012-07-19 21:48
Hi Ned,

I've used ./configure --with-pydebug && make -j2

$ gcc --version
i686-apple-darwin10-gcc-4.2.1 (GCC) 4.2.1 (Apple Inc. build 5666) (dot 3)
Copyright (C) 2007 Free Software Foundation, Inc.

$ printenv | grep LC_
$ printenv| grep LANG
LANG=en_US.UTF-8

$ mount
/dev/disk0s2 on / (hfs, local, journaled)
msg165886 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2012-07-19 22:38
Thanks, Flávio.  That configuration looks perfectly normal and what I use so that should not be an issue.

Interesting link, David.  I'm not able to reproduce that failure on 10.6.8 using the procedure in the link but I am running 10.6.8 on a virtual machine so that isn't conclusive.  The author says that the problem is fixed in 10.7' so it's not surprising that I can't reproduce it on a non-virtual 10.7, either.  I guess it would be interesting to know if Flávio or Tatiana can duplicate the results of the blog post.  It would also be interesting to know if test_pep277 also fails in the same environment with Python 3.2.

But, assuming the issue is OS-related, I don't see what we should do about it other than possibly adding a comment to the test.  Opinions?
msg165900 - (view) Author: Ronald Oussoren (ronaldoussoren) * (Python committer) Date: 2012-07-20 06:12
Whether or not rename is atomic should be irrelevant for test_rename. Test_rename "just" performs renames in a tight loop and doesn't do concurrent access from another thread.

The test result seems to indicate that rename() sometimes isn't done yet when the sys call returns (or even that it fails silently), which would be even worse than it not being atomic.

That said, I cannot reproduce using Python 3.3.0b1 (default:abc26b51fbfc, Jul 20 2012, 07:50:15) on an OSX 10.7 system.

I'm currently rebuilding for a test run on a OSX 10.5.8 machine on real hardware.
msg165922 - (view) Author: Rafael Caricio (rafaelcaricio) Date: 2012-07-20 13:38
I had this problem when I run the tests in my machine (Mac OSX 10.6.8). The intermittence happen here.
msg165926 - (view) Author: Flávio Ribeiro (flavio.ribeiro) * Date: 2012-07-20 13:56
Ronald,

I thought it could be an `atomic` issue by the fact that test_rename transforms a filename in tmp and then it change again to the original name. Not being atomic, the rename will not finish the executation of the first one (even though a return code has been sent) and FileNotFoundError is dispatched. 

Anyway, i've added a time.sleep in the middle of the two lines to assert this and no more intermittence could be found. Ideas?
msg194232 - (view) Author: Ned Deily (ned.deily) * (Python committer) Date: 2013-08-03 03:19
Has anyone seen this problem on other than OS X 10.6?  If not, I suggest we assume it was, in fact, due to a platform bug and close.
msg224035 - (view) Author: Ronald Oussoren (ronaldoussoren) * (Python committer) Date: 2014-07-26 09:40
I'd be in favour of closing this issue, I haven't seen the problem in a while and it is almost certainly due to a platform bug on OSX 10.6.
History
Date User Action Args
2014-07-26 19:23:31ned.deilysetstatus: open -> closed
resolution: third party
stage: resolved
2014-07-26 09:40:49ronaldoussorensetmessages: + msg224035
2013-08-03 03:19:51ned.deilysetmessages: + msg194232
2012-07-20 13:56:29flavio.ribeirosetmessages: + msg165926
2012-07-20 13:38:14rafaelcariciosetnosy: + rafaelcaricio
messages: + msg165922
2012-07-20 06:12:07ronaldoussorensetmessages: + msg165900
2012-07-19 22:38:47ned.deilysetmessages: + msg165886
2012-07-19 21:48:09flavio.ribeirosetmessages: + msg165880
2012-07-19 21:34:25r.david.murraysetmessages: + msg165879
2012-07-19 21:00:40ned.deilysetmessages: + msg165877
2012-07-19 20:51:26ned.deilysetassignee: ronaldoussoren ->

messages: + msg165876
nosy: + ned.deily
2012-07-19 20:40:13flavio.ribeirosetmessages: + msg165875
2012-07-19 19:25:46hltbrasetnosy: + hltbra
messages: + msg165865
2012-07-19 19:23:18tati_alchueyrsetmessages: + msg165864
2012-07-19 19:17:10r.david.murraysetmessages: + msg165858
2012-07-19 19:16:17r.david.murraysetnosy: + r.david.murray
messages: + msg165857
2012-07-19 18:37:03tati_alchueyrsetnosy: + tati_alchueyr
messages: + msg165851
2012-07-19 18:33:56flavio.ribeirocreate