We've had occurrences where some reservations will load, but the login screen 
on the vm is slow and turns black and becomes unusable.  When parsing through 
the logs, there seems to be issues at the point of configuring the firewall to 
allow RDP.  The messages first state the firewall was configured to allow RDP 
access from the user's ip address, but then states that the firewall could not 
be configured to grant RDP access.  Then a "failed to grant OS access on 
<computer_name>" message is given, but the reservation continues to load and 
does not fail.  Has anyone had any similar issues or know what the problem 
could be?  A snippet from that portion of the log is given below: (note: the 
user's ipaddress has been X'ed out) 

+++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 
2011-02-23 14:58:55|29239|1436:1429|reserved|vcld:make_new_child(581)|vcld 
environment variable set to 0 for this process 
2011-02-23 14:58:55|29239|1436:1429|reserved|Module.pm:new(132)|constructor 
called, class=VCL::reserved 
2011-02-23 14:58:55|29239|1436:1429|reserved|Module.pm:new(154)|VCL::reserved 
object created 
2011-02-23 14:58:55|29239|1436:1429|reserved|State.pm:initialize(85)|obtained a 
database handle for this state process, stored as $ENV{dbh} 
2011-02-23 14:58:55|29239|1436:1429|reserved|State.pm:check_image_os(820)|no 
corrections need to be made, not an imaging request, returning 1 
2011-02-23 
14:58:55|29239|1436:1429|reserved|DataStructure.pm:is_parent_reservation(854)|returning
 true: parent reservation ID for this request: 1429 
2011-02-23 
14:58:55|29239|1436:1429|reserved|utils.pm:rename_vcld_process(7520)|reservation
 count: 1 
2011-02-23 
14:58:55|29239|1436:1429|reserved|utils.pm:rename_vcld_process(7539)|PARENTIMAGE:
 1 
2011-02-23 
14:58:55|29239|1436:1429|reserved|utils.pm:rename_vcld_process(7540)|SUBIMAGE: 
0 
2011-02-23 
14:58:55|29239|1436:1429|reserved|utils.pm:rename_vcld_process(7558)|renamed 
process to 'vcld VCL::reserved 1436:1429 reserved' 
2011-02-23 
14:58:55|29239|1436:1429|reserved|DataStructure.pm:is_parent_reservation(854)|returning
 true: parent reservation ID for this request: 1429 
2011-02-23 
14:58:55|29239|1436:1429|reserved|DataStructure.pm:is_parent_reservation(854)|returning
 true: parent reservation ID for this request: 1429 
2011-02-23 
14:58:55|29239|1436:1429|reserved|State.pm:initialize(121)|attempting to load 
provisioning module: VCL::Module::Provisioning::esx 
2011-02-23 14:58:55|29239|1436:1429|reserved|esx.pm:initialize(138)|esx vmware 
toolkit root path found: /usr/lib/vmware-viperl/apps 
2011-02-23 14:58:55|29239|1436:1429|reserved|esx.pm:initialize(140)|vmware ESX 
module initialized 
2011-02-23 
14:58:55|29239|1436:1429|reserved|State.pm:initialize(127)|VCL::Module::Provisioning::esx
 module loaded 
2011-02-23 14:58:55|29239|1436:1429|reserved|Module.pm:new(132)|constructor 
called, class=VCL::Module::Provisioning::esx 
2011-02-23 
14:58:55|29239|1436:1429|reserved|Module.pm:new(154)|VCL::Module::Provisioning::esx
 object created 
2011-02-23 14:58:55|29239|1436:1429|reserved|esx.pm:initialize(138)|esx vmware 
toolkit root path found: /usr/lib/vmware-viperl/apps 
2011-02-23 14:58:55|29239|1436:1429|reserved|esx.pm:initialize(140)|vmware ESX 
module initialized 
2011-02-23 
14:58:55|29239|1436:1429|reserved|State.pm:initialize(131)|VCL::Module::Provisioning::esx
 provisioner object created 
2011-02-23 
14:58:55|29239|1436:1429|reserved|State.pm:initialize(145)|attempting to load 
OS module: VCL::Module::OS::Windows::Version_5::XP 
2011-02-23 
14:58:55|29239|1436:1429|reserved|State.pm:initialize(151)|VCL::Module::OS::Windows::Version_5::XP
 module loaded 
