NetBSD Problem Report #49342

From www@NetBSD.org  Thu Oct 30 22:01:02 2014
Return-Path: <www@NetBSD.org>
Received: from mail.netbsd.org (mail.netbsd.org [149.20.53.66])
	(using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits))
	(Client CN "mail.netbsd.org", Issuer "Postmaster NetBSD.org" (verified OK))
	by mollari.NetBSD.org (Postfix) with ESMTPS id 9FA3CA65E9
	for <gnats-bugs@gnats.NetBSD.org>; Thu, 30 Oct 2014 22:01:02 +0000 (UTC)
Message-Id: <20141030220101.9FCCDA66A4@mollari.NetBSD.org>
Date: Thu, 30 Oct 2014 22:01:01 +0000 (UTC)
From: yaneurabeya@gmail.com
Reply-To: yaneurabeya@gmail.com
To: gnats-bugs@NetBSD.org
Subject: [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)
X-Send-Pr-Version: www-1.0

>Number:         49342
>Category:       misc
>Synopsis:       [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)
>Confidential:   no
>Severity:       non-critical
>Priority:       low
>Responsible:    misc-bug-people
>State:          closed
>Class:          sw-bug
>Submitter-Id:   net
>Arrival-Date:   Thu Oct 30 22:05:00 +0000 2014
>Closed-Date:    Tue Nov 11 08:45:37 +0000 2014
>Last-Modified:  Wed Apr 15 00:20:06 +0000 2015
>Originator:     Garrett Cooper
>Release:        n/a
>Organization:
EMC / Isilon Storage Division
>Environment:
n/a
>Description:
The lib/libc/gen/t_time:time_timeofday testcase works in most cases, but
if the clock rolls over between when time and gettimeofday are called, the value returned from time and the tv_sec value can vary between, as noted in one of our Kyua runs on FreeBSD:

Test case: lib/libc/gen/t_time:time_timeofday

    Test program: /var/crash/lib/libc/gen/t_time
    Result: failed: time(3) and gettimeofday(2) differ
    Duration: 0.093s
    Execution context

Metadata

    allowed_architectures =
    allowed_platforms =
    description = Test time(3) vs. gettimeofday(2)
    has_cleanup = false
    required_configs =
    required_files =
    required_memory = 0
    required_programs =
    required_user =
    timeout = 300

Standard output
Test case did not write anything to stdout.
Standard error

1414695298 vs. 1414695299

The testcase should have "fuzzing" built in so it allows for a maximum of 1 second difference between the two compared values.
>How-To-Repeat:

>Fix:

>Release-Note:

>Audit-Trail:
From: Justin Cormack <justin@specialbusservice.com>
To: gnats-bugs@netbsd.org
Cc: misc-bug-people@netbsd.org, gnats-admin@netbsd.org, netbsd-bugs@netbsd.org
Subject: Re: misc/49342: [test] lib/libc/gen/t_time.c is non-deterministic;
 compares set time vs current time (and can vary by a second under rare circumstances)
Date: Thu, 30 Oct 2014 22:45:48 +0000

 On Thu, Oct 30, 2014 at 10:05 PM,  <yaneurabeya@gmail.com> wrote:
 > The lib/libc/gen/t_time:time_timeofday testcase works in most cases, but
 > if the clock rolls over between when time and gettimeofday are called, the value returned from time and the tv_sec value can vary between, as noted in one of our Kyua runs on FreeBSD:
 >
 > Test case: lib/libc/gen/t_time:time_timeofday

 > The testcase should have "fuzzing" built in so it allows for a maximum of 1 second difference between the two compared values.

 It could be worse than 1s, worst case, as this is not a monotonic
 clock, and in either direction, in theory. Not a very good test, but I
 suppose if we change to 10s wither way its fairly safe...

 Justin

From: Dennis Ferguson <dennis.c.ferguson@gmail.com>
To: gnats-bugs@NetBSD.org
Cc: misc-bug-people@netbsd.org,
 gnats-admin@netbsd.org,
 netbsd-bugs@netbsd.org,
 yaneurabeya@gmail.com
