Problem:
System starts without starting tftpd-hpa via sysv init script.
Details:
I am using stock wheezy system with Debian kernel.
And, from a newly opened desktop terminal, this is what I can do and
see.
----
$ sudo invoke-rc.d tftpd-hpa status
[FAIL] in.tftpd is not running ... failed!
invoke-rc.d: initscript tftpd-hpa, action "status" failed.
$ sudo invoke-rc.d tftpd-hpa start
[ ok ] Starting HPA's tftpd: in.tftpd.
$ sudo invoke-rc.d tftpd-hpa status
[ ok ] in.tftpd is running.
----
So this problem of tftpd-hpa not starting is only when system is
starting via sysv init program. Its log also confirms:
in.tftpd[3590]: cannot resolve local IPv4 bind address: 0.0.0.0, Name or service not known
Maybe we need to wait until NM complete IPV4 configuration.
This problem of daemon not starting is not just this tftpd-hpa.
I do not know how to fix this. Adding requirement for NM seems too
much.
One hope is that ntpd is doing something right to avoid this failure.
Osamu
PS: (Full disclosure) I have the same problem with my package. I am
hoping to see you figure this out before I figure this out by myself.
My package have other big problem as I found out....
Your init:
# Provides: tftp-hpa
# Required-Start: $local_fs $remote_fs $syslog $network
# Required-Stop: $local_fs $remote_fs $syslog $network
# Default-Start: 2 3 4 5
# Default-Stop: 1
My init:
# Provides: pxe-pdhcp
# Required-Start: $remote_fs $network $syslog $time
# Required-Stop: $remote_fs $network $syslog $time
# Should-Start:
# Should-Stop:
# Default-Start: 2 3 4 5
# Default-Stop: 0 1 6
# Short-Description: ProxyDHCP server
# Description: ProxyDHCP server for the non-DHCP server host
===============================
Reference data: /var/log/syslog (excerpts for network related things and
ntpd/minissdpd daemons as reference):
...
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (eth0): preparing device.
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (eth0): deactivating device (reason 'managed') [2]
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): using nl80211 for WiFi device control
Jun 2 09:11:11 goofy NetworkManager[3270]: <warn> (wlan0): driver supports Access Point (AP) mode
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): new 802.11 WiFi device (driver: 'rtl8192ce' ifindex: 3)
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): exported as /org/freedesktop/NetworkManager/Devices/1
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): now managed
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): device state change: unmanaged -> unavailable (reason 'managed') [10 20 2]
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): bringing up device.
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> (wlan0): deactivating device (reason 'managed') [2]
Jun 2 09:11:11 goofy kernel: [ 194.889075] r8169 0000:02:00.0: eth0: link down
Jun 2 09:11:11 goofy kernel: [ 194.889135] r8169 0000:02:00.0: eth0: link down
Jun 2 09:11:11 goofy kernel: [ 194.889918] ADDRCONF(NETDEV_UP): eth0: link is not ready
Jun 2 09:11:11 goofy NetworkManager[3270]: <warn> bluez error getting default adapter: The name org.bluez was not provided by any .service files
Jun 2 09:11:11 goofy NetworkManager[3270]: <info> modem-manager is now available
Jun 2 09:11:11 goofy in.tftpd[3590]: cannot resolve local IPv4 bind address: 0.0.0.0, Name or service not known
Jun 2 09:11:11 goofy ntpd[3545]: ntpd 4.2.6p5@1.2349-o Sat May 12 09:54:55 UTC 2012 (1)
Jun 2 09:11:11 goofy ntpd[3639]: proto: precision = 0.628 usec
Jun 2 09:11:11 goofy avahi-daemon[3646]: Found user 'avahi' (UID 106) and group 'avahi' (GID 114).
Jun 2 09:11:11 goofy ntpd[3639]: Listen and drop on 0 v4wildcard 0.0.0.0 UDP 123
Jun 2 09:11:11 goofy kernel: [ 194.998984] NET: Registered protocol family 31
...
Jun 2 09:11:11 goofy ntpd[3639]: Listen and drop on 1 v6wildcard :: UDP 123
Jun 2 09:11:11 goofy ntpd[3639]: Listen normally on 2 lo 127.0.0.1 UDP 123
Jun 2 09:11:11 goofy ntpd[3639]: Listen normally on 3 lo ::1 UDP 123
Jun 2 09:11:11 goofy ntpd[3639]: peers refreshed
Jun 2 09:11:11 goofy ntpd[3639]: Listening on routing socket on fd #20 for interface updates
Jun 2 09:11:11 goofy ntpd[3639]: Deferring DNS for 0.debian.pool.ntp.org 1
Jun 2 09:11:11 goofy ntpd[3639]: Deferring DNS for 1.debian.pool.ntp.org 1
Jun 2 09:11:11 goofy ntpd[3639]: Deferring DNS for 2.debian.pool.ntp.org 1
Jun 2 09:11:11 goofy ntpd[3639]: Deferring DNS for 3.debian.pool.ntp.org 1
Jun 2 09:11:11 goofy ntpd[3713]: signal_no_reset: signal 17 had flags 4000000
Jun 2 09:11:12 goofy kernel: [ 195.650464] Ebtables v2.0 registered
Jun 2 09:11:13 goofy ntpd_intres[3713]: host name not found: 0.debian.pool.ntp.org
Jun 2 09:11:13 goofy ntpd_intres[3713]: host name not found: 1.debian.pool.ntp.org
Jun 2 09:11:13 goofy ntpd_intres[3713]: host name not found: 2.debian.pool.ntp.org
Jun 2 09:11:13 goofy ntpd_intres[3713]: host name not found: 3.debian.pool.ntp.org
Jun 2 09:11:14 goofy minissdpd[5171]: setsockopt(udp, IP_ADD_MEMBERSHIP)(0.0.0.0): No such device
Jun 2 09:11:14 goofy minissdpd[5171]: Failed to add IPv4 multicast membership for interface 0.0.0.0.
... (now dbus and avahi-daemon are also kept)
Jun 2 09:11:29 goofy kernel: [ 212.814450] r8169 0000:02:00.0: eth0: link up
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): carrier now ON (device state 20)
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Auto-activating connection 'DHCP'.
Jun 2 09:11:29 goofy kernel: [ 212.817401] ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) starting connection 'DHCP'
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) scheduled...
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) started...
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) scheduled...
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 1 of 5 (Device Prepare) complete.
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) starting...
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): device state change: prepare -> config (reason 'none') [40 50 0]
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) successful.
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) scheduled.
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 2 of 5 (Device Configure) complete.
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) started...
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): device state change: config -> ip-config (reason 'none') [50 70 0]
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Beginning DHCPv4 transaction (timeout in 45 seconds)
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> dhclient started with pid 5648
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 3 of 5 (IP Configure Start) complete.
Jun 2 09:11:29 goofy dhclient: Internet Systems Consortium DHCP Client 4.2.4
Jun 2 09:11:29 goofy dhclient: Copyright 2004-2012 Internet Systems Consortium.
Jun 2 09:11:29 goofy dhclient: All rights reserved.
Jun 2 09:11:29 goofy dhclient: For info, please visit https://www.isc.org/software/dhcp/
Jun 2 09:11:29 goofy dhclient:
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): DHCPv4 state changed nbi -> preinit
Jun 2 09:11:29 goofy dhclient: Listening on LPF/eth0/b8:70:f4:d5:9e:c9
Jun 2 09:11:29 goofy dhclient: Sending on LPF/eth0/b8:70:f4:d5:9e:c9
Jun 2 09:11:29 goofy dhclient: Sending on Socket/fallback
Jun 2 09:11:29 goofy dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 5
Jun 2 09:11:29 goofy dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Jun 2 09:11:29 goofy dhclient: DHCPOFFER from 192.168.0.1
Jun 2 09:11:29 goofy dhclient: DHCPACK from 192.168.0.1
Jun 2 09:11:29 goofy dhclient: bound to 192.168.0.5 -- renewal in 1788 seconds.
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> (eth0): DHCPv4 state changed preinit -> bound
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> address 192.168.0.5
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> prefix 24 (255.255.255.0)
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> gateway 192.168.0.1
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> nameserver '192.168.0.1'
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Configure Commit) scheduled...
Jun 2 09:11:29 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) started...
Jun 2 09:11:29 goofy avahi-daemon[3646]: Joining mDNS multicast group on interface eth0.IPv4 with address 192.168.0.5.
Jun 2 09:11:29 goofy avahi-daemon[3646]: New relevant interface eth0.IPv4 for mDNS.
Jun 2 09:11:29 goofy avahi-daemon[3646]: Registering new address record for 192.168.0.5 on eth0.IPv4.
Jun 2 09:11:30 goofy NetworkManager[3270]: <info> (eth0): writing resolv.conf to /sbin/resolvconf
Jun 2 09:11:30 goofy NetworkManager[3270]: <info> (eth0): device state change: ip-config -> activated (reason 'none') [70 100 0]
Jun 2 09:11:30 goofy NetworkManager[3270]: <info> Policy set 'DHCP' (eth0) as default for IPv4 routing and DNS.
Jun 2 09:11:30 goofy NetworkManager[3270]: <info> Activation (eth0) successful, device activated.
Jun 2 09:11:30 goofy NetworkManager[3270]: <info> Activation (eth0) Stage 5 of 5 (IPv4 Commit) complete.
Jun 2 09:11:30 goofy dbus[3196]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jun 2 09:11:31 goofy dbus[3196]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jun 2 09:11:31 goofy avahi-daemon[3646]: Joining mDNS multicast group on interface eth0.IPv6 with address fe80::ba70:f4ff:fed5:9ec9.
Jun 2 09:11:31 goofy avahi-daemon[3646]: New relevant interface eth0.IPv6 for mDNS.
Jun 2 09:11:31 goofy avahi-daemon[3646]: Registering new address record for fe80::ba70:f4ff:fed5:9ec9 on eth0.*.
Jun 2 09:11:32 goofy avahi-daemon[3646]: Leaving mDNS multicast group on interface eth0.IPv6 with address fe80::ba70:f4ff:fed5:9ec9.
Jun 2 09:11:32 goofy avahi-daemon[3646]: Joining mDNS multicast group on interface eth0.IPv6 with address 240f:f:1302:1:ba70:f4ff:fed5:9ec9.
Jun 2 09:11:32 goofy avahi-daemon[3646]: Registering new address record for 240f:f:1302:1:ba70:f4ff:fed5:9ec9 on eth0.*.
Jun 2 09:11:32 goofy avahi-daemon[3646]: Withdrawing address record for fe80::ba70:f4ff:fed5:9ec9 on eth0.
Jun 2 09:11:34 goofy ntpd[3639]: Listen normally on 4 eth0 192.168.0.5 UDP 123
Jun 2 09:11:34 goofy ntpd[3639]: Listen normally on 5 eth0 240f:f:1302:1:ba70:f4ff:fed5:9ec9 UDP 123
Jun 2 09:11:34 goofy ntpd[3639]: Listen normally on 6 eth0 fe80::ba70:f4ff:fed5:9ec9 UDP 123
Jun 2 09:11:34 goofy ntpd[3639]: peers refreshed
Jun 2 09:11:36 goofy ntpd_intres[3713]: DNS 0.debian.pool.ntp.org -> 103.6.16.254
Jun 2 09:11:37 goofy ntpd_intres[3713]: DNS 1.debian.pool.ntp.org -> 182.48.61.190
Jun 2 09:11:37 goofy ntpd_intres[3713]: DNS 2.debian.pool.ntp.org -> 2403:1b00::2
Jun 2 09:11:37 goofy ntpd_intres[3713]: DNS 3.debian.pool.ntp.org -> 180.235.254.234
... (this has been sysv init starting process. Desktop is active after
this is)