classification
Title: Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
Type: behavior Stage: patch review
Components: Tests Versions: Python 3.6, Python 3.4, Python 3.5
process
Status: closed Resolution: fixed
Dependencies: Superseder:
Assigned To: trent Nosy List: Arfrever, BreamoreBoy, Claudiu.Popa, emaste, harrison.grundy, jcea, koobs, larry, martin.panter, pitrou, python-dev, r.david.murray, trent, vstinner
Priority: normal Keywords: needs review, patch

Created on 2012-08-21 02:15 by trent, last changed 2015-07-20 14:19 by martin.panter. This issue is now closed.

Files
File name Uploaded Description Edit
test_os.patch trent, 2012-10-16 21:40 review
almostequaltime.diff harrison.grundy, 2015-04-21 09:45 review
test_utime_ns.patch vstinner, 2015-06-11 22:55 review
test_utime.patch vstinner, 2015-06-12 00:39 review
Messages (50)
msg168728 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-21 02:15
I've got two FreeBSD buildslaves running on ZFS (8.2 and 9.1) experiencing this:

======================================================================
FAIL: test_futimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 369, in test_futimes_ns
    self._test_utime_ns(futimes_ns, test_dir=False)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270884503433 != 1345497270884503000

======================================================================
FAIL: test_lutimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 362, in test_lutimes_ns
    self._test_utime_ns(lutimes_ns)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270888847634 != 1345497270888847000

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 331, in test_utime
    self._test_utime(self.fname, getattr, utime, 10)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270.8923829 != 1345497270.892382

======================================================================
FAIL: test_utime_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 346, in test_utime_ns
    self._test_utime_ns(utime_ns)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270894558518 != 1345497270894558000


I briefly stepped through the test on one of the affected slaves.  There's a rounding issue somewhere... I personally think this method is involved:

    def _test_utime_ns(self, set_times_ns, test_dir=True):
        def getattr_ns(o, attr):
            return getattr(o, attr + "_ns")
        ten_s = 10 * 1000 * 1000 * 1000
        self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
        if test_dir:
            self._test_utime(support.TESTFN, getattr_ns, set_times_ns, ten_s)

I didn't have enough time to keep debugging, so I'm raising this as a placeholder until I can pick it back up again.
msg168770 - (view) Author: Stefan Krah (skrah) * (Python committer) Date: 2012-08-21 13:45
Looks like a ZFS/nanosecond issue. My FreeBSD buildbot uses FFS and does not
have the failures.
msg168808 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-08-21 21:52
Can you tell me which code path it took?  Either by walking through the code as it runs, or by telling me about the preprocessor defines used by utime (HAVE_FUTIMES, HAVE_FUTIMENS, HAVE_FUTIMESAT, HAVE_UTIMENSAT, HAVE_UTIMES, HAVE_UTIME_H).  The easy way to do this would be to say

    from posix import _have_functions
    print(_have_functions)

and paste the result in.  Then also tell me if you have a file "utime.h" in either your standard include directory or in the "sys" subdirectory of that directory.
msg168811 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-21 22:06
>>> print(_have_functions)
['HAVE_FACCESSAT', 'HAVE_FCHDIR', 'HAVE_FCHMOD', 'HAVE_FCHMODAT', 'HAVE_FCHOWN', 'HAVE_FEXECVE', 'HAVE_FDOPENDIR', 'HAVE_FPATHCONF', 'HAVE_FSTATAT', 'HAVE_FSTATVFS', 'HAVE_FTRUNCATE', 'HAVE_FUTIMES', 'HAVE_FUTIMESAT', 'HAVE_LINKAT', 'HAVE_LCHFLAGS', 'HAVE_LCHMOD', 'HAVE_LCHOWN', 'HAVE_LSTAT', 'HAVE_LUTIMES', 'HAVE_MKDIRAT', 'HAVE_MKFIFOAT', 'HAVE_MKNODAT', 'HAVE_OPENAT', 'HAVE_READLINKAT', 'HAVE_RENAMEAT', 'HAVE_SYMLINKAT', 'HAVE_UNLINKAT']

/usr/include/utime.h exists.

FWIW, when I stepped through it a few nights ago, I remember that all the code paths eventually visited the point where the mtime gets converted into a decimal:

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 331, in test_utime
    self._test_utime(self.fname, getattr, utime, 10)
  File "/home/buildslave/cpython/3.x.snakebite-freebsd91-amd64/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345497270.8923829 != 1345497270.892382

However, for the other errors:
    AssertionError: 1345497270884503433 != 1345497270884503000
    AssertionError: 1345497270888847634 != 1345497270888847000
....they'd get cast back before the assertEqual test would be done.

As for this:
    1345497270.8923829 != 1345497270.892382

