Disabling ACL for qla2xxx

[Henrik Goldman]

Hello,

For iSCSI it seems to be an option that you can disable ACL. I'm
trying to do the same FC using qla2xxx. Targetcli (and docs) doesn't
say clearly that it's possible but on the other hand it seems some
parameters indicates there is something tweakable about it.

However I'd like to understand if and how it's possible. When you have
a simple environment then ACL is rather a bottleneck than a feature.

Thanks.

-- Henrik

[Nicholas A. Bellinger]

Hi Henrik,

Post by Henrik Goldman
Hello,
For iSCSI it seems to be an option that you can disable ACL. I'm
trying to do the same FC using qla2xxx. Targetcli (and docs) doesn't
say clearly that it's possible but on the other hand it seems some
parameters indicates there is something tweakable about it.
However I'd like to understand if and how it's possible. When you have
a simple environment then ACL is rather a bottleneck than a feature.

The following patch to support demo-mode for qla2xxx went into v3.12-rc1
code here:

target/qla2xxx: Make demo_mode_login_only modifiable
https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/drivers/scsi/qla2xxx/tcm_qla2xxx.c?id=de04a8aa6b292b9c7e559794cb50e4296b193002
generate_node_acls=1
cache_dynamic_acls=1
demo_mode_write_protect=0
demo_mode_login_only=0

for each qla2xxx endpoint to be configured for demo-mode (un-restricted)
access.

--nab

[Henrik Goldman]

Post by Nicholas A. Bellinger
The following patch to support demo-mode for qla2xxx went into v3.12-rc1

Beautiful. I see it already in the latest kernel releases so I can't
wait until it gets into the main distro of Ubuntu.

Thank you.

-- Henrik

[Craig Watson]

Hi,

Well, I finally had a chance to set up a fibre channel target system
with kernel
3.12. Unfortunately, demo mode still doesn't appear to work for me. Here's
what I have:

Initiator Fedora 18
kernel 3.10.4-100
QLogic QLE2562 HBA

Target Fedora 20
kernel 3.12.6-300
QLogic QLE2462 HBA
targetcli 2.1.fb30-1
rtslib 2.1.fb40-1
configshell 1.1.fb9-1

I set things up as below:
-----------------------------------------------------------------------------
o- / ..................................................................
[...]
o- backstores .......................................................
[...]
| o- block ........................................... [Storage
Objects: 1]
| | o- strg .................. [/dev/md_d0 (238.5GiB) write-thru
activated]
| o- fileio .......................................... [Storage
Objects: 0]
| o- pscsi ........................................... [Storage
Objects: 0]
| o- ramdisk ......................................... [Storage
Objects: 0]
o- iscsi .....................................................
[Targets: 0]
o- loopback ..................................................
[Targets: 0]
o- qla2xxx ...................................................
[Targets: 2]
| o- naa.21000024XXXXXXXe ......................................
[gen-acls]
| | o- acls .....................................................
[ACLs: 0]
| | o- luns .....................................................
[LUNs: 1]
| | o- lun0 ................................... [block/strg
(/dev/md_d0)]
| o- naa.21000024XXXXXXXf ......................................
[gen-acls]
| o- acls .....................................................
[ACLs: 0]
| o- luns .....................................................
[LUNs: 1]
| o- lun0 ................................... [block/strg
(/dev/md_d0)]
o- vhost .....................................................
[Targets: 0]
-----------------------------------------------------------------------------

To enable demo mode I issued the following:

targetcli /qla2xxx/naa.21000024XXXXXXXe set attribute\
demo_mode_write_protect=0 generate_node_acls=1 cache_dynamic_acls=1\
demo_mode_login_only=0

This responded with:

Parameter demo_mode_login_only is now '0'.
Parameter demo_mode_write_protect is now '0'.
Parameter generate_node_acls is now '1'.
Parameter cache_dynamic_acls is now '1'.


Unfortunately, nothing I do enables the initiator to see the target machine.
Rebooting the initiator or issuing a link initialization and scan don't
help.

What does work is to add the initiator WWPNs to the target's acls which
is, of
course, what demo mode is supposed to dispel.

This works:
-----------------------------------------------------------------------------
o- / ..................................................................
[...]
o- backstores .......................................................
[...]
| o- block ........................................... [Storage
Objects: 1]
| | o- strg .................. [/dev/md_d0 (238.5GiB) write-thru
activated]
| o- fileio .......................................... [Storage
Objects: 0]
| o- pscsi ........................................... [Storage
Objects: 0]
| o- ramdisk ......................................... [Storage
Objects: 0]
o- iscsi .....................................................
[Targets: 0]
o- loopback ..................................................
[Targets: 0]
o- qla2xxx ...................................................
[Targets: 2]
| o- naa.21000024XXXXXXXe ......................................
[gen-acls]
| | o- acls .....................................................
[ACLs: 2]
| | | o- naa.21000024XXXXXXXa ............................ [Mapped
LUNs: 1]
| | | | o- mapped_lun0 ............................. [lun0 block/strg
(rw)]
| | | o- naa.21000024XXXXXXXb ............................ [Mapped
LUNs: 1]
| | | o- mapped_lun0 ............................. [lun0 block/strg
(rw)]
| | o- luns .....................................................
[LUNs: 1]
| | o- lun0 ................................... [block/strg
(/dev/md_d0)]
| o- naa.21000024XXXXXXXf ......................................
[gen-acls]
| o- acls .....................................................
[ACLs: 2]
| | o- naa.21000024XXXXXXXa ............................ [Mapped
LUNs: 1]
| | | o- mapped_lun0 ............................. [lun0 block/strg
(rw)]
| | o- naa.21000024XXXXXXXb ............................ [Mapped
LUNs: 1]
| | o- mapped_lun0 ............................. [lun0 block/strg
(rw)]
| o- luns .....................................................
[LUNs: 1]
| o- lun0 ................................... [block/strg
(/dev/md_d0)]
o- vhost .....................................................
[Targets: 0]
-----------------------------------------------------------------------------

This doesn't work.
Here's the saveconfig.json file:

{
"fabric_modules": [],
"storage_objects": [
{
"attributes": {
"block_size": 512,
"emulate_3pc": 1,
"emulate_caw": 1,
"emulate_dpo": 0,
"emulate_fua_read": 0,
"emulate_fua_write": 1,
"emulate_model_alias": 1,
"emulate_rest_reord": 0,
"emulate_tas": 1,
"emulate_tpu": 0,
"emulate_tpws": 0,
"emulate_ua_intlck_ctrl": 0,
"emulate_write_cache": 0,
"enforce_pr_isids": 1,
"fabric_max_sectors": 8192,
"is_nonrot": 0,
"max_unmap_block_desc_count": 1,
"max_unmap_lba_count": 1024,
"max_write_same_len": 65535,
"optimal_sectors": 8192,
"queue_depth": 128,
"unmap_granularity": 1,
"unmap_granularity_alignment": 0
},
"dev": "/dev/md_d0",
"name": "strg",
"plugin": "block",
"readonly": false,
"write_back": false,
"wwn": "XXXXXXXX-XXXX-XXXX-XXXX-XXXXXXXXXXXX"
}
],
"targets": [
{
"fabric": "qla2xxx",
"tpgs": [
{
"attributes": {
"cache_dynamic_acls": 1,
"demo_mode_login_only": 0,
"demo_mode_write_protect": 0,
"generate_node_acls": 1,
"prod_mode_write_protect": 0
},
"enable": true,
"luns": [
{
"index": 0,
"storage_object": "/backstores/block/strg"
}
],
"node_acls": [],
"portals": [],
"tag": 1
}
],
"wwn": "naa.21000024XXXXXXXe"
},
{
"fabric": "qla2xxx",
"tpgs": [
{
"attributes": {
"cache_dynamic_acls": 1,
"demo_mode_login_only": 0,
"demo_mode_write_protect": 0,
"generate_node_acls": 1,
"prod_mode_write_protect": 0
},
"enable": true,
"luns": [
{
"index": 0,
"storage_object": "/backstores/block/strg"
}
],
"node_acls": [],
"portals": [],
"tag": 1
}
],
"wwn": "naa.21000024XXXXXXXf"
}
]
}


Am I missing something?

After waiting 6 months and being assured that this would be fixed in
3.12 it is a bit frustrating not be able to get this to work. I know
since I identified the issue 6 months ago a couple of other people
have also queried the list concerning this feature.

I hope I'm just overlooking something.

Thanks for any insight,

Craig Watson

[Nicholas A. Bellinger]

Hi Craig,

Post by Craig Watson
Hi,
Well, I finally had a chance to set up a fibre channel target system
with kernel
3.12. Unfortunately, demo mode still doesn't appear to work for me. Here's
Initiator Fedora 18
kernel 3.10.4-100
QLogic QLE2562 HBA
Target Fedora 20
kernel 3.12.6-300
QLogic QLE2462 HBA
targetcli 2.1.fb30-1
rtslib 2.1.fb40-1
configshell 1.1.fb9-1
-----------------------------------------------------------------------------
o- / ..................................................................
[...]
o- backstores .......................................................
[...]
| o- block ........................................... [Storage
Objects: 1]
| | o- strg .................. [/dev/md_d0 (238.5GiB) write-thru
activated]
| o- fileio .......................................... [Storage
Objects: 0]
| o- pscsi ........................................... [Storage
Objects: 0]
| o- ramdisk ......................................... [Storage
Objects: 0]
o- iscsi .....................................................
[Targets: 0]
o- loopback ..................................................
[Targets: 0]
o- qla2xxx ...................................................
[Targets: 2]
| o- naa.21000024XXXXXXXe ......................................
[gen-acls]
| | o- acls .....................................................
[ACLs: 0]
| | o- luns .....................................................
[LUNs: 1]
| | o- lun0 ................................... [block/strg
(/dev/md_d0)]
| o- naa.21000024XXXXXXXf ......................................
[gen-acls]
| o- acls .....................................................
[ACLs: 0]
| o- luns .....................................................
[LUNs: 1]
| o- lun0 ................................... [block/strg
(/dev/md_d0)]
o- vhost .....................................................
[Targets: 0]
-----------------------------------------------------------------------------
targetcli /qla2xxx/naa.21000024XXXXXXXe set attribute\
demo_mode_write_protect=0 generate_node_acls=1 cache_dynamic_acls=1\
demo_mode_login_only=0
Parameter demo_mode_login_only is now '0'.
Parameter demo_mode_write_protect is now '0'.
Parameter generate_node_acls is now '1'.
Parameter cache_dynamic_acls is now '1'.
Unfortunately, nothing I do enables the initiator to see the target machine.
Rebooting the initiator or issuing a link initialization and scan don't
help.

