On 6/20/2014 11:17 PM, Nicholas A. Bellinger wrote:
> On Fri, 2014-06-20 at 15:54 +0530, Arshad Hussain wrote:
>> Hi Nab,
>> On 6/20/2014 12:32 PM, Nicholas A. Bellinger wrote:
>>> On Thu, 2014-06-19 at 23:43 -0700, Nicholas A. Bellinger wrote:
>>>> On Fri, 2014-06-20 at 11:30 +0530, Santosh Kulkarni wrote:
> <SNIP>
>
>>> One other quick thing to try is the following patch to dump the Data-out
>>> payload when a ITT received is not associated with a WRITE (following
>>> the log), instead of generating a Reject for the existing ITT.
>>>
>>> I can't quite tell from wireshark output why your test is sending
>>> Data-out with an ITT that is associated with a READ that has not been
>>> acknowledged by StatSN, but the following should at least leave the READ
>>> ITT alone.
>>>
>>> --nab
>>>
>>> diff --git a/drivers/target/iscsi/iscsi_target.c b/drivers/target/iscsi/iscsi_target.c
>>> index b87721a..049fe14 100644
>>> --- a/drivers/target/iscsi/iscsi_target.c
>>> +++ b/drivers/target/iscsi/iscsi_target.c
>>> @@ -1308,7 +1308,7 @@ iscsit_check_dataout_hdr(struct iscsi_conn *conn, unsigned char *buf,
>>> if (cmd->data_direction != DMA_TO_DEVICE) {
>>> pr_err("Command ITT: 0x%08x received DataOUT for a"
>>> " NON-WRITE command.\n", cmd->init_task_tag);
>>> - return iscsit_reject_cmd(cmd, ISCSI_REASON_PROTOCOL_ERROR, buf);
>>> + return iscsit_dump_data_payload(conn, payload_length, 1);
>>> }
>>> se_cmd = &cmd->se_cmd;
>>> iscsit_mod_dataout_timer(cmd);
>>>
>>>
>> Santosh is traveling and I will help out with any answers you need.
>>
>> The ITT is unique within a session, should READ here be a problem.? And
>> what we have observed that our the crash is intermittent as we have
>> mention before.
>>
> That is not what is indicated in the logs so far. The output (appears)
> to show that an ITT that was previously used by a READ is being reused
> by a WRITE + associated Data-Out, before the original READ is explicitly
> acknowledged via StatSN.
>
> This results in the lookup for the Data-out ITT to locate the original
> READ, and correctly fail due to the incorrect data_direction type of the
> original command.
>
>> Tried out your patch on 3.14.0-rc6+ and 3.15.0-rc3+. With 3.15.0-rc3
>> the target is not crashing. The dmesg shows the line below.
>>
>> [root@wfsc iscsi]# dmesg -c
>> [ 210.623207] Command ITT: 0xa3a3a3a3 received DataOUT for a NON-WRITE
>> command.
>>
> Thanks for confirming. I think this is the correct fix, but would like
> to verify some more on my end. Please send me the test off-list.
>
>> [root@wfsc iscsi]# uname -a
>> Linux wfsc 3.15.0-rc3+ #3 SMP Fri May 30 06:11:42 EDT 2014 x86_64 x86_64
>> x86_64 GNU/Linux
>>
>> With 3.14.0-rc6+. It is crashing with the below output.
>>
> This output for v3.14-rc6 would indicate that the patch is not applied.
> Eg:
>
> "ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set."
>
> means that iscsi_dump_data_payload() is not being called, because the
> subsequent Data-Out payload (still in the TCP stream) is processed, and
> fails at the WRITE + FINAL bits sanity checks.
>
> Please confirm this patch is applied with a printk() ahead of the call
> to iscsi_dump_data_payload().
Apologies for the delay.
I double check your patch on 3.14.0-rc6+. It is applied and I have
added debug statement as you have advised to see if we are hitting the
correct area. I have also attached a .png, as I was getting a soft lock.
This is on same kernel (3.14.0-rc6+), but without your patch. I will
also revisit our test plan and get back.
<Dmesg output With your patch on 3.14.0-rc6+>
root@wfsc target-pending]# dmesg
[ 8915.579866] Debug#1
[ 8915.607790] Debug#1
[ 8915.607862] Debug#4
[ 8915.607923] Command ITT: 0xa3a3a3a3 received DataOUT for a NON-WRITE
command.
[root@wfsc target-pending]#
diff --git a/drivers/target/iscsi/iscsi_target.c
b/drivers/target/iscsi/iscsi_target.c
index 7e5469a..f941bac 100644
--- a/drivers/target/iscsi/iscsi_target.c
+++ b/drivers/target/iscsi/iscsi_target.c
@@ -1252,6 +1252,8 @@ iscsit_check_dataout_hdr(struct iscsi_conn *conn,
unsigned char *buf,
struct se_cmd *se_cmd;
u32 payload_length = ntoh24(hdr->dlength);
int rc;
+
+ pr_err("Debug#1\n");
if (!payload_length) {
pr_warn("DataOUT payload is ZERO, ignoring.\n");
@@ -1262,6 +1264,7 @@ iscsit_check_dataout_hdr(struct iscsi_conn *conn,
unsigned char *buf,
atomic_long_add(payload_length, &conn->sess->rx_data_octets);
if (payload_length > conn->conn_ops->MaxXmitDataSegmentLength) {
+ pr_err("Debug#2\n");
pr_err("DataSegmentLength: %u is greater than"
" MaxXmitDataSegmentLength: %u\n", payload_length,
conn->conn_ops->MaxXmitDataSegmentLength);
@@ -1280,6 +1283,7 @@ iscsit_check_dataout_hdr(struct iscsi_conn *conn,
unsigned char *buf,
payload_length, conn->cid);
if (cmd->cmd_flags & ICF_GOT_LAST_DATAOUT) {
+ pr_err("Debug#3\n");
pr_err("Command ITT: 0x%08x received DataOUT after"
" last DataOUT received, dumping payload\n",
cmd->init_task_tag);
@@ -1287,9 +1291,11 @@ iscsit_check_dataout_hdr(struct iscsi_conn *conn,
unsigned char *buf,
}
if (cmd->data_direction != DMA_TO_DEVICE) {
+ pr_err("Debug#4\n");
pr_err("Command ITT: 0x%08x received DataOUT for a"
" NON-WRITE command.\n", cmd->init_task_tag);
- return iscsit_reject_cmd(cmd,
ISCSI_REASON_PROTOCOL_ERROR, buf);
+ return iscsit_dump_data_payload(conn, payload_length, 1);
}
se_cmd = &cmd->se_cmd;
iscsit_mod_dataout_timer(cmd);
@@ -1564,7 +1570,10 @@ int iscsit_process_nop_out(struct iscsi_conn
*conn, struct iscsi_cmd *cmd,
* Initiator is expecting a NopIN ping reply..
*/
if (hdr->itt != RESERVED_ITT) {
- BUG_ON(!cmd);
+ if (!cmd)
+ return iscsit_add_reject(conn,
ISCSI_REASON_PROTOCOL_ERROR,
+
(unsigned char *)hdr);
spin_lock_bh(&conn->cmd_lock);
list_add_tail(&cmd->i_conn_node, &conn->conn_cmd_list);
[root@wfsc target-pending]#
Thanks,
Arshad
>
> Thanks,
>
> --nab
>
>> [ 124.571009] Command ITT: 0xa3a3a3a3 received DataOUT for a NON-WRITE
>> command.
>> [ 124.623127] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 124.632252] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 124.676209] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 124.736480] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 124.924880] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 124.940144] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 125.040862] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 125.050377] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 125.066584] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 125.078853] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 125.081819] ISCSI_FLAG_CMD_WRITE & ISCSI_FLAG_CMD_FINAL not set. Bad
>> iSCSI Initiator.
>> [ 127.576143] general protection fault: 0000 [#1] SMP
>> [ 127.580095] Modules linked in: nls_utf8 isofs vboxsf(O) tcm_loop
>> tcm_fc libfc scsi_transport_fc scsi_tgt iscsi_target_mod
>> target_core_pscsi target_core_file target_core_iblock target_core_mod
>> configfs ib_iser rdma_cm ib_cm iw_cm ib_sa ib_mad ib_core ib_addr
>> iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi bnep rfcomm
>> bluetooth snd_intel8x0 snd_ac97_codec 6lowpan_iphc ac97_bus snd_pcm
>> snd_seq_midi snd_rawmidi snd_seq_midi_event snd_seq snd_timer
>> snd_seq_device snd joydev vboxguest(O) psmouse mac_hid i2c_piix4 ppdev
>> serio_raw soundcore parport_pc lp parport hid_generic usbhid hid e1000
>> [ 127.580095] CPU: 0 PID: 0 Comm: swapper/0 Tainted: G O
>> 3.14.0-rc6+ #4
>> [ 127.580095] Hardware name: innotek GmbH VirtualBox/VirtualBox, BIOS
>> VirtualBox 12/01/2006
>> [ 127.580095] task: ffffffff81c104a0 ti: ffffffff81c00000 task.ti:
>> ffffffff81c00000
>> [ 127.580095] RIP: 0010:[<ffffffffa02f7c10>] [<ffffffffa02f7c10>]
>> iscsit_tpg_get_node_attrib+0x10/0x20 [iscsi_target_mod]
>> [ 127.580095] RSP: 0018:ffff88003fc03dd8 EFLAGS: 00010246
>> [ 127.580095] RAX: 617941580000000d RBX: ffff880037baa640 RCX:
>> 0000000000000000
>> [ 127.580095] RDX: 0000000000000002 RSI: 0000000000000200 RDI:
>> ffff88001a1d2800
>> [ 127.580095] RBP: ffff88003fc03dd8 R08: 0000000000016ab1 R09:
>> 0000000081e5b240
>> [ 127.580095] R10: 0000000000000020 R11: 0000000000000000 R12:
>> ffff880037b65800
>> [ 127.580095] R13: ffff880037baa724 R14: ffff88001a1d2800 R15:
>> ffffffffa02f17d0
>> [ 127.580095] FS: 0000000000000000(0000) GS:ffff88003fc00000(0000)
>> knlGS:0000000000000000
>> [ 127.580095] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
>> [ 127.580095] CR2: 00007fe77c00b208 CR3: 000000002fdad000 CR4:
>> 00000000000006f0
>> [ 127.580095] Stack:
>> [ 127.580095] ffff88003fc03e28 ffffffffa02f183b 0000000000000000
>> 0000000000000000
>> [ 127.580095] ffff88003fc0d1a0 0000000000000000 0000000000000100
>> ffffffffa02f17d0
>> [ 127.580095] ffff880037baa758 ffffffff81e5c268 ffff88003fc03e78
>> ffffffff8105cc15
>> [ 127.580095] Call Trace:
>> [ 127.580095] <IRQ>
>> [ 127.580095] [<ffffffffa02f183b>]
>> iscsit_handle_dataout_timeout+0x6b/0x250 [iscsi_target_mod]
>> [ 127.580095] [<ffffffffa02f17d0>] ?
>> iscsit_start_dataout_timer+0xa0/0xa0 [iscsi_target_mod]
>> [ 127.580095] [<ffffffff8105cc15>] call_timer_fn+0x45/0x160
>> [ 127.580095] [<ffffffffa02f17d0>] ?
>> iscsit_start_dataout_timer+0xa0/0xa0 [iscsi_target_mod]
>> [ 127.580095] [<ffffffff8105dfa4>] run_timer_softirq+0x244/0x290
>> [ 127.580095] [<ffffffff810bc4e4>] ? clockevents_program_event+0x74/0x100
>> [ 127.580095] [<ffffffff8105591f>] __do_softirq+0xef/0x2e0
>> [ 127.580095] [<ffffffff81055d0e>] irq_exit+0x7e/0xa0
>> [ 127.580095] [<ffffffff816c2cda>] smp_apic_timer_interrupt+0x4a/0x60
>> [ 127.580095] [<ffffffff816c1a8a>] apic_timer_interrupt+0x6a/0x70
>> [ 127.580095] <EOI>
>> [ 127.580095] [<ffffffff8100b830>] ? default_idle+0x20/0xe0
>> [ 127.580095] [<ffffffff8100c02e>] arch_cpu_idle+0x1e/0x30
>> [ 127.580095] [<ffffffff810a8770>] cpu_startup_entry+0xa0/0x260
>> [ 127.580095] [<ffffffff816a3357>] rest_init+0x77/0x80
>> [ 127.580095] [<ffffffff81d05e68>] start_kernel+0x3c9/0x3d6
>> [ 127.580095] [<ffffffff81d0589f>] ? repair_env_string+0x5a/0x5a
>> [ 127.580095] [<ffffffff81d055b2>] x86_64_start_reservations+0x2a/0x2c
>> [ 127.580095] [<ffffffff81d056a4>] x86_64_start_kernel+0xf0/0xf7
>> [ 127.580095] Code: 01 0f b7 73 08 48 c7 c7 e8 df 30 a0 31 c0 41 83 cd
>> ff e8 7d 58 3b e1 eb 9f 66 90 0f 1f 44 00 00 48 8b 87 f8 01 00 00 55 48
>> 89 e5 <48> 8b 40 10 5d 48 2d 20 05 00 00 c3 0f 1f 40 00 0f 1f 44 00 00
>> [ 127.580095] RIP [<ffffffffa02f7c10>]
>> iscsit_tpg_get_node_attrib+0x10/0x20 [iscsi_target_mod]
>> [ 127.580095] RSP <ffff88003fc03dd8>
>> [ 127.857183] ---[ end trace 4185931fc757e117 ]---
>> [ 127.857838] Kernel panic - not syncing: Fatal exception in interrupt
>> [ 127.858779] Kernel Offset: 0x0 from 0xffffffff81000000 (relocation
>> range: 0xffffffff80000000-0xffffffff9fffffff)
>>
>> Thanks,
>> Arshad
>> --
>> 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
>
>
Attachment:
WFS Clone (SCST) 3.png
Description: PNG image
