[SOLVED] Time synchronization problem

[FalconB]

I use Clouflare’s ntp server IP address, rather than a domain name.
Any ntp IP address would do I guess.

That way when restarting, your time acquisition isn’t dependant on a dns resolution to get up & running?

Those with more knowledge than me, chime in here.

Still no luck (using ip address instead of domain). I have noticed this when I log in via SSH:

login as: XXXX
XXXX@192.168.1.1's password:


ASUSWRT-Merlin RT-AC68U 384.14-0 Sat Dec 14 00:39:28 UTC 2019
XXXX@RT-AC68U:/tmp/home/root# date
Sat May  5 05:07:36 UTC 2018
XXXX@RT-AC68U:/tmp/home/root#

I don't know where the 'Sat Dec 14 00:39:28' comes from, but it's more correct than 'May 5' ...

 

[FalconB]

Changing ntp server to 'pool.ntp.org' doesn't help either. Here is a snippet of my syslog (since I can't seem to post the whole thing):

May  5 07:05:09 dnsmasq[249]: using nameserver 1.1.1.1#53 for domain ntp.se (no DNSSEC)
[...]
May  5 07:05:16 rc_service: udhcpc 541:notify_rc stop_ntpd
May  5 07:05:16 rc_service: udhcpc 541:notify_rc start_ntpd
May  5 07:05:16 rc_service: waitting "stop_ntpd" via udhcpc ...
[...]
May  5 07:05:18 custom_script: Running /jffs/scripts/service-event (args: stop ntpd)
[...]
May  5 07:05:32 rc_service: skip the event: start_ntpd.
[...]
May  5 07:07:05 amtm disk-check: NTP timeout (100s) reached, date is router default

EDIT: Also found out, that if I go to Administration->System and just hit 'Reply' wighout changing anything (ie ntp server is still ntp.se), the router updates the time correctly (the same way as if I run the command from shell).

EDIT 2: Don't know if it's been like this always (getting so confused now ), but when the time is set, the router gui shows correct local time but logging in through shell shows UTC-time (1 hour off where I live).

 

[Martineau]

ASUSWRT-Merlin RT-AC68U 384.14-0 Sat Dec 14 00:39:28 UTC 2019

XXXX@RT-AC68U:/tmp/home/root# date

Sat May  5 05:07:36 UTC 2018

I don't know where the 'Sat Dec 14 00:39:28' comes from...

The date the v384.14 firmware was compiled?

 

[FalconB]

The date the v384.14 firmware was compiled?

Ah, of course! Thanks for the heads up. Any idea where the May 5 comes from? Is that related to when busybox (or some other component) was compiled?

 

[FalconB]

Well, well, well! Changing this line in/jffs/scripts/services-start from

/usr/sbin/ntp -t -S /sbin/ntpd_synced -p 194.58.200.20

to

/usr/sbin/ntpd -t -S /sbin/ntpd_synced -p 194.58.200.20

seems to have done the trick, ie I now get the time sync. However, it doesn't explain why I would need that line in the script in the first place . But hey, it's working, I'm happy ! It also times perfect with the rest of the family's "stop messing with internet" bombardment (yeah, you moms and dads out there know what I'm talking about ). Further testing will be postponed till tomorrow. Fingers crossed it will stay good.

 

[dave14305]

Look for entries in syslog about WAN connection or ISP. I still feel like it’s a timing issue during boot.

Many people upload the syslog to pastebin.com or similar services and just post a link here for large logs.

 

[dave14305]

Changing ntp server to 'pool.ntp.org' doesn't help either. Here is a snippet of my syslog (since I can't seem to post the whole thing):

May  5 07:05:09 dnsmasq[249]: using nameserver 1.1.1.1#53 for domain ntp.se (no DNSSEC)
[...]
May  5 07:05:16 rc_service: udhcpc 541:notify_rc stop_ntpd
May  5 07:05:16 rc_service: udhcpc 541:notify_rc start_ntpd
May  5 07:05:16 rc_service: waitting "stop_ntpd" via udhcpc ...
[...]
May  5 07:05:18 custom_script: Running /jffs/scripts/service-event (args: stop ntpd)
[...]
May  5 07:05:32 rc_service: skip the event: start_ntpd.
[...]
May  5 07:07:05 amtm disk-check: NTP timeout (100s) reached, date is router default

