This was a bug which was fixed in VCL 2.2. You can resolve this by
editing Windows.pm:
-Find "sub firewall_enable_rdp"
-Add the following line to the end of this subroutine:
return 1;
-Andy
On 2/23/2011 6:30 PM, Kelly Robinson wrote:
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
