Bug 485994

Summary:	dma-debug: fedora11:iwlagn 0000:03:00.0: DMA-API: device driver syncs DMA memory outside allocated range
Product:	[Fedora] Fedora	Reporter:	Joel <xurzwi2q1>
Component:	kernel	Assignee:	John W. Linville <linville>
Status:	CLOSED NEXTRELEASE	QA Contact:	Fedora Extras Quality Assurance <extras-qa>
Severity:	medium	Docs Contact:
Priority:	low
Version:	rawhide	CC:	dwmw2, kernel-maint, kmcmartin, quintela
Target Milestone:	---
Target Release:	---
Hardware:	i686
OS:	Linux
Whiteboard:
Fixed In Version:		Doc Type:	Bug Fix
Doc Text:		Story Points:	---
Clone Of:		Environment:
Last Closed:	2009-05-14 18:19:28 UTC	Type:	---
Regression:	---	Mount Type:	---
Documentation:	---	CRM:
Verified Versions:		Category:	---
oVirt Team:	---	RHEL 7.3 requirements from Atomic Host:
Cloudforms Team:	---	Target Upstream Version:
Embargoed:
Bug Depends On:
Bug Blocks:	487882

Description Joel 2009-02-17 20:30:28 UTC

Description of problem:
When attempting to attach to my company's wireless network, a stack trace is produced as network manager is setting up the connection.  The connection eventually is successfully established, but it soon disconnects after about a minute.

Version-Release number of selected component (if applicable):
kernel-2.6.29-0.124.rc5.fc11.i586

How reproducible:
First time I try doing wireless with Fedora 11 at work...will try again several times and will update the bug with findings.


Steps to Reproduce:
1. Click on Network Manager, then select "Connect to Hidden Wireless Network..."
2. Fill in the information for the wireless network (ie. SSID, authentication scheme, and userid/password)
3. Watch /var/log/messages as Network Manger is setting up the connection, and it'll dump the stack trace.
  
