Bug 194124 - NM tries to get address on wired connection without link
NM tries to get address on wired connection without link
Status: CLOSED ERRATA
Product: Fedora
Classification: Fedora
Component: NetworkManager (Show other bugs)
rawhide
All Linux
medium Severity medium
: ---
: ---
Assigned To: Christopher Aillon
: Reopened
: 224086 230256 242786 244353 (view as bug list)
Depends On:
Blocks: FC7Target
  Show dependency treegraph
 
Reported: 2006-06-05 17:23 EDT by Jeremy Katz
Modified: 2007-11-30 17:11 EST (History)
11 users (show)

See Also:
Fixed In Version: 0.6.5-6.fc7
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2007-06-25 19:24:40 EDT
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)
Syslog (with extra debug code) (25.42 KB, text/plain)
2007-06-12 09:51 EDT, Onno Witvliet
no flags Details
/var/log/messages (95.46 KB, application/octet-stream)
2007-06-18 13:10 EDT, drago01
no flags Details
better one (27.40 KB, text/plain)
2007-06-18 13:24 EDT, drago01
no flags Details
my /var/log/messages cutting (12.28 KB, text/plain)
2007-06-24 06:15 EDT, Martin Jürgens
no flags Details


External Trackers
Tracker ID Priority Status Summary Last Updated
GNOME Desktop 354565 None None None Never

  None (edit)
Description Jeremy Katz 2006-06-05 17:23:48 EDT
On first login after reboot, NetworkManager is wanting to get a connection on
the wired connection which doesn't have a link established (nm-tool even says
Hardware link: no)

Obviously, this doesn't really work :)
Comment 1 Ray Strode [halfline] 2006-07-24 13:27:41 EDT
Are you still seeing this?
Comment 2 Jeremy Katz 2006-07-24 13:34:13 EDT
Yep
Comment 3 Ray Strode [halfline] 2006-07-27 10:51:55 EDT
So I'm having difficulty reproducing this.

The symptoms are that you log in and see the nm-applet spinning dots?

Do any of them turn green? 

Can you attach relevant bits from your syslog?
Comment 4 Matthias Clasen 2006-07-29 14:14:23 EDT
Jeremy ?
Comment 5 Jeremy Katz 2006-07-31 10:35:24 EDT
I log in, the applet starts spinning dots then I get the notification bubble
that it's gotten a connection on the wired connection.  Which has no link (and
the addr it gets is just the link-local one).  And then, after that, the
behavior I saw on Friday night when I got home was that it then saw the wireless
and tried to use it.

There's not anything in the syslog to make it seem like anything should have
told NM that the wired connection has a link.  What I *think* is happening is
that we're init'ing to "there's a link" and that's not getting invalidated until
we get the list of valid APs.  But that's pure speculation from just reading the
current log :)

Jul 28 20:46:54 aglarond NetworkManager: <information>  starting... 
Jul 28 20:46:54 aglarond NetworkManager: <information>  Adding VPN service 'org.
freedesktop.NetworkManager.vpnc' with name 'vpnc' and program '/usr/bin/nm-vpnc-
service' 
Jul 28 20:46:54 aglarond NetworkManager: <information>  eth1: Device is fully-su
pported using driver 'ipw3945'. 
Jul 28 20:46:54 aglarond NetworkManager: <information>  nm_device_init(): waitin
g for device's worker thread to start 
Jul 28 20:46:54 aglarond NetworkManager: <information>  nm_device_init(): device
's worker thread started, continuing. 
Jul 28 20:46:54 aglarond NetworkManager: <information>  Now managing wireless (8
02.11) device 'eth1'. 
Jul 28 20:46:54 aglarond NetworkManager: <information>  Deactivating device eth1
. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  eth0: Device is fully-su
pported using driver 'e100'. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  nm_device_init(): waitin
g for device's worker thread to start 
Jul 28 20:46:57 aglarond NetworkManager: <information>  nm_device_init(): device
's worker thread started, continuing. 
net (802.3) device 'eth0'. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Deactivating device eth0
. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Found dial up configurat
ion for gprsusb via Modem: gprsusb 
Jul 28 20:46:57 aglarond NetworkManager: <information>  SWITCH: no current conne
ction, found better connection 'eth0'. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Will activate wired conn
ection 'eth0' because it now has a link. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Will activate connection
 'eth0'. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Device eth0 activation s