EDIT: Also found out, that if I go to Administration->System and just hit 'Reply' wighout changing anything (ie ntp server is still ntp.se), the router updates the time correctly (the same way as if I run the command from shell).

EDIT 2: Don't know if it's been like this always (getting so confused now ), but when the time is set, the router gui shows correct local time but logging in through shell shows UTC-time (1 hour off where I live).

What’s inside /jffs/scripts/service-event? Maybe something is hanging in there since rc decides to skip the start event.

 

[FalconB]

Look for entries in syslog about WAN connection or ISP. I still feel like it’s a timing issue during boot.

Many people upload the syslog to pastebin.com or similar services and just post a link here for large logs.

I think I managed to upload the syslog to pastebin, see this link: https://pastebin.com/JfE5NuRU

 

[FalconB]

What’s inside /jffs/scripts/service-event? Maybe something is hanging in there since rc decides to skip the start event.

This is the content of /jffs/scripts/service-event:

#!/bin/sh

/jffs/scripts/uiDivStats generate "$1" "$2" & # uiDivStats
/jffs/scripts/YazFi bounceclients "$1" "$2" & # YazFi Guest Networks

# VLAN144 br40
/jffs/scripts/VLANSwitch.sh 40 bridge notag autodnsmasq

 

[FalconB]

@dave14305: Btw, thanks for helping me out! Really appreciate it!

 

[dave14305]

I think I managed to upload the syslog to pastebin, see this link: https://pastebin.com/JfE5NuRU

It just seems like the router isn't able to stop the ntp daemon successfully once the ISP WAN connection is restored. Therefore NTP doesn't startup. The real question is why.

As an experiment, what if you temporarily renamed /jffs/scripts/service-event to /jffs/scripts/service-event.disabled and did a reboot? Since the Yaz scripts all fork in the background, I don't think they're blocking anything, but depending how it goes we might know where to dig deeper. service-event is a blocking script so maybe it's relevant.

Otherwise it's time to call in the big guns (paging Dr. Taylor, Dr. @ColinTaylor).

 

[FalconB]

[...]As an experiment, what if you temporarily renamed /jffs/scripts/service-event to /jffs/scripts/service-event.disabled and did a reboot? Since the Yaz scripts all fork in the background, I don't think they're blocking anything, but depending how it goes we might know where to dig deeper. service-event is a blocking script so maybe it's relevant.[...]

Nice work, detective ! I will try it tomorrow and get back with what happens if i rename the service-event script (and remove the successful workaround line in services-start).

 

[Martineau]

This is the content of /jffs/scripts/service-event:

#!/bin/sh

/jffs/scripts/uiDivStats generate "$1" "$2" & # uiDivStats
/jffs/scripts/YazFi bounceclients "$1" "$2" & # YazFi Guest Networks

# VLAN144 br40
/jffs/scripts/VLANSwitch.sh 40 bridge notag autodnsmasq

FYI....Not related to your NTP issue, 'service-event' is NOT the place to create the VLAN.

EDIT: As per post #58 the OP placed my 'VLANSwitch.sh' script in a blocking script as a foreground task rather than as an asynchronous background task (missing the '&') so technically I am to blame

i.e. 'VLANSwitch.sh' is being executed multiple times....

May  5 07:05:21 (VLANSwitch.sh): 646 v1.21 non-public Beta © 2016-2018 Martineau. VLAN configuration utility.
May  5 07:05:21 (VLANSwitch.sh): 781 v1.21 non-public Beta © 2016-2018 Martineau. VLAN configuration utility.

May  5 07:05:39 (VLANSwitch.sh): 646 VLAN 'vlan144' alias 'None144' (192.168.144.0/24) via Switch Port 4 created.
May  5 07:05:39 (VLANSwitch.sh): 781 VLAN 'vlan144' alias 'None144' (192.168.144.0/24) via Switch Port 4 created.

