I'm running a setup composed of: Linux 2.6.27 x86 based on SLES + Xen 3.4 (as dom0) running a couple of RHEL 5.5 VMs. The underlying storage for these VMs is iSCSI based via open-iscsi 2.0.870-26.6.1 and a DELL equallogic array.
Whenever the equallogic rebalances the LUNs between the controllers/ports, it requests the initiator to logout and login again to the new port/ip. If the guests are idle, the following messages show up in the logs:
Aug 3 17:55:08 goncalog140 kernel: connection1:0: detected conn error (1011)
Aug 3 17:55:09 goncalog140 kernel: connection1:0: detected conn error (1011)
Aug 3 17:55:10 goncalog140 iscsid: connection1:0 is operational after recovery (1 attempts)
However, if one of the RHEL guests is busy performing IO, we end up having a few failed requests as well:
Aug 3 17:55:26 goncalog140 kernel: connection1:0: dropping R2T itt 55 in recovery.
Aug 3 17:55:26 goncalog140 kernel: connection1:0: detected conn error (1011)
Aug 3 17:55:26 goncalog140 kernel: sd 6:0:0:0: [sdb] Result: hostbyte=DID_TRANSPORT_DISRUPTED driverbyte=DRIVER_OK,SUGGEST_OK
Aug 3 17:55:26 goncalog140 kernel: end_request: I/O error, dev sdb, sector 533399
Aug 3 17:55:26 goncalog140 kernel: sd 6:0:0:0: [sdb] Result: hostbyte=DID_TRANSPORT_DISRUPTED driverbyte=DRIVER_OK,SUGGEST_OK
Aug 3 17:55:26 goncalog140 kernel: end_request: I/O error, dev sdb, sector 5337 51
Aug 3 17:55:27 goncalog140 kernel: connection1:0: detected conn error (1011)
Aug 3 17:55:29 goncalog140 iscsid: connection1:0 is operational after recovery (1 attempts)
And as a side effect, the guest filesystem goes read-only. Googling around, I've found the following thread on this list which covers the same error I’m seeing in the logs:
I've also compiled the drivers iscsi_tcp/libiscsi with the patch from Mike Christie taken from that thread which can be found in the link below:
Is this a known issue? Is there anything else from a troubleshooting perspective that I could do?
I've uploaded the following files, in case someone would like to take a look:
Tcpdump's collected a couple of days ago in another reproduction/analysis of the same bug (apologies, but I didn’t get around to collect new tcp dumps with today’s reproduction):
0tcpdump0947.pcap 162K - 09:47 (GMT+1) nothing occurred.
1tcpdump0952.pcap 4.8M - 09:52 (GMT+2) problem occurred
Logs from today’s reproduction of the issue with the patched drivers for additional backtracing:
vm-boot.txt 2.7K After VM creation
vm-lun-rebalance-no-effect.txt 3.1K VM is idling, FS does not become read-only.
vm-lun-rebalance-fs-readonly.txt 3.3K VM is dd'ing /dev/zero to iscsi based disk, FS becomes read-only.
guest-dmesg.txt 14K RHEL 5.3 with 2.6.18-194.8.1.el5xen (RHEL 5.5 kernel)
All these files can be found in the following link:
Any help would be greatly appreciated!
Cheers,
-Goncalo.
conn error 1011 is generic. If this is occurring when the eql box is
rebalancing luns, it is a little different than above. With the above
problem we did not know why we got the error. With your situation we
sort of expect this. We should not be getting disk IO errors though.
When we get the logout request from the target, we send the logout
request, then basically handle the cleanup like if we got a connection
error. That is why you would see the conn error msg in this path. This
also means if this happened to the same IO 5 times, then you would see
the disk IO errors (scsi layer only lets us retry disk IO 5 times). But
if it just happened once, then the IO should be retried when we log into
the new portal and execute like normal.
Or are you using dm-multipath over iscsi? In that case you do not get
any retries, so we would expect to see that end_request: I/O error
message, but dm-multipath should just be retrying a new path or
internally queueing for whatever timeout value you had it use in
multipath.conf.
>
>
> I've also compiled the drivers iscsi_tcp/libiscsi with the patch from Mike Christie taken from that thread which can be found in the link below:
>
>
>
> http://groups.google.com/group/open-iscsi/attach/db552832995daaa7/trace-conn-error.patch?part=2&view=1
>
>
Could you send me the libiscsi.c file you patched?
Could you also send more of the log for either case? I want to see the
iscsid log info and any more of the kernel iscsi log info that you have.
I am looking for session recovery timed out messages and/or target
requested logout messages.
I guess that's SLES11 already. I just read an announcement that there is an opne-iscsi update for SLES11 SP1 available. Unfortunately Novell does not give any details in the announcements:
4. Recommended update for open-iscsi
SUSE Linux Enterprise Desktop 11 SP1 for x86-64
http://download.novell.com/Download?buildid=MAugs_l2FJY~
SUSE Linux Enterprise Desktop 11 SP1 for x86
http://download.novell.com/Download?buildid=U2OyI_9oJ5g~
SUSE Linux Enterprise Server 11 SP1 for x86-64
http://download.novell.com/Download?buildid=1Z1WASv0lfE~
SUSE Linux Enterprise Server 11 SP1 for x86
http://download.novell.com/Download?buildid=EzU17PIvOTc~
SUSE Linux Enterprise Server 11 SP1 for s390x
http://download.novell.com/Download?buildid=xqwCozVDBjM~
SUSE Linux Enterprise Server 11 SP1 for ppc
http://download.novell.com/Download?buildid=fMD_W5XKEtI~
SUSE Linux Enterprise Server 11 SP1 for ia64
http://download.novell.com/Download?buildid=_QVtGS0824o~
Maybe you should try the latest (and greatest?) version... ;-)
Regards,
Ulrich
Fron the description:
* Occasionally, not all iSCSI multipath mapping are being created
after boot up
* Stopping of the open-iscsi service fails even if no iSCSI device
is mounted.
* When configuring iBFT, the iscsiadm program does not display the
details of a session.
Do you think any of the fixes above may help in the issue I described
before? I'm presently not making use of multipath nor booting from SAN.
Although, these fixes are worth having, I'm mostly concerned about
understanding the nature/reason of the issue I described before at this
stage.
Thanks,
-Goncalo.
> Regards,
> Ulrich
>
>
What would be the best way to I identify how many retries have elapsed?
> Or are you using dm-multipath over iscsi? In that case you do not get
> any retries, so we would expect to see that end_request: I/O error
> message, but dm-multipath should just be retrying a new path or
> internally queueing for whatever timeout value you had it use in
> multipath.conf.
Multipath is not enabled at all. The equallogic array is active/passive
and we only have a view into one controller at any time, so we don't
make use of multipath at present.
> Could you send me the libiscsi.c file you patched?
>
> Could you also send more of the log for either case? I want to see the
> iscsid log info and any more of the kernel iscsi log info that you have.
> I am looking for session recovery timed out messages and/or target
> requested logout messages.
I've copied both the messages file from the host goncalog140 and the
patched libiscsi.c. FWIW, I've also included the iscsid.conf. Find these
files in the link below:
N.B: the messages file contains spew from other instrumentation tests
(e.g a dump_stack() call in scsi_transport_iscsi.c::iscsi_conn_error()).
The last set of tests which I've made available yesterday have only the
libiscsi.c and IIRC the iscsi_tcp.c, and this output can be found around
the timeframe of 17:50.
If required I can spin a new set of tests with different instrumentation
and/or collect different information, logs or tcpdumps, if that helps in
any way.
Thanks,
-Goncalo.
Hey Hannes,
The user is using Linux 2.6.27 x86 based on SLES + Xen 3.4 (as dom0)
running a couple of RHEL 5.5 VMs. The underlying storage for these VMs
is iSCSI based via open-iscsi 2.0.870-26.6.1 and a DELL equallogic array.
On 08/05/2010 02:21 PM, Goncalo Gomes wrote:
> I've copied both the messages file from the host goncalog140 and the
> patched libiscsi.c. FWIW, I've also included the iscsid.conf. Find these
> files in the link below:
>
> http://promisc.org/iscsi/
>
It looks like this chunk from libiscsi.c:iscsi_queuecommand:
case ISCSI_STATE_FAILED:
reason = FAILURE_SESSION_FAILED;
sc->result = DID_TRANSPORT_DISRUPTED << 16;
break;
is causing IO errors.
You want to use something like DID_IMM_RETRY because it can be a long
time between the time the kernel marks the state as ISCSI_STATE_FAILED
until we start recovery and properly get all the device queues blocked,
so we can exhaust all the retries if we use DID_TRANSPORT_DISRUPTED.
Sadly I got additional bugreports about this so I think I'll have
to revert it.
I have put some test kernels at
http://beta.suse.com/private/hare/sles11/iscsi
Can you test with them and check if this issue is solved?
Thanks.
Cheers,
Hannes
--
Dr. Hannes Reinecke zSeries & Storage
ha...@suse.de +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 N�rnberg
GF: Markus Rex, HRB 16746 (AG N�rnberg)
Would you be able to send me a unified patch containing the changes included in the test kernels so I can rebuild the drivers with them and update you today?
For completeness, we are not running SLES, but rather the Citrix XenServer 5.6 release which is based off of the Linux 2.6.27 tree of SLES. Also, for this specific controller we don't enable MPIO, but in most other arrays we do.
Thanks,
-Goncalo.
http://beta.suse.com/private/hare/sles11/iscsi
Thanks.
Cheers,
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: Markus Rex, HRB 16746 (AG Nürnberg)
It should stall, It works like FC and the fast io fail tmo. Users need
to set the iscsi replacement/recovery timeout like they would FC's fast
io fail tmo. They should set it to 3 or 5 secs or lower if they want
really fast failovers.
Oh yeah, Qlogic recently did this patch:
so we can have multipath tools set the recovery_tmo like it does for
fast io fail tmo.
I applied and tested the changes Mike Christie suggests. After the LUN
is rebalanced within the array I no longer see the IO errors and it
appears the setup is now resilient to the equallogic LUN failover
process.
I'm attaching the log from the dmesg merely for sanity check purposes,
if anyone cares to take a look?
> I have put some test kernels at
>
> http://beta.suse.com/private/hare/sles11/iscsi
Do the test kernels in the url above contain the change of
DID_TRANSPORT_DISRUPTED to DID_DIMM_RETRY or is there more to it than
simply changing the result code? If the latter, would you be able to
upload the source rpms or a unified patch containing the changes you are
are staging? I'm looking for a more pallatable way to test them, given I
have no SLES box lying around, but will install one if needs be.
Thanks,
-Goncalo.
Am I missing something?
Cheers,
Hannes
--
Dr. Hannes Reinecke zSeries & Storage
ha...@suse.de +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 Nürnberg
GF: Markus Rex, HRB 16746 (AG Nürnberg)
diff --git a/drivers/scsi/libiscsi.c b/drivers/scsi/libiscsi.c
index 32b30f1..441ca8b 100644
--- a/drivers/scsi/libiscsi.c
+++ b/drivers/scsi/libiscsi.c
@@ -1336,9 +1336,6 @@ int iscsi_queuecommand(struct scsi_cmnd *sc, void (*done)(
struct scsi_cmnd *))
*/
switch (session->state) {
case ISCSI_STATE_FAILED:
- reason = FAILURE_SESSION_FAILED;
- sc->result = DID_TRANSPORT_DISRUPTED << 16;
- break;
case ISCSI_STATE_IN_RECOVERY:
reason = FAILURE_SESSION_IN_RECOVERY;
sc->result = DID_IMM_RETRY << 16;
HTH,
> Since we already saw one problem with "DID_TRANSPORT_DISRUPTED", I was
> wondering if "DID_TRANSPORT_FAILFAST" also has some similar issues with
> limited retries and such.
>
No, that's actually okay. The I/O error will be reported in either case,
it's just that it'll never reaches the upper layers.
In your case it looks as if the 'tapdisk' thing runs on the raw disks,
not the multipathed device. So of course it'll register the error.
Maybe it's an idea to have the 'tapdisk' run on the multipath device-mapper
device ...
Cheers,
Hannes
--
Dr. Hannes Reinecke zSeries & Storage
ha...@suse.de +49 911 74053 688
SUSE LINUX Products GmbH, Maxfeldstr. 5, 90409 N�rnberg
GF: Markus Rex, HRB 16746 (AG N�rnberg)
uns fiel gestern ein Controller am SAN-Storage aus, und open-iscsi auf SLES10
SP3 (open-iscsi-2.0.868-0.6.11) erzeugte _sehr_ viele (419869 Einträge in
wenigen Stunden) Fehlermeldungen in Syslog. Gat Novell Bestrebungen, diese zu
drosseln? Beispiel:
Sep 7 16:08:23 hostname kernel: connection19:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection31:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection20:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection32:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection23:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection7:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection24:0: iscsi: detected conn error
(1011)
Sep 7 16:08:23 hostname kernel: connection8:0: iscsi: detected conn error
(1011)
[...]
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:24 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:25 hostname iscsid: conn 0 login rejected: target error (03/01)
[...]
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:53 hostname kernel: session19: iscsi: session recovery timed out
after 30 secs
Sep 7 16:08:53 hostname kernel: session31: iscsi: session recovery timed out
after 30 secs
Sep 7 16:08:53 hostname kernel: session20: iscsi: session recovery timed out
after 30 secs
[...]
Sep 7 16:08:54 hostname kernel: device-mapper: multipath: Failing path
8:192.
Sep 7 16:08:54 hostname multipathd: L116_hostas03: remaining active paths:
14
Sep 7 16:08:54 hostname multipathd: sdac: tur checker reports path is down
Sep 7 16:08:54 hostname multipathd: checker failed path 65:192 in map
L116_hostas03
Sep 7 16:08:54 hostname multipathd: L116_hostas03: remaining active paths:
13
Sep 7 16:08:54 hostname multipathd: sdv: tur checker reports path is down
Sep 7 16:08:54 hostname multipathd: checker failed path 65:80 in map
L116_hostas03
Sep 7 16:08:54 hostname multipathd: L116_hostas03: remaining active paths:
12
Sep 7 16:08:54 hostname multipathd: sdx: tur checker reports path is down
Sep 7 16:08:54 hostname multipathd: checker failed path 65:112 in map
L116_hostas03
Sep 7 16:08:54 hostname multipathd: L116_hostas03: remaining active paths:
11
Sep 7 16:08:54 hostname multipathd: sdab: tur checker reports path is down
Sep 7 16:08:54 hostname multipathd: checker failed path 65:176 in map
L116_hostas03
[...]
Sep 7 16:08:54 hostname multipathd: L111_hostsod: remaining active paths: 7
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
Sep 7 16:08:54 hostname iscsid: conn 0 login rejected: target error (03/01)
[...]
Sep 7 20:47:59 hostname multipathd: sdag: tur checker reports path is up
Sep 7 20:47:59 hostname multipathd: 66:0: reinstated
Sep 7 20:47:59 hostname multipathd: L116_hostas03: remaining active paths:
16
Sep 7 20:47:59 hostname multipathd: sdai: tur checker reports path is up
Sep 7 20:47:59 hostname multipathd: 66:32: reinstated
Sep 7 20:47:59 hostname multipathd: L117_hostas04: remaining active paths:
14
Sep 7 20:47:59 hostname multipathd: sdaj: tur checker reports path is up
Sep 7 20:47:59 hostname multipathd: 66:48: reinstated
Sep 7 20:47:59 hostname multipathd: L117_hostas04: remaining active paths:
15
Sep 7 20:48:00 hostname multipathd: sdak: tur checker reports path is up
Sep 7 20:48:00 hostname multipathd: 66:64: reinstated
Sep 7 20:48:00 hostname multipathd: L117_hostas04: remaining active paths:
16
Mit freundlichen Grüßen
Ulrich Windl
this message was intended for someone else. E-Mail program tricked me. -- Ulrich
>>> "Ulrich Windl" <Ulrich...@rz.uni-regensburg.de> schrieb am 08.09.2010 um
13:51 in Nachricht <4C8794DA0200...@gwsmtp1.uni-regensburg.de>: