[Stgt-devel] dd fails with iSER

[Erez Zilber]

Pete Wyckoff wrote:

> erezz at voltaire.com wrote on Sun, 12 Aug 2007 17:03 +0300:
>   
>> I ran the following command:
>>
>> sgp_dd bs=512 of=/dev/null if=/dev/sg3 bpt=256 thr=8 time=1 count=8000
>>
>> and got the following error:
>>     
>
> I'm on travel this week, but want to fix this!  Everything works
> here unfortunately.  WC status 10 == IBV_WC_REM_ACCESS_ERR, which
> means that the other side was somehow unhappy.  Maybe wrong rkey.
> We've never seen that error, even in testing, so I will probably ask
> you for more debugging information on both sides.
>
> If you are motivated, you might check the key and VA that appears
> in the initiator request and make sure the target tries to use those
> same values when it does RDMA.
>   

Pete,

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)

Erez