GNOME.org
 

Re: NetworkManager not reliably starting ethernet interface directly wired between two computers

The kernel version info from   cat /proc/version
Linux version 2.6.38.8-32.fc15.x86_64  (mockbuild x86-13 phx2 fedoraproject org) (gcc version 4.6.0 20110530 (Red Hat 4.6.0-9) (GCC) ) #1 SMP Mon Jun 13 19:49:05 UTC 2011


It just happened again.  Here are parts of the messages:

Jul  1 15:36:24 owl10 kernel: [    3.893089] NetworkManager[590]: <info> VPN: loaded org.freedesktop.NetworkManager.openvpn
Jul  1 15:36:24 owl10 kernel: [    3.893097] NetworkManager[590]: <info> VPN: loaded org.freedesktop.NetworkManager.vpnc
Jul  1 15:36:24 owl10 kernel: [    3.893103] NetworkManager[590]: <info> VPN: loaded org.freedesktop.NetworkManager.pptp
Jul  1 15:36:24 owl10 kernel: [    3.893110] NetworkManager[590]: <info> VPN: loaded org.freedesktop.NetworkManager.openconnect
Jul  1 15:36:24 owl10 kernel: [    3.929057] r8169 0000:05:00.0: p6p1: link down
Jul  1 15:36:24 owl10 kernel: [    3.929083] r8169 0000:05:00.0: p6p1: link down
Jul  1 15:36:24 owl10 kernel: [    3.929469] ADDRCONF(NETDEV_UP): p6p1: link is not ready
Jul  1 15:36:24 owl10 kernel: [    3.932967] r8169 0000:06:00.0: p7p1: link down
Jul  1 15:36:24 owl10 kernel: [    3.932974] r8169 0000:06:00.0: p7p1: link down
Jul  1 15:36:24 owl10 NetworkManager[590]: <info> (p7p1): preparing device.
Jul  1 15:36:24 owl10 NetworkManager[590]: <info> (p7p1): deactivating device (reason: 2).
Jul  1 15:36:24 owl10 kernel: [    3.933421] ADDRCONF(NETDEV_UP): p7p1: link is not ready
Jul  1 15:36:24 owl10 NetworkManager[590]: <warn> bluez error getting default adapter: Unit dbus-org.bluez.service failed to load: No such file or directory. See system logs and 'systemctl status' for details.
Jul  1 15:36:24 owl10 kernel: [    4.149816] RPC: Registered udp transport module.
Jul  1 15:36:24 owl10 kernel: [    4.149818] RPC: Registered tcp transport module.
Jul  1 15:36:24 owl10 kernel: [    4.149819] RPC: Registered tcp NFSv4.1 backchannel transport module.
Jul  1 15:36:26 owl10 kernel: [    5.521884] r8169 0000:05:00.0: p6p1: link up
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> (p6p1): carrier now ON (device state 20)
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> (p6p1): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Jul  1 15:36:26 owl10 kernel: [    5.522409] ADDRCONF(NETDEV_CHANGE): p6p1: link becomes ready
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Auto-activating connection 'Middle Port'.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) starting connection 'Middle Port'
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> (p6p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 1 of 5 (Device Prepare) scheduled...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 1 of 5 (Device Prepare) started...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) scheduled...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 1 of 5 (Device Prepare) complete.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) starting...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> (p6p1): device state change: prepare -> config (reason 'none') [40 50 0]
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) successful.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 3 of 5 (IP Configure Start) scheduled.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) complete.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 3 of 5 (IP Configure Start) started...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> (p6p1): device state change: config -> ip-config (reason 'none') [50 70 0]
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 4 of 5 (IP4 Configure Get) scheduled...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 3 of 5 (IP Configure Start) complete.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 4 of 5 (IP4 Configure Get) started...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 5 of 5 (IP Configure Commit) scheduled...
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 4 of 5 (IP4 Configure Get) complete.
Jul  1 15:36:26 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 5 of 5 (IP Configure Commit) started...
Jul  1 15:36:26 owl10 avahi-daemon[602]: Joining mDNS multicast group on interface p6p1.IPv4 with address 192.168.3.10.
Jul  1 15:36:26 owl10 avahi-daemon[602]: New relevant interface p6p1.IPv4 for mDNS.
Jul  1 15:36:26 owl10 avahi-daemon[602]: Registering new address record for 192.168.3.10 on p6p1.IPv4.
Jul  1 15:36:26 owl10 kernel: [    5.571056] fuse init (API version 7.16)
Jul  1 15:36:26 owl10 kernel: [    5.578142] r8169 0000:06:00.0: p7p1: link up
Jul  1 15:36:26 owl10 kernel: [    5.578545] ADDRCONF(NETDEV_CHANGE): p7p1: link becomes ready
Jul  1 15:36:26 owl10 kernel: [    5.624665] r8169 0000:05:00.0: p6p1: link down
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p6p1): device state change: ip-config -> activated (reason 'none') [70 100 0]
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p6p1) successful, device activated.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 5 of 5 (IP Configure Commit) complete.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p7p1): carrier now ON (device state 20)
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p7p1): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p6p1): carrier now OFF (device state 100, deferring action for 4 seconds)
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Auto-activating connection 'Side Port'.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) starting connection 'Side Port'
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p7p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 1 of 5 (Device Prepare) scheduled...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 1 of 5 (Device Prepare) started...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) scheduled...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 1 of 5 (Device Prepare) complete.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) starting...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p7p1): device state change: prepare -> config (reason 'none') [40 50 0]
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) successful.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 3 of 5 (IP Configure Start) scheduled.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) complete.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 3 of 5 (IP Configure Start) started...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> (p7p1): device state change: config -> ip-config (reason 'none') [50 70 0]
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 4 of 5 (IP4 Configure Get) scheduled...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 3 of 5 (IP Configure Start) complete.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 4 of 5 (IP4 Configure Get) started...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 5 of 5 (IP Configure Commit) scheduled...
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 4 of 5 (IP4 Configure Get) complete.
Jul  1 15:36:27 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 5 of 5 (IP Configure Commit) started...
Jul  1 15:36:28 owl10 NetworkManager[590]: <info> (p7p1): device state change: ip-config -> activated (reason 'none') [70 100 0]
Jul  1 15:36:28 owl10 NetworkManager[590]: <info> Policy set 'Side Port' (p7p1) as default for IPv4 routing and DNS.
Jul  1 15:36:28 owl10 NetworkManager[590]: <info> Activation (p7p1) successful, device activated.
Jul  1 15:36:28 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 5 of 5 (IP Configure Commit) complete.
Jul  1 15:36:29 owl10 systemd[1]: Startup finished in 1s 257ms 977us (kernel) + 1s 272ms 221us (initrd) + 6s 732ms 838us (userspace) = 9s 263ms 36us.
Jul  1 15:36:31 owl10 ntpd_intres[601]: DNS 0.fedora.pool.ntp.org -> 64.6.144.6
Jul  1 15:36:31 owl10 ntpd_intres[601]: DNS 1.fedora.pool.ntp.org -> 74.118.152.85
Jul  1 15:36:31 owl10 NetworkManager[590]: <info> (p6p1): device state change: activated -> unavailable (reason 'carrier-changed') [100 20 40]
Jul  1 15:36:31 owl10 NetworkManager[590]: <info> (p6p1): deactivating device (reason: 40).
Jul  1 15:36:31 owl10 avahi-daemon[602]: Withdrawing address record for 192.168.3.10 on p6p1.
Jul  1 15:36:31 owl10 avahi-daemon[602]: Leaving mDNS multicast group on interface p6p1.IPv4 with address 192.168.3.10.
Jul  1 15:36:31 owl10 avahi-daemon[602]: Interface p6p1.IPv4 no longer relevant for mDNS.
Jul  1 15:36:31 owl10 NetworkManager[590]: <info> Policy set 'Side Port' (p7p1) as default for IPv4 routing and DNS.
Jul  1 15:36:31 owl10 NetworkManager[590]: <info> Policy set 'Side Port' (p7p1) as default for IPv4 routing and DNS.