2011-02-23 14:58:55|29239|1436:1429|reserved|Module.pm:new(132)|constructor 
called, class=VCL::Module::OS::Windows::Version_5::XP 
2011-02-23 
14:58:55|29239|1436:1429|reserved|Module.pm:new(154)|VCL::Module::OS::Windows::Version_5::XP
 object created 
2011-02-23 
14:58:55|29239|1436:1429|reserved|State.pm:initialize(154)|VCL::Module::OS::Windows::Version_5::XP
 OS object created 
2011-02-23 14:58:55|29239|1436:1429|reserved|State.pm:initialize(169)|returning 
1 
2011-02-23 
14:58:55|29239|1436:1429|reserved|vcld:make_new_child(590)|VCL::reserved object 
created and initialized 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(120)|updated 
log table, set loaded time to now for id:912 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(132)|imagemeta 
user group defined 
2011-02-23 
14:58:55|29239|1436:1429|reserved|utils.pm:getusergroupmembers(3601)|no data 
returned for usergroupid returning empty lists 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(137)|imagemeta 
user group membership count = 0 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(157)|computer 
info: id=133, type=virtualmachine, hostname=prodvcl1-58 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(158)|user 
info: login_id id=<vcluser>, standalone=1 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(159)|imagemeta 
checkuser set to: 1 
2011-02-23 
14:58:55|29239|1436:1429|reserved|reserved.pm:process(160)|formimaging set to: 
0 
2011-02-23 14:58:55|29239|1436:1429|reserved|reserved.pm:process(172)|begin 
checking for user acknowledgement 
2011-02-23 
14:58:55|29239|1436:1429|reserved|utils.pm:insertloadlog(4346)|inserted 
computer=133, info, reserved: waiting for user acknowledgement 
2011-02-23 
14:58:55|29239|1436:1429|reserved|DataStructure.pm:get_reservation_remote_ip(956)|reservation
 remote IP is not defined 
2011-02-23 
14:59:00|29239|1436:1429|reserved|DataStructure.pm:get_reservation_remote_ip(956)|reservation
 remote IP is not defined 
2011-02-23 
14:59:05|29239|1436:1429|reserved|DataStructure.pm:get_reservation_remote_ip(969)|retrieved
 remote IP for reservation 1429: 131.96.XXX.XX 
2011-02-23 14:59:05|29239|1436:1429|reserved|reserved.pm:process(190)|user 
acknowledged, remote IP: 131.96.XXX.XX 
2011-02-23 14:59:05|29239|1436:1429|reserved|reserved.pm:process(204)|calling 
VCL::Module::OS::Windows::Version_5::XP::grant_access() subroutine 
|29239|1436:1429|reserved| ---- WARNING ---- 
|29239|1436:1429|reserved| 2011-02-23 
14:59:05|29239|1436:1429|reserved|DataStructure.pm:_automethod(675)|corresponding
 data has not been initialized for get_management_node_keys: 
$ENV{management_node_info}{keys} 
|29239|1436:1429|reserved| ( 0) utils.pm, notify (line: 791) 
|29239|1436:1429|reserved| (-1) DataStructure.pm, _automethod (line: 675) 
|29239|1436:1429|reserved| (-2) Autoload.pm, __ANON__ (line: 80) 
|29239|1436:1429|reserved| (-3) Windows.pm, grant_access (line: 747) 
|29239|1436:1429|reserved| (-4) reserved.pm, process (line: 205) 
|29239|1436:1429|reserved| (-5) vcld, make_new_child (line: 593) 
|29239|1436:1429|reserved| (-6) vcld, main (line: 340) 
2011-02-23 
14:59:05|29239|1436:1429|reserved|DataStructure.pm:get_reservation_remote_ip(969)|retrieved
 remote IP for reservation 1429: 131.96.XXX.XX 
2011-02-23 14:59:05|29239|1436:1429|reserved|Windows.pm:grant_access(767)|RDP 
will be allowed from 131.96.XXX.XX/16 on prodvcl1-58 
|29239|1436:1429|reserved| ---- WARNING ---- 
|29239|1436:1429|reserved| 2011-02-23 
14:59:05|29239|1436:1429|reserved|DataStructure.pm:_automethod(675)|corresponding
 data has not been initialized for get_management_node_keys: 
