590874 – let dhclient get a new lease on existing lease expiration before terminating connection

Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.

Bug 590874 - let dhclient get a new lease on existing lease expiration before terminating connection

Summary: let dhclient get a new lease on existing lease expiration before terminating ...

Keywords:
Status:	CLOSED ERRATA
Alias:	None
Product:	Fedora
Classification:	Fedora
Component:	NetworkManager
Sub Component:
Version:	13
Hardware:	All
OS:	Linux
Priority:	low
Severity:	medium
Target Milestone:	---
Assignee:	Dan Williams
QA Contact:	Fedora Extras Quality Assurance
Docs Contact:
URL:
Whiteboard:	https://fedoraproject.org/wiki/Common...
Duplicates (2):	606130 617354 (view as bug list)
Depends On:
Blocks:	F13Target
TreeView+	depends on / blocked

Reported:	2010-05-10 20:40 UTC by Orion Poplawski
Modified:	2013-01-10 05:57 UTC (History)
CC List:	14 users (show)
Fixed In Version:	NetworkManager-0.8.1-4.git20100817.fc13
Doc Type:	Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed:	2010-08-23 22:05:41 UTC
Type:	---
Embargoed:
Dependent Products:

Attachments	(Terms of Use)
logs from anaconda with time change in syslog (330.00 KB, application/x-tar) 2010-05-11 13:44 UTC, Kamil Páral	no flags	Details
messages.log (1.50 KB, application/octet-stream) 2010-07-16 07:15 UTC, Misha Shnurapet	no flags	Details
/tmp/syslog from fresh kickstart install (58.21 KB, text/plain) 2010-07-20 18:37 UTC, John Sopko	no flags	Details
View All

Description Orion Poplawski 2010-05-10 20:40:38 UTC

Description of problem:

Seen this twice (on same machine) now installing from today's install image in development/13 and 2.6.33.3-85.fc13.x86_64:


syslog (note clock jumping forward 6 hours):
13:47:34,016 ERR udevd: worker [487] unexpectedly returned with status 0x0100
13:47:34,016 ERR udevd: worker [487] failed while handling '/devices/platform/floppy.0/block/fd0
'
13:47:37,025 ERR kernel:end_request: I/O error, dev fd0, sector 0
13:47:37,025 ERR kernel:Buffer I/O error on device fd0, logical block 0
19:47:39,756 INFO kernel: sda: sda1 sda2 sda3 sda4 < >
19:47:40,243 INFO kernel: sda: sda1 sda2 sda3
20:15:28,252 INFO NetworkManager: <info> (eth1): DHCPv4 state changed bound -> expire
20:15:28,252 INFO NetworkManager: <info> (eth1): device state change: 8 -> 9 (reason 6)
20:15:28,252 INFO NetworkManager: <info> Marking connection 'System eth1' invalid because IP con
figuration expired.
20:15:28,252 WARN NetworkManager: <warn> Activation (eth1) failed.
20:15:28,253 INFO NetworkManager: <info> (eth1): device state change: 9 -> 3 (reason 0)
20:15:28,253 INFO NetworkManager: <info> (eth1): deactivating device (reason: 0).
20:15:28,254 INFO NetworkManager: <info> (eth1): canceled DHCP transaction, DHCP client pid 374
20:15:28,254 ERR NetworkManager: <error> [1273522528.254853] [nm-system.c:1229] check_one_route(
): (eth1): error -34 returned from rtnl_route_del(): Sucess#012
20:15:28,268 INFO NetworkManager: <info> Setting system hostname to 'localhost.localdomain' (no 
default device)
20:15:28,272 WARN NetworkManager: <warn> (pid 374) unhandled DHCP event for interface eth1

anaconda.log:
13:53:02,124 DEBUG anaconda: installpackages is a direct step
13:53:02,124 INFO anaconda: Preparing to install packages
14:15:28,818 WARNING anaconda: Try 1/10 for http://fedora.cora.nwra.com/development/13/x86_64/os
/Packages/jdepend-2.9.1-2.fc13.noarch.rpm failed: [Errno 14] PYCURL ERROR 6 - ""
14:15:29,069 WARNING anaconda: Failed to get http://fedora.cora.nwra.com/development/13/x86_64/o
s/Packages/jdepend-2.9.1-2.fc13.noarch.rpm from mirror 1/1, or downloaded file is corrupt

