0

I built an iscsi gateway using ceph-iscsi and set up an iSCSI target and an initiator that can attach to the target.

And as shown in the figure below, I entered the iSCSI Initiator and Target information in the Server's Bios - Network settings.

enter image description here

enter image description here

enter image description here

The iSCSI connection is failing, I have attached some kernel logs from ceph-iscsi.

Among the logs, 'Did not receive response to NOPIN on CID: 1, failing connection for I_T Nexus iqn.2023-07.com.kakao:initiator1111,i,0x349691d2ea8a,iqn.2023-07.com.kakao:target,t,0x0 after message 'Started NOPIN Response Timer on CID: 1 to 5 seconds' after iSCSI connection 1' is output, and after the iSCSI connection is terminated, the iSCSI connection is tried again from the beginning and repeats.

Please advise what is the problem.

# ceph-iscsi kern.log
[507977.797512] iscsi_start_login_thread_timer: Added timeout timer to iSCSI login request for 15 seconds.
[507977.797519] __iscsi_target_login_thread: Moving to TARG_CONN_STATE_XPT_UP.
[507977.797538] rx_data: rx_loop: 48, total_rx: 48, data: 48
[507977.797541] iscsit_get_login_rx: Got Login Command, Flags 0x01, ITT: 0x01000000, CmdSN: 0x01000000, ExpStatSN: 0x00000000, CID: 256, Length: 145
[507977.797548] rx_data: rx_loop: 148, total_rx: 148, data: 148
[507977.797551] __iscsi_target_login_thread: Received iSCSI login request from 192.168.36.100:1029 on iSCSI/TCP Network Portal 192.168.36.5:3260
[507977.797556] __iscsi_target_login_thread: Moving to TARG_CONN_STATE_IN_LOGIN.
[507977.797589] iscsi_target_set_sock_callbacks: Entering iscsi_target_set_sock_callbacks: conn: 000000003f28dd8e
[507977.797596] iscsi_target_locate_portal: Located Storage Object: iqn.2023-07.com.kakao:target
[507977.797600] iscsi_target_locate_portal: Located Portal Group Object: 1
[507977.797798] iscsi_update_param_value: iSCSI Parameter updated to TargetPortalGroupTag=1
[507977.797802] iscsi_update_param_value: iSCSI Parameter updated to ErrorRecoveryLevel=0
[507977.797806] iscsi_decode_text_input: Got key: InitiatorName=iqn.2023-07.com.kakao:initiator1111
[507977.797811] iscsi_update_param_value: iSCSI Parameter updated to InitiatorName=iqn.2023-07.com.kakao:initiator1111
[507977.797814] iscsi_decode_text_input: Got key: SessionType=Normal
[507977.797816] iscsi_update_param_value: iSCSI Parameter updated to SessionType=Normal
[507977.797818] iscsi_decode_text_input: Got key: TargetName=iqn.2023-07.com.kakao:target
[507977.797821] iscsi_update_param_value: iSCSI Parameter updated to TargetName=iqn.2023-07.com.kakao:target
[507977.797823] iscsi_decode_text_input: Got key: AuthMethod=CHAP
[507977.797826] iscsi_update_param_value: iSCSI Parameter updated to AuthMethod=CHAP
[507977.797832] iscsi_encode_text_output: Sending key: AuthMethod=CHAP
[507977.797834] iscsi_encode_text_output: Sending key: TargetAlias=LIO Target
[507977.797836] iscsi_encode_text_output: Sending key: TargetPortalGroupTag=1
[507977.797839] iscsi_target_do_tx_login_io: Sending Login Response, Flags: 0x00, ITT: 0x01000000, ExpCmdSN; 0x00000001, MaxCmdSN: 0x00000001, StatSN: 0xdc4e8515, Length: 62
[507977.797862] tx_data: tx_loop: 112, total_tx: 112, data: 112
[507977.797867] iscsit_alloc_conn: Moving to TARG_CONN_STATE_FREE.
[507980.933577] iscsi_target_sk_data_ready: Entering iscsi_target_sk_data_ready: conn: 000000003f28dd8e
[507980.933620] iscsi_target_do_login_rx: entering iscsi_target_do_login_rx, conn: 000000003f28dd8e, kworker/151:1:1427
[507980.933631] iscsi_target_do_login_rx: Starting login timer for kworker/151:1/1427
[507980.933642] rx_data: rx_loop: 48, total_rx: 48, data: 48
[507980.933646] iscsit_get_login_rx: Got Login Command, Flags 0x01, ITT: 0x01000000, CmdSN: 0x01000000, ExpStatSN: 0x16854edc, CID: 256, Length: 9
[507980.933657] rx_data: rx_loop: 12, total_rx: 12, data: 12
[507980.933661] iscsi_target_do_login_rx: iscsi_target_do_login_rx after rx_login_io, 000000003f28dd8e, kworker/151:1:1427
[507980.933670] iscsi_decode_text_input: Got key: CHAP_A=5
[507980.933683] chap_check_algorithm: Selected md5 Algorithm
[507980.933702] chap_server_open: [server] Got CHAP_A=5
[507980.933704] chap_server_open: [server] Sending CHAP_A=5
[507980.933708] chap_server_open: [server] Sending CHAP_I=3
[507980.933711] chap_gen_challenge: [server] Sending CHAP_C=0xbd0bba967bf1a1b22b327130aa3494ee
[507980.933711]
[507980.933715] iscsi_target_do_authentication: Received OK response from LIO Authentication, continuing.
[507980.933718] iscsi_target_do_tx_login_io: Sending Login Response, Flags: 0x00, ITT: 0x01000000, ExpCmdSN; 0x00000001, MaxCmdSN: 0x00000001, StatSN: 0xdc4e8516, Length: 60
[507980.933759] tx_data: tx_loop: 108, total_tx: 108, data: 108
[507999.109620] iscsi_target_sk_data_ready: Entering iscsi_target_sk_data_ready: conn: 000000003f28dd8e
[507999.109666] iscsi_target_do_login_rx: entering iscsi_target_do_login_rx, conn: 000000003f28dd8e, kworker/151:1:1427
[507999.109673] iscsi_target_do_login_rx: Starting login timer for kworker/151:1/1427
[507999.109682] rx_data: rx_loop: 48, total_rx: 48, data: 48
[507999.109687] iscsit_get_login_rx: Got Login Command, Flags 0x81, ITT: 0x01000000, CmdSN: 0x01000000, ExpStatSN: 0x17854edc, CID: 256, Length: 58
[507999.109699] rx_data: rx_loop: 60, total_rx: 60, data: 60
[507999.109703] iscsi_target_do_login_rx: iscsi_target_do_login_rx after rx_login_io, 000000003f28dd8e, kworker/151:1:1427
[507999.109712] iscsi_decode_text_input: Got key: CHAP_N=lucian86
[507999.109729] chap_server_compute_hash: [server] Got CHAP_N=lucian86
[507999.109733] chap_server_compute_hash: [server] Got CHAP_R=06E3CD958548DF9BBD60741BEAC61020
[507999.109751] chap_server_compute_hash: [server] md5 Server Digest: 06e3cd958548df9bbd60741beac61020
[507999.109755] chap_server_compute_hash: [server] md5 Digests match, CHAP connection successful.
[507999.109755]
[507999.109759] iscsi_target_do_authentication: iSCSI security negotiation completed successfully.
[507999.109770] iscsi_target_do_tx_login_io: Sending Login Response, Flags: 0x81, ITT: 0x01000000, ExpCmdSN; 0x00000001, MaxCmdSN: 0x00000001, StatSN: 0xdc4e8517, Length: 0
[507999.109788] tx_data: tx_loop: 48, total_tx: 48, data: 48
[508072.581782] iscsi_target_sk_data_ready: Entering iscsi_target_sk_data_ready: conn: 000000003f28dd8e
[508072.581839] iscsi_target_do_login_rx: entering iscsi_target_do_login_rx, conn: 000000003f28dd8e, kworker/151:1:1427
[508072.581848] iscsi_target_do_login_rx: Starting login timer for kworker/151:1/1427
[508072.581859] rx_data: rx_loop: 48, total_rx: 48, data: 48
[508072.581865] iscsit_get_login_rx: Got Login Command, Flags 0x87, ITT: 0x01000000, CmdSN: 0x01000000, ExpStatSN: 0x18854edc, CID: 256, Length: 284
[508072.581876] rx_data: rx_loop: 284, total_rx: 284, data: 284
[508072.581879] iscsi_target_do_login_rx: iscsi_target_do_login_rx after rx_login_io, 000000003f28dd8e, kworker/151:1:1427
[508072.581887] iscsi_decode_text_input: Got key: HeaderDigest=None
[508072.581896] iscsi_update_param_value: iSCSI Parameter updated to HeaderDigest=None
[508072.581899] iscsi_decode_text_input: Got key: DataDigest=None
[508072.581902] iscsi_update_param_value: iSCSI Parameter updated to DataDigest=None
[508072.581904] iscsi_decode_text_input: Got key: ErrorRecoveryLevel=0
[508072.581916] iscsi_update_param_value: iSCSI Parameter updated to ErrorRecoveryLevel=0
[508072.581919] iscsi_decode_text_input: Got key: InitialR2T=No
[508072.581921] iscsi_update_param_value: iSCSI Parameter updated to InitialR2T=Yes
[508072.581923] iscsi_decode_text_input: Got key: ImmediateData=Yes
[508072.581926] iscsi_decode_text_input: Got key: MaxRecvDataSegmentLength=65536
[508072.581930] iscsi_update_param_value: iSCSI Parameter updated to MaxRecvDataSegmentLength=65536
[508072.581935] iscsi_check_acceptor_state: Saving op->MaxRecvDataSegmentLength from original initiator received value: 65536
[508072.581938] iscsi_update_param_value: iSCSI Parameter updated to MaxRecvDataSegmentLength=262144
[508072.581941] iscsi_check_acceptor_state: Updated MaxRecvDataSegmentLength to target MXDSL value: 262144
[508072.581943] iscsi_decode_text_input: Got key: MaxBurstLength=262144
[508072.581947] iscsi_update_param_value: iSCSI Parameter updated to MaxBurstLength=262144
[508072.581949] iscsi_decode_text_input: Got key: FirstBurstLength=65536
[508072.581952] iscsi_update_param_value: iSCSI Parameter updated to FirstBurstLength=65536
[508072.581953] iscsi_decode_text_input: Got key: MaxConnections=1
[508072.581956] iscsi_update_param_value: iSCSI Parameter updated to MaxConnections=1
[508072.581958] iscsi_decode_text_input: Got key: DataPDUInOrder=Yes
[508072.581961] iscsi_update_param_value: iSCSI Parameter updated to DataPDUInOrder=Yes
[508072.581963] iscsi_decode_text_input: Got key: DataSequenceInOrder=Yes
[508072.581965] iscsi_update_param_value: iSCSI Parameter updated to DataSequenceInOrder=Yes
[508072.581967] iscsi_decode_text_input: Got key: DefaultTime2Wait=2
[508072.581970] iscsi_update_param_value: iSCSI Parameter updated to DefaultTime2Wait=2
[508072.581972] iscsi_decode_text_input: Got key: DefaultTime2Retain=20
[508072.581975] iscsi_update_param_value: iSCSI Parameter updated to DefaultTime2Retain=20
[508072.581976] iscsi_decode_text_input: Got key: MaxOutstandingR2T=1
[508072.581979] iscsi_update_param_value: iSCSI Parameter updated to MaxOutstandingR2T=1
[508072.581989] iscsi_encode_text_output: Sending key: HeaderDigest=None
[508072.581990] iscsi_encode_text_output: Sending key: DataDigest=None
[508072.581992] iscsi_encode_text_output: Sending key: MaxConnections=1
[508072.581994] iscsi_encode_text_output: Sending key: InitialR2T=Yes
[508072.581996] iscsi_encode_text_output: Sending key: ImmediateData=Yes
[508072.581998] iscsi_encode_text_output: Sending key: MaxRecvDataSegmentLength=262144
[508072.582000] iscsi_encode_text_output: Sending key: MaxBurstLength=262144
[508072.582001] iscsi_encode_text_output: Sending key: FirstBurstLength=65536
[508072.582004] iscsi_encode_text_output: Sending key: DefaultTime2Wait=2
[508072.582006] iscsi_encode_text_output: Sending key: DefaultTime2Retain=20
[508072.582008] iscsi_encode_text_output: Sending key: MaxOutstandingR2T=1
[508072.582010] iscsi_encode_text_output: Sending key: ErrorRecoveryLevel=0
[508072.582013] iscsi_target_restore_sock_callbacks: Entering iscsi_target_restore_sock_callbacks: conn: 000000003f28dd8e
[508072.582017] iscsi_target_do_tx_login_io: Sending Login Response, Flags: 0x87, ITT: 0x01000000, ExpCmdSN; 0x00000001, MaxCmdSN: 0x00000001, StatSN: 0xdc4e8518, Length: 243
[508072.582260] tx_data: tx_loop: 292, total_tx: 292, data: 292
[508072.582267] iscsi_post_login_handler: Moving to TARG_CONN_STATE_LOGGED_IN.
[508072.582269] iscsi_set_connection_parameters: ------------------------------------------------------------------
[508072.582271] iscsi_set_connection_parameters: AuthMethod:                   CHAP
[508072.582274] iscsi_set_connection_parameters: HeaderDigest:                 None
[508072.582276] iscsi_set_connection_parameters: DataDigest:                   None
[508072.582279] iscsi_set_connection_parameters: MaxXmitDataSegmentLength:     262144
[508072.582282] iscsi_set_connection_parameters: MaxRecvDataSegmentLength:     65536
[508072.582286] iscsi_set_connection_parameters: ------------------------------------------------------------------
[508072.582288] iscsi_set_session_parameters: ------------------------------------------------------------------
[508072.582292] iscsi_set_session_parameters: MaxConnections:               1
[508072.582294] iscsi_set_session_parameters: TargetName:                   iqn.2023-07.com.kakao:target
[508072.582297] iscsi_set_session_parameters: InitiatorName:                iqn.2023-07.com.kakao:initiator1111
[508072.582300] iscsi_set_session_parameters: TargetAlias:                  LIO Target
[508072.582301] iscsi_set_session_parameters: TargetPortalGroupTag:         1
[508072.582304] iscsi_set_session_parameters: InitialR2T:                   Yes
[508072.582305] iscsi_set_session_parameters: ImmediateData:                Yes
[508072.582308] iscsi_set_session_parameters: MaxBurstLength:               262144
[508072.582311] iscsi_set_session_parameters: FirstBurstLength:             65536
[508072.582314] iscsi_set_session_parameters: DefaultTime2Wait:             2
[508072.582316] iscsi_set_session_parameters: DefaultTime2Retain:           20
[508072.582317] iscsi_set_session_parameters: MaxOutstandingR2T:            1
[508072.582319] iscsi_set_session_parameters: DataPDUInOrder:               Yes
[508072.582321] iscsi_set_session_parameters: DataSequenceInOrder:          Yes
[508072.582322] iscsi_set_session_parameters: ErrorRecoveryLevel:           0
[508072.582325] iscsi_set_session_parameters: SessionType:                  Normal
[508072.582326] iscsi_set_session_parameters: ------------------------------------------------------------------
[508072.582338] iscsi_post_login_handler: Moving to TARG_SESS_STATE_LOGGED_IN.
[508072.582340] iscsi_post_login_handler: iSCSI Login successful on CID: 1 from 192.168.36.100:1029 to 192.168.36.5:3260,1
[508072.582345] iscsi_post_login_handler: Incremented iSCSI Connection count to 1 from node: iqn.2023-07.com.kakao:initiator1111
[508072.582347] iscsi_post_login_handler: Established iSCSI session from node: iqn.2023-07.com.kakao:initiator1111
[508072.582349] iscsi_post_login_handler: Incremented number of active iSCSI sessions to 1 on iSCSI Target Portal Group: 1
[508072.582354] __iscsit_start_nopin_timer: Started NOPIN Timer on CID: 1 at 5 second interval
[508077.701623] iscsit_start_nopin_response_timer: Started NOPIN Response Timer on CID: 1 to 5 seconds
[508077.701659] iscsit_build_nopin_rsp: Built NOPIN Unsolicited Response ITT: 0xffffffff, TTT: 0x00000000, StatSN: 0xdc4e8519, Length 0
[508077.701671] iscsit_send_unsolicited_nopin: Sending Unsolicited NOPIN TTT: 0x00000000 StatSN: 0xdc4e8519 CID: 1
[508077.701710] tx_data: tx_loop: 48, total_tx: 48, data: 48
[508082.821626] Did not receive response to NOPIN on CID: 1, failing connection for I_T Nexus iqn.2023-07.com.kakao:initiator1111,i,0x349691d2ea8a,iqn.2023-07.com.kakao:target,t,0x01
[508082.840602] rx_data: rx_loop: -512 total_rx: 0
[508082.840612] iscsit_take_action_for_connection_exit: Moving to TARG_CONN_STATE_CLEANUP_WAIT.
[508082.840617] iscsit_handle_connection_cleanup: Performing cleanup for failed iSCSI Connection ID: 1 from iqn.2023-07.com.kakao:initiator1111
[508082.840624] iscsit_close_connection: Closing iSCSI connection CID 1 on SID: 4
[508082.840661] iscsit_increment_maxcmdsn: Updated MaxCmdSN to 0x00000081
[508082.840715] iscsit_close_connection: Moving to TARG_CONN_STATE_FREE.
[508082.840719] iscsit_close_connection: Decremented iSCSI connection count to 0 from node: iqn.2023-07.com.kakao:initiator1111
[508082.840743] iscsit_close_session: Moving to TARG_SESS_STATE_FREE.
[508082.840745] iscsit_close_session: Released iSCSI session from node: iqn.2023-07.com.kakao:initiator1111
[508082.840747] iscsit_close_session: Decremented number of active iSCSI Sessions on iSCSI TPG: 1 to 0