cheduled... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) starte
d... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
1 of 5 (Device Prepare) scheduled... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
1 of 5 (Device Prepare) started... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
2 of 5 (Device Configure) scheduled... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
1 of 5 (Device Prepare) complete. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
2 of 5 (Device Configure) starting... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
2 of 5 (Device Configure) successful. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
3 of 5 (IP Configure Start) scheduled. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
2 of 5 (Device Configure) complete. 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Activation (eth0) Stage 
3 of 5 (IP Configure Start) started... 
Jul 28 20:46:57 aglarond NetworkManager: <information>  Old device 'eth0' activa
ting, won't change. 
Jul 28 20:46:58 aglarond NetworkManager: <information>  Activation (eth0) Beginn
ing DHCP transaction. 
Jul 28 20:46:58 aglarond NetworkManager: <information>  Activation (eth0) Stage 
3 of 5 (IP Configure Start) complete. 
Jul 28 20:46:58 aglarond NetworkManager: <information>  DHCP daemon state is now
 12 (successfully started) for interface eth0 
Jul 28 20:46:58 aglarond NetworkManager: <information>  DHCP daemon state is now
 1 (starting) for interface eth0 
Jul 28 20:47:04 aglarond NetworkManager: <information>  Old device 'eth0' activa
ting, won't change. 
Jul 28 20:47:19 aglarond NetworkManager: <information>  Updating allowed wireles
s network lists. 
... 
Jul 28 20:47:20 aglarond NetworkManager: <information>  Old device 'eth0' activa
ting, won't change. 
Jul 28 20:47:34 aglarond NetworkManager: <information>  Old device 'eth0' activa
ting, won't change. 
Jul 28 20:47:43 aglarond NetworkManager: <information>  Device 'eth0' DHCP trans
action took too long (>45s), stopping it. 
Jul 28 20:47:44 aglarond NetworkManager: <information>  Activation (eth0) Stage 
4 of 5 (IP Configure Timeout) scheduled... 
Jul 28 20:47:44 aglarond NetworkManager: <information>  DHCP daemon state is now
 14 (normal exit) for interface eth0 
Jul 28 20:47:44 aglarond NetworkManager: <information>  Activation (eth0) Stage 
4 of 5 (IP Configure Timeout) started... 
Jul 28 20:47:44 aglarond NetworkManager: <information>  No DHCP reply received. 
 Automatically obtaining IP via Zeroconf. 
Jul 28 20:47:44 aglarond NetworkManager: <information>  DHCP daemon state is now
 11 (unknown) for interface eth0 
(autoip stuff here)
Jul 28 20:48:00 aglarond NetworkManager: <information>  Activation (eth0) Stage 
5 of 5 (IP Configure Commit) scheduled... 
Jul 28 20:48:00 aglarond NetworkManager: <information>  Activation (eth0) Stage 
4 of 5 (IP Configure Timeout) complete. 
Jul 28 20:48:00 aglarond NetworkManager: <information>  Activation (eth0) Stage 
5 of 5 (IP Configure Commit) started... 
Jul 28 20:48:01 aglarond NetworkManager: <information>  Activation (eth0) succes
sful, device activated. 
Jul 28 20:48:01 aglarond NetworkManager: <information>  Activation (eth0) Finish
 handler scheduled. 
Jul 28 20:48:01 aglarond NetworkManager: <information>  Activation (eth0) Stage 
5 of 5 (IP Configure Commit) complete. 
Jul 28 20:48:04 aglarond NetworkManager: <information>  SWITCH: found better con
nection 'eth1' than current connection 'eth0'. 
Jul 28 20:48:04 aglarond NetworkManager: <information>  Will activate connection
 'eth1/e^(i*pi)'. 
Comment 6 Ray Strode [halfline] 2006-08-04 17:17:21 EDT
Can you try tomorrow's rawhide and report if the problem goes away for you?
Comment 7 Dan Williams 2006-08-08 07:27:33 EDT
Ray, is the fix in NetworkManager-0.7.0-dont-choose-inactive-wired-device.patch?
 It doesn't seem to apply, because the "if (!link_active)" bit is actually "if
(link_active)" in NetworkManagerPolicy.c...  What's the fix then?
Comment 8 Ray Strode [halfline] 2006-08-09 12:08:54 EDT
wow, so I:

1) diffed the patch to a modified source tree (so it couldn't actually be applied)
2) didn't notice that it couldn't be applied, because I never tried to apply it
in the spec file.

Awesome.  Building hopefully better packages now.  Jeremy can you give them a go?
Comment 9 Matthias Clasen 2006-08-14 12:49:18 EDT
Jeremy ?
Comment 10 Bernard Johnson 2006-08-17 13:01:06 EDT
NetworkManager-0.7.0-0.cvs20060529.5 still exhibits this behavior.
Comment 11 Ray Strode [halfline] 2006-08-17 13:15:52 EDT
bummer.