$ENV{management_node_info}{keys} 
|29239|1436:1429|reserved| ( 0) utils.pm, notify (line: 791) 
|29239|1436:1429|reserved| (-1) DataStructure.pm, _automethod (line: 675) 
|29239|1436:1429|reserved| (-2) Autoload.pm, __ANON__ (line: 80) 
|29239|1436:1429|reserved| (-3) Windows.pm, firewall_enable_rdp (line: 4437) 
|29239|1436:1429|reserved| (-4) Windows.pm, grant_access (line: 774) 
|29239|1436:1429|reserved| (-5) reserved.pm, process (line: 205) 
|29239|1436:1429|reserved| (-6) vcld, make_new_child (line: 593) 
2011-02-23 
14:59:05|29239|1436:1429|reserved|utils.pm:run_ssh_command(5825)|executing SSH 
command on prodvcl1-58: 
|29239|1436:1429|reserved| /usr/bin/ssh  -l root -p 22 -x prodvcl1-58 'reg.exe 
ADD "HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Control\Terminal Server" /t 
REG_DWORD /v fDenyTSConnections /d 0 /f ; netsh.exe firewall set portopening 
name = "Remote Desktop" protocol = TCP port = 3389 mode = ENABLE scope = CUSTOM 
addresses = 131.96.XXX.XX/16' 2>&1 
2011-02-23 
14:59:08|29239|1436:1429|reserved|utils.pm:run_ssh_command(5916)|run_ssh_command
 output: 
