Connection Errors
swejis
me if asking stupid questions.
I'm evaluation opensuse 11 (Beta1) for my servers and have found some
worrying errors in the log. The following error quite frequently shows
up.
May 5 21:15:05 manjula klogd: connection1:0: ping timeout of 5 secs
expired, last rx 4626267449, last ping 4626264949, now 4626269949
May 5 21:15:05 manjula klogd: connection1:0: detected conn error
(1011)
May 5 21:15:05 manjula iscsid: Kernel reported iSCSI connection 1:0
error (1011) state (3)
May 5 21:15:09 manjula iscsid: connection1:0 is operational after
recovery (1 attempts)
The target is the infamous Promise m500i and the initiator "transport
class version 2.0-869. iscsid version 2.0-868"
Nic : Broadcom NetXtreme BCM5721 Gigabit Ethernet PCI Express (tg3)
Kernel 2.6.25-rc9-17-default x86_64
There is really no load on this system yet. I used a sniffer to record
the traffic and it seem the target "all the sudden" sends a reset
(frame 65). I'm not sure if this happens at the same time as the error
printed to the log. I have uploaded the capture file here:
http://www.wehay.com/iscsi.cap.gz
To my first stupid question. The target is equipped with 2 x 1GB nics
having address 192.168.43.5 & 6. When I did the discovery I only
pointed to one of these addresses still both where found and used
(magic). Also I noticed that every lun is registered twice (sdc & d
for lun1 etc), is the reason for this performance, fail over or
perhaps both ? I've spotted in the target the following setting "Max
Connections 1" (non-configurable) and was thinking perhaps this reset
was related to this. I have left all configuration to it's defaults
only changing the login information.
Config file: http://www.wehay.com/iscsid.conf
I have several older machines accessing the same target without any
problems.
Any ides on what todo next would be most appreciated.
Brgds Jonas Israelsson
Mike Christie
> Hello everyone. I'm not very experienced with iscsi, so please excuse
> me if asking stupid questions.
>
> I'm evaluation opensuse 11 (Beta1) for my servers and have found some
> worrying errors in the log. The following error quite frequently shows
> up.
>
> May 5 21:15:05 manjula klogd: connection1:0: ping timeout of 5 secs
> expired, last rx 4626267449, last ping 4626264949, now 4626269949
> May 5 21:15:05 manjula klogd: connection1:0: detected conn error
> (1011)
> May 5 21:15:05 manjula iscsid: Kernel reported iSCSI connection 1:0
> error (1011) state (3)
> May 5 21:15:09 manjula iscsid: connection1:0 is operational after
> recovery (1 attempts)
>
Could you send me the /boot/config-2.6.whatever-kernel-version-you-are-using
Mike Christie
Could you also do
cat /sys/class/iscsi_connection/connection1:0/recv_tmo
cat /sys/class/iscsi_connection/connection1:0/ping_tmo
and send those values.
swejis
swejis
5
# cat /sys/class/iscsi_connection/connection1:0/ping_tmo
5
Mike Christie
Ignore that. I forgot suse uses HZ=250.
Mike Christie
> Hello everyone. I'm not very experienced with iscsi, so please excuse
> me if asking stupid questions.
>
> I'm evaluation opensuse 11 (Beta1) for my servers and have found some
> worrying errors in the log. The following error quite frequently shows
> up.
>
> May 5 21:15:05 manjula klogd: connection1:0: ping timeout of 5 secs
> expired, last rx 4626267449, last ping 4626264949, now 4626269949
It looks like the nop code it broken. If you use
node.conn[0].timeo.noop_out_interval = 0
node.conn[0].timeo.noop_out_timeout = 0
Set that for each portal or set it in your /etc/iscsi/iscsi.conf file
and then redo discovery.
> May 5 21:15:05 manjula klogd: connection1:0: detected conn error
> (1011)
> May 5 21:15:05 manjula iscsid: Kernel reported iSCSI connection 1:0
> error (1011) state (3)
> May 5 21:15:09 manjula iscsid: connection1:0 is operational after
> recovery (1 attempts)
>
> The target is the infamous Promise m500i and the initiator "transport
> class version 2.0-869. iscsid version 2.0-868"
> Nic : Broadcom NetXtreme BCM5721 Gigabit Ethernet PCI Express (tg3)
> Kernel 2.6.25-rc9-17-default x86_64
>
> There is really no load on this system yet. I used a sniffer to record
> the traffic and it seem the target "all the sudden" sends a reset
> (frame 65). I'm not sure if this happens at the same time as the error
> printed to the log. I have uploaded the capture file here:
> http://www.wehay.com/iscsi.cap.gz
>
> To my first stupid question. The target is equipped with 2 x 1GB nics
> having address 192.168.43.5 & 6. When I did the discovery I only
> pointed to one of these addresses still both where found and used
> (magic). Also I noticed that every lun is registered twice (sdc & d
This is expected. Normally if you do discovery to one port it will tell
you about all of them on the target.
The multiple sd entries is also expected. The scsi layer does not know
or care if it can see the same LU from different paths, so it creates a
sd everytime it sees it. You could then use multipath to assemble all
the sds into one multipath device.
> for lun1 etc), is the reason for this performance, fail over or
> perhaps both ? I've spotted in the target the following setting "Max
> Connections 1" (non-configurable) and was thinking perhaps this reset
> was related to this. I have left all configuration to it's defaults
> only changing the login information.
>
max connections is not used so do not worry about it.
Mike Christie
> swejis wrote:
>> Hello everyone. I'm not very experienced with iscsi, so please excuse
>> me if asking stupid questions.
>>
>> I'm evaluation opensuse 11 (Beta1) for my servers and have found some
>> worrying errors in the log. The following error quite frequently shows
>> up.
>>
>> May 5 21:15:05 manjula klogd: connection1:0: ping timeout of 5 secs
>> expired, last rx 4626267449, last ping 4626264949, now 4626269949
>
>
> It looks like the nop code it broken. If you use
>
>
> node.conn[0].timeo.noop_out_interval = 0
> node.conn[0].timeo.noop_out_timeout = 0
>
> Set that for each portal or set it in your /etc/iscsi/iscsi.conf file
> and then redo discovery.
If that works could you try the kernel modules and tools in this tarball?
http://open-iscsi.org/bits/open-iscsi-2.0-869.1.test1.tar.gz
Renable nops by setting:
node.conn[0].timeo.noop_out_interval = 5
node.conn[0].timeo.noop_out_timeout = 5
back to five, then retry the test. This should fix the root problem
where we drop the session when we wanted to test it.
swejis
## node.conn[0].timeo.noop_out_interval = 5
node.conn[0].timeo.noop_out_interval = 0
node.conn[1].timeo.noop_out_interval = 0
# node.conn[0].timeo.noop_out_timeout = 5
I noticed this:
May 6 08:52:22 manjula iscsid: connection2:0 is operational now
May 6 08:52:22 manjula iscsid: connection1:0 is operational now
Should the above changes instead be:
node.conn[1].xxx
node.conn[2].xxx
I still see the same errors though:
May 6 09:07:06 manjula klogd: connection1:0: ping timeout of 5 secs
expired, last rx 4636947795, last ping 4636942795, now 4636950295
May 6 09:07:06 manjula klogd: connection1:0: detected conn error
(1011)
May 6 09:07:07 manjula iscsid: Kernel reported iSCSI connection 1:0
error (1011) state (3)
May 6 09:07:10 manjula iscsid: connection1:0 is operational after
recovery (1 attempts)
May 6 09:08:11 manjula klogd: connection1:0: ping timeout of 5 secs
expired, last rx 4636964045, last ping 4636960295, now 4636966545
May 6 09:08:11 manjula klogd: connection1:0: detected conn error
(1011)
May 6 09:08:12 manjula iscsid: Kernel reported iSCSI connection 1:0
error (1011) state (3)
May 6 09:08:15 manjula iscsid: connection1:0 is operational after
recovery (1 attempts)
May 6 09:08:41 manjula klogd: connection1:0: ping timeout of 5 secs
expired, last rx 4636971545, last ping 4636970295, now 4636974045
May 6 09:08:41 manjula klogd: connection1:0: detected conn error
(1011)
May 6 09:08:42 manjula iscsid: Kernel reported iSCSI connection 1:0
error (1011) state (3)
May 6 09:08:45 manjula iscsid: connection1:0 is operational after
recovery (1 attempts)
May 6 09:09:49 manjula klogd: connection1:0: ping timeout of 5 secs
expired, last rx 4636988378, last ping 4636977795, now 4636990878
May 6 09:09:49 manjula klogd: connection1:0: detected conn error
(1011)
May 6 09:09:49 manjula iscsid: Kernel reported iSCSI connection 1:0
error (1011) state (3)
May 6 09:09:52 manjula iscsid: connection1:0 is operational after
recovery (1 attempts)
May 6 09:10:36 manjula klogd: connection1:0: ping timeout of 5 secs
expired, last rx 4637000296, last ping 4637000296, now 4637002796
May 6 09:10:36 manjula klogd: connection1:0: detected conn error
(1011)
May 6 09:10:37 manjula iscsid: Kernel reported iSCSI connection 1:0
error (1011) state (3)
May 6 09:10:40 manjula iscsid: connection1:0 is operational after
recovery (1 attempts)
There seem to be about one minute between the failures. One
observation, it's always connection1:0 that fails.
Both target ports are connected to the same switch.
Furthermore, are there supposed to as many processes as this ?
root 104 2 0 Apr20 ? 00:00:00 [scsi_eh_0]
root 124 2 0 Apr20 ? 00:00:00 [scsi_eh_1]
root 125 2 0 Apr20 ? 00:00:00 [scsi_eh_2]
root 126 2 0 Apr20 ? 00:00:00 [scsi_eh_3]
root 127 2 0 Apr20 ? 00:00:00 [scsi_eh_4]
root 134 2 0 Apr20 ? 00:00:00 [scsi_eh_5]
root 135 2 0 Apr20 ? 00:00:00 [scsi_eh_6]
root 9580 2 0 May05 ? 00:00:00 [scsi_eh_24]
root 9581 2 0 May05 ? 00:00:00 [scsi_wq_24]
root 9583 2 0 May05 ? 00:00:00 [scsi_eh_25]
root 9584 2 0 May05 ? 00:00:00 [scsi_wq_25]
root 16981 2 0 08:35 ? 00:00:00 [scsi_eh_26]
root 16982 2 0 08:35 ? 00:00:00 [scsi_wq_26]
root 16984 2 0 08:35 ? 00:00:00 [scsi_eh_27]
root 16985 2 0 08:35 ? 00:00:00 [scsi_wq_27]
root 18289 2 0 Apr21 ? 00:00:00 [scsi_eh_10]
root 18290 2 0 Apr21 ? 00:00:00 [scsi_wq_10]
root 18369 2 0 Apr21 ? 00:00:00 [scsi_eh_11]
root 18370 2 0 Apr21 ? 00:00:00 [scsi_wq_11]
root 18448 2 0 08:52 ? 00:00:00 [iscsi_eh]
root 18517 1 0 08:52 ? 00:00:00 /sbin/iscsid -c /etc/
iscsi/iscsid.conf -p /var/run/iscsi.pid
root 18518 1 0 08:52 ? 00:00:00 /sbin/iscsid -c /etc/
iscsi/iscsid.conf -p /var/run/iscsi.pid
root 18547 2 0 08:52 ? 00:00:00 [scsi_eh_28]
root 18548 2 0 08:52 ? 00:00:00 [scsi_wq_28]
root 18549 2 0 08:52 ? 00:00:00 [iscsi_scan_28]
root 18550 2 0 08:52 ? 00:00:00 [scsi_eh_29]
root 18551 2 0 08:52 ? 00:00:00 [scsi_wq_29]
root 18552 2 0 08:52 ? 00:00:00 [iscsi_scan_29]
root 18719 2 0 Apr21 ? 00:00:00 [scsi_eh_12]
root 18720 2 0 Apr21 ? 00:00:02 [scsi_wq_12]
root 18722 2 0 Apr21 ? 00:00:00 [scsi_eh_13]
root 18723 2 0 Apr21 ? 00:00:00 [scsi_wq_13]
root 19272 15942 0 09:15 pts/0 00:00:00 grep scsi
root 25657 2 0 May01 ? 00:00:00 [scsi_eh_14]
root 25659 2 0 May01 ? 00:00:00 [scsi_wq_14]
root 25663 2 0 May01 ? 00:00:00 [scsi_eh_15]
root 25664 2 0 May01 ? 00:00:00 [scsi_wq_15]
root 26038 2 0 May01 ? 00:00:00 [scsi_eh_16]
root 26039 2 0 May01 ? 00:00:00 [scsi_wq_16]
root 26041 2 0 May01 ? 00:00:00 [scsi_eh_17]
root 26042 2 0 May01 ? 00:00:00 [scsi_wq_17]
root 26390 2 0 May01 ? 00:00:00 [scsi_eh_18]
root 26392 2 0 May01 ? 00:00:00 [scsi_wq_18]
root 26427 2 0 May01 ? 00:00:00 [scsi_eh_19]
root 26428 2 0 May01 ? 00:00:00 [scsi_wq_19]
root 26763 2 0 May01 ? 00:00:00 [scsi_eh_20]
root 26764 2 0 May01 ? 00:00:00 [scsi_wq_20]
root 26766 2 0 May01 ? 00:00:00 [scsi_eh_21]
root 26767 2 0 May01 ? 00:00:00 [scsi_wq_21]
root 27122 2 0 May01 ? 00:00:00 [scsi_eh_22]
root 27123 2 0 May01 ? 00:00:00 [scsi_wq_22]
root 27125 2 0 May01 ? 00:00:00 [scsi_eh_23]
root 27126 2 0 May01 ? 00:00:00 [scsi_wq_23]
TIA
// Jonas
Mike Christie
> I have now changed the following, correct ?
>
> ## node.conn[0].timeo.noop_out_interval = 5
> node.conn[0].timeo.noop_out_interval = 0
> node.conn[1].timeo.noop_out_interval = 0
>
> # node.conn[0].timeo.noop_out_timeout = 5
> node.conn[0].timeo.noop_out_timeout = 0
> node.conn[1].timeo.noop_out_timeout = 0
>
> I noticed this:
>
> May 6 08:52:22 manjula iscsid: connection2:0 is operational now
> May 6 08:52:22 manjula iscsid: connection1:0 is operational now
>
> Should the above changes instead be:
>
> node.conn[1].xxx
> node.conn[2].xxx
No. The first numnber in connectionX:Y is the session number.
>
> I still see the same errors though:
>
> May 6 09:07:06 manjula klogd: connection1:0: ping timeout of 5 secs
> expired, last rx 4636947795, last ping 4636942795, now 4636950295
It looks the value did not get picked up. Forget I asked you to do this
ok? We do not need it.
Could you just try
http://open-iscsi.org/bits/open-iscsi-2.0-869.1.test1.tar.gz
Remove the old iscsi tools (I think in suse the package is named
open-iscsi).
Do
rpm -e open-iscsi
Now build this test package
http://open-iscsi.org/bits/open-iscsi-2.0-869.1.test1.tar.gz
with extra debugging:
Build it with
make DEBUG_SCSI=1
make DEBUG_SCSI=1 install
>
> Furthermore, are there supposed to as many processes as this ?
>
You are going to get a scsi_eh and a scsi_wq and a iscsi_scan thread per
session/target. Some targets do a target per device/LU/LUN and in that
case you would see a lot. If you run iscsiadm -m session we can see what
is up.
swejis
Compiled new package (added suse-parameters recommended from readme
file)
make DEBUG_SCSI=1 KSRC=/usr/src/linux-2.6.25-rc9-17 KBUILD_OUTPUT=/usr/
src/linux-obj/x86_64/default
Compilation complete Output file
----------------------------------- ----------------
Built iSCSI Open Interface module: kernel/scsi_transport_iscsi.ko
Built iSCSI library module: kernel/libiscsi.ko
Built iSCSI over TCP kernel module: kernel/iscsi_tcp.ko
Built iSCSI daemon: usr/iscsid
Built management application: usr/iscsiadm
make DEBUG_SCSI=1 install
make -C kernel install_kernel
make[1]: Entering directory `/opt/src/open-iscsi-2.0-869.1.test1/
kernel'
make[1]: *** No rule to make target `linux_2_6_', needed by
`kernel_check'. Stop.
make[1]: Leaving directory `/opt/src/open-iscsi-2.0-869.1.test1/
kernel'
make: *** [install_kernel] Error 2
Am I doing something wrong? Do I have to prepare the kernel source
tree somehow? I just installed the sources.
rgds
Jonas
Mike Christie
Apply the attached patch.
swejis
compare against your previously attached patch but with no success.
manjula:/opt/src/open-iscsi-2.0-869.1.test1 # patch < iscsi.patch
patching file Makefile
Hunk #1 FAILED at 32.
1 out of 1 hunk FAILED -- saving rejects to file Makefile.rej
patching file Makefile
Hunk #1 FAILED at 32.
Hunk #2 FAILED at 64.
Hunk #3 FAILED at 133.
Hunk #4 FAILED at 176.
4 out of 4 hunks FAILED -- saving rejects to file Makefile.rej
patching file Makefile
Hunk #1 FAILED at 7.
1 out of 1 hunk FAILED -- saving rejects to file Makefile.rej
May I kindly ask you to attach this patch as you did with the other
one ?
Thanks
Jonas
swejis
Built and installed the debug-initiator.
The [scsi_eh_xx] scsi_wq_xx] processes, there are about 60 of those
before I have even started open-iscsi, zombies ?
May 6 21:03:53 manjula iscsid: connection3:0 is operational now
May 6 21:03:53 manjula iscsid: connection4:0 is operational now
3 and 4 now, could this be caused by those processes ?
I would have expected this version to be very noisy log-wise, however
I have stressed the disk quite alot now and have not seen anything in
the log. Performance actually also looks better. 3GB in 40 sec, that
is far better than before.
Those processes, could I just shut everything down and kill the
remaining ?
Rgds
Jonas
Michael Christie
>
> OK, were back in business.
>
> Built and installed the debug-initiator.
>
> The [scsi_eh_xx] scsi_wq_xx] processes, there are about 60 of those
> before I have even started open-iscsi, zombies ?
>
Eh..... I do not know what is on your box. If you have not started
open-iscsi they could be from something else.
> May 6 21:03:53 manjula iscsid: connection3:0 is operational now
> May 6 21:03:53 manjula iscsid: connection4:0 is operational now
>
> 3 and 4 now, could this be caused by those processes ?
>
I am not sure what you are doing. If yo had started iscsi previously then
the session number would be incremented like it is above.
> I would have expected this version to be very noisy log-wise, however
It should be really noisy. Did you build with "make DEBUG_SCSI=1"?
> I have stressed the disk quite alot now and have not seen anything in
> the log. Performance actually also looks better. 3GB in 40 sec, that
> is far better than before.
>
> Those processes, could I just shut everything down and kill the
> remaining ?
>
Yeah, reboot the box, use the new modules and tools build with
DEBUG_SCSI=1. Remove the suse tools, stop the init iscsi and open-iscsi
init scripts from running, and then just start iscsid by hand. Then run
iscsiadm by hand.
> Rgds
> Jonas
> >
>
swejis
until now. Still I had no success getting your test-version to write
more debug info into the logs. I therefor downloaded and compiled the
latest semi-stable version I found meaning 2.0-869.2. When not this
version either wrote any debug-info I started to look around and
realized the kernel modules where far older than expected. It seem
even though I have not installed anything related to open-iscsi suse
still ships the kernel-modules of open-iscsi. I think this cause the
install_kernel function to skip installing the modules and only return
"kernel is up to date", anyway after I manually copied the kernel
modules and fired up iscsi.. finally I can see more info in the the
logs. The messages file is found here: http://www.wehay.com/messages.gz
and contains two connections errors.
Brgds Jonas
swejis
http://www.wehay.com/iscsi.cap.gz
Frame 225 Target sends a reset followed by a new login from the
initiator. Can't see the reason for that reset though.
Brgds Jonas
swejis
Mike Christie
Can you remind me what target you are using and how many sessions you
should have? It looks like only one session has problems. The other/s
look like they are just fine. Are the errors now (before I understood
that it happened when no IO was running) only occuring when you put IO
on the session/disk?
Pasi Kärkkäinen
From the first mail of this thread:
"The target is the infamous Promise m500i"
-- Pasi
swejis
> > Can you remind me what target you are using and how many sessions you
> > should have?
portal.
tcp: [1] 192.168.43.6:3260,2 iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20
tcp: [2] 192.168.43.5:3260,1 iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20
> > It looks like only one session has problems.
error, I actually
tried to shift to the second portal when doing the discovery in order
to see if that would make
any difference.
The other/s
> > look like they are just fine. Are the errors now (before I understood
> > that it happened when no IO was running) only occuring when you put IO
> > on the session/disk?
thought we had fixed the problem when I had not seen any errors for
days, but
during that time the machine just idled, as soon as I got some I/O the
error came back immediately.
Brgds Jonas
swejis
only one connection seem to suffer of those connections errors. What
also said however is that only connections with I/O suffer. One thing
bothered me for some time is that the /dev/sdX devices "move around"
when restarting the initiator. To settle this once and for all I read
thought quite a few posts this morning until I finally found one with
a solution. I was unaware of the /dev/disk/by-path devices. By instead
using one of those devices I mounted one lun pointing to the other
connection, and now I see both connection report errors.
tcp: [3] 192.168.43.6:3260,2 iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20
tcp: [4] 192.168.43.5:3260,1 iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20
May 29 09:36:32 manjula klogd: connection3:0: detected conn error
(1011)
May 29 09:36:33 manjula iscsid: Kernel reported iSCSI connection 3:0
error (1011) state (3)
May 29 09:48:37 manjula klogd: connection4:0: detected conn error
(1011)
May 29 09:48:38 manjula iscsid: Kernel reported iSCSI connection 4:0
error (1011) state (3)
May 29 09:49:11 manjula klogd: connection4:0: detected conn error
(1011)
May 29 09:49:12 manjula iscsid: Kernel reported iSCSI connection 4:0
error (1011) state (3)
swejis
Node ID 1
Node Name iqn.1994-12.com.promise.target.a9.39.4.55.1.0.0.20
Node Alias VTrak M500i
Max Outstanding R2T 1
Max Burst Length 256KB
Max Connections 1
Default Time to Wait 2 Seconds
Default Time to Retain 20 Seconds
Error Recovery Level 0
Initial R2T Enabled
Header Digest Disabled
Data Digest Disabled
Data PDU In Order Disabled
Data Sequence In Order Disabled
Uni-directional CHAP Authentication Enabled
Bi-directional CHAP Authentication Disabled
Help text.
* Maximum number of nodes supported
* Number of nodes present
* Number of failed nodes
* Node ID
* Node Name – An iSCSI node is identified by its name.
* Node Alias – A user-friendly string associated with an iSCSI
Node. Not a substitute for the iSCSI Name.
* Max outstanding R2T – Sets the maximum number of outstanding
ready to transfer PDUs (a number).
* Maximum burst length – Maximum length of a solicited data
sequence (512 B to 16,776,704 B [16 MB – 512 B]).
* Maximum number of connections – Maximum number of connections
supported.
* Default time to wait – After a dropped connection, the number of
seconds to wait before attempting to reconnect.
* Default time to retain – Number of seconds after time to wait
(above) before reassigning outstanding commands.
* Error recovery level – Error recovery level supported.
* Initial R2T – Allows initiator to begin sending data to a target
without receiving a ready to transfer command.
* Header Digest – Enables the use of Header Digest (CRC). See note
below.
* Data Digest – Enables the use of a Data Digest (CRC). See note
below.
* Data PDU in order – Enables placement of data in PDU order.
* Data sequence in order – Enables placement of data in sequence
order.
* Uni-directional CHAP Authentication – Enables Challenge
Handshake Authentication Protocol.
* Bi-directional CHAP Authentication – Enables bi-directional and
uni-directional CHAP authentication.
Pasi Kärkkäinen
Hi!
I'm also (unfortunately) running Promise m500i on one setup, and I've had
problems with it basicly all the time. Should just get rid of it and replace
it with something more stable and powerful.
You can check this thread for more info about my problems with this target:
"open-iscsi with Promise M500i dropping session / Nop-out timedout"
Basicly I'm seeing "Nop-out timedout" and "Session dropped" errors whenever
there is IO going on..
-- Pasi
swejis
post some Target-configuration to compare ?
Pasi Kärkkäinen
>
> Thanks Pasi, I saw your post a couple of days ago. Perhaps you could
> post some Target-configuration to compare ?
>
It's pretty much the standard or "out of the box" configuration with a
couple of LD's defined.. I'm running the latest Promise firmware.
I have two disk arrays, both having a single LD (so two LD's total).
This LD having problems is RAID5 with 5 drives in use (and a hotspare).
I'm not sure if the other LD has problems too.. It's being used by
Qlogic iSCSI HBA so I'm not sure if there are problems or not.
-- Pasi
Mike Christie
But with this test are there no nop out timed out errors like before?
Mike Christie
Hey could you guys try this patch. It is made over open-iscsi-2.0-869.2.
Pasi, I do not think 869 compiles over RHEL, because it has some stuff
backported that the tarball does not expect, so you would have to run a
kernel.org kernel.
swejis
Am I doing something wrong again ?
patch -p1 -i ../more-nop-debug.patch
patching file kernel/libiscsi.c
Hunk #1 FAILED at 319.
Hunk #2 FAILED at 481.
Hunk #3 FAILED at 639.
Hunk #4 succeeded at 758 with fuzz 2 (offset 10 lines).
Hunk #5 FAILED at 1401.
4 out of 5 hunks FAILED -- saving rejects to file kernel/
libiscsi.c.rej
Brgds Jonas
swejis
previous patch applied.
New log: http://www.wehay.com/messages.1.gz
Brgds Jonas
swejis
Brgds Jonas
swejis
interval to zero.
manjula:/ # iscsiadm -m node -T iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20 -p 192.168.43.5:3260 -o
update -n node.conn[0].timeo.noop_out_interval -v 0
manjula:/ # iscsiadm -m node -T iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20 -p 192.168.43.5:3260 -o
update -n node.conn[0].timeo.noop_out_timeout -v 0
manjula:/ # iscsiadm -m node --targetname iqn.
1994-12.com.promise.target.a9.39.4.55.1.0.0.20 | grep noop
Still I'm seeing quite a few connection errors (with the latest path
applied)
New logfile with many errors: http://whs3.wehay.com/messages.gz
Mike Christie
Yeah, something is still setting the nops somehow so we are still
hitting the same problem. If you do
cat /sys/class/iscsi_connection/connectionX:0/ping_tmo
cat /sys/class/iscsi_connection/connectionX:0/recv_tmo
Do you see 5 for both values (X would be the session number)?
Could also send the beginning of the log where you login and see the
scsi devices get added? The parts right after:
Loading iSCSI transport class v2.0-869.
iscsi: registered transport (tcp)
Up to the parts where you see the last scsi device get added.
Also what arch are you running? Are you running x86 or x86_64? If the
latter are you running both 64bit kernels and userspace?
And could you just run iscsid by hand with
iscsid -d 8 -f &
login to the target then send the output? You do not have to do any
other IO. I just want to make sure the params are getting sent to the
kernel right.
Oh yeah I found the reason for the zobmie process you were hitting.
There was a bug introduced into 2.5.25 which left them hanging around
even though we removed the host and sessions. You need the attached
patch on your kernel to fix the problem.
swejis
> swejis wrote:
> > I managed to reconfigure the nop-timeouts and set both timeout and
> > interval to zero.
>
> > manjula:/ # iscsiadm -m node -T iqn.
> > 1994-12.com.promise.target.a9.39.4.55.1.0.0.20 -p 192.168.43.5:3260 -o
> > update -n node.conn[0].timeo.noop_out_interval -v 0
> > manjula:/ # iscsiadm -m node -T iqn.
> > 1994-12.com.promise.target.a9.39.4.55.1.0.0.20 -p 192.168.43.5:3260 -o
> > update -n node.conn[0].timeo.noop_out_timeout -v 0
>
> > manjula:/ # iscsiadm -m node --targetname iqn.
> > 1994-12.com.promise.target.a9.39.4.55.1.0.0.20 | grep noop
> > node.conn[0].timeo.noop_out_interval = 0
> > node.conn[0].timeo.noop_out_timeout = 0
> > node.conn[0].timeo.noop_out_interval = 0
> > node.conn[0].timeo.noop_out_timeout = 0
>
> > Still I'm seeing quite a few connection errors (with the latest path
> > applied)
>
> Yeah, something is still setting the nops somehow so we are still
> hitting the same problem. If you do
>
> cat /sys/class/iscsi_connection/connectionX:0/ping_tmo
> cat /sys/class/iscsi_connection/connectionX:0/recv_tmo
>
> Do you see 5 for both values (X would be the session number)?
manjula:~ # cat /sys/class/iscsi_connection/connection*/recv_tmo
5
5
manjula:~ # cat /sys/class/iscsi_connection/connection*/ping_tmo
5
5
> Could also send the beginning of the log where you login and see the
> scsi devices get added? The parts right after:
>
> Loading iSCSI transport class v2.0-869.
> iscsi: registered transport (tcp)
>
> Up to the parts where you see the last scsi device get added.
that do ?
> Also what arch are you running? Are you running x86 or x86_64? If the
> latter are you running both 64bit kernels and userspace?
manjula:/sbin # file iscsid
iscsid: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), for GNU/
Linux 2.6.4, dynamically linked (uses shared libs), not stripped
manjula:/lib/modules/2.6.25.3-2-default/kernel/drivers/scsi # ls |
grep iscsi | while read i ; do file $i ; done
iscsi_tcp.ko: ELF 64-bit LSB relocatable, x86-64, version 1 (SYSV),
not stripped
libiscsi.ko: ELF 64-bit LSB relocatable, x86-64, version 1 (SYSV), not
stripped
scsi_transport_iscsi.ko: ELF 64-bit LSB relocatable, x86-64, version 1
(SYSV), not stripped
> And could you just run iscsid by hand with
>
> iscsid -d 8 -f &
>
> login to the target then send the output? You do not have to do any
> other IO. I just want to make sure the params are getting sent to the
> kernel right.
Brgds Jonas
Mike Christie
>> Up to the parts where you see the last scsi device get added.
>
> I previously posted this file: http://www.wehay.com/messages.1.gz wont
> that do ?
No. I do not need any of the kernel info. It all seems to be telling us
that the kernel really does think we set the timers as 5 seconds. We
want to see why iscsid thinks it wants to set these timers as 5 seconds
even though you set it so it shouldn't.
>
>> Also what arch are you running? Are you running x86 or x86_64? If the
>> latter are you running both 64bit kernels and userspace?
>
> Everything should have been built for the x86_64 architecture.
>
> manjula:/sbin # file iscsid
> iscsid: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), for GNU/
> Linux 2.6.4, dynamically linked (uses shared libs), not stripped
>
ok.
swejis
the timeout values to zero. Yesterday I removed all "saved data"
meaning the nodes and send_targets directory from /etc/isci and reran
the discovery, now the values where indeed set. I did this yesterday
on two machines (one 64 and one 32 bit) and have not seen any
connection-error since, nothing else reported from iscsid for that
matter.
manjula:/ # cat /sys/class/iscsi_connection/connection*/ping_tmo
0
0
manjula:/ # cat /sys/class/iscsi_connection/connection*/recv_tmo
0
0
swejis
holding our mySQL database on this server. Everything looks 'quite'
well part from the error I got this morning. All nop time out set to
zero.
Jul 1 07:15:23 manjula syslog-ng[17906]: STATS: dropped 0
Jul 1 07:20:38 manjula kernel: Pid: 0, comm: swapper Tainted:
G N 2.6.25.5-1.1-default #1
Jul 1 07:20:38 manjula kernel:
Jul 1 07:20:38 manjula kernel: Call Trace:
Jul 1 07:20:38 manjula kernel: [<ffffffff8020d686>] dump_trace
+0xc4/0x576
Jul 1 07:20:38 manjula kernel: [<ffffffff8020db78>] show_trace
+0x40/0x57
Jul 1 07:20:38 manjula kernel: [<ffffffff8044f865>] _etext+0x72/0x7b
Jul 1 07:20:38 manjula kernel:
[<ffffffff8841c47a>] :libiscsi:iscsi_conn_failure+0x1a/0x90
Jul 1 07:20:38 manjula kernel:
[<ffffffff8842960b>] :iscsi_tcp:iscsi_tcp_state_change+0x41/0x5e
Jul 1 07:20:38 manjula kernel: [<ffffffff803ff632>] tcp_done
+0x61/0x70
Jul 1 07:20:38 manjula kernel: [<ffffffff8040339f>] tcp_reset
+0x55/0x59
Jul 1 07:20:38 manjula kernel: [<ffffffff80409add>]
tcp_rcv_established+0x981/0xd30
Jul 1 07:20:38 manjula kernel: [<ffffffff8040fc7d>] tcp_v4_do_rcv
+0x31/0x1d3
Jul 1 07:20:38 manjula kernel: [<ffffffff8041035f>] tcp_v4_rcv
+0x540/0x7c0
Jul 1 07:20:38 manjula kernel: [<ffffffff803f5bd6>]
ip_local_deliver_finish+0x124/0x1f9
Jul 1 07:20:38 manjula kernel: [<ffffffff803f5d1d>] ip_local_deliver
+0x72/0x7a
Jul 1 07:20:38 manjula kernel: [<ffffffff803f57e6>] ip_rcv_finish
+0x306/0x32d
Jul 1 07:20:38 manjula kernel: [<ffffffff803f5a7c>] ip_rcv+0x26f/
0x2a5
Jul 1 07:20:38 manjula kernel: [<ffffffff803d478a>] netif_receive_skb
+0x408/0x42d
Jul 1 07:20:38 manjula kernel: [<ffffffff882350f8>] :tg3:tg3_poll
+0x7d8/0xae1
Jul 1 07:20:38 manjula kernel: [<ffffffff803d2e55>] net_rx_action
+0xba/0x1fc
Jul 1 07:20:38 manjula kernel: [<ffffffff8023ca52>] __do_softirq
+0x6d/0xe1
Jul 1 07:20:38 manjula kernel: [<ffffffff8020d3fc>] call_softirq
+0x1c/0x28
Jul 1 07:20:38 manjula kernel: DWARF2 unwinder stuck at call_softirq
+0x1c/0x28
Jul 1 07:20:38 manjula kernel:
Jul 1 07:20:38 manjula kernel: Leftover inexact backtrace:
Jul 1 07:20:38 manjula kernel:
Jul 1 07:20:38 manjula kernel: <IRQ> [<ffffffff8020e94c>] ?
do_softirq+0x44/0x8b
Jul 1 07:20:38 manjula kernel: [<ffffffff8023c823>] ? irq_exit+0x3f/
0x80
Jul 1 07:20:38 manjula kernel: [<ffffffff8020ec03>] ? do_IRQ+0xba/
0xd8
Jul 1 07:20:38 manjula kernel: [<ffffffff8020b0d2>] ? default_idle
+0x0/0x78
Jul 1 07:20:38 manjula kernel: [<ffffffff8020c59d>] ? ret_from_intr
+0x0/0x19
Jul 1 07:20:38 manjula kernel: <EOI> [<ffffffff8024eee7>] ?
getnstimeofday+0x31/0x88
Jul 1 07:20:38 manjula kernel: [<ffffffff8020b133>] ? default_idle
+0x61/0x78
Jul 1 07:20:38 manjula kernel: [<ffffffff8020b12e>] ? default_idle
+0x5c/0x78
Jul 1 07:20:38 manjula kernel: [<ffffffff8020b0d2>] ? default_idle
+0x0/0x78
Jul 1 07:20:38 manjula kernel: [<ffffffff8020b08a>] ? cpu_idle
+0x92/0xda
Jul 1 07:20:38 manjula kernel: [<ffffffff804447fc>] ? start_secondary
+0x408/0x417
Jul 1 07:20:38 manjula kernel:
Jul 1 07:20:38 manjula kernel: connection3:0: detected conn error
(1011)
Jul 1 07:20:39 manjula iscsid: Target dropping connection 0,
reconnect min 0 max 0
Jul 1 07:20:39 manjula iscsid: Kernel reported iSCSI connection 3:0
error (1011) state (3)
Jul 1 07:20:40 manjula iscsid: connection3:0 is operational after
recovery (1 attempts)
Looks like a tcp-reset was received ? Would it help if I start the
initiator by hand and increased debug-level ?
TIA
Brgds Jonas
Mike Christie
No. It looks like the target dropped the connection on us. Did you see
anything on the target logs?
swejis
> > initiator by hand and increased debug-level ?
>
> No. It looks like the target dropped the connection on us. Did you see
> anything on the target logs?
good log-function being one (jumboframes another). The only log
facility I am aware of is the so called eventlogger, only giving
information on major events such as disk failures etc. I am certain
however a more sophisticated log-function does exist but is kept
hidden from us mortals. Perhaps if Pasi reads this knows something
that I do not (in the matter hehe..) ? Log entrys on the initiator
side before and after the iscsi-error reveals the error occurred
during backup which most likely is the I/O peak. No error was however
reported by the backup routine nor have I found any data inconsistent.
Probably yet another stupid question, but how is that possible ? Is a
modern filesystem (I use XFS) able to recover or are the program told
by the initiator to wait until it's recover have completed ?
Last night backup succeeded with no errors reported.
Furthermore I would also like (as others) to thank you Mike for
spending time to help someone like me. It is greatly appreciated and
widely spread among those in doubt of the open source philosophy.
Brgds Jonas
Pasi Kärkkäinen
>
> > > Looks like a tcp-reset was received ? Would it help if I start the
> > > initiator by hand and increased debug-level ?
> >
> > No. It looks like the target dropped the connection on us. Did you see
> > anything on the target logs?
>
> I am afraid not, this target unfortunately leaves much to wish for, a
> good log-function being one (jumboframes another). The only log
> facility I am aware of is the so called eventlogger, only giving
> information on major events such as disk failures etc. I am certain
> however a more sophisticated log-function does exist but is kept
> hidden from us mortals. Perhaps if Pasi reads this knows something
> that I do not (in the matter hehe..) ?
Hi!
I'm afraid I don't know more about that..
My general impression about this target (Promise Vtrak M500i) is that it sucks a
lot. I've seen a lot of target crashes, failing firmware updates, missing
(unimplemented) features in the menus, especially in the cmdline, missing
links on the web management (mentioned in the docs but nowhere in the actual
gui) and general feeling of "unstable and not finished".. not to mention bad
customer support.
It's the same as always.. good and cheap come in different packages :(
-- Pasi