Bernard, do your logs look the same?  can you attach them?
Comment 12 Dan Williams 2006-08-17 13:39:21 EDT
Jeremy,

Does 'cat /sys/class/net/eth0/carrier' give you a 1 or a 0 when you boot up and
have _no_ link?  Also, is there just no cable plugged in, or is there a cable
plugged in an nothing on the other end?  Or is there something on the other end
that's not powered on, or what?

What's the output of '/sbin/mii-tool eth0' when you have a link and also when no
link?

What's the ouptut of '/sbin/ethtool eth0' for both link and no link?

Comment 13 Bernard Johnson 2006-08-17 13:58:06 EDT
My logs more or less look the same with NM saying "Will activate wired
connection 'eth0' because it now has a link." - when it doesn't have a link (no
cable plugged in).

(with no link - no cable plugged in):
[root@localhost ~]# cat /sys/class/net/eth0/carrier 
0
[root@localhost ~]# /sbin/mii-tool eth0
eth0: no link
[root@localhost ~]# /sbin/ethtool eth0
Settings for eth0:
        Supported ports: [ TP MII ]
        Supported link modes:   10baseT/Half 10baseT/Full 
                                100baseT/Half 100baseT/Full 
        Supports auto-negotiation: Yes
        Advertised link modes:  10baseT/Half 10baseT/Full 
                                100baseT/Half 100baseT/Full 
        Advertised auto-negotiation: Yes
        Speed: 10Mb/s
        Duplex: Half
        Port: MII
        PHYAD: 32
        Transceiver: internal
        Auto-negotiation: on
        Supports Wake-on: pumbg
        Wake-on: d
        Current message level: 0x00000007 (7)
        Link detected: no

(with link):
[root@localhost ~]# cat /sys/class/net/eth0/carrier 
1
[root@localhost ~]# /sbin/mii-tool eth0
eth0: negotiated 100baseTx-FD, link ok
[root@localhost ~]# /sbin/ethtool eth0
Settings for eth0:
        Supported ports: [ TP MII ]
        Supported link modes:   10baseT/Half 10baseT/Full 
                                100baseT/Half 100baseT/Full 
        Supports auto-negotiation: Yes
        Advertised link modes:  10baseT/Half 10baseT/Full 
                                100baseT/Half 100baseT/Full 
        Advertised auto-negotiation: Yes
        Speed: 100Mb/s
        Duplex: Full
        Port: MII
        PHYAD: 32
        Transceiver: internal
        Auto-negotiation: on
        Supports Wake-on: pumbg
        Wake-on: d
        Current message level: 0x00000007 (7)
        Link detected: yes
Comment 14 Dan Williams 2006-08-17 16:06:57 EDT
Ok; NM uses netlink to detect whether the device has a link or not; I've got a
tool I can post somewhere that you can run to see whether or not netlink reports
the devices as having the link.  If that works as expected, then something in NM
is actually wrong.  At this point I'm blaming the driver and/or netlink
reporting the wrong thing, which has bitten us before.
Comment 15 Bernard Johnson 2006-08-17 20:20:26 EDT
Post the tool and I'll produce whatever output you're looking for.
Comment 16 Dan Williams 2006-08-18 10:52:40 EDT
Ok, please grab: http://people.redhat.com/dcbw/NetworkManager/nmnetlinktest

It's an i386 executable.  Turn both NM and the 'network' init script off at boot
time, make sure the cable is _unplugged_, and then when the system has booted,
run the tool.  Plug in the cable, then unplug the cable.  Post the output here.

Thanks!
Comment 17 Bernard Johnson 2006-08-18 13:56:34 EDT
There is no change when I plug in the cable or unplug the cable.

[root@localhost ~]# ./nmnetlinktest
interface 'lo' connected
interface 'dev1804289383' disconnected
interface 'eth0' disconnected
interface 'sit0' disconnected
Comment 18 Bernard Johnson 2006-08-18 14:17:42 EDT
It seems that if NetworkManager is not running the state of eth0 doesn't get
reported.  I don't know if this is a valid test or not, but I ran nmnetlinktest
while NM was first attempting to connect:

