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:reservation_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:reservation_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:get_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:get_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:get_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:get_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:get_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:get_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:get_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:get_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:get_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 ???
