VmWare vCenter Converter hangs

[beppesk]

Hi,

i have installed VMware vCenter Converter 5 Standalone Client on two pc's: one runs with Windows XP-Sp3 and the other is with Windows7sp1-x86.

I usually convert the VM from a .tib image created with Acronis True Image.

On my XP pc, when i first load the .tib image and click on "View source details", after 30 sec. i see the details of the machine to convert.

On my Windows7 PC, when i click on "View souce details", with the same .tib image (a small test image about 300Mb.) the vCenter converter hangs.

The PC's have the same antivirus software (kaspersky) and when i start the vCenter Converter i've disabled it......

Another my collegue has tried to install the vCenter Converter on his Windows7 pc and the problem is the same....

Please help me. Did you have any suggestion ?

Thanks in advance.

Regards.

[POCEH]

What you mean with "converter hangs"? UI, services, etc? Where you install the converter server? What about firewalls...

Please upload log bundle for investigation.

[beppesk]

Let me explain....

The converter is installed only in local pc, no server.

The firewall service is off and disabled.

When i click on "View souce details", after select the .tib image, starts the process of recognition and after 30 minutes the recognition is still in progress. If i try to abort the recognition process the converter hangs and the pc with windows7 freeze. If i start the same process on my Windows XP pc after about 30 sec. the converter is recognize the .tib image correctly.

The versions of vCenter converter are the same.

Where can i find the logfile ?

Thanks for your help.

Best regards. Ciao. Grazie.

[POCEH]

Logs could be found in menu "Export Logs". Are you ever wait "View source details" until finished? Sometimes depending on different .tib images the process must be very long, please be patient.

[beppesk]

Ok, i'll take a look at the logs when i'll return to office.

This morning i retry to convert the .tib image and after about 20mins. the error message is "unable to obtain hardware information". The same .tib image was converted with the other pc XP-Professional with no error messages.

If i open the .tib image on the "Windows 7" pc with Acronis True Image is seems all ok.

This afternoon i'll post the log.

Thank you very much for your help and suggestions.

Bye. Ciao

[beppesk]

Here is one of my logs.....

