Received-SPF: pass (google.com: best guess record for domain of linux-kernel-owner@vger.kernel.org designates 209.132.180.67 as permitted sender) client-ip=209.132.180.67;
Date:   Thu, 27 Jun 2019 07:26:54 +0200
Message-ID: <s5htvcbr42p.wl-tiwai@suse.de>
From:   Takashi Iwai <tiwai@suse.de>
To:     Evan Green <evgreen@chromium.org>
Cc:     alsa-devel@alsa-project.org, Thomas Gleixner <tglx@linutronix.de>,
        "Amadeusz S*awi*ski" <amadeuszx.slawinski@linux.intel.com>,
        Greg Kroah-Hartman <gregkh@linuxfoundation.org>,
        Jaroslav Kysela <perex@perex.cz>,
        LKML <linux-kernel@vger.kernel.org>
Subject: Re: [PATCH] ALSA: hda: Use correct start/count for sysfs init
In-Reply-To: <CAE=gft664LfHU58Hm+Xtu-OYqiZT0Xsp3X2=U-Q+ApTsgj7z+g@mail.gmail.com>
References: <20190625215418.17548-1-evgreen@chromium.org>
        <s5himsssqe8.wl-tiwai@suse.de>
        <CAE=gft62iv=V=auOhocRRfPV2Tuc2WiRYJOH5_M+HkM0qH-Jhw@mail.gmail.com>
        <s5hy31oqc8a.wl-tiwai@suse.de>
        <CAE=gft664LfHU58Hm+Xtu-OYqiZT0Xsp3X2=U-Q+ApTsgj7z+g@mail.gmail.com>
User-Agent: Wanderlust/2.15.9 (Almost Unreal) SEMI/1.14.6 (Maruoka)
 FLIM/1.14.9 (=?UTF-8?B?R29qxY0=?=) APEL/10.8 Emacs/25.3
 (x86_64-suse-linux-gnu) MULE/6.0 (HANACHIRUSATO)
MIME-Version: 1.0 (generated by SEMI 1.14.6 - "Maruoka")
Content-Type: text/plain; charset=US-ASCII
Sender: linux-kernel-owner@vger.kernel.org
Precedence: bulk