If I log on the the install machine and run date:

Mon May 10 14:35:16 MDT 2010

I get what I expect.  But something is up with the time being logged by syslog and it messes with dhcp/NM.

I'm also seeing similar clock jumps on a Fedora 13 VM on a Centos 5.4 host.

Version-Release number of selected component (if applicable):
2.6.33.3-85.fc13.x86_64

Comment 1 Orion Poplawski 2010-05-10 22:43:52 UTC

Reproduced on another machine with the RC2 install image.  Adding to blocker list.

Interestingly, I see similar time jump in previous successful install logs, but NM was able to recover:

13:47:06,129 INFO kernel:device-mapper: multipath round-robin: version 1.0.0 loaded
19:47:27,260 INFO kernel: sda: sda1
19:47:27,863 INFO kernel: sda:
19:47:28,185 INFO kernel: sda: sda1
19:47:29,934 INFO kernel: sda: sda1 sda2
19:47:47,253 INFO kernel: sda: sda1 sda2 sda3
19:50:40,044 INFO kernel:Adding 4094968k swap on /dev/sda3.  Priority:-1 extents:1 across:409496
8k 
19:50:40,223 INFO kernel:EXT4-fs (sda2): mounted filesystem with ordered data mode
19:50:40,223 DEBUG kernel:SELinux: initialized (dev sda2, type ext4), uses xattr
19:50:40,340 INFO kernel:EXT4-fs (sda1): mounted filesystem with ordered data mode
19:50:40,340 DEBUG kernel:SELinux: initialized (dev sda1, type ext4), uses xattr
19:50:40,464 DEBUG kernel:SELinux: initialized (dev tmpfs, type tmpfs), uses transition SIDs
19:50:40,786 INFO kernel:EXT4-fs (sdb1): mounted filesystem with ordered data mode
19:50:40,786 DEBUG kernel:SELinux: initialized (dev sdb1, type ext4), uses xattr
20:00:19,065 INFO NetworkManager: <info> (eth0): DHCPv4 state changed bound -> expire
20:00:19,076 INFO NetworkManager: <info> (eth0): DHCPv4 state changed expire -> preinit
20:00:19,078 INFO dhclient: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 8
20:00:19,079 INFO dhclient: DHCPOFFER from 192.168.0.8
20:00:19,079 INFO dhclient: DHCPREQUEST on eth0 to 255.255.255.255 port 67
20:00:19,080 INFO dhclient: DHCPACK from 192.168.0.8
20:00:19,091 INFO dhclient: bound to 192.168.0.39 -- renewal in 7076 seconds.
20:00:19,091 INFO NetworkManager: <info> (eth0): DHCPv4 state changed preinit -> bound
20:00:19,092 INFO NetworkManager: <info>   address 192.168.0.39
20:00:19,092 INFO NetworkManager: <info>   prefix 24 (255.255.255.0)
20:00:19,092 INFO NetworkManager: <info>   gateway 192.168.0.1
20:00:19,092 INFO NetworkManager: <info>   hostname 'orca'
20:00:19,092 INFO NetworkManager: <info>   nameserver '192.168.0.8'
20:00:19,092 INFO NetworkManager: <info>   nameserver '192.168.0.12'
20:00:19,092 INFO NetworkManager: <info>   domain name 'cora.nwra.com'


So perhaps for the purpose of fixing for release, this needs to be assigned to NM (or dhclient).  Or cloned if there are two issues.

Comment 2 Jesse Keating 2010-05-10 23:37:34 UTC

There may indeed be a bug here, but I'm curious why your clock is jumping.  I haven't had that happen in KVM or real hardware, or even parallels.  If you can find that out, that'd be helpful.  Since I haven't seen any reports of this until now, I don't really consider it a blocker.

Comment 3 Kamil Páral 2010-05-11 13:44:48 UTC

Created attachment 413143 [details]
logs from anaconda with time change in syslog

I managed to reproduce the clock jump. Just set your timezone to the other half of the world and uncheck "system clock uses UTC", that should do it. Then continue with installation and watch the syslog.

...
13:31:31,252 INFO kernel:EXT4-fs (dm-0): mounted filesystem with ordered data mode
13:31:31,252 DEBUG kernel:SELinux: initialized (dev dm-0, type ext4), uses xattr
02:35:53,098 INFO kernel: vda: vda1
02:35:53,668 INFO kernel: vda:
...