So, the issue your hitting is in the use of the global parameter
'auto_enable_tgpt' in targetcli.

By default when auto_enable_tgpt=true is set, and after creation of
a /qla2xxx/$FC_WWPN context in targetcli, target mode is enabled on the
FC port thus allowing FC initiators to login immediately using the
default hardcoded demo_mode_login_only=1 setting.

What happens is that a dynamic NodeACL with no MappedLUNs is created
within tcm_qla2xxx code for the FC initiator, and once
demo_mode_login_only=0 is changed after the fact, this dynamic ACL
remains unchanged because of cache_dynamic_acls=1 attribute usage.

So you've got two options here, either:

* After setting 'demo_mode_login_only=0' + configuring the rest of
$FC_WWPN, simply run 'saveconfig' and restart the target

A restart will cause demo_mode_login_only=0 to be set before target mode
is enabled during recreation of the configfs layout. Eg: No FC
initiators can login before enable occurs.

Or secondly, within targetcli use

* 'set global auto_enable_tpgt=false'

in order to prevent the automatic enabling of /qla2xxx/$FC_WWPN before
the attributes your currently using to enable demo mode have been
explicitly set. Of course, this will require an explicit 'enable' from
within /qla2xxx/$FC_WWPN context to enable target mode operation once
configuration is complete.

--nab

[Craig Watson]

Post by Nicholas A. Bellinger
Hi Craig,

Post by Craig Watson
Hi,
Well, I finally had a chance to set up a fibre channel target system
with kernel
3.12. Unfortunately, demo mode still doesn't appear to work for me. Here's
Initiator Fedora 18
kernel 3.10.4-100
QLogic QLE2562 HBA
Target Fedora 20
kernel 3.12.6-300
QLogic QLE2462 HBA
targetcli 2.1.fb30-1
rtslib 2.1.fb40-1
configshell 1.1.fb9-1
-----------------------------------------------------------------------------
o- / ..................................................................
[...]
o- backstores .......................................................
[...]
| o- block ........................................... [Storage
Objects: 1]
| | o- strg .................. [/dev/md_d0 (238.5GiB) write-thru
activated]
| o- fileio .......................................... [Storage
Objects: 0]
| o- pscsi ........................................... [Storage
Objects: 0]
| o- ramdisk ......................................... [Storage
Objects: 0]
o- iscsi .....................................................
[Targets: 0]
o- loopback ..................................................
[Targets: 0]
o- qla2xxx ...................................................
[Targets: 2]
| o- naa.21000024XXXXXXXe ......................................
[gen-acls]
| | o- acls .....................................................
[ACLs: 0]
| | o- luns .....................................................
[LUNs: 1]
| | o- lun0 ................................... [block/strg
(/dev/md_d0)]
| o- naa.21000024XXXXXXXf ......................................
[gen-acls]
| o- acls .....................................................
[ACLs: 0]
| o- luns .....................................................
[LUNs: 1]
| o- lun0 ................................... [block/strg
(/dev/md_d0)]
o- vhost .....................................................
[Targets: 0]
-----------------------------------------------------------------------------
targetcli /qla2xxx/naa.21000024XXXXXXXe set attribute\
demo_mode_write_protect=0 generate_node_acls=1 cache_dynamic_acls=1\
demo_mode_login_only=0
Parameter demo_mode_login_only is now '0'.
Parameter demo_mode_write_protect is now '0'.
Parameter generate_node_acls is now '1'.
Parameter cache_dynamic_acls is now '1'.
Unfortunately, nothing I do enables the initiator to see the target machine.
Rebooting the initiator or issuing a link initialization and scan don't
help.

So, the issue your hitting is in the use of the global parameter
'auto_enable_tgpt' in targetcli.
By default when auto_enable_tgpt=true is set, and after creation of
a /qla2xxx/$FC_WWPN context in targetcli, target mode is enabled on the
FC port thus allowing FC initiators to login immediately using the
default hardcoded demo_mode_login_only=1 setting.
What happens is that a dynamic NodeACL with no MappedLUNs is created
within tcm_qla2xxx code for the FC initiator, and once
demo_mode_login_only=0 is changed after the fact, this dynamic ACL
remains unchanged because of cache_dynamic_acls=1 attribute usage.
* After setting 'demo_mode_login_only=0' + configuring the rest of
$FC_WWPN, simply run 'saveconfig' and restart the target
A restart will cause demo_mode_login_only=0 to be set before target mode
is enabled during recreation of the configfs layout. Eg: No FC
initiators can login before enable occurs.
Or secondly, within targetcli use
* 'set global auto_enable_tpgt=false'
in order to prevent the automatic enabling of /qla2xxx/$FC_WWPN before
the attributes your currently using to enable demo mode have been
explicitly set. Of course, this will require an explicit 'enable' from
within /qla2xxx/$FC_WWPN context to enable target mode operation once
configuration is complete.
--nab

Hi Nicholas,

It's late here on the east coast but I had to put off sleep to try
this. Sure enough, it works!
We'll be going with the restart option since the target system is an
embedded device with
a somewhat fixed configuration. The users will have the option to use
the ACL WWPN
filtering but I haven't met one yet (in our niche market) that wants to
do that.

You have just made a lot of people very happy. You have no idea how
many people don't
like having to deal with ACLs on a private FC SAN. I didn't until we
sent a few of these out.
I've dealt with big system arrays that required setting up ACLs and
while it was a pain, I just
shrugged and dealt with it. When you run into entrenched organizations
that haven't had
to deal with it, their response is; "Well, if we have to do that out in
the field, we just won't buy
your product." They will go buy straight FC disk drives and avoid the
situation even though
they will take a performance and cost hit.

Now I have to try to get 3 hours sleep before I have to get up in the
morning.

Anyway, thanks for your prompt response and all the hard work you put
into this.

Sincerely,

Craig Watson

[Craig Watson]

Hi Nicholas,

One of our systems is seeing a kernel BUG with a fibre channel target
system. The system is an Intel i7 with a qle2562 FC HBA running FC20
with kernel 3.14.4-200. (We have seen this with several older kernel
versions too).

The LIO component versions are:
targetcli 2.1.fb35-1
rtslib 2.1.fb47-1
configshell 1.1.fb13-1

The bug/crash is repeatable. It happens every time the LIO target
system is attached to the initiator. The target is connected to an
older VxWorks initiator system. This system has been in service for
years and works with several models of FC disk drives. The new
LIO-based system is an attempt to replace aging hardware with newer,
more reliable, and higher performance storage.

Here is the console output of the kernel BUG:

