NM 1.0.6, Bridge takes 30 seconds to initialize

["Nathanael D. Noblet" <nathanael gnat ca>]

Hello,


  I've been using NM to have a bridge setup. It works, however it takes
a *long* time (to me anyway) to come up. Around 30 seconds it seems.
The problem with this is that for example I have libvirt VMs that I
used to have set to come up on boot that shared that bridge. However
because of the length of time for the bridge to come up networking
would get seriously messed up. 

  Since then I've told the VMs not to come up on boot, and the system
comes online. 30 seconds and the bridge is up and then I can bring up
the VMs. Any reason it takes so long? I've pasted in the email and on
fpaste.org the NM logs.

http://www.fpaste.org/281121/52776931/


Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  NetworkManager (version 1.0.6-6.fc23) is starting...
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Read
config: /etc/NetworkManager/NetworkManager.conf and conf.d: 10-ibft-
plugin.conf, 20-connectivity
-fedora.conf
Oct 16 08:50:12 iridium.noblet.ca audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=NetworkManager comm="
systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=? terminal=?
res=success'
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  VPN:
loaded org.freedesktop.NetworkManager.vpnc
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  VPN:
loaded org.freedesktop.NetworkManager.openvpn
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  VPN:
loaded org.freedesktop.NetworkManager.pptp
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  VPN:
loaded org.freedesktop.NetworkManager.l2tp
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  VPN:
loaded org.freedesktop.NetworkManager.openconnect
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
settings plugin ifcfg-rh: (c) 2007 - 2015 Red Hat, Inc.  To report bugs
please use the Network
Manager mailing list. (/usr/lib64/NetworkManager/libnm-settings-plugin-
ifcfg-rh.so)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
settings plugin iBFT: (c) 2014 Red Hat, Inc.  To report bugs please use
the NetworkManager mai
ling list. (/usr/lib64/NetworkManager/libnm-settings-plugin-ibft.so)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
settings plugin keyfile: (c) 2007 - 2015 Red Hat, Inc.  To report bugs
please use the NetworkM
anager mailing list.
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  ifcfg-
rh: new connection /etc/sysconfig/network-scripts/ifcfg-em1 (12721930-
c418-4f00-9476-5e08d2150f
af,"em1")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  ifcfg-
rh: new connection /etc/sysconfig/network-scripts/ifcfg-
Wired_connection_1 (eda9a055-e0da-45f4-
9cf1-6fa0176f324b,"Wired connection 1")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  ifcfg-
rh: new connection /etc/sysconfig/network-scripts/ifcfg-
Bridge_connection_1 (62a5d08c-1e57-4f03
-8ee3-f9998b6c5714,"Bridge connection 1")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  ifcfg-
rh: new connection /etc/sysconfig/network-scripts/ifcfg-bridge0_slave_1 
(e7c1b9ef-9944-4eaa-a61
7-6023946819e3,"bridge0 slave 1")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  ifcfg-
rh: new connection /etc/sysconfig/network-scripts/ifcfg-virbr0
(1a3620a0-0be7-41e5-9a0d-df5bdb6
a831d,"virbr0")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  keyfile: new connection /etc/NetworkManager/system-
connections/vnet0-ddfee215-c626-4336-9f10-b2f2bb0e
11d0 (ddfee215-c626-4336-9f10-b2f2bb0e11d0,"vnet0")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  keyfile: new connection /etc/NetworkManager/system-
connections/vnet0 (4c21783b-01b1-4ea9-b29e-2a8ad73
afe8b,"vnet0")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  keyfile: new connection /etc/NetworkManager/system-
connections/virbr0-nic (746f5e18-b115-4ae1-acef-d3
6fc6578494,"virbr0-nic")
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  monitoring kernel firmware directory '/lib/firmware'.
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  WiFi
hardware radio set enabled
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  WWAN
hardware radio set enabled
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMVxlanFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMVlanFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMVethFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMTunFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMMacvlanFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMInfinibandFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMGreFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMEthernetFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMBridgeFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMBondFactory (internal)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMWifiFactory (/usr/lib64/NetworkManager/libnm-device-
plugin-wifi.so)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMAtmManager (/usr/lib64/NetworkManager/libnm-device-
plugin-adsl.so)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMBluezManager (/usr/lib64/NetworkManager/libnm-device-
plugin-bluetooth.so)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Loaded
device plugin: NMWwanFactory (/usr/lib64/NetworkManager/libnm-device-
plugin-wwan.so)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  WiFi
enabled by radio killswitch; enabled by state file
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  WWAN
enabled by radio killswitch; enabled by state file
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  WiMAX
enabled by radio killswitch; enabled by state file
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  Networking is enabled by state file
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
new Ethernet device (carrier: OFF, driver: 'e1000e', ifindex: 2)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: unmanaged -> unavailable (reason 'managed') [10 20
2]
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): new Bridge device (carrier: OFF, driver: 'bridge',
ifindex: 3)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: unmanaged -> unavailable
(reason 'managed') [10 20 2]
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  (lo):
link connected
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  (lo):
new Generic device (carrier: ON, driver: 'unknown', ifindex: 1)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: unavailable -> disconnected
(reason 'none') [20 30 0]
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  Auto-
activating connection 'Bridge connection 1'.
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): Activation: starting connection 'Bridge connection
1' (62a5d08c-1e57-4f03-8ee3-f9998b6c571
4)
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: disconnected -> prepare (reason
'none') [30 40 0]
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  NetworkManager state is now CONNECTING
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: prepare -> config (reason
'none') [40 50 0]
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]: <info>  use
BlueZ version 5
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  ModemManager available in the bus
Oct 16 08:50:12 iridium.noblet.ca NetworkManager[1192]:
<info>  wpa_supplicant running
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: config -> ip-config (reason
'none') [50 70 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): IPv4 config waiting until carrier is on
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): IPv6 config waiting until carrier is on
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): new Bridge device (carrier: OFF, driver: 'bridge',
ifindex: 4)
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): new Tun device (carrier: OFF, driver: 'tun',
ifindex: 5)
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): bridge port virbr0-nic was attached
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): enslaved to virbr0
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): link connected
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: unmanaged -> unavailable (reason
'connection-assumed') [10 20 41]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]: <info>  ifcfg-
rh: add connection in-memory (4422bcd5-a32b-463f-8859-
c99a3d845d33,"virbr0")
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: unavailable -> disconnected
(reason 'connection-assumed') [20 30 41]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): Activation: starting connection 'virbr0' (4422bcd5-
a32b-463f-8859-c99a3d845d33)
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: disconnected -> prepare (reason
'none') [30 40 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: prepare -> config (reason
'none') [40 50 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): found matching connection 'virbr0-nic'
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: unmanaged -> unavailable
(reason 'connection-assumed') [10 20 41]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: unavailable -> disconnected
(reason 'connection-assumed') [20 30 4
1]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): Activation: starting connection 'virbr0-nic'
(746f5e18-b115-4ae1-acef-d36fc6578494)
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: config -> ip-config (reason
'none') [50 70 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: disconnected -> prepare
(reason 'none') [30 40 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: ip-config -> ip-check (reason
'none') [70 80 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: prepare -> config (reason
'none') [40 50 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: config -> ip-config (reason
'none') [50 70 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: ip-config -> secondaries
(reason 'none') [70 90 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): device state change: secondaries -> activated
(reason 'none') [90 100 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): Activation: successful, device activated.
Oct 16 08:50:13 iridium.noblet.ca audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=NetworkManager-dispat
cher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=?
terminal=? res=success'
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: ip-check -> secondaries (reason
'none') [80 90 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): device state change: secondaries -> activated (reason
'none') [90 100 0]
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0): Activation: successful, device activated.
Oct 16 08:50:13 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): link disconnected (deferring action for 4
seconds)
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
link connected
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: unavailable -> disconnected (reason 'carrier-
changed') [20 30 40]
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  Auto-
activating connection 'em1'.
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
Activation: starting connection 'em1' (12721930-c418-4f00-9476-
5e08d2150faf)
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: disconnected -> prepare (reason 'none') [30 40 0]
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: prepare -> config (reason 'none') [40 50 0]
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: config -> ip-config (reason 'none') [50 70 0]
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): attached bridge port em1
Oct 16 08:50:16 iridium.noblet.ca audit[1192]: SYSCALL arch=c000003e
syscall=46 success=yes exit=40 a0=8 a1=7ffe33fe5d80 a2=0
a3=558de0635310 items=0 ppid=1 pid=1192
 auid=4294967295 uid=0 gid=0 euid=0 suid=0 fsuid=0 egid=0 sgid=0
fsgid=0 tty=(none) ses=4294967295 comm="NetworkManager"
exe="/usr/sbin/NetworkManager" subj=system_u
:system_r:NetworkManager_t:s0 key=(null)
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
Activation: connection 'em1' enslaved, continuing activation
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): IPv4 config waiting until carrier is on
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): IPv6 config waiting until carrier is on
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: ip-config -> secondaries (reason 'none') [70 90 0]
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
device state change: secondaries -> activated (reason 'none') [90 100
0]
Oct 16 08:50:16 iridium.noblet.ca NetworkManager[1192]: <info>  (em1):
Activation: successful, device activated.
Oct 16 08:50:18 iridium.noblet.ca NetworkManager[1192]:
<info>  (virbr0-nic): link disconnected (calling deferred action)
Oct 16 08:50:26 iridium.noblet.ca audit[1]: SERVICE_STOP pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=NetworkManager-dispatc
her comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=?
terminal=? res=success'
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): link connected
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  Activation (bridge0) Beginning DHCPv4 transaction (timeout in
45 seconds)
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  dhclient started with pid 3756
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>    address 192.168.4.100
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]: <info>    plen
24 (255.255.255.0)
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>    gateway 192.168.4.1
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>    server identifier 192.168.4.1
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]: <info>    lease
time -1
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>    hostname 'iridium'
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>    nameserver '192.168.4.1'
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>    domain name 'noblet.ca'
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): DHCPv4 state changed unknown -> bound
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: ip-config -> ip-check (reason
'none') [70 80 0]
Oct 16 08:50:46 iridium.noblet.ca audit[1]: SERVICE_START pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=NetworkManager-dispat
cher comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=?
terminal=? res=success'
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: ip-check -> secondaries (reason
'none') [80 90 0]
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): device state change: secondaries -> activated
(reason 'none') [90 100 0]
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  NetworkManager state is now CONNECTED_LOCAL
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  NetworkManager state is now CONNECTED_SITE
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]: <info>  Policy
set 'Bridge connection 1' (bridge0) as default for IPv4 routing and
DNS.
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  (bridge0): Activation: successful, device activated.
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]: <info>  startup
complete
Oct 16 08:50:46 iridium.noblet.ca NetworkManager[1192]:
<info>  NetworkManager state is now CONNECTED_GLOBAL
Oct 16 08:50:56 iridium.noblet.ca audit[1]: SERVICE_STOP pid=1 uid=0
auid=4294967295 ses=4294967295 subj=system_u:system_r:init_t:s0
msg='unit=NetworkManager-dispatc
her comm="systemd" exe="/usr/lib/systemd/systemd" hostname=? addr=?
terminal=? res=success'
Oct 16 09:01:01 iridium.noblet.ca NetworkManager[1192]:
<info>  connectivity: check for uri 'http://fedoraproject.org/static/ho
tspot.txt' failed with 'Error resolvin
g 'fedoraproject.org': No address associated with hostname'