The first warning in the vcld.log file... 2017-05-23 05:02:29|16309|18|18|image|VMware.pm:get_vmhost_product_name|6544|VMware product being used on VM host localhost: 'VMware ESXi 5.5.0 build-1331820' 2017-05-23 05:02:29|16309|18|18|image| 2017-05-23 05:02:29|16309|18|18|image|VMware.pm:get_vmx_base_directory_path|2921|determined vmx base directory path: datastore1/win7 |16309|18|18|image|VMware.pm: *|16309|18|18|image|VMware.pm:initialize|358| ---- WARNING ---- |16309|18|18|image|VMware.pm:* *|16309|18|18|image|VMware.pm:initialize|358| 2017-05-23 05:02:29|16309|18|18|image|VMware.pm:initialize|358|unable to access vmx base directory path on VM host localhost: datastore1/win7*
...appears to indicate that the datastore specified in the virtual host profile configuration cannot be found. Check your virtual host configuration in VCL and verify that it exists in ESXi. The VCL logs are purposefully very verbose, so always look for the text "WARNING" and "CRITICAL" to quickly identify issues. On Tue, May 23, 2017 at 8:07 AM, Ariuntulga Kikoo <[email protected] > wrote: > Run tail -f /var/log/vcld.log to see progress > > > ============================================================================ > VCL Management Node Daemon (vcld) | 2017-05-23 05:00:58 > ============================================================================ > bin path: /usr/local/vcl-2.4.2/bin config file: /etc/vcl/vcld.conf log > file: /var/log/vcld.log pid file: /var/run/vcld.pid daemon mode: 1 setup > mode: 0 verbose mode: 1 ============================== > ============================================== Created VCL daemon > process: 16191 2017-05-23 05:00:58|16191|||vcld|utils. > pm:rename_vcld_process|6245|renamed process to 'vcld' 2017-05-23 > 05:00:58|16191|||vcld|vcld:main|120|retrieved management node information > from database 2017-05-23 > 05:00:58|16191|||vcld|vcld:main|133|management_node_id > environment variable set: 1 2017-05-23 > 05:00:58|16191|||vcld|vcld:main|141|management > node checkin interval is 12 seconds 2017-05-23 > 05:00:58|16191|||vcld|vcld:main|142|vcld > started on localhost 2017-05-23 05:00:58|16191|||vcld|vcld:main|164|vcld > environment variable set to 1 for this process 2017-05-23 > 05:00:58|16135|||vcld|utils.pm:run_command|9339|executed command: > 'service vcld restart', exit status: 0, output: |16135|||vcld|utils.pm: > run_command|9339| Restarting vcld (via systemctl): [ OK ] 2017-05-23 > 05:00:58|16191|||vcld|vcld:main|175|lastcheckin time updated for > management node 1: 2017-05-23 05:00:58 2017-05-23 > 05:01:10|16191|||vcld|vcld:main|175|lastcheckin time updated for > management node 1: 2017-05-23 05:01:10 2017-05-23 > 05:01:16|16135|||vcld|utils.pm:get_computer_ids|8089|1 computer was found > matching argument: 192.168.10.131, returning computer ID: 2 2017-05-23 > 05:01:16|16135|||vcld|utils.pm:get_production_imagerevision_info|3737|retrieved > info from database for production revision for image identifier '1', > production image: 'noimage' 2017-05-23 05:01:16|16135|||vcld|utils. > pm:get_computer_info|7324|skipping retrieval of VM host 1 info for > localhost to avoid recursion 2017-05-23 05:01:16|16135|||vcld|utils. > pm:get_computer_info|7344|retrieved info for computer: localhost (1) > 2017-05-23 05:01:16|16135|||vcld|utils.pm:get_vmhost_info|4090|retrieved > VM host 1 info, VM host ID: 1, computer: localhost, computer ID: 1 > 2017-05-23 05:01:16|16135|||vcld|utils.pm:get_computer_info|7344|retrieved > info for computer: root-PC (2) 2017-05-23 05:01:16|16135|||vcld|utils. > pm:get_provisioning_osinstalltype_info|14082|retrieved info for > OSinstalltypes mapped to provisioning ID 7: : { |16135|||vcld|utils.pm: > get_provisioning_osinstalltype_info|14082| : 4 => { > |16135|||vcld|utils.pm:get_provisioning_osinstalltype_info|14082| : "id" > => 4, |16135|||vcld|utils.pm:get_provisioning_osinstalltype_info|14082| : > "name" => "vmware", > |16135|||vcld|utils.pm:get_provisioning_osinstalltype_info|14082| > : "provisioningOSinstalltype" => { |16135|||vcld|utils.pm:get_ > provisioning_osinstalltype_info|14082| : "OSinstalltypeid" => 4, > |16135|||vcld|utils.pm:get_provisioning_osinstalltype_info|14082| : > "provisioningid" => 7 |16135|||vcld|utils.pm:get_ > provisioning_osinstalltype_info|14082| : } |16135|||vcld|utils.pm:get_ > provisioning_osinstalltype_info|14082| : } |16135|||vcld|utils.pm:get_ > provisioning_osinstalltype_info|14082| : } 2017-05-23 > 05:01:16|16135|||vcld|utils.pm:get_computer_current_ > private_ip_address|13882|retrieved private IP address for computer > root-PC (2) from database: 192.168.10.131 2017-05-23 > 05:01:16|16135|||vcld|utils.pm:determine_remote_connection_target|14283|private > IP address is set in database for root-PC, it will be used as the remote > connection target: 192.168.10.131 2017-05-23 > 05:01:17|16135|||vcld|utils.pm:nmap_port|2173|port > 22 is open on 192.168.10.131 (root-PC) 2017-05-23 > 05:01:18|16135|||vcld|utils.pm:nmap_port|2173|port 24 is open on > 192.168.10.131 (root-PC) 2017-05-23 05:01:18|16135|||vcld|utils. > pm:get_request_by_computerid|5319|2 is not assigned to any reservations > 2017-05-23 05:01:18|16135|||vcld|utils.pm:setup_get_array_choice|10941|choices > argument: |16135|||vcld|utils.pm:setup_get_array_choice|10941| Generic > Linux (VMware) |16135|||vcld|utils.pm:setup_get_array_choice|10941| OSX > Snow Leopard (VMware) |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Ubuntu (VMware) |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows 2003 Server (VMware) > |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows 7 (VMware) |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows 8.x (VMware) |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows Server 2008 (VMware) > |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows Server 2012 (VMware) > |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows Vista (VMware) |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows XP (VMware ESX) |16135|||vcld|utils.pm:setup_get_array_choice|10941| > Windows XP (VMware) 2017-05-23 05:01:22|16191|||vcld|vcld:main|175|lastcheckin > time updated for management node 1: 2017-05-23 05:01:22 2017-05-23 > 05:01:34|16191|||vcld|vcld:main|175|lastcheckin time updated for > management node 1: 2017-05-23 05:01:34 2017-05-23 > 05:01:46|16191|||vcld|vcld:main|175|lastcheckin time updated for > management node 1: 2017-05-23 05:01:46 2017-05-23 > 05:01:58|16191|||vcld|vcld:main|175|lastcheckin time updated for > management node 1: 2017-05-23 05:01:58 2017-05-23 > 05:02:01|16135|||vcld|utils.pm:setup_get_array_choice|10941|choices > argument: |16135|||vcld|utils.pm:setup_get_array_choice|10941| x86 > |16135|||vcld|utils.pm:setup_get_array_choice|10941| x86_64 2017-05-23 > 05:02:07|16135|||vcld|utils.pm:setup_get_array_choice|10941|choices > argument: |16135|||vcld|utils.pm:setup_get_array_choice|10941| Yes > |16135|||vcld|utils.pm:setup_get_array_choice|10941| No 2017-05-23 > 05:02:10|16191|||vcld|vcld:main|175|lastcheckin time updated for > management node 1: 2017-05-23 05:02:10 2017-05-23 > 05:02:14|16135|||vcld|utils.pm:xmlrpc_call|9604|RPC::XML version supports > useragent options, setting verify_hostname to 0 2017-05-23 > 05:02:14|16135|||vcld|utils.pm:xmlrpc_call|9616|created RPC::XML client > object: |16135|||vcld|utils.pm:xmlrpc_call|9616| URL: > https://localhost/vcl/index.php?mode=xmlrpccall |16135|||vcld|utils.pm: > xmlrpc_call|9616| username: vclsystem@Local 2017-05-23 > 05:02:15|16135|||vcld|utils.pm:xmlrpc_call|9661|called > RPC::XML::Client::send_request: |16135|||vcld|utils.pm:xmlrpc_call|9661| > arguments: XMLRPCfinishBaseImageCapture, 3, 29, 1 |16135|||vcld|utils.pm: > xmlrpc_call|9661| response value: |16135|||vcld|utils.pm:xmlrpc_call|9661| > : { |16135|||vcld|utils.pm:xmlrpc_call|9661| : "status" => "success" > |16135|||vcld|utils.pm:xmlrpc_call|9661| : } 2017-05-23 > 05:02:15|16135|||vcld|utils.pm:add_imageid_to_newimages|9558|added image > to owner's new images group, user ID: 3, image resource ID: 29, VM image: 1 > 2017-05-23 05:02:15|16135|||vcld|utils.pm:insert_request|8403|inserted > new image/image request into request table, request id=18 2017-05-23 > 05:02:15|16135|||vcld|utils.pm:insert_request|8434|inserted new > reservation for request 18: 18 2017-05-23 > 05:02:22|16191|||vcld|vcld:main|175|lastcheckin > time updated for management node 1: 2017-05-23 05:02:22 2017-05-23 > 05:02:22|16191|18|18|image|utils.pm:run_command|9339|executed command: > 'ps -e -o pid,args | grep -P "vcld .\|[0-9]+\|[0-9]+\|18\|"', exit status: > 1, output: 2017-05-23 05:02:22|16191|18|18|image|utils.pm: > is_management_node_process_running|9772|process is NOT running, > identifier: 'vcld .\|[0-9]+\|[0-9]+\|18\|' 2017-05-23 > 05:02:22|16191|18|18|image|utils.pm:reservation_being_processed|9275|reservation > 18 is NOT currently being processed |16191|18|18|image|utils.pm:re > servation_being_processed|9275| reservation ID: 18 > |16191|18|18|image|utils.pm:reservation_being_processed|9275| parent > reservation ID: 18 |16191|18|18|image|utils.pm:re > servation_being_processed|9275| reservation computerloadlog 'begin' entry > exists: no |16191|18|18|image|utils.pm:reservation_being_processed|9275| > parent reservation computerloadlog 'begin' entry exists: no > |16191|18|18|image|utils.pm:reservation_being_processed|9275| reservation > process running: no 2017-05-23 > 05:02:22|16191|18|18|image|vcld:main|294|reservation > 18 is NOT already being processed 2017-05-23 05:02:23|16191|18|18|image| > utils.pm:get_imagemeta_info|3849|retrieved imagemeta info: > |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : { > |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : "architecture" => > "", |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : "checkuser" => > 1, |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : "id" => 18, > |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : "postoption" => > "", |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : "rootaccess" > => 1, |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : > "sethostname" => "", |16191|18|18|image|utils.pm:get_imagemeta_info|3849| > : "subimages" => 0, |16191|18|18|image|utils.pm:get_imagemeta_info|3849| > : "sysprep" => 0 |16191|18|18|image|utils.pm:get_imagemeta_info|3849| : } > 2017-05-23 05:02:23|16191|18|18|image|utils.pm:get_user_info|6962|UID > value is not configured for user 'vclsystem', setting UID: 503, standalone: > 1 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_management_node_info|4675|retrieving > current management node info for 'localhost' from database, cached data is > stale: 85 seconds old > |16191|18|18|image|utils.pm:get_management_node_info|4767| > ---- WARNING ---- |16191|18|18|image|utils.pm:get_management_node_info|4767| > 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_management_node_info|4767|zero > rows were returned from database select, image library functions will be > disabled |16191|18|18|image|utils.pm:get_management_node_info|4767| ( 0) > utils.pm, get_management_node_info (line: 4767) > |16191|18|18|image|utils.pm:get_management_node_info|4767| (-1) utils.pm, > get_image_info (line: 3584) > |16191|18|18|image|utils.pm:get_management_node_info|4767| > (-2) utils.pm, get_request_info (line: 3020) |16191|18|18|image|utils.pm: > get_management_node_info|4767| (-3) vcld, main (line: 299) 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_variable|12882|variable > 'user_password_length' is not set in the database 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_variable|12882|variable > 'user_password_spchar' is not set in the database 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_management_node_info|4837|retrieved > management node info: 'localhost' (localhost) 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_production_ > imagerevision_info|3737|retrieved info from database for production > revision for image identifier '1', production image: 'noimage' 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_computer_info|7324|skipping > retrieval of VM host 1 info for localhost to avoid recursion 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_computer_info|7344|retrieved info > for computer: localhost (1) 2017-05-23 05:02:23|16191|18|18|image| > utils.pm:get_vmhost_info|4090|retrieved VM host 1 info, VM host ID: 1, > computer: localhost, computer ID: 1 2017-05-23 05:02:23|16191|18|18|image| > utils.pm:get_computer_info|7344|retrieved info for computer: root-PC (2) > 2017-05-23 05:02:23|16191|18|18|image|utils.pm:get_reservation_ > connect_method_info|11619|retrieved connect method info for reservation > 18: |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : { |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : 2 => { > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : "RETRIEVAL_TIME" => "1495540943", |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "connectmethodmap" => { > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > "OSid" => undef, |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "OStypeid" => 1, > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > "autoprovisioned" => undef, |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "connectmethodid" => 2, > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > "disabled" => 0, |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "imagerevisionid" => undef > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > }, |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : "connectmethodport" => { |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : 2 => { > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > "connectmethodid" => 2, |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "id" => 2, > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > "port" => 3389, |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "protocol" => "TCP" > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > } |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : }, |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : "description" => "Remote Desktop for Windows", > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| : > "id" => 2, > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : "name" => "RDP", |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : "servicename" => > "TermService", > |16191|18|18|image|utils.pm:get_reservation_connect_method_info|11619| > : "startupscript" => undef |16191|18|18|image|utils.pm:ge > t_reservation_connect_method_info|11619| : } |16191|18|18|image|utils.pm: > get_reservation_connect_method_info|11619| : } 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:get_user_info|6962|UID value is not > configured for user 'vclsystem', setting UID: 503, standalone: 1 2017-05-23 > 05:02:23|16191|18|18|image|vcld:main|300|retrieved request information > from database 2017-05-23 05:02:23|16191|18|18|image|utils.pm:delete_ > computerloadlog_reservation|5844|deleted rows from computerloadlog > matching loadstate regex 'exited' for reservation IDs: 18 2017-05-23 > 05:02:23|16191|18|18|image|utils.pm:insertloadlog|2758|inserted 'begin' > computerloadlog entry 2017-05-23 05:02:23|16191|18|18|image| > vcld:make_new_child|514|request will be processed by image.pm 2017-05-23 > 05:02:23|16191|18|18|image|vcld:make_new_child|536|created child process > 16309 for reservation 18, state: image, current number of forked kids: 1 > 2017-05-23 05:02:23|16309|18|18|image|vcld:make_new_child|556|vcld > environment variable set to 0 for this process 2017-05-23 > 05:02:23|16309|18|18|image|DataStructure.pm:is_parent_reservation|1101|this > is the parent reservation 2017-05-23 05:02:23|16309|18|18|image|utils.pm: > rename_vcld_process|6207|reservation count: 1 2017-05-23 > 05:02:23|16309|18|18|image|utils.pm:rename_vcld_process|6226|PARENTIMAGE: > 1 2017-05-23 > 05:02:23|16309|18|18|image|utils.pm:rename_vcld_process|6227|SUBIMAGE: > 0 2017-05-23 > 05:02:23|16309|18|18|image|utils.pm:rename_vcld_process|6245|renamed > process to 'vcld '|16309|18|18|image|' root-PC>localhost > vmwarewin7-winroot19-v0 vclsystem' 2017-05-23 > 05:02:23|16309|18|18|image|vcld:make_new_child|575|loaded > VCL::image module 2017-05-23 > 05:02:23|16309|18|18|image|Module.pm:new|184|VCL::image > object created for state image, address: 32b60b8 2017-05-23 > 05:02:23|16309|18|18|image|DataStructure.pm:_initialize|705|image > identifier argument was specified: noimage, DataStructure object will > contain image information for the production imagerevision of this image > 2017-05-23 05:02:23|16309|18|18|image|utils.pm:get_production_ > imagerevision_info|3737|retrieved info from database for production > revision for image identifier 'noimage', production image: 'noimage' > 2017-05-23 > 05:02:23|16309|18|18|image|DataStructure.pm:_initialize|735|retrieved > data for imagerevision ID: 1 2017-05-23 05:02:23|16309|18|18|image| > DataStructure.pm:_initialize|751|retrieved data for image ID: 1 > 2017-05-23 05:02:23|16309|18|18|image|Module.pm:create_mn_os_object| > 481|VCL::Module::OS::Linux::ManagementNode module loaded 2017-05-23 > 05:02:23|16309|18|18|image|Module.pm:new|195|VCL::Module::OS::Linux::ManagementNode > object created, address: 33cce50 2017-05-23 05:02:23|16309|18|18|image| > utils.pm:hostname_to_ip_address|13910|resolved IP address from hostname > localhost --> 127.0.0.1 2017-05-23 05:02:23|16309|18|18|image| > DataStructure.pm:set_computer_private_ip_address|1624|private IP address > of localhost set to 127.0.0.1 2017-05-23 05:02:23|16309|18|18|image| > Module.pm:create_mn_os_object|486|VCL::Module::OS::Linux::ManagementNode > OS object created, address: 33cce50 2017-05-23 05:02:23|16309|18|18|image| > Module.pm:set_mn_os|1032|storing reference to managment node OS object > (address: 33cce50) in this VCL::image object (address: 32b60b8) 2017-05-23 > 05:02:23|16309|18|18|image|State.pm:initialize|86|initializing > VCL::Module::State object 2017-05-23 05:02:23|16309|18|18|image| > DataStructure.pm:is_parent_reservation|1101|this is the parent > reservation 2017-05-23 > 05:02:23|16309|18|18|image|State.pm:initialize|103|obtained > a database handle for this state process, stored as $ENV{dbh} 2017-05-23 > 05:02:23|16309|18|18|image|utils.pm:update_reservation_lastcheck|5551|updated > reservation.lastcheck to '2017-05-23 05:02:23' for reservation IDs: 18 > 2017-05-23 > 05:02:23|16309|18|18|image|utils.pm:update_request_state|1399|request > 18 state updated to pending/image 2017-05-23 05:02:23|16309|18|18|image| > DataStructure.pm:is_parent_reservation|1101|this is the parent > reservation 2017-05-23 05:02:23|16309|18|18|image| > DataStructure.pm:is_parent_reservation|1101|this is the parent > reservation 2017-05-23 05:02:24|16309|18|18|image| > Module.pm:create_os_object|420|VCL::Module::OS::Windows::Version_6::7 > module loaded 2017-05-23 05:02:24|16309|18|18|image| > Module.pm:new|188|VCL::Module::OS::Windows::Version_6::7 object created > for image vmwarewin7-winroot19-v0, address: 39be790 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:set_mn_os|1032|storing reference to > managment node OS object (address: 33cce50) in this > VCL::Module::OS::Windows::Version_6::7 object (address: 39be790) > 2017-05-23 05:02:24|16309|18|18|image|Windows.pm:initialize|212|beginning > Windows module initialization 2017-05-23 05:02:24|16309|18|18|image| > Windows.pm:initialize|222|Windows module initialization complete > 2017-05-23 05:02:24|16135|||vcld|Module.pm:DESTROY|1880|destroying > VCL::Module::OS::Windows object, address: 59632a0 2017-05-23 > 05:02:24|16135|||vcld|State.pm:DESTROY|1046|VCL::image destructor called, > address: 544b5a8 2017-05-23 > 05:02:24|16135|||vcld|Module.pm:DESTROY|1880|destroying > VCL::image object, address: 544b5a8 2017-05-23 > 05:02:24|16135|||vcld|Module.pm:DESTROY|1880|destroying > VCL::Module::Provisioning::VMware::VMware object, address: 42e29c0 > 2017-05-23 05:02:24|16135|||vcld|Module.pm:DESTROY|1880|destroying > VCL::Module object, address: 56233a8 2017-05-23 > 05:02:24|16135|||vcld|Module.pm:DESTROY|1880|destroying > VCL::Module::OS::Linux::ManagementNode object, address: 5805a98 > 2017-05-23 05:02:24|16135|||vcld|Module.pm:DESTROY|1880|destroying > VCL::Module::OS::Linux::ManagementNode object, address: 4af5960 > 2017-05-23 05:02:24|16309|18|18|image|Module.pm:create_os_object| > 433|VCL::Module::OS::Windows::Version_6::7 OS object created, address: > 39be790 2017-05-23 05:02:24|16309|18|18|image| > DataStructure.pm:_initialize|667|computer identifier argument was > specified, retrieving data for computer: 1 2017-05-23 > 05:02:24|16309|18|18|image|utils.pm:get_computer_info|7324|skipping > retrieval of VM host 1 info for localhost to avoid recursion 2017-05-23 > 05:02:24|16309|18|18|image|utils.pm:get_computer_info|7344|retrieved info > for computer: localhost (1) 2017-05-23 05:02:24|16309|18|18|image| > utils.pm:get_vmhost_info|4090|retrieved VM host 1 info, VM host ID: 1, > computer: localhost, computer ID: 1 2017-05-23 05:02:24|16309|18|18|image| > utils.pm:get_computer_info|7344|retrieved info for computer: localhost > (1) 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|705|image > identifier argument was specified: 1, DataStructure object will contain > image information for the production imagerevision of this image 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|735|retrieved > data for imagerevision ID: 1 2017-05-23 05:02:24|16309|18|18|image| > DataStructure.pm:_initialize|751|retrieved data for image ID: 1 > 2017-05-23 05:02:24|16309|18|18|image|Module.pm:create_vmhost_os_object|564|VM > host OS image Perl package is VCL::Module::OS::Linux::UnixLab, most > likely will not work correctly, changing to Linux 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:create_vmhost_os_object|569|attempting > to load VM host OS module: VCL::Module::OS::Linux (image: 1) 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:create_vmhost_os_object|575|VM host > OS module loaded: VCL::Module::OS::Linux 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:new|188|VCL::Module::OS::Linux > object created for image noimage, address: 405bd40 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:set_mn_os|1032|storing reference to > managment node OS object (address: 33cce50) in this VCL::Module::OS::Linux > object (address: 405bd40) 2017-05-23 05:02:24|16309|18|18|image| > Module.pm:create_vmhost_os_object|588|VCL::Module::OS::Linux OS object > created, address: 405bd40 2017-05-23 05:02:24|16309|18|18|image| > Module.pm:set_vmhost_os|1067|storing reference to VM host OS object > (address: 405bd40) in this VCL::image object (address: 32b60b8) 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:create_provisioning_ > object|719|VCL::Module::Provisioning::VMware::VMware module loaded > 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:new|192|VCL::Module::Provisioning::VMware::VMware > object created for computer root-PC, address: 39bead8 2017-05-23 > 05:02:24|16309|18|18|image|Module.pm:set_mn_os|1032|storing reference to > managment node OS object (address: 33cce50) in this > VCL::Module::Provisioning::VMware::VMware object (address: 39bead8) > 2017-05-23 05:02:24|16309|18|18|image|VMware.pm:initialize|271|initializing > VCL::Module::Provisioning::VMware::VMware object 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|667|computer > identifier argument was specified, retrieving data for computer: 1 > 2017-05-23 05:02:24|16309|18|18|image|utils.pm:get_computer_info|7324|skipping > retrieval of VM host 1 info for localhost to avoid recursion 2017-05-23 > 05:02:24|16309|18|18|image|utils.pm:get_computer_info|7344|retrieved info > for computer: localhost (1) 2017-05-23 05:02:24|16309|18|18|image| > utils.pm:get_vmhost_info|4090|retrieved VM host 1 info, VM host ID: 1, > computer: localhost, computer ID: 1 2017-05-23 05:02:24|16309|18|18|image| > utils.pm:get_computer_info|7344|retrieved info for computer: localhost > (1) 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|705|image > identifier argument was specified: 1, DataStructure object will contain > image information for the production imagerevision of this image 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|735|retrieved > data for imagerevision ID: 1 2017-05-23 05:02:24|16309|18|18|image| > DataStructure.pm:_initialize|751|retrieved data for image ID: 1 > 2017-05-23 > 05:02:24|16309|18|18|image|VMware.pm:get_vmhost_datastructure|1233|created > DataStructure object for VM host: localhost 2017-05-23 > 05:02:24|16309|18|18|image|VMware.pm:initialize|290|VM profile assigned > to localhost: VMware ESXi - local storage 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|667|computer > identifier argument was specified, retrieving data for computer: 1 > 2017-05-23 05:02:24|16309|18|18|image|utils.pm:get_computer_info|7324|skipping > retrieval of VM host 1 info for localhost to avoid recursion 2017-05-23 > 05:02:24|16309|18|18|image|utils.pm:get_computer_info|7344|retrieved info > for computer: localhost (1) 2017-05-23 05:02:24|16309|18|18|image| > utils.pm:get_vmhost_info|4090|retrieved VM host 1 info, VM host ID: 1, > computer: localhost, computer ID: 1 2017-05-23 05:02:24|16309|18|18|image| > utils.pm:get_computer_info|7344|retrieved info for computer: localhost > (1) 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|705|image > identifier argument was specified: 1, DataStructure object will contain > image information for the production imagerevision of this image 2017-05-23 > 05:02:24|16309|18|18|image|DataStructure.pm:_initialize|735|retrieved > data for imagerevision ID: 1 2017-05-23 05:02:24|16309|18|18|image| > DataStructure.pm:_initialize|751|retrieved data for image ID: 1 > 2017-05-23 > 05:02:24|16309|18|18|image|VMware.pm:get_vmhost_datastructure|1233|created > DataStructure object for VM host: localhost 2017-05-23 > 05:02:24|16309|18|18|image|VMware.pm:get_vmhost_api_object|1336|attempting > to load VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK > 2017-05-23 > 05:02:24|16309|18|18|image|VMware.pm:get_vmhost_api_object|1342|loaded > VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK > 2017-05-23 05:02:24|16309|18|18|image|Module.pm:new|192|VCL::Module: > :Provisioning::VMware::vSphere_SDK object created for computer root-PC, > address: 468c798 2017-05-23 05:02:24|16309|18|18|image| > Module.pm:set_mn_os|1032|storing reference to managment node OS object > (address: 33cce50) in this VCL::Module::Provisioning::VMware::vSphere_SDK > object (address: 468c798) 2017-05-23 05:02:24|16309|18|18|image| > vSphere_SDK.pm:initialize|98|vSphere SDK for Perl does not appear to be > installed on this managment node, unable to load VMware vSphere SDK Perl > modules, error: |16309|18|18|image|vSphere_SDK.pm:initialize|98| Can't > locate VMware/VIRuntime.pm in @INC (@INC contains: > /usr/local/vcl-2.4.2/bin/../../../.. /usr/local/vcl-2.4.2/bin/../.. > /usr/local/vcl-2.4.2/bin/../../.. /usr/local/vcl-2.4.2/bin/../../../../.. > /usr/local/vcl-2.4.2/bin/.. /usr/local/vcl-2.4.2/bin/../lib > /usr/local/lib64/perl5 /usr/local/share/perl5 /usr/lib64/perl5/vendor_perl > /usr/share/perl5/vendor_perl /usr/lib64/perl5 /usr/share/perl5 .) at (eval > 280) line 1. |16309|18|18|image|vSphere_SDK.pm:initialize|98| BEGIN > failed--compilation aborted at (eval 280) line 1. 2017-05-23 > 05:02:24|16309|18|18|image|VMware.pm:get_vmhost_api_object|1357|API > object could not be created: VCL::Module::Provisioning::VMware::vSphere_SDK > 2017-05-23 05:02:24|16309|18|18|image|utils.pm:get_computer_current_ > private_ip_address|13882|retrieved private IP address for computer > localhost (1) from database: 192.168.10.130 2017-05-23 > 05:02:24|16309|18|18|image|utils.pm:determine_remote_ > connection_target|14283|private IP address is set in database for > localhost, it will be used as the remote connection target: 192.168.10.130 > 2017-05-23 05:02:25|16309|18|18|image|utils.pm:nmap_port|2173|port 22 is > open on 192.168.10.130 (localhost) 2017-05-23 05:02:25|16309|18|18|image| > utils.pm:nmap_port|2173|port 24 is open on 192.168.10.130 (localhost) > 2017-05-23 05:02:28|16309|18|18|image|OS.pm:is_ssh_responding|955|localhost > is responding to SSH, port 22: open, port 24: open 2017-05-23 > 05:02:28|16309|18|18|image|VMware.pm:initialize|307|OS on VM host > localhost will be controlled using VCL::Module::OS::Linux OS object > 2017-05-23 > 05:02:28|16309|18|18|image|DataStructure.pm:_initialize|667|computer > identifier argument was specified, retrieving data for computer: 1 > 2017-05-23 05:02:28|16309|18|18|image|utils.pm:get_computer_info|7324|skipping > retrieval of VM host 1 info for localhost to avoid recursion 2017-05-23 > 05:02:28|16309|18|18|image|utils.pm:get_computer_info|7344|retrieved info > for computer: localhost (1) 2017-05-23 05:02:28|16309|18|18|image| > utils.pm:get_vmhost_info|4090|retrieved VM host 1 info, VM host ID: 1, > computer: localhost, computer ID: 1 2017-05-23 05:02:28|16309|18|18|image| > utils.pm:get_computer_info|7344|retrieved info for computer: localhost > (1) 2017-05-23 > 05:02:28|16309|18|18|image|DataStructure.pm:_initialize|705|image > identifier argument was specified: 1, DataStructure object will contain > image information for the production imagerevision of this image 2017-05-23 > 05:02:28|16309|18|18|image|DataStructure.pm:_initialize|735|retrieved > data for imagerevision ID: 1 2017-05-23 05:02:28|16309|18|18|image| > DataStructure.pm:_initialize|751|retrieved data for image ID: 1 > 2017-05-23 > 05:02:28|16309|18|18|image|VMware.pm:get_vmhost_datastructure|1233|created > DataStructure object for VM host: localhost 2017-05-23 > 05:02:28|16309|18|18|image|VMware.pm:get_vmhost_api_object|1336|attempting > to load VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH > 2017-05-23 > 05:02:28|16309|18|18|image|VMware.pm:get_vmhost_api_object|1342|loaded > VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH > 2017-05-23 > 05:02:28|16309|18|18|image|Module.pm:new|192|VCL::Module::Provisioning::VMware::VIM_SSH > object created for computer root-PC, address: 41487d8 2017-05-23 > 05:02:28|16309|18|18|image|Module.pm:set_mn_os|1032|storing reference to > managment node OS object (address: 33cce50) in this > VCL::Module::Provisioning::VMware::VIM_SSH object (address: 41487d8) > 2017-05-23 05:02:28|16309|18|18|image|utils.pm:run_ssh_command|4302|executing > SSH command on 192.168.10.130 (localhost): '/usr/bin/ssh -o > StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o > ConnectionAttempts=1 -o ConnectTimeout=3 -o BatchMode=no -o > PasswordAuthentication=no -l root -p 22 -x 192.168.10.130 'vim-cmd ; > vmware-vim-cmd' 2>&1' 2017-05-23 05:02:29|16309|18|18|image|utils.pm: > run_ssh_command|4451|command: 'vim-cmd ; vmware-vim-cmd', exit_status: > 127, output: |16309|18|18|image|utils.pm:run_ssh_command|4451| Commands > available under /: |16309|18|18|image|utils.pm:run_ssh_command|4451| > hbrsvc/ internalsvc/ solo/ vmsvc/ > |16309|18|18|image|utils.pm:run_ssh_command|4451| > hostsvc/ proxysvc/ vimsvc/ help > |16309|18|18|image|utils.pm:run_ssh_command|4451| > sh: vmware-vim-cmd: not found 2017-05-23 > 05:02:29|16309|18|18|image|VIM_SSH.pm:initialize|141|VIM > executable available on VM host: vim-cmd 2017-05-23 > 05:02:29|16309|18|18|image|VIM_SSH.pm:initialize|143|VCL: > :Module::Provisioning::VMware::VIM_SSH object initialized 2017-05-23 > 05:02:29|16309|18|18|image|VMware.pm:get_vmhost_api_object|1364|created > API object: VCL::Module::Provisioning::VMware::VIM_SSH 2017-05-23 > 05:02:29|16309|18|18|image|VMware.pm:initialize|316|VM host localhost > will be controlled using vim-cmd via SSH 2017-05-23 > 05:02:29|16309|18|18|image|VMware.pm:initialize|335|VMware OS and API > objects created for VM host localhost: > |16309|18|18|image|VMware.pm:initialize|335| > VM host OS object type: VCL::Module::OS::Linux > |16309|18|18|image|VMware.pm:initialize|335| > VMware API object type: VCL::Module::Provisioning::VMware::VIM_SSH > 2017-05-23 05:02:29|16309|18|18|image|utils.pm:run_ssh_command|4302|executing > SSH command on 192.168.10.130 (localhost): '/usr/bin/ssh -o > StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o > ConnectionAttempts=1 -o ConnectTimeout=3 -o BatchMode=no -o > PasswordAuthentication=no -l root -p 22 -x 192.168.10.130 'vmware -v' 2>&1' > 2017-05-23 05:02:29|16309|18|18|image|utils.pm:run_ssh_command|4451|command: > 'vmware -v', exit_status: 0, output: > |16309|18|18|image|utils.pm:run_ssh_command|4451| > VMware ESXi 5.5.0 build-1331820 2017-05-23 05:02:29|16309|18|18|image| > VMware.pm:get_vmhost_product_name|6544|VMware product being used on VM > host localhost: 'VMware ESXi 5.5.0 build-1331820' 2017-05-23 > 05:02:29|16309|18|18|image|VMware.pm:get_vmx_base_directory_path|2921|determined > vmx base directory path: datastore1/win7 > |16309|18|18|image|VMware.pm:initialize|358| > ---- WARNING ---- |16309|18|18|image|VMware.pm:initialize|358| 2017-05-23 > 05:02:29|16309|18|18|image|VMware.pm:initialize|358|unable to access vmx > base directory path on VM host localhost: datastore1/win7 > |16309|18|18|image|VMware.pm:initialize|358| ( 0) VMware.pm, initialize > (line: 358) |16309|18|18|image|VMware.pm:initialize|358| (-1) Module.pm, > new (line: 224) |16309|18|18|image|VMware.pm:initialize|358| (-2) > Module.pm, create_provisioning_object (line: 727) > |16309|18|18|image|VMware.pm:initialize|358| (-3) State.pm, initialize > (line: 205) |16309|18|18|image|VMware.pm:initialize|358| (-4) Module.pm, > new (line: 224) |16309|18|18|image|VMware.pm:initialize|358| (-5) vcld, > (eval) (line: 580) 2017-05-23 05:02:29|16309|18|18|image| > Module.pm:DESTROY|1880|destroying VCL::Module::Provisioning::VMware::VMware > object, address: 39bead8 |16309|18|18|image|Module.pm: > create_provisioning_object|736| ---- WARNING ---- > |16309|18|18|image|Module.pm:create_provisioning_object|736| 2017-05-23 > 05:02:29|16309|18|18|image|Module.pm:create_provisioning_object|736|provisioning > object could not be created, returning 0 |16309|18|18|image|Module.pm: > create_provisioning_object|736| ( 0) Module.pm, > create_provisioning_object (line: 736) |16309|18|18|image|Module.pm: > create_provisioning_object|736| (-1) State.pm, initialize (line: 205) > |16309|18|18|image|Module.pm:create_provisioning_object|736| (-2) > Module.pm, new (line: 224) |16309|18|18|image|Module.pm: > create_provisioning_object|736| (-3) vcld, (eval) (line: 580) > |16309|18|18|image|Module.pm:create_provisioning_object|736| (-4) vcld, > make_new_child (line: 579) |16309|18|18|image|Module.pm: > create_provisioning_object|736| (-5) vcld, main (line: 348) 2017-05-23 > 05:02:29|16309|18|18|image|DataStructure.pm:get_computer_state_name|2012|retrieved > current state of computer root-PC from the database: available > |16309|18|18|image|image.pm:reservation_failed|419| ---- CRITICAL ---- > |16309|18|18|image|image.pm:reservation_failed|419| 2017-05-23 > 05:02:29|16309|18|18|image|image.pm:reservation_failed|419|vmwarewin7-winroot19-v0 > image creation failed - failed to create provisioning object > |16309|18|18|image|image.pm:reservation_failed|419| ( 0) image.pm, > reservation_failed (line: 419) > |16309|18|18|image|image.pm:reservation_failed|419| > (-1) State.pm, initialize (line: 216) > |16309|18|18|image|image.pm:reservation_failed|419| > (-2) Module.pm, new (line: 224) > |16309|18|18|image|image.pm:reservation_failed|419| > (-3) vcld, (eval) (line: 580) > |16309|18|18|image|image.pm:reservation_failed|419| > (-4) vcld, make_new_child (line: 579) > |16309|18|18|image|image.pm:reservation_failed|419| > (-5) vcld, main (line: 348) No recipient addresses found in header > 2017-05-23 05:02:30|16309|18|18|image|utils.pm:mail|1279|SUCCESS -- > Sending mail To: , VCL -- NOTICE DELAY Image Creation winroot 2017-05-23 > 05:02:30|16309|18|18|image|utils.pm:update_request_state|1399|request 18 > state updated to maintenance/image 2017-05-23 05:02:30|16309|18|18|image| > image.pm:reservation_failed|496|request state set to maintenance, > laststate to image 2017-05-23 05:02:30|16309|18|18|image|utils.pm: > update_computer_state|1458|computer 2 state updated to: maintenance > 2017-05-23 05:02:30|16309|18|18|image|image.pm:reservation_failed|504|root-PC > state set to maintenance 2017-05-23 05:02:30|16309|18|18|image|image.pm: > reservation_failed|511|exiting 2017-05-23 05:02:30|16309|18|18|image| > State.pm:DESTROY|1046|VCL::image destructor called, address: 32b60b8 > 2017-05-23 05:02:30|16309|18|18|image|State.pm:state_exit|864|beginning > state module exit tasks |16309|18|18|image|State.pm:state_exit|864| > request state argument: <not specified> > |16309|18|18|image|State.pm:state_exit|864| > computer state argument: <not specified> > |16309|18|18|image|State.pm:state_exit|864| > log ending argument: <not specified> 2017-05-23 05:02:30|16309|18|18|image| > DataStructure.pm:is_parent_reservation|1101|this is the parent > reservation 2017-05-23 05:02:30|16309|18|18|image|utils.pm:delete_ > computerloadlog_reservation|5844|deleted rows from computerloadlog for > reservation IDs: 18 2017-05-23 05:02:30|16309|18|18|image|utils.pm: > insertloadlog|2758|inserted 'exited' computerloadlog entry 2017-05-23 > 05:02:30|16309|18|18|image|State.pm:state_exit|1015|calling subroutine: > VCL::Module::State::DESTROY, skipping call to exit 2017-05-23 > 05:02:30|16309|18|18|image|Module.pm:DESTROY|1880|destroying VCL::image > object, address: 32b60b8 2017-05-23 05:02:30|16309|18|18|image| > State.pm:DESTROY|1099|VCL::image process duration: 7 seconds 2017-05-23 > 05:02:30|16309|18|18|image|Module.pm:DESTROY|1880|destroying > VCL::Module::OS::Windows::Version_6::7 object, address: 39be790 > 2017-05-23 05:02:30|16309|18|18|image|Module.pm:DESTROY|1880|destroying > VCL::Module::Provisioning::VMware::VIM_SSH object, address: 41487d8 > 2017-05-23 05:02:30|16309|18|18|image|Module.pm:DESTROY|1880|destroying > VCL::Module::OS::Linux object, address: 405bd40 2017-05-23 > 05:02:30|16309|18|18|image|Module.pm:DESTROY|1880|destroying > VCL::Module::OS::Linux::ManagementNode object, address: 33cce50 > 2017-05-23 05:02:31|16191|||vcld|vcld:REAPER|741|VCL process exited for > reservation 18, PID: 16309, signal: CHLD > > > > > > > what happen ??? >
