hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[Andreas Henriksson]

Hello!

The below forwarded issue seems to have been introduced in
commit ab8f402952301106ad0bd5c5a51dc
"hwclock: don't confuse users with select() timeout warning"

This issue is also tracked at http://bugs.debian.org/782726

Regards,
Andreas Henriksson

----- Forwarded message from Serge Schneider <serge@raspberrypi.org> -----

Date: Thu, 16 Apr 2015 20:24:26 +0100
From: Serge Schneider <serge@raspberrypi.org>
To: submit@bugs.debian.org
Subject: Bug#782726: util-linux: hwclock's synchronize_to_clock_tick_rtc
	returns inconsistent values
User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101
	Thunderbird/31.6.0

Package: util-linux
Version: 2.25.2-6
Severity: normal

Dear Maintainer,
                        rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
                        ret = 1;
                        if (rc == -1)
                                warn(_("select() to %s to wait for clock tick
failed"),
                                     rtc_dev_name);
                        else if (rc == 0 && debug)
                                printf(_("select() to %s to wait for clock
tick timed out"),
                                     rtc_dev_name);
                        else
                                ret = 0;

When 'select' times out and returns 0, synchronize_to_clock_tick_rtc returns
either 1 or 0, depnding on whether the -D option (debug) was used. This causes
hwclock -r to succeed and hwclock -r -D to return an error. In one case, it
just fails, in the other, the values are off by the timeout period (10
seconds, in this version).

pi@test-pi ~/dev/util-linux-2.25.2 $ sudo ./hwclock -r
Thu 16 Apr 2015 19:18:44 UTC  -10.016913 seconds
pi@test-pi ~/dev/util-linux-2.25.2 $ sudo ./hwclock -r -D
hwclock from util-linux 2.25.2
Using the /dev interface to the clock.
Last drift adjustment done at 1429205484 seconds after 1969
Last calibration done at 1429205484 seconds after 1969
Hardware clock is on UTC time
Assuming hardware clock is kept in UTC time.
Waiting for clock tick...
select() to /dev/rtc0 to wait for clock tick timed out...synchronization
failed

----- End forwarded message -----

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[J William Piggott]

On 04/16/2015 04:36 PM, Andreas Henriksson wrote:
> Hello!
> 
> The below forwarded issue seems to have been introduced in
> commit ab8f402952301106ad0bd5c5a51dc
> "hwclock: don't confuse users with select() timeout warning"
> 
> This issue is also tracked at http://bugs.debian.org/782726
> 
> Regards,
> Andreas Henriksson
> 
> ----- Forwarded message from Serge Schneider <serge@raspberrypi.org> -----
> 
> Date: Thu, 16 Apr 2015 20:24:26 +0100
> From: Serge Schneider <serge@raspberrypi.org>
> To: submit@bugs.debian.org
> Subject: Bug#782726: util-linux: hwclock's synchronize_to_clock_tick_rtc
> 	returns inconsistent values
> User-Agent: Mozilla/5.0 (X11; Linux x86_64; rv:31.0) Gecko/20100101
> 	Thunderbird/31.6.0
> 
> Package: util-linux
> Version: 2.25.2-6
> Severity: normal
> 
> Dear Maintainer,
>                         rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
>                         ret = 1;
>                         if (rc == -1)
>                                 warn(_("select() to %s to wait for clock tick
> failed"),
>                                      rtc_dev_name);
>                         else if (rc == 0 && debug)
>                                 printf(_("select() to %s to wait for clock
> tick timed out"),
>                                      rtc_dev_name);
>                         else
>                                 ret = 0;
>

Karel,

The select time out still needs to return 1, so the debug test should
have been a separate statement.

I don't have time to patch and test this right now, but I can do it
later if you want?


> When 'select' times out and returns 0, synchronize_to_clock_tick_rtc returns
> either 1 or 0, depnding on whether the -D option (debug) was used. This causes
> hwclock -r to succeed and hwclock -r -D to return an error. In one case, it
> just fails, in the other, the values are off by the timeout period (10
> seconds, in this version).
> 
> pi@test-pi ~/dev/util-linux-2.25.2 $ sudo ./hwclock -r
> Thu 16 Apr 2015 19:18:44 UTC  -10.016913 seconds
> pi@test-pi ~/dev/util-linux-2.25.2 $ sudo ./hwclock -r -D
> hwclock from util-linux 2.25.2
> Using the /dev interface to the clock.
> Last drift adjustment done at 1429205484 seconds after 1969
> Last calibration done at 1429205484 seconds after 1969
> Hardware clock is on UTC time
> Assuming hardware clock is kept in UTC time.
> Waiting for clock tick...
> select() to /dev/rtc0 to wait for clock tick timed out...synchronization
> failed
> 
> ----- End forwarded message -----
> --
> To unsubscribe from this list: send the line "unsubscribe util-linux" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[Karel Zak]

On Sun, Apr 19, 2015 at 08:16:08PM -0400, J William Piggott wrote:
> >                         rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
> >                         ret = 1;
> >                         if (rc == -1)
> >                                 warn(_("select() to %s to wait for clock tick
> > failed"),
> >                                      rtc_dev_name);
> >                         else if (rc == 0 && debug)
> >                                 printf(_("select() to %s to wait for clock
> > tick timed out"),
> >                                      rtc_dev_name);
> >                         else
> >                                 ret = 0;
> >
> 
> Karel,
> 
> The select time out still needs to return 1, so the debug test should
> have been a separate statement.

Yes, the debug (-D) should bot affect how this code works, but it
seems that hwclock.c:manipulate_clock() assumes return 2 after 
time out and we already use "2" in busy wait version of the
synchronization. 

> I don't have time to patch and test this right now, but I can do it
> later if you want?

See the patch below (note that patch also remove never used #ifdef
dead code).


diff --git a/sys-utils/hwclock-rtc.c b/sys-utils/hwclock-rtc.c
index 78f42aa..3173591 100644
--- a/sys-utils/hwclock-rtc.c
+++ b/sys-utils/hwclock-rtc.c
@@ -280,18 +280,6 @@ static int synchronize_to_clock_tick_rtc(void)
 				       rtc_dev_name);
 			ret = busywait_for_rtc_clock_tick(rtc_fd);
 		} else if (rc == 0) {
-#ifdef Wait_until_update_interrupt
-			unsigned long dummy;
-
-			/* this blocks until the next update interrupt */
-			rc = read(rtc_fd, &dummy, sizeof(dummy));
-			ret = 1;
-			if (rc == -1)
-				warn(_("read() to %s to wait for clock tick failed"),
-				     rtc_dev_name);
-			else
-				ret = 0;
-#else
 			/*
 			 * Just reading rtc_fd fails on broken hardware: no
 			 * update interrupt comes and a bootscript with a
@@ -310,15 +298,22 @@ static int synchronize_to_clock_tick_rtc(void)
 			tv.tv_usec = 0;
 			rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
 			ret = 1;
-			if (rc == -1)
+
+			switch (rc) {
+			case -1: /* error */
 				warn(_("select() to %s to wait for clock tick failed"),
 				     rtc_dev_name);
-			else if (rc == 0 && debug)
-				printf(_("select() to %s to wait for clock tick timed out"),
-				     rtc_dev_name);
-			else
+				break;
+			case 0: /* timeout */
+				if (debug)
+					printf(_("select() to %s to wait for clock tick timed out"),
+					     rtc_dev_name);
+				ret = 2;
+				break;
+			default: /* success */
 				ret = 0;
-#endif
+				break;
+			}
 
 			/* Turn off update interrupts */
 			rc = ioctl(rtc_fd, RTC_UIE_OFF, 0);

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[J William Piggott]

On 04/20/2015 08:21 AM, Karel Zak wrote:
> On Sun, Apr 19, 2015 at 08:16:08PM -0400, J William Piggott wrote:
>>>                         rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
>>>                         ret = 1;
>>>                         if (rc == -1)
>>>                                 warn(_("select() to %s to wait for clock tick
>>> failed"),
>>>                                      rtc_dev_name);
>>>                         else if (rc == 0 && debug)
>>>                                 printf(_("select() to %s to wait for clock
>>> tick timed out"),
>>>                                      rtc_dev_name);
>>>                         else
>>>                                 ret = 0;
>>>
>>
>> Karel,
>>
>> The select time out still needs to return 1, so the debug test should
>> have been a separate statement.
> 
> Yes, the debug (-D) should bot affect how this code works, but it
> seems that hwclock.c:manipulate_clock() assumes return 2 after 
> time out and we already use "2" in busy wait version of the
> synchronization. 
> 

Returning 2 will not fix this bug. When select times out, we need to
error out on everything except set functions (even that exception has
issues, because we need to also inhibit updating the drift factor then.
Nobody has complained about that so it is not a priority to fix. I will
look at it when refactoring).

hwclock.c:1326 should not be testing for "rc != 2", but that is for
Alpha so I am concerned about changing it now either.

Previous to the commit that caused this regression, the behavior was to
return 1, that was correct.

Removing the 'dead' code should be a separate commit from this
regression fix, IMHO.

I do not think two message strings justify using a switch, it is
inconsistent with the style of the rest of the code. I would just
separate the debug test for now:

diff --git a/sys-utils/hwclock-rtc.c b/sys-utils/hwclock-rtc.c
index 78f42aa..b5ecc5a 100644
--- a/sys-utils/hwclock-rtc.c
+++ b/sys-utils/hwclock-rtc.c
@@ -313,10 +313,11 @@ static int synchronize_to_clock_tick_rtc(void)
                        if (rc == -1)
                                warn(_("select() to %s to wait for clock tick failed"),
                                     rtc_dev_name);
-                       else if (rc == 0 && debug)
-                               printf(_("select() to %s to wait for clock tick timed out"),
-                                    rtc_dev_name);
-                       else
+                       else if (rc == 0) {
+                               if (debug)
+                                       printf(_("select() to %s to wait for clock tick timed out"),
+                                              rtc_dev_name);
+                       } else
                                ret = 0;
 #endif
 


I did some basic hwclock testing with the above patch, but I didn't come
up with a quick way to force the select time out to test this specific
change.


>> I don't have time to patch and test this right now, but I can do it
>> later if you want?
> 
> See the patch below (note that patch also remove never used #ifdef
> dead code).
> 
> 
> diff --git a/sys-utils/hwclock-rtc.c b/sys-utils/hwclock-rtc.c
> index 78f42aa..3173591 100644
> --- a/sys-utils/hwclock-rtc.c
> +++ b/sys-utils/hwclock-rtc.c
> @@ -280,18 +280,6 @@ static int synchronize_to_clock_tick_rtc(void)
>  				       rtc_dev_name);
>  			ret = busywait_for_rtc_clock_tick(rtc_fd);
>  		} else if (rc == 0) {
> -#ifdef Wait_until_update_interrupt
> -			unsigned long dummy;
> -
> -			/* this blocks until the next update interrupt */
> -			rc = read(rtc_fd, &dummy, sizeof(dummy));
> -			ret = 1;
> -			if (rc == -1)
> -				warn(_("read() to %s to wait for clock tick failed"),
> -				     rtc_dev_name);
> -			else
> -				ret = 0;
> -#else
>  			/*
>  			 * Just reading rtc_fd fails on broken hardware: no
>  			 * update interrupt comes and a bootscript with a
> @@ -310,15 +298,22 @@ static int synchronize_to_clock_tick_rtc(void)
>  			tv.tv_usec = 0;
>  			rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
>  			ret = 1;
> -			if (rc == -1)
> +
> +			switch (rc) {
> +			case -1: /* error */
>  				warn(_("select() to %s to wait for clock tick failed"),
>  				     rtc_dev_name);
> -			else if (rc == 0 && debug)
> -				printf(_("select() to %s to wait for clock tick timed out"),
> -				     rtc_dev_name);
> -			else
> +				break;
> +			case 0: /* timeout */
> +				if (debug)
> +					printf(_("select() to %s to wait for clock tick timed out"),
> +					     rtc_dev_name);
> +				ret = 2;
> +				break;
> +			default: /* success */
>  				ret = 0;
> -#endif
> +				break;
> +			}
>  
>  			/* Turn off update interrupts */
>  			rc = ioctl(rtc_fd, RTC_UIE_OFF, 0);
> 

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[J William Piggott]

Karel,

I pushed the patch to my repo, if you want to use it.


The following changes since commit a53e37f9d4c9b7b88f13e44f5c82a0ac92dbfd6a:

  sfdisk: don't use BLKRRPART to check loopdev usage (2015-04-17 10:32:48 +0200)

are available in the git repository at:

  git@github.com:jwpi/util-linux.git sync-err

for you to fetch changes up to 9fb890c3c5fccf9a9a02b251dfa5332f427d4c78:

  hwclock: remove dead code (2015-04-21 16:46:23 -0400)

----------------------------------------------------------------
J William Piggott (2):
      hwclock: regression fix
      hwclock: remove dead code

 sys-utils/hwclock-rtc.c | 23 +++++------------------
 1 file changed, 5 insertions(+), 18 deletions(-)



On 04/20/2015 10:50 PM, J William Piggott wrote:
> 
> 
> On 04/20/2015 08:21 AM, Karel Zak wrote:
>> On Sun, Apr 19, 2015 at 08:16:08PM -0400, J William Piggott wrote:
>>>>                         rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
>>>>                         ret = 1;
>>>>                         if (rc == -1)
>>>>                                 warn(_("select() to %s to wait for clock tick
>>>> failed"),
>>>>                                      rtc_dev_name);
>>>>                         else if (rc == 0 && debug)
>>>>                                 printf(_("select() to %s to wait for clock
>>>> tick timed out"),
>>>>                                      rtc_dev_name);
>>>>                         else
>>>>                                 ret = 0;
>>>>
>>>
>>> Karel,
>>>
>>> The select time out still needs to return 1, so the debug test should
>>> have been a separate statement.
>>
>> Yes, the debug (-D) should bot affect how this code works, but it
>> seems that hwclock.c:manipulate_clock() assumes return 2 after 
>> time out and we already use "2" in busy wait version of the
>> synchronization. 
>>
> 
> Returning 2 will not fix this bug. When select times out, we need to
> error out on everything except set functions (even that exception has
> issues, because we need to also inhibit updating the drift factor then.
> Nobody has complained about that so it is not a priority to fix. I will
> look at it when refactoring).
> 
> hwclock.c:1326 should not be testing for "rc != 2", but that is for
> Alpha so I am concerned about changing it now either.
> 
> Previous to the commit that caused this regression, the behavior was to
> return 1, that was correct.
> 
> Removing the 'dead' code should be a separate commit from this
> regression fix, IMHO.
> 
> I do not think two message strings justify using a switch, it is
> inconsistent with the style of the rest of the code. I would just
> separate the debug test for now:
> 
> diff --git a/sys-utils/hwclock-rtc.c b/sys-utils/hwclock-rtc.c
> index 78f42aa..b5ecc5a 100644
> --- a/sys-utils/hwclock-rtc.c
> +++ b/sys-utils/hwclock-rtc.c
> @@ -313,10 +313,11 @@ static int synchronize_to_clock_tick_rtc(void)
>                         if (rc == -1)
>                                 warn(_("select() to %s to wait for clock tick failed"),
>                                      rtc_dev_name);
> -                       else if (rc == 0 && debug)
> -                               printf(_("select() to %s to wait for clock tick timed out"),
> -                                    rtc_dev_name);
> -                       else
> +                       else if (rc == 0) {
> +                               if (debug)
> +                                       printf(_("select() to %s to wait for clock tick timed out"),
> +                                              rtc_dev_name);
> +                       } else
>                                 ret = 0;
>  #endif
>  
> 
> 
> I did some basic hwclock testing with the above patch, but I didn't come
> up with a quick way to force the select time out to test this specific
> change.
> 
> 
>>> I don't have time to patch and test this right now, but I can do it
>>> later if you want?
>>
>> See the patch below (note that patch also remove never used #ifdef
>> dead code).
>>
>>
>> diff --git a/sys-utils/hwclock-rtc.c b/sys-utils/hwclock-rtc.c
>> index 78f42aa..3173591 100644
>> --- a/sys-utils/hwclock-rtc.c
>> +++ b/sys-utils/hwclock-rtc.c
>> @@ -280,18 +280,6 @@ static int synchronize_to_clock_tick_rtc(void)
>>  				       rtc_dev_name);
>>  			ret = busywait_for_rtc_clock_tick(rtc_fd);
>>  		} else if (rc == 0) {
>> -#ifdef Wait_until_update_interrupt
>> -			unsigned long dummy;
>> -
>> -			/* this blocks until the next update interrupt */
>> -			rc = read(rtc_fd, &dummy, sizeof(dummy));
>> -			ret = 1;
>> -			if (rc == -1)
>> -				warn(_("read() to %s to wait for clock tick failed"),
>> -				     rtc_dev_name);
>> -			else
>> -				ret = 0;
>> -#else
>>  			/*
>>  			 * Just reading rtc_fd fails on broken hardware: no
>>  			 * update interrupt comes and a bootscript with a
>> @@ -310,15 +298,22 @@ static int synchronize_to_clock_tick_rtc(void)
>>  			tv.tv_usec = 0;
>>  			rc = select(rtc_fd + 1, &rfds, NULL, NULL, &tv);
>>  			ret = 1;
>> -			if (rc == -1)
>> +
>> +			switch (rc) {
>> +			case -1: /* error */
>>  				warn(_("select() to %s to wait for clock tick failed"),
>>  				     rtc_dev_name);
>> -			else if (rc == 0 && debug)
>> -				printf(_("select() to %s to wait for clock tick timed out"),
>> -				     rtc_dev_name);
>> -			else
>> +				break;
>> +			case 0: /* timeout */
>> +				if (debug)
>> +					printf(_("select() to %s to wait for clock tick timed out"),
>> +					     rtc_dev_name);
>> +				ret = 2;
>> +				break;
>> +			default: /* success */
>>  				ret = 0;
>> -#endif
>> +				break;
>> +			}
>>  
>>  			/* Turn off update interrupts */
>>  			rc = ioctl(rtc_fd, RTC_UIE_OFF, 0);
>>
> --
> To unsubscribe from this list: send the line "unsubscribe util-linux" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> 

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[Karel Zak]

On Tue, Apr 21, 2015 at 10:18:04PM -0400, J William Piggott wrote:
> I pushed the patch to my repo, if you want to use it.
 
 Merged, thanks.

-- 
 Karel Zak  <kzak@redhat.com>
 http://karelzak.blogspot.com

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[J William Piggott]

On 04/22/2015 03:46 AM, Karel Zak wrote:
> On Tue, Apr 21, 2015 at 10:18:04PM -0400, J William Piggott wrote:
>> I pushed the patch to my repo, if you want to use it.
>  
>  Merged, thanks.
>

Karel,

I forgot to give Reported-by credit to:
 Andreas Henriksson <andreas@fatal.se>
 Serge Schneider <serge@raspberrypi.org>

In commit efc4eaf4229f78f14430d8739ddef2c5101f05cc

My apologies to you, Andreas, and Serge for forgetting.

Thank you both for reporting it.

William

Re: hwclock's synchronize_to_clock_tick_rtc returns inconsistent values

[Andreas Henriksson]

Hello!

On Wed, Apr 22, 2015 at 12:45:47PM -0400, J William Piggott wrote:
> I forgot to give Reported-by credit to:
>  Andreas Henriksson <andreas@fatal.se>
>  Serge Schneider <serge@raspberrypi.org>
> 
> In commit efc4eaf4229f78f14430d8739ddef2c5101f05cc
> 
> My apologies to you, Andreas, and Serge for forgetting.

No problem! Doesn't matter to me. Thanks to Serge
for originally reporting the issue to me (Debian).

> 
> Thank you both for reporting it.

Thank you for making sure it got fixed!

Regards,
Andreas Henriksson