[ 2669.734186] ------------[ cut here ]------------
[ 2669.738893] kernel BUG at drivers/scsi/qla2xxx/qla_target.c:1343!
[ 2669.745080] invalid opcode: 0000 [#1] SMP
[ 2669.749275] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211 rfkill snd_hda_codec_realtek snd_hda_codec_generic
snd_hda_intel snd_hda_codec serio_raw snd_hwdep snd_pcm snd_timer
x86_pkg_temp_thermal snd e1000e ptp iTCO_wdt mei_me iTCO_vendor_support
mei lpc_ich mfd_core raid0 i2c_i801 shpchp pps_core soundcore coretemp
kvm_intel kvm crct10dif_pclmul crc32_pclmul crc32c_intel
ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi i915
pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2669.805324] CPU: 1 PID: 558 Comm: kworker/1:0 Not tainted
3.14.4-200.fc20.x86_64 #1
[ 2669.813052] Hardware name: Intel Corporation ChiefRiver
Platform/PCOM-B219VG, BIOS R1.00.W3 09/24/2012
[ 2669.822485] Workqueue: qla_tgt_wq qlt_do_work [qla2xxx]
[ 2669.827810] task: ffff8800d28f1c80 ti: ffff8800d3eea000
task.ti: ffff8800d3eea000
[ 2669.835399] RIP: 0010:[<ffffffffa00edfe4>] [<ffffffffa00edfe4>]
qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2669.845308] RSP: 0018:ffff8800d3eebba8 EFLAGS: 00010246
[ 2669.850712] RAX: ffff880117d3b400 RBX: ffff880036b9d6f0
RCX: ffffffffa010a19a
[ 2669.857957] RDX: 0000000000000000 RSI: ffff880036b9d6f0 RDI:
ffff8800d3eebc00
[ 2669.865190] RBP: ffff8800d3eebbe0 R08: 0000000000000000 R09:
0000000000000020
[ 2669.872418] R10: 0000000000000002 R11: 0000000000000000 R12:
ffff8800d3eebc00
[ 2669.879646] R13: ffff8800d3eebc00 R14: ffff8800d1e30000 R15: ffff880117d3
[ 2669.886897] FS: 0000000000000000(0000) GS:ffff88011e240000(0000)
knlGS:0000000000000000
[ 2669.895102] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2669.900937] CR2: 00007f5efb75b000 CR3: 0000000001c0c000 CR4:
00000000001407e0
[ 2669.908144] Stack:
[ 2669.910187] 000000006acfe608 0000000100000000 ffff880036b9d6f0
ffff880117d3b400
[ 2669.917797] ffff8800d3eebc00 ffff8800d1e30000 ffff880117d3b72c
ffff8800d3eebc78
[ 2669.925387] ffffffffa00ef933 0000000000000000 0000000000000000
ffff880117d3b400
[ 2669.932969] Call Trace:
[ 2669.935455] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2669.942070] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60
[tcm_qla2xxx]
[ 2669.949855] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0
[target_core_mod]
[ 2669.958184] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90
[target_core_mod]
[ 2669.966510] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280
[target_core_mod]
[ 2669.974917] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60
[target_core_mod]
[ 2669.982336] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90
[tcm_qla2xxx]
[ 2669.989847] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2669.996231] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.002163] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.007809] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.013710] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.018763] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.024943] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.031673] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.039056] Code: 0f 1f 80 00 00 00 00 45 8b 4c 24 24 eb be 66 0f 1f
84 00
00 00 00 00 48 c7 45 c8 00 00 00 00 4c 8b 3d 01 a6
b2 e1
e9 18 ff ff ff <0f> 0b 48 8b b0 f8 02 00 00 44 8b
88 d0
02 00 00 45 31 c0 31 c0
[ 2670.062304] RIP [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0
[qla2xxx]
[ 2670.071041] RSP <ffff8800d3eebba8>
[ 2670.201729] ---[ end trace ec1db6cbc3980106 ]---
[ 2670.207583] BUG: unable to handle kernel paging request at
ffffffffffffffd8
[ 2670.215756] IP: [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.222563] PGD 1c0f067 PUD 1c11067 PMD 0
[ 2670.227968] Oops: 0000 [#2] SMP
[ 2670.232458] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211
rfkill snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel
snd_hda_codec
serio_raw snd_hwdep snd_pcm snd_timer x86_pkg_temp_thermal snd e1000e ptp
iTCO_wdt mei_me iTCO_vendor_support mei lpc_ich mfd_core raid0 i2c_i801
shpchp
pps_core soundcore coretemp kvm_intel kvm crct10dif_pclmul crc32_pclmul
crc32c_intel ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi
i915 pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2670.293550] CPU: 1 PID: 558 Comm: kworker/1:0 Tainted: G D
3.14.4-200.fc20.x86_64 #1
[ 2670.303354] Hardware name: Intel Corporation ChiefRiver
Platform/PCOM-B219VG,
BIOS R1.00.W3 09/24/2012
[ 2670.313751] task: ffff8800d28f1c80 ti: ffff8800d3eea000
task.ti: ffff8800d3eea000
[ 2670.322257] RIP: 0010:[<ffffffff810ae800>] [<ffffffff810ae800>]
kthread_data+0x10/0x20
[ 2670.331302] RSP: 0018:ffff8800d3eeb880 EFLAGS: 00010002
[ 2670.337864] RAX: 0000000000000000 RBX: 0000000000000001 RCX:
000000000000000f
[ 2670.346306] RDX: 0000000000000000 RSI: 0000000000000001 RDI:
ffff8800d28f1c80
[ 2670.354446] RBP: ffff8800d3eeb880 R08: ffff8800d28f1d10 R09:
00000001800f000c
[ 2670.362579] R10: ffffffff8108760c R11: ffffea00034fc200 R12:
ffff88011e254640
[ 2670.370972] R13: 0000000000000001 R14: ffff8800d28f1c70 R15:
ffff8800d28f1c80
[ 2670.379385] FS: 0000000000000000(0000) GS:ffff88011e240000(0000)
knlGS:0000000000000000
[ 2670.388826] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2670.395561] CR2: 0000000000000028 CR3: 0000000001c0c000 CR4:
00000000001407e0
[ 2670.403681] Stack:
[ 2670.406688] ffff8800d3eeb898 ffffffff810a7b91 ffff8800d28f1c80
ffff8800d3eeb8f8
[ 2670.415307] ffffffff816f2b89 ffff8800d28f1c80 ffff8800d3eebfd8
0000000000014640
[ 2670.424064] 0000000000014640 ffff8800d28f1c80 ffff8800d28f2318
ffff8800d3eeb5d0
[ 2670.432560] Call Trace:
[ 2670.436195] [<ffffffff810a7b91>] wq_worker_sleeping+0x11/0x90
[ 2670.443065] [<ffffffff816f2b89>] __schedule+0x4a9/0x740
[ 2670.449512] [<ffffffff816f2e49>] schedule+0x29/0x70
[ 2670.455693] [<ffffffff8108cb47>] do_exit+0x6b7/0xa30
[ 2670.461709] [<ffffffff816f758c>] oops_end+0x9c/0xe0
[ 2670.467649] [<ffffffff81017fcb>] die+0x4b/0x70
[ 2670.473359] [<ffffffff816f6e20>] do_trap+0x60/0x170
[ 2670.479445] [<ffffffff810150aa>] do_invalid_op+0xaa/0xe0
[ 2670.485816] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0
[qla2xxx]
[ 2670.494264] [<ffffffff8117e148>] ? __alloc_pages_nodemask+0x188/0xb60
[ 2670.501765] [<ffffffff81700c9e>] invalid_op+0x1e/0x30
[ 2670.508219] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0
[qla2xxx]
[ 2670.516726] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2670.524462] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60
[tcm_qla2xxx]
[ 2670.533387] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0
[target_core_mod]
[ 2670.542841] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90
[target_core_mod]
[ 2670.552307] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280
[target_core_mod]
[ 2670.561778] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60
[target_core_mod]
[ 2670.570364] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90
[tcm_qla2xxx]
[ 2670.578795] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2670.586343] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.593454] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.600058] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.606910] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.612885] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.620058] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.626578] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.633697] Code: 00 48 89 e5 5d 48 8b 40 c8 48 c1 e8 02 83 e0 01 c3
66 2e
0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 87 28 04 00 00 55 48 89 e5
<48> 8b
40 d8 5d c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
[ 2670.656112] RIP [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.662623] RSP <ffff8800d3eeb880>
[ 2670.666936] CR2: ffffffffffffffd8
[ 2670.671170] ---[ end trace ec1db6cbc3980107 ]---
[ 2670.676804] Fixing recursive fault but reboot is needed!
[ 2691.628643] ------------[ cut here ]------------


Looking at protocol traces on a Fibre Channel Protocol Analyzer, a Report
LUNs command requesting 0x1008 bytes of data (FCP_DL=0x1008) appears to
trigger the crash.

It is a rare target that has 0x1008 (5004) bytes of LUN data to return.
What should happen is the actual data available should be returned and a
residual under flag be set in the response along with the residual under
field being set to the number of bytes not returned. This system
actually is occasionally attached to a large storage array and
presumably that is why the large buffer is allocated for LUNs responses.

Since many of the Qla2xxx operations seem to pad (with zeros) the
responses out to whatever the requested data length was, maybe this is
overrunning a 4k buffer somewhere? Note, the responses should not be
padding and returning more data than what is actually available but this
is what we are seeing on the analyzer. The data length on the request
is specifying a maximum to return, not how much has to be returned.

So, this appears to be a combination of 2 problems. 1) Returns are
padding with zeros to the size of the request rather than truncating to
the size of actual data on hand. 2) Apparently a 4k buffer is being
overrun and crashing the system when a 0x1008 (4k + 8) Request for LUNs
command is received (this is speculation on my part).

Note the target system only has 1 LUN and should never come close to
returning 4k of data. What we actually see are 2 response PDUs with 2k
(LEX=0x0800) of data. This is mostly 0's, only the first 16-24 bytes
has information. These are followed by a response PDU with 8 bytes (of
zeros). The system then crashes hard.

We have traces of the initiator system connected to a Hitachi FC disk
drive where the same Report LUNs command (w/FCP_DL=0x1008) receives a
single response with 16 bytes of data (Len=0x0010). The drive functions
fine after this.

Looking at another initiator system and our LIO target, we see Requests
for LUNs asking for approximately 2k of data and the LIO-based target
system responds without crashing but does return approximately 2k of
data (mostly zeros).

Please let me know if I can provide any more information to facilitate
getting this fixed. Access to the systems is extremely limited though.

Thank you,

Craig Watson

[Nicholas A. Bellinger]

Hi Craig,

Thanks for the detailed bug report. Comments are inline below.

Also, adding some QLogic folks on the CC'..

Post by Craig Watson
Hi Nicholas,
One of our systems is seeing a kernel BUG with a fibre channel target
system. The system is an Intel i7 with a qle2562 FC HBA running FC20
with kernel 3.14.4-200. (We have seen this with several older kernel
versions too).
targetcli 2.1.fb35-1
rtslib 2.1.fb47-1
configshell 1.1.fb13-1
The bug/crash is repeatable. It happens every time the LIO target
system is attached to the initiator. The target is connected to an
older VxWorks initiator system. This system has been in service for
years and works with several models of FC disk drives. The new
LIO-based system is an attempt to replace aging hardware with newer,
more reliable, and higher performance storage.

<nod>, thanks for the extra background on your setup.

