It looks like the target does not respond to nop-in so that initiator complains and drops connection exactly twice the 5 sec time-out following transition to logged-in state.
On 10/22/08, Eugene Chupriyanov <[EMAIL PROTECTED]> wrote: >> Further to Andrey kuzmin's post, it would be >> interesting >> to see part of the initiator log from just before the >> line: >> "iscsid: Nop-out timedout after 15 seconds on >> connection 5:0 state (3). Dropping session." >> All subsequent lines are from the "kernel", (except >> the last) >> which is expected as it is just seeing the iscsi >> drive disappear. >> Are there any prior lines, from "iscsid", to give a >> clue to what >> the initiator was trying to do before the connection >> was lost. >> (Can you turn up the verbosity of messages from >> iscsid?) > > I've tried to use iscsi initiator in VM (CentOS 5.2 i386). Problem persists. > Here is what we can see in the log: > Oct 22 19:12:07 redmine iscsid: iSCSI logger with pid=24402 started! > Oct 22 19:12:07 redmine kernel: scsi7 : iSCSI Initiator over TCP/IP > Oct 22 19:12:07 redmine kernel: Vendor: SUN Model: SOLARIS > Rev > : 1 > Oct 22 19:12:07 redmine kernel: Type: Direct-Access > ANS > I SCSI revision: 05 > Oct 22 19:12:07 redmine kernel: SCSI device sda: 209715200 512-byte hdwr > sectors > (107374 MB) > Oct 22 19:12:07 redmine kernel: sda: Write Protect is off > Oct 22 19:12:08 redmine kernel: SCSI device sda: drive cache: write through > Oct 22 19:12:08 redmine kernel: SCSI device sda: 209715200 512-byte hdwr > sectors > (107374 MB) > Oct 22 19:12:08 redmine kernel: sda: Write Protect is off > Oct 22 19:12:08 redmine kernel: SCSI device sda: drive cache: write through > Oct 22 19:12:08 redmine kernel: sda: sda1 > Oct 22 19:12:08 redmine kernel: sd 7:0:0:0: Attached scsi disk sda > Oct 22 19:12:08 redmine kernel: sd 7:0:0:0: Attached scsi generic sg0 type 0 > Oct 22 19:12:08 redmine iscsid: transport class version 2.0-724. iscsid > version > 2.0-868 > Oct 22 19:12:08 redmine iscsid: iSCSI daemon with pid=24403 started! > Oct 22 19:12:08 redmine iscsid: received iferror -38 > Oct 22 19:12:08 redmine last message repeated 2 times > Oct 22 19:12:08 redmine iscsid: connection8:0 is operational now > > At this point I just started iscsi initiator. Some time in the past I've > already created partition on that LUN so I just do mkfs on /dev/sda1. It > successfully writed superblocks and starts to build inod table and hangs > very soon. Whats going on in the log: > Oct 22 19:14:51 redmine kernel: ping timeout of 5 secs expired, last rx > 79318126 > 8, last ping 793186268, now 793191268 > Oct 22 19:14:51 redmine kernel: connection8:0: iscsi: detected conn error > (1011 > ) > Oct 22 19:14:52 redmine iscsid: Kernel reported iSCSI connection 8:0 error > (1011 > ) state (3) > Oct 22 19:14:59 redmine iscsid: received iferror -38 > Oct 22 19:14:59 redmine last message repeated 2 times > Oct 22 19:14:59 redmine iscsid: connection8:0 is operational after recovery > (1 a > ttempts) > Oct 22 19:15:09 redmine kernel: ping timeout of 5 secs expired, last rx > 79319877 > 0, last ping 793203770, now 793208770 > Oct 22 19:15:09 redmine kernel: connection8:0: iscsi: detected conn error > (1011 > ) > Oct 22 19:15:09 redmine iscsid: Kernel reported iSCSI connection 8:0 error > (1011 > ) state (3) > Oct 22 19:15:17 redmine iscsid: received iferror -38 > Oct 22 19:15:17 redmine last message repeated 2 times > Oct 22 19:15:17 redmine iscsid: connection8:0 is operational after recovery > (1 a > ttempts) > Oct 22 19:15:27 redmine kernel: ping timeout of 5 secs expired, last rx > 79321654 > 0, last ping 793221540, now 793226540 > Oct 22 19:15:27 redmine kernel: connection8:0: iscsi: detected conn error > (1011 > ) > Oct 22 19:15:27 redmine iscsid: Kernel reported iSCSI connection 8:0 error > (1011 > ) state (3) > Oct 22 19:15:35 redmine iscsid: received iferror -38 > Oct 22 19:15:35 redmine last message repeated 2 times > Oct 22 19:15:35 redmine iscsid: connection8:0 is operational after recovery > (1 a > ttempts) > > ... and so on and on. > And here is part of /tmp/target_log: > Wed Oct 22 19:10:00 2008 > MAIN bnx0: 0:1a:64:66:cd:8 > Wed Oct 22 19:10:00 2008 > Got IPv6 socketWed Oct 22 19:12:07 2008 > CON0 ---- Start Receiver > ---- > Wed Oct 22 19:12:07 2008 > CON0 ---- Wed Oct 22 19:12:07 2008 > ---- > Wed Oct 22 19:12:07 2008 > CON0 ---- FREE(T3) -> XPT_UP > Wed Oct 22 19:12:07 2008 > CON0 ---- Start Poller > ---- > Wed Oct 22 19:12:07 2008 > CON0 ---- XPT_UP(T4) -> IN_LOGIN > Wed Oct 22 19:12:07 2008 > SES1 ---- Start Session > ---- > Wed Oct 22 19:12:07 2008 > CON0 Available text size 488 > Wed Oct 22 19:12:07 2008 > CON0 InitiatorName = iqn.1994-05.com.redhat:c66ba66694c5 > Wed Oct 22 19:12:07 2008 > CON0 InitiatorAlias = redmine.cpm.ru > Wed Oct 22 19:12:07 2008 > CON0 TargetName = > iqn.1986-03.com.sun:02:02e3feb6-ffa4-45cf-d8Wed Oct 22 19:12:07 2008 > CON0 SessionType = Normal > Wed Oct 22 19:12:07 2008 > CON0 HeaderDigest = None,CRC32C > Wed Oct 22 19:12:07 2008 > CON0 DataDigest = None > Wed Oct 22 19:12:07 2008 > CON0 DefaultTime2Wait = 2 > Wed Oct 22 19:12:07 2008 > CON0 DefaultTime2Retain = 0 > Wed Oct 22 19:12:07 2008 > CON0 IFMarker = No > Wed Oct 22 19:12:07 2008 > CON0 OFMarker = No > Wed Oct 22 19:12:07 2008 > CON0 ErrorRecoveryLevel = 0 > Wed Oct 22 19:12:07 2008 > CON0 InitialR2T = No > Wed Oct 22 19:12:07 2008 > CON0 ImmediateData = Yes > Wed Oct 22 19:12:07 2008 > CON0 MaxBurstLength = 16776192 > Wed Oct 22 19:12:07 2008 > CON0 FirstBurstLength = 262144 > Wed Oct 22 19:12:07 2008 > CON0 MaxOutstandingR2T = 1 > Wed Oct 22 19:12:07 2008 > CON0 MaxConnections = 1 > Wed Oct 22 19:12:07 2008 > CON0 DataPDUInOrder = Yes > Wed Oct 22 19:12:07 2008 > CON0 DataSequenceInOrder = Yes > Wed Oct 22 19:12:07 2008 > CON0 MaxRecvDataSegmentLength = 131072 > Wed Oct 22 19:12:07 2008 > SES1 redmine.cpm.ru ISID[00023d080000] > Wed Oct 22 19:12:07 2008 > CON0 ---- IN_LOGIN(T5) -> LOGGED_IN > Wed Oct 22 19:12:07 2008 > SAM0 LU[0.0] Created new LU thread 0xa > Wed Oct 22 19:12:07 2008 > SAM0 ---- Start LU > ---- > Wed Oct 22 19:12:08 2008 > CON0 Underflow occurred > Wed Oct 22 19:12:08 2008 > SPC0 INQUIRY Page0 request > Wed Oct 22 19:12:08 2008 > CON0 Underflow occurred > Wed Oct 22 19:12:08 2008 > SPC0 INQUIRY Page83 request > Wed Oct 22 19:12:08 2008 > CON0 Underflow occurred > Wed Oct 22 19:14:58 2008 > CON1 ---- Start Receiver > ---- > Wed Oct 22 19:14:58 2008 > CON1 ---- Wed Oct 22 19:14:58 2008 > ---- > Wed Oct 22 19:14:58 2008 > CON1 ---- FREE(T3) -> XPT_UP > Wed Oct 22 19:14:58 2008 > CON1 ---- Start Poller > ---- > Wed Oct 22 19:14:59 2008 > CON1 ---- XPT_UP(T4) -> IN_LOGIN > Wed Oct 22 19:14:59 2008 > SES2 ---- Start Session > ---- > Wed Oct 22 19:14:59 2008 > CON1 Available text size 488 > Wed Oct 22 19:14:59 2008 > CON1 InitiatorName = iqn.1994-05.com.redhat:c66ba66694c5 > Wed Oct 22 19:14:59 2008 > CON1 InitiatorAlias = redmine.cpm.ru > Wed Oct 22 19:14:59 2008 > CON1 TargetName = > iqn.1986-03.com.sun:02:02e3feb6-ffa4-45cf-d8Wed Oct 22 19:14:59 2008 > CON1 SessionType = Normal > Wed Oct 22 19:14:59 2008 > CON1 HeaderDigest = None,CRC32C > Wed Oct 22 19:14:59 2008 > CON1 DataDigest = None > Wed Oct 22 19:14:59 2008 > CON1 DefaultTime2Wait = 2 > Wed Oct 22 19:14:59 2008 > CON1 DefaultTime2Retain = 0 > Wed Oct 22 19:14:59 2008 > CON1 IFMarker = No > Wed Oct 22 19:14:59 2008 > CON1 OFMarker = No > Wed Oct 22 19:14:59 2008 > CON1 ErrorRecoveryLevel = 0 > Wed Oct 22 19:14:59 2008 > CON1 InitialR2T = No > Wed Oct 22 19:14:59 2008 > CON1 ImmediateData = Yes > Wed Oct 22 19:14:59 2008 > CON1 MaxBurstLength = 16776192 > Wed Oct 22 19:14:59 2008 > CON1 FirstBurstLength = 262144 > Wed Oct 22 19:14:59 2008 > CON1 MaxOutstandingR2T = 1 > Wed Oct 22 19:14:59 2008 > CON1 MaxConnections = 1 > Wed Oct 22 19:14:59 2008 > > CON1 DataPDUInOrder = Yes > Wed Oct 22 19:14:59 2008 > CON1 DataSequenceInOrder = Yes > Wed Oct 22 19:14:59 2008 > CON1 MaxRecvDataSegmentLength = 131072 > Wed Oct 22 19:14:59 2008 > SES2 redmine.cpm.ru ISID[00023d080000] > Wed Oct 22 19:14:59 2008 > SES1 Implicit shutdown > Wed Oct 22 19:14:59 2008 > CON0 ---- LOGGED_IN(T8) -> FREE > Wed Oct 22 19:14:59 2008 > SES1 Starting shutdown > Wed Oct 22 19:14:59 2008 > CON1 ---- IN_LOGIN(T5) -> LOGGED_IN > Wed Oct 22 19:14:59 2008 > LU_0 No remaining targets for LU(5) > Wed Oct 22 19:14:59 2008 > SAM0 ---- End LU > ---- > Wed Oct 22 19:14:59 2008 > SAM0 Sent 1 shutdown requests for > iqn.1986-03.com.sun:02:02e3feb6-ffa4-45cf-d8Wed Oct 22 19:14:59 2008 > SES1 ---- End Session > ---- > > And so on in circles. > iscsisnoop.d is not showing anything suspicious either, tomorrow I'll try to > add timestamps to it and will repeat experiment. > /var/svc/log/system-iscsitgt:default.log shows only start/stop messages. > > For awhile I'm out of ideas. Will try to google for it tomorrow... > > Thanks for helping! > Eugene > -- > This message posted from opensolaris.org > _______________________________________________ > storage-discuss mailing list > [email protected] > http://mail.opensolaris.org/mailman/listinfo/storage-discuss > -- Regards, Andrey _______________________________________________ storage-discuss mailing list [email protected] http://mail.opensolaris.org/mailman/listinfo/storage-discuss
