Re: [chrony-dev] macOS 13: suspicious jumps while sleeping

["Gerriet M. Denkmann" <gerrietm@xxxxxxxxxx>]

> On 22 Nov 2017, at 15:42, Bryan Christianson <bryan@xxxxxxxxxxxxx> wrote:
> 
>> On 22/11/2017, at 9:15 PM, Miroslav Lichvar <mlichvar@xxxxxxxxxx> wrote:
>> 
>> On Wed, Nov 22, 2017 at 02:03:17PM +0700, Gerriet M. Denkmann wrote:
>>> macOS 13.1, chrony 3.2.
>>> 
>>> I modified check_current_time() in sched.c:
>>>   LOG(LOGS_WARN, "Forward time jump detected! %4ld sec”, raw->tv_sec - (prev_raw->tv_sec + elapsed_max.tv_sec) );
>>> 
>>> After the computer has been sleeping for some time (since about 10:10), I saw:
>> 
>> The computer has woken up only once and there are multiple messages
>> saying the clock jumped forward? That is weird. Any chance the new
>> timed daemon is interfering with the clock? There was a post on the
>> -users list how it can be disabled.
> 
> This looks like the 'timed' problem. Here is what I posted to the users list.
> 
> There is a bug in High Sierra (macOS 10.13) that leaves Apple's timed daemon active after it has been disabled in the System Settings 'Date and Time' preferences
> 
> timed continues to send NTP packets to the server specified in the System Preferences and then adjusts the system clock. This of course has a terrible effect on chronyd, with frequency and offsets jumping all over the place.
> 
> I have reported the bug to Apple so hopefully it will be fixed in some forthcoming patch release of macOS 10.13

I wrote a small program to see what my MacBook is doing when it thinks that no-one is looking (e.g. when the lid is closed).

Here is the output with comments and lines from chrony added:


First the poor MacBook has terrible problems falling asleep: repeatedly sleeping for less than 3 seconds and waking again for 45 seconds:

2017-11-22 18:59:33.314973 -[AppDelegate receiveSleepNote:]: awake    for   106.3 sec; start sleep
2017-11-22 18:59:35.468490 -[AppDelegate receiveWakeNote:]:  sleeping for     2.2 sec; now awake
2017-11-22 19:00:20.474175 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:00:23.001654 -[AppDelegate receiveWakeNote:]:  sleeping for     2.5 sec; now awake
2017-11-22 19:01:08.000719 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:01:10.553012 -[AppDelegate receiveWakeNote:]:  sleeping for     2.6 sec; now awake
2017-11-22 19:01:55.557896 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:01:58.086610 -[AppDelegate receiveWakeNote:]:  sleeping for     2.5 sec; now awake
2017-11-22 19:02:43.089206 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:02:45.639407 -[AppDelegate receiveWakeNote:]:  sleeping for     2.6 sec; now awake
2017-11-22 19:03:30.644818 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:03:33.196194 -[AppDelegate receiveWakeNote:]:  sleeping for     2.6 sec; now awake
2017-11-22 19:04:18.201862 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:04:20.747223 -[AppDelegate receiveWakeNote:]:  sleeping for     2.5 sec; now awake
2017-11-22 19:05:05.750811 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:05:08.296899 -[AppDelegate receiveWakeNote:]:  sleeping for     2.5 sec; now awake
2017-11-22 19:05:53.302906 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep
2017-11-22 19:05:55.841995 -[AppDelegate receiveWakeNote:]:  sleeping for     2.5 sec; now awake
2017-11-22 19:06:40.846943 -[AppDelegate receiveSleepNote:]: awake    for    45.0 sec; start sleep

But even when it finally manages to sleep it will from time to time become active (while still asleep) and stay active for about 40 seconds:
On each of these occasions chrony will see a jump comparable to the time spend inactive.
All of this happens when it is supposed to be asleep.

2017-11-22 19:36:59.183870 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping active since Wed Nov 22 18:57:25 2017 for   570.0 sec
2017-11-22 19:36:59.184052 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping inactive                              for  1803.2 sec

default	19:36:59.679124 +0700	chronyd	Forward time jump detected! 1794 sec

2017-11-22 19:46:12.739923 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping active since Wed Nov 22 19:36:59 2017 for    40.0 sec
2017-11-22 19:46:12.740084 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping inactive                              for   513.6 sec

default	19:46:37.786756 +0700	chronyd	Forward time jump detected! 504 sec

2017-11-22 20:11:19.325330 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping active since Wed Nov 22 19:46:12 2017 for    40.0 sec
2017-11-22 20:11:19.325525 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping inactive                              for  1466.6 sec

default	20:11:59.634231 +0700	chronyd	Forward time jump detected! 1457 sec

2017-11-22 20:19:34.860451 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping active since Wed Nov 22 20:11:19 2017 for    40.0 sec
2017-11-22 20:19:34.860603 -[AppDelegate applicationDidFinishLaunching:]_block_invoke sleeping inactive                              for   455.5 sec

default	20:19:27.018218 +0700	chronyd	Forward time jump detected! 447 sec

2017-11-22 20:29:38.999731 -[AppDelegate receiveWakeNote:]:  sleeping for  4978.2 sec; now awake
2017-11-22 20:29:48.913202 -[AppDelegate applicationDidFinishLaunching:]_block_invoke awake    active since Wed Nov 22 20:19:34 2017 for    40.0 sec
2017-11-22 20:29:48.913376 -[AppDelegate applicationDidFinishLaunching:]_block_invoke awake    inactive                              for   574.1 sec

default	20:29:54.537872 +0700	chronyd	Forward time jump detected! 564 sec


I do not know anything about the internal workings of chrony, but wouldn’t it be possible to block all activity when the computer is supposed to be asleep?

While listening for NSWorkspaceWillSleepNotification probably will not be suitable for chrony, there should be an IOKit way of determining sleep status.


Kind regards,

Gerriet.



--
To unsubscribe email chrony-dev-request@xxxxxxxxxxxxxxxxxxxx with "unsubscribe" in the subject.
For help email chrony-dev-request@xxxxxxxxxxxxxxxxxxxx with "help" in the subject.
Trouble?  Email listmaster@xxxxxxxxxxxxxxxxxxxx.