Post by Craig Watson
[ 2669.734186] ------------[ cut here ]------------
[ 2669.738893] kernel BUG at drivers/scsi/qla2xxx/qla_target.c:1343!
[ 2669.745080] invalid opcode: 0000 [#1] SMP
[ 2669.749275] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211 rfkill snd_hda_codec_realtek snd_hda_codec_generic
snd_hda_intel snd_hda_codec serio_raw snd_hwdep snd_pcm snd_timer
x86_pkg_temp_thermal snd e1000e ptp iTCO_wdt mei_me iTCO_vendor_support
mei lpc_ich mfd_core raid0 i2c_i801 shpchp pps_core soundcore coretemp
kvm_intel kvm crct10dif_pclmul crc32_pclmul crc32c_intel
ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi i915
pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2669.805324] CPU: 1 PID: 558 Comm: kworker/1:0 Not tainted 3.14.4-200.fc20.x86_64 #1
[ 2669.813052] Hardware name: Intel Corporation ChiefRiver Platform/PCOM-B219VG, BIOS R1.00.W3 09/24/2012
[ 2669.822485] Workqueue: qla_tgt_wq qlt_do_work [qla2xxx]
[ 2669.827810] task: ffff8800d28f1c80 ti: ffff8800d3eea000 task.ti: ffff8800d3eea000
[ 2669.835399] RIP: 0010:[<ffffffffa00edfe4>] [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2669.845308] RSP: 0018:ffff8800d3eebba8 EFLAGS: 00010246
[ 2669.850712] RAX: ffff880117d3b400 RBX: ffff880036b9d6f0 RCX: ffffffffa010a19a
[ 2669.857957] RDX: 0000000000000000 RSI: ffff880036b9d6f0 RDI: ffff8800d3eebc00
[ 2669.865190] RBP: ffff8800d3eebbe0 R08: 0000000000000000 R09: 0000000000000020
[ 2669.872418] R10: 0000000000000002 R11: 0000000000000000 R12: ffff8800d3eebc00
[ 2669.879646] R13: ffff8800d3eebc00 R14: ffff8800d1e30000 R15: ffff880117d3
[ 2669.886897] FS: 0000000000000000(0000) GS:ffff88011e240000(0000) knlGS:0000000000000000
[ 2669.895102] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2669.900937] CR2: 00007f5efb75b000 CR3: 0000000001c0c000 CR4: 00000000001407e0
[ 2669.910187] 000000006acfe608 0000000100000000 ffff880036b9d6f0 ffff880117d3b400
[ 2669.917797] ffff8800d3eebc00 ffff8800d1e30000 ffff880117d3b72c ffff8800d3eebc78
[ 2669.925387] ffffffffa00ef933 0000000000000000 0000000000000000 ffff880117d3b400
[ 2669.935455] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2669.942070] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60 [tcm_qla2xxx]
[ 2669.949855] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0 [target_core_mod]
[ 2669.958184] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90 [target_core_mod]
[ 2669.966510] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280 [target_core_mod]
[ 2669.974917] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60 [target_core_mod]
[ 2669.982336] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90 [tcm_qla2xxx]
[ 2669.989847] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2669.996231] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.002163] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.007809] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.013710] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.018763] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.024943] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.031673] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.039056] Code: 0f 1f 80 00 00 00 00 45 8b 4c 24 24 eb be 66 0f 1f 84 00
00 00 00 00 48 c7 45 c8 00 00 00 00 4c 8b 3d 01 a6 b2 e1
e9 18 ff ff ff <0f> 0b 48 8b b0 f8 02 00 00 44 8b 88 d0
02 00 00 45 31 c0 31 c0
[ 2670.062304] RIP [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.071041] RSP <ffff8800d3eebba8>
[ 2670.201729] ---[ end trace ec1db6cbc3980106 ]---
[ 2670.207583] BUG: unable to handle kernel paging request at ffffffffffffffd8
[ 2670.215756] IP: [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.222563] PGD 1c0f067 PUD 1c11067 PMD 0
[ 2670.227968] Oops: 0000 [#2] SMP
[ 2670.232458] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211
rfkill snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel
snd_hda_codec
serio_raw snd_hwdep snd_pcm snd_timer x86_pkg_temp_thermal snd e1000e ptp
iTCO_wdt mei_me iTCO_vendor_support mei lpc_ich mfd_core raid0 i2c_i801
shpchp
pps_core soundcore coretemp kvm_intel kvm crct10dif_pclmul crc32_pclmul
crc32c_intel ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi
i915 pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2670.293550] CPU: 1 PID: 558 Comm: kworker/1:0 Tainted: G D 3.14.4-200.fc20.x86_64 #1
[ 2670.303354] Hardware name: Intel Corporation ChiefRiver Platform/PCOM-B219VG,BIOS R1.00.W3 09/24/2012
[ 2670.313751] task: ffff8800d28f1c80 ti: ffff8800d3eea000 task.ti: ffff8800d3eea000
[ 2670.322257] RIP: 0010:[<ffffffff810ae800>] [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.331302] RSP: 0018:ffff8800d3eeb880 EFLAGS: 00010002
[ 2670.337864] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 00000000000000f
[ 2670.346306] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff8800d28f1c80
[ 2670.354446] RBP: ffff8800d3eeb880 R08: ffff8800d28f1d10 R09: 00000001800f000c
[ 2670.362579] R10: ffffffff8108760c R11: ffffea00034fc200 R12: ffff88011e254640
[ 2670.370972] R13: 0000000000000001 R14: ffff8800d28f1c70 R15: ffff8800d28f1c80
[ 2670.379385] FS: 0000000000000000(0000) GS:ffff88011e240000(0000) knlGS:0000000000000000
[ 2670.388826] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2670.395561] CR2: 0000000000000028 CR3: 0000000001c0c000 CR4: 00000000001407e0
[ 2670.406688] ffff8800d3eeb898 ffffffff810a7b91 ffff8800d28f1c80 ffff8800d3eeb8f8
[ 2670.415307] ffffffff816f2b89 ffff8800d28f1c80 ffff8800d3eebfd8 0000000000014640
[ 2670.424064] 0000000000014640 ffff8800d28f1c80 ffff8800d28f2318 ffff8800d3eeb5d0
[ 2670.436195] [<ffffffff810a7b91>] wq_worker_sleeping+0x11/0x90
[ 2670.443065] [<ffffffff816f2b89>] __schedule+0x4a9/0x740
[ 2670.449512] [<ffffffff816f2e49>] schedule+0x29/0x70
[ 2670.455693] [<ffffffff8108cb47>] do_exit+0x6b7/0xa30
[ 2670.461709] [<ffffffff816f758c>] oops_end+0x9c/0xe0
[ 2670.467649] [<ffffffff81017fcb>] die+0x4b/0x70
[ 2670.473359] [<ffffffff816f6e20>] do_trap+0x60/0x170
[ 2670.479445] [<ffffffff810150aa>] do_invalid_op+0xaa/0xe0
[ 2670.485816] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.494264] [<ffffffff8117e148>] ? __alloc_pages_nodemask+0x188/0xb60
[ 2670.501765] [<ffffffff81700c9e>] invalid_op+0x1e/0x30
[ 2670.508219] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.516726] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2670.524462] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60 [tcm_qla2xxx]
[ 2670.533387] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0 [target_core_mod]
[ 2670.542841] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90 [target_core_mod]
[ 2670.552307] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280 [target_core_mod]
[ 2670.561778] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60 [target_core_mod]
[ 2670.570364] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90 [tcm_qla2xxx]
[ 2670.578795] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2670.586343] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.593454] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.600058] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.606910] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.612885] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.620058] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.626578] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.633697] Code: 00 48 89 e5 5d 48 8b 40 c8 48 c1 e8 02 83 e0 01 c3 66 2e
0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 87 28 04 00 00 55 48 89 e5 <48> 8b
40 d8 5d c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
[ 2670.656112] RIP [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.662623] RSP <ffff8800d3eeb880>
[ 2670.666936] CR2: ffffffffffffffd8
[ 2670.671170] ---[ end trace ec1db6cbc3980107 ]---
[ 2670.676804] Fixing recursive fault but reboot is needed!
[ 2691.628643] ------------[ cut here ]------------
Looking at protocol traces on a Fibre Channel Protocol Analyzer, a Report
LUNs command requesting 0x1008 bytes of data (FCP_DL=0x1008) appears to
trigger the crash.
It is a rare target that has 0x1008 (5004) bytes of LUN data to return.
What should happen is the actual data available should be returned and a
residual under flag be set in the response along with the residual under
field being set to the number of bytes not returned. This system
actually is occasionally attached to a large storage array and
presumably that is why the large buffer is allocated for LUNs responses.

AFAICT, the 'what should happen' is the current behavior in target core.

That is, the REPORT_LUNS response sets the underflow bit and associated
residual length in target_complete_cmd_with_length() when the outgoing
REPORT_LUNS payload is smaller than the received SCSI EDTL.

Post by Craig Watson
Since many of the Qla2xxx operations seem to pad (with zeros) the
responses out to whatever the requested data length was, maybe this is
overrunning a 4k buffer somewhere? Note, the responses should not be
padding and returning more data than what is actually available but this
is what we are seeing on the analyzer. The data length on the request
is specifying a maximum to return, not how much has to be returned.

Ok, based on the comments below, I think this is a separate issue that
is specific to qla2xxx fabric, but is not the cause of the above
BUG_ON().

Post by Craig Watson
So, this appears to be a combination of 2 problems. 1) Returns are
padding with zeros to the size of the request rather than truncating to
the size of actual data on hand. 2) Apparently a 4k buffer is being
overrun and crashing the system when a 0x1008 (4k + 8) Request for LUNs
command is received (this is speculation on my part).

So based upon the above trace, the BUG_ON() being triggered is in the
WRITE code-path and doesn't appear related to a specific REPORT_LUNS
payload size.

Namely, there is a check in qlt_pci_map_calc_cnt() that ensures that a
non zero scatterlist count exists when a given command's scatterlists
are mapped into PCI address space for receiving the incoming WRITE
payload.

I'm thinking this could very well be some form of zero-length WRITE that
is occurring immediately after the REPORT_LUNs.

Is anything else showing up on the trace after the REPORT_LUNs..?

Post by Craig Watson
Note the target system only has 1 LUN and should never come close to
returning 4k of data. What we actually see are 2 response PDUs with 2k
(LEX=0x0800) of data. This is mostly 0's, only the first 16-24 bytes
has information. These are followed by a response PDU with 8 bytes (of
zeros). The system then crashes hard.
We have traces of the initiator system connected to a Hitachi FC disk
drive where the same Report LUNs command (w/FCP_DL=0x1008) receives a
single response with 16 bytes of data (Len=0x0010). The drive functions
fine after this.
Looking at another initiator system and our LIO target, we see Requests
for LUNs asking for approximately 2k of data and the LIO-based target
system responds without crashing but does return approximately 2k of
data (mostly zeros).
Please let me know if I can provide any more information to facilitate
getting this fixed. Access to the systems is extremely limited though.

Thanks. I need to verify zero-length WRITEs work as expected first, and
then will take a look at why REPORT_LUNS is returning the extra payload
with qla2xxx.

What would also be useful is to identify the specific WRITE CDB that is
triggering the sanity check in qlt_pci_map_calc_cnt() that is being
triggered. Below is a debug patch to dump some information before
invoking BUG_ON(). Would it be possible to apply it to your build and
reproduce..?

Thanks again,

--nab

