Hey Bryant,
After spending more time reviewing fs/configfs code today, I've
convenienced myself this is a long standing configfs race between
config_group shutdown and symlink creation.
Have you been able to verify the particular scenario is in fact what's
happening..?
On Tue, 2017-05-30 at 23:26 -0700, Nicholas A. Bellinger wrote:
> On Fri, 2017-05-26 at 09:51 -0500, Bryant G. Ly wrote:
> > On 5/26/17 1:51 AM, Nicholas A. Bellinger wrote:
> >
> > > Hey Bryant,
> > >
> > > On Wed, 2017-05-24 at 13:34 -0500, Bryant G. Ly wrote:
> > >> Hi Nick,
> > >>
> > >> We are seeing the below kernel crash with a block backstore.
> > >>
> > >> The steps to reproduce are: Discovered a new iSCSI volume, created a new ibmvscsis instance, mapped it.
> > >>
> > > Mmmm, based upon the INQUIRY string this looks like a PSCSI backstore,
> > > yes..?
> >
> > No, its a block backstore, we dont support PSCSI via our management console (Novalink).
> > I don't know why the inquiry string would show it as a PSCSI backstore.
> >
>
> Ah, was getting confused by the initiator INQUIRY strings..
>
> > >
> > > So a iscsi initiator provided struct scsi_device is registered
> > > with /sys/kernel/config/target/core/pscsi_*, and then mapped to a
> > > ibmvscsis lun, right..?
> > >
> > > Btw looking at 4.8.17, nothing has changed since Jan
> > > in /drivers/target/, and certainly nothing related to configfs operation
> > > well before that..
> > >
> > > I assume this not a new regression, right..?
> >
> > We just started testing with iSCSI, so we did not see it before.
> >
> > >> [ 7872.359650] scsi host6: iSCSI Initiator over TCP/IP
> > >> [ 7872.621777] scsi 6:0:0:0: Direct-Access IBM 2145 0000 PQ: 0 ANSI: 6
> > >> [ 7872.665105] sd 6:0:0:0: Attached scsi generic sg14 type 0
> > >> [ 7872.665600] sd 6:0:0:0: [sdg] 2097152 512-byte logical blocks: (1.07 GB/1.00 GiB)
> > >> [ 7872.666986] sd 6:0:0:0: [sdg] Write Protect is off
> > >> [ 7872.666990] sd 6:0:0:0: [sdg] Mode Sense: 97 00 10 08
> > >> [ 7872.667691] sd 6:0:0:0: [sdg] Write cache: disabled, read cache: enabled, supports DPO and FUA
> > >> [ 7872.680928] sd 6:0:0:0: [sdg] Attached SCSI disk
> > >> [ 7877.289863] rpadlpar_io: slot U8247.22L.212A91A-V1-C8 added
> > >> [ 7879.893760] ------------[ cut here ]------------
> > >> [ 7879.893768] WARNING: CPU: 15 PID: 17585 at ./include/linux/kref.h:46 config_item_get+0x7c/0x90 [configfs]
> > >> [ 7879.893768] Modules linked in: target_core_pscsi target_core_file target_core_iblock rpadlpar_io rpaphp ip6table_raw xt_CT xt_mac xt_tcpudp xt_comment xt_physdev xt_set ip_set_hash_net ip_set iscsi_target_mod iptable_raw dccp_diag dccp tcp_diag udp_diag inet_diag unix_diag af_packet_diag netlink_diag openvswitch nf_nat_ipv6 libcrc32c target_core_user uio binfmt_misc pseries_rng ibmvmc(O) vmx_crypto rtc_generic xt_conntrack nf_nat_ftp nf_conntrack_ftp nf_conntrack_netlink nfnetlink nf_conntrack_netbios_ns nf_conntrack_broadcast nf_conntrack_ipv6 nf_defrag_ipv6 nbd ipt_REJECT nf_reject_ipv4 ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_filter ip_tables ip6table_filter ip6_tables ebtables x_tables br_netfilter
> > >> [ 7879.893797] bridge stp llc ib_iser rdma_cm iw_cm ib_cm ib_core iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi autofs4 ses enclosure scsi_transport_sas ibmvscsis target_core_mod configfs ibmvscsi ibmveth(O) qla2xxx scsi_transport_fc ipr
> > >> [ 7879.893811] CPU: 15 PID: 17585 Comm: targetcli Tainted: G O 4.8.17-customv2.22 #12
> > >> [ 7879.893812] task: c00000018a0d3400 task.stack: c0000001f3b40000
> > >> [ 7879.893813] NIP: d000000002c664ec LR: d000000002c60980 CTR: c000000000b70870
> > >> [ 7879.893814] REGS: c0000001f3b43810 TRAP: 0700 Tainted: G O (4.8.17-customv2.22)
> > >> [ 7879.893815] MSR: 8000000000029033 <SF,EE,ME,IR,DR,RI,LE> CR: 28222242 XER: 00000000
> > >> [ 7879.893820] CFAR: d000000002c664bc SOFTE: 1
> > >> GPR00: d000000002c60980 c0000001f3b43a90 d000000002c70908 c0000000fbc06820
> > >> GPR04: c0000001ef1bd900 0000000000000004 0000000000000001 0000000000000000
> > >> GPR08: 0000000000000000 0000000000000001 d000000002c69560 d000000002c66d80
> > >> GPR12: c000000000b70870 c00000000e798700 c0000001f3b43ca0 c0000001d4949d40
> > >> GPR16: c00000014637e1c0 0000000000000000 0000000000000000 c0000000f2392940
> > >> GPR20: c0000001f3b43b98 0000000000000041 0000000000600000 0000000000000000
> > >> GPR24: fffffffffffff000 0000000000000000 d000000002c60be0 c0000001f1dac490
> > >> GPR28: 0000000000000004 0000000000000000 c0000001ef1bd900 c0000000f2392940
> > >> [ 7879.893839] NIP [d000000002c664ec] config_item_get+0x7c/0x90 [configfs]
> > >> [ 7879.893841] LR [d000000002c60980] check_perm+0x80/0x2e0 [configfs]
> > >> [ 7879.893842] Call Trace:
> > >> [ 7879.893844] [c0000001f3b43ac0] [d000000002c60980] check_perm+0x80/0x2e0 [configfs]
> > >> [ 7879.893847] [c0000001f3b43b10] [c000000000329770] do_dentry_open+0x2c0/0x460
> > >> [ 7879.893849] [c0000001f3b43b70] [c000000000344480] path_openat+0x210/0x1490
> > >> [ 7879.893851] [c0000001f3b43c80] [c00000000034708c] do_filp_open+0xfc/0x170
> > >> [ 7879.893853] [c0000001f3b43db0] [c00000000032b5bc] do_sys_open+0x1cc/0x390
> > >> [ 7879.893856] [c0000001f3b43e30] [c000000000009584] system_call+0x38/0xec
> > >> [ 7879.893856] Instruction dump:
> > >> [ 7879.893858] 409d0014 38210030 e8010010 7c0803a6 4e800020 3d220000 e94981e0 892a0000
> > >> [ 7879.893861] 2f890000 409effe0 39200001 992a0000 <0fe00000> 4bffffd0 60000000 60000000
> > >> [ 7879.893866] ---[ end trace 14078f0b3b5ad0aa ]---
> > >> [ 7912.992583] sd 6:0:0:0: [sdg] tag#0 FAILED Result: hostbyte=DID_OK driverbyte=DRIVER_SENSE
> > >> [ 7912.992587] sd 6:0:0:0: [sdg] tag#0 Sense Key : Illegal Request [current]
> > >> [ 7912.992589] sd 6:0:0:0: [sdg] tag#0 Add. Sense: Logical unit not supported
> > >> [ 7912.992591] sd 6:0:0:0: [sdg] tag#0 CDB: Read(10) 28 00 00 00 00 00 00 00 80 00
> > >> [ 7912.992593] blk_update_request: I/O error, dev sdg, sector 0
> > >>
> > > The kref_get() on struct config_item->ci_kref in config_item_get() is
> > > triggering a sanity check warning struct kref has reached zero, while a
> > > new kref_get() is attempting to take a new reference.
> > >
> > > Normally it means kref_get() should be using kref_get_unless_zero(), but
> > > since this has never been reported before, it makes me think something
> > > else outside of configfs proper is going on..
> > >
> > > What configfs operations are triggering this warning, and what do the
> > > configfs operations preceding it look like..?
> > >
> > > Also, is this specific to PSCSI export or does it trigger independent of
> > > target-core backend driver..?
> >
> > They were attaching a iSCSI volume, so basically we do a discover/login and then targetcli
> > is called to do the mappings. Also between the attach there were a few ls queries.
> > All this is done via Novalink API(Virtualization management).
> >
> > So the only configfs operations are through the mapping (backstores/block create) and the ls queries.
> >
>
> Ok, after doing further investigation in fs/configfs, it looks like the
> config_item_get() triggering WARN_ON() here is most likely coming from
> configfs_symlink() -> create_link().
>
> So assuming this is the code-path in question, it looks like a backend
> device is being released via:
>
> rmdir /sys/kernel/config/target/core/iblock_XXXX/$FOO
>
> at the same time another process is attempting to symlink the same
> configfs location via target_fabric_port_link() to a ibmvscsis port via:
>
> ln -s /sys/kernel/config/target/core/iblock_XXX/$FOO \
> /sys/kernel/config/target/ibmvscsis/$WWPN/$TPGT/lun/lun_XXX/$LINK
>
> So let's first confirm this is in fact what's triggering the kref_get()
> warning. With CONFIG_DYNAMIC_DEBUG=y, and enabling full debug with:
>
> echo 'module target_core_mod +p' > /debug/dynamic_debug/control
>
> should do the trick.
>
> There is enough debug in target-core-mod already to
> verify configfs_symlink() -> type->ct_item_ops->allow_link()
> target_fabric_port_link() -> core_dev_add_lun() is what's getting
> invoked, which happens immediately before create_link() ->
> config_item_get() -> kref_get() gets called and hits the WARN_ON.
>
> That said, I do see a race in fs/configfs/symlink.c:create_link() that
> might explain what you've observed..
>
> Looking at create_link(), the config_item_get() -> kref_get() for the
> struct config_item (eg: se_dev_ci from target_fabric_port_link) symlink
> target is attempted before the check for
> target_sd->s_type & CONFIGFS_USET_DROPPING occurs, eg:
>
> sl = kmalloc(sizeof(struct configfs_symlink), GFP_KERNEL);
> if (sl) {
> sl->sl_target = config_item_get(item);
> spin_lock(&configfs_dirent_lock);
> if (target_sd->s_type & CONFIGFS_USET_DROPPING) {
> spin_unlock(&configfs_dirent_lock);
> config_item_put(item);
> kfree(sl);
> return -ENOENT;
> }
> list_add(&sl->sl_list, &target_sd->s_links);
> spin_unlock(&configfs_dirent_lock);
> ret = configfs_create_link(sl, parent_item->ci_dentry,
> dentry);
>
> which means configfs_rmdir() -> configfs_detach_prep() setting
> CONFIGFS_USET_DROPPING and subsequently doing the final:
>
> /* Drop our reference from above */
> config_item_put(item);
>
> could happen while config_item_get() is called from create_link(),
> before the CONFIGFS_USET_DROPPING check occurs..
>
> Here's a quick (untested) patch to close that potential race.
>
> Please confirm with and without the following with debug enabled, and
> let's see what we find.
>
> diff --git a/fs/configfs/symlink.c b/fs/configfs/symlink.c
> index a6ab012..c8aabba 100644
> --- a/fs/configfs/symlink.c
> +++ b/fs/configfs/symlink.c
> @@ -83,14 +83,13 @@ static int create_link(struct config_item *parent_item,
> ret = -ENOMEM;
> sl = kmalloc(sizeof(struct configfs_symlink), GFP_KERNEL);
> if (sl) {
> - sl->sl_target = config_item_get(item);
> spin_lock(&configfs_dirent_lock);
> if (target_sd->s_type & CONFIGFS_USET_DROPPING) {
> spin_unlock(&configfs_dirent_lock);
> - config_item_put(item);
> kfree(sl);
> return -ENOENT;
> }
> + sl->sl_target = config_item_get(item);
> list_add(&sl->sl_list, &target_sd->s_links);
> spin_unlock(&configfs_dirent_lock);
> ret = configfs_create_link(sl, parent_item->ci_dentry,
>
> --
> To unsubscribe from this list: send the line "unsubscribe target-devel" in
> the body of a message to majordomo@xxxxxxxxxxxxxxx
> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
To unsubscribe from this list: send the line "unsubscribe target-devel" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