This is the output from where it tries to connect to the (un)wired eth0 network,
then switches back to the wireless:
[root@localhost ~]# ./nmnetlinktest 
interface 'lo' connected
interface 'eth0' disconnected
interface 'eth1' disconnected
interface 'sit0' disconnected
interface 'eth1' connected
interface 'eth1' connected
[eth0 plugged in here]
interface 'eth0' connected
interface 'eth1' disconnected
interface 'eth1' disconnected
interface 'eth1' disconnected
[eth0 unplugged here]
interface 'eth0' disconnected
interface 'eth1' connected
interface 'eth1' connected
interface 'eth1' disconnected
interface 'eth1' connected
interface 'eth1' connected
Comment 19 Dan Williams 2006-08-18 15:06:07 EDT
What do you mean in comment #17?  Do you mean that plug/unplug of the cable
produces _no_ messages from nmnetlinktest when NM isn't running?
Comment 20 Bernard Johnson 2006-08-18 15:12:24 EDT
It produces no messages when the cable is plugged or unplugged, only output when
nmnetlinktest is started before I start messing with the cable.  Comment #18 is
with NM running.
Comment 21 Matthias Clasen 2006-08-22 13:08:22 EDT
Dan, what is the next step here ?
Comment 22 Ray Strode [halfline] 2006-08-29 11:55:31 EDT
comment 17 could be because the network card drivers aren't loaded.

If you modprobe the drivers or start NetworkManager and then stop it again, what
does nmnetlinktest report?
Comment 23 Bernard Johnson 2006-08-29 15:58:04 EDT
Ok, I let NetworkManager start normally, then I stopped it.

I checked for drivers:
[root@localhost ~]# lsmod  | egrep "bcm|8139"
bcm43xx               434145  0 
ieee80211softmac       37833  1 bcm43xx
ieee80211              35601  2 bcm43xx,ieee80211softmac
8139cp                 29257  0 
8139too                31953  0 
mii                     9793  2 8139cp,8139too

I then ran nmnetlinktest and plugged in the network cable and then unplugged it:
[root@localhost ~]# ./nmnetlinktest 
interface 'lo' connected
interface 'eth0' disconnected
interface 'eth1' disconnected
interface 'sit0' disconnected
interface 'eth0' connected  (<-- This is where I plugged it in)
interface 'eth0' disconnected (<-- This is where I unplugged it)
Comment 24 Matthias Clasen 2006-08-31 14:06:29 EDT
Dan, any chance the recent reversal to the stable branch changes this ?
Comment 25 Dan Williams 2006-08-31 16:04:03 EDT
Possibly; but I looked over the code again and the patch Ray did shouldn't have
changed behavior at all.  Is this still being seen on specific hardware that
you've got?  Which driver?  If you're still getting it, I'll post a debug binary
to try that will print out more information about the device autochoose process.
Comment 26 Bernard Johnson 2006-09-04 18:32:13 EDT
I'm running NetworkManager-0.6.4-4.fc6 now and I don't have this problem anymore.
Comment 27 Ray Strode [halfline] 2006-09-05 11:04:38 EDT
Okay, so it must be a regression in 0.7.0. 

We aren't going with it anymore.  Would you mind filing an upstream bug report?
Comment 28 Bernard Johnson 2006-09-06 01:54:28 EDT
Upstreamed: http://bugzilla.gnome.org/show_bug.cgi?id=354565
Comment 29 Bernard Johnson 2007-03-26 16:46:28 EDT
This is back in F7 rawhide.

$ rpm -q NetworkManager
NetworkManager-0.6.5-0.4.svn2474.fc7
Comment 30 drago01 2007-05-11 11:19:47 EDT
just want to add a "me too" here (I have the exact same problem)
see: http://bugzilla.gnome.org/show_bug.cgi?id=431680
Comment 31 Will Woods 2007-05-14 16:06:03 EDT
NetworkManager is not enabled by default; moving to FC7Target
Comment 32 Adam Pribyl 2007-05-21 04:22:36 EDT
I think I experience even more troubles with this bug in latest rawhide live
image (20050517). I have two ethernet cards one is connected to network with
DHCP the other one is disconnected. After boot the NM incorrectly configures
both interfaces. eth0 (disconn) is havind 169.x.x.x IP the eth1 is not
configured at all. When I do "service network restart" then ifup configures
correctly eth1 and loads IP, DNS, routes from dhcp, however NM tries to
configure eth0 even though it failed during "service network restart". After
some timeout the NM sets eth0 to 169.x.x.x, empties resolv.conf and sets default
route to 169.x.x.x. Then the network is broken again.
Comment 33 Dan Williams 2007-06-07 09:51:56 EDT
Fixed in revision 2578 on NETWORKMANAGER_0_6_0_RELEASE branch upstream.
Comment 34 Bastien Nocera 2007-06-07 13:26:12 EDT
*** Bug 230256 has been marked as a duplicate of this bug. ***
Comment 35 Dan Williams 2007-06-07 15:23:58 EDT
Should be fixed in NetworkManager-0.6.5-4.f7
Comment 36 Fedora Update System 2007-06-08 11:55:02 EDT
NetworkManager-0.6.5-4.fc7 has been pushed to the Fedora 7 testing repository.  If problems still persist, please make note of it in this bug report.
Comment 37 louisgtwo 2007-06-08 15:27:56 EDT
I still see this problem with NetworkManager-0.6.5-4.f7 from testing. Updated F7
as of Friday June 8:

Jun  8 14:51:40 sonlaptop NetworkManager: <info>  starting... 
Jun  8 14:51:40 sonlaptop kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
Jun  8 14:51:40 sonlaptop NetworkManager: <info>  wlan0: Device is
fully-supported using driver 'iwl3945'. 
Jun  8 14:51:41 sonlaptop NetworkManager: <info>  nm_device_init(): waiting for
device's worker thread to start 
Jun  8 14:51:41 sonlaptop NetworkManager: <info>  nm_device_init(): device's
worker thread started, continuing. 
Jun  8 14:51:41 sonlaptop NetworkManager: <info>  Now managing wireless (802.11)
device 'wlan0'. 
Jun  8 14:51:42 sonlaptop NetworkManager: <info>  Deactivating device wlan0. 
Jun  8 14:51:42 sonlaptop kernel: ADDRCONF(NETDEV_UP): eth0: link is not ready
Jun  8 14:51:42 sonlaptop NetworkManager: <info>  eth0: Device is
fully-supported using driver 'e100'. 
Jun  8 14:51:42 sonlaptop NetworkManager: <info>  nm_device_init(): waiting for
device's worker thread to start 
Jun  8 14:51:42 sonlaptop NetworkManager: <info>  nm_device_init(): device's
worker thread started, continuing. 
Jun  8 14:51:43 sonlaptop NetworkManager: <info>  Now managing wired Ethernet
(802.3) device 'eth0'. 
Jun  8 14:51:43 sonlaptop NetworkManager: <info>  Deactivating device eth0. 
Jun  8 14:51:43 sonlaptop NetworkManager: <info>  Will activate wired connection
'eth0' because it now has a link. 
Jun  8 14:51:43 sonlaptop NetworkManager: <info>  SWITCH: no current connection,
found better connection 'eth0'. 
Jun  8 14:51:44 sonlaptop dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/eth0 for sub-path eth0.dbus.get.reason
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Will activate connection 'eth0'. 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Device eth0 activation
scheduled... 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) started... 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 1 of 5
(Device Prepare) scheduled... 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 1 of 5
(Device Prepare) started... 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) scheduled... 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 1 of 5
(Device Prepare) complete. 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) starting... 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) successful. 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 3 of 5
(IP Configure Start) scheduled. 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 2 of 5
(Device Configure) complete. 
Jun  8 14:51:44 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 3 of 5
(IP Configure Start) started... 
Jun  8 14:51:45 sonlaptop NetworkManager: <info>  Activation (eth0) Beginning
DHCP transaction. 
Jun  8 14:51:45 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 3 of 5
(IP Configure Start) complete. 
Jun  8 14:51:45 sonlaptop NetworkManager: <info>  DHCP daemon state is now 12
(successfully started) for interface eth0 
Jun  8 14:51:45 sonlaptop dhclient: wmaster0: unknown hardware address type 801
Jun  8 14:51:45 sonlaptop dhclient: wmaster0: unknown hardware address type 801
Jun  8 14:51:45 sonlaptop NetworkManager: <info>  DHCP daemon state is now 1
(starting) for interface eth0 
Jun  8 14:51:45 sonlaptop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 5
Jun  8 14:51:50 sonlaptop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 6
Jun  8 14:51:50 sonlaptop NetworkManager: <info>  Old device 'eth0' activating,
won't change. 
Jun  8 14:51:56 sonlaptop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 13
Jun  8 14:52:09 sonlaptop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 15
Jun  8 14:52:20 sonlaptop NetworkManager: <info>  Old device 'eth0' activating,
won't change. 
Jun  8 14:52:21 sonlaptop NetworkManager: <info>  Updating allowed wireless
network lists. 
Jun  8 14:52:22 sonlaptop NetworkManager: <info>  Old device 'eth0' activating,
won't change. 
Jun  8 14:52:24 sonlaptop dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port
67 interval 8
Jun  8 14:52:30 sonlaptop NetworkManager: <info>  Device 'eth0' DHCP transaction
took too long (>45s), stopping it. 
Jun  8 14:52:30 sonlaptop dhclient: wmaster0: unknown hardware address type 801
Jun  8 14:52:30 sonlaptop dhclient: wmaster0: unknown hardware address type 801
Jun  8 14:52:30 sonlaptop dhclient: DHCPRELEASE on eth0 to 10.0.0.1 port 67
Jun  8 14:52:30 sonlaptop dhclient: send_packet: Network is unreachable
Jun  8 14:52:30 sonlaptop dhclient: send_packet: please consult README file
regarding broadcast address.
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 4 of 5
(IP Configure Timeout) scheduled... 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 4 of 5
(IP Configure Timeout) started... 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  No DHCP reply received. 
Automatically obtaining IP via Zeroconf. 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  DHCP daemon state is now 14
(normal exit) for interface eth0 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  DHCP daemon state is now 11
(unknown) for interface eth0 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  DHCP daemon state is now 14
(normal exit) for interface eth0 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  autoip: Sending probe #0 for
IP address 169.254.143.1. 
Jun  8 14:52:31 sonlaptop NetworkManager: <info>  autoip: Waiting for reply... 
Jun  8 14:52:33 sonlaptop NetworkManager: <info>  autoip: Sending probe #1 for
IP address 169.254.143.1. 
Jun  8 14:52:33 sonlaptop NetworkManager: <info>  autoip: Waiting for reply... 
Jun  8 14:52:35 sonlaptop NetworkManager: <info>  autoip: Sending probe #2 for
IP address 169.254.143.1. 
Jun  8 14:52:35 sonlaptop NetworkManager: <info>  autoip: Waiting for reply... 
Jun  8 14:52:38 sonlaptop NetworkManager: <info>  autoip: Sending announce #0
for IP address 169.254.143.1. 
Jun  8 14:52:38 sonlaptop NetworkManager: <info>  autoip: Waiting for reply... 
Jun  8 14:52:41 sonlaptop NetworkManager: <info>  autoip: Sending announce #1
for IP address 169.254.143.1. 
Jun  8 14:52:41 sonlaptop NetworkManager: <info>  autoip: Waiting for reply... 
Jun  8 14:52:44 sonlaptop NetworkManager: <info>  autoip: Sending announce #2
for IP address 169.254.143.1. 
Jun  8 14:52:44 sonlaptop NetworkManager: <info>  autoip: Waiting for reply... 
Jun  8 14:52:47 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) scheduled... 
Jun  8 14:52:47 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 4 of 5
(IP Configure Timeout) complete. 
Jun  8 14:52:47 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) started... 
Jun  8 14:52:48 sonlaptop NetworkManager: <info>  Activation (eth0) Finish
handler scheduled. 
Jun  8 14:52:48 sonlaptop NetworkManager: <info>  Activation (eth0) Stage 5 of 5
(IP Configure Commit) complete. 
Jun  8 14:52:48 sonlaptop NetworkManager: <info>  Activation (eth0) successful,
device activated. 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  SWITCH: found better
connection 'wlan0' than current connection 'eth0'. 
Jun  8 14:52:50 sonlaptop dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.reason
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Will activate connection
'wlan0/sabastion'. 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Device wlan0 activation
scheduled... 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Deactivating device eth0. 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) started... 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) scheduled... 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) started... 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) scheduled... 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) complete. 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) starting... 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0/wireless):
access point 'sabastion' is encrypted, but NO valid key exists.  New key needed. 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) New
wireless user key requested for network 'sabastion'. 
Jun  8 14:52:50 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) complete. 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0) New
wireless user key for network 'sabastion' received. 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) scheduled... 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) started... 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) scheduled... 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 1 of
5 (Device Prepare) complete. 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) starting... 
Jun  8 14:52:59 sonlaptop NetworkManager: <info>  Activation (wlan0/wireless):
access point 'sabastion' is encrypted, and a key exists.  No new key needed. 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'INTERFACE_ADD wlan0             wext    /var/run/wpa_supplicant ' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command 'AP_SCAN 1' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'ADD_NETWORK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was '0' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 ssid 736162617374696f6e' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 proto WPA' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 key_mgmt WPA-PSK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 psk <key>' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 pairwise TKIP' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'SET_NETWORK 0 group TKIP' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: sending command
'ENABLE_NETWORK 0' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  SUP: response was 'OK' 
Jun  8 14:53:00 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 2 of
5 (Device Configure) complete. 
Jun  8 14:53:02 sonlaptop kernel: iwl3945: REPLY_ADD_STA failed
Jun  8 14:53:02 sonlaptop kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Jun  8 14:53:03 sonlaptop NetworkManager: <info>  Activation (wlan0/wireless)
Stage 2 of 5 (Device Configure) successful.  Connected to access point 'sabastion'. 
Jun  8 14:53:03 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 3 of
5 (IP Configure Start) scheduled. 
Jun  8 14:53:03 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 3 of
5 (IP Configure Start) started... 
Jun  8 14:53:04 sonlaptop NetworkManager: <info>  Activation (wlan0) Beginning
DHCP transaction. 
Jun  8 14:53:04 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 3 of
5 (IP Configure Start) complete. 
Jun  8 14:53:04 sonlaptop NetworkManager: <info>  DHCP daemon state is now 12
(successfully started) for interface wlan0 
Jun  8 14:53:04 sonlaptop dhclient: wmaster0: unknown hardware address type 801
Jun  8 14:53:04 sonlaptop dhclient: wmaster0: unknown hardware address type 801
Jun  8 14:53:04 sonlaptop NetworkManager: <info>  DHCP daemon state is now 1
(starting) for interface wlan0 
Jun  8 14:53:04 sonlaptop dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Jun  8 14:53:06 sonlaptop dhclient: DHCPACK from 10.0.0.1
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  DHCP daemon state is now 4
(reboot) for interface wlan0 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 4 of
5 (IP Configure Get) scheduled... 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 4 of
5 (IP Configure Get) started... 
Jun  8 14:53:06 sonlaptop dhclient: bound to 10.0.0.10 -- renewal in 33528 seconds.
Jun  8 14:53:06 sonlaptop dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.host_name
Jun  8 14:53:06 sonlaptop dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.domain_name
Jun  8 14:53:06 sonlaptop dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.nis_domain
Jun  8 14:53:06 sonlaptop dhcdbd: message_handler: message handler not found
under /com/redhat/dhcp/wlan0 for sub-path wlan0.dbus.get.nis_servers
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  Retrieved the following IP4
configuration from the DHCP daemon: 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>    address 10.0.0.10 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>    netmask 255.255.0.0 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>    broadcast 10.0.255.255 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>    gateway 10.0.0.1 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>    nameserver 205.152.144.23 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>    nameserver 205.152.132.23 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 5 of
5 (IP Configure Commit) scheduled... 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 4 of
5 (IP Configure Get) complete. 
Jun  8 14:53:06 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 5 of
5 (IP Configure Commit) started... 
Jun  8 14:53:07 sonlaptop NetworkManager: <info>  Activation (wlan0) Finish
handler scheduled. 
Jun  8 14:53:07 sonlaptop NetworkManager: <info>  Activation (wlan0) Stage 5 of
5 (IP Configure Commit) complete. 
Jun  8 14:53:07 sonlaptop NetworkManager: <info>  Activation (wlan0) successful,
device activated. 
Jun  8 14:53:29 sonlaptop kernel: iwl3945: REPLY_ADD_STA failed
Jun  8 14:56:10 sonlaptop last message repeated 3 times
Jun  8 14:59:08 sonlaptop last message repeated 6 times
Jun  8 15:01:19 sonlaptop kernel: iwl3945: REPLY_ADD_STA failed
Jun  8 15:03:29 sonlaptop last message repeated 2 times
Jun  8 15:05:39 sonlaptop kernel: iwl3945: REPLY_ADD_STA failed
Jun  8 15:07:49 sonlaptop kernel: iwl3945: REPLY_ADD_STA failed
Jun  8 15:09:59 sonlaptop kernel: iwl3945: REPLY_ADD_STA failed
Comment 38 Christopher Aillon 2007-06-08 17:48:56 EDT
*** Bug 242786 has been marked as a duplicate of this bug. ***
Comment 39 Bernard Johnson 2007-06-09 01:05:12 EDT
I can confirm that this is still not fixed in (fully updated) rawhide with
NetworkManager-0.6.5-5.fc8.

