iSCSI connection lost

Status
Not open for further replies.

tequesta

Cadet
Joined
Mar 15, 2012
Messages
1
Hello everybody, this is my situation:

I got two scenarios, one of testing and one of production.

Both scenarios has 2 IBM servers (testing 2 x IBM x346 and production, 1 IBM x3400 and 1 IBM x3200) all four only has local disk for storage.
All has ESXi 4.1 U2 installed on.

On both scenarios I got some VMs and one of them has FreeNAS (8.0.3 on testing and now 8.0.4 on production) installed on.

On both scenarios I configure the FreeNAS and ESXi following this: http://www.vladan.fr/how-to-configure-freenas-8-for-iscsi-and-connect-to-esxi/

On both scenarios I configure ghettoVCB to backup VMs and send the backups to the shared storage from FreeNAS.

On testing scenario, everything going fine and after one week of test, I implement the solution on production and it never work.

The ESXi lost and reestablish the connection all the time, the speed sucks, and so on.

This is a part of the log from ESXi:

3/15/2012 9:26:54 AM - esxi02.local - Successfully restored access to volume 4f61cb8c-b99bbea0-297c-00145e5d7158 (backup) following connectivity issues.
3/15/2012 9:26:49 AM - esxi02.local - Lost access to volume 4f61cb8c-b99bbea0-297c-00145e5d7158 (backup) due to connectivity issues. Recovery attempt is in progress and outcome will be reported shortly.
3/15/2012 9:26:23 AM - esxi02.local - Successfully restored access to volume 4f61cb8c-b99bbea0-297c-00145e5d7158 (backup) following connectivity issues.
3/15/2012 9:26:19 AM - esxi02.local - Lost access to volume 4f61cb8c-b99bbea0-297c-00145e5d7158 (backup) due to connectivity issues. Recovery attempt is in progress and outcome will be reported shortly.

This is part of the messages from FreeNAS:

Mar 15 05:25:52 freenas istgt[1718]: Login from iqn.1998-01.com.vmware:esxi02-4dea8d88 (192.168.70.10) on iqn.2011-03.example.org.istgt:backup LU1 (192.168.70.15:3260,1), ISID=23d000002, TSIH=12, CID=0, HeaderDigest=off, DataDigest=off
Mar 15 05:26:19 freenas istgt[1718]: istgt_lu_disk.c:5137:istgt_lu_disk_queue_start: ***WARNING*** transfer abort CmdSN=2178
Mar 15 05:26:19 freenas istgt[1718]: istgt_lu.c:2798:luworker: ***WARNING*** LU1: lu_disk_queue_start() aborted
Mar 15 05:26:19 freenas istgt[1718]: istgt_iscsi.c: 777:istgt_iscsi_write_pdu_internal: ***ERROR*** iscsi_write() failed (errno=32)
Mar 15 05:26:19 freenas istgt[1718]: istgt_iscsi.c:3508:istgt_iscsi_task_response: ***ERROR*** iscsi_write_pdu() failed
Mar 15 05:26:19 freenas istgt[1718]: istgt_iscsi.c:4957:sender: ***ERROR*** iscsi_task_response() failed on iqn.2011-03.example.org.istgt:backup,t,0x0001(iqn.1998-01.com.vmware:esxi02-4dea8d88,i,0x00023d000002)

This situation starts the past monday and I surf a lot on the forums before post. If anybody can give me a clue on this, a really apreciate that.

Thanks a lot.

tequesta
 

DavePearson

Cadet
Joined
Jun 3, 2012
Messages
1
Hi

I have Freenas 8.0.4p2. Created an iSCSI target pointing at a zvol. Connected to this fine from VirtualBox, but get a very similar bunch of messages to you about 40% into the install of ubuntu in the VM - i.e. once the ubuntu installer starts to do a serious amount of i/o while unpacking all of the packages.

It's not a huge problem - we can use volumes on NFS for now, but a shame we can't succesfully try out iScsi from freenas with virtualbox.

Bit more detail:

Thought I'd give it another go... Bit more info from the logs - istgt didn't crash for me this time, but lots of disconnects & had to resume the VM over&over. Errors on the FreeNAS side:

