I've been experimenting recently, in version 0.71, with connman's ability to
launch the NTP daemon in one-shot mode when the service state transitions to
online mode.
However, what I notice in practice is that when the time server is any named
entity (e.g. time.ubuntu.org or pool.ntp.org), the NTP daemon fails to resolve
the name, ntpd_intres gets forked and launched and then indefinitely fails to
resolve the name.
If I rework the plugin to delay NTP start up and then periodically retry
several times over time, I see the same results: NTP never successfully
resolves the name.
If I run tcpdump while connman is starting up and bringing up the service, I
see requests going out for wpad.<mydomain> to the name server; however, I never
see a resolve request going out on the wire for the time server, ever.
If I manually run the NTP daemon in one-shot mode, the name resolves
immediately and time is updated. If I run nslookup on the time server while all
these retries and failures are occurring from the instance dispatched in
connman, the name resolves successfully.
Has anyone else seen this? Here's the experimental output:
# ./connmand -n & tail -f /var/log/messages | grep ntp &
connmand[412]: Connection Manager version 0.71
connmand[412]: Checking loopback interface settings
connmand[412]: System hostname is fish
connmand[412]: System domainname is domain.actdsltmp
connmand[412]: Adding profile default
connmand[412]: Failed to open RFKILL control device
connmand[412]: lo {newlink} index 1 operstate 0 <UNKNOWN>
connmand[412]: wlan0 {create} index 2 type 1 <ETHER>
connmand[412]: wlan0 {RX} 47543 packets 12791557 bytes
connmand[412]: wlan0 {TX} 2056 packets 220819 bytes
connmand[412]: wlan0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
connmand[412]: wlan0 {newlink} index 2 address 00:0c:29:4c:56:a2 mtu 1500
connmand[412]: wlan0 {newlink} index 2 operstate 6 <UP>
connmand[412]: wlan0 runs an unsupported 802.11 driver
connmand[412]: Create interface wlan0 [ wifi ]
connmand[412]: mmap error Invalid argument for
/var/lib/connman/stats/wifi_000c294c56a2_54616e6b_managed_psk.data
connmand[412]:
/var/lib/connman/stats/wifi_000c294c56a2_54616e6b_managed_psk.data might be on
a file system, such as JFFS2, that does not allow shared writable mappings.
connmand[412]: wlan0 up
connmand[412]: wlan0 lower up
connmand[412]: wlan0 up
connmand[412]: wlan0 lower up
connmand[412]: Skipping disconnect of 54616e6b_managed_psk
connmand[412]: wlan0 {add} route ff00:: gw :: scope 0 <UNIVERSE>
connmand[412]: wlan0 {add} route fe80:: gw :: scope 0 <UNIVERSE>
connmand[412]: wlan0 {newlink} index 2 address 00:0c:29:4c:56:a2 mtu 1500
connmand[412]: wlan0 {RX} 47552 packets 12793289 bytes
connmand[412]: wlan0 {TX} 2057 packets 220909 bytes
connmand[412]: wlan0 {update} flags 69635 <UP,LOWER_UP>
connmand[412]: wlan0 {newlink} index 2 address 00:0c:29:4c:56:a2 mtu 1500
connmand[412]: wlan0 {newlink} index 2 operstate 5 <DORMANT>
connmand[412]: wlan0 {RX} 47552 packets 12793289 bytes
connmand[412]: wlan0 {TX} 2057 packets 220909 bytes
connmand[412]: wlan0 {update} flags 4099 <UP>
connmand[412]: wlan0 lower down
connmand[412]: wlan0 lower down
connmand[412]: Clear IPv6 address error
connmand[412]: wlan0 {newlink} index 2 address 00:0c:29:4c:56:a2 mtu 1500
connmand[412]: wlan0 {newlink} index 2 operstate 2 <DOWN>
connmand[412]: wlan0 {RX} 47552 packets 12793289 bytes
connmand[412]: wlan0 {TX} 2057 packets 220909 bytes
connmand[412]: wlan0 {update} flags 69635 <UP,LOWER_UP>
connmand[412]: wlan0 {newlink} index 2 address 00:0c:29:4c:56:a2 mtu 1500
connmand[412]: wlan0 {newlink} index 2 operstate 5 <DORMANT>
connmand[412]: wlan0 {RX} 47554 packets 12793567 bytes
connmand[412]: wlan0 {TX} 2059 packets 221157 bytes
connmand[412]: wlan0 {update} flags 69699 <UP,RUNNING,LOWER_UP>
connmand[412]: wlan0 lower up
connmand[412]: wlan0 lower up
connmand[412]: wlan0 {newlink} index 2 address 00:0c:29:4c:56:a2 mtu 1500
connmand[412]: wlan0 {newlink} index 2 operstate 6 <UP>
connmand[412]: mmap error Invalid argument for
/var/lib/connman/stats/wifi_000c294c56a2_54616e6b_managed_psk.data
connmand[412]:
/var/lib/connman/stats/wifi_000c294c56a2_54616e6b_managed_psk.data might be on
a file system, such as JFFS2, that does not allow shared writable mappings.
connmand[412]: Setting domainname to domain.actdsltmp
connmand[412]: Deleting host route failed (No such process)
connmand[412]: Adding DNS server 10.2.0.1
connmand[412]: Enabling DNS server 10.2.0.1
connmand[412]: Enabling DNS server 10.2.0.1
connmand[412]: 946688189: Will start NTPD in 5 seconds.
connmand[412]: Enabling DNS server 10.2.0.1
connmand[412]: Removing DNS server 10.2.0.1
connmand[412]: Adding DNS server 10.2.0.1
connmand[412]: Enabling DNS server 10.2.0.1
connmand[412]: wlan0 {add} address 10.2.1.231/16 label wlan0 family 2
connmand[412]: wlan0 ip bound
connmand[412]: wlan0 ip bound
connmand[412]: wlan0 {add} route 10.2.0.0 gw 0.0.0.0 scope 253 <LINK>
connmand[412]: wlan0 {add} route 10.2.0.1 gw 0.0.0.0 scope 253 <LINK>
connmand[412]: wlan0 {del} route fe80:: gw :: scope 0 <UNIVERSE>
connmand[412]: wlan0 {del} route ff00:: gw :: scope 0 <UNIVERSE>
connmand[412]: wlan0 ip bound
connmand[412]: wlan0 ip bound
connmand[412]: wlan0 {add} route 0.0.0.0 gw 10.2.0.1 scope 0 <UNIVERSE>
connmand[412]: 946688195: Launching NTPD.
Jan 1 00:56:35 fish daemon.notice ntpd[415]: ntpd [email protected] Fri Apr 22
18:24:18 UTC 2011 (1)
Jan 1 00:56:35 fish daemon.debug ntpd[415]: set_process_priority: Leave
priority alone: priority_done is <2>
Jan 1 00:56:35 fish daemon.notice ntpd[415]: proto: precision = 30.517 usec
Jan 1 00:56:35 fish daemon.debug ntpd[415]: ntp_io: estimated max descriptors:
768, initial socket boundary: 16
Jan 1 00:56:35 fish daemon.info ntpd[415]: Listen and drop on 0 v4wildcard
0.0.0.0 UDP 123
Jan 1 00:56:35 fish daemon.info ntpd[415]: Listen and drop on 1 v6wildcard ::
UDP 123
Jan 1 00:56:35 fish daemon.info ntpd[415]: Listen normally on 2 lo 127.0.0.1
UDP 123
Jan 1 00:56:35 fish daemon.info ntpd[415]: Listen normally on 3 wlan0
10.2.1.231 UDP 123
Jan 1 00:56:35 fish daemon.info ntpd[415]: Listen normally on 4 lo ::1 UDP 123
Jan 1 00:56:35 fish daemon.info ntpd[415]: getaddrinfo pool.ntp.org
Jan 1 00:56:35 fish daemon.info ntpd[415]: getaddrinfo -2
Jan 1 00:56:35 fish daemon.err ntpd[415]: getaddrinfo: "pool.ntp.org" invalid
host address, ignored
Jan 1 00:56:35 fish daemon.info ntpd[415]: Resolution for pool.ntp.org with
status 0
Jan 1 00:56:35 fish daemon.info ntpd[415]: Deferring DNS for pool.ntp.org 1
Jan 1 00:56:35 fish daemon.debug ntpd[418]: signal_no_reset: signal 17 had
flags 4000000
Jan 1 00:56:35 fish daemon.info ntpd_intres[418]: NTP_INTRES running
Jan 1 00:56:35 fish daemon.info ntpd_intres[418]: intres: <pool.ntp.org> 1 0 3
4 0 0 8 0 0 *
Jan 1 00:56:37 fish daemon.info ntpd_intres[418]: Running doconfigure with DNS
Jan 1 00:56:37 fish daemon.info ntpd_intres[418]: doconfigure: <pool.ntp.org>
has peeraddr 0.0.0.0
Jan 1 00:56:37 fish daemon.info ntpd_intres[418]: findhostaddr: Resolving
<pool.ntp.org>
Jan 1 00:56:37 fish daemon.info ntpd_intres[418]: findhostaddr: Resolve error
-2: Name or service not known
Jan 1 00:56:37 fish daemon.err ntpd_intres[418]: host name not found:
pool.ntp.org
Jan 1 00:56:37 fish daemon.err ntpd_intres[418]: intres: got error status of:
-2: Name or service not known
Jan 1 00:56:37 fish daemon.info ntpd_intres[418]: resolve_timer: 0->2
# nslookup pool.ntp.org
Server: 127.0.0.1
Address 1: 127.0.0.1 localhost.localdomain
Name: pool.ntp.org
Address 1: 74.207.249.60 dione.cbane.org
Address 2: 68.68.18.78 68.68.18.78.customer.bluemilenetworks.com
Address 3: 97.107.134.28 rigel.jeffkaplan.net
connmand[412]: 946688225: ntpd_stop: Stopping current NTP task we started.
connmand[412]: 946688225: Will start NTPD in 5 seconds.
Jan 1 00:57:05 fish daemon.debug connmand[412]: 946688225: ntpd_stop: Stopping
current NTP task we started.
Jan 1 00:57:05 fish daemon.notice ntpd[415]: ntpd exiting on signal 15
Jan 1 00:57:07 fish daemon.info ntpd_intres[418]: parent died before we
finished, exiting
connmand[412]: 946688230: Launching NTPD.
Jan 1 00:57:10 fish daemon.notice ntpd[420]: ntpd [email protected] Fri Apr 22
18:24:18 UTC 2011 (1)
Jan 1 00:57:10 fish daemon.debug ntpd[420]: set_process_priority: Leave
priority alone: priority_done is <2>
Jan 1 00:57:10 fish daemon.notice ntpd[420]: proto: precision = 30.517 usec
Jan 1 00:57:10 fish daemon.debug ntpd[420]: ntp_io: estimated max descriptors:
768, initial socket boundary: 16
Jan 1 00:57:10 fish daemon.info ntpd[420]: Listen and drop on 0 v4wildcard
0.0.0.0 UDP 123
Jan 1 00:57:10 fish daemon.info ntpd[420]: Listen and drop on 1 v6wildcard ::
UDP 123
Jan 1 00:57:10 fish daemon.info ntpd[420]: Listen normally on 2 lo 127.0.0.1
UDP 123
Jan 1 00:57:10 fish daemon.info ntpd[420]: Listen normally on 3 wlan0
10.2.1.231 UDP 123
Jan 1 00:57:10 fish daemon.info ntpd[420]: Listen normally on 4 lo ::1 UDP 123
Jan 1 00:57:10 fish daemon.info ntpd[420]: getaddrinfo pool.ntp.org
Jan 1 00:57:10 fish daemon.info ntpd[420]: getaddrinfo -2
Jan 1 00:57:10 fish daemon.err ntpd[420]: getaddrinfo: "pool.ntp.org" invalid
host address, ignored
Jan 1 00:57:10 fish daemon.info ntpd[420]: Resolution for pool.ntp.org with
status 0
Jan 1 00:57:10 fish daemon.info ntpd[420]: Deferring DNS for pool.ntp.org 1
Jan 1 00:57:10 fish daemon.debug ntpd[423]: signal_no_reset: signal 17 had
flags 4000000
Jan 1 00:57:10 fish daemon.info ntpd_intres[423]: NTP_INTRES running
Jan 1 00:57:10 fish daemon.info ntpd_intres[423]: intres: <pool.ntp.org> 1 0 3
4 0 0 8 0 0 *
Jan 1 00:57:12 fish daemon.info ntpd_intres[423]: Running doconfigure with DNS
Jan 1 00:57:12 fish daemon.info ntpd_intres[423]: doconfigure: <pool.ntp.org>
has peeraddr 0.0.0.0
Jan 1 00:57:12 fish daemon.info ntpd_intres[423]: findhostaddr: Resolving
<pool.ntp.org>
Jan 1 00:57:12 fish daemon.info ntpd_intres[423]: findhostaddr: Resolve error
-2: Name or service not known
Jan 1 00:57:12 fish daemon.err ntpd_intres[423]: host name not found:
pool.ntp.org
Jan 1 00:57:12 fish daemon.err ntpd_intres[423]: intres: got error status of:
-2: Name or service not known
Jan 1 00:57:12 fish daemon.info ntpd_intres[423]: resolve_timer: 0->2
# nslookup pool.ntp.org
Server: 127.0.0.1
Address 1: 127.0.0.1 localhost.localdomain
Name: pool.ntp.org
Address 1: 68.68.18.78 68.68.18.78.customer.bluemilenetworks.com
Address 2: 169.229.70.183 ntp1.Housing.Berkeley.EDU
Address 3: 169.229.70.64 ntp2.Housing.Berkeley.EDU
connmand[412]: 946688260: ntpd_stop: Stopping current NTP task we started.
connmand[412]: 946688260: Will start NTPD in 5 seconds.
Jan 1 00:57:40 fish daemon.debug connmand[412]: 946688260: ntpd_stop: Stopping
current NTP task we started.
Jan 1 00:57:40 fish daemon.notice ntpd[420]: ntpd exiting on signal 15
Jan 1 00:57:42 fish daemon.info ntpd_intres[423]: parent died before we
finished, exiting
Jan 1 00:57:45 fish daemon.notice ntpd[426]: ntpd [email protected] Fri Apr 22
18:24:18 UTC 2011 (1)
Jan 1 00:57:45 fish daemon.debug ntpd[426]: set_process_priority: Leave
priority alone: priority_done is <2>
Jan 1 00:57:45 fish daemon.notice ntpd[426]: proto: precision = 30.517 usec
Jan 1 00:57:45 fish daemon.debug ntpd[426]: ntp_io: estimated max descriptors:
768, initial socket boundary: 16
Jan 1 00:57:45 fish daemon.info ntpd[426]: Listen and drop on 0 v4wildcard
0.0.0.0 UDP 123
Jan 1 00:57:45 fish daemon.info ntpd[426]: Listen and drop on 1 v6wildcard ::
UDP 123
Jan 1 00:57:45 fish daemon.info ntpd[426]: Listen normally on 2 lo 127.0.0.1
UDP 123
Jan 1 00:57:45 fish daemon.info ntpd[426]: Listen normally on 3 wlan0
10.2.1.231 UDP 123
Jan 1 00:57:45 fish daemon.info ntpd[426]: Listen normally on 4 lo ::1 UDP 123
Jan 1 00:57:45 fish daemon.info ntpd[426]: getaddrinfo pool.ntp.org
Jan 1 00:57:45 fish daemon.info ntpd[426]: getaddrinfo -2
Jan 1 00:57:45 fish daemon.err ntpd[426]: getaddrinfo: "pool.ntp.org" invalid
host address, ignored
Jan 1 00:57:45 fish daemon.info ntpd[426]: Resolution for pool.ntp.org with
status 0
Jan 1 00:57:45 fish daemon.info ntpd[426]: Deferring DNS for pool.ntp.org 1
Jan 1 00:57:45 fish daemon.debug ntpd[429]: signal_no_reset: signal 17 had
flags 4000000
Jan 1 00:57:45 fish daemon.info ntpd_intres[429]: NTP_INTRES running
Jan 1 00:57:45 fish daemon.info ntpd_intres[429]: intres: <pool.ntp.org> 1 0 3
4 0 0 8 0 0 *
Jan 1 00:57:47 fish daemon.info ntpd_intres[429]: Running doconfigure with DNS
Jan 1 00:57:47 fish daemon.info ntpd_intres[429]: doconfigure: <pool.ntp.org>
has peeraddr 0.0.0.0
Jan 1 00:57:47 fish daemon.info ntpd_intres[429]: findhostaddr: Resolving
<pool.ntp.org>
Jan 1 00:57:47 fish daemon.info ntpd_intres[429]: findhostaddr: Resolve error
-2: Name or service not known
Jan 1 00:57:47 fish daemon.err ntpd_intres[429]: host name not found:
pool.ntp.org
Jan 1 00:57:47 fish daemon.err ntpd_intres[429]: intres: got error status of:
-2: Name or service not known
Jan 1 00:57:47 fish daemon.info ntpd_intres[429]: resolve_timer: 0->2
# nslookup pool.ntp.org
Server: 127.0.0.1
Address 1: 127.0.0.1 localhost.localdomain
Name: pool.ntp.org
Address 1: 69.65.40.29 barricade.rack911.com
Address 2: 72.18.205.157 lasvegas-nv-datacenter.com
Address 3: 199.4.29.166
connmand[412]: 946688295: ntpd_stop: Stopping current NTP task we started.
connmand[412]: 946688295: Will start NTPD in 5 seconds.
Jan 1 00:58:15 fish daemon.debug connmand[412]: 946688295: ntpd_stop: Stopping
current NTP task we started.
Jan 1 00:58:15 fish daemon.notice ntpd[426]: ntpd exiting on signal 15
Jan 1 00:58:17 fish daemon.info ntpd_intres[429]: parent died before we
finished, exiting
connmand[412]: 946688300: Launching NTPD.
Jan 1 00:58:20 fish daemon.notice ntpd[431]: ntpd [email protected] Fri Apr 22
18:24:18 UTC 2011 (1)
Jan 1 00:58:20 fish daemon.debug ntpd[431]: set_process_priority: Leave
priority alone: priority_done is <2>
Jan 1 00:58:20 fish daemon.notice ntpd[431]: proto: precision = 30.517 usec
Jan 1 00:58:20 fish daemon.debug ntpd[431]: ntp_io: estimated max descriptors:
768, initial socket boundary: 16
Jan 1 00:58:20 fish daemon.info ntpd[431]: Listen and drop on 0 v4wildcard
0.0.0.0 UDP 123
Jan 1 00:58:20 fish daemon.info ntpd[431]: Listen and drop on 1 v6wildcard ::
UDP 123
Jan 1 00:58:20 fish daemon.info ntpd[431]: Listen normally on 2 lo 127.0.0.1
UDP 123
Jan 1 00:58:20 fish daemon.info ntpd[431]: Listen normally on 3 wlan0
10.2.1.231 UDP 123
Jan 1 00:58:20 fish daemon.info ntpd[431]: Listen normally on 4 lo ::1 UDP 123
Jan 1 00:58:20 fish daemon.info ntpd[431]: getaddrinfo pool.ntp.org
Jan 1 00:58:20 fish daemon.info ntpd[431]: getaddrinfo -2
Jan 1 00:58:20 fish daemon.err ntpd[431]: getaddrinfo: "pool.ntp.org" invalid
host address, ignored
Jan 1 00:58:20 fish daemon.info ntpd[431]: Resolution for pool.ntp.org with
status 0
Jan 1 00:58:20 fish daemon.info ntpd[431]: Deferring DNS for pool.ntp.org 1
Jan 1 00:58:20 fish daemon.debug ntpd[434]: signal_no_reset: signal 17 had
flags 4000000
Jan 1 00:58:20 fish daemon.info ntpd_intres[434]: NTP_INTRES running
Jan 1 00:58:20 fish daemon.info ntpd_intres[434]: intres: <pool.ntp.org> 1 0 3
4 0 0 8 0 0 *
Jan 1 00:58:22 fish daemon.info ntpd_intres[434]: Running doconfigure with DNS
Jan 1 00:58:22 fish daemon.info ntpd_intres[434]: doconfigure: <pool.ntp.org>
has peeraddr 0.0.0.0
Jan 1 00:58:22 fish daemon.info ntpd_intres[434]: findhostaddr: Resolving
<pool.ntp.org>
Jan 1 00:58:22 fish daemon.info ntpd_intres[434]: findhostaddr: Resolve error
-2: Name or service not known
Jan 1 00:58:22 fish daemon.err ntpd_intres[434]: host name not found:
pool.ntp.org
Jan 1 00:58:22 fish daemon.err ntpd_intres[434]: intres: got error status of:
-2: Name or service not known
Jan 1 00:58:22 fish daemon.info ntpd_intres[434]: resolve_timer: 0->2
# nslookup pool.ntp.org
Server: 127.0.0.1
Address 1: 127.0.0.1 localhost.localdomain
Name: pool.ntp.org
Address 1: 69.164.222.108 mail.melancthon.net
Address 2: 67.159.5.90 B1-66ER.matrix.gs
Address 3: 204.235.61.9 name1.glorb.com
connmand[412]: 946688330: ntpd_timeout: NTP did not complete: no retries left!
connmand[412]: 946688330: ntpd_stop: Stopping current NTP task we started.
Jan 1 00:58:50 fish daemon.debug connmand[412]: 946688330: ntpd_timeout: NTP
did not complete: no retries left!
Jan 1 00:58:50 fish daemon.debug connmand[412]: 946688330: ntpd_stop: Stopping
current NTP task we started.
Jan 1 00:58:50 fish daemon.notice ntpd[431]: ntpd exiting on signal 15
Jan 1 00:58:52 fish daemon.info ntpd_intres[434]: parent died before we
finished, exiting
# nslookup pool.ntp.org
Server: 127.0.0.1
Address 1: 127.0.0.1 localhost.localdomain
Name: pool.ntp.org
Address 1: 63.240.161.99 mighty.poclabs.net
Address 2: 68.68.18.78 68.68.18.78.customer.bluemilenetworks.com
Address 3: 173.255.193.172 i4.fwwds.com
# ps ax | grep ntp
414 ttyS0 S 0:00 grep ntp
415 ttyS0 Z 0:00 [ntpd] <defunct>
420 ttyS0 Z 0:00 [ntpd] <defunct>
426 ttyS0 Z 0:00 [ntpd] <defunct>
431 ttyS0 Z 0:00 [ntpd] <defunct>
438 ttyS0 S+ 0:00 grep ntp
# date
Fri Dec 31 16:59:50 PST 1999
# cat ./ntp.conf
server pool.ntp.org iburst
# /usr/sbin/ntpd -g -q -c ./ntp.conf
Jan 1 01:00:44 fish daemon.notice ntpd[441]: ntpd [email protected] Fri Apr 22
18:24:18 UTC 2011 (1)
Jan 1 01:00:44 fish daemon.notice ntpd[441]: proto: precision = 30.517 usec
Jan 1 01:00:44 fish daemon.debug ntpd[441]: ntp_io: estimated max descriptors:
1024, initial socket boundary: 16
Jan 1 01:00:44 fish daemon.info ntpd[441]: Listen and drop on 0 v4wildcard
0.0.0.0 UDP 123
Jan 1 01:00:44 fish daemon.info ntpd[441]: Listen and drop on 1 v6wildcard ::
UDP 123
Jan 1 01:00:44 fish daemon.info ntpd[441]: Listen normally on 2 lo 127.0.0.1
UDP 123
Jan 1 01:00:44 fish daemon.info ntpd[441]: Listen normally on 3 wlan0
10.2.1.231 UDP 123
Jan 1 01:00:44 fish daemon.info ntpd[441]: Listen normally on 4 lo::1 UDP 123
Jan 1 01:00:44 fish daemon.info ntpd[441]: getaddrinfo pool.ntp.org
Jan 1 01:00:44 fish daemon.info ntpd[441]: getaddrinfo 0
Jan 1 01:00:44 fish daemon.info ntpd[441]: Resolution for pool.ntp.org with
status 1 ntpd: time set +357080785.476768s
Apr 25 22:07:16 fish daemon.notice ntpd[441]: ntpd: time set +357080785.476768 s
# date
Mon Apr 25 15:07:18 PDT 2011
_______________________________________________
connman mailing list
[email protected]
http://lists.connman.net/listinfo/connman
