4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Sander Eikelenboom]

Hi,

I encountered this splat with 4.12-RC2.
--

Sander

[  119.021594] BUG: scheduling while atomic: irq/47-iwlwifi/517/0x00000200
[  119.021604] Modules linked in: xt_tcpudp ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 nf_conntrack_ipv6 nf_defrag_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_raw ip6table_security ip6table_mangle iptable_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_security iptable_mangle ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter ip_tables x_tables rfcomm bnep binfmt_misc arc4 iTCO_wdt iTCO_vendor_support uvcvideo videobuf2_vmalloc videobuf2_memops videobuf2_v4l2 videobuf2_core videodev intel_rapl cdc_mbim iwlmvm x86_pkg_temp_thermal intel_powerclamp mac80211 media cdc_wdm btusb coretemp cdc_ncm kvm_intel usbnet mii cdc_acm iwlwifi kvm btintel joydev pcspkr serio_raw cfg802
 11 snd_hda_codec_hdmi
[  119.021701]  bluetooth lpc_ich snd_hda_codec_realtek snd_hda_codec_generic shpchp sg ecdh_generic snd_hda_intel thinkpad_acpi snd_hda_codec snd_hwdep snd_hda_core snd_pcm snd_timer nvram snd soundcore evdev tpm_tis tpm_tis_core tpm algif_skcipher af_alg crct10dif_pclmul crc32_pclmul crc32c_intel ghash_clmulni_intel rtsx_pci_sdmmc mmc_core aesni_intel aes_x86_64 crypto_simd cryptd glue_helper psmouse i2c_i801 sd_mod ehci_pci ehci_hcd e1000e rtsx_pci mfd_core ptp xhci_pci pps_core xhci_hcd
[  119.021759] CPU: 1 PID: 517 Comm: irq/47-iwlwifi Not tainted 4.12.0-rc2-t440s-20170522+ #1
[  119.021763] Hardware name: LENOVO 20AQS03H00/20AQS03H00, BIOS GJET91WW (2.41 ) 09/21/2016
[  119.021766] Call Trace:
[  119.021778]  ? dump_stack+0x5c/0x84
[  119.021784]  ? __schedule_bug+0x4c/0x70
[  119.021792]  ? __schedule+0x496/0x5c0
[  119.021798]  ? schedule+0x2d/0x80
[  119.021804]  ? schedule_preempt_disabled+0x5/0x10
[  119.021810]  ? __mutex_lock.isra.0+0x18e/0x4c0
[  119.021817]  ? __wake_up+0x2f/0x50
[  119.021833]  ? cfg80211_sched_scan_results+0x19/0x60 [cfg80211]
[  119.021844]  ? cfg80211_sched_scan_results+0x19/0x60 [cfg80211]
[  119.021859]  ? iwl_mvm_rx_lmac_scan_iter_complete_notif+0x17/0x30 [iwlmvm]
[  119.021869]  ? iwl_pcie_rx_handle+0x2a9/0x7e0 [iwlwifi]
[  119.021878]  ? iwl_pcie_irq_handler+0x17c/0x730 [iwlwifi]
[  119.021884]  ? irq_forced_thread_fn+0x60/0x60
[  119.021887]  ? irq_thread_fn+0x16/0x40
[  119.021892]  ? irq_thread+0x109/0x180
[  119.021896]  ? wake_threads_waitq+0x30/0x30
[  119.021901]  ? kthread+0xf2/0x130
[  119.021905]  ? irq_thread_dtor+0x90/0x90
[  119.021910]  ? kthread_create_on_node+0x40/0x40
[  119.021915]  ? ret_from_fork+0x26/0x40

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Johannes Berg]

On Mon, 2017-05-22 at 12:36 +0200, Sander Eikelenboom wrote:
> Hi,
> 
> I encountered this splat with 4.12-RC2.

Ugh, yeah, I should've seen that in the review.

Arend, please take a look at this. cfg80211_sched_scan_results() cannot
sleep, so you can't rtnl_lock() in there. Looks like you can just rely
on RCU though?

johannes

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Arend van Spriel]