diff --git a/drivers/scsi/qla2xxx/qla_target.c b/drivers/scsi/qla2xxx/qla_target.c
index e632e14..9a97707 100644
--- a/drivers/scsi/qla2xxx/qla_target.c
+++ b/drivers/scsi/qla2xxx/qla_target.c
@@ -1350,7 +1350,21 @@ static int qlt_pci_map_calc_cnt(struct qla_tgt_prm *prm)
{
struct qla_tgt_cmd *cmd = prm->cmd;

- BUG_ON(cmd->sg_cnt == 0);
+ if (cmd->sg_cnt == 0) {
+ struct se_cmd *se_cmd = &cmd->se_cmd;
+ int i;
+
+ printk("qlt_pci_map_calc_cnt cmd->bufflen: %u\n", cmd->bufflen);
+ printk("qlt_pci_map_calc_cnt se_cmd->data_length: %u\n",
+ se_cmd->data_length);
+ printk("qlt_pci_map_calc_cnt se_cmd->t_task_cdb: 0x%02x",
+ se_cmd->t_task_cdb[0]);
+ for (i = 1; i < 16; i++)
+ printk(" %02x", se_cmd->t_task_cdb[i]);
+
+ printk("\n");
+ BUG();
+ }

prm->sg = (struct scatterlist *)cmd->sg;
prm->seg_cnt = pci_map_sg(prm->tgt->ha->pdev, cmd->sg,

[Nicholas A. Bellinger]

Hi Craig,

A quick update on this bug. Comments below.

Post by Nicholas A. Bellinger
Hi Craig,
Thanks for the detailed bug report. Comments are inline below.
Also, adding some QLogic folks on the CC'..

Post by Craig Watson
Hi Nicholas,
One of our systems is seeing a kernel BUG with a fibre channel target
system. The system is an Intel i7 with a qle2562 FC HBA running FC20
with kernel 3.14.4-200. (We have seen this with several older kernel
versions too).
targetcli 2.1.fb35-1
rtslib 2.1.fb47-1
configshell 1.1.fb13-1
The bug/crash is repeatable. It happens every time the LIO target
system is attached to the initiator. The target is connected to an
older VxWorks initiator system. This system has been in service for
years and works with several models of FC disk drives. The new
LIO-based system is an attempt to replace aging hardware with newer,
more reliable, and higher performance storage.

<nod>, thanks for the extra background on your setup.

Post by Craig Watson
[ 2669.734186] ------------[ cut here ]------------
[ 2669.738893] kernel BUG at drivers/scsi/qla2xxx/qla_target.c:1343!
[ 2669.745080] invalid opcode: 0000 [#1] SMP
[ 2669.749275] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211 rfkill snd_hda_codec_realtek snd_hda_codec_generic
snd_hda_intel snd_hda_codec serio_raw snd_hwdep snd_pcm snd_timer
x86_pkg_temp_thermal snd e1000e ptp iTCO_wdt mei_me iTCO_vendor_support
mei lpc_ich mfd_core raid0 i2c_i801 shpchp pps_core soundcore coretemp
kvm_intel kvm crct10dif_pclmul crc32_pclmul crc32c_intel
ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi i915
pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2669.805324] CPU: 1 PID: 558 Comm: kworker/1:0 Not tainted 3.14.4-200.fc20.x86_64 #1
[ 2669.813052] Hardware name: Intel Corporation ChiefRiver Platform/PCOM-B219VG, BIOS R1.00.W3 09/24/2012
[ 2669.822485] Workqueue: qla_tgt_wq qlt_do_work [qla2xxx]
[ 2669.827810] task: ffff8800d28f1c80 ti: ffff8800d3eea000 task.ti: ffff8800d3eea000
[ 2669.835399] RIP: 0010:[<ffffffffa00edfe4>] [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2669.845308] RSP: 0018:ffff8800d3eebba8 EFLAGS: 00010246
[ 2669.850712] RAX: ffff880117d3b400 RBX: ffff880036b9d6f0 RCX: ffffffffa010a19a
[ 2669.857957] RDX: 0000000000000000 RSI: ffff880036b9d6f0 RDI: ffff8800d3eebc00
[ 2669.865190] RBP: ffff8800d3eebbe0 R08: 0000000000000000 R09: 0000000000000020
[ 2669.872418] R10: 0000000000000002 R11: 0000000000000000 R12: ffff8800d3eebc00
[ 2669.879646] R13: ffff8800d3eebc00 R14: ffff8800d1e30000 R15: ffff880117d3
[ 2669.886897] FS: 0000000000000000(0000) GS:ffff88011e240000(0000) knlGS:0000000000000000
[ 2669.895102] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2669.900937] CR2: 00007f5efb75b000 CR3: 0000000001c0c000 CR4: 00000000001407e0
[ 2669.910187] 000000006acfe608 0000000100000000 ffff880036b9d6f0 ffff880117d3b400
[ 2669.917797] ffff8800d3eebc00 ffff8800d1e30000 ffff880117d3b72c ffff8800d3eebc78
[ 2669.925387] ffffffffa00ef933 0000000000000000 0000000000000000 ffff880117d3b400
[ 2669.935455] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2669.942070] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60 [tcm_qla2xxx]
[ 2669.949855] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0 [target_core_mod]
[ 2669.958184] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90 [target_core_mod]
[ 2669.966510] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280 [target_core_mod]
[ 2669.974917] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60 [target_core_mod]
[ 2669.982336] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90 [tcm_qla2xxx]
[ 2669.989847] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2669.996231] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.002163] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.007809] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.013710] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.018763] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.024943] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.031673] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.039056] Code: 0f 1f 80 00 00 00 00 45 8b 4c 24 24 eb be 66 0f 1f 84 00
00 00 00 00 48 c7 45 c8 00 00 00 00 4c 8b 3d 01 a6 b2 e1
e9 18 ff ff ff <0f> 0b 48 8b b0 f8 02 00 00 44 8b 88 d0
02 00 00 45 31 c0 31 c0
[ 2670.062304] RIP [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.071041] RSP <ffff8800d3eebba8>
[ 2670.201729] ---[ end trace ec1db6cbc3980106 ]---
[ 2670.207583] BUG: unable to handle kernel paging request at ffffffffffffffd8
[ 2670.215756] IP: [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.222563] PGD 1c0f067 PUD 1c11067 PMD 0
[ 2670.227968] Oops: 0000 [#2] SMP
[ 2670.232458] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211
rfkill snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel
snd_hda_codec
serio_raw snd_hwdep snd_pcm snd_timer x86_pkg_temp_thermal snd e1000e ptp
iTCO_wdt mei_me iTCO_vendor_support mei lpc_ich mfd_core raid0 i2c_i801
shpchp
pps_core soundcore coretemp kvm_intel kvm crct10dif_pclmul crc32_pclmul
crc32c_intel ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi
i915 pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2670.293550] CPU: 1 PID: 558 Comm: kworker/1:0 Tainted: G D 3.14.4-200.fc20.x86_64 #1
[ 2670.303354] Hardware name: Intel Corporation ChiefRiver Platform/PCOM-B219VG,BIOS R1.00.W3 09/24/2012
[ 2670.313751] task: ffff8800d28f1c80 ti: ffff8800d3eea000 task.ti: ffff8800d3eea000
[ 2670.322257] RIP: 0010:[<ffffffff810ae800>] [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.331302] RSP: 0018:ffff8800d3eeb880 EFLAGS: 00010002
[ 2670.337864] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 00000000000000f
[ 2670.346306] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff8800d28f1c80
[ 2670.354446] RBP: ffff8800d3eeb880 R08: ffff8800d28f1d10 R09: 00000001800f000c
[ 2670.362579] R10: ffffffff8108760c R11: ffffea00034fc200 R12: ffff88011e254640
[ 2670.370972] R13: 0000000000000001 R14: ffff8800d28f1c70 R15: ffff8800d28f1c80
[ 2670.379385] FS: 0000000000000000(0000) GS:ffff88011e240000(0000) knlGS:0000000000000000
[ 2670.388826] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2670.395561] CR2: 0000000000000028 CR3: 0000000001c0c000 CR4: 00000000001407e0
[ 2670.406688] ffff8800d3eeb898 ffffffff810a7b91 ffff8800d28f1c80 ffff8800d3eeb8f8
[ 2670.415307] ffffffff816f2b89 ffff8800d28f1c80 ffff8800d3eebfd8 0000000000014640
[ 2670.424064] 0000000000014640 ffff8800d28f1c80 ffff8800d28f2318 ffff8800d3eeb5d0
[ 2670.436195] [<ffffffff810a7b91>] wq_worker_sleeping+0x11/0x90
[ 2670.443065] [<ffffffff816f2b89>] __schedule+0x4a9/0x740
[ 2670.449512] [<ffffffff816f2e49>] schedule+0x29/0x70
[ 2670.455693] [<ffffffff8108cb47>] do_exit+0x6b7/0xa30
[ 2670.461709] [<ffffffff816f758c>] oops_end+0x9c/0xe0
[ 2670.467649] [<ffffffff81017fcb>] die+0x4b/0x70
[ 2670.473359] [<ffffffff816f6e20>] do_trap+0x60/0x170
[ 2670.479445] [<ffffffff810150aa>] do_invalid_op+0xaa/0xe0
[ 2670.485816] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.494264] [<ffffffff8117e148>] ? __alloc_pages_nodemask+0x188/0xb60
[ 2670.501765] [<ffffffff81700c9e>] invalid_op+0x1e/0x30
[ 2670.508219] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.516726] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2670.524462] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60 [tcm_qla2xxx]
[ 2670.533387] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0 [target_core_mod]
[ 2670.542841] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90 [target_core_mod]
[ 2670.552307] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280 [target_core_mod]
[ 2670.561778] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60 [target_core_mod]
[ 2670.570364] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90 [tcm_qla2xxx]
[ 2670.578795] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2670.586343] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.593454] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.600058] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.606910] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.612885] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.620058] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.626578] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.633697] Code: 00 48 89 e5 5d 48 8b 40 c8 48 c1 e8 02 83 e0 01 c3 66 2e
0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 87 28 04 00 00 55 48 89 e5 <48> 8b
40 d8 5d c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
[ 2670.656112] RIP [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.662623] RSP <ffff8800d3eeb880>
[ 2670.666936] CR2: ffffffffffffffd8
[ 2670.671170] ---[ end trace ec1db6cbc3980107 ]---
[ 2670.676804] Fixing recursive fault but reboot is needed!
[ 2691.628643] ------------[ cut here ]------------
Looking at protocol traces on a Fibre Channel Protocol Analyzer, a Report
LUNs command requesting 0x1008 bytes of data (FCP_DL=0x1008) appears to
trigger the crash.
It is a rare target that has 0x1008 (5004) bytes of LUN data to return.
What should happen is the actual data available should be returned and a
residual under flag be set in the response along with the residual under
field being set to the number of bytes not returned. This system
actually is occasionally attached to a large storage array and
presumably that is why the large buffer is allocated for LUNs responses.

AFAICT, the 'what should happen' is the current behavior in target core.
That is, the REPORT_LUNS response sets the underflow bit and associated
residual length in target_complete_cmd_with_length() when the outgoing
REPORT_LUNS payload is smaller than the received SCSI EDTL.

Post by Craig Watson
Since many of the Qla2xxx operations seem to pad (with zeros) the
responses out to whatever the requested data length was, maybe this is
overrunning a 4k buffer somewhere? Note, the responses should not be
padding and returning more data than what is actually available but this
is what we are seeing on the analyzer. The data length on the request
is specifying a maximum to return, not how much has to be returned.

Ok, based on the comments below, I think this is a separate issue that
is specific to qla2xxx fabric, but is not the cause of the above
BUG_ON().