running ifconfig gives:
[root@owl10 log]# ifconfig
lo        Link encap:Local Loopback 
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:16436  Metric:1
          RX packets:94 errors:0 dropped:0 overruns:0 frame:0
          TX packets:94 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:7576 (7.3 KiB)  TX bytes:7576 (7.3 KiB)

p6p1      Link encap:Ethernet  HWaddr 00:60:E0:4D:64:F1 
          inet6 addr: fe80::260:e0ff:fe4d:64f1/64 Scope:Link
          UP BROADCAST MULTICAST  MTU:1500  Metric:1
          RX packets:1876 errors:0 dropped:0 overruns:0 frame:0
          TX packets:8 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:540830 (528.1 KiB)  TX bytes:1819 (1.7 KiB)
          Interrupt:47 Base address:0xc000

p7p1      Link encap:Ethernet  HWaddr 00:60:E0:4D:64:F2 
          inet addr:10.1.10.10  Bcast:10.1.255.255  Mask:255.255.0.0
          inet6 addr: fe80::260:e0ff:fe4d:64f2/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:3343 errors:0 dropped:0 overruns:0 frame:0
          TX packets:4499 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:2131028 (2.0 MiB)  TX bytes:2927659 (2.7 MiB)
          Interrupt:48 Base address:0x6000

