You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@vcl.apache.org by Kelly Robinson <is...@langate.gsu.edu> on 2011/02/24 00:30:27 UTC
VCL fails to grant OS access
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
Re: VCL fails to grant OS access
Posted by 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
>