The trailing 9 is getting lopped off, which results in the rounding errors.
msg168822 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-08-21 23:38
mtime is never converted into a "decimal".  Do you perhaps mean "double"?
msg168828 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-22 00:03
Oh, heh, yes, I meant double :-)
msg168883 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-08-22 13:11
Looks like it's not specific to just FreeBSD, no ZFS.  From a new NetBSD slave I set up:

======================================================================
FAIL: test_futimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 369, in test_futimes_ns
    self._test_utime_ns(futimes_ns, test_dir=False)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345639042446725659 != 1345639042446725000

======================================================================
FAIL: test_lutimes_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 362, in test_lutimes_ns
    self._test_utime_ns(lutimes_ns)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345639042450323780 != 1345639042450323000

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 331, in test_utime
    self._test_utime(self.fname, getattr, utime, 10)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 319, in _test_utime
    self.assertEqual(attr(st0, "st_atime"), attr(st1, "st_atime"))
AssertionError: 1345639042.4583352 != 1345639042.458335

======================================================================
FAIL: test_utime_ns (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 346, in test_utime_ns
    self._test_utime_ns(utime_ns)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 339, in _test_utime_ns
    self._test_utime(self.fname, getattr_ns, set_times_ns, ten_s)
  File "/home/cpython/buildslave/3.x.snakebite-netbsd51-x86-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1345639042463150626 != 1345639042463150000

----------------------------------------------------------------------
(from http://buildbot.python.org/all/builders/x86%20NetBSD%205.1.2%20%5BSB%5D%203.x/builds/0/steps/test/logs/stdio)


Exact same symptoms as the original FreeBSD issue.
msg168898 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-08-22 17:04
> AssertionError: 1345639042446725659 != 1345639042446725000

Well, by the looks of it, some filesystems only have microsecond precision?
Would be best to confirm with a {Free,Net}BSD mailing-list, I think.
msg168911 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-08-23 00:34
Yes, but the code should still work.  The test that's failing reads the atime/mtime from a file, then writes those values out to the file, then reads again to confirm that they're the same.  That should always work.
msg170631 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-09-18 03:03
Just noticed that the Solaris 10 slave is failing in the same way:

======================================================================
FAIL: test_utime (test.test_os.StatAttributeTests)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "/home/cpython/buildslave/3.x.snakebite-solaris10-u10ga2-sparc64-1/build/Lib/test/test_os.py", line 332, in test_utime
    self._test_utime(support.TESTFN, getattr, utime, 10)
  File "/home/cpython/buildslave/3.x.snakebite-solaris10-u10ga2-sparc64-1/build/Lib/test/test_os.py", line 318, in _test_utime
    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1347752941.275297 != 1347752941.275296

Note that /home/cpython on this slave is backed by UFS, not ZFS.

(It's accessible to committers via sb->s10.)
msg173087 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-16 20:04
I've figured out what the primary problem is on these platforms: os.stat() returns st_mtime and st_atime values with nanosecond resolution, but without a corresponding utimensat(), we can only affect time with microsecond precision via utimes().

Therefore, the following logic is faulty:

    def _test_utime(self, filename, attr, utime, delta):
        # Issue #13327 removed the requirement to pass None as the
        # second argument. Check that the previous methods of passing
        # a time tuple or None work in addition to no argument.
        st0 = os.stat(filename)
        # Doesn't set anything new, but sets the time tuple way
        utime(filename, (attr(st0, "st_atime"), attr(st0, "st_mtime")))
        # Setting the time to the time you just read, then reading again,
        # should always return exactly the same times.
        st1 = os.stat(filename)
        self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
        self.assertEqual(attr(st0, "st_atime"), attr(st1, "st_atime"))
msg173092 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-10-16 20:59
Is there a different utime family function on these platforms that *can* write atime/mtime with ns resolution?
msg173094 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-16 21:03
There doesn't appear to be on FreeBSD.  Although, on Solaris, -D__EXTENSIONS__ opens up access to utimensat() (at least on 11), so I'll factor that into configure.ac.
msg173102 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-16 21:40
This patch (surprisingly) seems to do the job quite nicely:

diff -r 1280b38fe583 Lib/test/test_os.py
--- a/Lib/test/test_os.py	Tue Oct 16 23:14:03 2012 +1000
+++ b/Lib/test/test_os.py	Tue Oct 16 21:25:36 2012 +0000
@@ -40,6 +40,20 @@
     or (st.st_mtime != st[8])
     or (st.st_ctime != st[9]))
 
+try:
+    import posix
+except ImportError:
+    # Windows has nanosecond utime resolution.
+    UTIME_EPSILON = 2e-9
+else:
+    import sysconfig
+    if 'HAVE_UTIMENSAT' in posix._have_functions:
+        UTIME_EPSILON = 2e-9
+    elif 'HAVE_UTIMES' in sysconfig.get_config_vars():
+        UTIME_EPSILON = 2e-6
+    else:
+        UTIME_EPSILON = 1.0
+
 # Detect whether we're on a Linux system that uses the (now outdated
 # and unmaintained) linuxthreads threading library.  There's an issue
 # when combining linuxthreads with a failed execv call: see
@@ -312,18 +326,32 @@
         st0 = os.stat(filename)
         # Doesn't set anything new, but sets the time tuple way
         utime(filename, (attr(st0, "st_atime"), attr(st0, "st_mtime")))
-        # Setting the time to the time you just read, then reading again,
-        # should always return exactly the same times.
         st1 = os.stat(filename)
-        self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
-        self.assertEqual(attr(st0, "st_atime"), attr(st1, "st_atime"))
+
+        def _t(left, right, attr, name):
+            l = attr(left, name)
+            r = attr(right, name)
+            if isinstance(l, int):
+                assert isinstance(r, int)
+                l = l / 1e9
+                r = r / 1e9
+            return abs(l - r)
+
+        epsilon = UTIME_EPSILON
+        self.assertLess(_t(st0, st1, attr, "st_mtime"), epsilon)
+        self.assertLess(_t(st0, st1, attr, "st_atime"), epsilon)
+
         # Set to the current time in the old explicit way.
         os.utime(filename, None)
         st2 = os.stat(support.TESTFN)
         # Set to the current time in the new way
         os.utime(filename)
         st3 = os.stat(filename)
-        self.assertAlmostEqual(attr(st2, "st_mtime"), attr(st3, "st_mtime"), delta=delta)
+        self.assertAlmostEqual(
+            attr(st2, "st_mtime"),
+            attr(st3, "st_mtime"),
+            delta=delta
+        )
 
     def test_utime(self):
         def utime(file, times):


test_os passes on FreeBSD, Linux and Mac OS X with that applied.  However, the Solaris 10/SPARC box still fails:

AssertionError: 9.5367431640625e-07 not less than 2e-09

But it appears that build is actually picking up utimensat(), which makes the Solaris failures unrelated to the FreeBSD/NetBSD ones.  I'll do some more investigating.  Might warrant a separate issue.

Larry: thoughts on the test_os.patch as is?
msg173130 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-10-17 04:38
You're a sneaky, naughty bunny.  "posix._have_functions" indeed!  I guess your back was to the wall.

1)
If I follow your code correctly, when one has utimensat, the assertLess calls using _t consider st0.st_mtime_ns < st1.st_mtime_ns even if the left operand is (2e18-1) greater than the right.  It divides both operands by 1e9, then checks whether their delta is < 2e9.  In nanoseconds, 2e18-1 is roughly 63.5 years.  The case where one doesn't have utimensat but do have utimens is similarly generous.  Little wonder the test now passes!  Could you narrow down the range a little?

2)
I'd prefer if you amended the comment rather than remove it, perhaps adding

