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 |