Edgewall Software

Opened 9 years ago

Closed 9 years ago

Last modified 9 years ago

#12019 closed defect (fixed)

Failures of trac.tests.config on Windows since Trac 1.1.3 — at Version 8

Reported by: Jun Omae Owned by: Jun Omae
Priority: normal Milestone: 1.0.6
Component: general Version:
Severity: normal Keywords: windows
Cc: Branch:
Release Notes:

Fix low resolution of wait_for_file_mtime_change() on Windows.

API Changes:

trac.util: Added touch_file() (r13969)

Internal Changes:

Description

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

Change History (9)

comment:1 by Ryan J Ollos, 9 years ago

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

Last edited 9 years ago by Ryan J Ollos (previous) (diff)

comment:2 by Peter Suter, 9 years ago

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

    diff -r e3f64f376184 trac/util/compat.py
    a b  
    7373    try:
    7474        mtime = os.stat(filename).st_mtime
    7575        os.utime(filename, None)
    76         while mtime == os.stat(filename).st_mtime:
     76        while mtime >= os.stat(filename).st_mtime:
    7777            time.sleep(1e-3)
    7878            os.utime(filename, None)
    7979    except OSError:
Last edited 9 years ago by Peter Suter (previous) (diff)

comment:3 by Jun Omae, 9 years ago

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'

by Jun Omae, 9 years ago

Attachment: t12019-touch_file.diff added

comment:4 by Ryan J Ollos, 9 years ago

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].

Last edited 9 years ago by Ryan J Ollos (previous) (diff)

comment:5 by Jun Omae, 9 years ago

Milestone: 1.1.51.0.6
Owner: set to Jun Omae
Status: newassigned

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

Proposed changes in jomae.git@t12019.

comment:6 by Jun Omae, 9 years ago

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.

comment:7 by Jun Omae, 9 years ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

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

comment:8 by Jun Omae, 9 years ago

API Changes: modified (diff)
Note: See TracTickets for help on using tickets.