# (assuming your read and write functions both take the same units,
# which isn't true on all platforms--some Solaris and FreeBSD versions
# can read ns time but can only write ms time)

3)
Could you please find better names than "_t", "l", and "r"?

4)
In the future, please upload a patch as an attached file rather than as an inline comment.  This will permit me to use the bug tracker's built-in  Reitveld to examine the diff, which is more comfortable and permits inline comments.
msg173131 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 05:46
Thanks for the feedback Larry; yeah that patch definitely wasn't intended to be "production quality" -- more of a proof of concept.  I agree with your points, they'll be factored into the next patch.

However, I'm absolutely baffled by the Solaris 10 failure.  The more I looked into it, the weirder it got.  The issue is always the same:

    self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
AssertionError: 1347752941.275297 != 1347752941.275296

That is, test_utime() always results in a st1.st_mtime that is "off-by-1" from st0.st_mtime.  The precision is well within the nanasecond resolution offered by utimensat, so it doesn't appear to be the same issue experienced by other platforms.

I'll have to break into the debugger again and see what's going on.

Side note: I noticed this comment/code just above _test_utime():

    def test_utime_dir(self):
        delta = 1000000
        st = os.stat(support.TESTFN)
        # round to int, because some systems may support sub-second
        # time stamps in stat, but not in utime.
        os.utime(support.TESTFN, (st.st_atime, int(st.st_mtime-delta)))
        st2 = os.stat(support.TESTFN)
        self.assertEqual(st2.st_mtime, int(st.st_mtime-delta))