But I haven't seen any problem with Network Manager. Maybe that occurs only sometimes depending on the DHCP configuration or star constellation.

Comment 4 Orion Poplawski 2010-05-11 14:20:20 UTC

I'm doing kickstart with:

timezone America/Denver

which is the same as I've been doing since forever.

I would love to figure out what's jumping the clock, but I have no idea what would do it.

Comment 5 Orion Poplawski 2010-05-11 14:26:26 UTC

Looking back, the clock jumping has been present since at least Fedora 11.  What's new is NM failing to renew the lease.

Comment 6 John Poelstra 2010-05-12 00:55:49 UTC

Reviewed by a QA, Release Engineering, etc. at 2010-05-11 "Go/No-Go Meeting and determined that this is not a release blocker, but should still be included on Common Bugs page.

Comment 7 Orion Poplawski 2010-05-12 15:02:21 UTC

Re-assigning to NM for now, as it used to be able to renew the lease in F11 and F12 and should be able to do so now.  Would still like to now what is up with the clock though at some point.

Comment 8 Orion Poplawski 2010-05-24 16:00:15 UTC

I'm seeing this problem as well when my machine wakes up from hibernation::

May 24 08:23:40 orca NetworkManager[954]: <info> (eth1): DHCPv4 state changed renew -> expire
May 24 08:23:40 orca NetworkManager[954]: <info> (eth1): device state change: 8 -> 9 (reason 6)
May 24 08:23:40 orca NetworkManager[954]: <info> Marking connection 'System eth1' invalid because IP configuration expired.
May 24 08:23:40 orca NetworkManager[954]: <warn> Activation (eth1) failed.
May 24 08:23:40 orca NetworkManager[954]: <info> (eth1): DHCPv4 state changed expire -> preinit
May 24 08:23:40 orca NetworkManager[954]: <info> (eth1): DHCPv4 state changed preinit -> bound
May 24 08:23:40 orca NetworkManager[954]: <info> (eth1): device state change: 9 -> 3 (reason 0)
May 24 08:23:40 orca NetworkManager[954]: <info> (eth1): deactivating device (reason: 0).
May 24 08:23:41 orca NetworkManager[954]: <info> (eth1): canceled DHCP transaction, DHCP client pid 966
May 24 08:23:41 orca NetworkManager[954]: <error> [1274711021.702053] [nm-system.c:1229] check_one_route(): (eth1): error -34 returned from rtnl_route_del(): Sucess#012

Comment 9 Dan Williams 2010-05-26 18:01:14 UTC

On the resume from hibernate case, does that happen right after NM wakes up, or a bit after it does?  We should be terminating the DHCP client before going to sleep. If you don't see "sleeping..." and "waking up..." in the logs, then yeah we're going to have problems because the pm-utils script isn't properly delivering the sleep/wake signals to NM.

One way to fix it might be to start a timer on 'expire' or at least consider 'expire' to not be a complete failure, but instead allow the connection to be reactivated.

Comment 10 Orion Poplawski 2010-05-26 20:36:40 UTC

Ah, we're running afoul of my attempts to keep the network up during hibernate.  We automount home directories over NFS and it causes problems if the network is shut down (see bug 287411 and bug 492665 and bug 503199).  I may have a better way around that though I think, and things may be better with F13 and sssd.

Comment 11 Adam Williamson 2010-05-31 22:13:41 UTC


-- 
Fedora Bugzappers volunteer triage team
https://fedoraproject.org/wiki/BugZappers

Comment 12 Dan Williams 2010-06-28 19:42:22 UTC

*** Bug 606130 has been marked as a duplicate of this bug. ***

Comment 13 Amappa 2010-07-07 20:02:43 UTC

My PC seems to have the same problem. 