Subject: Re: misc/49342: [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)
Date: Thu, 30 Oct 2014 15:59:17 -0700

 On 30 Oct, 2014, at 15:50 , Justin Cormack =
 <justin@specialbusservice.com> wrote:
 > On Thu, Oct 30, 2014 at 10:05 PM,  <yaneurabeya@gmail.com> wrote:
 >> The lib/libc/gen/t_time:time_timeofday testcase works in most cases, =
 but
 >> if the clock rolls over between when time and gettimeofday are =
 called, the value returned from time and the tv_sec value can vary =
 between, as noted in one of our Kyua runs on FreeBSD:
 >>=20
 >> Test case: lib/libc/gen/t_time:time_timeofday
 >=20
 >> The testcase should have "fuzzing" built in so it allows for a =
 maximum of 1 second difference between the two compared values.
 >=20
 > It could be worse than 1s, worst case, as this is not a monotonic
 > clock, and in either direction, in theory. Not a very good test, but I
 > suppose if we change to 10s wither way its fairly safe.

 I was going to say that the monotonic time() test in the same file
 was assuming that the time would never be wrong and in need of fixing,
 which doesn't match real life.

 For the other test it might be better to call time() after the call
 to gettimeofday(), as well as before, and only insist that =
 gettimeofday()
 match when the calls to time() have returned the same value.  This is
 also not quite perfect, but leaves some possibility of finding a problem
 by running the test with a fairly low probability of a false positive.

 Dennis Ferguson

From: "Justin Cormack" <justin@netbsd.org>
To: gnats-bugs@gnats.NetBSD.org
Cc: 
Subject: PR/49342 CVS commit: src/tests/lib/libc/gen
Date: Fri, 31 Oct 2014 12:22:38 +0000

 Module Name:	src
 Committed By:	justin
 Date:		Fri Oct 31 12:22:38 UTC 2014

 Modified Files:
 	src/tests/lib/libc/gen: t_time.c

 Log Message:
 PR misc/49342 fix issue where time can tick during tests

 Note there are still potential issues as the clock being tested is not
 monotonic but it should now not fail unless time is being adjusted.


 To generate a diff of this commit:
 cvs rdiff -u -r1.2 -r1.3 src/tests/lib/libc/gen/t_time.c

 Please note that diffs are not public domain; they are subject to the
 copyright notices on the relevant files.

From: Justin Cormack <justin@specialbusservice.com>
To: gnats-bugs@netbsd.org
Cc: misc-bug-people@netbsd.org, gnats-admin@netbsd.org, netbsd-bugs@netbsd.org, 
	yaneurabeya@gmail.com
Subject: Re: misc/49342: [test] lib/libc/gen/t_time.c is non-deterministic;
 compares set time vs current time (and can vary by a second under rare circumstances)
Date: Fri, 31 Oct 2014 12:27:15 +0000

 On Thu, Oct 30, 2014 at 10:05 PM,  <yaneurabeya@gmail.com> wrote:
 >>Number:         49342
 >>Category:       misc
 >>Synopsis:       [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)

 > The lib/libc/gen/t_time:time_timeofday testcase works in most cases, but
 > if the clock rolls over between when time and gettimeofday are called, the value returned from time and the tv_sec value can vary between, as noted in one of our Kyua runs on FreeBSD:

 This should be fixed now. The issues that these clocks are not
 monotonic are still there, but should generally not be an issue.

 Thanks for the report!

 Justin

From: Garrett Cooper <yaneurabeya@gmail.com>
To: Justin Cormack <justin@specialbusservice.com>
Cc: "gnats-bugs@netbsd.org" <gnats-bugs@netbsd.org>,
 "misc-bug-people@netbsd.org" <misc-bug-people@netbsd.org>,
 "gnats-admin@netbsd.org" <gnats-admin@netbsd.org>,
 "netbsd-bugs@netbsd.org" <netbsd-bugs@netbsd.org>
Subject: Re: misc/49342: [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)
Date: Fri, 31 Oct 2014 09:23:58 -0700

 > On Oct 31, 2014, at 05:27, Justin Cormack <justin@specialbusservice.com> w=
 rote:
 >=20
 > On Thu, Oct 30, 2014 at 10:05 PM,  <yaneurabeya@gmail.com> wrote:
 >>> Number:         49342
 >>> Category:       misc
 >>> Synopsis:       [test] lib/libc/gen/t_time.c is non-deterministic; compa=
 res set time vs current time (and can vary by a second under rare circumstan=
 ces)
 >=20
 >> The lib/libc/gen/t_time:time_timeofday testcase works in most cases, but
 >> if the clock rolls over between when time and gettimeofday are called, th=
 e value returned from time and the tv_sec value can vary between, as noted i=
 n one of our Kyua runs on FreeBSD:
 >=20
 > This should be fixed now. The issues that these clocks are not
 > monotonic are still there, but should generally not be an issue.
 >=20
 > Thanks for the report!

 Thank you for the help!=

State-Changed-From-To: open->closed
State-Changed-By: dholland@NetBSD.org
State-Changed-When: Tue, 11 Nov 2014 08:45:37 +0000
State-Changed-Why:
fixed last week


