Feature: NTP Client
Severity: medium
Summary of the issues:
NTP Client is not working, not pulling time from NTP server(s)
Observed behavior (What it did or didn’t do):
The NTP Client does not sync time over the internet. The "Use pre-defined NTP server" and the "Use custom NTP server" option is affected.
The time of my XG is out of sync since the upgrade to V18 EAP1
Desired behavior (How is it expected to or should behave):
The NTP Client of XG should sync its time from the configured NTP Servers
How do we reproduce it (Provide instructions to help us reproduce the behavior):
Try to set NTP Servers and sync the time. Nothing happens.
Other (Any other detail that we need to know about):
After the first try to sync and hitting the Apply button on the NTP section, my XG reboots.
After the first unwanted reboot the NTP Client does not sync the time anyway, but the unexpected reboot issue is gone.
Supporting logs, pcaps, etc.:
Snippet of the NTP Log:
MESSAGE Oct 13 21:42:34 [11924]: Server 'time.euro.apple.com' => '17.253.54.253' Timeout.
MESSAGE Oct 13 21:42:34 [11924]: Switch to Server 'time.euro.apple.com' => '17.253.108.125'.
MESSAGE Oct 13 21:43:04 [11924]: Server 'time.euro.apple.com' => '17.253.108.125' Timeout.
MESSAGE Oct 13 21:43:04 [11924]: Switch to Server 'time.euro.apple.com' => '17.253.108.253'.
MESSAGE Oct 13 21:43:34 [11924]: Server 'time.euro.apple.com' => '17.253.108.253' Timeout.
MESSAGE Oct 13 21:43:34 [11924]: Switch to Server 'time.euro.apple.com' => '17.253.54.123'.
MESSAGE Oct 13 21:44:04 [11924]: Server 'time.euro.apple.com' => '17.253.54.123' Timeout.
MESSAGE Oct 13 21:44:04 [11924]: Switch to Server 'time.euro.apple.com' => '17.253.54.253'.
MESSAGE Oct 13 21:44:34 [11924]: Server 'time.euro.apple.com' => '17.253.54.253' Timeout.
MESSAGE Oct 13 21:44:34 [11924]: Switch to Server 'time.euro.apple.com' => '17.253.108.125'.
MESSAGE Oct 13 21:45:04 [11924]: Server 'time.euro.apple.com' => '17.253.108.125' Timeout.
MESSAGE Oct 13 21:45:04 [11924]: Switch to Server 'time.euro.apple.com' => '17.253.108.253'.
Starting NTP Client v0.0.2
Configuration:
-f inital_freq 0
-c probe_count 0
-d (debug) 0
-g goodness 0
-i interval 600
-l live 1
-T TimeOut 30
-o Offset 900
-q min_delay 800.000000
-s set_clock 0
-H Num of Hours 24
-x cross_check 1
-p local_port 0
-L LogFile 'STDERR|STDOUT'
-D Daemonize 0
-h Host pool.ntp.org
ERROR Oct 13 21:45:15 [13313]: setup_receive: bind for fd,family (3,2)
ERROR Oct 13 21:45:15 [13313]: setup_receive: bind for fd,family (4,10)
MESSAGE Oct 13 21:45:15 [13313]: Switch to Server 'pool.ntp.org' => '213.239.239.164'.
Starting NTP Client v0.0.2
Configuration:
-f inital_freq 0
-c probe_count 0
-d (debug) 0
-g goodness 0
-i interval 600
-l live 1
-T TimeOut 30
-o Offset 900
-q min_delay 800.000000
-s set_clock 0
-H Num of Hours 24
-x cross_check 1
-p local_port 0
-L LogFile 'STDERR|STDOUT'
-D Daemonize 0
-h Host pool.ntp.org
ERROR Oct 13 21:45:57 [14041]: setup_receive: bind for fd,family (3,2)
ERROR Oct 13 21:45:57 [14041]: setup_receive: bind for fd,family (4,10)
MESSAGE Oct 13 21:45:57 [14041]: Switch to Server 'pool.ntp.org' => '213.239.239.164'.
Starting NTP Client v0.0.2
Configuration:
-f inital_freq 0
-c probe_count 0
-d (debug) 0
-g goodness 0
-i interval 600
-l live 1
-T TimeOut 30
-o Offset 900
-q min_delay 800.000000
-s set_clock 0
-H Num of Hours 24
-x cross_check 1
-p local_port 0
-L LogFile 'STDERR|STDOUT'
-D Daemonize 0
-h Host pool.ntp.org
ERROR Oct 13 21:46:43 [14728]: setup_receive: bind for fd,family (3,2)
ERROR Oct 13 21:46:43 [14728]: setup_receive: bind for fd,family (4,10)
MESSAGE Oct 13 21:46:43 [14728]: Switch to Server 'pool.ntp.org' => '213.239.239.164'.
MESSAGE Oct 13 21:47:13 [14728]: Server 'pool.ntp.org' => '213.239.239.164' Timeout.
MESSAGE Oct 13 21:47:13 [14728]: Switch to Server 'pool.ntp.org' => '5.9.113.140'.
MESSAGE Oct 13 21:49:25 [14728]: System Clock set to : 'Sun Oct 13 19:49:25 2019'.
Snippet of syslog.log:
Oct 13 20:30:40 (none) daemon.debug /bin/smcroute[5154]: Debu: 32 byte IGMP signaling dropped
Oct 13 20:30:50 (none) daemon.debug /bin/smcroute[5154]: Debu: 32 byte IGMP signaling dropped
Oct 13 21:31:39 (none) daemon.info init: System will reboot
Oct 13 21:31:40 (none) daemon.info init: The system is going down NOW!
Snippets of csc.log:
CRITICAL Oct 13 20:30:01 [worker:1003]:ERROR Oct 13 20:30:01 [listener:4878]: csc_waitpid: pid(1003) exited with signal 9
we got spool usage 0
ERROR Oct 13 20:30:01 [listener:4878]: worker 8395 killed
ERROR Oct 13 20:30:01 [listener:4878]: csc_waitpid: pid(8395) exited with signal 9
ERROR Oct 13 20:30:01 [listener:4878]: worker 4358 killed
ERROR Oct 13 20:30:01 [listener:4878]: csc_waitpid: pid(4358) exited with signal 9
ERROR Oct 13 20:30:01 [listener:4878]: worker 8396 killed
CRITICAL Oct 13 20:30:01 [worker:8396]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 20:30:01 [listener:4878]: csc_waitpid: pid(8396) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9611 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9611) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9632 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9632) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9618 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9618) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9633 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9633) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9620 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9620) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9629 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9629) exited with signal 9
ERROR Oct 13 20:30:07 [listener:4878]: worker 9631 killed
ERROR Oct 13 20:30:07 [listener:4878]: csc_waitpid: pid(9631) exited with signal 9
ERROR Oct 13 20:30:26 [listener:4878]: worker 9670 killed
CRITICAL Oct 13 20:30:26 [worker:9670]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 20:30:26 [listener:4878]: csc_waitpid: pid(9670) exited with signal 9
MESSAGE Oct 13 20:30:30 [u2d_pt_installer:9702]: Child exited with status 244
WARNING Oct 13 20:30:30 [u2d_pt_installer:9702]: action with nofail failed
MESSAGE Oct 13 20:30:30 [u2d_dr_installer:9669]: Child exited with status 244
WARNING Oct 13 20:30:30 [u2d_dr_installer:9669]: action with nofail failed
ERROR Oct 13 20:30:30 [listener:4878]: worker 9669 killed
ERROR Oct 13 20:30:30 [listener:4878]: csc_waitpid: pid(9669) exited with signal 9
ERROR Oct 13 20:30:31 [listener:4878]: worker 9667 killed
ERROR Oct 13 20:30:31 [listener:4878]: csc_waitpid: pid(9667) exited with signal 9
ERROR Oct 13 20:30:31 [listener:4878]: worker 9702 killed
CRITICAL Oct 13 20:30:31 [worker:9702]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 20:30:31 [listener:4878]: csc_waitpid: pid(9702) exited with signal 9
ERROR Oct 13 20:30:47 [listener:4878]: worker 9763 killed
CRITICAL Oct 13 20:30:47 [worker:9763]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 20:30:47 [listener:4878]: csc_waitpid: pid(9763) exited with signal 9
PAckage ::::system::systemgraphERROR Oct 13 20:30:48 [listener:4878]: worker 9797 killed
ERROR Oct 13 20:30:48 [listener:4878]: csc_waitpid: pid(9797) exited with signal 9
ERROR Oct 13 20:30:48 [listener:4878]: ln_recvfrom: fd '107.TCP.INET.auxilary': peer connection closed'Success'
ERROR Oct 13 20:30:56 [listener:4878]: worker 9806 killed
ERROR Oct 13 20:30:56 [listener:4878]: csc_waitpid: pid(9806) exited with signal 9
ERROR Oct 13 20:30:59 [listener:4878]: worker 9742 killed
ERROR Oct 13 20:30:59 [listener:4878]: csc_waitpid: pid(9742) exited with signal 9
ERROR Oct 13 20:30:59 [listener:4878]: worker 9807 killed
CRITICAL Oct 13 20:30:59 [worker:9807]: read_packet: read error 'Interrupted system call'
Oct 13 21:31:40 (none) syslog.info syslogd exiting
Oct 13 21:32:19 (none) syslog.info syslogd started: BusyBox v1.21.1
Oct 13 21:32:19 (none) user.notice kernel: klogd started: BusyBox v1.21.1 (2019-10-09 03:10:30 UTC)
Oct 13 21:32:19 (none) user.notice kernel: [ 0.000000] Linux version 4.14.38 (jenkins@ci-37) (gcc version 7.3.0 (OpenWrt GCC 7.3.0 6275-g1d4a4e7e)) #2 SMP Wed Oct 9 06:20:38 UTC 2019
Oct 13 21:32:19 (none) user.info kernel: [ 0.000000] Command line: BOOT_IMAGE=/18_0_0_102 quiet console=tty0 console=ttyS0,38400n8 amd_iommu=on iommu=pt memmap=64K$512M
Oct 13 21:32:19 (none) user.info kernel: [ 0.000000] x86/fpu: x87 FPU will use FXSAVE
Oct 13 21:32:19 (none) user.info kernel: [ 0.000000] e820: BIOS-provided physical RAM map:
MESSAGE Oct 13 21:42:23 [fwm:1945]: Child exited with status 1
WARNING Oct 13 21:42:23 [fwm:1945]: action with nofail failed
MESSAGE Oct 13 21:42:23 [fwm:1945]: Child exited with status 1
WARNING Oct 13 21:42:23 [fwm:1945]: action with nofail failed
ERROR Oct 13 21:42:24 [listener:1869]: worker 12686 killed
ERROR Oct 13 21:42:24 [listener:1869]: csc_waitpid: pid(12686) exited with signal 9
ERROR Oct 13 21:42:24 [listener:1869]: worker 12738 killed
CRITICAL Oct 13 21:42:24 [worker:12738]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:24 [listener:1869]: csc_waitpid: pid(12738) exited with signal 9
ERROR Oct 13 21:42:24 [listener:1869]: worker 12605 killed
CRITICAL Oct 13 21:42:24 [worker:12605]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:24 [listener:1869]: csc_waitpid: pid(12605) exited with signal 9
PAckage ::::cli::alertERROR Oct 13 21:42:24 [listener:1869]: ln_recvfrom: fd '107.TCP.INET.auxilary': peer connection closed'Success'
ERROR Oct 13 21:42:24 [listener:1869]: worker 12687 killed
ERROR Oct 13 21:42:24 [listener:1869]: csc_waitpid: pid(12687) exited with signal 9
ERROR Oct 13 21:42:24 [listener:1869]: worker 12107 killed
CRITICAL Oct 13 21:42:24 [worker:12107]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:24 [listener:1869]: csc_waitpid: pid(12107) exited with signal 9
MESSAGE Oct 13 21:42:30 [u2d_dr_installer:12742]: Child exited with status 244
MESSAGE Oct 13 21:42:30 [u2d_pt_installer:12743]: Child exited with status 244
WARNING Oct 13 21:42:30 [u2d_dr_installer:12742]: action with nofail failed
WARNING Oct 13 21:42:30 [u2d_pt_installer:12743]: action with nofail failed
ERROR Oct 13 21:42:30 [listener:1869]: worker 12742 killed
CRITICAL Oct 13 21:42:30 [worker:12742]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:30 [listener:1869]: csc_waitpid: pid(12742) exited with signal 9
ERROR Oct 13 21:42:30 [listener:1869]: worker 12741 killed
ERROR Oct 13 21:42:30 [listener:1869]: csc_waitpid: pid(12741) exited with signal 9
ERROR Oct 13 21:42:30 [listener:1869]: worker 12743 killed
CRITICAL Oct 13 21:42:30 [worker:12743]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:30 [listener:1869]: csc_waitpid: pid(12743) exited with signal 9
ERROR Oct 13 21:42:33 [listener:1869]: worker 12790 killed
ERROR Oct 13 21:42:33 [listener:1869]: csc_waitpid: pid(12790) exited with signal 9
ERROR Oct 13 21:42:34 [listener:1869]: worker 12792 killed
ERROR Oct 13 21:42:34 [listener:1869]: csc_waitpid: pid(12792) exited with signal 9
PAckage ::::system::systemgraphERROR Oct 13 21:42:39 [listener:1869]: worker 12814 killed
CRITICAL Oct 13 21:42:39 [worker:12814]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:39 [listener:1869]: csc_waitpid: pid(12814) exited with signal 9
ERROR Oct 13 21:42:39 [listener:1869]: ln_recvfrom: fd '107.TCP.INET.auxilary': peer connection closed'Success'
ERROR Oct 13 21:42:43 [listener:1869]: worker 12819 killed
ERROR Oct 13 21:42:43 [listener:1869]: csc_waitpid: pid(12819) exited with signal 9
ERROR Oct 13 21:42:47 [listener:1869]: worker 12823 killed
CRITICAL Oct 13 21:42:47 [worker:12823]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:47 [listener:1869]: csc_waitpid: pid(12823) exited with signal 9
ERROR Oct 13 21:42:49 [listener:1869]: worker 12833 killed
CRITICAL Oct 13 21:42:49 [worker:12833]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:49 [listener:1869]: csc_waitpid: pid(12833) exited with signal 9
ERROR Oct 13 21:42:55 [listener:1869]: worker 12858 killed
CRITICAL Oct 13 21:42:55 [worker:12858]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:55 [listener:1869]: csc_waitpid: pid(12858) exited with signal 9
ERROR Oct 13 21:42:55 [listener:1869]: worker 12769 killed
ERROR Oct 13 21:42:55 [listener:1869]: csc_waitpid: pid(12769) exited with signal 9
ERROR Oct 13 21:42:56 [listener:1869]: worker 12873 killed
CRITICAL Oct 13 21:42:56 [worker:12873]: read_packet: read error 'Interrupted system call'
ERROR Oct 13 21:42:56 [listener:1869]: csc_waitpid: pid(12873) exited with signal 9
ERROR Oct 13 21:43:00 [listener:1869]: worker 12762 killed