at first it was going ok:
Jun 18 14:24:24 localhost dhclient[1394]: DHCPREQUEST on eth0 to 192.168.1.1 port 67
Jun 18 14:24:24 localhost dhclient[1394]: DHCPNAK from 192.168.1.1
Jun 18 14:24:24 localhost NetworkManager: <info> (eth0): DHCPv4 state changed bound -> expire
Jun 18 14:24:24 localhost NetworkManager: <info> (eth0): DHCPv4 state changed expire -> preinit
Jun 18 14:24:24 localhost dhclient[1394]: DHCPDISCOVER on eth0 to 255.255.255.255 port 67 interval 4
Jun 18 14:24:24 localhost dhclient[1394]: DHCPOFFER from 192.168.1.1
Jun 18 14:24:24 localhost dhclient[1394]: DHCPREQUEST on eth0 to 255.255.255.255 port 67
Jun 18 14:24:24 localhost dhclient[1394]: DHCPACK from 192.168.1.1
Jun 18 14:24:24 localhost NetworkManager: <info> (eth0): DHCPv4 state changed preinit -> bound
Jun 18 14:24:24 localhost NetworkManager: <info>   address 192.168.1.28
Jun 18 14:24:24 localhost NetworkManager: <info>   prefix 24 (255.255.255.0)
Jun 18 14:24:24 localhost NetworkManager: <info>   gateway 192.168.1.1
Jun 18 14:24:24 localhost NetworkManager: <info>   nameserver '192.168.1.1'
Jun 18 14:24:24 localhost NetworkManager: <info>   domain name 'fritz.box'
Jun 18 14:24:24 localhost dhclient[1394]: bound to 192.168.1.28 -- renewal in 419899 seconds.

Update on June 20:
Jun 20 20:39:49 Updated: 1:NetworkManager-glib-0.8.1-0.1.git20100510.fc12.i686
Jun 20 20:40:31 Installed: kernel-PAE-2.6.32.14-127.fc12.i686
Jun 20 20:40:35 Updated: 1:NetworkManager-0.8.1-0.1.git20100510.fc12.i686
Jun 20 20:40:50 Updated: 1:NetworkManager-gnome-0.8.1-0.1.git20100510.fc12.i686
Jun 20 20:40:53 Updated: 1:NetworkManager-vpnc-0.8.0-1.git20100411.fc12.i686
Jun 20 20:40:54 Updated: 1:NetworkManager-pptp-0.8.0-1.git20100411.fc12.i686
Jun 20 20:41:38 Installed: kernel-2.6.32.14-127.fc12.i686

After the update the error:
Jun 25 23:14:35 localhost dhclient[1431]: DHCPREQUEST on eth0 to 192.168.1.1 port 67
Jun 25 23:14:35 localhost dhclient[1431]: DHCPNAK from 192.168.1.1
Jun 25 23:14:35 localhost NetworkManager[1398]: <info> (eth0): DHCPv4 state changed bound -> expire
Jun 25 23:14:35 localhost NetworkManager[1398]: <info> (eth0): device state change: 8 -> 9 (reason 6)
Jun 25 23:14:35 localhost NetworkManager[1398]: <info> Marking connection 'System eth0' invalid because IP configuration expired.
Jun 25 23:14:35 localhost NetworkManager[1398]: <warn> Activation (eth0) failed.
Jun 25 23:14:35 localhost NetworkManager[1398]: <info> (eth0): device state change: 9 -> 3 (reason 0)
Jun 25 23:14:35 localhost NetworkManager[1398]: <info> (eth0): deactivating device (reason: 0).
Jun 25 23:14:35 localhost NetworkManager[1398]: <info> (eth0): canceled DHCP transaction, DHCP client pid 1431
Jun 25 23:14:35 localhost NetworkManager[1398]: <error> [1277500475.575320] [nm-system.c:1229] check_one_route(): (eth0): error -34 returned from rtnl_route_del(): Sucess#012

The error is coming back and I had it for a couple of times now.  

Hope this will help..

Comment 14 Mike Loseke 2010-07-15 18:28:57 UTC

I'm seeing this same issue - dhclient getting a DHCPNAK and NetworkManager marking the wireless connection as invalid.  This is unrelated to suspend/hibernate/resume for me.

Jul 11 18:44:38 local dhclient[28983]: DHCPREQUEST on wlan0 to 10.1.1.1 port 67
Jul 11 18:44:38 local dhclient[28983]: DHCPNAK from 10.1.1.1
Jul 11 18:44:38 local NetworkManager[1542]: <info> (wlan0): DHCPv4 state changed renew -> expire
Jul 11 18:44:38 local NetworkManager[1542]: <info> (wlan0): device state change: 8 -> 9 (reason 6)
Jul 11 18:44:38 local NetworkManager[1542]: <warn> Activation (wlan0) failed for access point (MYSSID)
Jul 11 18:44:38 local NetworkManager[1542]: <info> Marking connection 'Auto MYSSID' invalid because IP configuration expired.
Jul 11 18:44:38 local NetworkManager[1542]: <warn> Activation (wlan0) failed.
Jul 11 18:44:38 local NetworkManager[1542]: <info> (wlan0): device state change: 9 -> 3 (reason 0)
Jul 11 18:44:38 local NetworkManager[1542]: <info> (wlan0): deactivating device (reason: 0).
Jul 11 18:44:38 local NetworkManager[1542]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 28983