Section for VMware vCenter Converter Standalone Client, pid=2340, version=5.0.0, build=build-470252, option=Release
2012-01-10T08:33:51.511+01:00 [00452 info 'Default'] Initialized channel manager
2012-01-10T08:33:51.511+01:00 [00452 info 'Default'] Current working directory: C:\Program Files\VMware\VMware vCenter Converter Standalone
2012-01-10T08:33:51.511+01:00 [00452 verbose 'ThreadPool'] TaskMax=10, IoMin=1, IoMax=21
2012-01-10T08:33:51.526+01:00 [00452 info 'Default'] Using locale for help and translations 'it_IT'.
2012-01-10T08:33:51.526+01:00 [00452 error 'Default'] Unable to load 'it_IT' translation.
2012-01-10T08:33:51.557+01:00 [00452 info 'Default'] Use GUI font 8 with correction 1.
2012-01-10T08:33:52.587+01:00 [00452 info 'Default'] Vmacore::InitSSL: doVersionCheck = true, handshakeTimeoutUs = 20000000
2012-01-10T08:33:52.587+01:00 [00452 info 'ConverterImpl'] Converter session created.
2012-01-10T08:33:52.587+01:00 [00452 verbose 'ConverterSession'] Converter::Client::Gui::Wizard::ConverterSessionImpl::Login - Connecting to local server.
2012-01-10T08:33:52.587+01:00 [03048 info 'BaseServerConnection'] Connecting to server on pipeName \\.\pipe\vmware-converter-server-soap.
--> SSL:false
--> Path:/converter/sdk
--> VMODL version:converter.version.version3
-->
2012-01-10T08:33:52.587+01:00 [03048 info 'BaseServerConnection'] NOT using SSL to connect to VMOMI server \\.\pipe\vmware-converter-server-soap
2012-01-10T08:33:52.587+01:00 [03048 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 20; idleTimeout = 900000000; maxOpenConnections = 20; maxConnectionAge = 0
2012-01-10T08:33:52.587+01:00 [03048 info 'ConverterServerConnPipe'] Getting ServiceInstance contents
2012-01-10T08:33:52.587+01:00 [03048 verbose 'ConverterServerConnPipe'] Yes, we connected to Converter Server.
2012-01-10T08:33:52.587+01:00 [03048 info 'ConverterSession'] Logging in to Converter Server (Using Impersonate).
2012-01-10T08:33:52.587+01:00 [03048 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 1; idleTimeout = 900000000; maxOpenConnections = 1; maxConnectionAge = 0
2012-01-10T08:33:52.743+01:00 [03048 info 'ConverterSession'] Converter Server session established. (Session ID = "52da7804-6135-c135-d97e-9716b9b7cef4")
2012-01-10T08:33:52.759+01:00 [03048 info 'ConverterSession'] Converter data provider created.
2012-01-10T08:33:53.134+01:00 [00452 info 'ConverterSession'] Converter data provider created.
2012-01-10T08:33:53.134+01:00 [00452 info 'ConverterSession'] Converter data provider created.
2012-01-10T08:33:53.165+01:00 [00452 info 'ConverterSession'] Converter data provider created.
2012-01-10T08:33:53.196+01:00 [00452 info 'ConverterSession'] Converter data provider created.
2012-01-10T08:33:53.212+01:00 [01808 verbose 'ConverterDataProviderImpl'] Converter::Client::Gui::Wizard::ConverterDataProviderImpl::PropertyCollectorThread[1] - (vmodl.query.PropertyCollector.UpdateSet) {
-->    dynamicType = <unset>,
-->    version = "1",
-->    filterSet = (vmodl.query.PropertyCollector.FilterUpdate) [
-->       (vmodl.query.PropertyCollector.FilterUpdate) {
-->          dynamicType = <unset>,
-->          filter = 'vmodl.query.PropertyCollector.Filter:session[52da7804-6135-c135-d97e-9716b9b7cef4]5212f49a-c860-4a99-17e7-2a5b8039eb7f',
-->          objectSet = (vmodl.query.PropertyCollector.ObjectUpdate) [
-->             (vmodl.query.PropertyCollector.ObjectUpdate) {
-->                dynamicType = <unset>,
-->                kind = "enter",
-->                obj = 'converter.task.TaskManager:TaskManager',
-->                changeSet = (vmodl.query.PropertyCollector.Change) [
-->                   (vmodl.query.PropertyCollector.Change) {
-->                      dynamicType = <unset>,
-->                      name = "recentTask",
-->                      op = "assign",
-->                      val = (ManagedObjectReference) [],
-->                   }
-->                ],
-->             }
-->          ],
-->       },
-->       (vmodl.query.PropertyCollector.FilterUpdate) {
-->          dynamicType = <unset>,
-->          filter = 'vmodl.query.PropertyCollector.Filter:session[52da7804-6135-c135-d97e-9716b9b7cef4]522ed50f-c907-a848-b2c2-e472cec9b2a4',
-->          objectSet = (vmodl.query.PropertyCollector.ObjectUpdate) [
-->             (vmodl.query.PropertyCollector.ObjectUpdate) {
-->                dynamicType = <unset>,
-->                kind = "enter",
-->                obj = 'converter.server.conversion.ConversionJobHistoryCollector:session[52da7804-6135-c135-d97e-9716b9b7cef4]52440f2e-601e-6929-556b-e70839de80c0',
-->                changeSet = (vmodl.query.PropertyCollector.Change) [
-->                   (vmodl.query.PropertyCollector.Change) {
-->                      dynamicType = <unset>,
-->                      name = "latestPage",
-->                      op = "assign",
-->                      val = (converter.server.conversion.ConversionJobInfo) [],
-->                   }
-->                ],
-->             }
-->          ],
-->       }
-->    ],
-->    truncated = <unset>,
--> }
2012-01-10T08:33:55.178+01:00 [00452 info 'ConverterImpl'] Converter session duplicated.
2012-01-10T08:33:55.178+01:00 [03048 info 'BaseServerConnection'] Connecting to server on pipeName \\.\pipe\vmware-converter-server-soap.
--> SSL:false
--> Path:/converter/sdk
--> VMODL version:converter.version.version3
-->
2012-01-10T08:33:55.178+01:00 [03048 info 'BaseServerConnection'] NOT using SSL to connect to VMOMI server \\.\pipe\vmware-converter-server-soap
2012-01-10T08:33:55.178+01:00 [03048 info 'ConverterServerConnPipe'] Getting ServiceInstance contents
2012-01-10T08:33:55.178+01:00 [03048 verbose 'ConverterServerConnPipe'] Yes, we connected to Converter Server.
2012-01-10T08:33:55.178+01:00 [03048 info 'ConverterSession'] Logging in to Converter Server (Using Impersonate).
2012-01-10T08:33:55.178+01:00 [03048 verbose 'HttpConnectionPool'] HttpConnectionPoolImpl created. maxPoolConnections = 1; idleTimeout = 900000000; maxOpenConnections = 1; maxConnectionAge = 0
2012-01-10T08:33:56.457+01:00 [03048 info 'ConverterSession'] Converter Server session established. (Session ID = "5277db37-8cec-0466-a232-aec4c1e99dd2")
2012-01-10T08:33:56.785+01:00 [00452 warning 'Locale'] Duplicate key 'hi_IN' in file 'C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\iso2win.vlcl', only first one is used
2012-01-10T08:33:56.785+01:00 [00452 warning 'Locale'] Duplicate key 'az_AZ' in file 'C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\iso2win.vlcl', only first one is used
2012-01-10T08:33:56.785+01:00 [00452 warning 'Locale'] Duplicate key 'sr_SP' in file 'C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\iso2win.vlcl', only first one is used
2012-01-10T08:33:56.785+01:00 [00452 warning 'Locale'] Duplicate key 'az_AZ' in file 'C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\isodata.vlcl', only first one is used
2012-01-10T08:33:56.785+01:00 [00452 warning 'Locale'] Duplicate key 'sr_SP' in file 'C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\isodata.vlcl', only first one is used
2012-01-10T08:33:56.785+01:00 [00452 warning 'Locale'] Duplicate key 'uz_UZ' in file 'C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\isodata.vlcl', only first one is used
2012-01-10T08:33:56.816+01:00 [00452 info 'Locale'] Added locale path C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\ to locale map
2012-01-10T08:33:56.832+01:00 [00452 info 'Locale'] Locale subsystem initialized from C:\Program Files\VMware\VMware vCenter Converter Standalone\locale\ with default locale en.
2012-01-10T08:33:56.832+01:00 [00452 info 'ConverterImpl'] Converter wizard created.
2012-01-10T08:33:56.879+01:00 [00452 info 'ConverterLogic'] Initializing Converter::Logic::ServiceInstance ...
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection SourceSelect
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection ManagedMachineDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection HyperVDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection DestinationSelect
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection ManagedDestinationAttributes
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection ManagedDestinationDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection DisksAndVolumesPlugin
2012-01-10T08:33:56.988+01:00 [03048 verbose 'DisksAndVolumesDataConnectionLogger'] Converter::Logic::DisksAndVolumesDataConnectionImpl::LoadFromSpec, _defaultDatastore
-->
2012-01-10T08:33:56.988+01:00 [03048 verbose 'DisksAndVolumesDataConnectionLogger'] Converter::Logic::DisksAndVolumesDataConnectionImpl::LoadFromSpec, _sourceStorageInfo
-->
2012-01-10T08:33:56.988+01:00 [03048 verbose 'DisksAndVolumesDataConnectionLogger'] Converter::Logic::DisksAndVolumesDataConnectionImpl::LoadFromSpec, _sourceOsInfo
-->
2012-01-10T08:33:56.988+01:00 [03048 verbose 'DisksAndVolumesDataConnectionLogger'] Converter::Logic::DisksAndVolumesDataConnectionImpl::LoadFromSpec, _currentCloningModes
-->
2012-01-10T08:33:56.988+01:00 [03048 verbose 'DisksAndVolumesDataConnectionLogger'] Converter::Logic::DisksAndVolumesDataConnectionImpl::LoadFromSpec, _currentDiskCreateTypes
-->
2012-01-10T08:33:56.988+01:00 [03048 verbose 'DisksAndVolumesDataConnectionLogger'] Converter::Logic::DisksAndVolumesDataConnectionImpl::LoadFromSpec, _defaultDiskCreateType
-->
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection DevicesPlugin
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection NetworksPlugin
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection ServicesDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection GuestOsCust
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection HelperVMNetworkDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection ThrottlingPluginDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection ComputerInformationDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection WindowsLicenseDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection TimeZoneDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection NIC_CustomizedSettings
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection WorkgroupOrDomainDataConnection
2012-01-10T08:33:56.988+01:00 [03048 verbose 'wizardController'] Created data connection TaskSummaryDataConnection
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] FillPageContents(): currentPage is 0
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] subpages = 1
2012-01-10T08:33:57.019+01:00 [03048 verbose 'wizardController'] Found data connection SourceSelect
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> DefaultPhysicalSource ( 1 )
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> DefaultRemoteOS ( windowsOs )
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> DefaultSource ( 0 )
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> ShowServer20 ( False )
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> ShowStandalone ( True )
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> ThirdPartyHostedFilter ( <obj xmlns="urn:ConverterLogic" versionId="1.0" xsi:type="ArrayOfConverterLogicKeyValuePair"><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>microsoftVirtualPCVM</key><val xsi:type="xsd:string">Microsoft Virtual PC (*.vmc)</val></ConverterLogicKeyValuePair><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>parallelsVM</key><val xsi:type="xsd:string">Parallels Virtualization Products Image (*.pvs)</val></ConverterLogicKeyValuePair><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>livestateBackup</key><val xsi:type="xsd:string">Symantec LiveState Recovery Image (*.sv2i)</val></ConverterLogicKeyValuePair><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>shadowProtectBackup</key><val xsi:type="xsd:string">StorageCraft ShadowStor Image (*.spf)</val></ConverterLogicKeyValuePair><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>acronisBackup</key><val xsi:type="xsd:string">Acronis True Image Backup (*.tib)</val></ConverterLogicKeyValuePair><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>vmwareVCBBackup</key><val xsi:type="xsd:string">VMware Consolidated Backup (*.vmx)</val></ConverterLogicKeyValuePair></obj> )
2012-01-10T08:33:57.019+01:00 [03048 info 'wizardController'] parameter>>> VMwareHostedFilter ( <obj xmlns="urn:ConverterLogic" versionId="1.0" xsi:type="ArrayOfConverterLogicKeyValuePair"><ConverterLogicKeyValuePair xsi:type="ConverterLogicKeyValuePair"><key>vmwareVM</key><val xsi:type="xsd:string">VMware virtual machine (*.vmx)</val></ConverterLogicKeyValuePair></obj> )
2012-01-10T08:34:12.172+01:00 [03048 info 'wizardController'] FillPage()
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type microsoftVirtualPCVM not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type parallelsVM not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type vmwareVCBBackup not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type livestateBackup not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type shadowProtectBackup not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type acronisBackup not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildFilter 3rd party type vmwareVM not found
2012-01-10T08:34:12.484+01:00 [00452 error 'Default'] SourceSelectPluginModel::BuildThirdpartyHostedExtVector 3rd party type vmwareVM not found
2012-01-10T08:34:23.106+01:00 [00452 info 'ConverterSession'] Converter::Client::Gui::Common::DiagnosticDataProvider::SetLastKnownSource - Setting last known source:
--> (converter.ComputerSpec) {
-->    dynamicType = <unset>,
-->    location = (converter.ComputerSpec.ThirdPartyHostedLocation) {
-->       dynamicType = <unset>,
-->       configFilePath = "C:\infogio3.tib",
-->       password = <unset>,
-->       networkUsername = <unset>,
-->       networkPassword = <unset>,
-->       type = "acronisBackup",
-->    },
--> }
2012-01-10T08:34:23.106+01:00 [00452 info 'ConverterSession'] Converter::Client::Gui::Common::DiagnosticDataProvider::SetLastKnownSource - Setting last known source:
--> (converter.ComputerSpec) {
-->    dynamicType = <unset>,
-->    location = (converter.ComputerSpec.ThirdPartyHostedLocation) {
-->       dynamicType = <unset>,
-->       configFilePath = "C:\infogio3.tib",
-->       password = <unset>,
-->       networkUsername = <unset>,
-->       networkPassword = <unset>,
-->       type = "acronisBackup",
-->    },
--> }
2012-01-10T08:39:43.261+01:00 [01564 verbose 'ManagedMachineDataConnectionLogger'] VimConnectionStore stopping keepalive
2012-01-10T08:39:43.261+01:00 [01564 info 'ManagedMachineDataConnectionLogger'] Scheduled timer canceled, StopKeepAlive succeeds
2012-01-10T08:39:43.276+01:00 [00452 info 'ConverterSession'] Converter::Client::Gui::Common::DiagnosticDataProvider::ClearLastKnownSource - Clearing last known source.
2012-01-10T08:39:43.322+01:00 [00452 info 'ConverterSession'] Logging out of the Converter Server. (Session ID = "5277db37-8cec-0466-a232-aec4c1e99dd2")
2012-01-10T08:39:45.507+01:00 [00452 error 'ConverterDataProviderImpl'] Exception in Converter::Client::Gui::Wizard::ConverterDataProviderImpl::DestroyFilterObject - Failed to destroy property collector filter. The object has already been deleted or has not been completely created
2012-01-10T08:39:45.522+01:00 [01808 info 'ConverterDataProviderImpl'] Converter::Client::Gui::Wizard::ConverterDataProviderImpl::PropertyCollectorThread: RequestCanceledException
2012-01-10T08:39:45.522+01:00 [01808 verbose 'ConverterDataProviderImpl'] Converter::Client::Gui::Wizard::ConverterDataProviderImpl::PropertyCollectorThread: Stopped.
2012-01-10T08:39:46.037+01:00 [00452 error 'ConverterDataProviderImpl'] Exception in Converter::Client::Gui::Wizard::ConverterDataProviderImpl::DestroyFilterObject - Failed to destroy property collector filter. The object has already been deleted or has not been completely created
2012-01-10T08:39:46.037+01:00 [00452 info 'ConverterSession'] Logging out of the Converter Server. (Session ID = "52da7804-6135-c135-d97e-9716b9b7cef4")

