Block Allocation Problems

["Hechler, Adam" <he...@rpi.edu>]

VCL 2.2.1
VMWare server 2

I'm trying to troubleshoot block allocations. I thought they were working but I had more copies of the image loaded in computers when I first tried so the allocations saw that enough images were loaded and reported a success. I think that's how it works, at least.

So I manually loaded (via the Manage Computers page) different images in all of the computers that were loaded with the image I'm testing with.

Every time I try to create a block allocation it fails. I think that it can't load the images.

So I loaded one computer (manually) with my Windows XP image (that I'm testing with) and then created a Block Allocation for 1 computer and that succeeded. I then modified the allocation to make it 5 machines and it failed.

Here is the relevant log section. I tried looking at blockrequest.pm but my coding experience is limited.  This log section includes the successful one machine and the failed 5 machine (modified) allocation.  If someone can even help me to troubleshoot I'd really appreciate it.


2012-09-18 08:07:18|6861|utils.pm:check_blockrequest_time(1026)|block request start time is within start window (112 minutes from now), returning 'start'
2012-09-18 08:07:18|6861|DataStructure.pm:_automethod(834)|data structure updated: $self->blockrequest_data->{6}{MODE}
|6861| blockrequest_mode = start
2012-09-18 08:07:19|6861|vcld:main(445)|block request 6 'XP1Test20120918' processing set to 1
2012-09-18 08:07:19|6861|vcld:make_new_child(515)|loaded VCL::blockrequest module
2012-09-18 08:07:19|8979|vcld:make_new_child(555)|vcld environment variable set to 0 for this process
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'numMachines' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|6861|vcld:make_new_child(539)|current number of forked kids: 1
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'ownerid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'expireTime' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'repeating' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'admingroupid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'status' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'managementnodeid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'name' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'blockTimes' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'groupname' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'groupid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'id' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'imageid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'processing' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(172)|set 'MODE' key for VCL::blockrequest object from arguments
2012-09-18 08:07:19|8979|blockrequest|Module.pm:create_mn_os_object(361)|VCL::Module::OS::Linux::ManagementNode module loaded
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode object created for image <not set>, address: 65c93f0
2012-09-18 08:07:19|8979|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{hostname}
|8979|blockrequest| computer_hostname = alpha-vcl.ewp.rpi.edu
2012-09-18 08:07:19|8979|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{NODENAME}
|8979|blockrequest| computer_node_name = alpha-vcl
2012-09-18 08:07:19|8979|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{SHORTNAME}
|8979|blockrequest| computer_short_name = alpha-vcl
2012-09-18 08:07:19|8979|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{IPaddress}
|8979|blockrequest| computer_ip_address = xx.xx.xx.xx (specific IP removed)
2012-09-18 08:07:19|8979|blockrequest|Module.pm:create_mn_os_object(366)|VCL::Module::OS::Linux::ManagementNode OS object created, address: 65c93f0
2012-09-18 08:07:19|8979|blockrequest|Module.pm:new(192)|VCL::blockrequest object created for state <not set>, address: 63cd670
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:initialize(84)|obtained a database handle for this state process, stored as $ENV{dbh}
2012-09-18 08:07:19|8979|blockrequest|utils.pm:rename_vcld_process(7136)|renamed process to 'vcld 6:4 'XP1Test20120918''
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:initialize(94)|returning 1
2012-09-18 08:07:19|8979|blockrequest|vcld:make_new_child(565)|VCL::blockrequest object created and initialized
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(158)|blockrequest id: 6
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(159)|blockrequest mode: start
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(160)|blockrequest image id: 73
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(161)|blockrequest number machines: 1
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(162)|blockrequest expire: 2012-09-18 23:59:59
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(163)|blocktime id: 4
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(164)|blocktime processed: 0
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(165)|blocktime start: 2012-09-18 10:00:00
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(166)|owner email: vcl_adminuser@ewp.rpi.edu
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(167)|help address: vcl_adminuser@ewp.rpi.edu
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(172)|updated process flag on blocktime_id= 4
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 4 pass 1
2012-09-18 08:07:19|8979|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 4 1
2012-09-18 08:07:19|8979|blockrequest|blockrequest.pm:process(206)|success blockTimes id 4 processed and allocated 1 nodes
|8979|blockrequest| status= success
2012-09-18 08:07:19|8979|blockrequest|utils.pm:mail(1255)|SUCCESS -- Sending mail To: vcl_adminuser@ewp.rpi.edu, VCL Block allocation results for XP1Test20120918
2012-09-18 08:07:29|8979|blockrequest|blockrequest.pm:process(343)|Removed processing flag on blockrequest_id 6
2012-09-18 08:07:29|8979|blockrequest|State.pm:DESTROY(829)|VCL::blockrequest destructor called, address: 63cd670
2012-09-18 08:07:29|8979|blockrequest|State.pm:DESTROY(848)|number of database handles state process created: 1
2012-09-18 08:07:29|6861|vcld:REAPER(718)|VCL process exited for reservation <unknown>, PID: 8979, signal: CHLD
2012-09-18 08:07:39|6861|utils.pm:check_blockrequest_time(1026)|block request start time is within start window (112 minutes from now), returning 'start'
2012-09-18 08:07:39|6861|DataStructure.pm:_automethod(834)|data structure updated: $self->blockrequest_data->{6}{MODE}
|6861| blockrequest_mode = start
2012-09-18 08:07:39|6861|vcld:main(445)|block request 6 'XP1Test20120918' processing set to 1
2012-09-18 08:07:39|6861|vcld:make_new_child(515)|loaded VCL::blockrequest module
2012-09-18 08:07:39|8990|vcld:make_new_child(555)|vcld environment variable set to 0 for this process
2012-09-18 08:07:39|6861|vcld:make_new_child(539)|current number of forked kids: 1
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'numMachines' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'ownerid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'expireTime' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'repeating' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'admingroupid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'status' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'managementnodeid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'name' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'blockTimes' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'groupname' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'id' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'groupid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'imageid' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'processing' key for VCL::blockrequest object from arguments
2012-09-18 08:07:39|8990|blockrequest|Module.pm:new(172)|set 'MODE' key for VCL::blockrequest object from arguments
2012-09-18 08:07:40|8990|blockrequest|Module.pm:create_mn_os_object(361)|VCL::Module::OS::Linux::ManagementNode module loaded
2012-09-18 08:07:40|8990|blockrequest|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode object created for image <not set>, address: 65c92e0
2012-09-18 08:07:40|8990|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{hostname}
|8990|blockrequest| computer_hostname = alpha-vcl.ewp.rpi.edu
2012-09-18 08:07:40|8990|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{NODENAME}
|8990|blockrequest| computer_node_name = alpha-vcl
2012-09-18 08:07:40|8990|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{SHORTNAME}
|8990|blockrequest| computer_short_name = alpha-vcl
2012-09-18 08:07:40|8990|blockrequest|DataStructure.pm:_automethod(834)|data structure updated: $self->request_data->{reservation}{0}{computer}{IPaddress}
|8990|blockrequest| computer_ip_address = xx.xx.xx.xx (specific IP removed)
2012-09-18 08:07:40|8990|blockrequest|Module.pm:create_mn_os_object(366)|VCL::Module::OS::Linux::ManagementNode OS object created, address: 65c92e0
2012-09-18 08:07:40|8990|blockrequest|Module.pm:new(192)|VCL::blockrequest object created for state <not set>, address: 61b14e0
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:initialize(84)|obtained a database handle for this state process, stored as $ENV{dbh}
2012-09-18 08:07:40|8990|blockrequest|utils.pm:rename_vcld_process(7136)|renamed process to 'vcld 6:5 'XP1Test20120918''
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:initialize(94)|returning 1
2012-09-18 08:07:40|8990|blockrequest|vcld:make_new_child(565)|VCL::blockrequest object created and initialized
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(158)|blockrequest id: 6
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(159)|blockrequest mode: start
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(160)|blockrequest image id: 73
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(161)|blockrequest number machines: 5
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(162)|blockrequest expire: 2012-09-18 23:59:59
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(163)|blocktime id: 5
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(164)|blocktime processed: 0
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(165)|blocktime start: 2012-09-18 10:00:00
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(166)|owner email: vcl_adminuser@ewp.rpi.edu
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(167)|help address: vcl_adminuser@ewp.rpi.edu
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(172)|updated process flag on blocktime_id= 5
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 5 pass 1
2012-09-18 08:07:40|8990|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 5 1
2012-09-18 08:07:40|8990|blockrequest|blockrequest.pm:process(212)|xmlrpc warning: unable to allocate any machines allocated= 0 unallocated= 5
2012-09-18 08:07:45|8990|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 5 pass 2
2012-09-18 08:07:45|8990|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 5 1
2012-09-18 08:07:45|8990|blockrequest|blockrequest.pm:process(212)|xmlrpc warning: unable to allocate any machines allocated= 0 unallocated= 5
2012-09-18 08:07:50|8990|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 5 pass 3
2012-09-18 08:07:50|8990|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 5 1
2012-09-18 08:07:50|8990|blockrequest|blockrequest.pm:process(212)|xmlrpc warning: unable to allocate any machines allocated= 0 unallocated= 5
2012-09-18 08:07:55|8990|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 5 pass 4
2012-09-18 08:07:55|8990|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 5 1
2012-09-18 08:07:56|8990|blockrequest|blockrequest.pm:process(212)|xmlrpc warning: unable to allocate any machines allocated= 0 unallocated= 5
2012-09-18 08:08:01|8990|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 5 pass 5
2012-09-18 08:08:01|8990|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 5 1
2012-09-18 08:08:01|8990|blockrequest|blockrequest.pm:process(212)|xmlrpc warning: unable to allocate any machines allocated= 0 unallocated= 5
2012-09-18 08:08:06|8990|blockrequest|blockrequest.pm:process(192)|processing blocktime_id= 5 pass 6
2012-09-18 08:08:06|8990|blockrequest|utils.pm:xmlrpc_call(9105)|argument_string= XMLRPCprocessBlockTime 5 1
2012-09-18 08:08:06|8990|blockrequest|blockrequest.pm:process(212)|xmlrpc warning: unable to allocate any machines allocated= 0 unallocated= 5
2012-09-18 08:08:11|8990|blockrequest|blockrequest.pm:process(197)|attempted 6 passes to complete block_request 6
|8990|blockrequest| allocated= 0
|8990|blockrequest| blockrequest_number_machines= 5
2012-09-18 08:08:13|8990|blockrequest|utils.pm:mail(1255)|SUCCESS -- Sending mail To: vcl_adminuser@ewp.rpi.edu, PROBLEM -- blockrequest.pm:process(243)|XP1Test20120918

|8990|blockrequest| ---- CRITICAL ----
|8990|blockrequest| 2012-09-18 08:08:11|8990|blockrequest|blockrequest.pm:process(243)|Problem processing block allocation
|8990|blockrequest| Block id = 6
|8990|blockrequest| Block name = XP1Test20120918
|8990|blockrequest| Block start time = 2012-09-18 10:00:00
|8990|blockrequest| Block end time = 2012-09-18 12:00:00
|8990|blockrequest| Environment name = WindowsXP
|8990|blockrequest| Allocated = 0
|8990|blockrequest| Block requested = 5
|8990|blockrequest| xmlrpc warn msg = unable to allocate any machines
|8990|blockrequest| ( 0) blockrequest.pm, process (line: 243)
|8990|blockrequest| (-1) vcld, make_new_child (line: 568)
|8990|blockrequest| (-2) vcld, main (line: 448)

2012-09-18 08:08:13|8990|blockrequest|utils.pm:mail(1255)|SUCCESS -- Sending mail To: vcl_adminuser@ewp.rpi.edu, VCL Block allocation warning for XP1Test20120918
2012-09-18 08:08:23|8990|blockrequest|blockrequest.pm:process(343)|Removed processing flag on blockrequest_id 6
2012-09-18 08:08:23|8990|blockrequest|State.pm:DESTROY(829)|VCL::blockrequest destructor called, address: 61b14e0
2012-09-18 08:08:23|8990|blockrequest|State.pm:DESTROY(848)|number of database handles state process created: 1
2012-09-18 08:08:23|6861|vcld:REAPER(718)|VCL process exited for reservation <unknown>, PID: 8990, signal: CHLD



Thanks,
Adam

- - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
Adam Hechler
Senior Analyst /PC Systems Administrator
Rensselaer Polytechnic Institute
275 Windsor Street
Hartford, CT 06120 USA
Ph: 860-548-2446
Email: hechla@rpi.edu<ma...@rpi.edu>
Web: http://www.ewp.rpi.edu<http://www.ewp.rpi.edu/>
[Description: fb]<http://www.facebook.com/pages/Rensselaer-Hartford-Campus/216532895053858> [Description: tw] <https://twitter.com/#!/RPI_Hartford>  [Description: yt] <http://www.youtube.com/user/RPIHartford>   [Description: blog] <http://rpihartford.blogspot.com/>