Comment 15 Misha Shnurapet 2010-07-16 07:14:21 UTC

It started happening since the recent update of Network Manager. It simply
loses the connection suddenly.

NetworkManager-0.8.1-0.1.git20100510.fc12.x86_64
NetworkManager-openvpn-0.7.996-4.git20090923.fc12.x86_64
NetworkManager-vpnc-0.8.0-1.git20100411.fc12.x86_64
NetworkManager-pptp-0.8.0-1.git20100411.fc12.x86_64
NetworkManager-glib-0.8.1-0.1.git20100510.fc12.x86_64
NetworkManager-gnome-0.8.1-0.1.git20100510.fc12.x86_64

Ethernet connection established, but after a while NM disconnects.

Comment 16 Misha Shnurapet 2010-07-16 07:15:13 UTC

Created attachment 432312 [details]
messages.log

Happens very often.

Comment 17 John Sopko 2010-07-20 18:37:52 UTC

Created attachment 433237 [details]
/tmp/syslog from fresh kickstart install

I attached the /tmp/syslog that is created during a fresh kickstart. The first part of the kickstart works fine, NetworkManager gets the IP etc fine from dhcp and is able to download the kickstart file. Then it loses the IP address and the install hangs. Repeated 5 times.

The work around is to specify the ip= dns= netmask= gateway= kickstart options.

Comment 18 Dan Williams 2010-07-28 01:35:58 UTC

So looking into this, the reason the "fail on expired DHCP" code was added was to prevent what I"d call a bug in dhclient, but which was rejected as a bug by our maintainers.  We'll need to revisit this.  When dhclient is given a leasefile with a long-past lease, it continually binds to the lease, figures out it's expired, then retries it.  See the comments in:

http://cgit.freedesktop.org/NetworkManager/NetworkManager/commit/?id=b172519045e5ea4825f85fca81de8395e92600c1

From which the interesting bits are:

    PRC: Bound to lease 00:01:00:01:12:e1:92:d9:00:14:22:fd:06:e7.
    PRC: Rebind event scheduled in -8604281 seconds, to run for 110 seconds.
    PRC: Depreference scheduled in -8604241 seconds.
    PRC: Expiration scheduled in -8604171 seconds.
    PRC: Rebinding lease on eth0.
    PRC: Depreference scheduled in -8604241 seconds.
    PRC: Expiration scheduled in -8604171 seconds.
    NetworkManager: <info> (eth0): DHCPv6 state changed preinit6 -> bound6

I assume that old leasefiles are somewhat uncommon, but I still believe this is a bug in dhclient that should get fixed.  So we'll revert the commit I reference above, and punt the problem to dhclient if it shows up again.

Comment 19 Dan Williams 2010-07-28 01:38:40 UTC

Upstream revert:

af2be00b8cae5e20ffb89f68c86c001a35a0f844 (master)
eadaa1f2c10fbab0c0aa2189b50432bf5823bb18 (0.8.x)

Comment 20 Amappa 2010-08-02 15:56:52 UTC

