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