It works well to attach iscsi using open-iscsi without using Bios - Network.

As advised by @Mike Andrews, I set NOPIN_TIMEOUT to 0, and the 'Did not receive response to NOPIN on CID: 1, failing connection for I_T Nexus...' message went away!

Thanks @Mike Andrews

However, if tx is sent as shown below and rx does not come for 120 seconds, it is terminated. Any advice on this?

        ...
        [558929.675224] iscsi_target_restore_sock_callbacks: Entering iscsi_target_restore_sock_callbacks: conn: 00000000dd3dace4
        [558929.675226] iscsi_target_do_tx_login_io: Sending Login Response, Flags: 0x87, ITT: 0x01000000, ExpCmdSN; 0x00000001, MaxCmdSN: 0x00000001, StatSN: 0xd2907d03, Length: 243
        [558929.675449] tx_data: tx_loop: 292, total_tx: 292, data: 292
        [558929.675453] iscsi_post_login_handler: Moving to TARG_CONN_STATE_LOGGED_IN.
        [558929.675456] iscsi_set_connection_parameters: ------------------------------------------------------------------
        [558929.675459] iscsi_set_connection_parameters: AuthMethod:                   CHAP
        [558929.675460] iscsi_set_connection_parameters: HeaderDigest:                 None
        [558929.675462] iscsi_set_connection_parameters: DataDigest:                   None
        [558929.675465] iscsi_set_connection_parameters: MaxXmitDataSegmentLength:     262144
        [558929.675467] iscsi_set_connection_parameters: MaxRecvDataSegmentLength:     65536
        [558929.675471] iscsi_set_connection_parameters: ------------------------------------------------------------------
        [558929.675472] iscsi_set_session_parameters: ------------------------------------------------------------------
        [558929.675475] iscsi_set_session_parameters: MaxConnections:               1
        [558929.675478] iscsi_set_session_parameters: TargetName:                   iqn.2023-07.com.kakao:target
        [558929.675481] iscsi_set_session_parameters: InitiatorName:                iqn.2023-07.com.kakao:initiator1111
        [558929.675483] iscsi_set_session_parameters: TargetAlias:                  LIO Target
        [558929.675485] iscsi_set_session_parameters: TargetPortalGroupTag:         1
        [558929.675487] iscsi_set_session_parameters: InitialR2T:                   Yes
        [558929.675489] iscsi_set_session_parameters: ImmediateData:                Yes
        [558929.675491] iscsi_set_session_parameters: MaxBurstLength:               262144
        [558929.675493] iscsi_set_session_parameters: FirstBurstLength:             65536
        [558929.675495] iscsi_set_session_parameters: DefaultTime2Wait:             2
        [558929.675497] iscsi_set_session_parameters: DefaultTime2Retain:           20
        [558929.675499] iscsi_set_session_parameters: MaxOutstandingR2T:            1
        [558929.675501] iscsi_set_session_parameters: DataPDUInOrder:               Yes
        [558929.675502] iscsi_set_session_parameters: DataSequenceInOrder:          Yes
        [558929.675504] iscsi_set_session_parameters: ErrorRecoveryLevel:           0
        [558929.675506] iscsi_set_session_parameters: SessionType:                  Normal
        [558929.675508] iscsi_set_session_parameters: ------------------------------------------------------------------
        [558929.675515] iscsi_post_login_handler: Moving to TARG_SESS_STATE_LOGGED_IN.
        [558929.675516] iscsi_post_login_handler: iSCSI Login successful on CID: 2 from 192.168.36.100:1151 to 192.168.36.5:3260,1
        [558929.675521] iscsi_post_login_handler: Incremented iSCSI Connection count to 1 from node: iqn.2023-07.com.kakao:initiator1111
        [558929.675522] iscsi_post_login_handler: Established iSCSI session from node: iqn.2023-07.com.kakao:initiator1111
        [558929.675524] iscsi_post_login_handler: Incremented number of active iSCSI sessions to 1 on iSCSI Target Portal Group: 1
        [558929.675652] rx_data: rx_loop: 48, total_rx: 48, data: 48
        [558929.675670] iscsit_setup_scsi_cmd: Got SCSI Command, ITT: 0x01000000, CmdSN: 0x01000000, ExpXferLen: 512, Length: 0, CID: 2
        [558929.675680] iscsit_check_received_cmdsn: Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000002
        [558929.676364] iscsit_increment_maxcmdsn: Updated MaxCmdSN to 0x00000081
        [558929.676377] iscsit_build_datain_pdu: Built DataIN ITT: 0x01000000, StatSN: 0xd2907d04, DataSN: 0x00000000, Offset: 0, Length: 512, CID: 2
        [558929.676439] tx_data: tx_loop: 48, total_tx: 48, data: 48
        [558929.882533] rx_data: rx_loop: 48, total_rx: 48, data: 48
        [558929.882546] iscsit_setup_scsi_cmd: Got SCSI Command, ITT: 0x02000000, CmdSN: 0x02000000, ExpXferLen: 16384, Length: 0, CID: 2
        [558929.882552] iscsit_check_received_cmdsn: Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000003
        [558929.882574] lio_release_cmd: Entering lio_release_cmd for se_cmd: 00000000324266a7
        [558929.883429] iscsit_increment_maxcmdsn: Updated MaxCmdSN to 0x00000082
        [558929.883432] iscsit_build_datain_pdu: Built DataIN ITT: 0x02000000, StatSN: 0xd2907d05, DataSN: 0x00000000, Offset: 0, Length: 16384, CID: 2
        [558929.883482] tx_data: tx_loop: 48, total_tx: 48, data: 48
        [558942.986774] rx_data: rx_loop: 48, total_rx: 48, data: 48
        [558942.986792] iscsit_setup_scsi_cmd: Got SCSI Command, ITT: 0x03000000, CmdSN: 0x03000000, ExpXferLen: 16384, Length: 0, CID: 2
        [558942.986800] iscsit_check_received_cmdsn: Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000004
        [558942.986828] lio_release_cmd: Entering lio_release_cmd for se_cmd: 00000000d821126d
        [558943.194949] iscsit_increment_maxcmdsn: Updated MaxCmdSN to 0x00000083
        [558943.194953] iscsit_build_datain_pdu: Built DataIN ITT: 0x03000000, StatSN: 0xd2907d06, DataSN: 0x00000000, Offset: 0, Length: 16384, CID: 2
        [558943.195002] tx_data: tx_loop: 48, total_tx: 48, data: 48
        [558956.558319] rx_data: rx_loop: 48, total_rx: 48, data: 48
        [558956.558335] iscsit_setup_scsi_cmd: Got SCSI Command, ITT: 0x04000000, CmdSN: 0x04000000, ExpXferLen: 512, Length: 0, CID: 2
        [558956.558343] iscsit_check_received_cmdsn: Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000005
        [558956.558372] lio_release_cmd: Entering lio_release_cmd for se_cmd: 00000000728b221d
        [558958.411518] iscsit_increment_maxcmdsn: Updated MaxCmdSN to 0x00000084
        [558958.411529] iscsit_build_datain_pdu: Built DataIN ITT: 0x04000000, StatSN: 0xd2907d07, DataSN: 0x00000000, Offset: 0, Length: 512, CID: 2
        [558958.411585] tx_data: tx_loop: 48, total_tx: 48, data: 48
        [558998.282819] rx_data: rx_loop: 48, total_rx: 48, data: 48
        [558998.282838] iscsit_setup_scsi_cmd: Got SCSI Command, ITT: 0x05000000, CmdSN: 0x05000000, ExpXferLen: 512, Length: 0, CID: 2
        [558998.282845] iscsit_check_received_cmdsn: Received CmdSN matches ExpCmdSN, incremented ExpCmdSN to: 0x00000006
        [558998.282872] lio_release_cmd: Entering lio_release_cmd for se_cmd: 00000000677c3747
        [558998.490952] iscsit_increment_maxcmdsn: Updated MaxCmdSN to 0x00000085
        [558998.490955] iscsit_build_datain_pdu: Built DataIN ITT: 0x05000000, StatSN: 0xd2907d08, DataSN: 0x00000000, Offset: 0, Length: 512, CID: 2
        [558998.490985] tx_data: tx_loop: 48, total_tx: 48, data: 48



        [559122.279650] rx_data: rx_loop: -104 total_rx: 0
        [559124.299046] iscsit_take_action_for_connection_exit: Moving to TARG_CONN_STATE_CLEANUP_WAIT.
        [559124.299057] iscsit_handle_connection_cleanup: Performing cleanup for failed iSCSI Connection ID: 2 from iqn.2023-07.com.kakao:initiator1111
        [559124.299061] iscsit_close_connection: Closing iSCSI connection CID 2 on SID: 9
        [559124.299146] lio_release_cmd: Entering lio_release_cmd for se_cmd: 00000000e102a5f8
        [559124.299183] iscsit_close_connection: Moving to TARG_CONN_STATE_FREE.
        [559124.299187] iscsit_close_connection: Decremented iSCSI connection count to 0 from node: iqn.2023-07.com.kakao:initiator1111
        [559124.299209] iscsit_close_session: Moving to TARG_SESS_STATE_FREE.
        [559124.299211] iscsit_close_session: Released iSCSI session from node: iqn.2023-07.com.kakao:initiator1111
        [559124.299213] iscsit_close_session: Decremented number of active iSCSI Sessions on iSCSI TPG: 1 to 0
        [559153.291127] iscsi_start_login_thread_timer: Added timeout timer to iSCSI login request for 15 seconds.
        [559153.291138] __iscsi_target_login_thread: Moving to TARG_CONN_STATE_XPT_UP.
        [559153.291148] rx_data: rx_loop: 48, total_rx: 48, data: 48
        [559153.291153] iscsit_get_login_rx: Got Login Command, Flags 0x01, ITT: 0x01000000, CmdSN: 0x01000000, ExpStatSN: 0x00000000, CID: 1024, Length: 145
        [559153.291160] rx_data: rx_loop: 148, total_rx: 148, data: 148
        [559153.291163] __iscsi_target_login_thread: Received iSCSI login request from 192.168.36.100:1155 on iSCSI/TCP Network Portal 192.168.36.5:3260
        [559153.291167] __iscsi_target_login_thread: Moving to TARG_CONN_STATE_IN_LOGIN.
        [559153.291197] iscsi_target_set_sock_callbacks: Entering iscsi_target_set_sock_callbacks: conn: 000000004edc1cbe

        < repeated >