On Wed, 26 Jun 2019 23:59:33 +0200,
Evan Green wrote:
> 
> On Wed, Jun 26, 2019 at 2:16 PM Takashi Iwai <tiwai@suse.de> wrote:
> >
> > On Wed, 26 Jun 2019 22:34:28 +0200,
> > Evan Green wrote:
> > >
> > > On Wed, Jun 26, 2019 at 1:27 AM Takashi Iwai <tiwai@suse.de> wrote:
> > > >
> > > > On Tue, 25 Jun 2019 23:54:18 +0200,
> > > > Evan Green wrote:
> > > > >
> > > > > The normal flow through the widget sysfs codepath is that
> > > > > snd_hdac_refresh_widgets() is called once without the sysfs bool set
> > > > > to set up codec->num_nodes and friends, then another time with the
> > > > > bool set to actually allocate all the sysfs widgets. However, during
> > > > > the first time allocation, hda_widget_sysfs_reinit() ignores the new
> > > > > num_nodes passed in via parameter and just calls hda_widget_sysfs_init(),
> > > > > using whatever was in codec->num_nodes before the update. This is not
> > > > > correct in cases where num_nodes changes. Here's an example:
> > > > >
> > > > > Sometime earlier:
> > > > > snd_hdac_refresh_widgets(hdac, false)
> > > > >   sets codec->num_nodes to 2, widgets is still not allocated
> > > > >
> > > > > Now:
> > > > > snd_hdac_refresh_widgets(hdac, true)
> > > > >   hda_widget_sysfs_reinit(num_nodes=7)
> > > > >     hda_widget_sysfs_init()
> > > > >       widget_tree_create()
> > > > >         alloc(codec->num_nodes) // this is still 2
> > > > >   codec->num_nodes = 7
> > > > >
> > > > > Pass num_nodes and start_nid down into widget_tree_create() so that
> > > > > the right number of nodes are allocated in all cases.
> > > > >
> > > > > Signed-off-by: Evan Green <evgreen@chromium.org>
> > > >
> > > > Thanks for the patch.  That's indeed a problem, but I guess a simpler
> > > > approach is just to return if sysfs didn't exist.  If the sysfs
> > > > entries aren't present at the second call with sysfs=true, it implies
> > > > that the codec object will be exposed anyway later, and the sysfs will
> > > > be created there.  So, something like below would work instead?
> > >
> > > Hi Takashi,
> > > Thanks for taking a look. I'm not sure you'd want to do that because
> > > then you end up returning from sysfs_reinit without having allocated
> > > any of the sysfs widgets. You'd be relying on the implicit behavior
> > > that another call to init is coming later (despite having updated
> > > num_nodes and start node), which is difficult to follow and easy to
> > > break. In my opinion the slight bit of extra diffs is well worth the
> > > clarity of having widget_tree_create always allocate the correct
> > > start/count.
> >
> > Well, skipping is the right behavior, actually.  The whole need of the
> > refresh function is just to refresh the widget list, and the current
> > behavior to create a sysfs is rather superfluous.  This action has
> > never been used, so better to get removed for avoiding misuse.
> 
> Whoops, I sent out a v2 before seeing this. Sorry to jump the gun like that.
> 
> I don't quite follow what you mean by "current behavior to create a
> sysfs is rather superfluous". Do you think we could delete this
> conditional in re-init altogether? I wasn't totally sure, but it
> seemed like if the conditional could possibly be activated, then the
> behavior was also incorrect.
> 
> Actually, couldn't this happen if something goes through
> widget_tree_free(), then something else goes through a reinit()? If
> the reinit call doesn't have the same number of widgets as before,
> then you'd need my patch to avoid initing with the wrong array size.

I meant that hda_widget_sysfs_reinit() creates sysfs files if they
weren't present. hda_widget_sysfs_reinit() should do nothing if the
sysfs wasn't created beforehand -- like my suggested patch does.

After that change, "bool sysfs" argument can be de even dropped from
snd_hdac_refresh_widgets().  The very first call of this function is
with sysfs=false, but at this point, codec->widgets=NULL, so reinit()
would just skip.  All later calls are with sysfs=true.


> > > Actually, in looking at the widget lock patch, I don't think it's
> > > sufficient either. It adds a lock around sysfs_reinit, but the setting
> > > of codec->num_nodes and codec->start_nid is unprotected by the lock.
> > > So you could have the two threads politely serialize through
> > > sysfs_reinit, but then get reordered before setting codec->num_nodes,
> > > landing you with an array whose length doesn't match num_nodes.
> >
> > The usage of snd_hdac_refresh_widgets() is supposed to be done only at
> > the codec probe phase, hence there is no lock done in the core code;
> > IOW, any concurrent access has to be protected in the caller side in
> > general.
> >
> > Have you actually seen such concurrent accesses?  If yes, that's a
> > problem in the usage.
> 
> I got into staring at this code while trying to debug a KASAN
> use-after-free in this code. I found the issue in this patch by
> inspection, so I'm not 100% sure if it could ever happen. My
> use-after-free appears to be fixed by the new widget_lock (I didn't
> have that at the time), but I think at least my other patch in v2 is
> necessary to make the widget_lock work correctly.
>
> I'll document my use-after-free here in case it helps. The cleaned up
> stacks racing to mess with sysfs look like this:
(snip)

OK, this information helps a lot for understanding the problem.
The parallel initialization hasn't been considered much, so far.
Let me check that in detail later.  I'll postspone your v2 patch for a
while.


thanks,

Takashi