Actual results:
 NetworkManager: <info>  Activation (wlan0) starting connection 'IBM'
 NetworkManager: <info>  (wlan0): device state change: 3 -> 4
 NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
 NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
 NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
 NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
 NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
 NetworkManager: <info>  (wlan0): device state change: 4 -> 5
 NetworkManager: <info>  Activation (wlan0/wireless): access point 'IBM' has security, but secrets are required.
 NetworkManager: <info>  (wlan0): device state change: 5 -> 6
 NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
 NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) scheduled...
 NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) started...
 NetworkManager: <info>  (wlan0): device state change: 6 -> 4
 NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) scheduled...
 NetworkManager: <info>  Activation (wlan0) Stage 1 of 5 (Device Prepare) complete.
 NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) starting...
 NetworkManager: <info>  (wlan0): device state change: 4 -> 5
 NetworkManager: <info>  Activation (wlan0/wireless): connection 'IBM' has security, and secrets exist.  No new secrets needed.
 NetworkManager: <info>  Config: added 'ssid' value 'IBM'
 NetworkManager: <info>  Config: added 'scan_ssid' value '1'
 NetworkManager: <info>  Config: added 'key_mgmt' value 'IEEE8021X'
 NetworkManager: <info>  Config: added 'auth_alg' value 'LEAP'
 NetworkManager: <info>  Config: added 'identity' value 'joeldiaz.com'
 NetworkManager: <info>  Config: added 'password' value '<omitted>'
 NetworkManager: <info>  Config: added 'eap' value 'LEAP'
 NetworkManager: <info>  Activation (wlan0) Stage 2 of 5 (Device Configure) complete.
 NetworkManager: <info>  Config: set interface ap_scan to 1
 NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> scanning
 avahi-daemon[2344]: Withdrawing address record for fe80::21d:e0ff:fe03:71ab on wlan0.
 kernel: iwlagn 0000:03:00.0: PCI INT A disabled
 kernel: iwlagn 0000:03:00.0: PCI INT A -> GSI 17 (level, low) -> IRQ 17
 kernel: Registered led device: iwl-phy0:radio
 kernel: Registered led device: iwl-phy0:assoc
 kernel: Registered led device: iwl-phy0:RX
 kernel: Registered led device: iwl-phy0:TX
 kernel: ADDRCONF(NETDEV_UP): wlan0: link is not ready
 NetworkManager: <info>  (wlan0): supplicant connection state:  scanning -> associating
 kernel: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
 kernel: cfg80211: Calling CRDA for country: US
 NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
 ntpd[2574]: Deleting interface #5 wlan0, fe80::21d:e0ff:fe03:71ab#123, interface stats: received=0, sent=0, dropped=0, active_time=84 secs
 avahi-daemon[2344]: Registering new address record for fe80::21d:e0ff:fe03:71ab on wlan0.*.
 kernel: ------------[ cut here ]------------
 kernel: WARNING: at lib/dma-debug.c:511 check_sync+0x176/0x23e() (Not tainted)
 kernel: Hardware name: 7659A71
 kernel: iwlagn 0000:03:00.0: DMA-API: device driver syncs DMA memory outside allocated range [device address=0x0000000031f4c000] [allocation size=336 bytes] [sync offset=0] [sync size=8192]
 kernel: Modules linked in: fuse rfcomm sco bridge stp llc bnep l2cap sunrpc ip6t_REJECT nf_conntrack_ipv6 ip6table_filter ip6_tables ipv6 cpufreq_ondemand acpi_cpufreq dm_multipath uinput thinkpad_acpi hwmon snd_hda_codec_analog snd_hda_intel snd_hda_codec pcspkr joydev firewire_ohci firewire_core arc4 snd_hwdep i2c_i801 sdhci_pci snd_seq_dummy sdhci mmc_core ecb snd_seq_oss ricoh_mmc crc_itu_t yenta_socket rsrc_nonstatic snd_seq_midi_event snd_seq iTCO_wdt iTCO_vendor_support snd_seq_device iwlagn snd_pcm_oss snd_mixer_oss iwlcore snd_pcm rfkill snd_timer wmi lib80211 video snd btusb mac80211 e1000e output soundcore bluetooth cfg80211 snd_page_alloc i915 drm i2c_algo_bit i2c_core [last unloaded: microcode]
 kernel: Pid: 0, comm: swapper Not tainted 2.6.29-0.124.rc5.fc11.i586 #1
 kernel: Call Trace:
 kernel: [<c042e082>] warn_slowpath+0x77/0x9a
 kernel: [<c044be5f>] ? trace_hardirqs_off_caller+0x18/0xa3
 kernel: [<c044bef5>] ? trace_hardirqs_off+0xb/0xd
 kernel: [<c06d883d>] ? _spin_unlock_irqrestore+0x39/0x50
 kernel: [<c06515cc>] ? skb_queue_tail+0x14/0x32
 kernel: [<c053b0d6>] ? debug_check_no_obj_freed+0x6b/0x153
 kernel: [<c044ddde>] ? print_lock_contention_bug+0x11/0xb2
 kernel: [<c0651500>] ? sock_spd_release+0xa/0xf
 kernel: [<c053e0d1>] ? get_hash_bucket+0x26/0x2f
 kernel: [<c053e0d1>] ? get_hash_bucket+0x26/0x2f
 kernel: [<c044ddde>] ? print_lock_contention_bug+0x11/0xb2
 kernel: [<c053e0d1>] ? get_hash_bucket+0x26/0x2f
 kernel: [<c053e250>] check_sync+0x176/0x23e
 kernel: [<c053e449>] debug_dma_sync_single_range_for_cpu+0x29/0x34
 kernel: [<c053e449>] ? debug_dma_sync_single_range_for_cpu+0x29/0x34
 kernel: [<f8776268>] iwl_rx_handle+0x11a/0x366 [iwlagn]
 kernel: [<f87779fa>] ? iwl_irq_tasklet+0x19/0x563 [iwlagn]
 kernel: [<f8777daf>] iwl_irq_tasklet+0x3ce/0x563 [iwlagn]
 kernel: [<c063c181>] ? dma_issue_pending_all+0x91/0x99
 kernel: [<c0432695>] tasklet_action+0x85/0xf1
 kernel: [<c0432d1f>] __do_softirq+0x94/0x14d
 kernel: [<c0432c8b>] ? __do_softirq+0x0/0x14d
 kernel: <IRQ>  [<c046e4e2>] ? handle_edge_irq+0x0/0xee
 kernel: [<c04329ee>] ? irq_exit+0x44/0x72
 kernel: [<c04056f6>] ? do_IRQ+0xef/0x105
 kernel: [<c040422c>] ? common_interrupt+0x2c/0x40
 kernel: [<c044cc4a>] ? trace_hardirqs_on+0xb/0xd
 kernel: [<c0584b7c>] ? acpi_idle_enter_bm+0x254/0x2a8
 kernel: [<c044cc4a>] ? trace_hardirqs_on+0xb/0xd
 kernel: [<c044007b>] ? process_cpu_timer_create+0x10/0x11
 kernel: [<c0584b7e>] ? acpi_idle_enter_bm+0x256/0x2a8
 kernel: [<c063a12d>] ? menu_select+0x38/0x9f
 kernel: [<c0639727>] ? cpuidle_idle_call+0x60/0x99
 kernel: [<c0639727>] ? cpuidle_idle_call+0x60/0x99
 kernel: [<c0402d18>] ? cpu_idle+0x81/0xa1
 kernel: [<c06c7e86>] ? rest_init+0x4e/0x50
 kernel: ---[ end trace 559dc665d9cf0b41 ]---
 NetworkManager: <info>  (wlan0): supplicant connection state:  associated -> completed
 NetworkManager: <info>  Activation (wlan0/wireless) Stage 2 of 5 (Device Configure) successful.  Connected to wireless network 'IBM'.
 NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) scheduled.
 NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) started...
 NetworkManager: <info>  (wlan0): device state change: 5 -> 7
 NetworkManager: <info>  Activation (wlan0) Beginning DHCP transaction.
 NetworkManager: <info>  dhclient started with pid 3433
 NetworkManager: <info>  Activation (wlan0) Stage 3 of 5 (IP Configure Start) complete.
 dhclient: Internet Systems Consortium DHCP Client 4.1.0
 dhclient: Copyright 2004-2008 Internet Systems Consortium.
 dhclient: All rights reserved.
 dhclient: For info, please visit http://www.isc.org/sw/dhcp/
 dhclient: 
 NetworkManager: <info>  DHCP: device wlan0 state changed normal exit -> preinit
 dhclient: Listening on LPF/wlan0/00:1d:e0:03:71:ab
 dhclient: Sending on   LPF/wlan0/00:1d:e0:03:71:ab
 dhclient: Sending on   Socket/fallback
 dhclient: DHCPDISCOVER on wlan0 to 255.255.255.255 port 67 interval 5
 ntpd[2574]: Listening on interface #6 wlan0, fe80::21d:e0ff:fe03:71ab#123 Enabled
 kerneloops: Submitted 1 kernel oopses to www.kerneloops.org
 dhclient: DHCPOFFER from 9.44.138.1
 dhclient: DHCPREQUEST on wlan0 to 255.255.255.255 port 67
 dhclient: DHCPACK from 9.44.138.1
 dhclient: bound to 9.44.138.29 -- renewal in 17131 seconds.
 NetworkManager: <info>  DHCP: device wlan0 state changed preinit -> bound
 NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) scheduled...
 NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) started...
 NetworkManager: <info>    address 9.44.138.29
 NetworkManager: <info>    prefix 23 (255.255.254.0)
 NetworkManager: <info>    gateway 9.44.138.1
 NetworkManager: <info>    nameserver '9.0.6.1'
 NetworkManager: <info>    nameserver '9.0.7.1'
 NetworkManager: <info>    domain name 'raleigh.ibm.com'
 NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) scheduled...
 NetworkManager: <info>  Activation (wlan0) Stage 4 of 5 (IP Configure Get) complete.
 NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) started...
 avahi-daemon[2344]: Joining mDNS multicast group on interface wlan0.IPv4 with address 9.44.138.29.
 avahi-daemon[2344]: New relevant interface wlan0.IPv4 for mDNS.
 avahi-daemon[2344]: Registering new address record for 9.44.138.29 on wlan0.IPv4.
 NetworkManager: <info>  (wlan0): device state change: 7 -> 8
 NetworkManager: <info>  Policy set 'IBM' (wlan0) as default for routing and DNS.
 NetworkManager: <info>  Activation (wlan0) successful, device activated.
 NetworkManager: <info>  Activation (wlan0) Stage 5 of 5 (IP Configure Commit) complete.
 ntpd[2574]: Listening on interface #7 wlan0, 9.44.138.29#123 Enabled
 NetworkManager: <info>  (wlan0): supplicant connection state:  completed -> associating
 NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> disconnected
 NetworkManager: <info>  (wlan0): supplicant connection state:  disconnected -> associating
 NetworkManager: <info>  (wlan0): supplicant connection state:  associating -> associated
 NetworkManager: <info>  (wlan0): device state change: 8 -> 3
 NetworkManager: <info>  (wlan0): deactivating device (reason: 11).
 NetworkManager: <info>  wlan0: canceled DHCP transaction, dhcp client pid 3433
 NetworkManager: <WARN>  check_one_route(): (wlan0) error -34 returned from rtnl_route_del(): Sucess#012
 avahi-daemon[2344]: Withdrawing address record for 9.44.138.29 on wlan0.
 avahi-daemon[2344]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 9.44.138.29.
 avahi-daemon[2344]: Interface wlan0.IPv4 no longer relevant for mDNS.
 ntpd[2574]: Deleting interface #7 wlan0, 9.44.138.29#123, interface stats: received=2, sent=3, dropped=0, active_time=60 secs
 NetworkManager: <info>  Activation (eth0) starting connection 'Auto eth0'
 NetworkManager: <info>  (eth0): device state change: 3 -> 4

Expected results:
All of the above minus the ---[cut here]---- to ---[end trace ...]---

Additional info:
Machine is a ThinkPad T61 with Intel Corporation PRO/Wireless 4965 AG or AGN [Kedron] Network Connection (rev 61)

Comment 1 Joel 2009-02-17 20:50:03 UTC

Out of three attempts I get the same stack trace three times (with a reboot between each attempt).  So it's quite reproducible.  The most recent one: http://www.kerneloops.org/submitresult.php?number=238192.

Comment 2 John W. Linville 2009-05-12 15:25:29 UTC

Can you recreate this with a current (i.e. 2.6.30-rc4 or later) rawhide kernel?

Comment 3 Joel 2009-05-14 14:58:11 UTC

I was able to quickly try with 2.6.29.3-140 (latest Fedora11 kernel as of today), and cannot reproduce the issue any more.

Do you still want to know the result of a 2.6.30 kernel?

Comment 4 John W. Linville 2009-05-14 18:19:28 UTC

No, that's fine...thanks!