Reopening.
Comment 40 Osma Ahvenlampi 2007-06-11 15:27:46 EDT
I upgraded to NetworkManager-0.6.5-4.fc7 on my F7 install, and a for at least
the couple of reboots I've done since, it no longer picks a nonexistent wired
network instead of the wireless. Seems to work for me, in other words.
Comment 41 Onno Witvliet 2007-06-12 09:51:45 EDT
Created attachment 156795 [details]
Syslog (with extra debug code)

I also see this problem.

I've tried with version: NetworkManager-0.6.5-5.fc7 on F7. I hope the extra
debug code gives some insight into what is wrong.
Comment 42 Christopher Aillon 2007-06-15 13:03:57 EDT
*** Bug 244353 has been marked as a duplicate of this bug. ***
Comment 43 drago01 2007-06-18 12:37:18 EDT
this "fix" results into nm does not detect link status @all ->regression
Comment 44 drago01 2007-06-18 12:39:50 EDT
ok let me correct my self:
it works sometimes and breaks after 2-3 disconnects I have to restart the
networkmanager service to get it working again for the next 2-3 dis/connects
Comment 45 Dan Williams 2007-06-18 12:50:05 EDT
drago01, can you attach your /var/log/messages so we can see what NM thinks it's
doing?
Comment 46 drago01 2007-06-18 13:10:34 EDT
Created attachment 157295 [details]
/var/log/messages