Ok, maybe a bug in dhclient. 
But if so why getting the errors after an upgrade/update of networkmanager (#13). Misha Shnurapet (#16&#17) also reported the error after the same upgrade/update. The error reported by Mike (#14) sounds like the same issue. I'm no pro but isn´t it more likely to be a bug in networkmanager?

I'm using now the workaround (#17): fixed ip.

Comment 21 Mike Loseke 2010-08-05 16:40:05 UTC

This last NM update doesn't appear to have changed the behavior for me.  My wireless connection is still being disabled when the DHCP lease expires.

NetworkManager-0.8.1-1.fc13.i686

Aug  5 00:36:34 local dhclient[20300]: DHCPREQUEST on wlan0 to 10.13.13.1 port 67
Aug  5 00:36:34 local dhclient[20300]: DHCPNAK from 10.13.13.1
Aug  5 00:36:34 local NetworkManager[1477]: <info> (wlan0): DHCPv4 state changed reboot -> expire
Aug  5 00:36:34 local NetworkManager[1477]: <info> (wlan0): device state change: 8 -> 9 (reason 6)
Aug  5 00:36:34 local NetworkManager[1477]: <warn> Activation (wlan0) failed for access point (MYSSID)
Aug  5 00:36:34 local NetworkManager[1477]: <info> Marking connection 'Auto MYSSID' invalid because IP configuration expired.
Aug  5 00:36:34 local NetworkManager[1477]: <warn> Activation (wlan0) failed.
Aug  5 00:36:34 local NetworkManager[1477]: <info> (wlan0): device state change: 9 -> 3 (reason 0)
Aug  5 00:36:34 local NetworkManager[1477]: <info> (wlan0): deactivating device (reason: 0).
Aug  5 00:36:34 local NetworkManager[1477]: <info> (wlan0): canceled DHCP transaction, DHCP client pid 20300
Aug  5 00:36:34 local NetworkManager[1477]: <error> [1280990194.261169] [nm-system.c:1229] check_one_route(): (wlan0): error -34 returned from rtnl_route_del(): Netlink Error (errno = Numerical result out of range)
Aug  5 00:36:34 local NetworkManager[1477]: <warn> (pid 20300) unhandled DHCP event for interface wlan0

Comment 22 Fedora Update System 2010-08-17 17:10:16 UTC

NetworkManager-0.8.1-4.git20100817.fc12 has been submitted as an update for Fedora 12.
http://admin.fedoraproject.org/updates/NetworkManager-0.8.1-4.git20100817.fc12

Comment 23 Fedora Update System 2010-08-17 17:12:04 UTC

NetworkManager-0.8.1-4.git20100817.fc13 has been submitted as an update for Fedora 13.
http://admin.fedoraproject.org/updates/NetworkManager-0.8.1-4.git20100817.fc13

Comment 24 Fedora Update System 2010-08-17 17:13:57 UTC

NetworkManager-0.8.1-4.git20100817.fc14 has been submitted as an update for Fedora 14.
http://admin.fedoraproject.org/updates/NetworkManager-0.8.1-4.git20100817.fc14

Comment 25 Mike Loseke 2010-08-18 17:24:33 UTC

This update looks like it's working for me on F13.  Upon lease expiry this morning the right thing appears to have been done:


Aug 18 09:00:46 local dhclient[12212]: DHCPREQUEST on wlan0 to 10.13.13.1 port 67
Aug 18 09:00:46 local dhclient[12212]: DHCPNAK from 10.13.13.1
Aug 18 09:00:46 local NetworkManager[2709]: <info> (wlan0): DHCPv4 state changed reboot -> expire
Aug 18 09:00:46 local dhclient[12212]: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
Aug 18 09:00:46 local NetworkManager[2709]: <info> (wlan0): DHCPv4 state changed expire -> preinit
Aug 18 09:00:46 local dhclient[12212]: DHCPOFFER from 10.13.13.1
Aug 18 09:00:46 local dhclient[12212]: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Aug 18 09:00:46 local dhclient[12212]: DHCPACK from 10.13.13.1
Aug 18 09:00:46 local dhclient[12212]: bound to 10.13.13.2 -- renewal in 38441 seconds.
Aug 18 09:00:46 local NetworkManager[2709]: <info> (wlan0): DHCPv4 state changed preinit -> bound

Thanks!

Comment 26 Fedora Update System 2010-08-19 20:32:28 UTC

NetworkManager-0.8.1-5.git20100818.fc14 has been submitted as an update for Fedora 14.
http://admin.fedoraproject.org/updates/NetworkManager-0.8.1-5.git20100818.fc14

Comment 27 Fedora Update System 2010-08-20 02:13:28 UTC

NetworkManager-0.8.1-4.git20100817.fc13 has been pushed to the Fedora 13 testing repository.  If problems still persist, please make note of it in this bug report.
 If you want to test the update, you can install it with 
 su -c 'yum --enablerepo=updates-testing update NetworkManager'.  You can provide feedback for this update here: http://admin.fedoraproject.org/updates/NetworkManager-0.8.1-4.git20100817.fc13

Comment 28 Fedora Update System 2010-08-23 22:04:59 UTC

NetworkManager-0.8.1-4.git20100817.fc13 has been pushed to the Fedora 13 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 29 Fedora Update System 2010-08-24 01:20:04 UTC

NetworkManager-0.8.1-5.git20100818.fc14 has been pushed to the Fedora 14 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 30 Fedora Update System 2010-09-01 01:25:45 UTC

NetworkManager-0.8.1-6.git20100831.fc13 has been submitted as an update for Fedora 13.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.1-6.git20100831.fc13

Comment 31 Fedora Update System 2010-09-01 01:42:47 UTC

NetworkManager-0.8.1-6.git20100831.fc12 has been submitted as an update for Fedora 12.
https://admin.fedoraproject.org/updates/NetworkManager-0.8.1-6.git20100831.fc12

Comment 32 Fedora Update System 2010-09-26 04:34:24 UTC

NetworkManager-0.8.1-6.git20100831.fc12 has been pushed to the Fedora 12 stable repository.  If problems still persist, please make note of it in this bug report.

Comment 33 Dan Williams 2010-10-07 04:41:25 UTC

*** Bug 617354 has been marked as a duplicate of this bug. ***

Comment 34 Jonathan Larmour 2010-10-22 01:19:32 UTC

I'm not sure all the issues raised in this bug have been fixed. At least not in Fedora 12. I have a log similar to that in comment #1:

Oct 21 19:53:38 lert NetworkManager[26305]: <info> (eth1): DHCPv4 state changed bound -> expire
Oct 21 19:53:38 lert dhclient[2978]: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 5
Oct 21 19:53:38 lert NetworkManager[26305]: <info> (eth1): DHCPv4 state changed expire -> preinit
Oct 21 19:53:43 lert dhclient[2978]: DHCPDISCOVER on eth1 to 255.255.255.255 port 67 interval 7
Oct 21 19:53:44 lert dhclient[2978]: DHCPOFFER from 172.31.1.2
Oct 21 19:53:44 lert dhclient[2978]: DHCPREQUEST on eth1 to 255.255.255.255 port 67
Oct 21 19:53:44 lert dhclient[2978]: DHCPACK from 172.31.1.2
Oct 21 19:53:44 lert dhclient[2978]: bound to 172.31.1.136 -- renewal in 8953 seconds.
Oct 21 19:53:44 lert NetworkManager[26305]: <info> (eth1): DHCPv4 state changed preinit -> bound

In other words, the lease got expired. The reason is that the laptop was put to sleep after the lease was granted, but NetworkManager was never informed. This was Dan's concern in comment #9. Looking at the logs, previously pm-utils has done the right thing, e.g.:
Oct 18 08:34:06 lert NetworkManager[26305]: <info> sleep requested (sleeping: no  enabled: yes)
(and there have been no relevant system changes/yum upgrades since then).
But earlier today, when the laptop was put to sleep, that did not happen. NetworkManager did notice the connection had dropped when the laptop resumed:
Oct 21 17:24:17 lert NetworkManager[26305]: <info> (eth1): supplicant connection state:  completed -> disconnected
Oct 21 17:24:17 lert NetworkManager[26305]: <info> (eth1): supplicant connection state:  disconnected -> scanning
Oct 21 17:24:22 lert NetworkManager[26305]: <info> (eth1): supplicant connection state:  scanning -> associating
Oct 21 17:24:23 lert NetworkManager[26305]: <info> (eth1): supplicant connection state:  associating -> associated
Oct 21 17:24:23 lert NetworkManager[26305]: <info> (eth1): supplicant connection state:  associated -> completed

but that's all.

According to /var/log/pm-suspend.log, the relevant hook for NetworkManager was executed:
/usr/lib64/pm-utils/sleep.d/55NetworkManager suspend suspend: success.
and later:
/usr/lib64/pm-utils/sleep.d/55NetworkManager resume suspend: success.

So it's not clear to me that the fault is pm-utils - clearly it tried to run the hook. I couldn't make dbus-monitor to show me the signals when I tried to run dbus-send by hand (which is what the sleep.d/55NetworkManager hook does), so can't confirm whether a dbus signal is actually sent, without guidance in driving dbus-monitor.

FAOD here are the versions:
NetworkManager-0.8.1-6.git20100831.fc12.x86_64
pm-utils-1.2.5-7.fc12.x86_64

Comment 35 Orion Poplawski 2010-10-22 21:23:09 UTC

Jonathan - you may have hit bug 638640

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