hi andy,
thanks for the response thanks to some over-zealous spam filtering on our
university servers, a lot of the list emails were not getting through to and
from me. i think it is resolved now, so i am going to attempt to include the
logs. the original error message was slightly different from the thread you
recommended (i always ran the script from the cygwin terminal). my efforts to
test what i found on markmail did not result in similar errors. this time (with
the new update_cygwin.cmd), the vm drops into a 'reload' state, but machine
disappears from the vm host. this could possibly be something in my
configuration. i saw another thread where the vmhosts could not be placed in
the 'vmhostinuse' state, and i'm seeing similar behavior. could be related
(?). the logs from the last attempt are below.
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:reservation_being_processed(8667)|computerloadlog
'begin' entry does NOT exist for reservation 9
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|utils.pm:run_command(8739)|executed
command: pgrep -fl 'vcld [0-9]+:9 ', pid: 13524, exit status: 1, output:
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:is_management_node_process_running(8972)|process
is NOT running, identifier: 'vcld [0-9]+:9 '
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:reservation_being_processed(8688)|reservation
is NOT currently being processed
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|vcld:main(282)|reservation 9 is NOT
already being processed
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:get_connect_method_info(10092)|attempting
to retrieve connect method info:
|7578|9:9|tovmhostinuse| imagerevision: 3 - vmwarewin7-win7_x64_base4-v0
|7578|9:9|tovmhostinuse| OS: 35 - vmwarewin7
|7578|9:9|tovmhostinuse| OS type: 1 - windows
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:get_connect_method_info(10156)|RDP:
connectmethodid=2, OStypeid=1, OSid=NULL, imagerevisionid=NULL, disabled=0
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:get_connect_method_info(10185)|retrieved connect
method info:
|7578|9:9|tovmhostinuse| : {
|7578|9:9|tovmhostinuse| : 2 => {
|7578|9:9|tovmhostinuse| : "connectmethodmap" => {
|7578|9:9|tovmhostinuse| : "OSid" => undef,
|7578|9:9|tovmhostinuse| : "OStypeid" => 1,
|7578|9:9|tovmhostinuse| : "autoprovisioned" => undef,
|7578|9:9|tovmhostinuse| : "connectmethodid" => 2,
|7578|9:9|tovmhostinuse| : "disabled" => 0,
|7578|9:9|tovmhostinuse| : "imagerevisionid" => undef
|7578|9:9|tovmhostinuse| : },
|7578|9:9|tovmhostinuse| : "description" => "Remote Desktop",
|7578|9:9|tovmhostinuse| : "id" => 2,
|7578|9:9|tovmhostinuse| : "name" => "RDP",
|7578|9:9|tovmhostinuse| : "port" => 3389,
|7578|9:9|tovmhostinuse| : "protocol" => "",
|7578|9:9|tovmhostinuse| : "servicename" => "TermService",
|7578|9:9|tovmhostinuse| : "startupscript" => undef
|7578|9:9|tovmhostinuse| : }
|7578|9:9|tovmhostinuse| : }
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|utils.pm:get_user_info(7573)|UID
value is not configured for user vclreload, setting UID to VCL user ID:
vclreload, standalone: 1
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|utils.pm:get_user_info(7573)|UID
value is not configured for user vclreload, setting UID to VCL user ID:
vclreload, standalone: 1
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:get_request_info(4100)|request length >
24 hours, disabling user checks
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|vcld:main(287)|retrieved request
information from database
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|DataStructure.pm:is_parent_reservation(993)|returning
true: parent reservation ID for this request: 9
2012-08-15
11:25:02|7578|9:9|tovmhostinuse|utils.pm:update_request_state(1545)|request 9
state updated to: pending, laststate to: tovmhostinuse
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|utils.pm:insertloadlog(3703)|inserted
computer=2, begin, beginning to process, state is tovmhostinuse
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|vcld:make_new_child(510)|request will
be processed by new.pm
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|vcld:make_new_child(518)|loaded
VCL::new module
2012-08-15 11:25:02|7578|9:9|tovmhostinuse|vcld:make_new_child(542)|current
number of forked kids: 2
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|vcld:make_new_child(558)|vcld
environment variable set to 0 for this process
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_initialize(637)|image ID
argument was specified: noimage, DataStructure object will contain image
information for the production imagerevision of this image
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_initialize(668)|retrieved
data for imagerevision ID: 1
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_initialize(684)|retrieved
data for image ID: 1
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:create_mn_os_object(376)|VCL::Module::OS::Linux::ManagementNode
module loaded
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode
object created for image noimage, address: 4224a08
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_automethod(836)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{hostname}, data identifier:
computer_hostname, data:
|13539|9:9|tovmhostinuse| : "localhost"
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_automethod(836)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{NODENAME}, data identifier:
computer_node_name, data:
|13539|9:9|tovmhostinuse| : "localhost"
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_automethod(836)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{SHORTNAME}, data identifier:
computer_short_name, data:
|13539|9:9|tovmhostinuse| : "localhost"
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_automethod(836)|data
structure updated, hash path:
$self->request_data->{reservation}{0}{computer}{IPaddress}, data identifier:
computer_ip_address, data:
|13539|9:9|tovmhostinuse| : "127.0.0.1"
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:create_mn_os_object(381)|VCL::Module::OS::Linux::ManagementNode
OS object created, address: 4224a08
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|Module.pm:new(192)|VCL::new object
created for state tovmhostinuse, address: 3a96e80
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|State.pm:initialize(88)|obtained a
database handle for this state process, stored as $ENV{dbh}
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|State.pm:check_image_os(771)|no
corrections need to be made, not an imaging request, returning 1
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:is_parent_reservation(993)|returning
true: parent reservation ID for this request: 9
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:rename_vcld_process(6785)|reservation
count: 1
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:rename_vcld_process(6804)|PARENTIMAGE: 1
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:rename_vcld_process(6805)|SUBIMAGE: 0
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:rename_vcld_process(6823)|renamed
process to 'vcld 9:9 tovmhostinuse vclhv02 vmwarewin7-win7_x64_base4-v0 vclreload'
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:is_parent_reservation(993)|returning
true: parent reservation ID for this request: 9
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:is_parent_reservation(993)|returning
true: parent reservation ID for this request: 9
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:create_os_object(308)|VCL::Module::OS::Windows::Version_6::7
module loaded
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:new(196)|VCL::Module::OS::Windows::Version_6::7
object created for image vmwarewin7-win7_x64_base4-v0, address: 42281e0
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:create_os_object(314)|VCL::Module::OS::Windows::Version_6::7
OS object created, address: 42281e0
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|State.pm:initialize(132)|computer is
NOT a VM, VM host OS object not created
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:create_provisioning_object(519)|VCL::Module
module loaded
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|Module.pm:new(203)|VCL::Module
object created, address: 4227ec8
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|Module.pm:create_provisioning_object(525)|VCL::Module
provisioner object created for vclhv02, address: 4227ec8
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|State.pm:initialize(154)|returning 1
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|vcld:make_new_child(568)|VCL::new
object created and initialized
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:is_parent_reservation(993)|returning
true: parent reservation ID for this request: 9
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:get_computer_state_name(2433)|attempting
to retrieve current state of computer vclhv02 from the database
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:get_computer_state_name(2464)|retrieved
current state of computer vclhv02 from the database: maintenance
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_automethod(836)|data
structure updated, hash path:
$self->request_data->{reservation}{9}{computer}{state}{name}, data identifier:
computer_state_name, data:
|13539|9:9|tovmhostinuse| : "maintenance"
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:get_computer_state_name(2433)|attempting
to retrieve current state of computer vclhv02 from the database
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:get_computer_state_name(2464)|retrieved
current state of computer vclhv02 from the database: maintenance
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|DataStructure.pm:_automethod(836)|data
structure updated, hash path:
$self->request_data->{reservation}{9}{computer}{state}{name}, data identifier:
computer_state_name, data:
|13539|9:9|tovmhostinuse| : "maintenance"
|13539|9:9|tovmhostinuse| ---- WARNING ----
|13539|9:9|tovmhostinuse| 2012-08-15
11:25:02|13539|9:9|tovmhostinuse|new.pm:computer_not_being_used(715)|vclhv02 is
NOT available, its state is maintenance
|13539|9:9|tovmhostinuse| ( 0) new.pm, computer_not_being_used (line: 715)
|13539|9:9|tovmhostinuse| (-1) new.pm, process (line: 127)
|13539|9:9|tovmhostinuse| (-2) vcld, make_new_child (line: 571)
|13539|9:9|tovmhostinuse| (-3) vcld, main (line: 350)
|13539|9:9|tovmhostinuse| ---- WARNING ----
|13539|9:9|tovmhostinuse| 2012-08-15
11:25:02|13539|9:9|tovmhostinuse|new.pm:process(160)|request
state=tovmhostinuse, vclhv02 is NOT available
|13539|9:9|tovmhostinuse| ( 0) new.pm, process (line: 160)
|13539|9:9|tovmhostinuse| (-1) vcld, make_new_child (line: 571)
|13539|9:9|tovmhostinuse| (-2) vcld, main (line: 350)
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|new.pm:process(164)|vclhv02 is not
available, setting computer next image to vmwarewin7-win7_x64_base4-v0
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|new.pm:process(165)|vclhv02 next
image set to vmwarewin7-win7_x64_base4-v0
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:update_request_state(1545)|request 9
state updated to: complete, laststate to: tovmhostinuse
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|new.pm:process(177)|request state
updated to 'complete'/'tovmhostinuse'
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|new.pm:process(184)|exiting
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:delete_computerloadlog_reservation(6429)|removing
computerloadlog entries matching loadstate = begin
2012-08-15
11:25:02|13539|9:9|tovmhostinuse|utils.pm:delete_computerloadlog_reservation(6476)|deleted
rows from computerloadlog for reservation id=9
2012-08-15 11:25:02|13539|9:9|tovmhostinuse|State.pm:DESTROY(929)|VCL::new
process duration: 0 seconds
2012-08-15 11:25:02|7578|9:9|complete|vcld:main(256)|request deleted
will
On 08/14/2012 09:44 AM, Andy Kurth wrote:
Hi Will,
Please check my reply in the "RE: New capture failed attempting
Windows post-load tasks" thread to see if this is the same issue
you're having. If this is a different issue, please send the complete
vcld.log output for the reservation. The following command should
filter out the reservation:
grep '|6:6|' /var/log/vcld.log
-Andy
