[Stgt-devel] dd fails with iSER

[Pete Wyckoff]

erezz at voltaire.com wrote on Tue, 14 Aug 2007 17:04 +0300:
> I went over the iSER target code, and something looks strange (unless
> I'm missing something here):
> 
> iscsi_iser_read calls iser_parse_hdr, which reads the iSER header and
> saves the remote va & stag on the conn_info object. Later,
> iser_rdma_read/write is called (from another context?), and uses the
> remote va & stag. The problem that I see is: what happens if another cmd
> is received before RDMA read/write is performed for the 1st cmd?
> 
> I can see that on the log file:
> 
> The last 3 cmds that were received have stags 6004a, 6004b & 6004c
> respectively.
> 
> [iSER]:iSCSI control type PDU.
> [iSER]:rem_write_stag 6004a rem_write_va 69cea000.
> [iSER]:iscsi_iser_read ret 48.
> tgtd: iscsi_scsi_cmd_rx_start(1462) 1 2a 0 8192 131072 1 42
> [iSER]:meml 0x634d88 buf 0x2aaaaad30010.
> tgtd: iscsi_scsi_cmd_rx_start(1489) 0 122880 0 8192
> [iSER]:in iscsi_iser_read buf 0x2aaaaad302b0 nbytes 8192.
> [iSER]:iscsi_iser_read ret 8192.
> tgtd: iscsi_task_queue(1403) 42 42 1
> tgtd: iser_event_modify(1435) ep 0 events 5
> tgtd: iser_event_modify(1442) ep 0 was already on the list.  Track?
> [iSER]:handle_wc() Done processing recv 0x642228, reposted it.
> [iSER]:handle_wc() Incoming Cmd - COMPLETE (8268 bytes).
> [iSER]:in iscsi_iser_read buf 0x636eb0 nbytes 48.
> [iSER]:iSCSI control type PDU.
> [iSER]:rem_write_stag 6004b rem_write_va 6a74a000.
> [iSER]:iscsi_iser_read ret 48.
> tgtd: iscsi_scsi_cmd_rx_start(1462) 1 2a 0 8192 131072 1 43
> [iSER]:meml 0x634da0 buf 0x2aaaaadb1010.
> tgtd: iscsi_scsi_cmd_rx_start(1489) 0 122880 0 8192
> [iSER]:in iscsi_iser_read buf 0x2aaaaadb12b0 nbytes 8192.
> [iSER]:iscsi_iser_read ret 8192.
> tgtd: iscsi_task_queue(1403) 43 43 1
> tgtd: iser_event_modify(1435) ep 0 events 5
> tgtd: iser_event_modify(1442) ep 0 was already on the list.  Track?
> [iSER]:handle_wc() Done processing recv 0x6432f8, reposted it.
> [iSER]:handle_wc() Incoming Cmd - COMPLETE (8268 bytes).
> [iSER]:in iscsi_iser_read buf 0x636eb0 nbytes 48.
> [iSER]:iSCSI control type PDU.
> [iSER]:rem_write_stag 6004c rem_write_va 6a18a000.
> [iSER]:iscsi_iser_read ret 48.
> 
> Later, RDMA read is performed for the cmds. For all cmds, the stag is
> 6004c - just like the last stag that was received:
> 
> [iSER]:in iser_rdma_read.
> [iSER]:in iser_post_rdma_wr size 122880 rem_va 6a18a000 rem_stag 6004c
> wr_id = 0x63f010 (itt = 0x3d)
> .
> [iSER]:iser_post_rdma_wr() Exit rdma = 0x63f010.
> tgtd: iser_progress(1382) trying tx on fd 0 conn 0x636d90
> tgtd: iscsi_task_tx_start(1750) found a task 3e 131072 8192 122880
> [iSER]:in iser_rdma_read.
> [iSER]:in iser_post_rdma_wr size 122880 rem_va 6a1a8000 rem_stag 6004c
> wr_id = 0x63f090 (itt = 0x3e)
> .
> [iSER]:iser_post_rdma_wr() Exit rdma = 0x63f090.
> tgtd: iser_progress(1382) trying tx on fd 0 conn 0x636d90
> tgtd: iscsi_task_tx_start(1750) found a task 3f 131072 8192 122880
> [iSER]:in iser_rdma_read.
> [iSER]:in iser_post_rdma_wr size 122880 rem_va 6a1c6000 rem_stag 6004c
> wr_id = 0x63f110 (itt = 0x3f)

You're absolutely right.  That's a pretty glaring problem and
there's even a TODO in struct conn_info that notices there is an
issue.  With the OSD initiator applications we use, multiple
commands are not in flight.

Probably what has to happen is to move the per-task stag and va
fields from conn_info into iscsi_task.  You are certainly welcome to
hack on the code yourself, or somebody here will take a look at it
if you don't find the time.

Thanks for taking the time to figure out this bug.

		-- Pete