lucian lee
  • 3
  • 2

1 Answers1

0

The Linux LIO iSCSI target probes the initiator's responsiveness by sending an unsolicited NOP-IP PDU back to the initiator and expecting a response. When it doesn't receive one in 5 seconds, it closes the connection. This is kind of a backwards protocol interaction that can be tricky to handle. It's famous for tripping up lightweight iSCSI initiators.

If you look on iPXE's iSCSI Targets Known to Work with iPXE page, you'll see how to disable this behavior. (I don't know that your Dell is running an iPXE initiator, but this is a good reference.) This command turns it off entirely:

  lio_node --setnodeattr <TARGET_IQN> <TPGT> <INITIATOR_IQN> nopin_timeout 0

In the Linux kernel, you can see where setting this to 0 short-circuits the process of starting the timer. You shouldn't see the "Started NOPIN Timer..." debug message any longer:

void __iscsit_start_nopin_timer(struct iscsit_conn *conn)
{
    struct iscsit_session *sess = conn->sess;
    struct iscsi_node_attrib *na = iscsit_tpg_get_node_attrib(sess);

    lockdep_assert_held(&conn->nopin_timer_lock);

    /*
    * NOPIN timeout is disabled.
     */
    if (!na->nopin_timeout)
        return;

    if (conn->nopin_timer_flags & ISCSI_TF_RUNNING)
        return;

    conn->nopin_timer_flags &= ~ISCSI_TF_STOP;
    conn->nopin_timer_flags |= ISCSI_TF_RUNNING;
    mod_timer(&conn->nopin_timer, jiffies + na->nopin_timeout * HZ);

    pr_debug("Started NOPIN Timer on CID: %d at %u second"
        " interval\n", conn->cid, na->nopin_timeout);
}
Mike Andrews
  • 3,045
  • 18
  • 28
  • Thanks for the quick reply! After setting nopin_timeout to 0, if there is no response for 120 seconds, it tries to connect again after 'Closing'. Can you also advise on this? The log for additional questions is written below the text. – lucian lee Jul 25 '23 at 01:58