Re: VCL fails to grant OS access

[Andy Kurth <an...@ncsu.edu>]

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
>