That... seems to (albeit vaguely) describe what's going on here with Solaris 10.  I also noticed support.TESTFN is actually a directory in this test case.  Again, I'm not sure how that fits in with test_utime_dir() versus a second invocation of _test_utime(support.TESTFN) from test_utime().

test_utime_dir() is ultra-lax, test_utime() is ultra-strict, I'm not sure which one should be updated to match the other.
msg173132 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 05:52
Oh, and another "quirk" I noticed yesterday.  I usually religiously disable atime on all my filesystems.  For whatever reason, it's not disabled on this Solaris 10 box.

Turns out os.stat() was updating st_atime, which kind of throws a spanner in the works for all our st_atime tests in _test_utime() -- we call os.stat() after utime() to check that our atime update worked -- but the stat call results in another st_atime update.
msg173148 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2012-10-17 09:49
I don't know POSIX / UNIX all that well.  Does it require that a stat call updates atime?  Because that's one of those "how does it ever work" head-scratchers.  (Maybe everybody always disables atime these days?  I don't think I do.)
msg173149 - (view) Author: Antoine Pitrou (pitrou) * (Python committer) Date: 2012-10-17 09:55
> I don't know POSIX / UNIX all that well.  Does it require that a stat
> call updates atime?  Because that's one of those "how does it ever
> work" head-scratchers.  (Maybe everybody always disables atime these
> days?  I don't think I do.)

I think most Linux distributions disable it for you; or, rather, they
use the "relatime" mount option which is a smart cheat:

relatime
    Update  inode  access  times  relative  to  modify  or change time.
    Access time is only updated if the previous access time was earlier
    than  the  current  modify or change time. (Similar to noatime, but
    doesn't break mutt or other applications that need  to  know  if  a
    file has been read since the last time it was modified.)
msg173150 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 09:57
Re: "how did it ever work"... on Solaris, because of the st_mtime failure, it doesn't even get a chance to fail on the subsequent st_atime.  I suspect the only platform that's exercised the utimensat() to date is Linux, and either a) os.stat() doesn't affect atime on Linux, b) everyone has atime disabled, c) the two stat calls happen quick enough that no measurable difference is observed against st_atime.

As for POSIX:

http://pubs.opengroup.org/onlinepubs/9699919799/toc.htm

"The fstat() function shall update any time-related fields (as described in XBD File Times Update ), before writing into the stat structure."

The referenced section:

4.8 File Times Update

Each file has three distinct associated timestamps: the time of last data access, the time of last data modification, and the time the file status last changed. These values are returned in the file characteristics structure struct stat, as described in <sys/stat.h> .

Each function or utility in POSIX.1-2008 that reads or writes data (even if the data does not change) or performs an operation to change file status (even if the file status does not change) indicates which of the appropriate timestamps shall be marked for update. If an implementation of such a function or utility marks for update one of these timestamps in a place or time not specified by POSIX.1-2008, this shall be documented, except that any changes caused by pathname resolution need not be documented. For the other functions or utilities in POSIX.1-2008 (those that are not explicitly required to read or write file data or change file status, but that in some implementations happen to do so), the effect is unspecified.

An implementation may update timestamps that are marked for update immediately, or it may update such timestamps periodically. At the point in time when an update occurs, any marked timestamps shall be set to the current time and the update marks shall be cleared. All timestamps that are marked for update shall be updated when the file ceases to be open by any process or before a fstat(), fstatat(), fsync(), futimens(), lstat(), stat(), utime(), utimensat(), or utimes() is successfully performed on the file. Other times at which updates are done are unspecified. Marks for update, and updates themselves, shall not be done for files on read-only file systems; see Read-Only File System .

The resolution of timestamps of files in a file system is implementation-defined, but shall be no coarser than one-second resolution. The three timestamps shall always have values that are supported by the file system. Whenever any of a file's timestamps are to be set to a value V according to the rules of the preceding paragraphs of this section, the implementation shall immediately set the timestamp to the greatest value supported by the file system that is not greater than V.
msg173151 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-17 10:05
Here's a thought...  why not alter the test to work with fixed times and separate the atime tests from the mtime tests.

For atime, we can set utime(filename, (0.0, ...)) and see if a subsequent os.stat() returns st_atime as 0.0 -- that'll tell us whether or not atime is affected.