Post by Craig Watson
So, this appears to be a combination of 2 problems. 1) Returns are
padding with zeros to the size of the request rather than truncating to
the size of actual data on hand. 2) Apparently a 4k buffer is being
overrun and crashing the system when a 0x1008 (4k + 8) Request for LUNs
command is received (this is speculation on my part).

So based upon the above trace, the BUG_ON() being triggered is in the
WRITE code-path and doesn't appear related to a specific REPORT_LUNS
payload size.
Namely, there is a check in qlt_pci_map_calc_cnt() that ensures that a
non zero scatterlist count exists when a given command's scatterlists
are mapped into PCI address space for receiving the incoming WRITE
payload.
I'm thinking this could very well be some form of zero-length WRITE that
is occurring immediately after the REPORT_LUNs.
Is anything else showing up on the trace after the REPORT_LUNs..?

Post by Craig Watson
Note the target system only has 1 LUN and should never come close to
returning 4k of data. What we actually see are 2 response PDUs with 2k
(LEX=0x0800) of data. This is mostly 0's, only the first 16-24 bytes
has information. These are followed by a response PDU with 8 bytes (of
zeros). The system then crashes hard.
We have traces of the initiator system connected to a Hitachi FC disk
drive where the same Report LUNs command (w/FCP_DL=0x1008) receives a
single response with 16 bytes of data (Len=0x0010). The drive functions
fine after this.
Looking at another initiator system and our LIO target, we see Requests
for LUNs asking for approximately 2k of data and the LIO-based target
system responds without crashing but does return approximately 2k of
data (mostly zeros).
Please let me know if I can provide any more information to facilitate
getting this fixed. Access to the systems is extremely limited though.

Thanks. I need to verify zero-length WRITEs work as expected first, and
then will take a look at why REPORT_LUNS is returning the extra payload
with qla2xxx.

OK, I've been able to verify with v3.14.13 + qla2xxx export that
zero-length WRITEs and residual handling for REPORT_LUNS with a 5004
byte transfer length are working as expected.

# sg_raw /dev/sg9 2a 00 00 00 00 00 00 00 00 00
SCSI Status: Good

# sg_luns -m 5004 -v /dev/sdj
report luns cdb: a0 00 00 00 00 00 00 00 13 8c 00 00
report luns: pass-through requested 5004 bytes but got 72 bytes
Lun list length = 8 which imples 1 lun entry
Report luns [select_report=0x0]:
0000000000000000

Looking at the v3.14.y change-log, Roland's patch below to fix the
residual handling went in for v3.14.9, and should address the zero
padding issue you observed with the FC analyzer.

target: Report correct response length for some commands
https://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?h=linux-3.14.y&id=9a7f545e75cef29dbdc4c585f3ae27c5f7f4ea48

It's still unclear if this is what triggered the BUG_ON() in
qlt_pci_map_calc_cnt() you originally reported, but at this point it
would be a good idea to retest with >= v3.14.13, preferably with extra
debug code in place to dump se_cmd if the same BUG_ON() triggers again.

Thanks,

--nab

[Craig Watson]

Hi Nicholas,

I'm sorry it has taken me so long to respond and follow up on this. I
recently had shoulder surgery and have been under the weather. Doing
better now.

Unfortunately I don't have direct access to the crashing system. It has
taken almost a year just to get the protocol traces and console dump I
have received.

The problem I am faced with is something is causing the kernel to crash
and there aren't any zero-length commands after the Report LUNs
command. Comparing 3 or 4 systems, the only anomaly we were able to
identify in the crashing system was the large (and incorrect) response
to the Report LUNs command. Other systems receiving less data (smaller
requesting FCP_DL) in the response worked without problems. This is the
only discernible difference in the traffic between a system that works
and one that crashes. Everyone is telling me the BUG is caused by a
zero-length command but I don't see one in the protocol trace. Since my
quick and uninformed perusal of the code turned up a 4096 byte buffer, I
theorized that a buffer overrun was possible. Is it possible that a
buffer overrun is corrupting the logic and looking like a zero-length
command? Probably not very likely.

I am not insisting this is a buffer overrun, but since there aren't any
zero-length commands, I'm just asking for someone who understands the
code to look at what is going on. Actually, since the 5004 byte
response is broken into 3 packets that do get returned successfully, I'm
not real confident of the buffer overrun theory. I just can't see a
more likely scenario.

Note: Roland Dreier's fix (commit 2426bd456a target: Report correct
response length for some commands) of the padding responses is not in
the kernel version(s) we have tested. Sometime in the future we'll be
able to roll out an update and see if it works. This might actually
"short-circuit" my theorized buffer overrun and fix my immediate problem.

Here's the details from the protocol analyzer of the crash with a few
comments thrown in. Note the only exchange after the large Report LUNs
command does not appear to be a zero-length command.


At time index = 00:41.005_695_148 Port(1:1:1)/Side A, the Initiator
sends our device, the LIO target unit, "Report Luns" with FC_DL =
0x00001008 or 5004 Bytes.

00:41.005_695_148 315.212 FC Port(1:1:1) FC4Cmd
Report LUNs; LUNs with specific address methods; LUN = 0x0000;
FCP_DL = 0x00001008; 68 0000EF 0000E8 0000 0005 FFFF
0000 Originator; First_Sequence; End_Sequence; Transfer Sequence
Initiative; 00000000 8B3E8E84 (Correct) EOFt(+)

Our device, the LIO target unit, responds by sending the available data
for it's two LUNS (approx. 24 Bytes) and then fills the balance of the
requested 5004 Bytes with zeros. The LIO target unit then terminates
this exchange with "Good Status".

00:41.005_859_180 164.032 FC Port(1:1:2)
FC4SData FC4SData; SCSI FCP; Offset = 0x00000000; Len = 0x0800;
2084 0000E8 0000EF 0005 0102 0000 Responder;
RO; 00000000 58C3EBB3 (Correct) EOFn(-)
00:41.005_864_152 4.972 FC Port(1:1:2)
FC4SData FC4SData; SCSI FCP; Offset = 0x00000800; Len = 0x0800;
2084 0000E8 0000EF 0005 0102 0001 Responder;
RO; 00000800 557D64B9 (Correct) EOFn(-)
00:41.005_869_120 4.968 FC Port(1:1:2)
FC4SData FC4SData; SCSI FCP; Offset = 0x00001000; Len = 0x0008;
44 0000E8 0000EF 0005 0102 0002 Responder;
End_Sequence; RO; 00001000 767079BC (Correct) EOFt(+)
00:41.005_869_664 0.544 FC Port(1:1:2)
FC4Status Good Status; 60 0000E8 0000EF
0005 0102 0000 Responder; Last_Sequence; End_Sequence;
00000000 021F63DE (Correct) EOFt(-)
00:41.006_107_404 237.740 FC Port(1:1:1) ExtLinkReq
ExtLinkReq; EX_LNK_SRV; ADISC; 64
0000EF 0000E8 0006 FFFF 0000 Originator; First_Sequence;
End_Sequence; Transfer Sequence Initiative; 00000000
1C806BCC (Correct) EOFt(-) Interesting Event Found
00:41.006_214_424 107.020 FC Port(1:1:2)
ExtLinkRply ExtLinkRply; EX_LNK_SRV; Accept; 64
0000E8 0000EF 0006 0006 0000 Responder; Last_Sequence;
End_Sequence; 00000000 C2C18DC8 (Correct) EOFt(+)


At time index = 00:41.006_323_460 Port(1:1:1)/Side A, the Initiator
sends our LIO target unit "Inquiry" Lun = 0x000 with FCP_DL = 0x00000090.

00:41.006_323_460 109.036 FC Port(1:1:1) FC4Cmd
Inquiry; LUN = 0x0000; FCP_DL = 0x00000090;
68 0000EF 0000E8 0000 0007 FFFF 0000 Originator;
First_Sequence; End_Sequence; Transfer Sequence Initiative;
00000000 C10AA6D0 (Correct) EOFt(-)

Our device, the LIO target unit, responds with 0x0090 Bytes of Data. The
LIO target unit then terminates this exchange with "Good Status".

00:41.006_450_404 126.944 FC Port(1:1:2)
FC4SData FC4SData; SCSI FCP; Offset = 0x00000000; Len = 0x0090;
180 0000E8 0000EF 0007 0103 0000 Responder;
End_Sequence; RO; 00000000 69B3CC1E (Correct) EOFt(+)
00:41.006_450_892 0.488 FC Port(1:1:2)
FC4Status Good Status; 60 0000E8 0000EF
0007 0103 0000 Responder; Last_Sequence; End_Sequence;
00000000 8417ABA0 (Correct) EOFt(+)

After this exchange, the LIO target unit no longer responds to the
initiator as shown by the trace lines below, because the Linux kernel
has crashed.

Eventually the Initiator logs off the link (LOGO) at time index
00:52.254_510_372

00:41.006_592_808 141.916 FC Port(1:1:1) FC4Cmd
Test Unit Ready; LUN = 0x0000; FCP_DL = 0x00000000;
68 0000EF 0000E8 0000 0008 FFFF 0000 Originator;
First_Sequence; End_Sequence; Transfer Sequence Initiative;
00000000 1EDFA836 (Correct) EOFt(-)
00:44.191_823_484 3185230.676 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange;
36 0000EF 0000E8 0008 FFFF 0000 Originator;
End_Sequence; Transfer Sequence Initiative; EA3CE37F
(Correct) EOFt(+) Interesting Event Found
00:44.191_897_724 74.240 FC Port(1:1:1) FC4Cmd
Test Unit Ready; LUN = 0x0000; FCP_DL = 0x00000000;
68 0000EF 0000E8 0000 0009 FFFF 0000 Originator;
First_Sequence; End_Sequence; Transfer Sequence Initiative;
00000000 D5EC0952 (Correct) EOFt(-)
00:47.416_231_268 3224333.544 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange;
36 0000EF 0000E8 0009 FFFF 0000 Originator;
End_Sequence; Transfer Sequence Initiative; 5E3794D9
(Correct) EOFt(-) Interesting Event Found
00:47.416_490_052 258.784 FC Port(1:1:1) FC4Cmd
Inquiry; LUN = 0x0000; FCP_DL = 0x00000090;
68 0000EF 0000E8 0000 000A FFFF 0000 Originator;
First_Sequence; End_Sequence; Transfer Sequence Initiative;
00000000 ECA729E4 (Correct) EOFt(-)
00:48.222_328_208 805838.156 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange;
36 0000EF 0000E8 0008 FFFF 0000 Originator;
End_Sequence; Transfer Sequence Initiative; EA3CE37F
(Correct) EOFt(+) Interesting Event Found
00:50.640_639_416 2418311.208 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange;
36 0000EF 0000E8 000A FFFF 0000 Originator;
End_Sequence; Transfer Sequence Initiative; C32D7CE8
(Correct) EOFt(+) Interesting Event Found
00:50.650_054_092 9414.676 FC Port(1:1:1) FC4Cmd
Inquiry; LUN = 0x0000; FCP_DL = 0x00000090;
68 0000EF 0000E8 0000 000B FFFF 0000 Originator;
First_Sequence; End_Sequence; Transfer Sequence Initiative;
00000000 27948880 (Correct) EOFt(-)
00:51.446_734_260 796680.168 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange;
36 0000EF 0000E8 0009 FFFF 0000 Originator;
End_Sequence; Transfer Sequence Initiative; 5E3794D9
(Correct) EOFt(-) Interesting Event Found
00:52.254_510_372 807776.112 FC Port(1:1:1) ExtLinkReq
ExtLinkReq; EX_LNK_SRV; LOGO; 52
0000EF 0000E8 000C FFFF 0000 Originator; First_Sequence;
End_Sequence; Transfer Sequence Initiative; 00000000
755F5787 (Correct) EOFt(-) Interesting Event Found

