My guess is I don't have something configured correctly in VM Host Profile, but
I don't know what it is.
2015-04-24 17:32:32|22064|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-04-24 17:32:32
2015-04-24 21:32:32|22064|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-04-24 21:32:32
2015-04-25 03:32:32|22064|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-04-25 03:32:32
2015-04-25 07:32:32|22064|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-04-25 07:32:32
2015-04-27 09:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-27 09:32:32
2015-04-27 12:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-27 12:32:32
2015-04-27 14:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-27 14:32:32
2015-04-27 16:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-27 16:32:32
2015-04-27 22:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-27 22:32:32
2015-04-28 03:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-28 03:32:32
2015-04-28 16:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-28 16:32:32
2015-04-28 19:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-28 19:32:32
2015-04-29 00:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-29 00:32:32
2015-04-29 05:32:32|2329|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-29 05:32:32
2015-04-29 17:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-29 17:32:32
2015-04-29 21:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-29 21:32:32
2015-04-30 02:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-30 02:32:32
2015-04-30 10:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-30 10:32:32
2015-04-30 12:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-04-30 12:32:32
2015-04-30 12:32:32|2326|12:12|new|utils.pm:check_time(1103)|reservation will
start in 25-35 minutes (27)
2015-04-30 12:32:32|2326|12:12|new|vcld:main(268)|preload request has already
been processed
2015-04-30 12:32:32|2326|14:14|new|utils.pm:check_time(1103)|reservation will
start in 25-35 minutes (27)
2015-04-30 12:32:32|2326|14:14|new|vcld:main(268)|preload request has already
been processed
2015-05-01 01:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 01:32:32
2015-05-01 07:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 07:32:32
2015-05-01 09:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 09:32:32
2015-05-01 11:32:32|2326|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 11:32:32
2015-05-01 15:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 15:32:32
2015-05-01 20:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 20:32:32
2015-05-01 22:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-01 22:32:32
2015-05-02 02:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-02 02:32:32
2015-05-03
09:29:33|2327|32:32|new|utils.pm:reservation_being_processed(8634)|computerloadlog
'begin' entry does NOT exist for reservation 32
2015-05-03 09:29:33|2327|32:32|new|utils.pm:run_command(8706)|executed command:
pgrep -fl 'vcld [0-9]+:32 ', pid: 8382, exit status: 1, output:
2015-05-03
09:29:33|2327|32:32|new|utils.pm:is_management_node_process_running(8939)|process
is NOT running, identifier: 'vcld [0-9]+:32 '
2015-05-03
09:29:33|2327|32:32|new|utils.pm:reservation_being_processed(8655)|reservation
is NOT currently being processed
2015-05-03 09:29:33|2327|32:32|new|vcld:main(282)|reservation 32 is NOT already
being processed
2015-05-03
09:29:33|2327|32:32|new|utils.pm:get_management_node_info(5456)|retrieving
current management node info for 'localhost' from database, cached data is
stale: 899 seconds old
2015-05-03
09:29:33|2327|32:32|new|utils.pm:get_management_node_info(5603)|retrieved
management node info: 'localhost' (localhost)
|2327|32:32|new| ---- WARNING ----
|2327|32:32|new| 2015-05-03
09:29:33|2327|32:32|new|utils.pm:get_imagerevision_info(4438)|imagerevision
'xenserverlinux-xen3test89-v0' was not found in the database, 0 rows were
returned from database select statement:
|2327|32:32|new| SELECT
|2327|32:32|new| imagerevision.*
|2327|32:32|new| FROM
|2327|32:32|new| imagerevision
|2327|32:32|new| WHERE
|2327|32:32|new| imagerevision.imagename = 'xenserverlinux-xen3test89-v0'
|2327|32:32|new| ( 0) utils.pm, get_imagerevision_info (line: 4438)
|2327|32:32|new| (-1) utils.pm, get_computer_info (line: 7895)
|2327|32:32|new| (-2) utils.pm, get_request_info (line: 4014)
|2327|32:32|new| (-3) vcld, main (line: 286)
|2327|32:32|new| ---- WARNING ----
|2327|32:32|new| 2015-05-03
09:29:33|2327|32:32|new|utils.pm:get_computer_info(7901)|failed to retrieve
nextimage info for xen3cent6vclw2, nextimageid=9
next_image_name=xenserverlinux-xen3test89-v0
|2327|32:32|new| ( 0) utils.pm, get_computer_info (line: 7901)
|2327|32:32|new| (-1) utils.pm, get_request_info (line: 4014)
|2327|32:32|new| (-2) vcld, main (line: 286)
2015-05-03
09:29:33|2327|32:32|new|utils.pm:get_connect_method_info(10059)|attempting to
retrieve connect method info:
|2327|32:32|new| imagerevision: 9 - xenserverlinux-xen3test8-9-v0
|2327|32:32|new| OS: 45 - xenserverlinux
|2327|32:32|new| OS type: 2 - linux
2015-05-03 09:29:33|2327|32:32|new|utils.pm:get_connect_method_info(10123)|ssh:
connectmethodid=1, OStypeid=2, OSid=NULL, imagerevisionid=NULL, disabled=0
2015-05-03 09:29:33|2327|32:32|new|vcld:main(287)|retrieved request information
from database
2015-05-03
09:29:33|2327|32:32|new|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-03 09:29:33|2327|32:32|new|utils.pm:update_request_state(1545)|request
32 state updated to: pending, laststate to: new
2015-05-03 09:29:33|2327|32:32|new|utils.pm:insertloadlog(3665)|inserted
computer=4, begin, beginning to process, state is new
2015-05-03 09:29:33|2327|32:32|new|vcld:make_new_child(518)|loaded VCL::new
module
2015-05-03 09:29:33|2327|32:32|new|vcld:make_new_child(542)|current number of
forked kids: 1
2015-05-03 09:29:33|8400|32:32|new|vcld:make_new_child(558)|vcld environment
variable set to 0 for this process
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(643)|image ID
argument was specified: noimage, DataStructure object will contain image
information for the production imagerevision of this image
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_mn_os_object(376)|VCL::Module::OS::Linux::ManagementNode
module loaded
2015-05-03
09:29:33|8400|32:32|new|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode
object created for image noimage, address: 3eb78f8
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{hostname}, data identifier:
computer_hostname, data:
|8400|32:32|new| : "localhost"
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{NODENAME}, data identifier:
computer_node_name, data:
|8400|32:32|new| : "localhost"
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{SHORTNAME}, data identifier:
computer_short_name, data:
|8400|32:32|new| : "localhost"
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{IPaddress}, data identifier:
computer_ip_address, data:
|8400|32:32|new| : "131.247.30.237"
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_mn_os_object(381)|VCL::Module::OS::Linux::ManagementNode
OS object created, address: 3eb78f8
2015-05-03 09:29:33|8400|32:32|new|Module.pm:new(192)|VCL::new object created
for state new, address: 3940350
2015-05-03 09:29:33|8400|32:32|new|State.pm:initialize(88)|obtained a database
handle for this state process, stored as $ENV{dbh}
2015-05-03 09:29:33|8400|32:32|new|State.pm:check_image_os(771)|no corrections
need to be made, not an imaging request, returning 1
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-03
09:29:33|8400|32:32|new|utils.pm:rename_vcld_process(6752)|reservation count: 1
2015-05-03
09:29:33|8400|32:32|new|utils.pm:rename_vcld_process(6771)|PARENTIMAGE: 1
2015-05-03 09:29:33|8400|32:32|new|utils.pm:rename_vcld_process(6772)|SUBIMAGE: 0
2015-05-03 09:29:33|8400|32:32|new|utils.pm:rename_vcld_process(6790)|renamed
process to 'vcld 32:32 new xen3cent6vclw2>Xen3 xenserverlinux-xen3test8-9-v0
admin'
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_os_object(308)|VCL::Module::OS::Linux
module loaded
2015-05-03 09:29:33|8400|32:32|new|Module.pm:new(196)|VCL::Module::OS::Linux
object created for image xenserverlinux-xen3test8-9-v0, address: 3ebaf38
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_os_object(314)|VCL::Module::OS::Linux
OS object created, address: 3ebaf38
2015-05-03 09:29:33|8400|32:32|new|State.pm:initialize(125)|computer is a VM,
attempting to create VM host OS object
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(619)|computer
ID argument was specified, retrieving data for computer ID: 1
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image information
for the production imagerevision of this image
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(674)|retrieved
data for imagerevision ID: 1
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_initialize(690)|retrieved
data for image ID: 1
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_vmhost_os_object(454)|attempting to
load VM host OS module: VCL::Module::OS::Linux::UnixLab (image: 1)
2015-05-03 09:29:33|8400|32:32|new|Module.pm:create_vmhost_os_object(460)|VM
host OS module loaded: VCL::Module::OS::Linux::UnixLab
2015-05-03
09:29:33|8400|32:32|new|Module.pm:new(196)|VCL::Module::OS::Linux::UnixLab
object created for image noimage, address: 3ebb1a8
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_vmhost_os_object(465)|VCL::Module::OS::Linux::UnixLab
OS object created, address: 3ebb1a8
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_provisioning_object(519)|VCL::Module::Provisioning::XenServer
module loaded
2015-05-03
09:29:33|8400|32:32|new|Module.pm:new(200)|VCL::Module::Provisioning::XenServer
object created for computer xen3cent6vclw2, address: 3ebb550
2015-05-03 09:29:33|8400|32:32|new|utils.pm:run_ssh_command(4902)|executing SSH
command on Xen3:
|8400|32:32|new| /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 Xen3 'which xe' 2>&1
2015-05-03
09:29:33|8400|32:32|new|utils.pm:run_ssh_command(5020)|run_ssh_command output:
|8400|32:32|new| /opt/xensource/bin/xe
2015-05-03 09:29:33|8400|32:32|new|utils.pm:run_ssh_command(5034)|SSH command
executed on Xen3, returning (0, "/opt/xensource/bin/xe")
2015-05-03 09:29:33|8400|32:32|new|XenServer.pm:initialize(100)|verified 'xe'
command is available on Xen3
2015-05-03 09:29:33|8400|32:32|new|XenServer.pm:initialize(109)|XenServer
driver module successfully initialized to control Xen3
2015-05-03
09:29:33|8400|32:32|new|Module.pm:create_provisioning_object(525)|VCL::Module::Provisioning::XenServer
provisioner object created for xen3cent6vclw2, address: 3ebb550
2015-05-03 09:29:33|8400|32:32|new|State.pm:initialize(154)|returning 1
2015-05-03 09:29:33|8400|32:32|new|vcld:make_new_child(568)|VCL::new object
created and initialized
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer xen3cent6vclw2 from the database
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer xen3cent6vclw2 from the database: available
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{32}{computer}{state}{name}, data identifier:
computer_state_name, data:
|8400|32:32|new| : "available"
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer xen3cent6vclw2 from the database
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer xen3cent6vclw2 from the database: available
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{32}{computer}{state}{name}, data identifier:
computer_state_name, data:
|8400|32:32|new| : "available"
2015-05-03
09:29:33|8400|32:32|new|new.pm:computer_not_being_used(742)|retrieving info for
reservations assigned to xen3cent6vclw2
2015-05-03 09:29:33|8400|32:32|new|utils.pm:get_imagemeta_info(4576)|retrieved
imagemeta info:
|8400|32:32|new| : {
|8400|32:32|new| : "architecture" => "",
|8400|32:32|new| : "checkuser" => 1,
|8400|32:32|new| : "id" => 6,
|8400|32:32|new| : "postoption" => "",
|8400|32:32|new| : "rootaccess" => 1,
|8400|32:32|new| : "subimages" => 0,
|8400|32:32|new| : "sysprep" => 1,
|8400|32:32|new| : "usergroupid" => ""
|8400|32:32|new| : }
|8400|32:32|new| ---- WARNING ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_imagerevision_info(4438)|imagerevision
'xenserverlinux-xen3test89-v0' was not found in the database, 0 rows were
returned from database select statement:
|8400|32:32|new| SELECT
|8400|32:32|new| imagerevision.*
|8400|32:32|new| FROM
|8400|32:32|new| imagerevision
|8400|32:32|new| WHERE
|8400|32:32|new| imagerevision.imagename = 'xenserverlinux-xen3test89-v0'
|8400|32:32|new| ( 0) utils.pm, get_imagerevision_info (line: 4438)
|8400|32:32|new| (-1) utils.pm, get_computer_info (line: 7895)
|8400|32:32|new| (-2) utils.pm, get_request_info (line: 4014)
|8400|32:32|new| (-3) utils.pm, get_request_by_computerid (line: 5978)
|8400|32:32|new| (-4) new.pm, computer_not_being_used (line: 743)
|8400|32:32|new| (-5) new.pm, process (line: 127)
|8400|32:32|new| ---- WARNING ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_computer_info(7901)|failed to retrieve
nextimage info for xen3cent6vclw2, nextimageid=9
next_image_name=xenserverlinux-xen3test89-v0
|8400|32:32|new| ( 0) utils.pm, get_computer_info (line: 7901)
|8400|32:32|new| (-1) utils.pm, get_request_info (line: 4014)
|8400|32:32|new| (-2) utils.pm, get_request_by_computerid (line: 5978)
|8400|32:32|new| (-3) new.pm, computer_not_being_used (line: 743)
|8400|32:32|new| (-4) new.pm, process (line: 127)
|8400|32:32|new| (-5) vcld, make_new_child (line: 571)
2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_connect_method_info(10059)|attempting to
retrieve connect method info:
|8400|32:32|new| imagerevision: 7 - xenserverlinux-xen3test67-v0
|8400|32:32|new| OS: 45 - xenserverlinux
|8400|32:32|new| OS type: 2 - linux
2015-05-03 09:29:33|8400|32:32|new|utils.pm:get_connect_method_info(10123)|ssh:
connectmethodid=1, OStypeid=2, OSid=NULL, imagerevisionid=NULL, disabled=0
2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_request_by_computerid(5991)|retrieved info
and DataStructure object for 6:6
|8400|32:32|new| ---- WARNING ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_imagerevision_info(4438)|imagerevision
'xenserverlinux-xen3test89-v0' was not found in the database, 0 rows were
returned from database select statement:
|8400|32:32|new| SELECT
|8400|32:32|new| imagerevision.*
|8400|32:32|new| FROM
|8400|32:32|new| imagerevision
|8400|32:32|new| WHERE
|8400|32:32|new| imagerevision.imagename = 'xenserverlinux-xen3test89-v0'
|8400|32:32|new| ( 0) utils.pm, get_imagerevision_info (line: 4438)
|8400|32:32|new| (-1) utils.pm, get_computer_info (line: 7895)
|8400|32:32|new| (-2) utils.pm, get_request_info (line: 4014)
|8400|32:32|new| (-3) utils.pm, get_request_by_computerid (line: 5978)
|8400|32:32|new| (-4) new.pm, computer_not_being_used (line: 743)
|8400|32:32|new| (-5) new.pm, process (line: 127)
|8400|32:32|new| ---- WARNING ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_computer_info(7901)|failed to retrieve
nextimage info for xen3cent6vclw2, nextimageid=9
next_image_name=xenserverlinux-xen3test89-v0
|8400|32:32|new| ( 0) utils.pm, get_computer_info (line: 7901)
|8400|32:32|new| (-1) utils.pm, get_request_info (line: 4014)
|8400|32:32|new| (-2) utils.pm, get_request_by_computerid (line: 5978)
|8400|32:32|new| (-3) new.pm, computer_not_being_used (line: 743)
|8400|32:32|new| (-4) new.pm, process (line: 127)
|8400|32:32|new| (-5) vcld, make_new_child (line: 571)
2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_connect_method_info(10059)|attempting to
retrieve connect method info:
|8400|32:32|new| imagerevision: 9 - xenserverlinux-xen3test8-9-v0
|8400|32:32|new| OS: 45 - xenserverlinux
|8400|32:32|new| OS type: 2 - linux
2015-05-03 09:29:33|8400|32:32|new|utils.pm:get_connect_method_info(10123)|ssh:
connectmethodid=1, OStypeid=2, OSid=NULL, imagerevisionid=NULL, disabled=0
2015-05-03
09:29:33|8400|32:32|new|utils.pm:get_request_by_computerid(5991)|retrieved info
and DataStructure object for 32:32
2015-05-03 09:29:33|8400|32:32|new|new.pm:computer_not_being_used(779)|checking
reservation assigned to xen3cent6vclw2:
|8400|32:32|new| request:reservation ID: 6:6
|8400|32:32|new| request state: pending/image
|8400|32:32|new| request start time: 2015-04-30 10:47:19
|8400|32:32|new| request end time: 2015-04-30 11:47:19
|8400|32:32|new| ---- WARNING ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|new.pm:computer_not_being_used(783)|xen3cent6vclw2 is
NOT available, it is assigned to an existing imaging reservation:
|8400|32:32|new| request:reservation ID: 6:6
|8400|32:32|new| request state: pending/image
|8400|32:32|new| request start time: 2015-04-30 10:47:19
|8400|32:32|new| request end time: 2015-04-30 11:47:19
|8400|32:32|new| ( 0) new.pm, computer_not_being_used (line: 783)
|8400|32:32|new| (-1) new.pm, process (line: 127)
|8400|32:32|new| (-2) vcld, make_new_child (line: 571)
|8400|32:32|new| (-3) vcld, main (line: 350)
|8400|32:32|new| ---- WARNING ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|new.pm:process(243)|xen3cent6vclw2 is NOT available
|8400|32:32|new| ( 0) new.pm, process (line: 243)
|8400|32:32|new| (-1) vcld, make_new_child (line: 571)
|8400|32:32|new| (-2) vcld, main (line: 350)
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_state_name(2436)|attempting
to retrieve current state of computer xen3cent6vclw2 from the database
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_state_name(2467)|retrieved
current state of computer xen3cent6vclw2 from the database: available
2015-05-03 09:29:33|8400|32:32|new|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{32}{computer}{state}{name}, data identifier:
computer_state_name, data:
|8400|32:32|new| : "available"
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_private_ip_address(1641)|attempting
to retrieve private IP address for computer: xen3cent6vclw2
2015-05-03 09:29:33|8400|32:32|new|OS.pm:get_file_contents(1897)|retrieved 12
lines from file on localhost: '/etc/hosts'
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_computer_private_ip_address(1697)|returning
IP address from /etc/hosts file: 192.168.10.53
2015-05-03 09:29:33|8400|32:32|new|utils.pm:is_inblockrequest(5760)|zero rows
were returned from database select
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:get_image_affiliation_name(2121)|image
owner id: 1
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:retrieve_user_data(1412)|attempting to
retrieve and store data for user: user.id = '1'
2015-05-03
09:29:33|8400|32:32|new|DataStructure.pm:retrieve_user_data(1475)|data has been
retrieved for user: admin (id: 1)
2015-05-03 09:29:33|8400|32:32|new|utils.pm:mail(1253)|SUCCESS -- Sending mail
To: [email protected], PROBLEM --
localhost|32:32|new|State.pm|xen3cent6vclw2>Xen3|xenserverlinux-xen3test8-9-v0|admin
|8400|32:32|new| ---- CRITICAL ----
|8400|32:32|new| 2015-05-03
09:29:33|8400|32:32|new|State.pm:reservation_failed(240)|reservation failed on
xen3cent6vclw2: process failed because computer is not available
|8400|32:32|new| ( 0) State.pm, reservation_failed (line: 240)
|8400|32:32|new| (-1) new.pm, process (line: 246)
|8400|32:32|new| (-2) vcld, make_new_child (line: 571)
|8400|32:32|new| (-3) vcld, main (line: 350)
2015-05-03 09:29:33|8400|32:32|new|utils.pm:insertloadlog(3665)|inserted
computer=4, failed, process failed because computer is not available
2015-05-03 09:29:33|8400|32:32|new|State.pm:reservation_failed(243)|inserted
computerloadlog entry
2015-05-03 09:29:33|8400|32:32|new|State.pm:reservation_failed(251)|updated log
ending value to 'failed', logid=28
2015-05-03
09:29:33|8400|32:32|new|utils.pm:update_computer_state(1587)|computer 4 state
updated to: failed
2015-05-03 09:29:33|8400|32:32|new|State.pm:reservation_failed(262)|computer
xen3cent6vclw2 (4) state set to failed
2015-05-03 09:29:33|8400|32:32|new|utils.pm:update_request_state(1545)|request
32 state updated to: failed, laststate to: new
2015-05-03 09:29:33|8400|32:32|new|State.pm:reservation_failed(275)|set request
state to 'failed'/'new'
2015-05-03 09:29:33|8400|32:32|new|utils.pm:is_inblockrequest(5760)|zero rows
were returned from database select
2015-05-03
09:29:33|8400|32:32|new|State.pm:reservation_failed(293)|xen3cent6vclw2 is NOT
in blockcomputers table
2015-05-03 09:29:33|8400|32:32|new|State.pm:reservation_failed(296)|exiting 1
2015-05-03
09:29:33|8400|32:32|new|utils.pm:delete_computerloadlog_reservation(6396)|removing
computerloadlog entries matching loadstate = begin
2015-05-03
09:29:33|8400|32:32|new|utils.pm:delete_computerloadlog_reservation(6443)|deleted
rows from computerloadlog for reservation id=32
2015-05-03 09:29:33|8400|32:32|new|State.pm:DESTROY(929)|VCL::new process
duration: 0 seconds
2015-05-03 10:00:34|2327|32:32|failed|utils.pm:check_time(1163)|reservation end
time was in the past (-1)
2015-05-03 10:00:34|2327|32:32|failed|vcld:main(256)|request deleted
2015-05-03 19:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-03 19:32:32
2015-05-04 02:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-04 02:32:32
2015-05-04 07:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-04 07:32:32
2015-05-04 11:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-04 11:32:32
2015-05-04 17:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-04 17:32:32
2015-05-04 22:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-04 22:32:32
2015-05-05 00:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-05 00:32:32
2015-05-05 11:32:32|2327|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-05 11:32:32
2015-05-05 16:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-05 16:32:32
2015-05-05 19:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-05 19:32:32
2015-05-06 00:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-06 00:32:32
2015-05-06 03:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-06 03:32:32
2015-05-06 08:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-06 08:32:32
2015-05-06 13:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-06 13:32:32
2015-05-06 16:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-06 16:32:32
2015-05-06 19:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-06 19:32:32
2015-05-07 03:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-07 03:32:32
2015-05-07 06:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-07 06:32:32
2015-05-07
07:32:32|7355|9:9|reserved|DataStructure.pm:get_reservation_remote_ip(1152)|reservation
remote IP is not defined
2015-05-07 09:32:32|2325|vcld:main(167)|lastcheckin time updated for management
node 1: 2015-05-07 09:32:32
2015-05-07 17:32:32|26123|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-05-07 17:32:32
2015-05-07 22:32:32|26123|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-05-07 22:32:32
2015-05-08 03:32:32|26123|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-05-08 03:32:32
2015-05-08 08:32:32|26123|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-05-08 08:32:32
2015-05-08 12:32:32|26123|vcld:main(167)|lastcheckin time updated for
management node 1: 2015-05-08 12:32:32
2015-05-08
14:54:19|26123|32:32|image|utils.pm:reservation_being_processed(8634)|computerloadlog
'begin' entry does NOT exist for reservation 32
2015-05-08 14:54:19|26123|32:32|image|utils.pm:run_command(8706)|executed
command: pgrep -fl 'vcld [0-9]+:32 ', pid: 1929, exit status: 1, output:
2015-05-08
14:54:19|26123|32:32|image|utils.pm:is_management_node_process_running(8939)|process
is NOT running, identifier: 'vcld [0-9]+:32 '
2015-05-08
14:54:19|26123|32:32|image|utils.pm:reservation_being_processed(8655)|reservation
is NOT currently being processed
2015-05-08 14:54:19|26123|32:32|image|vcld:main(282)|reservation 32 is NOT
already being processed
2015-05-08
14:54:19|26123|32:32|image|utils.pm:get_imagemeta_info(4576)|retrieved
imagemeta info:
|26123|32:32|image| : {
|26123|32:32|image| : "architecture" => "",
|26123|32:32|image| : "checkuser" => 1,
|26123|32:32|image| : "id" => 28,
|26123|32:32|image| : "postoption" => "",
|26123|32:32|image| : "rootaccess" => 1,
|26123|32:32|image| : "subimages" => 0,
|26123|32:32|image| : "sysprep" => 1,
|26123|32:32|image| : "usergroupid" => ""
|26123|32:32|image| : }
2015-05-08
14:54:19|26123|32:32|image|utils.pm:get_management_node_info(5456)|retrieving
current management node info for 'localhost' from database, cached data is
stale: 178 seconds old
2015-05-08
14:54:19|26123|32:32|image|utils.pm:get_management_node_info(5603)|retrieved
management node info: 'localhost' (localhost)
2015-05-08
14:54:19|26123|32:32|image|utils.pm:get_connect_method_info(10059)|attempting
to retrieve connect method info:
|26123|32:32|image| imagerevision: 29 - vmwarelinux-vm7vcl71030-v0
|26123|32:32|image| OS: 36 - vmwarelinux
|26123|32:32|image| OS type: 2 - linux
2015-05-08
14:54:19|26123|32:32|image|utils.pm:get_connect_method_info(10123)|ssh:
connectmethodid=1, OStypeid=2, OSid=NULL, imagerevisionid=NULL, disabled=0
2015-05-08 14:54:19|26123|32:32|image|vcld:main(287)|retrieved request
information from database
2015-05-08
14:54:19|26123|32:32|image|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-08
14:54:19|26123|32:32|image|utils.pm:update_request_state(1545)|request 32 state
updated to: pending, laststate to: image
2015-05-08 14:54:19|26123|32:32|image|utils.pm:insertloadlog(3665)|inserted
computer=10, begin, beginning to process, state is image
2015-05-08 14:54:19|26123|32:32|image|vcld:make_new_child(518)|loaded
VCL::image module
2015-05-08 14:54:19|26123|32:32|image|vcld:make_new_child(542)|current number
of forked kids: 2
2015-05-08 14:54:19|1948|32:32|image|vcld:make_new_child(558)|vcld environment
variable set to 0 for this process
2015-05-08 14:54:19|1948|32:32|image|DataStructure.pm:_initialize(643)|image ID
argument was specified: noimage, DataStructure object will contain image
information for the production imagerevision of this image
2015-05-08
14:54:19|1948|32:32|image|DataStructure.pm:_initialize(674)|retrieved data for
imagerevision ID: 1
2015-05-08
14:54:19|1948|32:32|image|DataStructure.pm:_initialize(690)|retrieved data for
image ID: 1
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_mn_os_object(376)|VCL::Module::OS::Linux::ManagementNode
module loaded
2015-05-08
14:54:20|1948|32:32|image|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode
object created for image noimage, address: 29c4ff0
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{hostname}, data identifier:
computer_hostname, data:
|1948|32:32|image| : "localhost"
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{NODENAME}, data identifier:
computer_node_name, data:
|1948|32:32|image| : "localhost"
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{SHORTNAME}, data identifier:
computer_short_name, data:
|1948|32:32|image| : "localhost"
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{IPaddress}, data identifier:
computer_ip_address, data:
|1948|32:32|image| : "131.247.30.237"
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_mn_os_object(381)|VCL::Module::OS::Linux::ManagementNode
OS object created, address: 29c4ff0
2015-05-08 14:54:20|1948|32:32|image|Module.pm:new(192)|VCL::image object
created for state image, address: 244cc40
2015-05-08 14:54:20|1948|32:32|image|State.pm:initialize(88)|obtained a
database handle for this state process, stored as $ENV{dbh}
2015-05-08 14:54:20|1948|32:32|image|State.pm:check_image_os(790)|no
corrections need to be made to image OS: vmwarelinux
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-08
14:54:20|1948|32:32|image|utils.pm:rename_vcld_process(6752)|reservation count:
1
2015-05-08
14:54:20|1948|32:32|image|utils.pm:rename_vcld_process(6771)|PARENTIMAGE: 1
2015-05-08
14:54:20|1948|32:32|image|utils.pm:rename_vcld_process(6772)|SUBIMAGE: 0
2015-05-08 14:54:20|1948|32:32|image|utils.pm:rename_vcld_process(6790)|renamed
process to 'vcld 32:32 image VM7Cent6VCL7>VM7 vmwarelinux-vm7vcl71030-v0 admin'
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:is_parent_reservation(1004)|returning
true: parent reservation ID for this request: 32
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_os_object(308)|VCL::Module::OS::Linux
module loaded
2015-05-08 14:54:20|1948|32:32|image|Module.pm:new(196)|VCL::Module::OS::Linux
object created for image vmwarelinux-vm7vcl71030-v0, address: 29c85a8
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_os_object(314)|VCL::Module::OS::Linux
OS object created, address: 29c85a8
2015-05-08 14:54:20|1948|32:32|image|State.pm:initialize(125)|computer is a VM,
attempting to create VM host OS object
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(619)|computer
ID argument was specified, retrieving data for computer ID: 5
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image information
for the production imagerevision of this image
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(674)|retrieved data for
imagerevision ID: 1
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(690)|retrieved data for
image ID: 1
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_vmhost_os_object(454)|attempting to
load VM host OS module: VCL::Module::OS::Linux::UnixLab (image: 1)
2015-05-08 14:54:20|1948|32:32|image|Module.pm:create_vmhost_os_object(460)|VM
host OS module loaded: VCL::Module::OS::Linux::UnixLab
2015-05-08
14:54:20|1948|32:32|image|Module.pm:new(196)|VCL::Module::OS::Linux::UnixLab
object created for image noimage, address: 29c8818
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_vmhost_os_object(465)|VCL::Module::OS::Linux::UnixLab
OS object created, address: 29c8818
2015-05-08
14:54:20|1948|32:32|image|Module.pm:create_provisioning_object(519)|VCL::Module::Provisioning::VMware::VMware
module loaded
2015-05-08
14:54:20|1948|32:32|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VMware
object created for computer VM7Cent6VCL7, address: 29c8bc0
2015-05-08 14:54:20|1948|32:32|image|VMware.pm:initialize(267)|initializing
VCL::Module::Provisioning::VMware::VMware object
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(619)|computer
ID argument was specified, retrieving data for computer ID: 5
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image information
for the production imagerevision of this image
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(674)|retrieved data for
imagerevision ID: 1
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(690)|retrieved data for
image ID: 1
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_datastructure(1397)|created
DataStructure object for VM host: VM7
2015-05-08 14:54:20|1948|32:32|image|VMware.pm:initialize(287)|VM profile
assigned to VM7: VMware ESXi - local storage
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(619)|computer
ID argument was specified, retrieving data for computer ID: 5
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image information
for the production imagerevision of this image
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(674)|retrieved data for
imagerevision ID: 1
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(690)|retrieved data for
image ID: 1
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_datastructure(1397)|created
DataStructure object for VM host: VM7
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_api_object(1500)|attempting to
load VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_api_object(1506)|loaded VMware
control module: VCL::Module::Provisioning::VMware::vSphere_SDK
2015-05-08
14:54:20|1948|32:32|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vSphere_SDK
object created for computer VM7Cent6VCL7, address: 2f7c600
2015-05-08 14:54:20|1948|32:32|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:
|1948|32:32|image| 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/../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 436)
line 1.
|1948|32:32|image| BEGIN failed--compilation aborted at (eval 436) line 1.
2015-05-08 14:54:20|1948|32:32|image|VMware.pm:get_vmhost_api_object(1520)|API
object could not be created: VCL::Module::Provisioning::VMware::vSphere_SDK
2015-05-08 14:54:20|1948|32:32|image|OS.pm:is_ssh_responding(678)|VM7 is
responding to SSH, port 22: open, port 24: closed
2015-05-08 14:54:20|1948|32:32|image|VMware.pm:initialize(303)|OS on VM host
VM7 will be controlled using VCL::Module::OS::Linux::UnixLab OS object
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(619)|computer
ID argument was specified, retrieving data for computer ID: 5
2015-05-08 14:54:20|1948|32:32|image|DataStructure.pm:_initialize(643)|image ID
argument was specified: 1, DataStructure object will contain image information
for the production imagerevision of this image
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(674)|retrieved data for
imagerevision ID: 1
2015-05-08
14:54:20|1948|32:32|image|DataStructure.pm:_initialize(690)|retrieved data for
image ID: 1
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_datastructure(1397)|created
DataStructure object for VM host: VM7
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_api_object(1500)|attempting to
load VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
2015-05-08
14:54:20|1948|32:32|image|VMware.pm:get_vmhost_api_object(1506)|loaded VMware
control module: VCL::Module::Provisioning::VMware::VIM_SSH
2015-05-08
14:54:20|1948|32:32|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VIM_SSH
object created for computer VM7Cent6VCL7, address: 2f7c6d8
2015-05-08 14:54:20|1948|32:32|image|utils.pm:run_ssh_command(4902)|executing
SSH command on VM7:
|1948|32:32|image| /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 VM7 'vim-cmd ; vmware-vim-cmd' 2>&1
2015-05-08
14:54:21|1948|32:32|image|utils.pm:run_ssh_command(5020)|run_ssh_command output:
|1948|32:32|image| Commands available under /:
|1948|32:32|image| hbrsvc/ internalsvc/ solo/ vmsvc/
|1948|32:32|image| hostsvc/ proxysvc/ vimsvc/ help
|1948|32:32|image| sh: vmware-vim-cmd: not found
2015-05-08 14:54:21|1948|32:32|image|utils.pm:run_ssh_command(5030)|SSH command
executed on VM7, command:
|1948|32:32|image| /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 VM7 'vim-cmd ; vmware-vim-cmd' 2>&1
|1948|32:32|image| returning (127, "Commands available under /: hb...")
2015-05-08 14:54:21|1948|32:32|image|VIM_SSH.pm:initialize(138)|VIM executable
available on VM host: vim-cmd
2015-05-08
14:54:21|1948|32:32|image|VIM_SSH.pm:initialize(140)|VCL::Module::Provisioning::VMware::VIM_SSH
object initialized
2015-05-08
14:54:21|1948|32:32|image|VMware.pm:get_vmhost_api_object(1527)|created API
object: VCL::Module::Provisioning::VMware::VIM_SSH
2015-05-08 14:54:21|1948|32:32|image|VMware.pm:initialize(312)|VM host VM7 will
be controlled using vim-cmd via SSH
2015-05-08 14:54:21|1948|32:32|image|VMware.pm:initialize(327)|VMware OS and
API objects created for VM host VM7:
|1948|32:32|image| VM host OS object type: VCL::Module::OS::Linux::UnixLab
|1948|32:32|image| VMware API object type:
VCL::Module::Provisioning::VMware::VIM_SSH
2015-05-08 14:54:21|1948|32:32|image|utils.pm:run_ssh_command(4902)|executing
SSH command on VM7:
|1948|32:32|image| /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 VM7 'vmware -v' 2>&1
2015-05-08
14:54:22|1948|32:32|image|utils.pm:run_ssh_command(5020)|run_ssh_command output:
|1948|32:32|image| VMware ESXi 5.5.0 build-1331820
2015-05-08 14:54:22|1948|32:32|image|utils.pm:run_ssh_command(5034)|SSH command
executed on VM7, returning (0, "VMware ESXi 5.5.0 build-133182...")
2015-05-08
14:54:22|1948|32:32|image|VMware.pm:get_vmhost_product_name(6634)|VMware
product being used on VM host VM7: 'VMware ESXi 5.5.0 build-1331820'
2015-05-08 14:54:22|1948|32:32|image|VIM_SSH.pm:_run_vim_cmd(210)|executed
command on VM host VM7: vim-cmd hostsvc/datastore/listsummary
2015-05-08
14:54:22|1948|32:32|image|VMware.pm:get_datastore_info(6760)|retrieved
datastore info from VM host:
|1948|32:32|image| : {
|1948|32:32|image| : "BlackArmor_Connect" => {
|1948|32:32|image| : "accessible" => "true",
|1948|32:32|image| : "capacity" => "5898541047808",
|1948|32:32|image| : "datastore" => "vim.Datastore:192.168.5.23:/DataVolume/VM",
|1948|32:32|image| : "dynamicType" => "<unset>",
|1948|32:32|image| : "freeSpace" => "5860950425600",
|1948|32:32|image| : "maintenanceMode" => "<unset>",
|1948|32:32|image| : "multipleHostAccess" => "<unset>",
|1948|32:32|image| : "normal_path" => "/vmfs/volumes/BlackArmor_Connect",
|1948|32:32|image| : "type" => "NFS",
|1948|32:32|image| : "uncommitted" => 0,
|1948|32:32|image| : "url" => "/vmfs/volumes/ff1e5fec-060d38c8"
|1948|32:32|image| : },
|1948|32:32|image| : "BlackArmor_ConnectISO" => {
|1948|32:32|image| : "accessible" => "true",
|1948|32:32|image| : "capacity" => "5898541047808",
|1948|32:32|image| : "datastore" =>
"vim.Datastore:192.168.5.23:/DataVolume/ISO",
|1948|32:32|image| : "dynamicType" => "<unset>",
|1948|32:32|image| : "freeSpace" => "5878084694016",
|1948|32:32|image| : "maintenanceMode" => "<unset>",
|1948|32:32|image| : "multipleHostAccess" => "<unset>",
|1948|32:32|image| : "normal_path" => "/vmfs/volumes/BlackArmor_ConnectISO",
|1948|32:32|image| : "type" => "NFS",
|1948|32:32|image| : "uncommitted" => 0,
|1948|32:32|image| : "url" => "/vmfs/volumes/bb84ee19-47a18f64"
|1948|32:32|image| : },
|1948|32:32|image| : "datastore1" => {
|1948|32:32|image| : "accessible" => "true",
|1948|32:32|image| : "capacity" => "491505319936",
|1948|32:32|image| : "datastore" =>
"vim.Datastore:54b943b2-7ee6229d-f173-0019b9ddadff",
|1948|32:32|image| : "dynamicType" => "<unset>",
|1948|32:32|image| : "freeSpace" => "383980142592",
|1948|32:32|image| : "maintenanceMode" => "<unset>",
|1948|32:32|image| : "multipleHostAccess" => "<unset>",
|1948|32:32|image| : "normal_path" => "/vmfs/volumes/datastore1",
|1948|32:32|image| : "type" => "VMFS",
|1948|32:32|image| : "uncommitted" => "5195810688",
|1948|32:32|image| : "url" =>
"/vmfs/volumes/54b943b2-7ee6229d-f173-0019b9ddadff"
|1948|32:32|image| : }
|1948|32:32|image| : }
2015-05-08
14:54:22|1948|32:32|image|VMware.pm:get_vmx_base_directory_path(3094)|determined
vmx base directory path: /vmfs/volumes/datastore1
2015-05-08 14:54:22|1948|32:32|image|utils.pm:run_ssh_command(4902)|executing
SSH command on VM7:
|1948|32:32|image| /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 VM7 'stat /vmfs/volumes/datastore1' 2>&1
2015-05-08
14:54:23|1948|32:32|image|utils.pm:run_ssh_command(5020)|run_ssh_command output:
|1948|32:32|image| File: '/vmfs/volumes/datastore1' ->
'54b943b2-7ee6229d-f173-0019b9ddadff'
|1948|32:32|image| Size: 35 Blocks: 0 IO Block: 131072 symbolic link
|1948|32:32|image| Device: 0h/0d Inode: 2147483647 Links: 1
|1948|32:32|image| Access: (0755/lrwxr-xr-x) Uid: ( 0/ root) Gid: ( 0/ root)
|1948|32:32|image| Access: 2015-05-08 18:45:09.000000000
|1948|32:32|image| Modify: 2015-05-08 18:45:09.000000000
|1948|32:32|image| Change: 2015-05-08 18:45:09.000000000
2015-05-08 14:54:23|1948|32:32|image|utils.pm:run_ssh_command(5034)|SSH command
executed on VM7, returning (0, "File: '/vmfs/volumes/datastore...")
2015-05-08
14:54:23|1948|32:32|image|Linux.pm:file_exists(1449)|'/vmfs/volumes/datastore1'
exists on VM7, files: 0, directories: 0, links: 1
2015-05-08 14:54:23|1948|32:32|image|VMware.pm:is_vm_dedicated(4257)|VM disk
mode does not need to be dedicated
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: datastore1
2015-05-08 14:54:23|1948|32:32|image|VMware.pm:initialize(351)|not checking if
vmdk base directory exists because it is the same as the vmx base directory:
/vmfs/volumes/datastore1
2015-05-08
14:54:23|1948|32:32|image|Module.pm:create_provisioning_object(525)|VCL::Module::Provisioning::VMware::VMware
provisioner object created for VM7Cent6VCL7, address: 29c8bc0
2015-05-08 14:54:23|1948|32:32|image|State.pm:initialize(154)|returning 1
2015-05-08 14:54:23|1948|32:32|image|vcld:make_new_child(568)|VCL::image object
created and initialized
2015-05-08 14:54:23|1948|32:32|image|utils.pm:mail(1253)|SUCCESS -- Sending
mail To: [email protected], VCL IMAGE Creation Started:
vmwarelinux-vm7vcl71030-v0
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: datastore1
2015-05-08 14:54:23|1948|32:32|image|utils.pm:run_ssh_command(4902)|executing
SSH command on VM7:
|1948|32:32|image| /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 VM7 'stat
/vmfs/volumes/datastore1/vmwarelinux\-vm7vcl71030\-v0/vmwarelinux\-vm7vcl71030\-v0\.vmdk'
2>&1
2015-05-08
14:54:23|1948|32:32|image|utils.pm:run_ssh_command(5020)|run_ssh_command output:
|1948|32:32|image| stat: can't stat
'/vmfs/volumes/datastore1/vmwarelinux-vm7vcl71030-v0/vmwarelinux-vm7vcl71030-v0.vmdk':
No such file or directory
2015-05-08 14:54:23|1948|32:32|image|utils.pm:run_ssh_command(5030)|SSH command
executed on VM7, command:
|1948|32:32|image| /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 VM7 'stat
/vmfs/volumes/datastore1/vmwarelinux\-vm7vcl71030\-v0/vmwarelinux\-vm7vcl71030\-v0\.vmdk'
2>&1
|1948|32:32|image| returning (1, "stat: can't stat '/vmfs/volume...")
2015-05-08 14:54:23|1948|32:32|image|VMware.pm:does_image_exist(4595)|image
does not exist in the shared directory on the VM host
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:get_repository_vmdk_base_directory_path(4140)|repository
path is not configured in the VM profile
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:get_repository_vmdk_directory_path(4181)|image
repository vmdk directory path cannot be determined because repository path is
not configured in the VM profile
2015-05-08 14:54:23|1948|32:32|image|VMware.pm:does_image_exist(4601)|image
does not exist on the VM host and image repository path is not configured in
the VM profile
2015-05-08 14:54:23|1948|32:32|image|image.pm:process(145)|image
vmwarelinux-vm7vcl71030-v0 does not exist in the repository
2015-05-08 14:54:23|1948|32:32|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{32}{image}{lastupdate}, data identifier:
image_lastupdate, data:
|1948|32:32|image| : "2015-05-08 14:54:23"
2015-05-08 14:54:23|1948|32:32|image|DataStructure.pm:_automethod(847)|data
structure updated, hash path:
$self->request_data->{reservation}{32}{imagerevision}{datecreated}, data
identifier: imagerevision_date_created, data:
|1948|32:32|image| : "2015-05-08 14:54:23"
2015-05-08 14:54:23|1948|32:32|image|image.pm:process(161)|calling provisioning
module's capture() subroutine
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:get_vmdk_base_directory_path_shared(3566)|using
VM profile datastore path as the vmdk base directory path: datastore1
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:get_repository_vmdk_base_directory_path(4140)|repository
path is not configured in the VM profile
2015-05-08
14:54:23|1948|32:32|image|VMware.pm:is_repository_mounted_on_vmhost(6709)|unable
to determine if image repository is mounted on VM host VM7, repository path is
not configured in the VM profile
2015-05-08 14:54:24|1948|32:32|image|OS.pm:is_ssh_responding(653)|VM7Cent6VCL7
is NOT responding to SSH, ports 22 or 24 are both closed
|1948|32:32|image| ---- WARNING ----
|1948|32:32|image| 2015-05-08
14:54:24|1948|32:32|image|VMware.pm:capture(613)|unable to capture image, VM
VM7Cent6VCL7 is not responding to SSH
|1948|32:32|image| ( 0) VMware.pm, capture (line: 613)
|1948|32:32|image| (-1) image.pm, process (line: 162)
|1948|32:32|image| (-2) vcld, make_new_child (line: 571)
|1948|32:32|image| (-3) vcld, main (line: 350)
|1948|32:32|image| ---- WARNING ----
|1948|32:32|image| 2015-05-08
14:54:24|1948|32:32|image|image.pm:process(166)|vmwarelinux-vm7vcl71030-v0
image failed to be captured by provisioning module
|1948|32:32|image| ( 0) image.pm, process (line: 166)
|1948|32:32|image| (-1) vcld, make_new_child (line: 571)
|1948|32:32|image| (-2) vcld, main (line: 350)
2015-05-08
14:54:24|1948|32:32|image|DataStructure.pm:get_computer_private_ip_address(1641)|attempting
to retrieve private IP address for computer: VM7Cent6VCL7
2015-05-08 14:54:24|1948|32:32|image|OS.pm:get_file_contents(1897)|retrieved 15
lines from file on localhost: '/etc/hosts'
2015-05-08
14:54:24|1948|32:32|image|DataStructure.pm:get_computer_private_ip_address(1697)|returning
IP address from /etc/hosts file: 192.168.10.70
2015-05-08 14:54:24|1948|32:32|image|utils.pm:is_inblockrequest(5760)|zero rows
were returned from database select
2015-05-08
14:54:24|1948|32:32|image|DataStructure.pm:get_image_affiliation_name(2121)|image
owner id: 1
2015-05-08
14:54:24|1948|32:32|image|DataStructure.pm:retrieve_user_data(1412)|attempting
to retrieve and store data for user: user.id = '1'
2015-05-08
14:54:24|1948|32:32|image|DataStructure.pm:retrieve_user_data(1475)|data has
been retrieved for user: admin (id: 1)
2015-05-08 14:54:24|1948|32:32|image|utils.pm:mail(1253)|SUCCESS -- Sending
mail To: [email protected], PROBLEM --
localhost|32:32|image|image.pm|VM7Cent6VCL7>VM7|vmwarelinux-vm7vcl71030-v0|admin
|1948|32:32|image| ---- CRITICAL ----
|1948|32:32|image| 2015-05-08
14:54:24|1948|32:32|image|image.pm:reservation_failed(387)|vmwarelinux-vm7vcl71030-v0
image creation failed
|1948|32:32|image| ( 0) image.pm, reservation_failed (line: 387)
|1948|32:32|image| (-1) image.pm, process (line: 167)
|1948|32:32|image| (-2) vcld, make_new_child (line: 571)
|1948|32:32|image| (-3) vcld, main (line: 350)
2015-05-08 14:54:24|1948|32:32|image|utils.pm:mail(1253)|SUCCESS -- Sending
mail To: root@localhost, VCL -- NOTICE DELAY Image Creation vm7vcl7-10
2015-05-08 14:54:24|1948|32:32|image|utils.pm:mail(1253)|SUCCESS -- Sending
mail To: [email protected], VCL -- NOTICE FAILED Image Creation vm7vcl7-10
2015-05-08
14:54:24|1948|32:32|image|utils.pm:update_request_state(1545)|request 32 state
updated to: maintenance, laststate to: image
2015-05-08 14:54:24|1948|32:32|image|image.pm:reservation_failed(441)|request
state set to maintenance, laststate to image
2015-05-08
14:54:24|1948|32:32|image|utils.pm:update_computer_state(1587)|computer 10
state updated to: maintenance
2015-05-08
14:54:24|1948|32:32|image|image.pm:reservation_failed(449)|VM7Cent6VCL7 state
set to maintenance
2015-05-08 14:54:24|1948|32:32|image|image.pm:reservation_failed(456)|exiting
2015-05-08
14:54:24|1948|32:32|image|utils.pm:delete_computerloadlog_reservation(6396)|removing
computerloadlog entries matching loadstate = begin
2015-05-08
14:54:24|1948|32:32|image|utils.pm:delete_computerloadlog_reservation(6443)|deleted
rows from computerloadlog for reservation id=32
2015-05-08 14:54:24|1948|32:32|image|State.pm:DESTROY(929)|VCL::image process
duration: 4 seconds
2015-05-08 14:54:24|1948|32:32|image|VIM_SSH.pm:DESTROY(2125)|vim-cmd call
count: 1
Lewis Litchfield
Technology Services - Viking Center Lab
University of South Florida Sarasota-Manatee
941-359-4231
