NAS-Absturz bei VM-Backup?

[AlbertMinrich]

Hallo,

ESX 3.5.0 Build 153875.
Es gibt zwei ESX-Server, VM´s liegen auf einem SUN Storage Tek NAS, Anbindung über SW-iSCSI. Ebenfalls über iSCSI angebunden ist ein Openfiler. Auf dem Openfiler wird nur gebackupt.

Gebackupt wird mit vmbk.pl (das gabs ursprünglich mal hier http://www.vmts.net).
Das machen wir seit ca. 2 Jahren so, es gab nie Probleme.

Jetzt ist innerhalb von 2 Tagen 3 mal das SUN-NAS abgestürzt, komischerweise immer, wenn grad ein Backup lief.

Wir haben natürlich einen Case beim SUN-Support aufgemacht, die sind noch beim analysieren. Aber ich wollte euch mal fragen, ob ihr schon ähnliches erlebt habt und euch bitten, mal einen Blick in unser vmkernel-log zu werfen.

Der (letzte) Absturz war gestern aben (08.03.2010 19:00 Uhr).
Hier mal auszugsweise einige vmkernel-Zeilen vor und nach dem Absturz:

Mar 8 14:48:12 esx-1 vmkernel: 1:07:24:50.987 cpu0:1180)Init: 1057: Received INIT from world 1180
Mar 8 14:48:42 esx-1 vmkernel: 1:07:25:20.705 cpu7:1068)LinSCSI: 3201: Abort failed for cmd with serial=3935, status=bad0001, retval=bad0001
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.304 cpu0:1177)iSCSI: session 0xb644c00 sending mgmt 25719 abort for itt 25695 task 0xb602420 cmnd 0x763be00 cdb 0x28 to (1 0 7 0) at 11313231
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.304 cpu7:1178)iSCSI: session 0xb644c00 abort success for mgmt 25719 due to completion of itt 25695, task 0xb602420, cmnd 0x763be00, cdb 0x28
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.304 cpu0:1177)iSCSI: session 0xb644c00 sending mgmt 25720 abort for itt 25699 task 0xb601620 cmnd 0x7639b00 cdb 0x28 to (1 0 7 0) at 11313231
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.305 cpu7:1178)iSCSI: session 0xb644c00 abort success for mgmt 25720 due to completion of itt 25699, task 0xb601620, cmnd 0x7639b00, cdb 0x28
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.309 cpu1:1177)iSCSI: session 0xb644c00 (1 0 7 0) finished error recovery at 11313231
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.309 cpu7:1180)Fil3: 4995: READ error 0xbad00e5
Mar 8 14:48:53 esx-1 vmkernel: 1:07:25:32.382 cpu6:1043)FS3: 4831: Reclaimed timed out heartbeat [HB state abcdef02 offset 3664896 gen 100 stamp 113115705744 uuid 4b934650-55fa80b4-e8d2-0021283d7baa jrnl <FB 970267> drv 4.31]
Mar 8 15:09:57 esx-1 vmkernel: 1:07:46:35.357 cpu2:1100)VSCSI: 4060: Creating Virtual Device for world 1101 vscsi0:0 (handle 8215)
Mar 8 15:47:30 esx-1 vmkernel: 1:08:24:08.088 cpu6:1180)Net: 4259: unicastAddr 00:50:56:b2:23:79;
Mar 8 15:52:49 esx-1 vmkernel: 1:08:29:27.096 cpu3:1100)DevFS: 2300: Unable to find device: 20020-agaana-000001-delta.vmdk
Mar 8 15:52:50 esx-1 vmkernel: 1:08:29:27.498 cpu1:1100)VSCSI: 4060: Creating Virtual Device for world 1101 vscsi0:0 (handle 8216)
Mar 8 15:52:50 esx-1 vmkernel: 1:08:29:27.501 cpu2:1102)World: vm 1184: 901: Starting world vmware-vmx with flags 44
Mar 8 15:52:52 esx-1 vmkernel: 1:08:29:29.388 cpu3:1100)DevFS: 2300: Unable to find device: 31043-agaana-000002-delta.vmdk
Mar 8 15:52:52 esx-1 vmkernel: 1:08:29:29.600 cpu1:1100)DevFS: 2300: Unable to find device: 49053-agaana-000002-delta.vmdk
Mar 8 15:52:52 esx-1 vmkernel: 1:08:29:29.976 cpu2:1100)DevFS: 2300: Unable to find device: 5059-agaana-000002-delta.vmdk
Mar 8 19:00:25 esx-1 vmkernel: 1:11:37:02.699 cpu7:1068)LinSCSI: 3201: Abort failed for cmd with serial=891395, status=bad0001, retval=bad0001
Mar 8 19:00:27 esx-1 vmkernel: 1:11:37:05.038 cpu0:1121)Cow: 866: IO to deltadisk handle 158448 failed: Busy
Mar 8 19:00:27 esx-1 vmkernel: 1:11:37:05.162 cpu7:1031)StorageMonitor: 196: vmhba32:4:0:0 status = 0/5 0x0 0x0 0x0
Mar 8 19:00:28 esx-1 vmkernel: 1:11:37:05.833 cpu2:1121)Cow: 866: IO to deltadisk handle 158448 failed: Busy
Mar 8 19:00:29 esx-1 vmkernel: 1:11:37:06.834 cpu0:1121)Cow: 866: IO to deltadisk handle 158448 failed: Busy
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:07.834 cpu1:1121)Cow: 866: IO to deltadisk handle 158448 failed: Busy
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.398 cpu7:1075)iSCSI: 65 second timeout expired for session 0xb6198e0, rx 12816340, ping 12822339, now 12822840
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.398 cpu7:1075)iSCSI: 65 second timeout expired for session 0xb62f338, rx 12816340, ping 12822339, now 12822840
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.398 cpu2:1079)iSCSI: session 0xb6198e0 to iqn.1986-03.com.sun:01:00144f7913b4.487B8D3C.ESX dropped
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.398 cpu2:1079)iSCSI: session 0xb6198e0 for (1 0 5 *) rx thread 1079handled timeout, notify tx
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.399 cpu2:1079)iSCSI: session 0xb6198e0 to iqn.1986-03.com.sun:01:00144f7913b4.487B8D3C.ESX waiting 2 seconds before next login attempt
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.399 cpu4:1081)iSCSI: session 0xb62f338 to iqn.1986-03.com.sun:01:00144f7913b4.487B8D3C.ESX dropped
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.399 cpu4:1081)iSCSI: session 0xb62f338 for (1 0 6 *) rx thread 1081handled timeout, notify tx
Mar 8 19:00:30 esx-1 vmkernel: 1:11:37:08.399 cpu4:1081)iSCSI: session 0xb62f338 to iqn.1986-03.com.sun:01:00144f7913b4.487B8D3C.ESX waiting 2 seconds before next login attempt
Mar 8 19:00:31 esx-1 vmkernel: 1:11:37:08.833 cpu0:1121)Cow: 866: IO to deltadisk handle 158448 failed: Busy
Mar 8 19:00:31 esx-1 vmkernel: 1:11:37:09.400 cpu3:1078)iSCSI: session 0xb6198e0 timed out:drop 12822840, now 12822941, failing all commands
Mar 8 19:00:31 esx-1 vmkernel: 1:11:37:09.400 cpu7:1080)iSCSI: session 0xb62f338 timed out:drop 12822840, now 12822941, failing all commands
Mar 8 19:00:32 esx-1 vmkernel: 1:11:37:09.834 cpu0:1121)Cow: 866: IO to deltadisk handle 158448 failed: Busy
Mar 8 19:00:32 esx-1 vmkernel: 1:11:37:10.399 cpu4:1081)iSCSI: bus 0 target 6 trying to establish session 0xb62f338 to portal 0, address 10.0.1.4 port 3260 group 1
Mar 8 19:00:32 esx-1 vmkernel: 1:11:37:10.399 cpu2:1079)iSCSI: bus 0 target 5 trying to establish session 0xb6198e0 to portal 0, address 10.10.10.166 port 3260 group 1