1:31 a.m.
Daniel Wagner wrote:
On 01/17/2018 08:50 AM, Daniel Wagner wrote:
> This is the attempt to fix the outstanding CM-636 bug. This is still
> not completely finished. There is some more potential to cleanup the
> timeserver code. But I thought maybe someone wants to test it. You can
> install a iptables rule to see if the retry logic works.
>
> iptables -A OUTPUT -p tcp --dport 123 -j DROP
> iptables -A OUTPUT -p udp --dport 123 -j DROP
>
> This should do the trick.
After some more debugging and removing of the unnecessary DBG() I
applied this.
I have a device using ConnMan 1.32, which is connected to the Internet through a FritzBox
home ADSL router. It is configured with NTP servers:
0.pool.ntp.org, 1.pool.ntp.org, 2.pool.ntp.org, 3.pool.ntp.org
It additionally gets the IPv4 address of the FritzBox router itself as a further NTP
server, from DHCP.
I have found that if the router is power-cycled just before the time of the next NTP sync
(which occurs at roughly 17 minute intervals), then it subsequently never does any more
NTP syncs.
I saw this recent work on CM-636 in the ConnMan git repository, so I have tried upgrading
the devices to use a recent git commit of ConnMan. Then I retested power-cycling the
router just before a scheduled NTP sync. I did the test twice, and the first time, it
still did a sync a minute later, after the router rebooted. But the second time I did the
test, the device subsequently never has done any more NTP syncs. That was roughly 14 hours
ago.
Any ideas on what is going on?
--
Craig McQueen
8:46 a.m.
New subject: Retry NTP servers periodically on startup
Hi Craig,
I have a device using ConnMan 1.32, which is connected to the
Internet through a FritzBox home ADSL router. It is configured with NTP servers:
0.pool.ntp.org, 1.pool.ntp.org, 2.pool.ntp.org, 3.pool.ntp.org
It additionally gets the IPv4 address of the FritzBox router itself
as a further NTP server, from DHCP.
I have found that if the router is power-cycled just before the time
of the next NTP sync (which occurs at roughly 17 minute intervals), then
it subsequently never does any more NTP syncs.
So ConnMan tries to sync and the router is down at this point?
I saw this recent work on CM-636 in the ConnMan git repository, so I
have tried upgrading the devices to use a recent git commit of ConnMan.
CM-636 should fix the case where ConnMan hasn't done any NTP sync yet.
After the first successful sync it is still the old algorithm. It sounds
like we need to address another fallback scenario.
Then I retested power-cycling the router just before a scheduled
NT> sync. I did the test twice, and the first time, it still did a sync a
minute later, after the router rebooted. But the second time I did the
test, the device subsequently never has done any more NTP syncs. That
was roughly 14 hours ago.
Could you post the debug log of both tests? It sounds like that in the
first case, ConnMan falls back to the aggressive retry loop and in the
second case it doesn't happen.
Thanks,
Daniel
11:12 p.m.
New subject: Retry NTP servers periodically on startup
Daniel Wagner wrote:
Hi Craig,
> I have a device using ConnMan 1.32, which is connected to the Internet
> through a FritzBox home ADSL router. It is configured with NTP servers:
> 0.pool.ntp.org, 1.pool.ntp.org, 2.pool.ntp.org, 3.pool.ntp.org It
> additionally gets the IPv4 address of the FritzBox router itself as a
> further NTP server, from DHCP.
>
> I have found that if the router is power-cycled just before the time
> of the next NTP sync (which occurs at roughly 17 minute intervals),
> then it subsequently never does any more NTP syncs.
So ConnMan tries to sync and the router is down at this point?
> I saw this recent work on CM-636 in the ConnMan git repository, so I
> have tried upgrading the devices to use a recent git commit of ConnMan.
CM-636 should fix the case where ConnMan hasn't done any NTP sync yet.
After the first successful sync it is still the old algorithm. It sounds like we
need to address another fallback scenario.
> Then I retested power-cycling the router just before a scheduled NT>
> sync. I did the test twice, and the first time, it still did a sync a
> minute later, after the router rebooted. But the second time I did the
> test, the device subsequently never has done any more NTP syncs. That
was roughly 14 hours ago.
Could you post the debug log of both tests? It sounds like that in the first
case, ConnMan falls back to the aggressive retry loop and in the second case
it doesn't happen.
Mar 21 18:56:05 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): -0.001583 sec
Mar 21 19:13:09 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): -0.000066 sec
Mar 21 19:30:13 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): +0.000107 sec
Mar 21 19:47:17 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): +0.000584 sec
Mar 21 20:04:21 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): -0.000795 sec
Mar 21 20:04:52 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): -0.009179 sec
Mar 21 20:21:56 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): +0.000409 sec
Mar 21 20:39:00 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): -0.000277 sec
Mar 21 20:56:04 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): +0.000192 sec
Mar 21 21:04:55 ws000024 authpriv.warn dropbear[9011]: lastlog_perform_login: Couldn't
stat /var/log/lastlog: No such file or directory
Mar 21 21:04:55 ws000024 authpriv.warn dropbear[9011]: lastlog_openseek: /var/log/lastlog
is not a file or directory!
Mar 21 21:12:21 ws000024 user.info kernel: [212910.721918] cpsw 4a100000.ethernet eth0:
Link is Down
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {RX} 34690 packets 6471180
bytes
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {TX} 7913 packets 925409 bytes
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {update} flags 36867
<UP>
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 2
<DOWN>
Mar 21 21:12:21 ws000024 daemon.info avahi-daemon[949]: Withdrawing address record for
192.168.178.28 on eth0.
Mar 21 21:12:21 ws000024 daemon.info avahi-daemon[949]: Leaving mDNS multicast group on
interface eth0.IPv4 with address 192.168.178.28.
Mar 21 21:12:21 ws000024 daemon.info avahi-daemon[949]: Interface eth0.IPv4 no longer
relevant for mDNS.
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {del} address 192.168.178.28/24
label eth0
Mar 21 21:12:21 ws000024 daemon.info connmand[1047]: eth0 {del} route 192.168.178.0 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:12:29 ws000024 user.info kernel: [212919.252634] cpsw 4a100000.ethernet eth0:
Link is Up - 100Mbps/Full - flow control off
Mar 21 21:12:29 ws000024 daemon.info connmand[1047]: eth0 {RX} 34690 packets 6471180
bytes
Mar 21 21:12:29 ws000024 daemon.info connmand[1047]: eth0 {TX} 7913 packets 925409 bytes
Mar 21 21:12:29 ws000024 daemon.info connmand[1047]: eth0 {update} flags 102467
<UP,RUNNING,LOWER_UP>
Mar 21 21:12:29 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:12:29 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 6
<UP>
Mar 21 21:12:29 ws000024 daemon.warn connmand[1047]: ipconfig state 3 ipconfig method 1
Mar 21 21:12:42 ws000024 daemon.info connmand[1047]: eth0 {RX} 34690 packets 6471180
bytes
Mar 21 21:12:42 ws000024 daemon.info connmand[1047]: eth0 {TX} 7916 packets 927179 bytes
Mar 21 21:12:42 ws000024 daemon.info connmand[1047]: eth0 {update} flags 36867
<UP>
Mar 21 21:12:42 ws000024 user.info kernel: [212931.762940] cpsw 4a100000.ethernet eth0:
Link is Down
Mar 21 21:12:42 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:12:42 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 2
<DOWN>
Mar 21 21:13:24 ws000024 user.info kernel: [212974.215729] cpsw 4a100000.ethernet eth0:
Link is Up - 100Mbps/Full - flow control rx/tx
Mar 21 21:13:24 ws000024 daemon.info connmand[1047]: eth0 {RX} 34690 packets 6471180
bytes
Mar 21 21:13:24 ws000024 daemon.info connmand[1047]: eth0 {TX} 7916 packets 927179 bytes
Mar 21 21:13:24 ws000024 daemon.info connmand[1047]: eth0 {update} flags 102467
<UP,RUNNING,LOWER_UP>
Mar 21 21:13:24 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:13:24 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 6
<UP>
Mar 21 21:13:24 ws000024 daemon.warn connmand[1047]: ipconfig state 3 ipconfig method 1
Mar 21 21:13:35 ws000024 daemon.info avahi-daemon[949]: Joining mDNS multicast group on
interface eth0.IPv4 with address 192.168.178.28.
Mar 21 21:13:35 ws000024 daemon.info avahi-daemon[949]: New relevant interface eth0.IPv4
for mDNS.
Mar 21 21:13:35 ws000024 daemon.info avahi-daemon[949]: Registering new address record for
192.168.178.28 on eth0.IPv4.
Mar 21 21:13:35 ws000024 daemon.info connmand[1047]: Setting domainname to fritz.box
Mar 21 21:13:35 ws000024 daemon.info connmand[1047]: eth0 {add} address 192.168.178.28/24
label eth0 family 2
Mar 21 21:13:35 ws000024 daemon.info connmand[1047]: eth0 {add} route 192.168.178.0 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:13:35 ws000024 daemon.info connmand[1047]: eth0 {add} route 192.168.178.1 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:13:35 ws000024 daemon.info connmand[1047]: eth0 {add} route 0.0.0.0 gw
192.168.178.1 scope 0 <UNIVERSE>
Mar 21 21:13:39 ws000024 daemon.warn connmand[1047]: Online check failed for 0xd8ae8
Wired
Mar 21 21:14:21 ws000024 daemon.info connmand[1047]: Skipping server 192.168.178.1 KoD
code
Mar 21 21:14:22 ws000024 daemon.info connmand[1047]: ntp: adjust (slew): -0.000754 sec
Mar 21 21:31:18 ws000024 daemon.info connmand[1047]: eth0 {RX} 35273 packets 6558646
bytes
Mar 21 21:31:18 ws000024 daemon.info connmand[1047]: eth0 {TX} 8147 packets 971230 bytes
Mar 21 21:31:18 ws000024 daemon.info connmand[1047]: eth0 {update} flags 36867
<UP>
Mar 21 21:31:18 ws000024 user.info kernel: [214048.618763] cpsw 4a100000.ethernet eth0:
Link is Down
Mar 21 21:31:19 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:31:19 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 2
<DOWN>
Mar 21 21:31:19 ws000024 daemon.info avahi-daemon[949]: Withdrawing address record for
192.168.178.28 on eth0.
Mar 21 21:31:19 ws000024 daemon.info avahi-daemon[949]: Leaving mDNS multicast group on
interface eth0.IPv4 with address 192.168.178.28.
Mar 21 21:31:19 ws000024 daemon.info avahi-daemon[949]: Interface eth0.IPv4 no longer
relevant for mDNS.
Mar 21 21:31:19 ws000024 daemon.info connmand[1047]: eth0 {del} address 192.168.178.28/24
label eth0
Mar 21 21:31:19 ws000024 daemon.info connmand[1047]: eth0 {del} route 192.168.178.0 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:31:29 ws000024 daemon.info connmand[1047]: eth0 {RX} 35273 packets 6558646
bytes
Mar 21 21:31:29 ws000024 daemon.info connmand[1047]: eth0 {TX} 8147 packets 971230 bytes
Mar 21 21:31:29 ws000024 daemon.info connmand[1047]: eth0 {update} flags 102467
<UP,RUNNING,LOWER_UP>
Mar 21 21:31:29 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:31:29 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 6
<UP>
Mar 21 21:31:29 ws000024 user.info kernel: [214058.749514] cpsw 4a100000.ethernet eth0:
Link is Up - 100Mbps/Full - flow control off
Mar 21 21:31:29 ws000024 daemon.warn connmand[1047]: ipconfig state 3 ipconfig method 1
Mar 21 21:31:41 ws000024 daemon.info connmand[1047]: eth0 {RX} 35273 packets 6558646
bytes
Mar 21 21:31:41 ws000024 daemon.info connmand[1047]: eth0 {TX} 8150 packets 973000 bytes
Mar 21 21:31:41 ws000024 daemon.info connmand[1047]: eth0 {update} flags 36867
<UP>
Mar 21 21:31:41 ws000024 user.info kernel: [214071.259645] cpsw 4a100000.ethernet eth0:
Link is Down
Mar 21 21:31:41 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:31:41 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 2
<DOWN>
Mar 21 21:31:45 ws000024 daemon.info connmand[1047]: eth0 {RX} 35273 packets 6558646
bytes
Mar 21 21:31:45 ws000024 daemon.info connmand[1047]: eth0 {TX} 8150 packets 973000 bytes
Mar 21 21:31:45 ws000024 daemon.info connmand[1047]: eth0 {update} flags 102467
<UP,RUNNING,LOWER_UP>
Mar 21 21:31:45 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 address
00:11:B9:09:00:06 mtu 1500
Mar 21 21:31:45 ws000024 daemon.info connmand[1047]: eth0 {newlink} index 2 operstate 6
<UP>
Mar 21 21:31:45 ws000024 user.info kernel: [214075.390595] cpsw 4a100000.ethernet eth0:
Link is Up - 100Mbps/Full - flow control rx/tx
Mar 21 21:31:45 ws000024 daemon.warn connmand[1047]: ipconfig state 3 ipconfig method 1
Mar 21 21:32:31 ws000024 daemon.info avahi-daemon[949]: Joining mDNS multicast group on
interface eth0.IPv4 with address 169.254.46.220.
Mar 21 21:32:31 ws000024 daemon.info avahi-daemon[949]: New relevant interface eth0.IPv4
for mDNS.
Mar 21 21:32:31 ws000024 daemon.info avahi-daemon[949]: Registering new address record for
169.254.46.220 on eth0.IPv4.
Mar 21 21:32:32 ws000024 daemon.info connmand[1047]: eth0 {add} address 169.254.46.220/16
label eth0 family 2
Mar 21 21:32:32 ws000024 daemon.info connmand[1047]: eth0 {add} route 169.254.0.0 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:32:32 ws000024 daemon.info connmand[1047]: eth0 {add} route 0.0.0.0 gw 0.0.0.0
scope 253 <LINK>
Mar 21 21:33:21 ws000024 daemon.info avahi-daemon[949]: Withdrawing address record for
169.254.46.220 on eth0.
Mar 21 21:33:21 ws000024 daemon.info avahi-daemon[949]: Leaving mDNS multicast group on
interface eth0.IPv4 with address 169.254.46.220.
Mar 21 21:33:21 ws000024 daemon.info avahi-daemon[949]: Interface eth0.IPv4 no longer
relevant for mDNS.
Mar 21 21:33:21 ws000024 daemon.info avahi-daemon[949]: Joining mDNS multicast group on
interface eth0.IPv4 with address 192.168.178.28.
Mar 21 21:33:21 ws000024 daemon.info avahi-daemon[949]: New relevant interface eth0.IPv4
for mDNS.
Mar 21 21:33:21 ws000024 daemon.info avahi-daemon[949]: Registering new address record for
192.168.178.28 on eth0.IPv4.
Mar 21 21:33:21 ws000024 daemon.info connmand[1047]: eth0 {del} address 169.254.46.220/16
label eth0
Mar 21 21:33:21 ws000024 daemon.info connmand[1047]: eth0 {del} route 169.254.0.0 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:33:21 ws000024 daemon.info connmand[1047]: eth0 {add} address 192.168.178.28/24
label eth0 family 2
Mar 21 21:33:21 ws000024 daemon.info connmand[1047]: eth0 {add} route 192.168.178.0 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:33:21 ws000024 daemon.info connmand[1047]: eth0 {add} route 192.168.178.1 gw
0.0.0.0 scope 253 <LINK>
Mar 21 21:33:21 ws000024 daemon.info connmand[1047]: eth0 {add} route 0.0.0.0 gw
192.168.178.1 scope 0 <UNIVERSE>
Mar 22 12:03:03 ws000024 authpriv.warn dropbear[24228]: Login attempt for nonexistent user
from 192.168.178.21:43798
Mar 22 12:03:18 ws000024 authpriv.warn dropbear[24307]: lastlog_perform_login:
Couldn't stat /var/log/lastlog: No such file or directory
Mar 22 12:03:18 ws000024 authpriv.warn dropbear[24307]: lastlog_openseek: /var/log/lastlog
is not a file or directory!
--
Craig McQueen
7:56 a.m.
New subject: Retry NTP servers periodically on startup
Daniel Wagner wrote:
Hi Craig,
> I have a device using ConnMan 1.32, which is connected to the Internet
> through a FritzBox home ADSL router. It is configured with NTP servers:
> 0.pool.ntp.org, 1.pool.ntp.org, 2.pool.ntp.org, 3.pool.ntp.org It
> additionally gets the IPv4 address of the FritzBox router itself as a
> further NTP server, from DHCP.
>
> I have found that if the router is power-cycled just before the time
> of the next NTP sync (which occurs at roughly 17 minute intervals),
> then it subsequently never does any more NTP syncs.
So ConnMan tries to sync and the router is down at this point?
> I saw this recent work on CM-636 in the ConnMan git repository, so I
> have tried upgrading the devices to use a recent git commit of ConnMan.
CM-636 should fix the case where ConnMan hasn't done any NTP sync yet.
After the first successful sync it is still the old algorithm. It sounds like we
need to address another fallback scenario.
> Then I retested power-cycling the router just before a scheduled NT>
> sync. I did the test twice, and the first time, it still did a sync a
> minute later, after the router rebooted. But the second time I did the
> test, the device subsequently never has done any more NTP syncs. That
was roughly 14 hours ago.
Could you post the debug log of both tests? It sounds like that in the first
case, ConnMan falls back to the aggressive retry loop and in the second case
it doesn't happen.
I sent the debug logs last week. Did that provide what you needed?
I'm interested to fix this issue soon. Has any work been done on this, or could I look
into it?
Regards,
Craig McQueen
9:07 a.m.
New subject: Retry NTP servers periodically on startup
Hi Craig,
On 04/04/2018 09:56 AM, Craig McQueen wrote:
> Could you post the debug log of both tests? It sounds like that
in the first
> case, ConnMan falls back to the aggressive retry loop and in the second case
> it doesn't happen.
I sent the debug logs last week. Did that provide what you needed?
Sorry about that. Got lost in the inbox. I did look at it but I need
some more debug prints enabled. There isn't much information in the log.
Could you try to get reproduced though this time with '-d
src/ntp.c:src/timeserver.c' added to ConnMan command line?
I'm interested to fix this issue soon. Has any work been done on
this, or could I look into it?
So far I haven't done anything. If you want to dig into the problem, I
suggest to look at the debug output of ntp.c and timeserver.c and figure
out why the state machine is not going back the initial state looking
for a NTP server. From your description it seems we miss the some event
and don't reset the state machine.
Thanks,
Daniel
1:59 a.m.
New subject: Retry NTP servers periodically on startup
Daniel Wagner wrote:
On 04/04/2018 09:56 AM, Craig McQueen wrote:
>> Could you post the debug log of both tests? It sounds like that in
>> the first case, ConnMan falls back to the aggressive retry loop and
>> in the second case it doesn't happen.
>
> I sent the debug logs last week. Did that provide what you needed?
Sorry about that. Got lost in the inbox. I did look at it but I need some more
debug prints enabled. There isn't much information in the log.
Could you try to get reproduced though this time with '-d
src/ntp.c:src/timeserver.c' added to ConnMan command line?
I found I needed to run:
connmand -d ../git/src/ntp.c:../git/src/timeserver.c
(I'm cross-compiling connman with the Yocto build system)
I'm attaching a log file of a test done today. The device is plugged into an Ethernet
switch. I unplugged the switch's upstream Internet connection a few times,
corresponding roughly to these two times in the log:
Apr 11 10:37:50
Apr 11 10:56:49
Apr 11 11:01:42
The last three lines of the log are most interesting, because it tries to use an IPv6
address:
Apr 11 11:01:42 wt000043 daemon.debug connmand[30185]: ../git/src/timeserver.c:sync_next()
Using timeserver 2405:3c00:5200:100::1
Apr 11 11:01:42 wt000043 daemon.debug connmand[30185]: ../git/src/ntp.c:start_ntp() server
2405:3c00:5200:100::1 family 10
Apr 11 11:01:42 wt000043 daemon.err connmand[30185]: Failed to open time server socket
I wonder if the problem was related to it trying to use a server with an IPv6 address,
even though the device's kernel has no IPv6 capability.
After this, no further ntp/timeserver activity has occurred (for 54 minutes, at the time
I'm writing this).
> I'm interested to fix this issue soon. Has any work been
done on this, or
could I look into it?
So far I haven't done anything. If you want to dig into the problem, I suggest
to look at the debug output of ntp.c and timeserver.c and figure out why the
state machine is not going back the initial state looking for a NTP server. From
your description it seems we miss the some event and don't reset the state
machine.
I can consider looking into it. First, I would be very interested to hear your thoughts on
the IPv6 address in the above log.
By the way, what might cause ConnMan to use a 16 second polling interval, rather than the
normal 1024 s (17 min) polling interval?
Thanks and regards,
Craig McQueen
6:59 p.m.
New subject: Retry NTP servers periodically on startup
Hi Craig,
On 04/11/2018 03:59 AM, Craig McQueen wrote:
Daniel Wagner wrote:
> On 04/04/2018 09:56 AM, Craig McQueen wrote:
>>> Could you post the debug log of both tests? It sounds like that in
>>> the first case, ConnMan falls back to the aggressive retry loop and
>>> in the second case it doesn't happen.
>>
>> I sent the debug logs last week. Did that provide what you needed?
>
> Sorry about that. Got lost in the inbox. I did look at it but I need some more
> debug prints enabled. There isn't much information in the log.
> Could you try to get reproduced though this time with '-d
> src/ntp.c:src/timeserver.c' added to ConnMan command line?
I found I needed to run:
connmand -d ../git/src/ntp.c:../git/src/timeserver.c
(I'm cross-compiling connman with the Yocto build system)
Ah, the joy of Yocto :)
I'm attaching a log file of a test done today. The device is
plugged
into an Ethernet switch. I unplugged the switch's upstream Internet
connection a few times, corresponding roughly to these two times in the log:
Apr 11 10:37:50
Apr 11 10:56:49
Apr 11 11:01:42
The last three lines of the log are most interesting, because it tries to use an IPv6
address:
Apr 11 11:01:42 wt000043 daemon.debug connmand[30185]:
../git/src/timeserver.c:sync_next() Using timeserver 2405:3c00:5200:100::1
Apr 11 11:01:42 wt000043 daemon.debug connmand[30185]: ../git/src/ntp.c:start_ntp()
server 2405:3c00:5200:100::1 family 10
Apr 11 11:01:42 wt000043 daemon.err connmand[30185]: Failed to open time server socket
I wonder if the problem was related to it trying to use a server
with an IPv6 address, even though the device's kernel has no IPv6 capability.
Yes, that sounds like the source your problem. Obviously, ConnMan
shouldn't try to use an IPv6 time server if there is no support
for IPv6 in the kernel.
After this, no further ntp/timeserver activity has occurred (for 54
minutes, at the time I'm writing this).
>> I'm interested to fix this issue soon. Has any work been done on this, or
> could I look into it?
>
> So far I haven't done anything. If you want to dig into the problem, I suggest
> to look at the debug output of ntp.c and timeserver.c and figure out why the
> state machine is not going back the initial state looking for a NTP server. From
> your description it seems we miss the some event and don't reset the state
> machine.
I can consider looking into it. First, I would be very interested to
hear your thoughts on the IPv6 address in the above log.
Can you try this one here?
diff --git a/src/ntp.c b/src/ntp.c
index 3c40f6210b81..335065f813e3 100644
--- a/src/ntp.c
+++ b/src/ntp.c
@@ -531,7 +531,9 @@ static void start_ntp(struct ntp_data *nd)
nd->transmit_fd = socket(family, SOCK_DGRAM | SOCK_CLOEXEC, 0);
if (nd->transmit_fd <= 0) {
- connman_error("Failed to open time server socket");
+ if (errno != EAFNOSUPPORT)
+ connman_error("Failed to open time server socket");
+ nd->cb(false, nd->user_data);
return;
}
If this works we should check all error paths in ntp and call the
callback to let the upper layer know something didn't work out.
By the way, what might cause ConnMan to use a 16 second polling
interval, rather than the normal 1024 s (17 min) polling interval?
The decode_msg() function in ntp.c extracts the polling interval from the
message it receives. According the logs the server tell us to poll
all 16 seconds. Obviously, the ConnMan code could be buggy. Could you
check with wireshark what the actually value in the frame is?
Thanks,
Daniel
7:48 a.m.
New subject: Retry NTP servers periodically on startup
Daniel Wagner wrote:
On 04/11/2018 03:59 AM, Craig McQueen wrote:
> Daniel Wagner wrote:
>> On 04/04/2018 09:56 AM, Craig McQueen wrote:
>>>> Could you post the debug log of both tests? It sounds like that in
>>>> the first case, ConnMan falls back to the aggressive retry loop and
>>>> in the second case it doesn't happen.
>>>
>>> I sent the debug logs last week. Did that provide what you needed?
>>
>> Sorry about that. Got lost in the inbox. I did look at it but I need
>> some more debug prints enabled. There isn't much information in the log.
>> Could you try to get reproduced though this time with '-d
>> src/ntp.c:src/timeserver.c' added to ConnMan command line?
>
> I found I needed to run:
>
> connmand -d ../git/src/ntp.c:../git/src/timeserver.c
>
> (I'm cross-compiling connman with the Yocto build system)
Ah, the joy of Yocto :)
> I'm attaching a log file of a test done today. The device is plugged
> into an Ethernet switch. I unplugged the switch's upstream Internet
> connection a few times, corresponding roughly to these two times in the
log:
>
> Apr 11 10:37:50
> Apr 11 10:56:49
> Apr 11 11:01:42
>
> The last three lines of the log are most interesting, because it tries to use
an IPv6 address:
>
> Apr 11 11:01:42 wt000043 daemon.debug connmand[30185]:
> ../git/src/timeserver.c:sync_next() Using timeserver
> 2405:3c00:5200:100::1 Apr 11 11:01:42 wt000043 daemon.debug
> connmand[30185]: ../git/src/ntp.c:start_ntp() server
> 2405:3c00:5200:100::1 family 10 Apr 11 11:01:42 wt000043 daemon.err
> connmand[30185]: Failed to open time server socket
>
> I wonder if the problem was related to it trying to use a server with
> an IPv6 address, even though the device's kernel has no IPv6 capability.
Yes, that sounds like the source your problem. Obviously, ConnMan
shouldn't try to use an IPv6 time server if there is no support for IPv6 in the
kernel.
> After this, no further ntp/timeserver activity has occurred (for 54 minutes,
at the time I'm writing this).
>
>>> I'm interested to fix this issue soon. Has any work been done on
>>> this, or
>> could I look into it?
>>
>> So far I haven't done anything. If you want to dig into the problem,
>> I suggest to look at the debug output of ntp.c and timeserver.c and
>> figure out why the state machine is not going back the initial state
>> looking for a NTP server. From your description it seems we miss the
>> some event and don't reset the state machine.
>
> I can consider looking into it. First, I would be very interested to
> hear your thoughts on the IPv6 address in the above log.
Can you try this one here?
diff --git a/src/ntp.c b/src/ntp.c
index 3c40f6210b81..335065f813e3 100644
--- a/src/ntp.c
+++ b/src/ntp.c
@@ -531,7 +531,9 @@ static void start_ntp(struct ntp_data *nd)
nd->transmit_fd = socket(family, SOCK_DGRAM | SOCK_CLOEXEC,
0);
if (nd->transmit_fd <= 0) {
- connman_error("Failed to open time server socket");
+ if (errno != EAFNOSUPPORT)
+ connman_error("Failed to open time server socket");
+ nd->cb(false, nd->user_data);
return;
}
Yes, that seems to fix the issue, based on my testing today. I'll give it more testing
in the next few days.
If this works we should check all error paths in ntp and call the
callback to let
the upper layer know something didn't work out.
> By the way, what might cause ConnMan to use a 16 second polling
> interval, rather than the normal 1024 s (17 min) polling interval?
The decode_msg() function in ntp.c extracts the polling interval from the
message it receives. According the logs the server tell us to poll all 16
seconds. Obviously, the ConnMan code could be buggy. Could you check
with wireshark what the actually value in the frame is?
I think most likely it's correct, it's just that I don't have total control
over the NTP server on my network. I think it just started using a different NTP server
that was configured with that short polling interval. But if it happens again, I'll
check it with Wireshark.
Regards,
Craig McQueen
6:09 a.m.
New subject: Retry NTP servers periodically on startup
On 04/17/2018 09:48 AM, Craig McQueen wrote:
> Can you try this one here?
>
> diff --git a/src/ntp.c b/src/ntp.c
> index 3c40f6210b81..335065f813e3 100644
> --- a/src/ntp.c
> +++ b/src/ntp.c
> @@ -531,7 +531,9 @@ static void start_ntp(struct ntp_data *nd)
> nd->transmit_fd = socket(family, SOCK_DGRAM | SOCK_CLOEXEC,
> 0);
>
> if (nd->transmit_fd <= 0) {
> - connman_error("Failed to open time server socket");
> + if (errno != EAFNOSUPPORT)
> + connman_error("Failed to open time server socket");
> + nd->cb(false, nd->user_data);
> return;
> }
Yes, that seems to fix the issue, based on my testing today. I'll give it more
testing in the next few days.
Thanks for confirming. That means we need to fixup all error paths in
this file.
Will spin a patch in the coming days. Though weather is reported to be
really good so it will take a while :)
Thanks,
Daniel
1583
days inactive
1610
days old
8 comments
2 participants
participants (2)
-
Craig McQueen -
Daniel Wagner