Note that p6p1 does not have an address, even though the config file is:
[root@owl10 log]# cat /etc/sysconfig/network-scripts/ifcfg-p6p1
DEVICE="p6p1"
_ONBOOT_="yes"
NM_CONTROLLED="yes"
BOOTPROTO=none
HWADDR=00:60:E0:4D:64:F1
TYPE=Ethernet
IPADDR0=192.168.3.10
PREFIX0=24
GATEWAY0=192.168.3.9
DEFROUTE=no
IPV4_FAILURE_FATAL=yes
IPV6INIT=no
NAME="Middle Port"
UUID=131a1c02-1aee-2884-a8f2-05cc5cd849d9
[root@owl10 log]#

I tried using ifconfig p6p1 up, but nothing changed.  However, if I do down then up it does work:

[root@owl10 log]# ifconfig p6p1 down
[root@owl10 log]# ifconfig p6p1 up
[root@owl10 log]# ifconfig
lo        Link encap:Local Loopback 
          inet addr:127.0.0.1  Mask:255.0.0.0
          inet6 addr: ::1/128 Scope:Host
          UP LOOPBACK RUNNING  MTU:16436  Metric:1
          RX packets:94 errors:0 dropped:0 overruns:0 frame:0
          TX packets:94 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:0
          RX bytes:7576 (7.3 KiB)  TX bytes:7576 (7.3 KiB)

p6p1      Link encap:Ethernet  HWaddr 00:60:E0:4D:64:F1 
          inet addr:192.168.3.10  Bcast:192.168.3.255  Mask:255.255.255.0
          inet6 addr: fe80::260:e0ff:fe4d:64f1/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:1876 errors:0 dropped:0 overruns:0 frame:0
          TX packets:16 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:540830 (528.1 KiB)  TX bytes:3638 (3.5 KiB)
          Interrupt:47 Base address:0xc000

p7p1      Link encap:Ethernet  HWaddr 00:60:E0:4D:64:F2 
          inet addr:10.1.10.10  Bcast:10.1.255.255  Mask:255.255.0.0
          inet6 addr: fe80::260:e0ff:fe4d:64f2/64 Scope:Link
          UP BROADCAST RUNNING MULTICAST  MTU:1500  Metric:1
          RX packets:4075 errors:0 dropped:0 overruns:0 frame:0
          TX packets:4817 errors:0 dropped:0 overruns:0 carrier:0
          collisions:0 txqueuelen:1000
          RX bytes:2191109 (2.0 MiB)  TX bytes:2984033 (2.8 MiB)
          Interrupt:48 Base address:0x6000

The new messages in /var/log/messages are below (this also includes the first ifconfig p6p1 up, I just diffed the files)

