Bug 471497 - iwl4965: DHCPREQUEST ever 20-30 seconds
iwl4965: DHCPREQUEST ever 20-30 seconds
Status: CLOSED RAWHIDE
Product: Fedora
Classification: Fedora
Component: kernel (Show other bugs)
10
All Linux
medium Severity medium
: ---
: ---
Assigned To: John W. Linville
Fedora Extras Quality Assurance
:
Depends On:
Blocks:
  Show dependency treegraph
 
Reported: 2008-11-13 18:51 EST by Tom London
Modified: 2009-01-13 14:28 EST (History)
3 users (show)

See Also:
Fixed In Version:
Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of:
Environment:
Last Closed: 2009-01-13 14:28:29 EST
Type: ---
Regression: ---
Mount Type: ---
Documentation: ---
CRM:
Verified Versions:
Category: ---
oVirt Team: ---
RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: ---


Attachments (Terms of Use)

  None (edit)
Description Tom London 2008-11-13 18:51:29 EST
Description of problem:
I've noticed that after running for several hours, I start getting DHCPREQUEST messages every 20-30 seconds:

Nov 13 14:47:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 14:47:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 14:57:25 tlondon kernel: CE: hpet increasing min_delta_ns to 33750 nsec
Nov 13 14:57:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 14:57:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 14:59:21 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 14:59:28 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 14:59:37 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 14:59:50 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 14:59:57 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:00:10 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:00:27 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:00:42 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:00:59 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:01:07 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:01:17 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:01:31 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:01:51 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:02:01 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:02:16 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:02:30 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:02:51 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:03:06 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:03:25 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:03:32 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:03:47 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:04:02 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:04:16 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:04:37 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:04:58 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:05:16 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:05:28 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:05:35 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:05:50 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:06:09 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:06:25 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:06:35 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:06:42 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:06:57 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:07:11 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:07:19 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:07:29 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:07:39 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:07:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 15:07:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 15:07:59 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:08:06 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67
Nov 13 15:08:21 tlondon dhclient: DHCPREQUEST on wlan0 to 10.10.2.11 port 67

This appears to go on indefinitely unless I take down the interface.