[POCEH]

This is part of UI log, others logs are more interesting.

Could you upload whole ZIP? or send to me as PM.

[beppesk]

Here it is !! Thank you and best regards.

Ciao

[POCEH]

For successfull convertion your user must be local administrator. If not this could be a problem. Also ensure that both services are running: converter-server and converter-worker.

[beppesk]

I checked your suggestions.... 😞

and...

....the user on Windows 7 belongs to "Administrators" group and the two services converter-server and converter-worker are up with automatic start.

Now i try to uninstall vCenter converter 5.xx and i'll try to install the old 4.xx version.

[patanassov]

Could you post also the worker's log, it might be more informative. Since you can't start a task, you may need to get the file(s) manually. They are located in %ALLUSERSPROFILE%\VMware\VMware vCenter Converter Standalone\logs, look for vmware-converter-worker-xxx.log.

Regards,

Plamen

[beppesk]

dear patanassov, in attachment you can find the worker logfile.

In the meantime i also tried to use the old 4.xx version but the result is always the same.

Thanks.

[patanassov]

Thanks, but this log doens't contain the timout problem, it has been taken after reinstalling but probably before you have reproduced the problem with 4.3. Could you post the log again, after reproducing the timeout?

Regards,

Plamen

[beppesk]

Dear Plamen,

you can find the new log generated with Converter 5.0.

Thank you. Ciao

[patanassov]

I couldn't find anything in the log pointing to why this happens unfortunately. A possible workaround would be to disable UAC on your Windows 7 machine and try again.

HTH

Plamen

[ivivanov]

Hm, this log file seems quite short and it ends quite surprisingly... is there a chance that converter worker service is crashing during the operation? Can you look in Task Manager or SCM while it tries to open the TIB file whether the service is restarted (or PID changed)?

[beppesk]

.....hmmm, UAC is disabled.

I'll try the suggestion of Jucka next Monday.

Thank you for now. Ciao