23162a23163,23242
> Jul  1 15:40:03 owl10 NetworkManager[590]: <warn> connection /org/freedesktop/NetworkManager/Settings/0 failed to activate: (2) Device not managed by NetworkManager or unavailable
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> (p7p1): disconnecting for new activation request.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> (p7p1): device state change: activated -> disconnected (reason 'none') [100 30 0]
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> (p7p1): deactivating device (reason: 0).
> Jul  1 15:40:03 owl10 avahi-daemon[602]: Withdrawing address record for 10.1.10.10 on p7p1.
> Jul  1 15:40:03 owl10 avahi-daemon[602]: Leaving mDNS multicast group on interface p7p1.IPv4 with address 10.1.10.10.
> Jul  1 15:40:03 owl10 avahi-daemon[602]: Interface p7p1.IPv4 no longer relevant for mDNS.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) starting connection 'Side Port'
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> (p7p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 1 of 5 (Device Prepare) scheduled...
> Jul  1 15:40:03 owl10 dbus-daemon: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 1 of 5 (Device Prepare) started...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) scheduled...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 1 of 5 (Device Prepare) complete.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) starting...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> (p7p1): device state change: prepare -> config (reason 'none') [40 50 0]
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) successful.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 3 of 5 (IP Configure Start) scheduled.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 2 of 5 (Device Configure) complete.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 3 of 5 (IP Configure Start) started...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> (p7p1): device state change: config -> ip-config (reason 'none') [50 70 0]
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 4 of 5 (IP4 Configure Get) scheduled...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 3 of 5 (IP Configure Start) complete.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 4 of 5 (IP4 Configure Get) started...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 5 of 5 (IP Configure Commit) scheduled...
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 4 of 5 (IP4 Configure Get) complete.
> Jul  1 15:40:03 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 5 of 5 (IP Configure Commit) started...
> Jul  1 15:40:03 owl10 avahi-daemon[602]: Joining mDNS multicast group on interface p7p1.IPv4 with address 10.1.10.10.
> Jul  1 15:40:03 owl10 avahi-daemon[602]: New relevant interface p7p1.IPv4 for mDNS.
> Jul  1 15:40:03 owl10 avahi-daemon[602]: Registering new address record for 10.1.10.10 on p7p1.IPv4.
> Jul  1 15:40:03 owl10 dbus-daemon: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
> Jul  1 15:40:04 owl10 NetworkManager[590]: <info> (p7p1): device state change: ip-config -> activated (reason 'none') [70 100 0]
> Jul  1 15:40:04 owl10 NetworkManager[590]: <info> Policy set 'Side Port' (p7p1) as default for IPv4 routing and DNS.
> Jul  1 15:40:04 owl10 NetworkManager[590]: <info> Activation (p7p1) successful, device activated.
> Jul  1 15:40:04 owl10 NetworkManager[590]: <info> Activation (p7p1) Stage 5 of 5 (IP Configure Commit) complete.
> Jul  1 15:40:04 owl10 systemd[1]: network.service: control process exited, code=exited status=1
> Jul  1 15:40:04 owl10 systemd[1]: Unit network.service entered failed state.
> Jul  1 15:40:36 owl10 avahi-daemon[602]: Withdrawing address record for fe80::260:e0ff:fe4d:64f1 on p6p1.
> Jul  1 15:40:38 owl10 ntpd[595]: Deleting interface #6 p6p1, fe80::260:e0ff:fe4d:64f1#123, interface stats: received=0, sent=0, dropped=0, active_time=250 secs
> Jul  1 15:40:38 owl10 ntpd[595]: peers refreshed
> Jul  1 15:40:39 owl10 kernel: [  259.962505] r8169 0000:05:00.0: p6p1: link down
> Jul  1 15:40:39 owl10 kernel: [  259.962514] r8169 0000:05:00.0: p6p1: link down
> Jul  1 15:40:39 owl10 kernel: [  259.963130] ADDRCONF(NETDEV_UP): p6p1: link is not ready
> Jul  1 15:40:41 owl10 kernel: [  262.014722] r8169 0000:05:00.0: p6p1: link up
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> (p6p1): carrier now ON (device state 20)
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> (p6p1): device state change: unavailable -> disconnected (reason 'carrier-changed') [20 30 40]
> Jul  1 15:40:41 owl10 kernel: [  262.015215] ADDRCONF(NETDEV_CHANGE): p6p1: link becomes ready
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Auto-activating connection 'Middle Port'.
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) starting connection 'Middle Port'
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> (p6p1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 1 of 5 (Device Prepare) scheduled...
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 1 of 5 (Device Prepare) started...
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) scheduled...
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 1 of 5 (Device Prepare) complete.
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) starting...
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> (p6p1): device state change: prepare -> config (reason 'none') [40 50 0]
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) successful.
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 3 of 5 (IP Configure Start) scheduled.
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 2 of 5 (Device Configure) complete.
> Jul  1 15:40:41 owl10 NetworkManager[590]: <info> Activation (p6p1) Stage 3 of 5 (IP Configure Start) started...












On Thu, 2011-06-30 at 11:40 -0500,
Dan Williams wrote: 
On Wed, 2011-06-22 at 14:38 -0400, Douglas C. MacKenzie wrote:
> I have two computers that have a direct ethernet wire between them. The
> interface is set to a static ip address on each side, and under control
> of the NetworkManager.  The computers are on the same power supply and
> power up at the same time.

What kernel version?  There was a driver bug with 8169 initial carrier
in some older kernels that I think got fixed in 2.6.38 and maybe the
patch needs to be backported.

One thing to check is that when things don't work, try:

cat /sys/class/net/eth0/carrier

if that's "1" the kernel driver thinks you  have a carrier, if it's "0"
then it doesn't, and if the kernel doesn't think so, neither will NM.

Dan