If I cycle the interface by disabling/enabling wireless in NetworkManager, the wireless appears to "clear" and stop the above:

Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) starting connection 'Auto insidex'
Nov 13 15:10:39 tlondon NetworkManager: <info>  (wlan0): device state change: 3 -> 4
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
Nov 13 15:10:39 tlondon NetworkManager: <info>  (wlan0): device state change: 4 -> 5
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0/wireless): connection 'Auto insidex' has security, and secrets exist.  No new secrets needed.
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'ssid' value 'insidex'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'scan_ssid' value '1'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'key_mgmt' value 'WPA-EAP'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'password' value '<omitted>'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'eap' value 'PEAP'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'fragment_size' value '1300'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'phase1' value 'peapver=0'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'phase2' value 'auth=MSCHAPV2'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: added 'identity' value 'tlondon'
Nov 13 15:10:39 tlondon NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
Nov 13 15:10:39 tlondon NetworkManager: <info>  Config: set interface ap_scan to 1
Nov 13 15:10:40 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
Nov 13 15:10:43 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
Nov 13 15:10:43 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
Nov 13 15:10:43 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> associated
Nov 13 15:10:44 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake
Nov 13 15:10:44 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
Nov 13 15:10:44 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 15:10:44 tlondon NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'insidex'.
Nov 13 15:10:44 tlondon NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
Nov 13 15:10:44 tlondon NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
Nov 13 15:10:44 tlondon NetworkManager: <info>  (wlan0): device state change: 5 -> 7
Nov 13 15:10:44 tlondon NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
Nov 13 15:10:44 tlondon NetworkManager: <info>  dhclient started with pid 9976
Nov 13 15:10:44 tlondon NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
Nov 13 15:10:44 tlondon dhclient: Internet Systems Consortium DHCP Client 4.0.0
Nov 13 15:10:44 tlondon dhclient: Copyright 2004-2007 Internet Systems Consortium.
Nov 13 15:10:44 tlondon dhclient: All rights reserved.
Nov 13 15:10:44 tlondon dhclient: For info, please visit http://www.isc.org/sw/dhcp/
Nov 13 15:10:44 tlondon dhclient: 
Nov 13 15:10:44 tlondon NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit
Nov 13 15:10:44 tlondon dhclient: Listening on LPF/wlan0/00:13:e8:77:49:e7
Nov 13 15:10:44 tlondon dhclient: Sending on   LPF/wlan0/00:13:e8:77:49:e7
Nov 13 15:10:44 tlondon dhclient: Sending on   Socket/fallback
Nov 13 15:10:45 tlondon dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 7
Nov 13 15:10:52 tlondon dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 11
Nov 13 15:10:52 tlondon dhclient: DHCPOFFER from 10.11.14.1
Nov 13 15:10:52 tlondon dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
Nov 13 15:10:52 tlondon dhclient: DHCPACK from 10.11.14.1
Nov 13 15:10:52 tlondon NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound
Nov 13 15:10:52 tlondon NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
Nov 13 15:10:52 tlondon NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
Nov 13 15:10:52 tlondon NetworkManager: <info>    address 10.11.14.42
Nov 13 15:10:52 tlondon NetworkManager: <info>    prefix 24 (255.255.255.0)
Nov 13 15:10:52 tlondon NetworkManager: <info>    gateway 10.11.14.1
Nov 13 15:10:52 tlondon NetworkManager: <info>    nameserver '10.10.3.10'
Nov 13 15:10:52 tlondon NetworkManager: <info>    nameserver '10.10.3.11'
Nov 13 15:10:52 tlondon NetworkManager: <info>    nameserver '10.10.2.11'
Nov 13 15:10:52 tlondon NetworkManager: <info>    domain name 'innopath.com.'
Nov 13 15:10:52 tlondon NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
Nov 13 15:10:52 tlondon NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
Nov 13 15:10:52 tlondon NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
Nov 13 15:10:52 tlondon avahi-daemon[2630]: Joining mDNS multicast group on interface wlan0.IPv4 with address 10.11.14.42.
Nov 13 15:10:52 tlondon avahi-daemon[2630]: New relevant interface wlan0.IPv4 for mDNS.
Nov 13 15:10:52 tlondon avahi-daemon[2630]: Registering new address record for 10.11.14.42 on wlan0.IPv4.
Nov 13 15:10:52 tlondon dhclient: bound to 10.11.14.42 -- renewal in 20076 seconds.
Nov 13 15:10:53 tlondon nscd: 9989 Access Vector Cache (AVC) started
Nov 13 15:10:53 tlondon NetworkManager: <info>  Policy set 'Auto eth0' (eth0) as default for routing and DNS.
Nov 13 15:10:53 tlondon NetworkManager: <info>  (wlan0): device state change: 7 -> 8
Nov 13 15:10:53 tlondon NetworkManager: <info>  Activation (wlan0) successful, device activated.
Nov 13 15:10:53 tlondon NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
Nov 13 15:10:53 tlondon nm-dispatcher.action: Script '/etc/NetworkManager/dispatcher.d/04-iscsi' exited with error status 1.
Nov 13 15:10:53 tlondon ntpd[2551]: Listening on interface #9 wlan0, 10.11.14.42#123 Enabled
Nov 13 15:17:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 15:17:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 15:19:46 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
Nov 13 15:19:46 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
Nov 13 15:20:17 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake
Nov 13 15:20:17 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
Nov 13 15:20:17 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 15:25:46 tlondon kernel: mac80211-phy0: failed to remove key (0, 00:19:77:00:4f:f4) from hardware (-22)
Nov 13 15:25:46 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
Nov 13 15:25:46 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
Nov 13 15:25:47 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> 4-way handshake
Nov 13 15:25:47 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  4-way handshake -> group handshake
Nov 13 15:25:47 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 15:27:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 15:37:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 15:37:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed
Nov 13 15:47:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> group handshake
Nov 13 15:47:50 tlondon NetworkManager: <info>  (wlan0): supplicant connection state:  group handshake -> completed

Version-Release number of selected component (if applicable):
kernel-2.6.27.5-101.fc10.x86_64

How reproducible:
Regular, but unknown trigger

Steps to Reproduce:
1.
2.
3.
  
Actual results:


Expected results:


Additional info:
Comment 1 Tom London 2008-11-13 18:52:06 EST
Sorry, forgot system details: 

Thinkpad X61.
Comment 2 Bug Zapper 2008-11-26 00:21:11 EST
This bug appears to have been reported against 'rawhide' during the Fedora 10 development cycle.
Changing version to '10'.

More information and reason for this action is here:
http://fedoraproject.org/wiki/BugZappers/HouseKeeping
Comment 3 John W. Linville 2008-12-09 11:33:06 EST
While the DHCP requests are on-going, are you still able to use the network (surf the web, etc)?
Comment 4 Tom London 2008-12-09 12:06:22 EST
Yes, but I'm usually connected to wired also.

I'm now running rawhide (kernel-2.6.28-0.121.rc7.git5.fc11.x86_64) and haven't noticed this for a while....
Comment 5 John W. Linville 2009-01-13 14:28:29 EST
Closing based on comment 4...

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