Re: Deconnection Problem with netapp
In the log below it seems that we just do not get any IO for 5 secs, so the initiator sends a nop as a ping. We do not get a response for 5 secs. So the initiator is just not seeing any data get through. Is the network trace you sent for the same test run as the log snippet is for? Is it possible that the nop-out/ping that times out is the one in packet 361? In there we also see that READ not get completed correctly. If the initiator is not causing the RST in packet 345, and if we are missing a kernel network event we might be sending the nop/ping that times out after the RST and we see the log or something like it below. I made this kernel: http://people.redhat.com/mchristi/kernel-2.6.18-274.el5.iscsidebug1.i686.rpm http://people.redhat.com/mchristi/kernel-PAE-2.6.18-274.el5.iscsidebug1.i686.rpm http://people.redhat.com/mchristi/kernel-2.6.18-274.el5.iscsidebug1.x86_64.rpm It is the rhel 5.7 kernel with some extra debugging output in the function that handles state changes for the socket and in the iscsi eh code. It could tell us if we are mishandling a event vs we are causing the RST. It will not tell us what is initiating the RST if it is not us, but it will hopefully tell us if the iscsi layer is or if it possibly something else in the kernel. Just run it like normal. You do not need any debugging on. On 11/21/2011 08:46 AM, Amaury FRANCOIS wrote: Hi, here is the output of /var/log/messages : Nov 21 10:32:21 bdd4a kernel: session1: iscsi_free_task freeing task itt 0xb state 1 sc Nov 21 10:32:21 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790025113 Nov 21 10:32:25 bdd4a kernel: connection2:0: iscsi_check_transport_timeouts Sending nopout as ping Nov 21 10:32:25 bdd4a kernel: connection2:0: iscsi_check_transport_timeouts Setting next tmo 4790029108 Nov 21 10:32:25 bdd4a kernel: session2: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr-itt 0x301d datalen 0] Nov 21 10:32:26 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Sending nopout as ping Nov 21 10:32:26 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790030113 Nov 21 10:32:26 bdd4a kernel: session1: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr-itt 0x1009 datalen 0] Nov 21 10:32:26 bdd4a kernel: session1: __iscsi2_complete_pdu [op 0x20 cid 0 itt 0x9 len 0] Nov 21 10:32:26 bdd4a kernel: session1: iscsi_complete_task complete task itt 0x9 state 3 sc Nov 21 10:32:26 bdd4a kernel: session1: iscsi_free_task freeing task itt 0x9 state 1 sc Nov 21 10:32:26 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790030113 Nov 21 10:32:30 bdd4a kernel: connection2:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4790019108, last ping 4790024108, now 4790029108 Nov 21 10:32:30 bdd4a kernel: connection2:0: detected conn error (1011) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:30 bdd4a last message repeated 2287 times Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queueued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuecomued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queueued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_qued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_qued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuued (7) . And so on . Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_ued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsiued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_quued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecon2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:31 bdd4a last message repeated 7702 times Nov 21 10:32:31 bdd4a kernel: session2: iscsi_start_session_recovery blocking session Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:31 bdd4a kernel: session2: fail_mgmt_tasks failing mgmt itt 0x1d state 3 Nov 21 10:32:31 bdd4a kernel: session2: iscsi_complete_task complete task itt 0x1d state 3 sc Nov 21 10:32:31 bdd4a kernel: session2: iscsi_free_task freeing task itt 0x1d state 5 sc Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (786432) Nov 21 10:32:31 bdd4a
Re: Deconnection Problem with netapp
Hi, here is the output of /var/log/messages : Nov 21 10:32:21 bdd4a kernel: session1: iscsi_free_task freeing task itt 0xb state 1 sc Nov 21 10:32:21 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790025113 Nov 21 10:32:25 bdd4a kernel: connection2:0: iscsi_check_transport_timeouts Sending nopout as ping Nov 21 10:32:25 bdd4a kernel: connection2:0: iscsi_check_transport_timeouts Setting next tmo 4790029108 Nov 21 10:32:25 bdd4a kernel: session2: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr-itt 0x301d datalen 0] Nov 21 10:32:26 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Sending nopout as ping Nov 21 10:32:26 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790030113 Nov 21 10:32:26 bdd4a kernel: session1: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr-itt 0x1009 datalen 0] Nov 21 10:32:26 bdd4a kernel: session1: __iscsi2_complete_pdu [op 0x20 cid 0 itt 0x9 len 0] Nov 21 10:32:26 bdd4a kernel: session1: iscsi_complete_task complete task itt 0x9 state 3 sc Nov 21 10:32:26 bdd4a kernel: session1: iscsi_free_task freeing task itt 0x9 state 1 sc Nov 21 10:32:26 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790030113 Nov 21 10:32:30 bdd4a kernel: connection2:0: ping timeout of 5 secs expired, recv timeout 5, last rx 4790019108, last ping 4790024108, now 4790029108 Nov 21 10:32:30 bdd4a kernel: connection2:0: detected conn error (1011) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:30 bdd4a last message repeated 2287 times Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queueued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuecomued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queueued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_qued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_qued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queued (7) Nov 21 10:32:30 bdd4a kernel: session2: iscsi2_queuued (7) . And so on . Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_ued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsiued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_quued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecon2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:31 bdd4a last message repeated 7702 times Nov 21 10:32:31 bdd4a kernel: session2: iscsi_start_session_recovery blocking session Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (7) Nov 21 10:32:31 bdd4a kernel: session2: fail_mgmt_tasks failing mgmt itt 0x1d state 3 Nov 21 10:32:31 bdd4a kernel: session2: iscsi_complete_task complete task itt 0x1d state 3 sc Nov 21 10:32:31 bdd4a kernel: session2: iscsi_free_task freeing task itt 0x1d state 5 sc Nov 21 10:32:31 bdd4a kernel: session2: iscsi2_queuecommand iscsi: cmd 0x28 is not queued (786432) Nov 21 10:32:31 bdd4a iscsid: Kernel reported iSCSI connection 2:0 error (1011) state (3) Nov 21 10:32:31 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Sending nopout as ping Nov 21 10:32:31 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790035113 Nov 21 10:32:31 bdd4a kernel: session1: iscsi_prep_mgmt_task mgmtpdu [op 0x0 hdr-itt 0x100c datalen 0] Nov 21 10:32:31 bdd4a kernel: session1: __iscsi2_complete_pdu [op 0x20 cid 0 itt 0xc len 0] Nov 21 10:32:31 bdd4a kernel: session1: iscsi_complete_task complete task itt 0xc state 3 sc Nov 21 10:32:31 bdd4a kernel: session1: iscsi_free_task freeing task itt 0xc state 1 sc Nov 21 10:32:31 bdd4a kernel: connection1:0: iscsi_check_transport_timeouts Setting next tmo 4790035113 Nov 21 10:32:32 bdd4a kernel: session1: iscsi_prep_scsi_cmd_pdu iscsi prep [read cid 0 sc 8105860860c0 cdb 0x28 itt 0xd len 4096 bidi_len 0 cmdsn 50514 win 256] Nov 21 10:32:32 bdd4a kernel: session1: __iscsi2_complete_pdu [op 0x25 cid 0 itt 0xd len 0] Nov 21 10:32:32 bdd4a kernel: session1: iscsi_data_in_rsp data in with status done [sc 8105860860c0 res 0 itt 0xd] Nov 21 10:32:32 bdd4a kernel: session1: iscsi_complete_task complete task itt 0xd state 3 sc 8105860860c0 Nov 21 10:32:32 bdd4a kernel: session1: iscsi_free_task freeing task itt 0xd state 1 sc 8105860860c0 Nov 21 10:32:32 bdd4a kernel: session1: iscsi_prep_scsi_cmd_pdu iscsi
