> 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
