Failures of trac.tests.config on Windows since Trac 1.1.3

[Jun Omae]

trunk

C:> git checkout mirror/trunk
Previous HEAD position was ebbd95d... 1.1.4: Tagging trac-1.1.4.
HEAD is now at e51a24c... Merge from 1.0-stable.

C:> python -m trac.tests.config
SKIP: trac.tests.config.ConfigurationSetDefaultsTestCase (__name__ is not trac.tests.config)
...........................F..........
======================================================================
FAIL: test_reparse (__main__.ConfigurationTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\usr\src\trac\trac.git\trac\tests\config.py", line 543, in test_reparse
    self.assertEqual('y', config.get('a', 'option'))
AssertionError: 'y' != u'x'

----------------------------------------------------------------------
Ran 38 tests in 2.142s

FAILED (failures=1)

Trac 1.1.4

C:> git checkout trac-1.1.4
Previous HEAD position was f4bc66e... 1.1.3: Tagging trac-1.1.3.
HEAD is now at ebbd95d... 1.1.4: Tagging trac-1.1.4.

C:> python -m trac.tests.config
SKIP: trac.tests.config.ConfigurationSetDefaultsTestCase (__name__ is not trac.tests.config)
..........F................F..........
======================================================================
FAIL: test_inherit_reparse (__main__.ConfigurationTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\usr\src\trac\trac.git\trac\tests\config.py", line 554, in test_inherit_reparse
    self._test_with_inherit(testcb)
  File "C:\usr\src\trac\trac.git\trac\tests\config.py", line 697, in _test_with_inherit
    testcb()
  File "C:\usr\src\trac\trac.git\trac\tests\config.py", line 553, in testcb
    self.assertEqual('y', config.get('a', 'option'))
AssertionError: 'y' != u'x'

======================================================================
FAIL: test_reparse (__main__.ConfigurationTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\usr\src\trac\trac.git\trac\tests\config.py", line 543, in test_reparse
    self.assertEqual('y', config.get('a', 'option'))
AssertionError: 'y' != u'x'

----------------------------------------------------------------------
Ran 38 tests in 2.219s

FAILED (failures=2)

Trac 1.1.3

C:> git checkout trac-1.1.3
Previous HEAD position was 58602e8... 1.1.2: Tagging trac-1.1.2.
HEAD is now at f4bc66e... 1.1.3: Tagging trac-1.1.3.

C:> python -m trac.tests.config
...........................F..........
======================================================================
FAIL: test_reparse (__main__.ConfigurationTestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "C:\usr\src\trac\trac.git\trac\tests\config.py", line 516, in test_reparse
    self.assertEqual('y', config.get('a', 'option'))
AssertionError: 'y' != u'x'

----------------------------------------------------------------------
Ran 38 tests in 1.719s

FAILED (failures=1)

Trac 1.1.2

C:> git checkout trac-1.1.2
Previous HEAD position was f4bc66e... 1.1.3: Tagging trac-1.1.3.
HEAD is now at 58602e8... 1.1.2: Tagging trac-1.1.2.

C:> python -m trac.tests.config
....................................
----------------------------------------------------------------------
Ran 36 tests in 4.659s

OK

[Ryan J Ollos]

The failing test was implemented in #11902 ([13628]). I don't have any idea of what the problem is.

[Peter Suter]

Weird. It's a timing / mtime issue, right? Here it only happens once in a while.

Maybe same issue as in #11904? This seems to fix it for me:

trac/util/compat.py

@@ -73 +73 @@
     try:
         mtime = os.stat(filename).st_mtime
         os.utime(filename, None)
-        while mtime == os.stat(filename).st_mtime:
+        while mtime >= os.stat(filename).st_mtime:
             time.sleep(1e-3)
             os.utime(filename, None)
     except OSError:

[Jun Omae]

The cause is that os.utime() is implemented using GetSystemTime() on Windows and the system clock has low resolution (15ms-16ms).

>>> import os
>>> from trac.util import create_file
>>> create_file('test.txt')
>>> '%.9f' % os.stat('test.txt').st_mtime
'1428046347.664300900'
>>> os.utimes('test.txt', None)
>>> os.utime('test.txt', None)
>>> '%.9f' % os.stat('test.txt').st_mtime
'1428046389.869000000'   # <== low resolution of mtime

Instead, we could use f.truncate(os.fstat(f.fileno()).st_size) to update modified time. See t12019-touch_file.diff​.

>>> create_file('test.txt')
>>> '%.9f' % os.stat('test.txt').st_mtime
'1428052266.600536600'
>>> with open('test.txt', 'ab') as f:
...     f.truncate(os.fstat(f.fileno()).st_size)
...
>>> '%.9f' % os.stat('test.txt').st_mtime
'1428052293.487920500'

[Ryan J Ollos]

All proposed changes look good to me. I haven't checked, but seems like the issue would be found on 1.0-stable as well.

Additionally, even prior to these changes it looks like the os.utime call in Configuration.touch is redundant: tags/trac-1.0.5/trac/config.py@:300#L296​. It looks like it could have been removed when wait_for_file_mtime_change was added in [12258#file1].

[Jun Omae]

Thanks for the reviewing. I get the same issue on 1.0-stable with Windows.

Proposed changes in jomae.git@t12019.

[Jun Omae]

See also ​Issue 19727: os.utime(..., None) has poor resolution on Windows - Python tracker. The os.utime() has been improved on Windows since Python 3.4.

[Jun Omae]

Committed in [13969] and merged to trunk in [13970].