May  5 07:07:15 (VLANSwitch.sh): 4965 v1.21 non-public Beta © 2016-2018 Martineau. VLAN configuration utility.
May  5 07:07:31 (VLANSwitch.sh): 4965 Warning Bridge br40 already assigned to NVRAM variable lan1_ifname=br40
May  5 07:07:31 (VLANSwitch.sh): 4965 Bridge br40 lan1_ifnames=vlan144
May  5 07:07:32 (VLANSwitch.sh): 4965 VLAN 'vlan144' alias 'None144' (192.168.144.0/24) via Switch Port 4 created.

I suggest you move 'VLANSwitch.sh' to 'services-start' or (assuming you have taken appropriate steps to ensure 'nat-start' cannot execute multiple times concurrently) to 'nat-start'

 

[FalconB]

FYI....Not related to your NTP issue, but 'service-event' is NOT the place to create the VLAN.

i.e. 'VLANSwitch.sh' is being executed multiple times....

May  5 07:05:21 (VLANSwitch.sh): 646 v1.21 non-public Beta © 2016-2018 Martineau. VLAN configuration utility.
May  5 07:05:21 (VLANSwitch.sh): 781 v1.21 non-public Beta © 2016-2018 Martineau. VLAN configuration utility.

May  5 07:05:39 (VLANSwitch.sh): 646 VLAN 'vlan144' alias 'None144' (192.168.144.0/24) via Switch Port 4 created.
May  5 07:05:39 (VLANSwitch.sh): 781 VLAN 'vlan144' alias 'None144' (192.168.144.0/24) via Switch Port 4 created.

May  5 07:07:15 (VLANSwitch.sh): 4965 v1.21 non-public Beta © 2016-2018 Martineau. VLAN configuration utility.
May  5 07:07:31 (VLANSwitch.sh): 4965 Warning Bridge br40 already assigned to NVRAM variable lan1_ifname=br40
May  5 07:07:31 (VLANSwitch.sh): 4965 Bridge br40 lan1_ifnames=vlan144
May  5 07:07:32 (VLANSwitch.sh): 4965 VLAN 'vlan144' alias 'None144' (192.168.144.0/24) via Switch Port 4 created.

I suggest you move 'VLANSwitch.sh' to 'services-start' or (assuming you have taken appropriate steps to ensure 'nat-start' cannot execute multiple times concurrently) to 'nat-start'

Indeed, that seems to be a wise choice, now that I'm getting the hang of it (sort of). Thanks for the heads up!

 

[dave14305]

Indeed, that seems to be a wise choice, now that I'm getting the hang of it (sort of). Thanks for the heads up!

I think this will help a lot since it's the only non-background command in this script. After moving it to the proper script, you might be in much better shape.

Referring to this older post by @john9527, these "skip the event" logs happen after 30 seconds of waiting. So maybe having the VLAN in the wrong place actually is affecting things indirectly. Test and we shall see!
[SOLVED-FOR REAL] rc_service: skip the event: start_firewall.

 

[FalconB]

I think this will help a lot since it's the only non-background command in this script. After moving it to the proper script, you might be in much better shape.

Referring to this older post by @john9527, these "skip the event" logs happen after 30 seconds of waiting. So maybe having the VLAN in the wrong place actually is affecting things indirectly. Test and we shall see!
[SOLVED-FOR REAL] rc_service: skip the event: start_firewall.

Yes, I hope so. I have it all set up now, waiting for a reboot tomorrow

One thing that I still can't figure out is that it worked before the FW-update. I have not changed any of the scripts between the FW-versions. But we'll see how it goes tomorrow!

 

[dave14305]

Yes, I hope so. I have it all set up now, waiting for a reboot tomorrow

One thing that I still can't figure out is that it worked before the FW-update. I have not changed any of the scripts between the FW-versions. But we'll see how it goes tomorrow!