> Thread A:
>     [   28.296049]  hda_widget_sysfs_reinit+0x184/0x552 [snd_hda_core]
>     [   28.526242]  snd_hdac_refresh_widgets+0x106/0x39c [snd_hda_core]
>     [   28.542238]  hdac_hdmi_dev_probe+0x19a8/0x1af5 [snd_soc_hdac_hdmi]
>     [   28.586440]  really_probe+0x3f4/0x58e
>     [   28.590563]  driver_probe_device+0xb1/0x1db
>     [   28.595266]  __driver_attach+0x14f/0x1f7
>     [   28.599684]  bus_for_each_dev+0x146/0x1a1
>     [   28.621944]  bus_add_driver+0x349/0x4f6
>     [   28.626266]  driver_register+0x1cb/0x328
>     [   28.634411]  do_one_initcall+0x3ea/0x903
>     [   28.738132]  do_init_module+0x1f9/0x56d
>     [   28.742463]  load_module+0x74d6/0x8d0a
>     [   28.783270]  __se_sys_finit_module+0x1d6/0x244
> 
> Thread B:
>     Thread B:
>     /mnt/host/source/src/third_party/kernel/v4.19/sound/hda/hdac_sysfs.c:423
> hda_widget_sysfs_init+0x345/0x41d
>     [snd_hda_core]
>     [   29.178793]  snd_hdac_device_register+0x20/0x3a [snd_hda_core]
>     [   29.185351]  snd_hdac_ext_bus_device_init+0x151/0x240 [snd_hda_ext_core]
>     [   29.211982]  hda_codec_probe_bus+0x298/0x35a [snd_sof_intel_hda]
>     [   29.228663]  hda_dsp_probe+0x15aa/0x1da9 [snd_sof_intel_hda_common]
>     [   29.257109]  sof_probe_work+0x120/0x930 [snd_sof]
>     [   29.284174]  process_one_work+0x90b/0x11b6
>     [   29.318222]  worker_thread+0xad5/0xdcc
>     [   29.336172]  kthread+0x34e/0x35e
> 
> The original use-after-free:
>     [   27.822086]
> ==================================================================
>     [   27.830522] BUG: KASAN: use-after-free in
> add_widget_node+0xc6/0xf3 [snd_hda_core]
>     [   27.839073] Write of size 8 at addr ffff888405d72f10 by task
> kworker/2:1/67
>     [   27.846940]
>     [   27.848645] CPU: 2 PID: 67 Comm: kworker/2:1 Not tainted 4.19.44 #93
>     [   27.855832] Hardware name: Google Hatch/Hatch, BIOS
> Google_Hatch.12225.0.2019_05_24_1436 05/24/2019
>     [   27.866009] Workqueue: events sof_probe_work [snd_sof]
>     [   27.871819] Call Trace:
>     [   27.874612]  dump_stack+0x122/0x1b5
>     [   27.878574]  ? do_raw_spin_lock+0xbd/0x1e9
>     [   27.883216]  ? show_regs_print_info+0x5/0x5
>     [   27.887962]  ? log_buf_vmcoreinfo_setup+0x131/0x131
>     [   27.893483]  ? _raw_spin_lock_irqsave+0xc5/0xfa
>     [   27.898620]  print_address_description+0x88/0x271
>     [   27.903959]  ? add_widget_node+0xc6/0xf3 [snd_hda_core]
>     [   27.909876]  kasan_report+0x274/0x29e
>     [   27.914032]  add_widget_node+0xc6/0xf3 [snd_hda_core]
>     [   27.919759]  hda_widget_sysfs_init+0x2b8/0x3a5 [snd_hda_core]
>     [   27.926283]  snd_hdac_device_register+0x20/0x3a [snd_hda_core]
>     [   27.932897]  snd_hdac_ext_bus_device_init+0x151/0x240 [snd_hda_ext_core]
>     [   27.940485]  ? snd_hdac_ext_bus_exit+0x44/0x44 [snd_hda_ext_core]
>     [   27.947381]  ? kmem_cache_alloc_trace+0x11d/0x19a
>     [   27.952712]  ? hda_codec_probe_bus+0x283/0x35a [snd_sof_intel_hda]
>     [   27.959705]  hda_codec_probe_bus+0x298/0x35a [snd_sof_intel_hda]
>     [   27.966517]  ? 0xffffffffa05c0000
>     [   27.970288]  ? snd_sof_pci_update_bits+0x53/0x64 [snd_sof]
>     [   27.976515]  hda_dsp_probe+0x15df/0x1de5 [snd_sof_intel_hda_common]
>     [   27.983619]  ? print_irqtrace_events+0x223/0x223
>     [   27.988861]  ? hda_dsp_get_status+0x1ba/0x1ba [snd_sof_intel_hda_common]
>     [   27.996433]  ? reacquire_held_locks+0x373/0x373
>     [   28.001570]  ? trace_hardirqs_on_thunk+0x1a/0x1c
>     [   28.006817]  ? __lock_is_held+0x61/0x11e
>     [   28.011277]  sof_probe_work+0x120/0x930 [snd_sof]
>     [   28.016617]  ? snd_sof_device_probe+0x47f/0x47f [snd_sof]
>     [   28.022736]  ? rcu_read_lock_sched_held+0x140/0x22a
>     [   28.028260]  ? __bpf_trace_rcu_utilization+0xa/0xa
>     [   28.033689]  ? read_word_at_a_time+0x12/0x18
>     [   28.038539]  process_one_work+0x90b/0x11b6
>     [   28.043210]  ? worker_detach_from_pool+0x1fa/0x1fa
>     [   28.048636]  ? is_mmconf_reserved+0x3bc/0x3bc
>     [   28.053577]  ? lock_downgrade+0x60a/0x60a
>     [   28.058133]  ? lockdep_hardirqs_on+0x6d8/0x6d8
>     [   28.063163]  ? _raw_spin_unlock_irq+0x83/0x100
>     [   28.068208]  ? do_raw_spin_lock+0xbd/0x1e9
>     [   28.068549] cr50_spi spi-PRP0001:01: SPI transfer timed out
>     [   28.072842]  worker_thread+0xad5/0xdcc
>     [   28.072861]  ? _raw_spin_unlock+0xfa/0xfa
>     [   28.072868]  ? _raw_spin_lock_irqsave+0xc5/0xfa
>     [   28.072898]  ? pr_cont_work+0xe6/0xe6
>     [   28.072905]  kthread+0x34e/0x35e
>     [   28.072914]  ? pr_cont_work+0xe6/0xe6
>     [   28.072922]  ? kthread_blkcg+0xa2/0xa2
>     [   28.109396]  ret_from_fork+0x24/0x50
>     [   28.113433]
>     [   28.115130] Allocated by task 67:
>     [   28.118894]  kmem_cache_alloc_trace+0x11d/0x19a
>     [   28.124038]  hda_widget_sysfs_init+0x8a/0x3a5 [snd_hda_core]
>     [   28.130444]  snd_hdac_device_register+0x20/0x3a [snd_hda_core]
>     [   28.137047]  snd_hdac_ext_bus_device_init+0x151/0x240 [snd_hda_ext_core]
>     [   28.144620]  hda_codec_probe_bus+0x298/0x35a [snd_sof_intel_hda]
>     [   28.151417]  hda_dsp_probe+0x15df/0x1de5 [snd_sof_intel_hda_common]
>     [   28.158508]  sof_probe_work+0x120/0x930 [snd_sof]
>     [   28.163829]  process_one_work+0x90b/0x11b6
>     [   28.168457]  worker_thread+0xad5/0xdcc
>     [   28.172693]  kthread+0x34e/0x35e
>     [   28.176349]  ret_from_fork+0x24/0x50
>     [   28.180388]
>     [   28.182078] Freed by task 2983:
>     [   28.185639]  kfree+0x239/0x723
>     [   28.189106]  hda_widget_sysfs_reinit+0x47e/0x50a [snd_hda_core]
>     [   28.195824]  snd_hdac_refresh_widgets+0xf8/0x2a0 [snd_hda_core]
>     [   28.202527]  hdac_hdmi_dev_probe+0x19a8/0x1af5 [snd_soc_hdac_hdmi]
>     [   28.209514]  really_probe+0x237/0x58e
>     [   28.213673]  driver_probe_device+0xb1/0x1db
>     [   28.218415]  __driver_attach+0x14f/0x1f7
>     [   28.222857]  bus_for_each_dev+0x146/0x1a1
>     [   28.227402]  bus_add_driver+0x349/0x4f6
>     [   28.231736]  driver_register+0x1cb/0x328
>     [   28.236164]  do_one_initcall+0x3ea/0x903
>     [   28.240611]  do_init_module+0x1f9/0x56d
>     [   28.244971]  load_module+0x74d6/0x8d0a
>     [   28.249218]  __se_sys_finit_module+0x1d6/0x244
>     [   28.254250]  do_syscall_64+0xcd/0x120
>     [   28.258389]  entry_SYSCALL_64_after_hwframe+0x49/0xbe
>     [   28.264095]
>     [   28.265794] The buggy address belongs to the object at ffff888405d72f08
>     [   28.265794]  which belongs to the cache kmalloc-32 of size 32
>     [   28.279733] The buggy address is located 8 bytes inside of
>     [   28.279733]  32-byte region [ffff888405d72f08, ffff888405d72f28)
>     [   28.292627] The buggy address belongs to the page:
>     [   28.298037] page:ffffea0010175c80 count:1 mapcount:0
> mapping:ffff88840cc0c5c0 index:0x0 compound_mapcount: 0
>     [   28.308498] cr50_spi spi-PRP0001:01: SPI transfer timed out
>     [   28.309102] flags: 0x8000000000008100(slab|head)
>     [   28.309111] raw: 8000000000008100 ffffea0010175c08
> ffffea00102ef108 ffff88840cc0c5c0
>     [   28.329340] raw: 0000000000000000 0000000000150015
> 00000001ffffffff 0000000000000000
>     [   28.338091] page dumped because: kasan: bad access detected
>     [   28.344381]
>     [   28.346079] Memory state around the buggy address:
>     [   28.351497]  ffff888405d72e00: fc fc fc fc fc fc fc fc fc fc fc
> fc fc fc fc fc
>     [   28.359663]  ffff888405d72e80: fc fc fc fc fc fc fc fc fc fc fc
> fc fc fc fc fc
>     [   28.367824] >ffff888405d72f00: fc fb fb fb fb fc fc fc fc fc fc
> fc fc fc fc fc
>     [   28.375987]                          ^
>     [   28.380236]  ffff888405d72f80: fc fc fc fc fc fc fc fc fc fc fc
> fc fc fc fc fc
>     [   28.388401]  ffff888405d73000: fc fc fc fc fc fc fc fc fc fc fc
> fc fc fc fc fc
> 
> Again, sorry about prematurely sending out the v2. This patch hasn't
> changed, so feel free to ignore that part of the v2. The other patch
> though is new, and I think is needed regardless of the state of this
> patch.
> 
> -Evan
> 
> >
> >
> > thanks,
> >
> > Takashi
> >
> > >
> > > Let me craft up an additional patch to fix the locking.
> > > -Evan
> > >
> > > >
> > > >
> > > > thanks,
> > > >
> > > > Takashi
> > > >
> > > > --- a/sound/hda/hdac_sysfs.c
> > > > +++ b/sound/hda/hdac_sysfs.c
> > > > @@ -428,7 +428,7 @@ int hda_widget_sysfs_reinit(struct hdac_device *codec,
> > > >         int i;
> > > >
> > > >         if (!codec->widgets)
> > > > -               return hda_widget_sysfs_init(codec);
> > > > +               return 0;
> > > >
> > > >         tree = kmemdup(codec->widgets, sizeof(*tree), GFP_KERNEL);
> > > >         if (!tree)
> > >
>