asked on

Why Does My VMWare Conversion Fail?

We have been converting several servers to VMWare, but more than a few times we have had trouble with the Converter failing. We are using the VMWare boot disk and cloning to an ESX server which has uses an iSCSI backend. It is bombing out at various percents. Usually 2-10%, though it has been higher. The problem does not go away until we reboot our ESX server. I have included an exert from the logs. However, this is only part of the vmware-converter-agent-0.log. Please let me know if anyone needs more of the logs or more of this log. Thanks!

[#2] [j1] [2010-07-17 06:37:02.015 'App' 1240 warning] [blockLevelVolumeCloningTaskImpl,764] Unable to get fileextents for c:\\hibernat.sys. Error: 2
[#2] [j1] [2010-07-17 06:37:02.015 'App' 1240 warning] [blockLevelVolumeCloningTaskImpl,764] Unable to get fileextents for c:\\hiberfil.sys. Error: 2
[#2] [j1] [2010-07-17 06:37:02.015 'App' 1240 warning] [blockLevelVolumeCloningTaskImpl,781] Unable to get bad blocks extents for c:\. Error: 5
[#2] [j1] [2010-07-17 06:37:36.625 'App' 1240 error] [blockLevelVolumeCloningTaskImpl,954] Error 5666 writing to the destination volume
[2010-07-17 06:37:36.625 'App' 1100 info] [stub,42] [NFC ERROR] NfcNetTcpRead: bRead: -1  err: 10054
[2010-07-17 06:37:36.625 'App' 1100 info] [stub,42] [NFC ERROR] NfcFssrvrRecv: failed with code = 8
[2010-07-17 06:37:36.625 'App' 1100 info] [stub,42] [NFC ERROR] NfcFssrvr_DiskIo: failed to receive io reply
[2010-07-17 06:37:36.625 'App' 1100 info] [stub,42] DISKLIB-LIB   : RWv failed ioId: #138 (5666) (34) .
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1240 error] [imageProcessingTaskImpl,556] BlockLevelVolumeCloning::task{6}: Image processing task has failed with PlatformError fault: (5666) 
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1240 verbose] [imageProcessingTaskImpl,154] BlockLevelVolumeCloning::task{6}: SetState to error
[2010-07-17 06:37:36.640 'App' 1232 verbose] [imageProcessingTaskWrapper,749] Got an update from CloneTask::task{5}
[2010-07-17 06:37:36.640 'App' 1232 verbose] [imageProcessingTaskWrapper,749] Got an update from BlockLevelVolumeCloning::task{6}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1252 verbose] [imageProcessingTaskWrapper,437] Waiting for updates from CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1252 verbose] [imageProcessingTaskWrapper,668] (Re)Start waiting for property updates from CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 verbose] [imageProcessingTaskWrapper,515] Cleaning up remote task BlockLevelVolumeCloning::task{6}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1240 verbose] [imageProcessingTaskWrapper,886] Remote task BlockLevelVolumeCloning::task{6} completed
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 verbose] [imageProcessingTaskWrapper,1201] Disposing task wrapper for task BlockLevelVolumeCloning::task{6}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [disposable,122] object explicitly disposed: BlockLevelVolumeCloning::task{6}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [imageProcessingTaskImpl,123] BlockLevelVolumeCloning::task{6} being destroyed
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 error] [imageProcessingTaskStep,423] CloneTask::task{5} step "Cloning into volume virtVol={computer={a0913673d0a995d9e083dff44570cc0627ece7e9},0}" failed
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 verbose] [imageProcessingTaskWrapper,1117] Reporting image processing task failure for task BlockLevelVolumeCloning::task{6}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 error] [imageProcessingTaskWrapper,1124] ImageProcessingTask FAILED. Fault name: sysimage.fault.PlatformError
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 info] [imageProcessingTaskStep,194] CloneTask::task{5} step "Cloning into volume virtVol={computer={a0913673d0a995d9e083dff44570cc0627ece7e9},0}" destroyed
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1228 info] [imageProcessingTaskStep,194] CloneTask::task{5} step "clone volumes" destroyed
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [disposable,122] object explicitly disposed: computer={a09136ece7e9}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [diskSet,114] Cleaning up computer's child objects
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [diskSet,130] Unregistring volume id=virtVol={computer={a09136ff44570cc0627ece7e9},0}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [diskSet,130] Unregistring volume id=virtVol={computer={a09136f44570cc0627ece7e9},1}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [diskSet,140] Unregistring disk id=disk={4acc979e295bfb63a89ce32d101}
[#2] [j1] [2010-07-17 06:37:36.640 'App' 1232 verbose] [diskSet,140] Unregistring disk id=disk={542327
b6fb8cc3a0b830789f}
[2010-07-17 06:37:36.640 'App' 1100 info] [stub,42] [NFC ERROR] NfcNetTcpWrite: bWritten: -1  err: 10054
[2010-07-17 06:37:36.640 'App' 1100 info] [stub,42] [NFC ERROR] NfcFssrvrSend: failed
[2010-07-17 06:37:36.640 'App' 1100 info] [stub,42] [NFC ERROR] NfcFssrvr_Close: failed to send close message
[2010-07-17 06:37:36.640 'App' 1100 info] [stub,42] [NFC ERROR] NfcNetTcpWrite: bWritten: -1  err: 10054
[2010-07-17 06:37:36.640 'App' 1100 info] [stub,42] [NFC ERROR] NfcNet_Send: requested 264, sent only 8 bytes
[2010-07-17 06:37:36.640 'App' 1100 info] [stub,42] [NFC ERROR] NfcSendMessage: send failed: 
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1228 error] [cloneTask,332] Cloning failed!
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1228 error] [imageProcessingTaskImpl,556] CloneTask::task{5}: Image processing task has failed with PlatformError fault: (5666) 
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1228 verbose] [imageProcessingTaskImpl,154] CloneTask::task{5}: SetState to error
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1228 verbose] [imageProcessingTaskWrapper,886] Remote task CloneTask::task{5} completed
[2010-07-17 06:37:55.562 'App' 1228 verbose] [imageProcessingTaskWrapper,749] Got an update from CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 verbose] [imageProcessingTaskWrapper,515] Cleaning up remote task CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 verbose] [imageProcessingTaskWrapper,1201] Disposing task wrapper for task CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1232 verbose] [disposable,122] object explicitly disposed: CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1232 verbose] [imageProcessingTaskImpl,123] CloneTask::task{5} being destroyed
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 error] [imageProcessingTaskStep,423] VmiImportTask::task{4} step "clone to VM" failed
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 verbose] [imageProcessingTaskWrapper,1117] Reporting image processing task failure for task CloneTask::task{5}
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 error] [imageProcessingTaskWrapper,1124] ImageProcessingTask FAILED. Fault name: sysimage.fault.PlatformError
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 info] [imageProcessingTaskStep,194] VmiImportTask::task{4} step "clone to VM" destroyed
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 error] [vmiImportTask,456] Cloning failed: sysimage.fault.PlatformError
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 info] [vmiImportTask,1054] Removing destination VM
[#2] [j1] [2010-07-17 06:37:55.562 'App' 1252 info] [vmiImportTask,1062] Successfully connected to UfaManagedVMCreator
[2010-07-17 06:37:55.562 'App' 1100 info] [stub,42] [NFC ERROR] NfcNetTcpRead: bRead: -1  err: 10054
[2010-07-17 06:37:55.562 'App' 1100 info] [stub,42] [NFC ERROR] NfcFssrvrRecv: failed with code = 8
[2010-07-17 06:37:55.562 'App' 1100 info] [stub,42] [NFC ERROR] NfcFssrvr_Close: failed to receive reply to close message
[2010-07-17 06:37:55.562 'App' 1100 info] [stub,42] [NFC ERROR] NfcNetTcpWrite: bWritten: -1  err: 10054
[2010-07-17 06:37:55.562 'App' 1100 info] [stub,42] [NFC ERROR] NfcNet_Send: requested 264, sent only 8 bytes
[2010-07-17 06:37:55.562 'App' 1100 info] [stub,42] [NFC ERROR] NfcSendMessage: send failed: 
[#2] [j1] [2010-07-17 06:38:16.562 'App' 1232 error] [vimAPI] Fail to send Http request /sdk/vimService?wsdl with error id 10060
[#2] [j1] [2010-07-17 06:38:16.562 'App' 1232 error] [vimAPI] Failed to get vim namespace from DELETED port DELETED 
[#2] [j1] [2010-07-17 06:38:16.562 'ManagedVMCreatorImpl::DestroyVM' 1232 info] Connecting to host DELETED on port DELETED using protocol https
[#2] [j1] 
[#2] [j1] [2010-07-17 06:38:16.562 'Libs' 1232 warning] SSLVerifyCertAgainstSystemStore: CertGetCertificateChain failed. LastError = -2146885628
[#2] [j1] [2010-07-17 06:38:16.562 'Libs' 1232 warning] SSLVerifyCertAgainstSystemStore: The remote host certificate has these problems:
[#2] [j1] 
[#2] [j1] * CertGetCertificateChain failed
[#2] [j1] [2010-07-17 06:38:16.562 'Libs' 1232 warning] SSLVerifyCertAgainstSystemStore: Certificate verification is disabled, so connection will proceed despite the error
[#2] [j1] [2010-07-17 06:38:16.609 'ManagedVMCreatorImpl::DestroyVM' 1232 info] Authenticating user root
[#2] [j1] [2010-07-17 06:38:16.656 'ManagedVMCreatorImpl::DestroyVM' 1232 info] Logged in!
[#2] [j1] [2010-07-17 06:38:17.125 'App' 1232 info] [managedVMCreator,2552] Waiting for VM destruction to complete...
[#2] [j1] [2010-07-17 06:38:17.125 'App' 1232 verbose] [rpcConnectionWrapper,918] Waiting for a task to complete...
[#2] [j1] [2010-07-17 06:38:18.046 'ManagedVMCreatorImpl::DestroyVM' 1232 info] *** Begin Logout() ***
[#2] [j1] [2010-07-17 06:38:18.093 'ManagedVMCreatorImpl::DestroyVM' 1232 info] *** Finish Logout() ***
[#2] [j1] [2010-07-17 06:38:18.093 'App' 1252 info] [imageProcessingTaskStep,194] VmiImportTask::task{4} step "create and clone to VM" destroyed
[#2] [j1] [2010-07-17 06:38:18.093 'App' 1252 info] [imageProcessingTaskStep,194] VmiImportTask::task{4} step "Clone VM" destroyed
[#2] [j1] [2010-07-17 06:38:18.093 'App' 1252 error] [imageProcessingTaskImpl,556] VmiImportTask::task{4}: Image processing task has failed with PlatformError fault: (5666) 
[#2] [j1] [2010-07-17 06:38:18.093 'App' 1252 verbose] [imageProcessingTaskImpl,154] VmiImportTask::task{4}: SetState to error
[#2] [j1] [2010-07-17 06:38:18.125 'App' 1232 verbose] [disposable,122] object explicitly disposed: VmiImportTask::task{4}
[#2] [j1] [2010-07-17 06:38:18.125 'managedImportDestination' 1232 info] *** Begin Logout() ***
[#2] [j1] [2010-07-17 06:38:18.171 'managedImportDestination' 1232 info] *** Finish Logout() ***
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1252 verbose] [disposable,122] object explicitly disposed: computer={2202622998d91b89190c31d}
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1252 verbose] [diskSet,114] Cleaning up computer's child objects
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1252 verbose] [diskSet,130] Unregistring volume id=attVol={computer={22026229c8980df6baba3cfd5d},1}
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1252 verbose] [diskSet,130] Unregistring volume id=attVol={computer={22026229980df6baba3cfd5d},2}
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1252 verbose] [diskSet,140] Unregistring disk id=disk={9ba2498efa945c367c0fea}
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1252 verbose] [diskSet,140] Unregistring disk id=disk={5c822bdfe43817c6666}
[#2] [j1] [2010-07-17 06:38:18.171 'App' 1232 verbose] [imageProcessingTaskImpl,123] VmiImportTask::task{4} being destroyed
[#2] [j1] [2010-07-17 06:38:18.218 'App' 1116 info] Stopped impersonating in session 9EF2B3D9-36FCBBE93
[2010-07-17 06:38:18.250 'App' 1116 verbose] CloseSession called for session id=9EF2B3DA040-71936FCBBE93
[2010-07-17 06:38:18.250 'VmdbAdapter' 1116 verbose] Removed vmdb connection /db/connection/#2/
[#3] [2010-07-17 06:39:39.890 'App' 1232 info] Impersonating user SYSTEM in session E6497-4051BF3C55E7
[#3] [2010-07-17 06:39:39.921 'App' 1232 info] Stopped impersonating in session E6497B7-4051BF3C55E7
[2010-07-17 06:39:39.953 'App' 1252 verbose] CloseSession called for session id=E6495128-787951BF3C55E7
[2010-07-17 06:39:39.953 'VmdbAdapter' 1252 verbose] Removed vmdb connection /db/connection/#3/

Open in new window

ASKER CERTIFIED SOLUTION

JustenC

membership

This solution is only available to members.

To access this solution, you must be a member of Experts Exchange.

Start Free Trial

CCB-Tech

ASKER

I'll do that for the Hibernation file. But the freaky part is that the problem goes away just as soon as the ESX server is rebooted. You can leave the computer you are going to virtualize up on VMWares boot disk, have the conversion fail, then reboot ESX and it will work. So I have no clue what is the problem. I'll check those the next time I come across the problem. The way the problem behaves though makes me feel that the problem is more tied to the ESX server itself.

JustenC

I'd still run chkdsk /f. That's solved a lot of weird block level issues for me.
Do you see this same behavior on a lot of other migration tasks or just this one client?

CCB-Tech

ASKER

We have had it happen on multiple servers at differnet times, on different days. I will keep the CHKDSK in mind, especially if you have it help you before. Any idea why I keep getting the SSL problems in the log?

JustenC

That's because you don't have your companies trusted PKI certificates installed on the ESX server. So it uses a default self signed cert that will work. If you have a PKI environment you can look up how to get your CA's certs into ESX. If you buy all your SSL certs from a 3rd party then the vendor has instructions.

Justen

JustenC

CCB-Tech one other thing. Are your NICs set for full duplex on ESX? Or at least not set to 'Auto negotiate'?

Justen

bgoering

Are all of the pieces of your ESX and backend storage on the VMware HCL?

CCB-Tech

ASKER

@JustenC

Yeah, all the Nics are set to full duplex both on the SAN side and the LAN side.

@bgoering

Yes, all of them are on the HCL.

I have uploaded a new log file from a conversion that just failed. Before I had only included a partial log, but this time I included a full log. To my knowledge I removed every bit of information that should not be posted on the web. But if I missed something please let me know!
vmware-converter-agent-0.log

JustenC

This one was:
1104 error] [reconfigurationTransaction,83] Can't create undo folder

CCB
What version of the converter are you using and is there a diagnostic partition before the OS?

Justen

CCB-Tech

ASKER

I am converting a Windows 7 machine hosted on Virtual Iron (I removed VI Tools first). Over to VMware ESXi 4.1. According to the information in the filename for the converter CD I am using version 4.1.1-206170. Also, because it is Windows 7 Ultimate it has support for BitLocker. So yes, there is a 100MB partition before the OS.

JustenC

well then its having problem identifying the OS partition. The OS does not reside on partition 1 as the log states. Deselecting the boot partition may produce a non bootable copy but I'd try it anyway. It's not encrypted is it?:

[#2] [j1] [2010-07-23 15:37:02.156 'App' 1328 info] [extendedOsInfo,501] SwagNTInfoFromString has Windows 7
[#2] [j1] [2010-07-23 15:37:02.156 'App' 1328 info] [extendedOsInfo,646] SwagNTInfoFromString found nothing
[#2] [j1] [2010-07-23 15:37:02.156 'App' 1328 info] [extendedOsInfo,228] Returning OS as display other
[#2] [j1] [2010-07-23 15:37:02.156 'App' 1328 verbose] [diskSet,548] Guessing which volume is system volume...
[#2] [j1] [2010-07-23 15:37:02.156 'App' 1328 info] [diskSet,291] OS resides on partition 1 , disk path [SATA-1] REMOVED/REMOVED.vmdk

bgoering

Hmmm, Bitlocker requires either a Trusted Platform Module (TPM), or a USB key to store the encryption information. You might be able to get a USB to work, but I doubt it.... The VMs BIOS must support access to the USB key at boot time and I don't believe ESX does that at least through 4.0. I have yet to take a look at 4.1.

Of course if the drive isn't encrypted, just ignore all the malarky above :)

http://windows.microsoft.com/en-US/windows-vista/Hardware-requirements-for-BitLocker-Drive-Encryption

CCB-Tech

ASKER

No the drive is not encrypted. It just installed the secondary partition just in case. Hmmmmm, well the machine is only kinda set up. So I think I might just flush it and do a fresh install on VMware. However, there are other machines that are either XP or Server 2003 that have failed as well. I will be doing several of those over the weekend. So I will post the logs when I get them if the problem occurs again.

CCB-Tech

ASKER

Well crap. It failed twice over the weekend doing a cold conversion. So I decided to try a hot conversion yesterday. It got to 94% and failed with "A general system error occurred: The specified network name is no longer available." I'm running out of ideas of what to try! The network is solid, no other servers had trouble over the weekend. Nor last night. And I've tried converting it to both an ESX host and an ESXi host.

SOLUTION

bgoering

membership

This solution is only available to members.

To access this solution, you must be a member of Experts Exchange.

Start Free Trial

CCB-Tech

ASKER

No clue what was causing this or ultimately fixed it. All I know is we finished our machine conversions. Thanks for all the help fellas!