Post by Nicholas A. Bellinger
Hi Craig,
A quick update on this bug. Comments below.

Post by Nicholas A. Bellinger
Hi Craig,
Thanks for the detailed bug report. Comments are inline below.
Also, adding some QLogic folks on the CC'..

Post by Craig Watson
Hi Nicholas,
One of our systems is seeing a kernel BUG with a fibre channel target
system. The system is an Intel i7 with a qle2562 FC HBA running FC20
with kernel 3.14.4-200. (We have seen this with several older kernel
versions too).
targetcli 2.1.fb35-1
rtslib 2.1.fb47-1
configshell 1.1.fb13-1
The bug/crash is repeatable. It happens every time the LIO target
system is attached to the initiator. The target is connected to an
older VxWorks initiator system. This system has been in service for
years and works with several models of FC disk drives. The new
LIO-based system is an attempt to replace aging hardware with newer,
more reliable, and higher performance storage.

<nod>, thanks for the extra background on your setup.

Post by Craig Watson
[ 2669.734186] ------------[ cut here ]------------
[ 2669.738893] kernel BUG at drivers/scsi/qla2xxx/qla_target.c:1343!
[ 2669.745080] invalid opcode: 0000 [#1] SMP
[ 2669.749275] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211 rfkill snd_hda_codec_realtek snd_hda_codec_generic
snd_hda_intel snd_hda_codec serio_raw snd_hwdep snd_pcm snd_timer
x86_pkg_temp_thermal snd e1000e ptp iTCO_wdt mei_me iTCO_vendor_support
mei lpc_ich mfd_core raid0 i2c_i801 shpchp pps_core soundcore coretemp
kvm_intel kvm crct10dif_pclmul crc32_pclmul crc32c_intel
ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi i915
pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2669.805324] CPU: 1 PID: 558 Comm: kworker/1:0 Not tainted 3.14.4-200.fc20.x86_64 #1
[ 2669.813052] Hardware name: Intel Corporation ChiefRiver Platform/PCOM-B219VG, BIOS R1.00.W3 09/24/2012
[ 2669.822485] Workqueue: qla_tgt_wq qlt_do_work [qla2xxx]
[ 2669.827810] task: ffff8800d28f1c80 ti: ffff8800d3eea000 task.ti: ffff8800d3eea000
[ 2669.835399] RIP: 0010:[<ffffffffa00edfe4>] [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2669.845308] RSP: 0018:ffff8800d3eebba8 EFLAGS: 00010246
[ 2669.850712] RAX: ffff880117d3b400 RBX: ffff880036b9d6f0 RCX: ffffffffa010a19a
[ 2669.857957] RDX: 0000000000000000 RSI: ffff880036b9d6f0 RDI: ffff8800d3eebc00
[ 2669.865190] RBP: ffff8800d3eebbe0 R08: 0000000000000000 R09: 0000000000000020
[ 2669.872418] R10: 0000000000000002 R11: 0000000000000000 R12: ffff8800d3eebc00
[ 2669.879646] R13: ffff8800d3eebc00 R14: ffff8800d1e30000 R15: ffff880117d3
[ 2669.886897] FS: 0000000000000000(0000) GS:ffff88011e240000(0000) knlGS:0000000000000000
[ 2669.895102] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2669.900937] CR2: 00007f5efb75b000 CR3: 0000000001c0c000 CR4: 00000000001407e0
[ 2669.910187] 000000006acfe608 0000000100000000 ffff880036b9d6f0 ffff880117d3b400
[ 2669.917797] ffff8800d3eebc00 ffff8800d1e30000 ffff880117d3b72c ffff8800d3eebc78
[ 2669.925387] ffffffffa00ef933 0000000000000000 0000000000000000 ffff880117d3b400
[ 2669.935455] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2669.942070] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60 [tcm_qla2xxx]
[ 2669.949855] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0 [target_core_mod]
[ 2669.958184] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90 [target_core_mod]
[ 2669.966510] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280 [target_core_mod]
[ 2669.974917] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60 [target_core_mod]
[ 2669.982336] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90 [tcm_qla2xxx]
[ 2669.989847] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2669.996231] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.002163] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.007809] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.013710] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.018763] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.024943] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.031673] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.039056] Code: 0f 1f 80 00 00 00 00 45 8b 4c 24 24 eb be 66 0f 1f 84 00
00 00 00 00 48 c7 45 c8 00 00 00 00 4c 8b 3d 01 a6 b2 e1
e9 18 ff ff ff <0f> 0b 48 8b b0 f8 02 00 00 44 8b 88 d0
02 00 00 45 31 c0 31 c0
[ 2670.062304] RIP [<ffffffffa00edfe4>] qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.071041] RSP <ffff8800d3eebba8>
[ 2670.201729] ---[ end trace ec1db6cbc3980106 ]---
[ 2670.207583] BUG: unable to handle kernel paging request at ffffffffffffffd8
[ 2670.215756] IP: [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.222563] PGD 1c0f067 PUD 1c11067 PMD 0
[ 2670.227968] Oops: 0000 [#2] SMP
[ 2670.232458] Modules linked in: tcm_qla2xxx target_core_pscsi
target_core_file target_core_iblock iscsi_target_mod target_core_mod
cfg80211
rfkill snd_hda_codec_realtek snd_hda_codec_generic snd_hda_intel
snd_hda_codec
serio_raw snd_hwdep snd_pcm snd_timer x86_pkg_temp_thermal snd e1000e ptp
iTCO_wdt mei_me iTCO_vendor_support mei lpc_ich mfd_core raid0 i2c_i801
shpchp
pps_core soundcore coretemp kvm_intel kvm crct10dif_pclmul crc32_pclmul
crc32c_intel ghash_clmulni_intel microcode usb_storage ata_generic pata_acpi
i915 pata_jmicron qla2xxx i2c_algo_bit drm_kms_helper drm scsi_transport_fc
scsi_tgt i2c_core video
[ 2670.293550] CPU: 1 PID: 558 Comm: kworker/1:0 Tainted: G D 3.14.4-200.fc20.x86_64 #1
[ 2670.303354] Hardware name: Intel Corporation ChiefRiver Platform/PCOM-B219VG,BIOS R1.00.W3 09/24/2012
[ 2670.313751] task: ffff8800d28f1c80 ti: ffff8800d3eea000 task.ti: ffff8800d3eea000
[ 2670.322257] RIP: 0010:[<ffffffff810ae800>] [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.331302] RSP: 0018:ffff8800d3eeb880 EFLAGS: 00010002
[ 2670.337864] RAX: 0000000000000000 RBX: 0000000000000001 RCX: 00000000000000f
[ 2670.346306] RDX: 0000000000000000 RSI: 0000000000000001 RDI: ffff8800d28f1c80
[ 2670.354446] RBP: ffff8800d3eeb880 R08: ffff8800d28f1d10 R09: 00000001800f000c
[ 2670.362579] R10: ffffffff8108760c R11: ffffea00034fc200 R12: ffff88011e254640
[ 2670.370972] R13: 0000000000000001 R14: ffff8800d28f1c70 R15: ffff8800d28f1c80
[ 2670.379385] FS: 0000000000000000(0000) GS:ffff88011e240000(0000) knlGS:0000000000000000
[ 2670.388826] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2670.395561] CR2: 0000000000000028 CR3: 0000000001c0c000 CR4: 00000000001407e0
[ 2670.406688] ffff8800d3eeb898 ffffffff810a7b91 ffff8800d28f1c80 ffff8800d3eeb8f8
[ 2670.415307] ffffffff816f2b89 ffff8800d28f1c80 ffff8800d3eebfd8 0000000000014640
[ 2670.424064] 0000000000014640 ffff8800d28f1c80 ffff8800d28f2318 ffff8800d3eeb5d0
[ 2670.436195] [<ffffffff810a7b91>] wq_worker_sleeping+0x11/0x90
[ 2670.443065] [<ffffffff816f2b89>] __schedule+0x4a9/0x740
[ 2670.449512] [<ffffffff816f2e49>] schedule+0x29/0x70
[ 2670.455693] [<ffffffff8108cb47>] do_exit+0x6b7/0xa30
[ 2670.461709] [<ffffffff816f758c>] oops_end+0x9c/0xe0
[ 2670.467649] [<ffffffff81017fcb>] die+0x4b/0x70
[ 2670.473359] [<ffffffff816f6e20>] do_trap+0x60/0x170
[ 2670.479445] [<ffffffff810150aa>] do_invalid_op+0xaa/0xe0
[ 2670.485816] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.494264] [<ffffffff8117e148>] ? __alloc_pages_nodemask+0x188/0xb60
[ 2670.501765] [<ffffffff81700c9e>] invalid_op+0x1e/0x30
[ 2670.508219] [<ffffffffa00edfe4>] ? qlt_pci_map_calc_cnt+0x164/0x1a0 [qla2xxx]
[ 2670.516726] [<ffffffffa00ef933>] qlt_rdy_to_xfer+0x93/0x210 [qla2xxx]
[ 2670.524462] [<ffffffffa03c267c>] tcm_qla2xxx_write_pending+0x5c/0x60 [tcm_qla2xxx]
[ 2670.533387] [<ffffffffa04ff677>] transport_generic_new_cmd+0x127/0x1a0 [target_core_mod]
[ 2670.542841] [<ffffffffa04ff72b>] transport_handle_cdb_direct+0x3b/0x90 [target_core_mod]
[ 2670.552307] [<ffffffffa04ff8c2>] target_submit_cmd_map_sgls+0x142/0x280 [target_core_mod]
[ 2670.561778] [<ffffffffa04ffa59>] target_submit_cmd+0x59/0x60 [target_core_mod]
[ 2670.570364] [<ffffffffa03c25ea>] tcm_qla2xxx_handle_cmd+0x5a/0x90 [tcm_qla2xxx]
[ 2670.578795] [<ffffffffa00f0624>] qlt_do_work+0x2e4/0x460 [qla2xxx]
[ 2670.586343] [<ffffffff810a6886>] process_one_work+0x176/0x430
[ 2670.593454] [<ffffffff810a74db>] worker_thread+0x11b/0x3a0
[ 2670.600058] [<ffffffff810a73c0>] ? rescuer_thread+0x370/0x370
[ 2670.606910] [<ffffffff810ae211>] kthread+0xe1/0x100
[ 2670.612885] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.620058] [<ffffffff816ff4bc>] ret_from_fork+0x7c/0xb0
[ 2670.626578] [<ffffffff810ae130>] ? insert_kthread_work+0x40/0x40
[ 2670.633697] Code: 00 48 89 e5 5d 48 8b 40 c8 48 c1 e8 02 83 e0 01 c3 66 2e
0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 48 8b 87 28 04 00 00 55 48 89 e5 <48> 8b
40 d8 5d c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00
[ 2670.656112] RIP [<ffffffff810ae800>] kthread_data+0x10/0x20
[ 2670.662623] RSP <ffff8800d3eeb880>
[ 2670.666936] CR2: ffffffffffffffd8
[ 2670.671170] ---[ end trace ec1db6cbc3980107 ]---
[ 2670.676804] Fixing recursive fault but reboot is needed!
[ 2691.628643] ------------[ cut here ]------------
Looking at protocol traces on a Fibre Channel Protocol Analyzer, a Report
LUNs command requesting 0x1008 bytes of data (FCP_DL=0x1008) appears to
trigger the crash.
It is a rare target that has 0x1008 (5004) bytes of LUN data to return.
What should happen is the actual data available should be returned and a
residual under flag be set in the response along with the residual under
field being set to the number of bytes not returned. This system
actually is occasionally attached to a large storage array and
presumably that is why the large buffer is allocated for LUNs responses.