Jun 5 18:12:43 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6de, TSIH=17, CID=1, HeaderDigest=off, DataDigest=off
Jun 5 18:12:43 giggs istgt[42755]: istgt_iscsi.c:3226:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/66) QCmdSN(63) error
Jun 5 18:12:43 giggs istgt[42755]: istgt_iscsi.c:4619:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Jun 5 18:12:43 giggs istgt[42755]: istgt_iscsi.c:5259:worker: ***ERROR*** iscsi_execute() failed on iqn.ecomsolve.com.tgt:targetname,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26,i,0x80123456e6de)
Jun 5 18:12:44 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6df, TSIH=18, CID=1, HeaderDigest=off, DataDigest=off
Jun 5 18:12:44 giggs istgt[42755]: istgt_iscsi.c:3226:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/39) QCmdSN(36) error
Jun 5 18:12:44 giggs istgt[42755]: istgt_iscsi.c:4619:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Jun 5 18:12:44 giggs istgt[42755]: istgt_iscsi.c:5259:worker: ***ERROR*** iscsi_execute() failed on iqn.ecomsolve.com.tgt:targetname,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26,i,0x80123456e6df)
Jun 5 18:12:45 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6e0, TSIH=19, CID=1, HeaderDigest=off, DataDigest=off
Jun 5 18:13:23 giggs istgt[42755]: istgt_iscsi.c:3226:istgt_iscsi_op_scsi: ***ERROR*** StatSN(3020/3056) QCmdSN(35) error
Jun 5 18:13:23 giggs istgt[42755]: istgt_iscsi.c:4619:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Jun 5 18:13:23 giggs istgt[42755]: istgt_iscsi.c:5259:worker: ***ERROR*** iscsi_execute() failed on iqn.ecomsolve.com.tgt:targetname,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26,i,0x80123456e6e0)
Jun 5 18:13:25 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6e7, TSIH=20, CID=1, HeaderDigest=off, DataDigest=off
Jun 5 18:13:25 giggs istgt[42755]: istgt_iscsi.c:3226:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/55) QCmdSN(52) error
Jun 5 18:13:25 giggs istgt[42755]: istgt_iscsi.c:4619:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Jun 5 18:13:25 giggs istgt[42755]: istgt_iscsi.c:5259:worker: ***ERROR*** iscsi_execute() failed on iqn.ecomsolve.com.tgt:targetname,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26,i,0x80123456e6e7)
Jun 5 18:13:30 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6e8, TSIH=21, CID=1, HeaderDigest=off, DataDigest=off
Jun 5 18:13:34 giggs istgt[42755]: istgt_iscsi.c:3226:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/41) QCmdSN(38) error
Jun 5 18:13:34 giggs istgt[42755]: istgt_iscsi.c:4619:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Jun 5 18:13:34 giggs istgt[42755]: istgt_iscsi.c:5259:worker: ***ERROR*** iscsi_execute() failed on iqn.ecomsolve.com.tgt:targetname,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26,i,0x80123456e6e8)
Jun 5 18:13:35 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6e9, TSIH=22, CID=1, HeaderDigest=off, DataDigest=off
Jun 5 18:13:35 giggs istgt[42755]: istgt_iscsi.c:3226:istgt_iscsi_op_scsi: ***ERROR*** StatSN(2/65) QCmdSN(62) error
Jun 5 18:13:35 giggs istgt[42755]: istgt_iscsi.c:4619:istgt_iscsi_execute: ***ERROR*** iscsi_op_scsi() failed
Jun 5 18:13:35 giggs istgt[42755]: istgt_iscsi.c:5259:worker: ***ERROR*** iscsi_execute() failed on iqn.ecomsolve.com.tgt:targetname,t,0x0001(iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26,i,0x80123456e6e9)
Jun 5 18:13:36 giggs istgt[42755]: Login from iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 (10.107.1.26) on iqn.ecomsolve.com.tgt:targetname LU1 (10.107.1.23:3260,1), ISID=80123456e6ea, TSIH=23, CID=1, HeaderDigest=off, DataDigest=off

Errors from the virtualbox point of view...

08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59135
00:19:07.400 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59136
00:19:08.405 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:08.418 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59136
00:19:08.418 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59137
00:19:09.423 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:09.423 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59137
00:19:09.424 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59138
00:19:10.428 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:10.435 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59138
00:19:10.435 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59139
00:19:11.440 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:11.473 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59139
00:19:11.473 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59140
00:19:12.479 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:12.490 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59140
00:19:12.490 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59141
00:19:13.495 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:13.526 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59141
00:19:13.527 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59142
00:19:14.535 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:14.561 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59142
00:19:14.561 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59143
00:19:15.567 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful
00:19:15.599 iSCSI: disconnect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59143
00:19:15.599 iSCSI: connect from initiator iqn.2009-08.com.sun.virtualbox.initiator:01:10.107.1.26 with source port 59144
00:19:16.606 iSCSI: login to target iqn.ecomsolve.com.tgt:targetname successful

Dave

PS as a footnote, just tried running Bonnie & get 30 MB/s out of the iscsi vs 100MB/s nfs performance.

My freenas setup is documented here: http://justwhatdoyouthinkyouredoing...2/06/host-virtualbox-vm-on-freenas-iscsi.html
 
Status
Not open for further replies.
Top