Gordon Messmer writes:
On 12/18/2017 05:52 AM, Sam Varshavchik wrote:
> Time IP addresses
> ======== ==================
> 08:35:34
> 08:35:35 192.168.0.1
>
> At 08:35:34 the server had no IP addresses
Well, it probably had 127.0.0.1, which brings into question what the
complete state of the network was.
Could you arrange to execute "ip addr show | logger" in your unfrak script?
That way we get all of the interfaces and all of the addresses regardless of
family.
Could you also see if removing the "-s" flag from
/usr/lib/systemd/system/NetworkManager-wait-online.service changes the
behavior of the system?
Running just "ip addr show | logger" was not conclusive. Looks like the
overhead of doing so delays things long enough so even the first time this
actually runs all the network interfaces have their IP addresses already
assigned.
Removing the -s option from actually makes things worse. The script has to
wait noticably longer before all IP addresses are assigned:
Subject: systemd network initialization unfrak report
Time IP addresses
======== ==================
06:52:56
06:52:57
06:52:58
06:52:59 192.168.0.1
Usually it's 1 or 2 seconds. Without the -s option it's 4-5 seconds.
This seems consistent with the description of what the -s option does, from
the man page. The way I parse its man page entry is that the -s option
actually waits for more things to happen, before it's done. So removing that
option makes NetworkManager's definition of when things are online occur
much earlier.
This is confirmed by running "ip addr show | logger" without -s option. This
produces some useful results. This time, the first time "ip addr show" runs
it's early enough so that the network is not fully initialized.
syslog shows two runs of "ip addr show", showing no IP addresses configured
on one of the two network interfaces. The 2nd network interface already has
its IP addresses assigned. This is followed by some messages from
NetworkManager, then another run of "ip addr show", showing all network
interfaces with assigned IP addresses.
Both eno1 and eno2 have statically assigned IP addresses in
/etc/sysconfig/network-scripts.
Dec 19 06:57:09 shorty systemd[1]: Starting Unfrak systemd network startup...
Dec 19 06:57:09 shorty systemd[1]: iscsi.service: Unit cannot be reloaded because it is
inactive.
Dec 19 06:57:09 shorty root[1400]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc
noqueue state UNKNOWN group default qlen 1000
Dec 19 06:57:09 shorty root[1400]: link/loopback 00:00:00:00:00:00 brd
00:00:00:00:00:00
Dec 19 06:57:09 shorty root[1400]: inet 127.0.0.1/8 scope host lo
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: inet6 ::1/128 scope host
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: 2: eno1: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu
1500 qdisc fq_codel state DOWN group default qlen 1000
Dec 19 06:57:09 shorty root[1400]: link/ether 0c:c4:7a:32:c1:82 brd ff:ff:ff:ff:ff:ff
Dec 19 06:57:09 shorty root[1400]: 3: eno2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu
1500 qdisc mq state UP group default qlen 1000
Dec 19 06:57:09 shorty root[1400]: link/ether 0c:c4:7a:32:c1:83 brd ff:ff:ff:ff:ff:ff
Dec 19 06:57:09 shorty root[1400]: inet 68.166.206.83/29 brd 68.166.206.87 scope global
eno2
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: inet 68.166.206.82/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: inet 68.166.206.84/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: inet 68.166.206.85/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: inet 68.166.206.86/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:09 shorty root[1400]: inet6 fe80::ec4:7aff:fe32:c183/64 scope link
tentative
Dec 19 06:57:09 shorty root[1400]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc
noqueue state UNKNOWN group default qlen 1000
Dec 19 06:57:10 shorty root[1403]: link/loopback 00:00:00:00:00:00 brd
00:00:00:00:00:00
Dec 19 06:57:10 shorty root[1403]: inet 127.0.0.1/8 scope host lo
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: inet6 ::1/128 scope host
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: 2: eno1: <NO-CARRIER,BROADCAST,MULTICAST,UP> mtu
1500 qdisc fq_codel state DOWN group default qlen 1000
Dec 19 06:57:10 shorty root[1403]: link/ether 0c:c4:7a:32:c1:82 brd ff:ff:ff:ff:ff:ff
Dec 19 06:57:10 shorty root[1403]: 3: eno2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu
1500 qdisc mq state UP group default qlen 1000
Dec 19 06:57:10 shorty root[1403]: link/ether 0c:c4:7a:32:c1:83 brd ff:ff:ff:ff:ff:ff
Dec 19 06:57:10 shorty root[1403]: inet 68.166.206.83/29 brd 68.166.206.87 scope global
eno2
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: inet 68.166.206.82/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: inet 68.166.206.84/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: inet 68.166.206.85/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: inet 68.166.206.86/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty root[1403]: inet6 fe80::ec4:7aff:fe32:c183/64 scope link
tentative
Dec 19 06:57:10 shorty root[1403]: valid_lft forever preferred_lft forever
Dec 19 06:57:10 shorty systemd-networkd[955]: eno2: Gained IPv6LL
Dec 19 06:57:10 shorty NetworkManager[956]: <info> [1513684630.6860] manager:
startup complete
Dec 19 06:57:11 shorty kernel: e1000e: eno1 NIC Link is Up 1000 Mbps Full Duplex, Flow
Control: Rx/Tx
Dec 19 06:57:11 shorty kernel: IPv6: ADDRCONF(NETDEV_CHANGE): eno1: link becomes ready
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4385] device (eno1):
link connected
Dec 19 06:57:11 shorty systemd-networkd[955]: eno1: Gained carrier
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4390] device (eno1):
state change: unavailable -> disconnected (reason 'carrier-changed', internal
state 'managed')
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4396] policy:
auto-activating connection 'lan0'
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4405] device (eno1):
Activation: starting connection 'lan0' (d1a1ee90-f006-43bb-9cbf-175ad32f6565)
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4406] device (eno1):
state change: disconnected -> prepare (reason 'none', internal state
'managed')
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4410] device (eno1):
state change: prepare -> config (reason 'none', internal state
'managed')
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4436] device (eno1):
state change: config -> ip-config (reason 'none', internal state
'managed')
Dec 19 06:57:11 shorty named[1035]: listening on IPv4 interface eno1, 192.168.0.1#53
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4464] device (eno1):
state change: ip-config -> ip-check (reason 'none', internal state
'managed')
Dec 19 06:57:11 shorty nm-dispatcher[990]: req:5 'pre-up' [eno1]: new request (1
scripts)
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4509] device (eno1):
state change: ip-check -> secondaries (reason 'none', internal state
'managed')
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.4511] device (eno1):
state change: secondaries -> activated (reason 'none', internal state
'managed')
Dec 19 06:57:11 shorty root[1415]: 1: lo: <LOOPBACK,UP,LOWER_UP> mtu 65536 qdisc
noqueue state UNKNOWN group default qlen 1000
Dec 19 06:57:11 shorty root[1415]: link/loopback 00:00:00:00:00:00 brd
00:00:00:00:00:00
Dec 19 06:57:11 shorty root[1415]: inet 127.0.0.1/8 scope host lo
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: inet6 ::1/128 scope host
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: 2: eno1: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu
1500 qdisc fq_codel state UP group default qlen 1000
Dec 19 06:57:11 shorty root[1415]: link/ether 0c:c4:7a:32:c1:82 brd ff:ff:ff:ff:ff:ff
Dec 19 06:57:11 shorty root[1415]: inet 192.168.0.1/24 brd 192.168.0.255 scope global
eno1
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: inet6 fe80::ec4:7aff:fe32:c182/64 scope link
tentative
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: 3: eno2: <BROADCAST,MULTICAST,UP,LOWER_UP> mtu
1500 qdisc mq state UP group default qlen 1000
Dec 19 06:57:11 shorty root[1415]: link/ether 0c:c4:7a:32:c1:83 brd ff:ff:ff:ff:ff:ff
Dec 19 06:57:11 shorty root[1415]: inet 68.166.206.83/29 brd 68.166.206.87 scope global
eno2
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: inet 68.166.206.82/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty NetworkManager[956]: <info> [1513684631.5589] device (eno1):
Activation: successful, device activated.
Dec 19 06:57:11 shorty root[1415]: inet 68.166.206.84/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: inet 68.166.206.85/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: inet 68.166.206.86/29 brd 68.166.206.87 scope global
secondary eno2
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty root[1415]: inet6 fe80::ec4:7aff:fe32:c183/64 scope link
Dec 19 06:57:11 shorty root[1415]: valid_lft forever preferred_lft forever
Dec 19 06:57:11 shorty nm-dispatcher[990]: req:6 'up' [eno1]: new request (7
scripts)
Dec 19 06:57:11 shorty systemd[1]: Started Unfrak systemd network startup.
Note that "ip addr show" ran as part of the script that has a dependency on
nm-line.
After reversing all changes, putting the -s option back in, and not running
"ip addr", repeated boots shows the status quo being restored. The presence
of the -s option reduces the additional time that the script needs to wait
for all IP addresses to be assigned to 1 or 2 seconds. But it still has to
wait, since nm-online -s -q returns too early.