For the mtime tests, rather than having a variable UTIME_EPSILON, just have fixed dates that match the expected precision of the underlying platform?
msg173337 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-19 13:04
Larry and I just chatted about this on IRC.  Summary:

 1.)  I was wrong about os.stat() affecting atime.  I fired up a
      console session on Solaris to "prove" my atime observation
      only to find os.stat() had no impact on atime:

        % ./python
        Python 2.7.3+ (2.7:90a46f8943d0, Oct 18 2012, 11:09:15) [C] on sunos5
        Type "help", "copyright", "credits" or "license" for more information.
        >>> import os
        >>> fname = 'configure'
        >>> st0 = os.stat(fname)
        >>> os.utime(fname, (st0.st_atime, st0.st_mtime))
        >>> st0.st_atime
        1350571183.474864
        >>> st1 = os.stat(fname)
        >>> st1.st_atime
        1350571183.474864

      So, we can ignore my "but os.stat() affects atime!" noise
      earlier in this report.

 2.)  Regardless of the underlying platform, the unit tests should
      test utime() with nano, micro and second resolution.  However,
      the tests should be cognizant of the underlying platform's
      os.stat() versus os.utime() resolution when testing the actual
      results.

      That is, if you pass a nanosecond time to os.utime() on a platform
      that doesn't have underlying nanosecond support for utime (i.e. no
      utimensat()), then expect a microsecond resolution time back from
      stat().

 3.)  Regarding fixed times versus re-setting the first results of our
      stat() call: no strong opinion either way -- the main objective
      is to ensure the tests have good coverage and are robust.  So
      whatever gets the job done.
msg173341 - (view) Author: Trent Nelson (trent) * (Python committer) Date: 2012-10-19 13:18
On Tue, Oct 16, 2012 at 10:46:34PM -0700, Trent Nelson wrote:
> 
> Trent Nelson added the comment:
> 
> Thanks for the feedback Larry; yeah that patch definitely wasn't
> intended to be "production quality" -- more of a proof of concept.  I
> agree with your points, they'll be factored into the next patch.
> 
> However, I'm absolutely baffled by the Solaris 10 failure.  The more I
> looked into it, the weirder it got.  The issue is always the same:
> 
>     self.assertEqual(attr(st0, "st_mtime"), attr(st1, "st_mtime"))
>     AssertionError: 1347752941.275297 != 1347752941.275296
> 
> That is, test_utime() always results in a st1.st_mtime that is
> "off-by-1" from st0.st_mtime.  The precision is well within the
> nanasecond resolution offered by utimensat, so it doesn't appear to be
> the same issue experienced by other platforms.

    I've concluded that the problem on Solaris is actually unrelated
    to the original failures on FreeBSD and NetBSD that this issue
    was raised for (where os.stat() returns nanosecond resolution but
    os.utime() only accepts microsecond).

    I've raised a separate bug for this issue: #16287.
msg176881 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2012-12-04 08:46
I didn't read the whole issue, but the following code makes sense.

+try:
+    import posix
+except ImportError:
+    # Windows has nanosecond utime resolution.
+    UTIME_EPSILON = 2e-9
+else:
+    import sysconfig
+    if 'HAVE_UTIMENSAT' in posix._have_functions:
+        UTIME_EPSILON = 2e-9
+    elif 'HAVE_UTIMES' in sysconfig.get_config_vars():
+        UTIME_EPSILON = 2e-6
+    else:
+        UTIME_EPSILON = 1.0

Windows doesn't really have nanosecond resolution: the common Windows unit is 100 ns. See GetFileInformationByHandle() documentation: its BY_HANDLE_FILE_INFORMATION  structure has FILETIME fields, and FILETIME uses the 100 ns unit.

We might expose this unit (UTIME_EPSILON, in the os module maybe?) as we done for time function with time.get_clock_info().
msg187495 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2013-04-21 06:46
There's some work that's been in the FreeBSD bleachers since Jul 2012 to add futimens() and utimensat(), with some recent activity:

RFC: futimens(2) and utimensat(2) - Jul 2012
http://lists.freebsd.org/pipermail/freebsd-arch/2012-February/012409.html 

RFC: futimens(2) and utimensat(2) - Jan 2013
http://lists.freebsd.org/pipermail/freebsd-arch/2013-January/013903.html 

I've also recently been made aware of a vfs.timestamp_precision sysctl and tested adjusting it from it's default of 0 -> 3, without success:

sysctl -d vfs.timestamp_precision
vfs.timestamp_precision: File timestamp precision (0: seconds, 1: sec + ns accurate to 1/HZ, 2: sec + ns truncated to ms, 3+: sec + ns (max. precision))

I'll do my best at this end to encourage the above implementation to be committed and request merges to other branches of FreeBSD (likely just 9-STABLE)

In the meantime however, what can be done in the short-term to either tweak the tests so they pass or account for the difference in implementations?

The current test failures on the buildbots make it difficult at best to ensure core developers are being notified or exposed to other regressions and issues that have cropped up in recent months.
msg190076 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2013-05-26 11:08
I've moved both of the FreeBSD buildbot slaves off their ZFS-backed home directories and back to good old UFS.

I want to ensure FreeBSD support continues to improve, and having slaves get noticed when they fail or regress with ongoing development is a big part of that.

