Open/iSCSI + Logout Response Timeout + replacement_timeout firing
Nicholas A. Bellinger
So, and Jerome and Myself have been pushing VHACS (please see towards
production, we have begin to run into a particular issue while during
the 'vhacs cluster -I' (eg: cluster initilization) routine when we had a
bunch of VHACS server and client clouds active, and need to bring them
all down. Before explaining the case, here is a little background:
DRBD_TARGET: LIO-Target + DRBD export Cluster RA (Server side VHACS)
ISCSI_MOUNT: Open/iSCSI + Ext3 Mount Cluster RA (Client side VHACS)
Here is the scenario using 'node.session.timeo.replacement_timeout =
120':
We have been experiencing a case where sometimes the DRBD_TARGET RA for
a particular VHACS cloud gets shutdown BEFORE the ISCSI_MOUNT RA. This
of course means that all of the outstanding I/Os from Open/iSCSI with
regard to the mounted filesystem from the DRBD_TARGET that has gone way
need to be failed back to SCSI with a DID_ERROR status.
The problem is that the failure of the outstanding I/Os does not seem to
be occuring in all cases. In particular, a iscsiadm --logout I believe
is getting issued, and said logout request failing/timing out because
DRBD_TARGET has been released. It is at this point where umount for the
ext3 mount and/or sync hangs indefinately. When the problem occurs, it
looks like this from the kernel ring buffer:
iscsi_deallocate_extra_thread_sets:285: ***OPS*** Stopped 1 thread set(s) (2 total threads).
iscsi_deallocate_extra_thread_sets:285: ***OPS*** Stopped 2 thread set(s) (4 total threads).
session10: iscsi: session recovery timed out after 120 secs
sd 51:0:0:0: scsi: Device offlined - not ready after error recovery
sd 51:0:0:0: [sdg] Result: hostbyte=DID_BUS_BUSY driverbyte=DRIVER_OK,SUGGEST_OK
end_request: I/O error, dev sdg, sector 0
Buffer I/O error on device sdg, logical block 0
lost page write due to I/O error on sdg
I should mention that we are not doing any I/O to said iSCSI LUN via
Open/iSCSI other than the filesystem metadata for ext3 umount and
SYNCHRONIZE_CACHE CDB during struct scsi_device deregistration. From
experience with Core-iSCSI, I know the logout path is tricky wrt
exceptions (I spent months on it to handle all cases with Immediate and
Non Immediate Logout, as well as doing logouts on the fly from the same
connection in MC/S and different connections in MC/S :-)
So the question is:
I) When a ISCSI_INIT_LOGOUT_REQ is not returned with a
ISCSI_TARGET_LOGOUT_RSP and replacement_timeout fires, are all
outstanding I/Os for that particular session being completed with an
non-recoveryable exception..? Has anyone ever run into this case and/or
tested it..?
Not being exquisitely fimilar with Open/iSCSI source code, if either of
you gents could have a quick look and see if this is indeed broken and
hopefully provide a simple fix (I will take care of drinks at the Kernel
Summit :-), or if not could point me in the right direction it would be
much apperciated.
--nab
Nicholas A. Bellinger
> Greetings Mike, Hannes, and all;
>
> So, and Jerome and Myself have been pushing VHACS (please see towards
Whoops, forgot to include the VHACS link. :-)
http://linux-iscsi.org/index.php/VHACS
--nab
Mike Christie
the kernel modules with open-iscsi or the ones that come with the kernel?
Nicholas A. Bellinger wrote:
>>
>> The problem is that the failure of the outstanding I/Os does not seem to
>> be occuring in all cases. In particular, a iscsiadm --logout I believe
>> is getting issued, and said logout request failing/timing out because
>> DRBD_TARGET has been released. It is at this point where umount for the
>> ext3 mount and/or sync hangs indefinately. When the problem occurs, it
>> looks like this from the kernel ring buffer:
>>
>> iscsi_deallocate_extra_thread_sets:285: ***OPS*** Stopped 1 thread set(s) (2 total threads).
>> iscsi_deallocate_extra_thread_sets:285: ***OPS*** Stopped 2 thread set(s) (4 total threads).
>> session10: iscsi: session recovery timed out after 120 secs
>> sd 51:0:0:0: scsi: Device offlined - not ready after error recovery
If you see this then any and all that was sent the device and any new IO
should be failed to the FS and block layer like below. There is a bug in
some kernels though, where if you were to run a iscsiadm logout command
it can hang and lead to weird problems, because the scsi layer is
broken. If you use open-iscsi 869.2's kernel modules or the iscsi
modules in 2.6.25.6 or newer then this is fixed. Not sure if that is
what you are seeing, because we see IO failed upwards here. Also once we
see "Device offlined", the scsi layer is going to fail the IO when it
hits the scsi prep functions and is never even reaches us. If there is
IO stuck in the driver you could do
cat /sys/class/scsi_host/hostX/host_busy
to check (that file prints the number of commands the scsi layer has
sent the driver and the driver has not yet returned back (ok so I mean
how many commands is outsatnding)).
>> sd 51:0:0:0: [sdg] Result: hostbyte=DID_BUS_BUSY driverbyte=DRIVER_OK,SUGGEST_OK
>> end_request: I/O error, dev sdg, sector 0
>> Buffer I/O error on device sdg, logical block 0
>> lost page write due to I/O error on sdg
>>
>> I should mention that we are not doing any I/O to said iSCSI LUN via
>> Open/iSCSI other than the filesystem metadata for ext3 umount and
>> SYNCHRONIZE_CACHE CDB during struct scsi_device deregistration. From
>> experience with Core-iSCSI, I know the logout path is tricky wrt
>> exceptions (I spent months on it to handle all cases with Immediate and
>> Non Immediate Logout, as well as doing logouts on the fly from the same
>> connection in MC/S and different connections in MC/S :-)
>>
>> So the question is:
>>
>> I) When a ISCSI_INIT_LOGOUT_REQ is not returned with a
>> ISCSI_TARGET_LOGOUT_RSP and replacement_timeout fires, are all
>> outstanding I/Os for that particular session being completed with an
>> non-recoveryable exception..? Has anyone ever run into this case and/or
>> tested it..?
If the connection is down when you run iscsiadm logout, we will not send
a logout and the replacement_timeout does not come into play. We just
fast fail the connection and just cleanup the commands and kernel
resrouces and iscsiadm returns (yeah pretty bad I know - it is on the TODO).
If the connection is up when you run iscsiadm logout, and while the
logout is floating around the connection drops, we are again lazy and
just fail and cleanup and return right away. The replacement_timeout
does not come into play for this and we just fail right away.
If you run 869.2 from open-iscsi.org and build with
make DEBUG_SCSI=1 DEBUG_TCP=1
make DEBUG_SCSI=1 DEBUG_TCP=1 install
and send all the log output I can tell you better what is going on.
Nicholas A. Bellinger
On Sat, 2008-06-28 at 15:33 -0500, Mike Christie wrote:
> What version of open-iscsi and kernel are you using? And are you using
> the kernel modules with open-iscsi or the ones that come with the kernel?
>
Whoops, forgot to include that tid-bit:
open-iscsi: 2.0.730-1etch1
kernel: I am using v2.6.22.19-kdb, and Jerome is using
v2.6.22-4-vserver-amd64
> Nicholas A. Bellinger wrote:
> >>
> >> The problem is that the failure of the outstanding I/Os does not seem to
> >> be occuring in all cases. In particular, a iscsiadm --logout I believe
> >> is getting issued, and said logout request failing/timing out because
> >> DRBD_TARGET has been released. It is at this point where umount for the
> >> ext3 mount and/or sync hangs indefinately. When the problem occurs, it
> >> looks like this from the kernel ring buffer:
> >>
> >> iscsi_deallocate_extra_thread_sets:285: ***OPS*** Stopped 1 thread set(s) (2 total threads).
> >> iscsi_deallocate_extra_thread_sets:285: ***OPS*** Stopped 2 thread set(s) (4 total threads).
> >> session10: iscsi: session recovery timed out after 120 secs
> >> sd 51:0:0:0: scsi: Device offlined - not ready after error recovery
>
> If you see this then any and all that was sent the device and any new IO
> should be failed to the FS and block layer like below. There is a bug in
> some kernels though, where if you were to run a iscsiadm logout command
> it can hang and lead to weird problems, because the scsi layer is
> broken. If you use open-iscsi 869.2's kernel modules or the iscsi
> modules in 2.6.25.6 or newer then this is fixed.
Ok boss, I will upgrade the tools and jump from v2.6.22.19-kdb to
v2.6.25.9-kdb on my VHACs nodes.
> Not sure if that is
> what you are seeing, because we see IO failed upwards here. Also once we
> see "Device offlined", the scsi layer is going to fail the IO when it
> hits the scsi prep functions and is never even reaches us. If there is
> IO stuck in the driver you could do
> cat /sys/class/scsi_host/hostX/host_busy
>
> to check (that file prints the number of commands the scsi layer has
> sent the driver and the driver has not yet returned back (ok so I mean
> how many commands is outsatnding)).
>
>
<nod>, got it.
Ok, I will get into this at the office tomorrow afternoon and let you
know what I find. Thanks for the info.
Many thanks for your most valuable of time,
--nab
Mike Christie
> Hi Mike!
>
Hey, looks like you doing some more cool stuff. Don't you have a job
where you have to hack on boring stuff like the rest of us :)
> On Sat, 2008-06-28 at 15:33 -0500, Mike Christie wrote:
>> What version of open-iscsi and kernel are you using? And are you using
>> the kernel modules with open-iscsi or the ones that come with the kernel?
>>
>
> Whoops, forgot to include that tid-bit:
>
> open-iscsi: 2.0.730-1etch1
>
> kernel: I am using v2.6.22.19-kdb, and Jerome is using
> v2.6.22-4-vserver-amd64
>
Ah if your disk are using write back cache then you are going to hit
some problems. So if you see this in /var/log/messages when you loging:
kernel: sd 9:0:0:1: [sdb] Write cache: enabled,
then later when you run iscsiadm to log out you see:
kernel: sd 9:0:0:1: [sdb] Synchronizing SCSI cache
Then you are going to hit problems due to the scsi sysfs interface
changing on us. iscsiadm is going to hang. IO is going to hang. You
basically have to reboot the box by hand.
Jerome Martin
Nicholas A. Bellinger wrote:
Hi Mike!
Hey, looks like you doing some more cool stuff. Don't you have a job where you have to hack on boring stuff like the rest of us :)
Hey, feel free to come and hack on VHACS with us to get you un-bored ;-)
Ah if your disk are using write back cache then you are going to hit some problems. So if you see this in /var/log/messages when you loging:
On Sat, 2008-06-28 at 15:33 -0500, Mike Christie wrote:
What version of open-iscsi and kernel are you using? And are you using the kernel modules with open-iscsi or the ones that come with the kernel?
Whoops, forgot to include that tid-bit:
open-iscsi: 2.0.730-1etch1
kernel: I am using v2.6.22.19-kdb, and Jerome is using
v2.6.22-4-vserver-amd64
kernel: sd 9:0:0:1: [sdb] Write cache: enabled,
then later when you run iscsiadm to log out you see:
kernel: sd 9:0:0:1: [sdb] Synchronizing SCSI cache
Then you are going to hit problems due to the scsi sysfs interface changing on us. iscsiadm is going to hang. IO is going to hang. You basically have to reboot the box by hand.
I NEW I had read something related to writeback cache + sysfs, I tried to point Nicholas to it but I just couldn't find the place I saw this. Was it on the open/iSCSI homepage or in the MLs, I never found out again, but thanks for confirming that :-)
I'll try to disable it and see how it goes from there.
Nicholas A. Bellinger
> Nicholas A. Bellinger wrote:
> > Hi Mike!
> >
>
> Hey, looks like you doing some more cool stuff. Don't you have a job
> where you have to hack on boring stuff like the rest of us :)
>
What Jerome said. :-)
>
> > On Sat, 2008-06-28 at 15:33 -0500, Mike Christie wrote:
> >> What version of open-iscsi and kernel are you using? And are you using
> >> the kernel modules with open-iscsi or the ones that come with the kernel?
> >>
> >
> > Whoops, forgot to include that tid-bit:
> >
> > open-iscsi: 2.0.730-1etch1
> >
> > kernel: I am using v2.6.22.19-kdb, and Jerome is using
> > v2.6.22-4-vserver-amd64
> >
>
> Ah if your disk are using write back cache then you are going to hit
> some problems. So if you see this in /var/log/messages when you loging:
>
> kernel: sd 9:0:0:1: [sdb] Write cache: enabled,
>
> then later when you run iscsiadm to log out you see:
>
> kernel: sd 9:0:0:1: [sdb] Synchronizing SCSI cache
>
> Then you are going to hit problems due to the scsi sysfs interface
> changing on us. iscsiadm is going to hang. IO is going to hang. You
> basically have to reboot the box by hand.
>
Yep, so the LIO-CORE does NOT emulate Write Cache Enable (although there
is some Read Cache code :-) bit in the caching mode page in the virtual
storage object case (IBLOCK, FILE, etc). We are using the LIO-Core
IBLOCK plugin for export DRBD's struct block_device, which uses the
generic emulation of MODE_SENSE*, which leaves buf[2] untouched in
caching mode page.
For the PSCSI subsystem plugin, these mode pages obviously come from the
underlying hardware. I even recall that libata does emulate this down
to SATA/PATA bits for us. (thanks jgarzik and co)
On a related note, did you and Tomo ever get around to implement
write/read caching emulation in STGT for virtual devices..? Its
definately something that is on my long term list for doing generically
amoungst virtual devices in LIO-Core v3.x.
Konrad Rzeszutek
> some problems. So if you see this in /var/log/messages when you loging:
>
> kernel: sd 9:0:0:1: [sdb] Write cache: enabled,
>
> then later when you run iscsiadm to log out you see:
>
> kernel: sd 9:0:0:1: [sdb] Synchronizing SCSI cache
>
> Then you are going to hit problems due to the scsi sysfs interface
> changing on us. iscsiadm is going to hang. IO is going to hang. You
> basically have to reboot the box by hand.
Mike,
Are you sure about this? When the sysfs entries are deleted (during the
iscsiadm logout phase), the SCSI ml finishes all of the I/Os and the last
operation is sending the SCSI Cache command. Wouldn't that quiesce I/O ? Granted
this means doing these steps which are outside the normal iscsiadm:
1). flush dirty pages (call 'sync')
2). delete the sysfs entries (echo 1 > /sys/block/sdX/device/delete)
3). wait until /sys/class/scsi_host/hostZ/host_busy reaches zero
4). iscsiadm -m logout
Mike Christie
> On Sun, 2008-06-29 at 01:36 -0500, Mike Christie wrote:
>> Nicholas A. Bellinger wrote:
>>> Hi Mike!
>>>
>> Hey, looks like you doing some more cool stuff. Don't you have a job
>> where you have to hack on boring stuff like the rest of us :)
>>
>
> What Jerome said. :-)
>
>>> On Sat, 2008-06-28 at 15:33 -0500, Mike Christie wrote:
>>>> What version of open-iscsi and kernel are you using? And are you using
>>>> the kernel modules with open-iscsi or the ones that come with the kernel?
>>>>
>>> Whoops, forgot to include that tid-bit:
>>>
>>> open-iscsi: 2.0.730-1etch1
>>>
>>> kernel: I am using v2.6.22.19-kdb, and Jerome is using
>>> v2.6.22-4-vserver-amd64
>>>
>> Ah if your disk are using write back cache then you are going to hit
>> some problems. So if you see this in /var/log/messages when you loging:
>>
>> kernel: sd 9:0:0:1: [sdb] Write cache: enabled,
>>
>> then later when you run iscsiadm to log out you see:
>>
>> kernel: sd 9:0:0:1: [sdb] Synchronizing SCSI cache
>>
>> Then you are going to hit problems due to the scsi sysfs interface
>> changing on us. iscsiadm is going to hang. IO is going to hang. You
>> basically have to reboot the box by hand.
>>
>
> Yep, so the LIO-CORE does NOT emulate Write Cache Enable (although there
Oh. There are some other issues that we can hit with IO getting failed
and applications hanging waiting for IO to be sent but it gets lost. Try
the newer code where all that should be fixed.
> is some Read Cache code :-) bit in the caching mode page in the virtual
> storage object case (IBLOCK, FILE, etc). We are using the LIO-Core
> IBLOCK plugin for export DRBD's struct block_device, which uses the
> generic emulation of MODE_SENSE*, which leaves buf[2] untouched in
> caching mode page.
>
> For the PSCSI subsystem plugin, these mode pages obviously come from the
> underlying hardware. I even recall that libata does emulate this down
> to SATA/PATA bits for us. (thanks jgarzik and co)
>
> On a related note, did you and Tomo ever get around to implement
> write/read caching emulation in STGT for virtual devices..? Its
I am not sure the exact status. We use the buffer cache normally and so
I think we always report that we support write caching. I think someone
just sent patches to turn it off.
> definately something that is on my long term list for doing generically
> amoungst virtual devices in LIO-Core v3.x.
>
> Many thanks for your most valuable of time,
>
No problem.
> --nab
>
>
>
> >
Mike Christie
>> Ah if your disk are using write back cache then you are going to hit
>> some problems. So if you see this in /var/log/messages when you loging:
>>
>> kernel: sd 9:0:0:1: [sdb] Write cache: enabled,
>>
>> then later when you run iscsiadm to log out you see:
>>
>> kernel: sd 9:0:0:1: [sdb] Synchronizing SCSI cache
>>
>> Then you are going to hit problems due to the scsi sysfs interface
>> changing on us. iscsiadm is going to hang. IO is going to hang. You
>> basically have to reboot the box by hand.
>
> Mike,
>
> Are you sure about this? When the sysfs entries are deleted (during the
> iscsiadm logout phase), the SCSI ml finishes all of the I/Os and the last
> operation is sending the SCSI Cache command. Wouldn't that quiesce I/O ? Granted
See below. You are right if everything goes ok.
> this means doing these steps which are outside the normal iscsiadm:
> 1). flush dirty pages (call 'sync')
> 2). delete the sysfs entries (echo 1 > /sys/block/sdX/device/delete)
> 3). wait until /sys/class/scsi_host/hostZ/host_busy reaches zero
> 4). iscsiadm -m logout
>
The problem that I described occurs when we run the iscsiadm logout
command and we used the sysfs delete file. When iscsiadm wrote to that
attr in 2.6.18 it would return when the cache sync was sent and the
device was fully deleted in the kernel. In 2.6.21 and above it returned
right away. So iscsiadm's logout code would write to that attr and think
the devices were cleaned up, then it would call the iscsi shutdown code
which would send a logout and cleanup the kernel session, connection and
host structs, thinking that the devices were properly flushed but IO
could still be waiting to get written so all types of fun things can
happen like....
We could get to the scsi host remove call and all the scsi device sysfs
delete calls would still be starting up, so the host remove call and
those delete calls would race (so this is we would have bypassed the
host_busy check in the connection deletion function in the kernel). When
this happens if the sysfs delete device got the scan mutex first, but
the iscsi shutdown code had blocked the devices, while we were trying to
remove the host then the iscsiadm logout command will hang, because the
delete device would wait forever to try and send the command (it is not
yet in the host so the command timer is not running and the device is
blocked), and the remove host call is waiting on the scan mutex which
the device has.
If you have multiple devices then the remove host command can also end
up failing IO, because we will have sent the logout and later set the
session internal state to terminiate and incoming IO on the other
devices that was queued will be failed when the remove devices functions
flush the IO.
If you do not have a write back cache we have other problems, where IO
can be failed when it should not have for the reason above where the
logout is sent, the terminate bit is set, and the remove host runs
before the devices were properly removed and that causes IO to be failed.
And actually in some kernels you can hang (the app would hang not
iscsiadm in this case) when a cache sync was not needed, because if a
cache sync was not needed when we would remove the host and it would
delete the device but IO would be stuck in the queues and no one did a
unplug of the queue when the scsi device was removed. We added a
iscsi_unblock_session in the iscsi_session_teardown to flush everything
so at least apps would not hang there (but that resulted in IO getting
failed like above).
Nicholas A. Bellinger
Yikes..
Ok, so with Open/iSCSI 2.0-869.2 running on 2.6.25.9 w/ LIO-Core IBLOCK
+ DRBD with write cache disabled, we are no longer seeing hanging
umounts during the rsc_stop() section of ISCSI_MOUNT VHACS cluster
resource. Thanks for the helpful info mnc!! :-)
Things have started to look up with the latest kernel + open/iscsi
userspace code. The only item left that I have been running into on
Etch are strange sshd segfaults (requring a service restart) during
ISCSI_MOUNT:rsc_stop. They seem to be somehow be Open/iSCSI related
(not exactly sure how yet) and happens on multiple machines, from both
myself and Jerome's clusters. We have been trying to track this issue
down with little luck, but with the new code it definately seems to be
happening alot less frequently on my setup (only once so far with the
latest Open/iSCSI). Pretty vague I know.. :)
Oh yeah, jerome also mentioned something to me this morning about
left-over iscsid processes after ISCSI_MOUNT:rsc_stop() as well. What
was the problem case on this one again..?
--nab
> >