On Tue, Dec 10, 2019 at 5:59 PM Miroslav Lichvar <[email protected]> wrote:
> On Tue, Dec 10, 2019 at 04:25:31PM +0100, Christian Ehrhardt wrote: > > On Tue, Dec 10, 2019 at 4:19 PM Miroslav Lichvar <[email protected]> > > > I'm sorry for changing my mind, but I now think this case should be > > > handled gracefully in chronyd and not avoided in the test. According > > > to the man page, the -s option is supposed to work even with no RTC or > > > broken RTCs. A hang or fatal error with the -s option may break > > > the user's expectation. > > > > > > Do you agree? > > > > > > > Yes, but I think the changes are not mutually exclusive and should both > be > > added. > > > > -s needs the change you suggested to make the fail fatal. > > As I tried to explain in the later post, I think chronyd -s should not > fail if the RTC doesn't support interrupts, as the documentation > implies chronyd can work with "broken" RTCs and we shouldn't expect > the users to test it before configuring chronyd. > > > Otherwise users will not realize that they don't get what they ordered. > > There will still be the error message in the log. > > Can you please try the test again with the latest code? > I tested with the current head being commit f5eb7daf "rtc: disable interrupts in finalization" With that the test finally worked on the two affected platforms that I had: ./run -d 103-refclock 103-refclock Testing reference clocks: non-default settings: extra_chronyd_directives= refclock SOCK /home/ubuntu/chrony/test/system/tmp/refclock.sock refclock SHM 100 starting chronyd OK waiting for synchronization OK stopping chronyd OK checking chronyd messages OK checking chronyd files OK PASS SUMMARY: TOTAL 1 PASSED 1 FAILED 0 () SKIPPED 0 () But when run in debug mode it still looks the same: $ ./chronyd -d -s -f /root/chronyd.conf 019-12-11T14:37:35Z chronyd version DEVELOPMENT starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER -SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG) 2019-12-11T14:37:36Z System time set from RTC 2019-12-11T14:37:36Z Initial frequency -13.014 ppm 2019-12-11T14:37:36Z Could not enable RTC interrupt : Invalid argument I'd have expected a fatal exit in these cases now - is that right? >From reading the (new) code I'd expect RTC_Linux_Initialise to now detect the problem and return 0 from this new section: + /* Make sure the RTC supports interrupts */ + if (!switch_interrupts(0)) { + close(fd); + return 0; + } But what I see happening is this: gdb) b RTC_Finalise Breakpoint 1 at 0x11bc8: file rtc.c, line 162. (gdb) b RTC_Initialise Breakpoint 2 at 0x119b8: file rtc.c, line 115. (gdb) b RTC_Linux_Initialise Breakpoint 3 at 0x373e8: file rtc_linux.c, line 509. (gdb) b switch_interrupts Breakpoint 4 at 0x36d28: switch_interrupts. (2 locations) (gdb) run -d -s -f /root/chronyd.conf Starting program: /home/ubuntu/chrony/chronyd -d -s -f /root/chronyd.conf [Thread debugging using libthread_db enabled] Using host libthread_db library "/lib/powerpc64le-linux-gnu/libthread_db.so.1". 2019-12-11T14:43:05Z chronyd version DEVELOPMENT starting (+CMDMON +NTP +REFCLOCK +RTC +PRIVDROP -SCFILTER -SIGND +ASYNCDNS +SECHASH +IPV6 -DEBUG) 2019-12-11T14:43:05Z Wrong owner of /var/run/chrony (UID != 0) 2019-12-11T14:43:05Z Disabled command socket /var/run/chrony/chronyd.sock Breakpoint 2, 0x00000001000119b8 in RTC_Initialise (initial_set=1) at rtc.c:115 115 { (gdb) n 125 if (initial_set) { (gdb) 126 driftfile_time = get_driftfile_time(); (gdb) 128 if (driver.time_pre_init && driver.time_pre_init(driftfile_time)) { (gdb) 129 driver_preinit_ok = 1; (gdb) 137 driver_initialised = 0; (gdb) 141 file_name = CNF_GetRtcFile(); (gdb) 143 if (file_name) { (gdb) 144 if (CNF_GetRtcSync()) { (gdb) 149 if ((driver.init)()) { (gdb) Breakpoint 3, 0x00000001000373e8 in RTC_Linux_Initialise () at rtc_linux.c:509 509 { (gdb) 511 fd = open(CNF_GetRtcDevice(), O_RDWR); (gdb) 512 if (fd < 0) { (gdb) 519 if (!switch_interrupts(0)) { (gdb) Breakpoint 4, 0x0000000100036d28 in switch_interrupts (on_off=0) at rtc_linux.c:489 489 { (gdb) 490 if (ioctl(fd, on_off ? RTC_UIE_ON : RTC_UIE_OFF, 0) < 0) { (gdb) RTC_Linux_Initialise () at rtc_linux.c:525 525 UTI_FdSetCloexec(fd); (gdb) 527 rtc_sec = MallocArray(time_t, MAX_SAMPLES); (gdb) 528 rtc_trim = MallocArray(double, MAX_SAMPLES); (gdb) 529 system_times = MallocArray(struct timespec, MAX_SAMPLES); (gdb) 532 setup_config(); (gdb) 535 coefs_file_name = CNF_GetRtcFile(); (gdb) 537 n_samples = 0; (gdb) 538 n_samples_since_regression = 0; (gdb) 539 n_runs = 0; (gdb) 540 coefs_valid = 0; (gdb) 547 SCH_AddFileHandler(fd, SCH_FILE_INPUT, read_from_device, NULL); (gdb) 550 LCL_AddParameterChangeHandler(slew_samples, NULL); (gdb) 552 logfileid = CNF_GetLogRtc() ? LOG_FileOpen("rtc", (gdb) 555 return 1; (gdb) RTC_Initialise (initial_set=<optimized out>) at rtc.c:150 150 driver_initialised = 1; (gdb) main (argc=<optimized out>, argv=0x7ffffffff558) at main.c:555 555 SRC_Initialise(); (gdb) 556 RCL_Initialise(); (gdb) 557 KEY_Initialise(); (gdb) 558 SCK_Initialise(); (gdb) 561 CAM_Initialise(address_family); (gdb) 562 NIO_Initialise(address_family); (gdb) 563 NCR_Initialise(); (gdb) 564 CNF_SetupAccessRestrictions(); (gdb) 567 if (!sched_priority) { (gdb) 568 sched_priority = CNF_GetSchedPriority(); (gdb) 570 if (sched_priority) { (gdb) 574 if (lock_memory || CNF_GetLockMemory()) { (gdb) 579 if (!geteuid() && (pw->pw_uid || pw->pw_gid)) (gdb) 582 REF_Initialise(); (gdb) 2019-12-11T14:43:52Z Initial frequency -21.507 ppm 583 SST_Initialise(); (gdb) 584 NSR_Initialise(); (gdb) 585 NSD_Initialise(); (gdb) 586 CLG_Initialise(); (gdb) 587 MNL_Initialise(); (gdb) 588 TMC_Initialise(); (gdb) 589 SMT_Initialise(); (gdb) 592 initialised = 1; (gdb) 594 UTI_SetQuitSignalsHandler(signal_cleanup, 1); (gdb) 596 CAM_OpenUnixSocket(); (gdb) 598 if (scfilter_level) (gdb) 601 if (ref_mode == REF_ModeNormal && CNF_GetInitSources() > 0) { (gdb) 605 REF_SetModeEndHandler(reference_mode_end); (gdb) 606 REF_SetMode(ref_mode); (gdb) 608 if (timeout > 0) (gdb) 611 if (do_init_rtc) { (gdb) 612 RTC_TimeInit(post_init_rtc_hook, NULL); (gdb) Breakpoint 4, 0x0000000100036d28 in switch_interrupts (on_off=1) at rtc_linux.c:489 489 { (gdb) 490 if (ioctl(fd, on_off ? RTC_UIE_ON : RTC_UIE_OFF, 0) < 0) { (gdb) 488 switch_interrupts(int on_off) (gdb) 2019-12-11T14:44:14Z Could not enable RTC interrupt : Invalid argument main (argc=<optimized out>, argv=0x7ffffffff558) at main.c:619 619 SCH_MainLoop(); (gdb) <hang> The latter part in more detail: 612 RTC_TimeInit(post_init_rtc_hook, NULL); (gdb) s RTC_TimeInit (after_hook=0x10000cb60 <post_init_rtc_hook>, anything=0x0) at rtc.c:182 182 if (driver_initialised && driver_preinit_ok) { (gdb) n 183 (driver.time_init)(after_hook, anything); (gdb) s RTC_Linux_TimeInit (after_hook=0x10000cb60 <post_init_rtc_hook>, anything=0x0) at rtc_linux.c:885 885 after_init_hook = after_hook; (gdb) n 886 after_init_hook_arg = anything; (gdb) n 888 operating_mode = OM_INITIAL; (gdb) n 889 timeout_id = 0; (gdb) n 890 switch_interrupts(1); (gdb) n Breakpoint 4, 0x0000000100036d28 in switch_interrupts (on_off=1) at rtc_linux.c:489 489 { (gdb) bt #0 0x0000000100036d28 in switch_interrupts (on_off=1) at rtc_linux.c:489 #1 0x0000000100011c74 in RTC_TimeInit (after_hook=<optimized out>, anything=<optimized out>) at rtc.c:183 #2 0x0000000100004878 in main (argc=<optimized out>, argv=0x7ffffffff558) at main.c:612 That means the first switch_interrupts call from RTC_Initialise -> RTC_Linux_Initialise -> switch_interrupts has on_off=0 and that doesn't trigger the issue at initialization phase. Later on on RTC_TimeInit -> switch_interrupts argument on_off=1 and the issue occurs. Turns out our "problematic" RTCs only trigger the issue on on_off=1. Can we safely set that to 1 in the check like? diff --git a/rtc_linux.c b/rtc_linux.c index aee768f..b1eee19 100644 --- a/rtc_linux.c +++ b/rtc_linux.c @@ -516,7 +516,7 @@ RTC_Linux_Initialise(void) } /* Make sure the RTC supports interrupts */ - if (!switch_interrupts(0)) { + if (!switch_interrupts(1)) { close(fd); return 0; } Or do we need some code to then revert that setting immediately to be on the safe side? diff --git a/rtc_linux.c b/rtc_linux.c index aee768f..8d0fae5 100644 --- a/rtc_linux.c +++ b/rtc_linux.c @@ -516,7 +516,7 @@ RTC_Linux_Initialise(void) } /* Make sure the RTC supports interrupts */ - if (!switch_interrupts(0)) { + if (!switch_interrupts(1) || switch_interrupts(0)) { close(fd); return 0; } Maybe even something with a harder implication on the order those are executed. I tested the second of the above and it did now trigger the issue when called from RTC_Linux_Initialise. It also did not set driver_initialised=1 this time. Now it behaves more like expected: Breakpoint 3, 0x00000001000373e8 in RTC_Linux_Initialise () at rtc_linux.c:509 509 { (gdb) n 511 fd = open(CNF_GetRtcDevice(), O_RDWR); (gdb) 512 if (fd < 0) { (gdb) 519 if (!switch_interrupts(1) || switch_interrupts(0)) { (gdb) Breakpoint 2, 0x0000000100036d28 in switch_interrupts (on_off=1) at rtc_linux.c:489 489 { (gdb) n 490 if (ioctl(fd, on_off ? RTC_UIE_ON : RTC_UIE_OFF, 0) < 0) { (gdb) n 488 switch_interrupts(int on_off) (gdb) 2019-12-11T14:58:46Z Could not enable RTC interrupt : Invalid argument RTC_Linux_Initialise () at rtc_linux.c:520 520 close(fd); (gdb) n 521 return 0; Nevertheless it hangs eventually in this mode. This is due to SCH_MainLoop begin the one with the select call where nothing returns. Program received signal SIGINT, Interrupt. 0x00007ffff7c40864 in __GI___select (nfds=514, readfds=0x7fffffffede8, writefds=0x0, exceptfds=0x0, timeout=0x0) at ../sysdeps/unix/sysv/linux/select.c:41 41 ../sysdeps/unix/sysv/linux/select.c: No such file or directory. (gdb) bt #0 0x00007ffff7c40864 in __GI___select (nfds=514, readfds=0x7fffffffede8, writefds=0x0, exceptfds=0x0, timeout=0x0) at ../sysdeps/unix/sysv/linux/select.c:41 #1 0x0000000100014440 in SCH_MainLoop () at sched.c:753 #2 0x0000000100004880 in main (argc=<optimized out>, argv=0x7ffffffff558) at main.c:619 I've understood that you wanted it to hard-fail and bail out of -s was set but RTC init failed right? Therefore I'd have expected an exit in this case instead of falling into SCH_MainLoop and waiting there. If that wasn't the expectation then we might be good - the initially reported test issues are fixed - thanks! > If you would like, I think it could be improved to prepare an rtcfile > and look for the "System clock off from RTC" message when hwclock > doesn't report that interrupts are not supported. > > -- > Miroslav Lichvar > > > -- > To unsubscribe email [email protected] with > "unsubscribe" in the subject. > For help email [email protected] with "help" in the > subject. > Trouble? Email [email protected]. > > -- Christian Ehrhardt Staff Engineer, Ubuntu Server Canonical Ltd