This is hard to achieve without movement on this issue, either in the form of a conditional skip, workaround or ultimate resolution
msg190077 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2013-05-26 11:15
I'm happy to move them back upon request, or create a FreeBSD/ZFS buildslave specially for the job, just let me know.
msg221252 - (view) Author: Mark Lawrence (BreamoreBoy) * Date: 2014-06-22 13:35
Could we have a formal review of the patch please as Victor seemed fairly happy with it in msg176881.  Note that #16287 also refers to this issue.
msg224791 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2014-08-05 01:16
Those interested in this issue might also be interested in #19838, in which I demonstrate that utime(path, NULL) can set mtime to an *earlier* time on ZFS on Linux.
msg241710 - (view) Author: Harrison Grundy (harrison.grundy) Date: 2015-04-21 09:45
The attached patch just explicitly cuts precision down for the test. It may be worth adding code to set "delta" to the expected level of precision for a given platform, rather than just universally saying "Microseconds are okay."
msg245163 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2015-06-11 12:37
I have tested both patches (test_os by trent) and almostequaltime by harrison on the default branch, and *both* result in test_os passing.

They also resolve the test_utime failure reported in bug 24175 and very likely 16287 (born from this issue)
msg245164 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2015-06-11 12:38
Hmm, that was supposed to be: issue 24175 and very likely issue 16287
msg245168 - (view) Author: Larry Hastings (larry) * (Python committer) Date: 2015-06-11 14:30
Of the two I prefer Harrison Grundy's patch, simply because it's shorter.

What OS / filesystem did you run the test on, koobs?
msg245169 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2015-06-11 14:40
Larry: The same two hosts that the FreeBSD Python buildslaves run on :)
msg245170 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2015-06-11 14:41
Additionally on koobs-freebsd9, in my home directory (which is on ZFS)

The buildbot home directories are on UFS
msg245171 - (view) Author: R. David Murray (r.david.murray) * (Python committer) Date: 2015-06-11 14:54
Note that the shorter patch means that the test is not actually testing what the comments say it is testing, so either the comments should admit we are checking that the result is "something close to what we set", or the longer fix should be used so as to continue to use the more rigorous test on platforms that support it.  Ideally the latter.
msg245174 - (view) Author: Kubilay Kocak (koobs) (Python triager) Date: 2015-06-11 15:25
Can a test be made to show a message (similar to a skipIf reason=) mentioning that a reduced precision is being used for certain tests?

It would be nice not to have to remember this issue as platform support changes (reads: improves) over time.

Not withstanding, it's also apparent that there may be an underlying rounding bug or race condition that ultimately causes some of the assertions in this tests to be false, which is the premise behind Harrisons assertAlmostEqual patch (matching other tests)
msg245192 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-11 22:04
almostequaltime.diff is wrong: it allows a different of 10 seconds, whereas the issue is a difference of less than 1000 nanoseconds.

test_os.patch looks more correct, but I didn't review the patch.
msg245196 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-11 22:27
The resolution of os.utime()+os.stat() depends on two things:

- resolution of the timestamp on the filesystem used to run test_os (where TESTFN is written)
- resolution of the C internal function used by os.utime()

os.utime() can have a resolution of 1 ns (ex: it's usually the case on Linux), whereas the FAT filesystem has as resolution of 2 seconds.

os.utime() can have a resolution of 1 us (ex: FreeBSD) whereas the ZFS filesystem has a resolution of 1 ns.

Currently, test_os.test_*utime*_ns checks that os.utime() is able to copy the timestamp of a file 1 to a file 2. Problem: we don't know the resolution of the timestamp of the file 2. We can get the resolution of the C internal function used by os.utime(). It is implemented in the attached test_os.patch. But it's much more complex to get the timestamp resolution of the filesystem, in a portable way.

Random thoughts:

* use a timestamp with a resolution of 1 us, smaller than 2^24 to avoid rounding issues. Example: (atime=1.002003, mtime=4.005006)?

* compute the effective utime resolution: call os.utime() with a well known timestamp with a resolution of 1 nanosecond (smaller than 2^24 to avoid rounding issues) and call os.stat() to check which digits were preserved

test_os must not depend too much on the filesystem. I don't think that we should implement complex code just to check a simple field in the os.stat_result structure. The first idea (call utime with a fixed number, don't rely on an unknown file timestamp) is probably enough.
msg245199 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-11 22:55
test_utime_ns.patch: rewrite _test_utime_ns(). It now uses constant timestamps for atime and mtime with a resolution of 1 us.

The test will fail if the internal function of os.utime() has a resolution of 1 sec (utime() with time_t) of if the resolution of filesystem timestamp is worse than 1 us.