> About 1/10 the time, the interface does not start. The messages log file
> will show:
> 
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): carrier is OFF
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): new Ethernet
> device (driver: 'r8169' ifindex: 2)
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): exported
> as /org/freedesktop/NetworkManager/Devices/0
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): now managed
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): device state
> change: unmanaged -> unavailable (reason 'managed') [10 20 2]
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): bringing up
> device.
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): preparing
> device.
> Jun 22 13:01:22 owl10 NetworkManager[601]: <info> (p6p1): deactivating
> device (reason: 2).
> Jun 22 13:01:22 owl10 kernel: [ 4.932240] r8169 0000:05:00.0: p6p1: link
> down
> Jun 22 13:01:22 owl10 kernel: [ 4.932248] r8169 0000:05:00.0: p6p1: link
> down
> Jun 22 13:01:22 owl10 kernel: [ 4.932634] ADDRCONF(NETDEV_UP): p6p1:
> link is not ready
> 
> 
> And, if I just physically unplug the cable and plug it back in
> NetworkManager starts the interface:
> 
> Jun 22 13:08:40 owl10 kernel: [ 442.658355] r8169 0000:05:00.0: p6p1:
> link up
> Jun 22 13:08:40 owl10 kernel: [ 442.658875] ADDRCONF(NETDEV_CHANGE):
> p6p1: link becomes ready
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> (p6p1): carrier now ON
> (device state 20)
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> (p6p1): device state
> change: unavailable -> disconnected (reason 'carrier-changed') [20 30
> 40]
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> starting connection 'Middle Port'
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> (p6p1): device state
> change: disconnected -> prepare (reason 'none') [30 40 0]
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 1 of 5 (Device Prepare) scheduled...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 1 of 5 (Device Prepare) started...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 2 of 5 (Device Configure) scheduled...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 1 of 5 (Device Prepare) complete.
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 2 of 5 (Device Configure) starting...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> (p6p1): device state
> change: prepare -> config (reason 'none') [40 50 0]
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 2 of 5 (Device Configure) successful.
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 3 of 5 (IP Configure Start) scheduled.
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 2 of 5 (Device Configure) complete.
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 3 of 5 (IP Configure Start) started...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> (p6p1): device state
> change: config -> ip-config (reason 'none') [50 70 0]
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 4 of 5 (IP4 Configure Get) scheduled...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 3 of 5 (IP Configure Start) complete.
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 4 of 5 (IP4 Configure Get) started...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 5 of 5 (IP Configure Commit) scheduled...
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 4 of 5 (IP4 Configure Get) complete.
> Jun 22 13:08:40 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 5 of 5 (IP Configure Commit) started...
> Jun 22 13:08:40 owl10 avahi-daemon[614]: Joining mDNS multicast group on
> interface p6p1.IPv4 with address 192.168.3.10.
> Jun 22 13:08:40 owl10 avahi-daemon[614]: New relevant interface
> p6p1.IPv4 for mDNS.
> Jun 22 13:08:40 owl10 avahi-daemon[614]: Registering new address record
> for 192.168.3.10 on p6p1.IPv4.
> Jun 22 13:08:41 owl10 NetworkManager[601]: <info> Policy set 'Side
> Port' (p7p1) as default for IPv4 routing and DNS.
> Jun 22 13:08:41 owl10 NetworkManager[601]: <info> (p6p1): device state
> change: ip-config -> activated (reason 'none') [70 100 0]
> Jun 22 13:08:41 owl10 NetworkManager[601]: <info> Activation (p6p1)
> successful, device activated.
> Jun 22 13:08:41 owl10 NetworkManager[601]: <info> Activation (p6p1)
> Stage 5 of 5 (IP Configure Commit) complete.
> 
> 
> So, I imagine there is a race condition where both boxes wait for the
> other to start the interface and provide a carrier.  Is that likely the
> problem?
> 
> If so, is there a way to force NetworkManager to bring up an interface
> even if there is no Carrier?  Or, is it a kernel issue.
> 
> BTW, this problem started recently on Fedora 13 after some upgrades. We
> upgraded to the latest Fedora 15 to try and solve it, and it now appears
> more often than it did on Fedora 13.  It is happening on two different
> pairs of computers, with different cables, so I doubt it is a hardware
> problem.
> 
> Doug
> 
> 
> _______________________________________________
> networkmanager-list mailing list
> networkmanager-list gnome org
> http://mail.gnome.org/mailman/listinfo/networkmanager-list




-- 
Douglas C. MacKenzie, Ph.D.
Mobile Intelligence Corporation
13620 Merriman Road
Livonia, MI  48150-1814
   Voice: +1 734 367-0430 Ext. 10
   Cell:  +1 734 716-5256
mailto:dmackenzie mobile-intelligence com
[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]