Thread Info
  • State Suggested Answer
  • +1 person also asked this people also asked this
  • Replies 4 replies
  • Answers 1 answer
  • Subscribers 7 subscribers
  • Views 5872 views
  • Users 0 members are here
Options
Suggested

NTP time Sync is not working

4ng3er

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

 

 

Parents
  • 0

    I am wonderin,g do you have the correct time zone? 

     

    NTP is getting a IP but its 2 hours behind (general speaking UTC+2 right now).

    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'.

     

    My Timezone works fine in EAP1.

    MESSAGE Oct 13 22:25:17 [18067]: Switch to Server 'pool.ntp.org' => '178.63.247.119'.
    MESSAGE Oct 13 22:25:17 [18067]: System Clock set to : 'Sun Oct 13 20:25:17 2019'.

     

     

    But the NTPclient.log does not always sync new. 

    __________________________________________________________________________________________________________________

  • 0 in reply to LuCar Toni

    Hi 

    yes i am in the same timezone like you. Europe/Berlin.

    After several syncing tries it worked with my fritzbox ntp server. At the time of the issue the ntp client of the XG cannot connect to any ntp server (apple, pool.ntp.org, local fritzbox).

    Weird behavior...

     

    When ill do an manual try on the shell, then the ntp client throw also errors:

    SFVH_SO01_SFOS 18.0.0 EAP1# ntpclient -h time.euro.apple.com

    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          0

      -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     time.euro.apple.com

    ERROR     Oct 13 22:26:14 [25059]: setup_receive: bind for fd,family (3,2) 

    ERROR     Oct 13 22:26:14 [25059]: setup_receive: bind for fd,family (4,10) 

    MESSAGE   Oct 13 22:26:14 [25059]: Switch to Server 'time.euro.apple.com' => '17.253.54.251'.

     

  • +1 in reply to 4ng3er

    Hi ,

    Thanks for the feedback.Sending you PM for more detailing.

    Thanks,

    Rana Sharma

  • 0 in reply to 4ng3er

    Hi ,

    Thanks for device access to analyse the device. I  really appreciate for your valuable input and prompt response.

    Here are the conclusion as followings 

       - NTP time sync : at that time gw down / up activity happened from isp side.

       - Unexpected device reboot while doing ntp setting : RCA - Time Zone change activity happened so device will reboot , that is acceptable behaviour

     

    Many Thanks for your support

     

    Thanks,

    Rana Sharma

Reply Children
No Data
Unfiltered HTML