|29239|1436:1429|reserved| The operation completed successfully 
|29239|1436:1429|reserved| Ok. 
2011-02-23 14:59:08|29239|1436:1429|reserved|utils.pm:run_ssh_command(5930)|SSH 
command executed on prodvcl1-58, returning (0, "The operation completed 
succes...") 
2011-02-23 
14:59:08|29239|1436:1429|reserved|Windows.pm:firewall_enable_rdp(4464)|configured
 firewall to allow RDP from 131.96.XXX.XX/16 
|29239|1436:1429|reserved| ---- WARNING ---- 
|29239|1436:1429|reserved| 2011-02-23 
14:59:08|29239|1436:1429|reserved|Windows.pm:grant_access(778)|firewall could 
not be configured to grant RDP access from 131.96.XXX.XX/16 on prodvcl1-58 
|29239|1436:1429|reserved| ( 0) utils.pm, notify (line: 791) 
|29239|1436:1429|reserved| (-1) Windows.pm, grant_access (line: 778) 
|29239|1436:1429|reserved| (-2) reserved.pm, process (line: 205) 
|29239|1436:1429|reserved| (-3) vcld, make_new_child (line: 593) 
|29239|1436:1429|reserved| (-4) vcld, main (line: 340) 
|29239|1436:1429|reserved| ---- WARNING ---- 
|29239|1436:1429|reserved| 2011-02-23 
14:59:08|29239|1436:1429|reserved|reserved.pm:process(209)|failed to grant OS 
access on prodvcl1-58 
|29239|1436:1429|reserved| ( 0) utils.pm, notify (line: 791) 
|29239|1436:1429|reserved| (-1) reserved.pm, process (line: 209) 
|29239|1436:1429|reserved| (-2) vcld, make_new_child (line: 593) 
|29239|1436:1429|reserved| (-3) vcld, main (line: 340) 
2011-02-23 
14:59:08|29239|1436:1429|reserved|reserved.pm:process(235)|VCL::Module::OS::Windows::Version_5::XP->post_reserve()
 not implemented by VCL::Module::OS::Windows::Version_5::XP 
2011-02-23 14:59:08|29239|1436:1429|reserved|reserved.pm:process(300)|checkuser 
flag is set to 1, checking user connection 
2011-02-23 
14:59:08|29239|1436:1429|reserved|reserved.pm:process(308)|forimaging flag is 
set to 0 and imageosname is vmwarewinxp, checking for connection by <vcluser> 
2011-02-23 
14:59:08|29239|1436:1429|reserved|utils.pm:check_connection(1828)|checking for 
connection by <vcluser> on prodvcl1-58, attempt 1 
2011-02-23 
14:59:08|29239|1436:1429|reserved|utils.pm:run_ssh_command(5825)|executing SSH 
command on prodvcl1-58: 
|29239|1436:1429|reserved| /usr/bin/ssh -i /etc/vcl/winxp_blade.key  -l root -p 
22 -x prodvcl1-58 'netstat -an' 2>&1 
2011-02-23 
14:59:29|29239|1436:1429|reserved|utils.pm:check_connection(1828)|checking for 
connection by <vcluser> on prodvcl1-58, attempt 2 
2011-02-23 
14:59:29|29239|1436:1429|reserved|utils.pm:run_ssh_command(5825)|executing SSH 
command on prodvcl1-58: 
|29239|1436:1429|reserved| /usr/bin/ssh -i /etc/vcl/winxp_blade.key  -l root -p 
22 -x prodvcl1-58 'netstat -an' 2>&1 
2011-02-23 
14:59:50|29239|1436:1429|reserved|utils.pm:check_connection(1828)|checking for 
connection by <vcluser> on prodvcl1-58, attempt 3 
2011-02-23 
14:59:50|29239|1436:1429|reserved|utils.pm:run_ssh_command(5825)|executing SSH 
command on prodvcl1-58: 
|29239|1436:1429|reserved| /usr/bin/ssh -i /etc/vcl/winxp_blade.key  -l root -p 
22 -x prodvcl1-58 'netstat -an' 2>&1 
2011-02-23 
14:59:51|29239|1436:1429|reserved|reserved.pm:process(313)|retval_conn = 
connected 
2011-02-23 
14:59:51|29239|1436:1429|reserved|reserved.pm:process(324)|131.96.XXX.XX 
connected to prodvcl1-58 
2011-02-23 
14:59:51|29239|1436:1429|reserved|utils.pm:insertloadlog(4346)|inserted 
computer=133, connected, reserved: user connected to remote machine 
2011-02-23 
14:59:51|29239|1436:1429|reserved|utils.pm:update_request_state(2249)|request 
1436 state updated to: inuse, laststate to: reserved 
2011-02-23 14:59:51|29239|1436:1429|reserved|reserved.pm:process(329)|setting 
request into inuse state 
2011-02-23 
14:59:51|29239|1436:1429|reserved|utils.pm:update_computer_state(2291)|computer 
133 state updated to: inuse 
2011-02-23 14:59:51|29239|1436:1429|reserved|reserved.pm:process(337)|setting 
computerid 133 into inuse state 
2011-02-23 14:59:51|29239|1436:1429|reserved|reserved.pm:process(345)|updated 
lastcheck time for reservation 1429 
2011-02-23 14:59:51|29239|1436:1429|reserved|reserved.pm:process(352)|exiting 
2011-02-23 14:59:51|29239|1436:1429|reserved|State.pm:DESTROY(905)|destructor 
called, ref($self)=VCL::reserved 
2011-02-23 
14:59:51|29239|1436:1429|reserved|utils.pm:delete_computerloadlog_reservation(7208)|removing
 computerloadlog entries matching loadstate = begin 
2011-02-23 
14:59:51|29239|1436:1429|reserved|utils.pm:delete_computerloadlog_reservation(7255)|deleted
 rows from computerloadlog for reservation id=1429 
2011-02-23 14:59:51|29239|1436:1429|reserved|State.pm:DESTROY(912)|removed 
computerloadlog rows with loadstate=begin for reservation 
2011-02-23 14:59:51|29239|1436:1429|reserved|State.pm:DESTROY(924)|number of 
database handles state process created: 1 
2011-02-23 14:59:51|29239|1436:1429|reserved|State.pm:DESTROY(933)|process has 
a database handle stored in $ENV{dbh}, attempting disconnect 
2011-02-23 14:59:51|29239|1436:1429|reserved|State.pm:DESTROY(935)|$ENV{dbh}: 
database disconnect successful 
2011-02-23 
14:59:51|29239|1436:1429|reserved|State.pm:DESTROY(949)|VCL::reserved process 
29239 exiting 

Thanks 

Reply via email to