Aaron, Aaron, and Andy, thanks much.
I tried to trace which it was before by adding warning lines to VMware.pm
that basically split it out to two if statements with one condition on
each and it returned that both were not defined. When I change it to the
notify line you gave me it errors out with
|3417|57:57|reload| 2014-08-08
15:46:31|3417|57:57|reload|Module.pm:create_provisioning_object(516)|VCL::Module::Provisioning::VMware::VMware
module could not be loaded, returning 0
When I leave it as stock here is the output to /var/log/vcld.log for a
reload (I'll gather a new image capture log in a different email):
2014-08-08 15:47:43|30305|vcld:main(167)|lastcheckin time updated for
management node 1: 2014-08-08 15:47:43
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:reservation_being_processed(8634)|computerloadlog
'begin' entry does NOT exist for reservation 59
2014-08-08 15:47:43|30305|59:59|reload|utils.pm:run_command(8706)|executed
command: pgrep -fl 'vcld [0-9]+:59 ', pid: 3541, exit status: 1, output:
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:is_management_node_process_running(8939)|process
is NOT running, identifier: 'vcld [0-9]+:59 '
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:reservation_being_processed(8655)|reservation
is NOT currently being processed
2014-08-08 15:47:43|30305|59:59|reload|vcld:main(282)|reservation 59 is
NOT already being processed
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:get_management_node_info(5456)|retrieving
current management node info for 'vcl.marist.edu' from database, cached
data is stale: 72 seconds old
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:get_management_node_info(5603)|retrieved
management node info: 'vcl.marist.edu' (vcl)
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:get_connect_method_info(10059)|attempting
to retrieve connect method info:
|30305|59:59|reload| imagerevision: 18 - vmwarewin7-noclean19-v0
|30305|59:59|reload| OS: 35 - vmwarewin7
|30305|59:59|reload| OS type: 1 - windows
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:get_connect_method_info(10123)|RDP:
connectmethodid=2, OStypeid=1, OSid=NULL, imagerevisionid=NULL, disabled=0
2014-08-08 15:47:43|30305|59:59|reload|utils.pm:get_user_info(7540)|UID
value is not configured for user vclreload, setting UID to VCL user ID:
vclreload, standalone: 1
2014-08-08 15:47:43|30305|59:59|reload|utils.pm:get_user_info(7540)|UID
value is not configured for user vclreload, setting UID to VCL user ID:
vclreload, standalone: 1
2014-08-08 15:47:43|30305|59:59|reload|vcld:main(287)|retrieved request
information from database
2014-08-08
15:47:43|30305|59:59|reload|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 59
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:update_request_state(1545)|request 59
state updated to: pending, laststate to: reload
2014-08-08
15:47:43|30305|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, begin, beginning to process, state is reload
2014-08-08 15:47:43|30305|59:59|reload|vcld:make_new_child(510)|request
will be processed by new.pm
2014-08-08 15:47:43|30305|59:59|reload|vcld:make_new_child(518)|loaded
VCL::new module
2014-08-08 15:47:43|30305|59:59|reload|vcld:make_new_child(542)|current
number of forked kids: 1
2014-08-08 15:47:43|3558|59:59|reload|vcld:make_new_child(558)|vcld
environment variable set to 0 for this process
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(643)|image ID
argument was specified: noimage, DataStructure object will contain image
information for the production imagerevision of this image
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_mn_os_object(376)|VCL::Module::OS::Linux::ManagementNode
module loaded
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode
object created for image noimage, address: 3c2ede0
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{hostname}, data
identifier: computer_hostname, data:
|3558|59:59|reload| : "vcl.marist.edu"
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{NODENAME}, data
identifier: computer_node_name, data:
|3558|59:59|reload| : "vcl"
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{SHORTNAME}, data
identifier: computer_short_name, data:
|3558|59:59|reload| : "vcl"
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{IPaddress}, data
identifier: computer_ip_address, data:
|3558|59:59|reload| : "172.20.101.31"
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_mn_os_object(381)|VCL::Module::OS::Linux::ManagementNode
OS object created, address: 3c2ede0
2014-08-08 15:47:43|3558|59:59|reload|Module.pm:new(192)|VCL::new object
created for state reload, address: 36bbc40
2014-08-08 15:47:43|3558|59:59|reload|State.pm:initialize(88)|obtained a
database handle for this state process, stored as $ENV{dbh}
2014-08-08 15:47:43|3558|59:59|reload|State.pm:check_image_os(771)|no
corrections need to be made, not an imaging request, returning 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 59
2014-08-08
15:47:43|3558|59:59|reload|utils.pm:rename_vcld_process(6752)|reservation
count: 1
2014-08-08
15:47:43|3558|59:59|reload|utils.pm:rename_vcld_process(6771)|PARENTIMAGE:
1
2014-08-08
15:47:43|3558|59:59|reload|utils.pm:rename_vcld_process(6772)|SUBIMAGE: 0
2014-08-08
15:47:43|3558|59:59|reload|utils.pm:rename_vcld_process(6790)|renamed
process to 'vcld 59:59 reload vm0402>node4-vcl vmwarewin7-noclean19-v0
vclreload'
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 59
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 59
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_os_object(308)|VCL::Module::OS::Windows::Version_6::7
module loaded
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:new(196)|VCL::Module::OS::Windows::Version_6::7
object created for image vmwarewin7-noclean19-v0, address: 3c316b0
2014-08-08 15:47:43|3558|59:59|reload|Windows.pm:initialize(214)|beginning
Windows module initialization
2014-08-08 15:47:43|3558|59:59|reload|Windows.pm:initialize(224)|Windows
module initialization complete
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_os_object(314)|VCL::Module::OS::Windows::Version_6::7
OS object created, address: 3c316b0
2014-08-08 15:47:43|3558|59:59|reload|State.pm:initialize(125)|computer is
a VM, attempting to create VM host OS object
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(619)|computer ID
argument was specified, retrieving data for computer ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image
information for the production imagerevision of this image
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_vmhost_os_object(454)|attempting
to load VM host OS module: VCL::Module::OS::Linux::UnixLab (image: 1)
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_vmhost_os_object(460)|VM host
OS module loaded: VCL::Module::OS::Linux::UnixLab
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:new(196)|VCL::Module::OS::Linux::UnixLab
object created for image noimage, address: 42bf718
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_vmhost_os_object(465)|VCL::Module::OS::Linux::UnixLab
OS object created, address: 42bf718
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:create_provisioning_object(519)|VCL::Module::Provisioning::VMware::VMware
module loaded
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VMware
object created for computer vm0402, address: 42bfb68
2014-08-08
15:47:43|3558|59:59|reload|VMware.pm:initialize(267)|initializing
VCL::Module::Provisioning::VMware::VMware object
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(619)|computer ID
argument was specified, retrieving data for computer ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image
information for the production imagerevision of this image
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2014-08-08
15:47:43|3558|59:59|reload|VMware.pm:get_vmhost_datastructure(1397)|created
DataStructure object for VM host: node4-vcl
2014-08-08 15:47:43|3558|59:59|reload|VMware.pm:initialize(287)|VM profile
assigned to node4-vcl: VMware ESXi - local & network storage
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(619)|computer ID
argument was specified, retrieving data for computer ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image
information for the production imagerevision of this image
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2014-08-08
15:47:43|3558|59:59|reload|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2014-08-08
15:47:43|3558|59:59|reload|VMware.pm:get_vmhost_datastructure(1397)|created
DataStructure object for VM host: node4-vcl
2014-08-08
15:47:43|3558|59:59|reload|VMware.pm:get_vmhost_api_object(1500)|attempting
to load VMware control module:
VCL::Module::Provisioning::VMware::vSphere_SDK
2014-08-08
15:47:43|3558|59:59|reload|VMware.pm:get_vmhost_api_object(1506)|loaded
VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK
2014-08-08
15:47:43|3558|59:59|reload|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vSphere_SDK
object created for computer vm0402, address: 4865ca8
2014-08-08
15:47:43|3558|59:59|reload|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:
|3558|59:59|reload| Can't locate VMware/VIRuntime.pm in @INC (@INC
contains: /usr/local/vcl/bin/../../../.. /usr/local/vcl/bin/../..
/usr/local/vcl/bin/../../.. /usr/local/vcl/bin/../../../../..
/usr/local/vcl/bin/.. /usr/local/vcl/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
284) line 1.
|3558|59:59|reload| BEGIN failed--compilation aborted at (eval 284) line
1.
2014-08-08
15:47:43|3558|59:59|reload|VMware.pm:get_vmhost_api_object(1520)|API
object could not be created:
VCL::Module::Provisioning::VMware::vSphere_SDK
2014-08-08 15:47:44|3558|59:59|reload|utils.pm:run_command(8694)|$? is set
to -1, setting exit status to 0, Perl bug likely encountered
2014-08-08
15:47:44|3558|59:59|reload|OS.pm:is_ssh_responding(678)|node4-vcl is
responding to SSH, port 22: open, port 24: closed
2014-08-08 15:47:44|3558|59:59|reload|VMware.pm:initialize(303)|OS on VM
host node4-vcl will be controlled using VCL::Module::OS::Linux::UnixLab OS
object
2014-08-08
15:47:44|3558|59:59|reload|DataStructure.pm:_initialize(619)|computer ID
argument was specified, retrieving data for computer ID: 1
2014-08-08
15:47:44|3558|59:59|reload|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image
information for the production imagerevision of this image
2014-08-08
15:47:44|3558|59:59|reload|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2014-08-08
15:47:44|3558|59:59|reload|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2014-08-08
15:47:44|3558|59:59|reload|VMware.pm:get_vmhost_datastructure(1397)|created
DataStructure object for VM host: node4-vcl
2014-08-08
15:47:44|3558|59:59|reload|VMware.pm:get_vmhost_api_object(1500)|attempting
to load VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
2014-08-08
15:47:44|3558|59:59|reload|VMware.pm:get_vmhost_api_object(1506)|loaded
VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
2014-08-08
15:47:44|3558|59:59|reload|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VIM_SSH
object created for computer vm0402, address: 4865f30
2014-08-08
15:47:44|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl
'vim-cmd ; vmware-vim-cmd' 2>&1
2014-08-08
15:47:45|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| Commands available under /:
|3558|59:59|reload| hbrsvc/ internalsvc/ solo/ vmsvc/
|3558|59:59|reload| hostsvc/ proxysvc/ vimsvc/ help
|3558|59:59|reload| sh: vmware-vim-cmd: not found
2014-08-08 15:47:45|3558|59:59|reload|utils.pm:run_ssh_command(5030)|SSH
command executed on node4-vcl, command:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl
'vim-cmd ; vmware-vim-cmd' 2>&1
|3558|59:59|reload| returning (127, "Commands available under /: hb...")
2014-08-08 15:47:45|3558|59:59|reload|VIM_SSH.pm:initialize(138)|VIM
executable available on VM host: vim-cmd
2014-08-08
15:47:45|3558|59:59|reload|VIM_SSH.pm:initialize(140)|VCL::Module::Provisioning::VMware::VIM_SSH
object initialized
2014-08-08
15:47:45|3558|59:59|reload|VMware.pm:get_vmhost_api_object(1527)|created
API object: VCL::Module::Provisioning::VMware::VIM_SSH
2014-08-08 15:47:45|3558|59:59|reload|VMware.pm:initialize(312)|VM host
node4-vcl will be controlled using vim-cmd via SSH
2014-08-08 15:47:45|3558|59:59|reload|VMware.pm:initialize(327)|VMware OS
and API objects created for VM host node4-vcl:
|3558|59:59|reload| VM host OS object type:
VCL::Module::OS::Linux::UnixLab
|3558|59:59|reload| VMware API object type:
VCL::Module::Provisioning::VMware::VIM_SSH
2014-08-08
15:47:45|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl
'vmware -v' 2>&1
2014-08-08
15:47:45|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| VMware ESXi 5.5.0 build-1623387
2014-08-08 15:47:45|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "VMware ESXi 5.5.0
build-162338...")
2014-08-08
15:47:45|3558|59:59|reload|VMware.pm:get_vmhost_product_name(6634)|VMware
product being used on VM host node4-vcl: 'VMware ESXi 5.5.0 build-1623387'
2014-08-08
15:47:46|3558|59:59|reload|VIM_SSH.pm:_run_vim_cmd(210)|executed command
on VM host node4-vcl: vim-cmd hostsvc/datastore/listsummary
2014-08-08
15:47:46|3558|59:59|reload|VMware.pm:get_datastore_info(6760)|retrieved
datastore info from VM host:
|3558|59:59|reload| : {
|3558|59:59|reload| : "datastore0" => {
|3558|59:59|reload| : "accessible" => "true",
|3558|59:59|reload| : "capacity" => "28454158336",
|3558|59:59|reload| : "datastore" =>
"vim.Datastore:53d0e783-7468ec60-9935-001a6433bf90",
|3558|59:59|reload| : "dynamicType" => "<unset>",
|3558|59:59|reload| : "freeSpace" => "27460108288",
|3558|59:59|reload| : "maintenanceMode" => "<unset>",
|3558|59:59|reload| : "multipleHostAccess" => "<unset>",
|3558|59:59|reload| : "normal_path" => "/vmfs/volumes/datastore0",
|3558|59:59|reload| : "type" => "VMFS",
|3558|59:59|reload| : "uncommitted" => 0,
|3558|59:59|reload| : "url" =>
"/vmfs/volumes/53d0e783-7468ec60-9935-001a6433bf90"
|3558|59:59|reload| : },
|3558|59:59|reload| : "datastore1" => {
|3558|59:59|reload| : "accessible" => "true",
|3558|59:59|reload| : "capacity" => "146565758976",
|3558|59:59|reload| : "datastore" =>
"vim.Datastore:53d65717-b62f0688-0c84-001a6433bf90",
|3558|59:59|reload| : "dynamicType" => "<unset>",
|3558|59:59|reload| : "freeSpace" => "145546543104",
|3558|59:59|reload| : "maintenanceMode" => "<unset>",
|3558|59:59|reload| : "multipleHostAccess" => "<unset>",
|3558|59:59|reload| : "normal_path" => "/vmfs/volumes/datastore1",
|3558|59:59|reload| : "type" => "VMFS",
|3558|59:59|reload| : "uncommitted" => "4560056838",
|3558|59:59|reload| : "url" =>
"/vmfs/volumes/53d65717-b62f0688-0c84-001a6433bf90"
|3558|59:59|reload| : },
|3558|59:59|reload| : "nfs-datastore" => {
|3558|59:59|reload| : "accessible" => "true",
|3558|59:59|reload| : "capacity" => "4092278726656",
|3558|59:59|reload| : "datastore" =>
"vim.Datastore:172.20.0.1:/opt/nfs-datastore",
|3558|59:59|reload| : "dynamicType" => "<unset>",
|3558|59:59|reload| : "freeSpace" => "2592382427136",
|3558|59:59|reload| : "maintenanceMode" => "<unset>",
|3558|59:59|reload| : "multipleHostAccess" => "<unset>",
|3558|59:59|reload| : "normal_path" => "/vmfs/volumes/nfs-datastore",
|3558|59:59|reload| : "type" => "NFS",
|3558|59:59|reload| : "uncommitted" => 0,
|3558|59:59|reload| : "url" => "/vmfs/volumes/fb70cb1b-1f7c5bac"
|3558|59:59|reload| : }
|3558|59:59|reload| : }
2014-08-08
15:47:46|3558|59:59|reload|VMware.pm:get_vmx_base_directory_path(3094)|determined
vmx base directory path: /vmfs/volumes/datastore1
2014-08-08
15:47:46|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
/vmfs/volumes/datastore1' 2>&1
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: '/vmfs/volumes/datastore1' ->
'53d65717-b62f0688-0c84-001a6433bf90'
|3558|59:59|reload| Size: 35 Blocks: 0 IO Block:
131072 symbolic link
|3558|59:59|reload| Device: 0h/0d Inode: 2147483647 Links: 1
|3558|59:59|reload| Access: (0755/lrwxr-xr-x) Uid: ( 0/ root) Gid:
( 0/ root)
|3558|59:59|reload| Access: 2014-08-08 15:47:51.000000000
|3558|59:59|reload| Modify: 2014-08-08 15:47:51.000000000
|3558|59:59|reload| Change: 2014-08-08 15:47:51.000000000
2014-08-08 15:47:47|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
'/vmfs/volumes/datastore...")
2014-08-08
15:47:47|3558|59:59|reload|Linux.pm:file_exists(1449)|'/vmfs/volumes/datastore1'
exists on node4-vcl, files: 0, directories: 0, links: 1
2014-08-08 15:47:47|3558|59:59|reload|VMware.pm:is_vm_dedicated(4257)|VM
disk mode does not need to be dedicated
2014-08-08
15:47:47|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
/vmfs/volumes/nfs\-datastore' 2>&1
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: '/vmfs/volumes/nfs-datastore' ->
'fb70cb1b-1f7c5bac'
|3558|59:59|reload| Size: 17 Blocks: 0 IO Block:
131072 symbolic link
|3558|59:59|reload| Device: 0h/0d Inode: 2147483647 Links: 1
|3558|59:59|reload| Access: (0755/lrwxr-xr-x) Uid: ( 0/ root) Gid:
( 0/ root)
|3558|59:59|reload| Access: 2014-08-08 15:47:51.000000000
|3558|59:59|reload| Modify: 2014-08-08 15:47:51.000000000
|3558|59:59|reload| Change: 2014-08-08 15:47:51.000000000
2014-08-08 15:47:47|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
'/vmfs/volumes/nfs-datas...")
2014-08-08
15:47:47|3558|59:59|reload|Linux.pm:file_exists(1449)|'/vmfs/volumes/nfs-datastore'
exists on node4-vcl, files: 0, directories: 0, links: 1
2014-08-08
15:47:47|3558|59:59|reload|Module.pm:create_provisioning_object(525)|VCL::Module::Provisioning::VMware::VMware
provisioner object created for vm0402, address: 42bfb68
2014-08-08 15:47:47|3558|59:59|reload|State.pm:initialize(154)|returning 1
2014-08-08 15:47:47|3558|59:59|reload|vcld:make_new_child(568)|VCL::new
object created and initialized
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 59
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer vm0402 from the database
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer vm0402 from the database: available
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{59}{computer}{state}{name}, data
identifier: computer_state_name, data:
|3558|59:59|reload| : "available"
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:is_inblockrequest(5760)|zero rows were
returned from database select
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer vm0402 from the database
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer vm0402 from the database: available
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{59}{computer}{state}{name}, data
identifier: computer_state_name, data:
|3558|59:59|reload| : "available"
2014-08-08
15:47:47|3558|59:59|reload|new.pm:computer_not_being_used(742)|retrieving
info for reservations assigned to vm0402
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:get_connect_method_info(10059)|attempting
to retrieve connect method info:
|3558|59:59|reload| imagerevision: 18 - vmwarewin7-noclean19-v0
|3558|59:59|reload| OS: 35 - vmwarewin7
|3558|59:59|reload| OS type: 1 - windows
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:get_connect_method_info(10123)|RDP:
connectmethodid=2, OStypeid=1, OSid=NULL, imagerevisionid=NULL, disabled=0
2014-08-08 15:47:47|3558|59:59|reload|utils.pm:get_user_info(7540)|UID
value is not configured for user vclreload, setting UID to VCL user ID:
vclreload, standalone: 1
2014-08-08 15:47:47|3558|59:59|reload|utils.pm:get_user_info(7540)|UID
value is not configured for user vclreload, setting UID to VCL user ID:
vclreload, standalone: 1
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:get_request_by_computerid(5991)|retrieved
info and DataStructure object for 59:59
2014-08-08
15:47:47|3558|59:59|reload|new.pm:computer_not_being_used(755)|vm0402 is
not assigned to any other reservations
2014-08-08 15:47:47|3558|59:59|reload|new.pm:process(127)|vm0402 is not
being used
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer vm0402 from the database
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer vm0402 from the database: available
2014-08-08
15:47:47|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{59}{computer}{state}{name}, data
identifier: computer_state_name, data:
|3558|59:59|reload| : "available"
2014-08-08 15:47:47|3558|59:59|reload|new.pm:reload_image(511)|calling
VCL::Module::Provisioning::VMware::VMware->node_status()
2014-08-08
15:47:47|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, statuscheck, checking status of node
2014-08-08
15:47:47|3558|59:59|reload|VMware.pm:node_status(1152)|attempting to check
the status of computer vm0402, image: vmwarewin7-noclean19-v0
2014-08-08 15:47:48|3558|59:59|reload|OS.pm:is_ssh_responding(653)|vm0402
is NOT responding to SSH, ports 22 or 24 are both closed
2014-08-08 15:47:48|3558|59:59|reload|VMware.pm:node_status(1189)|VM
vm0402 is not responding to SSH, returning 'RELOAD'
2014-08-08 15:47:48|3558|59:59|reload|new.pm:reload_image(526)|node_status
returned a hash reference
2014-08-08 15:47:48|3558|59:59|reload|new.pm:reload_image(531)|node_status
hash reference contains key {status}=RELOAD
2014-08-08 15:47:48|3558|59:59|reload|new.pm:reload_image(608)|node status
is RELOAD, vm0402 will be reloaded
2014-08-08
15:47:48|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, loadimageblade, vm0402 must be reloaded with
vmwarewin7-noclean19-v0
2014-08-08 15:47:48|3558|59:59|reload|new.pm:reload_image(622)|calling
VCL::Module::Provisioning::VMware::VMware->does_image_exist()
2014-08-08
15:47:48|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:48|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
/vmfs/volumes/nfs\-datastore/vmwarewin7\-noclean19\-v0/vmwarewin7\-noclean19\-v0\.vmdk'
2>&1
2014-08-08
15:47:48|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File:
/vmfs/volumes/nfs-datastore/vmwarewin7-noclean19-v0/vmwarewin7-noclean19-v0.vmdk
|3558|59:59|reload| Size: 559 Blocks: 8 IO Block: 131072 regular file
|3558|59:59|reload| Device: b8af75691ac4ade4h/13307984518184218084d Inode:
154779651 Links: 1
|3558|59:59|reload| Access: (0600/-rw-------) Uid: ( 0/ root) Gid: ( 0/
root)
|3558|59:59|reload| Access: 2014-08-08 18:49:03.000000000
|3558|59:59|reload| Modify: 2014-08-08 18:49:03.000000000
|3558|59:59|reload| Change: 2014-08-08 18:49:03.000000000
2014-08-08 15:47:48|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
/vmfs/volumes/nfs-datast...")
2014-08-08
15:47:48|3558|59:59|reload|Linux.pm:file_exists(1449)|'/vmfs/volumes/nfs-datastore/vmwarewin7-noclean19-v0/vmwarewin7-noclean19-v0.vmdk'
exists on node4-vcl, files: 1, directories: 0, links: 0
2014-08-08
15:47:48|3558|59:59|reload|VMware.pm:does_image_exist(4591)|image exists
in the shared directory on the VM host:
/vmfs/volumes/nfs-datastore/vmwarewin7-noclean19-v0/vmwarewin7-noclean19-v0.vmdk
2014-08-08
15:47:48|3558|59:59|reload|new.pm:reload_image(625)|vmwarewin7-noclean19-v0
exists on this management node
2014-08-08
15:47:48|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, doesimageexists, confirmed image exists
2014-08-08
15:47:48|3558|59:59|reload|utils.pm:update_computer_state(1587)|computer 3
state updated to: reloading
2014-08-08 15:47:48|3558|59:59|reload|new.pm:reload_image(658)|computer
vm0402 state set to reloading
2014-08-08
15:47:48|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, info, computer state updated to reloading
2014-08-08 15:47:48|3558|59:59|reload|new.pm:reload_image(669)|calling
VCL::Module::Provisioning::VMware::VMware->load() subroutine
2014-08-08
15:47:49|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, info, calling
VCL::Module::Provisioning::VMware::VMware->load() subroutine
2014-08-08
15:47:49|3558|59:59|reload|VMware.pm:get_vmx_base_directory_path(3094)|determined
vmx base directory path: /vmfs/volumes/datastore1
2014-08-08
15:47:49|3558|59:59|reload|VMware.pm:get_vmx_file_path(3034)|determined
vmx file path: /vmfs/volumes/datastore1/vm0402_19-v0/vm0402_19-v0.vmx
2014-08-08
15:47:49|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, doesimageexists, image exists vmwarewin7-noclean19-v0
2014-08-08
15:47:49|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, startload, vm0402 vmwarewin7-noclean19-v0
2014-08-08
15:47:49|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:49|3558|59:59|reload|VMware.pm:get_vmx_file_paths(5237)|attempting
to find existing vmx files on the VM host
2014-08-08 15:47:49|3558|59:59|reload|OS.pm:find_files(2917)|attempting to
find files on node4-vcl, base directory path: '/vmfs/volumes/datastore1/',
pattern: *.vmx, command: /usr/bin/find "/vmfs/volumes/datastore1/" -type f
-iname "*.vmx"
2014-08-08 15:47:49|3558|59:59|reload|OS.pm:find_files(2945)|files found:
0, base directory: '/vmfs/volumes/datastore1/', pattern: '*.vmx'
|3558|59:59|reload| command: '/usr/bin/find "/vmfs/volumes/datastore1/"
-type f -iname "*.vmx"'
2014-08-08
15:47:49|3558|59:59|reload|VMware.pm:get_vmx_file_paths(5243)|found 0 vmx
files under /vmfs/volumes/datastore1
2014-08-08
15:47:50|3558|59:59|reload|VIM_SSH.pm:_run_vim_cmd(210)|executed command
on VM host node4-vcl: vim-cmd vmsvc/getallvms
2014-08-08
15:47:50|3558|59:59|reload|VIM_SSH.pm:get_registered_vms(837)|found 0
registered VMs
2014-08-08
15:47:50|3558|59:59|reload|VMware.pm:get_vmx_file_paths(5247)|found 0
registered vmx files
2014-08-08
15:47:50|3558|59:59|reload|VMware.pm:get_vmx_file_paths(5252)|found 0 vmx
files on VM host
2014-08-08 15:47:50|3558|59:59|reload|OS.pm:find_files(2917)|attempting to
find files on node4-vcl, base directory path: '/vmfs/volumes/datastore1/',
pattern: *vm0402*.vmx, command: /usr/bin/find "/vmfs/volumes/datastore1/"
-type f -iname "*vm0402*.vmx"
2014-08-08 15:47:50|3558|59:59|reload|OS.pm:find_files(2945)|files found:
0, base directory: '/vmfs/volumes/datastore1/', pattern: '*vm0402*.vmx'
|3558|59:59|reload| command: '/usr/bin/find "/vmfs/volumes/datastore1/"
-type f -iname "*vm0402*.vmx"'
2014-08-08 15:47:51|3558|59:59|reload|OS.pm:is_ssh_responding(653)|vm0402
is NOT responding to SSH, ports 22 or 24 are both closed
2014-08-08
15:47:51|3558|59:59|reload|utils.pm:update_computer_imagename(5633)|successfully
retreived image info for noimage
2014-08-08
15:47:51|3558|59:59|reload|utils.pm:update_currentimage(5685)|updating
computer 3: image=1, imagerevision=1
2014-08-08
15:47:51|3558|59:59|reload|utils.pm:update_currentimage(5715)|updated
currentimageid and imagerevision id for computer id 3
2014-08-08
15:47:51|3558|59:59|reload|utils.pm:update_computer_imagename(5645)|successfully
updated computerid= 3 image_id= 1 imagerevision_id= 1
2014-08-08
15:47:51|3558|59:59|reload|VMware.pm:remove_existing_vms(1635)|set
computer vm0402 current image to 'noimage'
2014-08-08
15:47:51|3558|59:59|reload|VMware.pm:check_vmhost_disk_space(2376)|checking
if enough space is available on VM host node4-vcl
2014-08-08
15:47:51|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:51|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
-f "/vmfs/volumes/datastore1"' 2>&1
2014-08-08
15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: "/vmfs/volumes/datastore1"
|3558|59:59|reload| ID: d5a1049e464bb5dc Namelen: 127 Type: vmfs
|3558|59:59|reload| Block size: 1048576
|3558|59:59|reload| Blocks: Total: 139776 Free: 138804 Available:
138804
|3558|59:59|reload| Inodes: Total: 2147483647 Free: 2147483647
2014-08-08 15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
"/vmfs/volumes/datastore...")
2014-08-08 15:47:52|3558|59:59|reload|Linux.pm:get_total_space(1773)|total
size of volume on node4-vcl containing '/vmfs/volumes/datastore1':
146,565,758,976 bytes - 143,130,624.0 KB - 139,776.0 MB - 136.50 GB
2014-08-08
15:47:52|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
-f "/vmfs/volumes/nfs-datastore"' 2>&1
2014-08-08
15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: "/vmfs/volumes/nfs-datastore"
|3558|59:59|reload| ID: 1ac4ade4b8af7569 Namelen: 127 Type: nfs
|3558|59:59|reload| Block size: 4096
|3558|59:59|reload| Blocks: Total: 999091486 Free: 629779051 Available:
579034117
|3558|59:59|reload| Inodes: Total: 507510784 Free: 507510637
2014-08-08 15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
"/vmfs/volumes/nfs-datas...")
2014-08-08 15:47:52|3558|59:59|reload|Linux.pm:get_total_space(1773)|total
size of volume on node4-vcl containing '/vmfs/volumes/nfs-datastore':
4,092,278,726,656 bytes - 3,996,365,944.0 KB - 3,902,701.1 MB - 3,811.23
GB - 3.72 TB
2014-08-08
15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
-f "/vmfs/volumes/datastore1"' 2>&1
2014-08-08
15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: "/vmfs/volumes/datastore1"
|3558|59:59|reload| ID: d5a1049e464bb5dc Namelen: 127 Type: vmfs
|3558|59:59|reload| Block size: 1048576
|3558|59:59|reload| Blocks: Total: 139776 Free: 138804 Available:
138804
|3558|59:59|reload| Inodes: Total: 2147483647 Free: 2147483647
2014-08-08 15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
"/vmfs/volumes/datastore...")
2014-08-08
15:47:52|3558|59:59|reload|Linux.pm:get_available_space(1702)|space
available on volume on node4-vcl containing '/vmfs/volumes/datastore1':
145,546,543,104 bytes - 142,135,296.0 KB - 138,804.0 MB - 135.55 GB
2014-08-08
15:47:52|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
-f "/vmfs/volumes/nfs-datastore"' 2>&1
2014-08-08
15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: "/vmfs/volumes/nfs-datastore"
|3558|59:59|reload| ID: 1ac4ade4b8af7569 Namelen: 127 Type: nfs
|3558|59:59|reload| Block size: 4096
|3558|59:59|reload| Blocks: Total: 999091486 Free: 629779051 Available:
579034117
|3558|59:59|reload| Inodes: Total: 507510784 Free: 507510637
2014-08-08 15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
"/vmfs/volumes/nfs-datas...")
2014-08-08
15:47:53|3558|59:59|reload|Linux.pm:get_available_space(1702)|space
available on volume on node4-vcl containing '/vmfs/volumes/nfs-datastore':
2,371,723,743,232 bytes - 2,316,136,468.0 KB - 2,261,852.0 MB - 2,208.84
GB - 2.16 TB
2014-08-08
15:47:53|3558|59:59|reload|VMware.pm:is_vmx_vmdk_volume_shared(2292)|checking
if vmx and vmdk base directory paths appear to be on the same volume:
|3558|59:59|reload| vmx base directory path: '/vmfs/volumes/datastore1'
|3558|59:59|reload| vmdk base directory path:
'/vmfs/volumes/nfs-datastore'
|3558|59:59|reload| vmx volume total space: 146,565,758,976 bytes -
143,130,624.0 KB - 139,776.0 MB - 136.50 GB
|3558|59:59|reload| vmdk volume total space: 4,092,278,726,656 bytes -
3,996,365,944.0 KB - 3,902,701.1 MB - 3,811.23 GB - 3.72 TB
|3558|59:59|reload| vmx volume available space: 145,546,543,104 bytes -
142,135,296.0 KB - 138,804.0 MB - 135.55 GB
|3558|59:59|reload| vmdk volume available space: 2,371,723,743,232 bytes -
2,316,136,468.0 KB - 2,261,852.0 MB - 2,208.84 GB - 2.16 TB
2014-08-08
15:47:53|3558|59:59|reload|VMware.pm:is_vmx_vmdk_volume_shared(2305)|vmx
and vmdk base directory paths do not appear to be on the same volume based
on the total and available space
2014-08-08
15:47:53|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
-f "/vmfs/volumes/datastore1"' 2>&1
2014-08-08
15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File: "/vmfs/volumes/datastore1"
|3558|59:59|reload| ID: d5a1049e464bb5dc Namelen: 127 Type: vmfs
|3558|59:59|reload| Block size: 1048576
|3558|59:59|reload| Blocks: Total: 139776 Free: 138804 Available:
138804
|3558|59:59|reload| Inodes: Total: 2147483647 Free: 2147483647
2014-08-08 15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
"/vmfs/volumes/datastore...")
2014-08-08
15:47:53|3558|59:59|reload|Linux.pm:get_available_space(1702)|space
available on volume on node4-vcl containing '/vmfs/volumes/datastore1':
145,546,543,104 bytes - 142,135,296.0 KB - 138,804.0 MB - 135.55 GB
2014-08-08
15:47:53|3558|59:59|reload|VMware.pm:get_vm_os_configuration(4895)|returning
matching 'win7-x86_64' OS configuration: vmwarewin7, image architecture:
x86_64
|3558|59:59|reload| : {
|3558|59:59|reload| : "cpu_socket_limit" => 2,
|3558|59:59|reload| : "ethernet-virtualDev" => "e1000",
|3558|59:59|reload| : "guestOS" => "windows7-64",
|3558|59:59|reload| : "memsize" => 2048,
|3558|59:59|reload| : "scsi-virtualDev" => "lsiLogic"
|3558|59:59|reload| : }
2014-08-08
15:47:53|3558|59:59|reload|VMware.pm:get_vm_additional_vmx_bytes_required(5721)|4294967296
additional bytes required for VM vmem file
2014-08-08
15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
/vmfs/volumes/datastore1/vm0402_19\-v0/vm0402_19\-v0\.vmx' 2>&1
2014-08-08 15:47:53|30305|vcld:main(167)|lastcheckin time updated for
management node 1: 2014-08-08 15:47:53
2014-08-08
15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| stat: can't stat
'/vmfs/volumes/datastore1/vm0402_19-v0/vm0402_19-v0.vmx': No such file or
directory
2014-08-08 15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(5030)|SSH
command executed on node4-vcl, command:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
/vmfs/volumes/datastore1/vm0402_19\-v0/vm0402_19\-v0\.vmx' 2>&1
|3558|59:59|reload| returning (1, "stat: can't stat '/vmfs/volume...")
2014-08-08
15:47:53|3558|59:59|reload|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: nfs-datastore
2014-08-08
15:47:53|3558|59:59|reload|utils.pm:run_ssh_command(4902)|executing SSH
command on node4-vcl:
|3558|59:59|reload| /usr/bin/ssh -i /etc/vcl/vcl.key -o
StrictHostKeyChecking=no -o UserKnownHostsFile=/dev/null -o
ConnectionAttempts=1 -o ConnectTimeout=3 -l root -p 22 -x node4-vcl 'stat
/vmfs/volumes/nfs\-datastore/vmwarewin7\-noclean19\-v0/vmwarewin7\-noclean19\-v0\.vmdk'
2>&1
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:run_ssh_command(5020)|run_ssh_command
output:
|3558|59:59|reload| File:
/vmfs/volumes/nfs-datastore/vmwarewin7-noclean19-v0/vmwarewin7-noclean19-v0.vmdk
|3558|59:59|reload| Size: 559 Blocks: 8 IO Block: 131072 regular file
|3558|59:59|reload| Device: b8af75691ac4ade4h/13307984518184218084d Inode:
154779651 Links: 1
|3558|59:59|reload| Access: (0600/-rw-------) Uid: ( 0/ root) Gid: ( 0/
root)
|3558|59:59|reload| Access: 2014-08-08 18:49:03.000000000
|3558|59:59|reload| Modify: 2014-08-08 18:49:03.000000000
|3558|59:59|reload| Change: 2014-08-08 18:49:03.000000000
2014-08-08 15:47:54|3558|59:59|reload|utils.pm:run_ssh_command(5034)|SSH
command executed on node4-vcl, returning (0, "File:
/vmfs/volumes/nfs-datast...")
2014-08-08
15:47:54|3558|59:59|reload|Linux.pm:file_exists(1449)|'/vmfs/volumes/nfs-datastore/vmwarewin7-noclean19-v0/vmwarewin7-noclean19-v0.vmdk'
exists on node4-vcl, files: 1, directories: 0, links: 0
|3558|59:59|reload| ---- WARNING ----
|3558|59:59|reload| 2014-08-08
15:47:54|3558|59:59|reload|VMware.pm:check_vmhost_disk_space(2393)|failed
to determine additional bytes required for the vmx and vmdk directories on
VM host node4-vcl
|3558|59:59|reload| ( 0) VMware.pm, check_vmhost_disk_space (line: 2393)
|3558|59:59|reload| (-1) VMware.pm, load (line: 475)
|3558|59:59|reload| (-2) new.pm, reload_image (line: 671)
|3558|59:59|reload| (-3) new.pm, process (line: 291)
|3558|59:59|reload| (-4) vcld, make_new_child (line: 571)
|3558|59:59|reload| (-5) vcld, main (line: 350)
|3558|59:59|reload| ---- WARNING ----
|3558|59:59|reload| 2014-08-08
15:47:54|3558|59:59|reload|VMware.pm:load(477)|failed to determine if
enough disk space is available on VM host node4-vcl
|3558|59:59|reload| ( 0) VMware.pm, load (line: 477)
|3558|59:59|reload| (-1) new.pm, reload_image (line: 671)
|3558|59:59|reload| (-2) new.pm, process (line: 291)
|3558|59:59|reload| (-3) vcld, make_new_child (line: 571)
|3558|59:59|reload| (-4) vcld, main (line: 350)
|3558|59:59|reload| ---- WARNING ----
|3558|59:59|reload| 2014-08-08
15:47:54|3558|59:59|reload|new.pm:reload_image(676)|vmwarewin7-noclean19-v0
failed to load on vm0402, returning
|3558|59:59|reload| ( 0) new.pm, reload_image (line: 676)
|3558|59:59|reload| (-1) new.pm, process (line: 291)
|3558|59:59|reload| (-2) vcld, make_new_child (line: 571)
|3558|59:59|reload| (-3) vcld, main (line: 350)
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, loadimagefailed, vmwarewin7-noclean19-v0 failed to load on
vm0402
|3558|59:59|reload| ---- WARNING ----
|3558|59:59|reload| 2014-08-08
15:47:54|3558|59:59|reload|new.pm:process(339)|failed to load vm0402 with
vmwarewin7-noclean19-v0
|3558|59:59|reload| ( 0) new.pm, process (line: 339)
|3558|59:59|reload| (-1) vcld, make_new_child (line: 571)
|3558|59:59|reload| (-2) vcld, main (line: 350)
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer vm0402 from the database
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer vm0402 from the database: reloading
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{59}{computer}{state}{name}, data
identifier: computer_state_name, data:
|3558|59:59|reload| : "reloading"
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:get_computer_private_ip_address(1641)|attempting
to retrieve private IP address for computer: vm0402
2014-08-08
15:47:54|3558|59:59|reload|OS.pm:get_file_contents(1897)|retrieved 77
lines from file on vcl: '/etc/hosts'
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:get_computer_private_ip_address(1697)|returning
IP address from /etc/hosts file: 172.20.101.42
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:is_inblockrequest(5760)|zero rows were
returned from database select
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:get_image_affiliation_name(2121)|image
owner id: 1
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:retrieve_user_data(1412)|attempting
to retrieve and store data for user: user.id = '1'
2014-08-08
15:47:54|3558|59:59|reload|DataStructure.pm:retrieve_user_data(1475)|data
has been retrieved for user: admin (id: 1)
2014-08-08 15:47:54|3558|59:59|reload|utils.pm:mail(1266)|SUCCESS --
Sending mail To: [email protected], PROBLEM --
vcl|59:59|reload|State.pm|vm0402>node4-vcl|vmwarewin7-noclean19-v0|vclreload
|3558|59:59|reload| ---- CRITICAL ----
|3558|59:59|reload| 2014-08-08
15:47:54|3558|59:59|reload|State.pm:reservation_failed(240)|reservation
failed on vm0402: process failed after trying to load or make available
|3558|59:59|reload| ( 0) State.pm, reservation_failed (line: 240)
|3558|59:59|reload| (-1) new.pm, process (line: 342)
|3558|59:59|reload| (-2) vcld, make_new_child (line: 571)
|3558|59:59|reload| (-3) vcld, main (line: 350)
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:insertloadlog(3665)|inserted
computer=3, failed, process failed after trying to load or make available
2014-08-08
15:47:54|3558|59:59|reload|State.pm:reservation_failed(243)|inserted
computerloadlog entry
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:update_computer_state(1587)|computer 3
state updated to: failed
2014-08-08
15:47:54|3558|59:59|reload|State.pm:reservation_failed(262)|computer
vm0402 (3) state set to failed
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:update_request_state(1545)|request 59
state updated to: failed, laststate to: reload
2014-08-08 15:47:54|3558|59:59|reload|State.pm:reservation_failed(275)|set
request state to 'failed'/'reload'
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:is_inblockrequest(5760)|zero rows were
returned from database select
2014-08-08
15:47:54|3558|59:59|reload|State.pm:reservation_failed(293)|vm0402 is NOT
in blockcomputers table
2014-08-08
15:47:54|3558|59:59|reload|State.pm:reservation_failed(296)|exiting 1
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:delete_computerloadlog_reservation(6396)|removing
computerloadlog entries matching loadstate = begin
2014-08-08
15:47:54|3558|59:59|reload|utils.pm:delete_computerloadlog_reservation(6443)|deleted
rows from computerloadlog for reservation id=59
2014-08-08 15:47:54|3558|59:59|reload|State.pm:DESTROY(929)|VCL::new
process duration: 11 seconds
2014-08-08 15:47:54|3558|59:59|reload|VIM_SSH.pm:DESTROY(2125)|vim-cmd
call count: 2
2014-08-08 15:47:54|30305|vcld:REAPER(721)|VCL process exited for
reservation 59, PID: 3558, signal: CHLD
2014-08-08 15:47:54|30305|vcld:main(167)|lastcheckin time updated for
management node 1: 2014-08-08 15:47:54
2014-08-08 15:47:54|30305|59:59|failed|vcld:main(256)|request deleted
From: Andy Kurth <[email protected]>
To: [email protected],
Date: 08/08/2014 02:48 PM
Subject: Re: First Base image on new VCL won't load after capture
I can't tell from the output if it's failing to determine vmx or vmdk
space. It would be helpful if you change VMware.pm line 2393 to try to
output the values it is checking, change it to:
notify($ERRORS{'WARNING'}, 0, "failed to determine additional bytes
required for the vmx and vmdk directories on VM host $vmhost_name, vmx:
$vmx_additional_bytes_required, vmdk: $vmdk_additional_bytes_required");
This will generate an ugly "failed to concatenate an undefined variable"
warning in vcld.log but at least we will be able to tell which value it is
failing to retrieve, $vmx_additional_bytes_required or
$vmdk_additional_bytes_required.
Also, please include the entire vcld.log output for the entire process.
Some information may have been retrieved earlier on in the execution
which could be helpful for debugging.
-Andy
On Fri, Aug 8, 2014 at 11:33 AM, Jeffrey Kirby <[email protected]>
wrote:
I've now also added an ESXi 5.1 host and it can't load to that, either,
same error.
Running vcld with the switch -d doesn't seem to add any debug info to the
log. Am I missing something?
From: Jeffrey Kirby <[email protected]>
To: [email protected],
Date: 08/06/2014 02:07 PM
Subject: First Base image on new VCL won't load after capture
I am trying to deploy a new VCL instance. I'm at the point where I have
captured a windows 8.1 image (64-bit, 64-bit cygwin; I altered Windows.pm
to correct the location of Sysnative as system32). The problem I'm
experiencing is that on redeploy at the end of the capture it errored out
with not being able to determine additional bytes required for the vmx and
vmdk directories on VM host. I can recreate the issue without capturing
by just requesting an image reload through Manage Computers > Computer
Utilities.