In practice on buildbots, it looks like the effective resolution of 1 us (FreeBSD, Solaris), 100 ns (Windows) or 1 ns (Linux). So 1 us should work on all buildbot slaves.

test_utime_ns.patch doesn't call os.utime() on directories, only on a regular file. I don't understand the purpose of testing with a directory. Are we testing the OS or Python?
msg245202 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-12 00:39
test_utime.patch: a much larger patch which rewrites all unit tests on os.utime().

Changes:

* Use a fixed timestamp instead of copying timestamps from an existing file. If the timestamp of the original file can have a resolution of 1 nanosecond, os.utime() rounds to a resolution of 1 us on some platforms (when the C function uses a structure with a resolutionf of 1 us).
* Use a fixed timestamp with a resolution of 1 us instead of a resolution of 1 ms.
* Remove test_1565150(): it's now redundant with test_utime() and many other test_utime_*() tests
* Use self.fname instead of __file__ to check if the filesystem supports subsecond resolution: these two files may be in two different filesystems
* test_large_time() now checks the filesystem when it is executed, not when the class is defined. This change is to ensure that we are testing the right filesystem.
* replace support.TESTFN with self.dirname for readability
* move all os.utime() tests in a new dedicated class
* _test_utime_current() now get the system clock using time.time() and tolerate a delta of 10 ms instead of 10 seconds: we may increase the delta because of slow buildbots, but I hope that we can find a value smaller than 10 seconds!
* Avoid tricky getattr(), it's no more needed
* Merge duplicated test_utime_*() and test_utime_subsecond_*() functions
* Test also st_atime on when testing os.utime() on a directory
* etc.
msg245260 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2015-06-12 15:48
New changeset 4335d898be59 by Victor Stinner in branch 'default':
Issue #15745: Rewrite os.utime() tests in test_os
https://hg.python.org/cpython/rev/4335d898be59
msg245261 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-12 15:54
I pushed test_utime.patch with minor updates:

* _test_utime_current() now also checks if the FS supports subsecond
* use a delta of 20 ms in _test_utime_current(), instead of 10 ms, for Windows

I will wait for FreeBSD and Solaris buildbots to see if my changes fixes failures on os.utime() tests. If it's a success, I will backport the change to Python 3.4.
msg245272 - (view) Author: Roundup Robot (python-dev) (Python triager) Date: 2015-06-12 20:03
New changeset 50ec3fb126dd by Victor Stinner in branch '3.4':
Issue #15745: Rewrite os.utime() tests in test_os
https://hg.python.org/cpython/rev/50ec3fb126dd

New changeset 744c96cd57da by Victor Stinner in branch '3.5':
(Merge 3.4) Issue #15745: Rewrite os.utime() tests in test_os
https://hg.python.org/cpython/rev/744c96cd57da
msg245273 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-12 20:08
I applied the fix to Python 3.4 and 3.5 too.

Python 2.7 doesn't look to be affected by the issue, I don't see any test copying the timestamp of a file to another, nor test on timestamp using nanosecond resolution.
msg245425 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-06-16 21:11
The issue looks to be fixed on Python 3.4, 3.5 and 3.6. I checked quickly buildbots. I close the issue.
msg245455 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-06-18 07:01
The commit causes test_os to emit DeprecationWarning warnings, which it didn’t before:

[vadmium@localhost cpython]$ hg update 4335d898be59
0 files updated, 0 files merged, 0 files removed, 0 files unresolved
[vadmium@localhost cpython]$ ./python -bWdefault -m test test_os
[1/1] test_os
/media/disk/home/proj/python/cpython/Lib/unittest/case.py:638: DeprecationWarning: stat_float_times() is deprecated
  function(*args, **kwargs)
[× 11 . . .]
msg246960 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-07-20 05:22
This patch defeats the warnings
msg246989 - (view) Author: STINNER Victor (vstinner) * (Python committer) Date: 2015-07-20 13:25
Can you please open a new issue for stat-times-deprecated.patch?
msg246996 - (view) Author: Martin Panter (martin.panter) * (Python committer) Date: 2015-07-20 14:19
Okay, now at Issue 24675
History
Date User Action Args
2015-07-20 14:19:32martin.pantersetstatus: open -> closed

