2017-07-21 07:19:27,540 [INFO][14840][ConfigMerger.LoadConfigFile]: config file C:\Users\da_ajsimonton\AppData\Roaming\Sophos for Virtual Environments\ssvm_installer.conf does not exist 2017-07-21 07:19:28,604 [INFO][14840][SSVMInstallerApp.Run]: system: 'Windows' 2017-07-21 07:19:28,604 [INFO][14840][SSVMInstallerApp.Run]: version: '6.2.9200' 2017-07-21 07:19:28,681 [INFO][12136][ControllerValidator.op_static_data]: appliance_dir.location='C:\Users\da_ajsimonton\Sophos\SVE_VMware\input\appliance' is valid 2017-07-21 07:19:34,572 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:19:34,651 [INFO][8876][ControllerValidator.op_static_data]: appliance_dir.location='C:\Users\da_ajsimonton\Sophos\SVE_VMware\input\appliance' is valid 2017-07-21 07:19:35,665 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:19:35,806 [INFO][12116][ControllerValidator.op_static_data]: appliance_dir.location='C:\Users\da_ajsimonton\Sophos\SVE_VMware\input\appliance' is valid 2017-07-21 07:20:12,947 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:20:14,509 [ERROR][12100][ControllerValidator.exception]: NotReadyException File "C:\Build\modules\controller\base.py", line 125, in __call__ File "C:\Build\modules\controller\validate.py", line 670, in op_vcenter File "C:\Build\modules\controller\base.py", line 53, in wrapped_func NotReadyException: Certificate error 2017-07-21 07:20:22,854 [INFO][6268][ControllerValidator.op_vcenter]: vcenter.hostname='prodvcenter.sc.vmware.local', vcenter.admin_user and vcenter.admin_pass are valid 2017-07-21 07:20:28,713 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:20:30,415 [INFO][7088][ControllerValidator.op_hosts]: hosts.hosts=[u'esx15.sc.vmware.local'] is valid 2017-07-21 07:20:32,526 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:21:27,854 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:21:28,417 [INFO][13416][SMB.SMBConnection.__init__]: Authetication with remote machine "SOPHOSMGR" for user "SophosUpdateMgr" will be using NTLM v2 authentication (with extended security) 2017-07-21 07:21:28,417 [INFO][13416][SMB.SMBConnection.onNMBSessionMessage]: Now switching over to SMB2 protocol communication 2017-07-21 07:21:28,417 [INFO][13416][SMB.SMBConnection._updateState_SMB2]: SMB2 dialect negotiation successful 2017-07-21 07:21:28,431 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: Performing NTLMv2 authentication (on SMB2) with server challenge "ef765afde0400f50" 2017-07-21 07:21:28,431 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: Performing NTLMv2 authentication (on SMB2) with server challenge "ef765afde0400f50" 2017-07-21 07:21:28,431 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: Server supports SMB signing 2017-07-21 07:21:28,431 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: SMB signing deactivated. SMB messages will NOT be signed. 2017-07-21 07:21:28,463 [INFO][13416][SMB.SMBConnection._updateState_SMB2]: Authentication (on SMB2) successful! 2017-07-21 07:21:28,494 [INFO][13416][SMB.SMBConnection.__init__]: Authetication with remote machine "SOPHOSMGR" for user "SophosUpdateMgr" will be using NTLM v2 authentication (with extended security) 2017-07-21 07:21:28,494 [INFO][13416][SMB.SMBConnection.onNMBSessionMessage]: Now switching over to SMB2 protocol communication 2017-07-21 07:21:28,494 [INFO][13416][SMB.SMBConnection._updateState_SMB2]: SMB2 dialect negotiation successful 2017-07-21 07:21:28,494 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: Performing NTLMv2 authentication (on SMB2) with server challenge "2de70e80368aeff8" 2017-07-21 07:21:28,494 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: Performing NTLMv2 authentication (on SMB2) with server challenge "2de70e80368aeff8" 2017-07-21 07:21:28,509 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: Server supports SMB signing 2017-07-21 07:21:28,509 [INFO][13416][SMB.SMBConnection._handleSessionChallenge_SMB2]: SMB signing deactivated. SMB messages will NOT be signed. 2017-07-21 07:21:28,509 [INFO][13416][SMB.SMBConnection._updateState_SMB2]: Authentication (on SMB2) successful! 2017-07-21 07:21:28,744 [INFO][13416][ControllerValidator._validate_cidlocation]: cid.location='\\sophosmgr\SophosUpdate\CIDs\S000\SVE', cid.username and cid.password are valid 2017-07-21 07:22:00,134 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:22:00,447 [INFO][5036][ControllerValidator.op_support]: support.password is valid 2017-07-21 07:22:07,979 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:22:08,479 [INFO][4556][ControllerValidator.op_svm_timezone]: svm_settings.timezone 'America/Chicago' is valid 2017-07-21 07:22:08,776 [INFO][4556][ControllerValidator.__svm_settings_datastore_minfree]: Minimum free space for deployment is 20.2 GB 2017-07-21 07:22:11,167 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:22:13,088 [INFO][14192][ControllerValidator.op_svm_datastore]: svm_settings.datastore 'vmlinux_n2' svm_settings.datastore_type 'custom' is valid 2017-07-21 07:22:18,181 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:22:38,354 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:22:40,479 [INFO][14564][ControllerValidator.op_svm_vm_network]: svm_settings.vm_network='dpgVlan15', svm_settings.address='139.67.15.146', svm_settings.netmask='255.255.255.0', svm_settings.domain='eiuad.eiu.edu' are valid 2017-07-21 07:22:40,479 [INFO][14564][ControllerValidator.op_svm_vm_network]: IP Address does not overlap any other entered IP address subnet mask. 2017-07-21 07:22:58,026 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:22:58,338 [INFO][5796][ControllerValidator.op_svm_ip_allocation]: svm_settings address configuration is valid 2017-07-21 07:22:58,354 [INFO][5796][ControllerValidator.op_svm_ip_allocation]: svm_settings.gateway='139.67.15.1', svm_settings.dns_1='139.67.14.190' and svm_settings.dns_2='139.67.14.191' are valid 2017-07-21 07:23:10,510 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext() 2017-07-21 07:23:11,119 [INFO][15080][SvmInstallIterator.onEsxiHostUpdater]: ESXi host name is esx15.sc.vmware.local 2017-07-21 07:23:11,119 [INFO][15080][SvmInstallIterator.onEsxiHostUpdater]: Security VM name is SecVMProd01 2017-07-21 07:23:11,119 [INFO][15080][SvmInstallIterator.onEsxiHostUpdater]: Datastore is eiulivevmware1_prod_linux 2017-07-21 07:23:11,119 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'running' 2017-07-21 07:23:11,119 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Installing SecVMProd01' 2017-07-21 07:23:11,167 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Preparing to deploy SVM' 2017-07-21 07:23:11,338 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Validating OVF on target host.' 2017-07-21 07:23:11,417 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Examining target host configuration.' 2017-07-21 07:23:20,213 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Requesting upload to target host.' 2017-07-21 07:23:20,463 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Initialising transfer.' 2017-07-21 07:23:21,042 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Initialising transfer..' 2017-07-21 07:23:21,619 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Initialising transfer...' 2017-07-21 07:23:21,681 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to '' 2017-07-21 07:23:21,776 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Transfer initialised.' 2017-07-21 07:23:21,776 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Starting upload.' 2017-07-21 07:23:22,401 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Upload progress: 0%' ---Upload Progress % Lines Removed To Save Space--- 2017-07-21 07:26:05,510 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Upload progress: 99%' 2017-07-21 07:26:05,885 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to '' 2017-07-21 07:26:05,947 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Upload completed.' 2017-07-21 07:26:07,463 [INFO][15080][SvmInstallIterator.deploySVM]: MOR of deployed Security VM SecVMProd01 is vm-574 2017-07-21 07:26:07,463 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Setting OVF properties' 2017-07-21 07:26:12,385 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Adding network cards' 2017-07-21 07:26:12,463 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Adding network card dpgVlan15 to SecVMProd01' 2017-07-21 07:26:16,885 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'VM SecVMProd01 successfully reconfigured' 2017-07-21 07:26:16,933 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Powering on SSVM' 2017-07-21 07:26:19,292 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Waiting for VMware Tools in SSVM' 2017-07-21 07:26:40,167 [INFO][15080][VIVirtualMachine.login_in_guest]: Attempting login_in_guest with user vmrun 2017-07-21 07:26:40,542 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Setting support password.' 2017-07-21 07:26:43,308 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Saving deployment summary.' 2017-07-21 07:26:46,010 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Setting timezone.' 2017-07-21 07:26:53,558 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Running configure_network with the following args: [u'SecVMProd01', u'139.67.15.1', u'139.67.14.190', u'139.67.14.191', '"vswitch=dpgVlan15 netmask=255.255.255.0 primary=True domain=eiuad.eiu.edu address=139.67.15.146"']' 2017-07-21 07:26:53,588 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Configuring Security VM networking.' 2017-07-21 07:26:56,369 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Acquiring Security VM IP address.' 2017-07-21 07:27:08,042 [INFO][15080][VIVirtualMachine.get_public_ip_address]: ip_address=139.67.15.146 2017-07-21 07:27:08,042 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Configuring statistic reporting.' 2017-07-21 07:27:10,994 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Configuring Security VM updating using SEC.' 2017-07-21 07:27:16,230 [ERROR][15080][SvmInstallIterator.exception]: Failed to configure SSVM File "C:\Build\modules\controller\execute.py", line 137, in onEsxiHostUpdater File "C:\Build\modules\controller\execute.py", line 218, in configureSVM File "C:\Build\modules\controller\svm.py", line 213, in sec_updating File "C:\Build\modules\controller\svm.py", line 70, in _runCommand ConfigurationFailedException: Configuration of Security VM failed. 2017-07-21 07:27:16,230 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Copying syslog' 2017-07-21 07:27:19,042 [INFO][15080][VIVirtualMachine.login_in_guest]: Attempting login_in_guest with user logcollector 2017-07-21 07:27:19,183 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Retrieving logs.' 2017-07-21 07:27:19,588 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Retrieved log file 'C:\Users\da_ajsimonton\Sophos\SVE_VMware\logs\2017-07-21_07-27-19\Configure.log' as 'Configure.log'' 2017-07-21 07:27:20,088 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Retrieved log file 'C:\Users\da_ajsimonton\Sophos\SVE_VMware\logs\2017-07-21_07-27-19\syslog.log' as 'syslog.log'' 2017-07-21 07:27:20,105 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Powering down deployed SSVM' 2017-07-21 07:27:30,776 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Removing deployed SSVM' 2017-07-21 07:27:33,167 [ERROR][15080][ControllerProgress.error]: Error: Failed to deploy SSVM: Configuration of Security VM failed. 2017-07-21 07:27:33,167 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'Error: Failed to deploy SSVM: Configuration of Security VM failed.' 2017-07-21 07:27:33,167 [INFO][15080][ControllerProgress.__updateState]: State of 'esx15.sc.vmware.local' changed to 'complete' 2017-07-21 07:28:36,496 [INFO][14840][SSVMInstallerWizard.OnWizardNext]: .OnWizardNext()