From: NGie Cooper <yaneurabeya@gmail.com>
To: "gnats-bugs@NetBSD.org" <gnats-bugs@netbsd.org>
Cc: "misc-bug-people@netbsd.org" <misc-bug-people@netbsd.org>, 
	"netbsd-bugs@netbsd.org" <netbsd-bugs@netbsd.org>, "gnats-admin@netbsd.org" <gnats-admin@netbsd.org>, dholland@netbsd.org
Subject: Re: misc/49342 ([test] lib/libc/gen/t_time.c is non-deterministic;
 compares set time vs current time (and can vary by a second under rare circumstances))
Date: Tue, 14 Apr 2015 17:16:22 -0700

 On Tue, Nov 11, 2014 at 12:45 AM,  <dholland@netbsd.org> wrote:
 > Synopsis: [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)
 >
 > State-Changed-From-To: open->closed
 > State-Changed-By: dholland@NetBSD.org
 > State-Changed-When: Tue, 11 Nov 2014 08:45:37 +0000
 > State-Changed-Why:
 > fixed last week

 This fix works better, but unfortunately in FreeBSD's case, adjkerntz
 -a plays around with the system time via crond, and the testcase
 failed again (it took 7 seconds to adjust the time), because things
 happened at the right moment and were slow enough to catch a time jump
 because of the debugging features we have enabled in our kernel.

 From /var/log/cron on the VM where the failure occurred:

 # grep -r 02:01 /var/log/
 /var/log/cron:2015-04-14T02:01:00-07:00 <9.6> VBOX6672-1(id1)
 /usr/sbin/cron[44778]: (root) CMD (adjkerntz -a)
 # grep -r adjkerntz /etc/crontab
 # See adjkerntz(8) for details.
 1,31    0-5    *    *    *    root    adjkerntz -a

 The Time derived from the kyua logs was as follows:

 1428829260 vs. 1428829261

 % python -c 'import time; print time.ctime(1428829260)'
 Sun Apr 12 02:01:00 2015

 So, as you can see, the time that the test ran was at the tail end of
 the adjkerntz -a call according to crond(8) :/...

 Are there any thoughts on fixing this further (should the threshold be
 increased? should things be left alone? etc)?

 Thanks!

From: NGie Cooper <yaneurabeya@gmail.com>
To: "gnats-bugs@NetBSD.org" <gnats-bugs@netbsd.org>
Cc: "misc-bug-people@netbsd.org" <misc-bug-people@netbsd.org>, 
	"netbsd-bugs@netbsd.org" <netbsd-bugs@netbsd.org>, "gnats-admin@netbsd.org" <gnats-admin@netbsd.org>, dholland@netbsd.org
Subject: Re: misc/49342 ([test] lib/libc/gen/t_time.c is non-deterministic;
 compares set time vs current time (and can vary by a second under rare circumstances))
Date: Tue, 14 Apr 2015 17:17:38 -0700

 On Tue, Apr 14, 2015 at 5:16 PM, NGie Cooper <yaneurabeya@gmail.com> wrote:
 > On Tue, Nov 11, 2014 at 12:45 AM,  <dholland@netbsd.org> wrote:
 >> Synopsis: [test] lib/libc/gen/t_time.c is non-deterministic; compares set time vs current time (and can vary by a second under rare circumstances)
 >>
 >> State-Changed-From-To: open->closed
 >> State-Changed-By: dholland@NetBSD.org
 >> State-Changed-When: Tue, 11 Nov 2014 08:45:37 +0000
 >> State-Changed-Why:
 >> fixed last week
 >
 > This fix works better, but unfortunately in FreeBSD's case, adjkerntz
 > -a plays around with the system time via crond, and the testcase
 > failed again (it took 7 seconds to adjust the time), because things
 > happened at the right moment and were slow enough to catch a time jump
 > because of the debugging features we have enabled in our kernel.
 >
 > From /var/log/cron on the VM where the failure occurred:
 >
 > # grep -r 02:01 /var/log/
 > /var/log/cron:2015-04-14T02:01:00-07:00 <9.6> VBOX6672-1(id1)
 > /usr/sbin/cron[44778]: (root) CMD (adjkerntz -a)
 > # grep -r adjkerntz /etc/crontab
 > # See adjkerntz(8) for details.
 > 1,31    0-5    *    *    *    root    adjkerntz -a
 >
 > The Time derived from the kyua logs was as follows:
 >
 > 1428829260 vs. 1428829261
 >
 > % python -c 'import time; print time.ctime(1428829260)'
 > Sun Apr 12 02:01:00 2015
 >
 > So, as you can see, the time that the test ran was at the tail end of
 > the adjkerntz -a call according to crond(8) :/...

 I meant to say "at the start", not "tail end".

>Unformatted:

Home	PR Database Search