#8343 HIGH 8.2.1: Wired ethernet not always connecting on startup

Tue Sep 23 15:19:31 EDT 2008

#8343: Wired ethernet not always connecting on startup
-------------------------------+--------------------------------------------
   Reporter:  mikus            |       Owner:  dcbw                             
       Type:  defect           |      Status:  new                              
   Priority:  high             |   Milestone:  8.2.1                            
  Component:  network manager  |     Version:  Development build as of this date
 Resolution:                   |    Keywords:  relnote                          
Next_action:  diagnose         |    Verified:  0                                
  Blockedby:                   |    Blocking:                                   
-------------------------------+--------------------------------------------
Changes (by pgf):

  * owner:  => dcbw
  * priority:  normal => high
  * component:  not assigned => network manager

Comment:

 in both nonetconn.tar.bz2 and
 logs.CSN74801834.2008-09-06.22-56-46.tar.bz2, /var/log/messages indicates
 that NetworkManager is ignoring the fact that dhclient has successfully
 obtained a lease.  here's an excerpt from nonetconn.tjz:

 (note dhclient's joy at 07:15:22, and NM's apparent disgust at 07:16:03)

 {{{
 Sep 23 07:15:18 localhost NetworkManager: <info>  Will activate connection
 'eth1
 '.
 Sep 23 07:15:18 localhost NetworkManager: <info>  Device eth1 activation
 schedul
 ed...
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1)
 started...
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 1 of 5
  (Device Prepare) scheduled...
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 1 of 5
  (Device Prepare) started...
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 2 of 5
  (Device Configure) scheduled...
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 1 of 5
  (Device Prepare) complete.
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 2 of 5
  (Device Configure) starting...
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 2 of 5
  (Device Configure) successful.
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 3 of 5
  (IP Configure Start) scheduled.
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 2 of 5
  (Device Configure) complete.
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 3 of 5
  (IP Configure Start) started...
 Sep 23 07:15:18 localhost NetworkManager: <info>
 nm_dhcp_manager_cancel_transac
 tion_real(): enter, pid 0
 Sep 23 07:15:18 localhost NetworkManager: <info>
 nm_dhcp_manager_cancel_transac
 tion_real(): returning, zero pid 0
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1)
 Beginning DH
 CP transaction.
 Sep 23 07:15:18 localhost NetworkManager: <info>  eth1:
 nm_dhcp_manager_begin_tr
 ansaction():661 started timeout source 0x82f33b8
 Sep 23 07:15:18 localhost NetworkManager: <info>  dhclient started with
 pid 1393
 Sep 23 07:15:18 localhost NetworkManager: <info>  Activation (eth1) Stage
 3 of 5
  (IP Configure Start) complete.
 Sep 23 07:15:18 localhost dhclient: Internet Systems Consortium DHCP
 Client 4.0.
 0
 Sep 23 07:15:18 localhost dhclient: Copyright 2004-2007 Internet Systems
 Consort
 ium.
 Sep 23 07:15:18 localhost dhclient: All rights reserved.
 Sep 23 07:15:18 localhost dhclient: For info, please visit
 http://www.isc.org/sw
 /dhcp/
 Sep 23 07:15:18 localhost dhclient:
 Sep 23 07:15:18 localhost NetworkManager: <info>  DHCP: device eth1 state
 changed (null) -> preinit
 Sep 23 07:15:18 localhost dhclient: Listening on
 LPF/eth1/00:10:60:16:9d:f6
 Sep 23 07:15:18 localhost dhclient: Sending on
 LPF/eth1/00:10:60:16:9d:f6
 Sep 23 07:15:18 localhost dhclient: Sending on   Socket/fallback
 Sep 23 07:15:19 localhost kernel: [   44.705408] ADDRCONF(NETDEV_CHANGE):
 msh0: link becomes ready
 Sep 23 07:15:20 localhost avahi-daemon[1376]: Registering new address
 record for fe80::217:c4ff:fe10:dc04 on msh0.*.
 Sep 23 07:15:21 localhost kernel: [   46.531372] olpc-dcon: The DCON has
 control
 Sep 23 07:15:22 localhost dhclient: DHCPDISCOVER on eth1 to
 255.255.255.255 port 67 interval 7
 Sep 23 07:15:22 localhost dhclient: DHCPOFFER from 192.168.1.1
 Sep 23 07:15:22 localhost dhclient: DHCPREQUEST on eth1 to 255.255.255.255
 port 67
 Sep 23 07:15:22 localhost dhclient: DHCPACK from 192.168.1.1
 Sep 23 07:15:22 localhost dhclient: bound to 192.168.1.9 -- renewal in
 87504 seconds.
 Sep 23 07:15:22 localhost NetworkManager: <info>  initial wireless
 suppression timeout up
 Sep 23 07:15:27 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:15:40 localhost NetworkManager: <info>  Updating allowed
 wireless network lists.
 Sep 23 07:15:49 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:15:49 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:15:49 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:15:49 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:15:49 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:15:51 localhost kernel: [   76.347874] olpc-dcon: The CPU has
 control
 Sep 23 07:15:58 localhost NetworkManager: <info>  Old device 'eth1'
 activating, won't change.
 Sep 23 07:16:03 localhost NetworkManager: <info>  Device 'eth1' DHCP
 transaction took too long (>45s), stopping it.
 Sep 23 07:16:03 localhost NetworkManager: <info>
 nm_dhcp_manager_cancel_transaction_real(): enter, pid 1393
 Sep 23 07:16:03 localhost NetworkManager: <info>
 nm_dhcp_manager_cancel_transaction_real(): kill -TERM-ing pid 1393

 }}}

-- 
Ticket URL: <http://dev.laptop.org/ticket/8343#comment:9>
One Laptop Per Child <http://laptop.org/>
OLPC bug tracking system