On 5/22/2017 12:57 PM, Johannes Berg wrote:
> On Mon, 2017-05-22 at 12:36 +0200, Sander Eikelenboom wrote:
>> Hi,
>>
>> I encountered this splat with 4.12-RC2.
> 
> Ugh, yeah, I should've seen that in the review.
> 
> Arend, please take a look at this. cfg80211_sched_scan_results() cannot
> sleep, so you can't rtnl_lock() in there. Looks like you can just rely
> on RCU though?

I see. I think you are right on RCU. Don't have the code in front of me 
now, but I think the lookup has an ASSERT_RTNL. Will look into it after 
my monday meeting :-p

Regards,
Arend

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Arend Van Spriel]

On 22-5-2017 14:09, Arend van Spriel wrote:
> On 5/22/2017 12:57 PM, Johannes Berg wrote:
>> On Mon, 2017-05-22 at 12:36 +0200, Sander Eikelenboom wrote:
>>> Hi,
>>>
>>> I encountered this splat with 4.12-RC2.
>>
>> Ugh, yeah, I should've seen that in the review.
>>
>> Arend, please take a look at this. cfg80211_sched_scan_results() cannot
>> sleep, so you can't rtnl_lock() in there. Looks like you can just rely
>> on RCU though?
> 
> I see. I think you are right on RCU. Don't have the code in front of me
> now, but I think the lookup has an ASSERT_RTNL. Will look into it after
> my monday meeting :-p

I realized I have a laptop lying around with intel 3160 wifi chip and
tried to reproduce the issue. Did not run into the splat running
4.12-rc1 from wireless-drivers-next repo. I did not get the email from
Sander so I don't know any details.

Here is what I changed based on the info Johannes provided. Can you
please check if this get rid of the splat and let me know.