messages: + msg246996
2015-07-20 14:05:56martin.pantersetfiles: - stat-times-deprecated.patch
2015-07-20 13:25:53vstinnersetmessages: + msg246989
2015-07-20 05:23:00martin.pantersetstatus: closed -> open
files: + stat-times-deprecated.patch
messages: + msg246960
2015-06-18 07:01:52martin.pantersetnosy: + martin.panter
messages: + msg245455
2015-06-16 21:11:28vstinnersetstatus: open -> closed
resolution: fixed
messages: + msg245425
2015-06-13 04:14:23zach.warelinkissue24175 superseder
2015-06-12 20:08:18vstinnersetmessages: + msg245273
versions: - Python 2.7
2015-06-12 20:03:52python-devsetmessages: + msg245272
2015-06-12 15:54:09vstinnersetmessages: + msg245261
2015-06-12 15:48:38python-devsetnosy: + python-dev
messages: + msg245260
2015-06-12 00:39:41vstinnersetfiles: + test_utime.patch

messages: + msg245202
2015-06-11 22:55:47vstinnersetfiles: + test_utime_ns.patch

messages: + msg245199
2015-06-11 22:27:56vstinnersetmessages: + msg245196
2015-06-11 22:04:10vstinnersetmessages: + msg245192
2015-06-11 15:25:25koobssetmessages: + msg245174
2015-06-11 14:54:14r.david.murraysetnosy: + r.david.murray
messages: + msg245171
2015-06-11 14:41:19koobssetmessages: + msg245170
2015-06-11 14:40:01koobssetmessages: + msg245169
2015-06-11 14:30:09larrysetmessages: + msg245168
2015-06-11 12:38:54koobssetmessages: + msg245164
2015-06-11 12:37:16koobssetmessages: + msg245163
versions: + Python 3.6
2015-04-21 09:47:24koobssetkeywords: + needs review
components: + Tests
stage: needs patch -> patch review
2015-04-21 09:45:17harrison.grundysetfiles: + almostequaltime.diff
nosy: + harrison.grundy
messages: + msg241710

2015-01-17 02:24:37terry.reedysetversions: + Python 3.4, Python 3.5, - Python 3.2, Python 3.3
2014-08-05 01:16:09larrysetmessages: + msg224791
title: Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS) -> Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
2014-06-22 13:35:45BreamoreBoysetnosy: + BreamoreBoy
messages: + msg221252
2014-05-13 22:14:54skrahsetnosy: - skrah
2013-11-05 17:08:25Claudiu.Popasetnosy: + Claudiu.Popa
2013-05-27 13:34:17emastesetnosy: + emaste
2013-05-26 11:15:01koobssetmessages: + msg190077
2013-05-26 11:08:14koobssetmessages: + msg190076
2013-04-21 06:46:22koobssetnosy: + koobs
messages: + msg187495
2012-12-05 12:15:26jceasetnosy: + jcea
2012-12-04 08:46:58vstinnersetnosy: + vstinner
messages: + msg176881
2012-10-19 13:18:08trentsetmessages: + msg173341
title: Numerous utime ns tests fail on FreeBSD w/ ZFS -> Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
2012-10-19 13:04:32trentsetmessages: + msg173337
title: Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS) -> Numerous utime ns tests fail on FreeBSD w/ ZFS
2012-10-17 10:05:21trentsetmessages: + msg173151
2012-10-17 09:57:37trentsetmessages: + msg173150
2012-10-17 09:55:56pitrousetmessages: + msg173149
2012-10-17 09:49:30larrysetmessages: + msg173148
2012-10-17 05:52:56trentsetmessages: + msg173132
2012-10-17 05:46:34trentsetmessages: + msg173131
2012-10-17 04:38:16larrysetmessages: + msg173130
2012-10-16 21:40:48trentsetfiles: + test_os.patch
keywords: + patch
messages: + msg173102
2012-10-16 21:09:32Arfreversetnosy: + Arfrever
2012-10-16 21:03:48trentsetmessages: + msg173094
2012-10-16 20:59:02larrysetmessages: + msg173092
2012-10-16 20:04:44trentsetmessages: + msg173087
2012-09-18 12:58:57trentsettitle: Numerous utime ns tests fail on FreeBSD w/ ZFS -> Numerous utime ns tests fail on FreeBSD w/ ZFS (update: and NetBSD w/ FFS, Solaris w/ UFS)
2012-09-18 03:03:47trentsetmessages: + msg170631
2012-08-23 00:34:38larrysetmessages: + msg168911
2012-08-22 17:04:35pitrousetnosy: + pitrou
messages: + msg168898
2012-08-22 13:11:14trentsetmessages: + msg168883
2012-08-22 00:03:26trentsetmessages: + msg168828
2012-08-21 23:38:22larrysetmessages: + msg168822
2012-08-21 22:06:05trentsetmessages: + msg168811
2012-08-21 21:52:05larrysetmessages: + msg168808
2012-08-21 13:45:05skrahsetmessages: + msg168770
2012-08-21 13:00:27pitrousetnosy: + skrah
2012-08-21 11:51:24vstinnersetnosy: + larry
2012-08-21 02:15:34trentcreate