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().
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
--
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