The unknown is really what else ASUS changed in their closed-source code beneath any modifications Merlin makes to the open-source code. In theory, ASUS may have changed the commands invoked by the VLAN script, or how long the rc_service waits in this release. Everything is suspect when "nothing changes."

 

[FalconB]

Well, what can I say!? Yous guys are geniuses!!! After moving the VLAN-command from /jffs/service-event to /jffs/services-start, where it should have been placed in the beginning if I would have been better at reading instructions and using my brain, it now seems to work. I can now do soft and hard reboot and still get the time sync. I also removed the ntp-command from my /jffs/scripts/services-start and the previously suggested 'server=/ntp.se/1.1.1.1' from my /jffs/configs/dnsmasq.conf.add. Below is a snippet of the syslog:

May  5 07:05:21 custom_script: Running /jffs/scripts/service-event (args: stop ntpd)
May  5 07:05:22 custom_script: Running /jffs/scripts/service-event (args: start ntpd)
May  5 07:05:23 custom_script: Running /jffs/scripts/pre-mount (args: /dev/sda1 ext4)
May  5 07:05:23 miniupnpd[1123]: HTTP listening on port 45602
May  5 07:05:23 miniupnpd[1123]: Listening for NAT-PMP/PCP traffic on port 5351
May  5 07:05:23 ntpd: Started ntpd

So, once again, a very big thank you to all you people trying to help me out. This forum and its members are awesome, keep it up!

Unfortunaltely I see a pattern here and that is unfortunately me . Most of my issues I've had are caused by me doing stuff that I don't fully understand, ending up in theses scenarios. But I'm learning, so I hope you will continue to put up with me and my mistakes .

PS
And @Martineau, you seem to have been wrong (first time ever?)! The VLAN-script placement actually seem to have been related to the ntp-issue (even though not in a direct way). Thanks!
DS

 

[Martineau]

P.S. @Martineau, you seem to have been wrong (first time ever?)!

The VLAN-script placement actually seem to have been related to the ntp-issue (even though not in a direct way).​

Well, what can I say!? Yous guys are geniuses!!! After moving the VLAN-command from /jffs/service-event to /jffs/services-start, where it should have been placed in the beginning if I would have been better at reading instructions and using my brain, it now seems to work. I can now do soft and hard reboot and still get the time sync. I also removed the ntp-command from my /jffs/scripts/services-start and the previously suggested 'server=/ntp.se/1.1.1.1' from my /jffs/configs/dnsmasq.conf.add. Below is a snippet of the syslog:

May  5 07:05:21 custom_script: Running /jffs/scripts/service-event (args: stop ntpd)
May  5 07:05:22 custom_script: Running /jffs/scripts/service-event (args: start ntpd)
May  5 07:05:23 custom_script: Running /jffs/scripts/pre-mount (args: /dev/sda1 ext4)
May  5 07:05:23 miniupnpd[1123]: HTTP listening on port 45602
May  5 07:05:23 miniupnpd[1123]: Listening for NAT-PMP/PCP traffic on port 5351
May  5 07:05:23 ntpd: Started ntpd

So, once again, a very big thank you to all you people trying to help me out. This forum and its members are awesome, keep it up!

Unfortunaltely I see a pattern here and that is unfortunately me . Most of my issues I've had are caused by me doing stuff that I don't fully understand, ending up in theses scenarios. But I'm learning, so I hope you will continue to put up with me and my mistakes .

Thanks!

Guilty as charged

However, your honour, in my defence

"Users Cripple Routers. But the Scripts seem to Matter."
​

to paraphrase a popular armaments quote ".....But the Bullets Seem to Matter."

Forthwith, I shall remove all my scripts/posts and leave the forum immediately in shame.

 

[FalconB]

Guilty as charged

However, your honour, in my defence

"Users Cripple Routers. But the Scripts seem to Matter."
​

to paraphrase a popular armaments quote ".....But the Bullets Seem to Matter."

Forthwith, I shall remove all my scripts/posts and leave the forum immediately in shame.

Oh no! We are all doomed! I hope you took no offence in my attempt of sarcasm. The forum needs people like you.