here is it...
Comment 47 drago01 2007-06-18 13:24:00 EDT
Created attachment 157301 [details]
better one

ok here is a new log. this time I did this:
reboot with a cabled plugged.
unplugged/plugged the cable until it failed to detect the link state (where I
had to rightclick on the applet to select the wired network to get it working).
Comment 48 drago01 2007-06-18 13:25:21 EDT
I think this are the interessting lines:
Jun 18 19:19:27 localhost NetworkManager: nm_device_is_802_3_ethernet: assertion
`dev != NULL' failed
Jun 18 19:19:27 localhost NetworkManager: nm_device_is_802_11_wireless:
assertion `dev != NULL' failed
Comment 49 drago01 2007-06-19 02:14:35 EDT
sorry I am still using NetworkManager-0.6.5-5.fc7 will test again with the
version from updates-testing... sorry again for the noise.
Comment 50 drago01 2007-06-19 12:55:07 EDT
(In reply to comment #49)
> sorry I am still using NetworkManager-0.6.5-5.fc7 will test again with the
> version from updates-testing... sorry again for the noise.

ignore this comment it is the lastest version...
so the problem described above is still present
Comment 51 Dan Williams 2007-06-21 01:25:11 EDT
*** Bug 224086 has been marked as a duplicate of this bug. ***
Comment 52 Dan Williams 2007-06-21 09:30:08 EDT
Additional fixes for this have been committed in revision 2605 on the 0.6.x branch
Comment 53 drago01 2007-06-21 10:04:39 EDT
(In reply to comment #52)
> Additional fixes for this have been committed in revision 2605 on the 0.6.x branch

can you backport them to the fedora package or even better release a 0.6.6 release?
Comment 54 Dan Williams 2007-06-21 11:06:43 EDT
Built in F-7 testing, http://koji.fedoraproject.org/koji/buildinfo?buildID=9454
, could you test the packages out and see if they help at all?

Also includes the HAL rfkill support.

Thanks!
Comment 55 drago01 2007-06-21 11:16:08 EDT
thx, will test them when I get home (in one hour ;) )
Comment 56 drago01 2007-06-21 12:17:35 EDT
(In reply to comment #54)
> Built in F-7 testing, http://koji.fedoraproject.org/koji/buildinfo?buildID=9454
> , could you test the packages out and see if they help at all?

ok here are the test results:
1)login with no link: nothing happens
2)I can plug/unplug the cable as often as I want ... nm always does the correct
thing (up/down)