AFAICT, the 'what should happen' is the current behavior in target core.
That is, the REPORT_LUNS response sets the underflow bit and associated
residual length in target_complete_cmd_with_length() when the outgoing
REPORT_LUNS payload is smaller than the received SCSI EDTL.

Post by Craig Watson
Since many of the Qla2xxx operations seem to pad (with zeros) the
responses out to whatever the requested data length was, maybe this is
overrunning a 4k buffer somewhere? Note, the responses should not be
padding and returning more data than what is actually available but this
is what we are seeing on the analyzer. The data length on the request
is specifying a maximum to return, not how much has to be returned.

Ok, based on the comments below, I think this is a separate issue that
is specific to qla2xxx fabric, but is not the cause of the above
BUG_ON().

Post by Craig Watson
So, this appears to be a combination of 2 problems. 1) Returns are
padding with zeros to the size of the request rather than truncating to
the size of actual data on hand. 2) Apparently a 4k buffer is being
overrun and crashing the system when a 0x1008 (4k + 8) Request for LUNs
command is received (this is speculation on my part).

So based upon the above trace, the BUG_ON() being triggered is in the
WRITE code-path and doesn't appear related to a specific REPORT_LUNS
payload size.
Namely, there is a check in qlt_pci_map_calc_cnt() that ensures that a
non zero scatterlist count exists when a given command's scatterlists
are mapped into PCI address space for receiving the incoming WRITE
payload.
I'm thinking this could very well be some form of zero-length WRITE that
is occurring immediately after the REPORT_LUNs.
Is anything else showing up on the trace after the REPORT_LUNs..?

Post by Craig Watson
Note the target system only has 1 LUN and should never come close to
returning 4k of data. What we actually see are 2 response PDUs with 2k
(LEX=0x0800) of data. This is mostly 0's, only the first 16-24 bytes
has information. These are followed by a response PDU with 8 bytes (of
zeros). The system then crashes hard.
We have traces of the initiator system connected to a Hitachi FC disk
drive where the same Report LUNs command (w/FCP_DL=0x1008) receives a
single response with 16 bytes of data (Len=0x0010). The drive functions
fine after this.
Looking at another initiator system and our LIO target, we see Requests
for LUNs asking for approximately 2k of data and the LIO-based target
system responds without crashing but does return approximately 2k of
data (mostly zeros).
Please let me know if I can provide any more information to facilitate
getting this fixed. Access to the systems is extremely limited though.

Thanks. I need to verify zero-length WRITEs work as expected first, and
then will take a look at why REPORT_LUNS is returning the extra payload
with qla2xxx.

OK, I've been able to verify with v3.14.13 + qla2xxx export that
zero-length WRITEs and residual handling for REPORT_LUNS with a 5004
byte transfer length are working as expected.
# sg_raw /dev/sg9 2a 00 00 00 00 00 00 00 00 00
SCSI Status: Good
# sg_luns -m 5004 -v /dev/sdj
report luns cdb: a0 00 00 00 00 00 00 00 13 8c 00 00
report luns: pass-through requested 5004 bytes but got 72 bytes
Lun list length = 8 which imples 1 lun entry
0000000000000000
Looking at the v3.14.y change-log, Roland's patch below to fix the
residual handling went in for v3.14.9, and should address the zero
padding issue you observed with the FC analyzer.
target: Report correct response length for some commands
https://git.kernel.org/cgit/linux/kernel/git/stable/linux-stable.git/commit/?h=linux-3.14.y&id=9a7f545e75cef29dbdc4c585f3ae27c5f7f4ea48
It's still unclear if this is what triggered the BUG_ON() in
qlt_pci_map_calc_cnt() you originally reported, but at this point it
would be a good idea to retest with >= v3.14.13, preferably with extra
debug code in place to dump se_cmd if the same BUG_ON() triggers again.
Thanks,
--nab

[Roland Dreier]

The problem I am faced with is something is causing the kernel to crash and
there aren't any zero-length commands after the Report LUNs command.

You say there are no zero-length commands, but...

Here's the details from the protocol analyzer of the crash with a few
comments thrown in. Note the only exchange after the large Report LUNs
command does not appear to be a zero-length command.

...

After this exchange, the LIO target unit no longer responds to the initiator
as shown by the trace lines below, because the Linux kernel has crashed.
Eventually the Initiator logs off the link (LOGO) at time index
00:52.254_510_372
00:41.006_592_808 141.916 FC Port(1:1:1) FC4Cmd
Test Unit Ready; LUN = 0x0000; FCP_DL = 0x00000000; 68 0000EF
0000E8 0000 0008 FFFF 0000 Originator; First_Sequence;
End_Sequence; Transfer Sequence Initiative; 00000000 1EDFA836
(Correct) EOFt(-)
00:44.191_823_484 3185230.676 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange; 36 0000EF
0000E8 0008 FFFF 0000 Originator; End_Sequence; Transfer
Sequence Initiative; EA3CE37F (Correct) EOFt(+)

Here clearly the initiator clearly *does* send a zero-length command
(TEST UNIT READY), and the target does not respond. The logical
conclusion is that *this* is the command that crashes the target,
since the target handle the previous INQUIRY command just fine, and
we're not responding to any commands after a panic.

And indeed, I have a theory about what is happening: I suspect the
initiator is sending a TEST UNIT READY command with the "WRDATA" bit
set, so that the target core treats it as a command with a data-out
phase (transferring data from the initiator), but with a data length
of 0. Unfortunately I don't see any indication of the value of WRDATA
in your trace. Looking at the target code, I think it does not handle
this correctly, even in the latest upstream code. I have a local
patch that I thought was upstream that I'll send shortly.

- R.

[Nicholas A. Bellinger]

Post by Roland Dreier

The problem I am faced with is something is causing the kernel to crash and
there aren't any zero-length commands after the Report LUNs command.

You say there are no zero-length commands, but...

Here's the details from the protocol analyzer of the crash with a few
comments thrown in. Note the only exchange after the large Report LUNs
command does not appear to be a zero-length command.

...

After this exchange, the LIO target unit no longer responds to the initiator
as shown by the trace lines below, because the Linux kernel has crashed.
Eventually the Initiator logs off the link (LOGO) at time index
00:52.254_510_372
00:41.006_592_808 141.916 FC Port(1:1:1) FC4Cmd
Test Unit Ready; LUN = 0x0000; FCP_DL = 0x00000000; 68 0000EF
0000E8 0000 0008 FFFF 0000 Originator; First_Sequence;
End_Sequence; Transfer Sequence Initiative; 00000000 1EDFA836
(Correct) EOFt(-)
00:44.191_823_484 3185230.676 FC Port(1:1:1) ABTS
ABTS; Basic Link Service; Abort Exchange; 36 0000EF
0000E8 0008 FFFF 0000 Originator; End_Sequence; Transfer
Sequence Initiative; EA3CE37F (Correct) EOFt(+)

Here clearly the initiator clearly *does* send a zero-length command
(TEST UNIT READY), and the target does not respond. The logical
conclusion is that *this* is the command that crashes the target,
since the target handle the previous INQUIRY command just fine, and
we're not responding to any commands after a panic.
And indeed, I have a theory about what is happening: I suspect the
initiator is sending a TEST UNIT READY command with the "WRDATA" bit
set, so that the target core treats it as a command with a data-out
phase (transferring data from the initiator), but with a data length
of 0. Unfortunately I don't see any indication of the value of WRDATA
in your trace. Looking at the target code, I think it does not handle
this correctly, even in the latest upstream code. I have a local
patch that I thought was upstream that I'll send shortly.

AFAICT, this theory makes perfect sense based upon the analyzer output.

--nab