Regards,
Arend
---
diff --git a/net/wireless/scan.c b/net/wireless/scan.c
index 14d5f0c..04833bb 100644
--- a/net/wireless/scan.c
+++ b/net/wireless/scan.c
@@ -322,9 +322,7 @@ static void cfg80211_del_sched_scan_req(struct
cfg80211_regi
 {
        struct cfg80211_sched_scan_request *pos;

-       ASSERT_RTNL();

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Johannes Berg]

Hi Arend,

Sorry, I forgot that the original message wasn't Cc'ed to the wireless
list, only netdev.

> +++ b/net/wireless/scan.c
> @@ -322,9 +322,7 @@ static void cfg80211_del_sched_scan_req(struct
> cfg80211_regi
>  {
>         struct cfg80211_sched_scan_request *pos;
> 
> -       ASSERT_RTNL();
> -
> -       list_for_each_entry(pos, &rdev->sched_scan_req_list, list) {
> +       list_for_each_entry_rcu(pos, &rdev->sched_scan_req_list,
> list) {

[snip]

This looks fine, but perhaps in the above we should have some kind of
locking assertion, e.g.

	WARN_ON_ONCE(!rcu_read_lock_held() && !lockdep_rtnl_is_held());

johannes

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Arend Van Spriel]

On 22-5-2017 23:04, Johannes Berg wrote:
> Hi Arend,
> 
> Sorry, I forgot that the original message wasn't Cc'ed to the wireless
> list, only netdev.

That explains. Not subscribed to that.

>> +++ b/net/wireless/scan.c
>> @@ -322,9 +322,7 @@ static void cfg80211_del_sched_scan_req(struct
>> cfg80211_regi
>>  {
>>         struct cfg80211_sched_scan_request *pos;
>>
>> -       ASSERT_RTNL();
>> -
>> -       list_for_each_entry(pos, &rdev->sched_scan_req_list, list) {
>> +       list_for_each_entry_rcu(pos, &rdev->sched_scan_req_list,
>> list) {
> 
> [snip]
> 
> This looks fine, but perhaps in the above we should have some kind of
> locking assertion, e.g.
> 
> 	WARN_ON_ONCE(!rcu_read_lock_held() && !lockdep_rtnl_is_held());

Thought about something like this after sending the email. So there are
two call sites. One for scheduled scan results notification and one in
scheduled scan stop scenario. So for the latter it is not needed to use
the rcu_read_lock() as it should have RTNL lock hence the two checks above?

Will create a formal patch.

Regards,
Arend

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Johannes Berg]

On Tue, 2017-05-23 at 09:19 +0200, Arend Van Spriel wrote:
> 
> > 	WARN_ON_ONCE(!rcu_read_lock_held() && !lockdep_rtnl_is_held());
> 
> Thought about something like this after sending the email. So there
> are two call sites. One for scheduled scan results notification and
> one in scheduled scan stop scenario. So for the latter it is not
> needed to use the rcu_read_lock() as it should have RTNL lock hence
> the two checks above?

Right. The latter can't even really use rcu_read_lock() since it also
wants to modify the list, and that's not sufficient protection for
modifying.

Thanks!

johannes

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Arend Van Spriel]

On 23-5-2017 9:22, Johannes Berg wrote:
> On Tue, 2017-05-23 at 09:19 +0200, Arend Van Spriel wrote:
>>
>>> 	WARN_ON_ONCE(!rcu_read_lock_held() && !lockdep_rtnl_is_held());
>>
>> Thought about something like this after sending the email. So there
>> are two call sites. One for scheduled scan results notification and
>> one in scheduled scan stop scenario. So for the latter it is not
>> needed to use the rcu_read_lock() as it should have RTNL lock hence
>> the two checks above?
> 
> Right. The latter can't even really use rcu_read_lock() since it also
> wants to modify the list, and that's not sufficient protection for
> modifying.

Hence the name ;-)

Regards,
Arend

Re: 4.12-RC2 BUG: scheduling while atomic: irq/47-iwlwifi

[Sander Eikelenboom]

On 22/05/17 23:02, Arend Van Spriel wrote:
> 
> 
> On 22-5-2017 14:09, Arend van Spriel wrote:
>> On 5/22/2017 12:57 PM, Johannes Berg wrote:
>>> On Mon, 2017-05-22 at 12:36 +0200, Sander Eikelenboom wrote:
>>>> Hi,
>>>>
>>>> I encountered this splat with 4.12-RC2.
>>>
>>> Ugh, yeah, I should've seen that in the review.
>>>
>>> Arend, please take a look at this. cfg80211_sched_scan_results() cannot
>>> sleep, so you can't rtnl_lock() in there. Looks like you can just rely
>>> on RCU though?
>>
>> I see. I think you are right on RCU. Don't have the code in front of me
>> now, but I think the lookup has an ASSERT_RTNL. Will look into it after
>> my monday meeting :-p
> 
> I realized I have a laptop lying around with intel 3160 wifi chip and
> tried to reproduce the issue. Did not run into the splat running
> 4.12-rc1 from wireless-drivers-next repo. I did not get the email from
> Sander so I don't know any details.
> 
> Here is what I changed based on the info Johannes provided. Can you
> please check if this get rid of the splat and let me know.

Hi Arend,

I ran your patch today, so far no issues.

--
Sander


> Regards,
> Arend
> ---
> diff --git a/net/wireless/scan.c b/net/wireless/scan.c
> index 14d5f0c..04833bb 100644
> --- a/net/wireless/scan.c
> +++ b/net/wireless/scan.c
> @@ -322,9 +322,7 @@ static void cfg80211_del_sched_scan_req(struct
> cfg80211_regi
>  {
>         struct cfg80211_sched_scan_request *pos;
> 
> -       ASSERT_RTNL();
> -
> -       list_for_each_entry(pos, &rdev->sched_scan_req_list, list) {
> +       list_for_each_entry_rcu(pos, &rdev->sched_scan_req_list, list) {
>                 if (pos->reqid == reqid)
>                         return pos;
>         }
> @@ -398,13 +396,13 @@ void cfg80211_sched_scan_results(struct wiphy
> *wiphy, u64
>         trace_cfg80211_sched_scan_results(wiphy, reqid);
>         /* ignore if we're not scanning */
> 
> -       rtnl_lock();
> +       rcu_read_lock();
>         request = cfg80211_find_sched_scan_req(rdev, reqid);
>         if (request) {
>                 request->report_results = true;
>                 queue_work(cfg80211_wq, &rdev->sched_scan_res_wk);
>         }
> -       rtnl_unlock();
> +       rcu_read_unlock();
>  }
>  EXPORT_SYMBOL(cfg80211_sched_scan_results);
> 
>