=> great work :)
Comment 57 Bernard Johnson 2007-06-21 22:23:46 EDT
rawhide NetworkManager-0.6.5-6.fc8 does not fix the problem, or was it supposed
to be another release?
Comment 58 Dan Williams 2007-06-22 07:11:18 EDT
Should be fixed in these two:

NetworkManager-0.6.5-6.fc7
NetworkManager-0.6.5-6.1.fc8
Comment 59 Bernard Johnson 2007-06-22 14:29:03 EDT
(In reply to comment #58)
> NetworkManager-0.6.5-6.1.fc8

This seems to resolve it for me.
Comment 60 Martin Jürgens 2007-06-23 18:29:49 EDT
I am using NetworkManager-0.6.5-5.fc7 and the problem still appears to me (see
my duplicate bug 242786)
Comment 61 Martin Jürgens 2007-06-24 06:15:17 EDT
Created attachment 157705 [details]
my /var/log/messages cutting

here's my syslog cutting as i still encounter the problem after booting and
logging in.
Comment 62 Onno Witvliet 2007-06-24 15:50:55 EDT
(In reply to comment #58)
> NetworkManager-0.6.5-6.fc7

This version resolves the problem for me on Fedora 7
Comment 63 Fedora Update System 2007-06-25 19:24:35 EDT
NetworkManager-0.6.5-6.fc7 has been pushed to the Fedora 7 stable repository.  If problems still persist, please make note of it in this bug report.

Note You need to log in before you can comment on or make changes to this bug.