Hello,
Welcome! You do not need the vSphere SDK and you don't need to
configure the username/password in the profile. All that is required
is that the management node is able to SSH without a password to both
the VM host and VM. It looks like this is working.
I don't think the problem has to do with your VCL configuration but
seems to be related to VMware. I can't recall seeing the "Failed to
login: vim.fault.NoPermission" error before and was not able to
reproduce it. Can you log in to the VMware web console as root? If
you can login, select the VM host in the Inventory pane and look at
the Permissions tab. Does root have the Administrator role?
Did you install any other VMware products except VMware Server 2.0? I
have seen conflicts before when the vSphere SDK or VIX API was
installed over VMware Server.
At any rate, you'll need to be able to manually run the vmware-vim-cmd
commands before attempting to capture the image with VCL again. When
logged in to the management node shell, do either of these commands
work?:
vmware-vim-cmd hostsvc/datastore/listsummary
ssh -i /etc/vcl/vcl.key alpha-vcl 'vmware-vim-cmd hostsvc/datastore/listsummary'
If neither works, try restarting the vmware service. If the commands
still don't work, try rerunning vmware-config.pl.
-Andy
On Mon, Apr 9, 2012 at 6:10 PM, B Hartlieb <har...@rpi.edu> wrote:
> Hi All,
>
> Being a newbie, I need some help in capturing my first Base Image.
>
> I have VMware Server 2.0, with a free license, installed on the same RHEL
> 5.8 hardware as my Management Node. I am not using the vSphere_SDK software.
> I am only using SSH. I believe that, I do not need the SDK in this
> situation. Is that true? My guest OS (winXP) is running, and I seem to be
> able to ssh to the guest with out a password. I tried my VM Host Profile
> with and without a password.
>
> VM Host Profile
> Select a profile to configure:
> Name: VMware Server 2.x - local storage
> Type: vmware
> Image: no image
> Repository Path: /vms/repository
> Data Store Path: /vms/datastore1
> VM Path: (empty)
> Virtual Switch 0: HostOnly
> Virtual Switch 1: Bridged
> VM Disk: localdisk
> Generate eth0 MAC: No
> Generate eth1 MAC: No
> Username: root
> Password: *****
> Confirm: ***** match
>
>
> Yet, VIM_SSH.pm it seems to be throwing a failed to login error. Which I
> think is my first major error message. I am assuming at this point, that
> vmi_ssh is trying to sign into the VMware Server.
>
> 16:05:55|3559|12:12|image|VIM_SSH.pm:_get_datastore_info(490)|unable to
> determine datastore names, unexpected output returned, VIM command
> arguments: 'hostsvc/datastore/listsummary', output:
> |3559|12:12|image| Failed to login: vim.fault.NoPermission
>
> Any ideas, anyone?
>
> If I do need the vSphere_SDK for perl, what version do I need for VMware
> Server 2.0?
>
> A more complete log follows.
> Thanks,
>
> /Brian
>
> --
> --
> Brian Hartlieb
> System Administrator
> TIS - Rensselaer at Hartford
> Rensselaer Polytechnic Institute (RPI)
> (860) 548-5459
> har...@rpi.edu
>
>
> [root@alpha-vcl ~]# ssh -o CheckHostIP=no -o StrictHostKeyChecking=no -o
> BatchMode=no -i /etc/vcl/vcl.key 10.5.120.11
> Warning: Permanently added '10.5.120.11' (RSA) to the list of known hosts.
> Last login: Mon Apr 9 16:02:39 2012 from 10.5.120.1
>
> root@winxp3 ~
> $ exit
> logout
> Connection to 10.5.120.11 closed.
> [root@alpha-vcl ~]# ssh 10.5.120.11
> Warning: Permanently added '10.5.120.11' (RSA) to the list of known hosts.
> Permission denied (publickey,keyboard-interactive).
> [root@alpha-vcl ~]#
> [root@alpha-vcl ~]# /usr/local/vcl/bin/vcld -setup
> VCL Management Node Setup
> ----------------------------------------------------------------------------
> Select a module to configure:
> 1. VCL Base Module
> 2. VCL Image State Module
> 3. Windows OS Module
>
> [vcld]
> Make a selection (1-3, 'c' to cancel): 2
> ----------------------------------------------------------------------------
> Choose an operation:
> 1. Capture Base Image
>
> [vcld/Image]
> Make a selection (1, 'c' to cancel): 1
>
> Enter the VCL login name or ID of the user who will own the image: [admin]:
>
> User who will own the image: admin (ID: 1)
>
> Enter the hostname or IP address of the computer to be captured: ('c' to
> cancel): 10.5.120.11
>
> Computer to be captured: vmguest-1 (ID: 2)
> Provisioning module: provisioning_vmware
> Install type: vmware
>
> Select the OS to be captured (install type: vmware):
> 1. Generic Linux (VMware)
> 2. Windows 2003 Server (VMware)
> 3. Windows 7 (VMware)
> 4. Windows Server 2008 (VMware)
> 5. Windows Vista (VMware)
> 6. Windows XP (VMware)
>
> [vcld/Image/Capture Base Image]
> Make a selection (1-6, 'c' to cancel): 6
>
> Selected OS: Windows XP (VMware)
>
> Image architecture:
> 1. x86
> 2. x86_64
>
> [vcld/Image/Capture Base Image]
> Make a selection (1-2, 'c' to cancel): 1
>
> Image architecture: x86
>
> Use Sysprep:
> 1. Yes
> 2. No
>
> [vcld/Image/Capture Base Image]
> Make a selection (1-2, 'c' to cancel): 2
>
> Use Sysprep: No
>
> Enter the name of the image to be captured: ('c' to cancel): WinXP Base
>
> Added new image to database: 'WinXP Base'
> image.name: vmwarewinxp-WinXPBase19-v0
> image.id: 19
> imagerevision.id: 16
> imagemeta.id: 15
> resource.id: 32
>
> ----------------------------------------------------------------------------
> Inserted imaging request to the database:
> request ID: 12
> reservation ID: 12
>
> This process will now display the contents of the vcld.log file if the vcld
> daemon is running. If you do not see many lines of additional output, exit
> this
> process, start the vcld daemon, and monitor the image capture process by
> running
> the command:
> tail -f /var/log/vcld.log | grep '12:12'
>
> ----------------------------------------------------------------------------
> 2012-04-09 16:05:30|3552|utils.pm:setup_get_array_choice(9947)|choices
> argument:
> 2012-04-09 16:05:32|3552|utils.pm:setup_get_array_choice(9947)|choices
> argument:
> 2012-04-09 16:05:35|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:05:35
> 2012-04-09 16:05:40|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:05:40
> 2012-04-09 16:05:41|3552|utils.pm:insert_request(8358)|inserted new reload
> request into request table, request id=12
> 2012-04-09 16:05:41|3552|utils.pm:insert_request(8389)|inserted new reload
> request into reservation table, reservation id=12
> 2012-04-09 16:05:45|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:05:45
> 2012-04-09
> 16:05:45|3519|12:12|image|utils.pm:reservation_being_processed(8938)|computerloadlog
> 'begin' entry does NOT exist for reservation 12
> 2012-04-09 16:05:45|3519|12:12|image|utils.pm:run_command(9010)|executed
> command: pgrep -fl 'vcld [0-9]+:12 ', pid: 3557, exit status: 1, output:
> 2012-04-09
> 16:05:45|3519|12:12|image|utils.pm:is_management_node_process_running(9192)|process
> is NOT running, identifier: 'vcld [0-9]+:12 '
> 2012-04-09
> 16:05:45|3519|12:12|image|utils.pm:reservation_being_processed(8959)|reservation
> is NOT currently being processed
> 2012-04-09 16:05:45|3519|12:12|image|vcld:main(278)|reservation 12 is NOT
> already being processed
> 2012-04-09
> 16:05:45|3519|12:12|image|utils.pm:get_request_info(4520)|standalone
> affiliation found: Local
> 2012-04-09 16:05:45|3519|12:12|image|vcld:main(283)|retrieved request
> information from database
> 2012-04-09
> 16:05:45|3519|12:12|image|DataStructure.pm:is_parent_reservation(991)|returning
> true: parent reservation ID for this request: 12
> 2012-04-09
> 16:05:45|3519|12:12|image|utils.pm:update_request_state(1991)|request 12
> state updated to: pending, laststate to: image
> 2012-04-09 16:05:45|3519|12:12|image|utils.pm:insertloadlog(3875)|inserted
> computer=2, begin, beginning to process, state is image
> 2012-04-09 16:05:45|3519|12:12|image|vcld:make_new_child(515)|loaded
> VCL::image module
> 2012-04-09 16:05:45|3559|12:12|image|vcld:make_new_child(555)|vcld
> environment variable set to 0 for this process
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'test' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'forimaging' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'reservation'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'userid' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'daterequested'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'RESERVATIONID'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'UPDATED' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'SUBIMAGE' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'CHECKTIME' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'state' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'laststate' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'PRELOADONLY'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'laststateid'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'user' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'id' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'PID' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'DURATION' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'PPID' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'datemodified'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set
> 'RESERVATIONCOUNT' key for VCL::image object from arguments
> 2012-04-09 16:05:45|3519|12:12|image|vcld:make_new_child(539)|current number
> of forked kids: 1
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'end' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'stateid' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'PARENTIMAGE'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'checkuser' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'preload' key
> for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'NOTICEINTERVAL'
> key for VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'start' key for
> VCL::image object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'logid' key for
> VCL::image object from arguments
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(361)|VCL::Module::OS::Linux::ManagementNode
> module loaded
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:new(196)|VCL::Module::OS::Linux::ManagementNode
> object created for image <not set>, address: 1802ab50
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_automethod(834)|data
> structure updated: $self->request_data->{reservation}{0}{computer}{hostname}
> |3559|12:12|image| computer_hostname = alpha-vcl.ewp.rpi.edu
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_automethod(834)|data
> structure updated: $self->request_data->{reservation}{0}{computer}{NODENAME}
> |3559|12:12|image| computer_node_name = alpha-vcl
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_automethod(834)|data
> structure updated:
> $self->request_data->{reservation}{0}{computer}{SHORTNAME}
> |3559|12:12|image| computer_short_name = alpha-vcl
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_automethod(834)|data
> structure updated:
> $self->request_data->{reservation}{0}{computer}{IPaddress}
> |3559|12:12|image| computer_ip_address = 129.5.80.51
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(366)|VCL::Module::OS::Linux::ManagementNode
> OS object created, address: 1802ab50
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(192)|VCL::image object
> created for state image, address: 17e256b0
> 2012-04-09 16:05:45|3559|12:12|image|State.pm:initialize(86)|obtained a
> database handle for this state process, stored as $ENV{dbh}
> 2012-04-09 16:05:45|3559|12:12|image|State.pm:check_image_os(762)|no
> corrections need to be made to image OS: vmwarewinxp
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:is_parent_reservation(991)|returning
> true: parent reservation ID for this request: 12
> 2012-04-09
> 16:05:45|3559|12:12|image|utils.pm:rename_vcld_process(7098)|reservation
> count: 1
> 2012-04-09
> 16:05:45|3559|12:12|image|utils.pm:rename_vcld_process(7117)|PARENTIMAGE: 1
> 2012-04-09
> 16:05:45|3559|12:12|image|utils.pm:rename_vcld_process(7118)|SUBIMAGE: 0
> 2012-04-09
> 16:05:45|3559|12:12|image|utils.pm:rename_vcld_process(7136)|renamed process
> to 'vcld 12:12 image vmguest-1>alpha-vcl.ewp.rpi.edu
> vmwarewinxp-WinXPBase19-v0 admin'
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:is_parent_reservation(991)|returning
> true: parent reservation ID for this request: 12
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:is_parent_reservation(991)|returning
> true: parent reservation ID for this request: 12
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_os_object(298)|VCL::Module::OS::Windows::Version_5::XP
> module loaded
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(335)|management node
> OS object has already been created, address: 1802ab50, returning 1
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:new(196)|VCL::Module::OS::Windows::Version_5::XP
> object created for image vmwarewinxp-WinXPBase19-v0, address: 1804eae0
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_os_object(304)|VCL::Module::OS::Windows::Version_5::XP
> OS object created for vmwarewinxp-WinXPBase19-v0, address: 1804eae0
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_provisioning_object(420)|VCL::Module::Provisioning::VMware::VMware
> module loaded
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(335)|management node
> OS object has already been created, address: 1802ab50, returning 1
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VMware
> object created for computer vmguest-1, address: 18516a70
> 2012-04-09 16:05:45|3559|12:12|image|VMware.pm:initialize(230)|initializing
> VCL::Module::Provisioning::VMware::VMware object
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(613)|computer ID
> argument was specified, retrieving data for computer ID: 1
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(643)|image
> ID argument was specified: 4, DataStructure object will contain image
> information for the production imagerevision of this image
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(660)|retrieved data
> for imagerevision ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(676)|retrieved data
> for image ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_datastructure(1190)|created
> DataStructure object for VM host: alpha-vcl
> 2012-04-09 16:05:45|3559|12:12|image|VMware.pm:initialize(249)|attempting to
> create OS object for the image currently loaded on the VM host: alpha-vcl
> |3559|12:12|image| image name: noimage
> |3559|12:12|image| OS module: VCL::Module::OS::Linux::UnixLab
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(613)|computer ID
> argument was specified, retrieving data for computer ID: 1
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(643)|image
> ID argument was specified: 4, DataStructure object will contain image
> information for the production imagerevision of this image
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(660)|retrieved data
> for imagerevision ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(676)|retrieved data
> for image ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_datastructure(1190)|created
> DataStructure object for VM host: alpha-vcl
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_os_object(1232)|attempting to
> load VM host OS module: VCL::Module::OS::Linux::UnixLab
> 2012-04-09 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_os_object(1238)|VM
> host OS module loaded: VCL::Module::OS::Linux::UnixLab
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(335)|management node
> OS object has already been created, address: 1802ab50, returning 1
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:new(196)|VCL::Module::OS::Linux::UnixLab
> object created for image noimage, address: 1888fe10
> 2012-04-09 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_os_object(1244)|VM
> host OS object created: VCL::Module::OS::Linux::UnixLab
> 2012-04-09 16:05:45|3559|12:12|image|OS.pm:is_ssh_responding(401)|alpha-vcl
> is responding to SSH, port 22: open, port 24: closed
> 2012-04-09 16:05:45|3559|12:12|image|VMware.pm:initialize(254)|OS on VM host
> alpha-vcl will be controlled using a VCL::Module::OS::Linux::UnixLab OS
> object
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(613)|computer ID
> argument was specified, retrieving data for computer ID: 1
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(643)|image
> ID argument was specified: 4, DataStructure object will contain image
> information for the production imagerevision of this image
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(660)|retrieved data
> for imagerevision ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(676)|retrieved data
> for image ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_datastructure(1190)|created
> DataStructure object for VM host: alpha-vcl
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_api_object(1293)|attempting
> to load VMware control module:
> VCL::Module::Provisioning::VMware::vSphere_SDK
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_api_object(1299)|loaded
> VMware control module: VCL::Module::Provisioning::VMware::vSphere_SDK
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'vmhost_data'
> key for VCL::Module::Provisioning::VMware::vSphere_SDK object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'vmhost_os' key
> for VCL::Module::Provisioning::VMware::vSphere_SDK object from arguments
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(335)|management node
> OS object has already been created, address: 1802ab50, returning 1
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vSphere_SDK
> object created for computer vmguest-1, address: 18882c50
> 2012-04-09 16:05:45|3559|12:12|image|vSphere_SDK.pm:initialize(1826)|vSphere
> SDK for Perl does not appear to be installed on this managment node, unable
> to load VMware vSphere SDK Perl modules
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_api_object(1313)|API object
> could not be created: VCL::Module::Provisioning::VMware::vSphere_SDK
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(613)|computer ID
> argument was specified, retrieving data for computer ID: 1
> 2012-04-09 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(643)|image
> ID argument was specified: 4, DataStructure object will contain image
> information for the production imagerevision of this image
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(660)|retrieved data
> for imagerevision ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|DataStructure.pm:_initialize(676)|retrieved data
> for image ID: 4
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_datastructure(1190)|created
> DataStructure object for VM host: alpha-vcl
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_api_object(1293)|attempting
> to load VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-04-09
> 16:05:45|3559|12:12|image|VMware.pm:get_vmhost_api_object(1299)|loaded
> VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'vmhost_data'
> key for VCL::Module::Provisioning::VMware::VIM_SSH object from arguments
> 2012-04-09 16:05:45|3559|12:12|image|Module.pm:new(172)|set 'vmhost_os' key
> for VCL::Module::Provisioning::VMware::VIM_SSH object from arguments
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:create_mn_os_object(335)|management node
> OS object has already been created, address: 1802ab50, returning 1
> 2012-04-09
> 16:05:45|3559|12:12|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VIM_SSH
> object created for computer vmguest-1, address: 188b39a0
> 2012-04-09 16:05:46|3559|12:12|image|VIM_SSH.pm:initialize(138)|VIM
> executable available on VM host: vmware-vim-cmd
> 2012-04-09
> 16:05:46|3559|12:12|image|VIM_SSH.pm:initialize(140)|VCL::Module::Provisioning::VMware::VIM_SSH
> object initialized
> 2012-04-09
> 16:05:46|3559|12:12|image|VMware.pm:get_vmhost_api_object(1320)|created API
> object: VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-04-09 16:05:46|3559|12:12|image|VMware.pm:initialize(278)|VMware on VM
> host alpha-vcl will be controlled using vim-cmd via SSH
> 2012-04-09 16:05:46|3559|12:12|image|VMware.pm:initialize(293)|VMware OS and
> API objects created for VM host alpha-vcl:
> |3559|12:12|image| VM host OS object type: VCL::Module::OS::Linux::UnixLab
> |3559|12:12|image| VMware API object type:
> VCL::Module::Provisioning::VMware::VIM_SSH
> 2012-04-09
> 16:05:47|3559|12:12|image|VMware.pm:get_vmhost_product_name(5405)|VMware
> product being used on VM host alpha-vcl.ewp.rpi.edu: 'VMware Server 2.0.2
> build-203138'
> 2012-04-09 16:05:47|3559|12:12|image|VMware.pm:initialize(307)|product:
> VMware Server 2.0.2 build-203138, OS object: VCL::Module::OS::Linux::UnixLab
> 2012-04-09
> 16:05:47|3559|12:12|image|VMware.pm:get_vmx_base_directory_path(2745)|determined
> vmx base directory path: /vms/datastore1
> 2012-04-09
> 16:05:47|3559|12:12|image|Linux.pm:file_exists(1404)|'/vms/datastore1'
> exists on alpha-vcl, files: 0, directories: 1, links: 0
> 2012-04-09 16:05:47|3559|12:12|image|VMware.pm:initialize(324)|not checking
> if vmdk base directory exists because it is the same as the vmx base
> directory: /vms/datastore1
> 2012-04-09
> 16:05:47|3559|12:12|image|Module.pm:create_provisioning_object(426)|VCL::Module::Provisioning::VMware::VMware
> provisioner object created for vmguest-1, address: 18516a70
> 2012-04-09 16:05:47|3559|12:12|image|State.pm:initialize(126)|returning 1
> 2012-04-09 16:05:47|3559|12:12|image|vcld:make_new_child(565)|VCL::image
> object created and initialized
> 2012-04-09 16:05:47|3559|12:12|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: vcl_adminu...@ewp.rpi.edu, VCL IMAGE Creation Started:
> vmwarewinxp-WinXPBase19-v0
> 2012-04-09 16:05:47|3559|12:12|image|Linux.pm:file_exists(1390)|file or
> directory does not exist on alpha-vcl:
> '/vms/datastore1/vmwarewinxp-WinXPBase19-v0/vmwarewinxp-WinXPBase19-v0.vmdk'
> 2012-04-09 16:05:47|3559|12:12|image|VMware.pm:does_image_exist(3915)|image
> does not exist in the non-persistent directory on the VM host
> 2012-04-09
> 16:05:47|3559|12:12|image|Linux.pm:file_exists(1404)|'/vms/repository'
> exists on alpha-vcl, files: 0, directories: 1, links: 0
> 2012-04-09
> 16:05:47|3559|12:12|image|VMware.pm:is_repository_mounted_on_vmhost(5485)|image
> repository is mounted on VM host alpha-vcl.ewp.rpi.edu: /vms/repository
> 2012-04-09
> 16:05:47|3559|12:12|image|VMware.pm:does_image_exist(3926)|checking if vmdk
> file exists in image repository mounted on VM host:
> alpha-vcl.ewp.rpi.edu:/vms/repository/vmwarewinxp-WinXPBase19-v0/vmwarewinxp-WinXPBase19-v0.vmdk
> 2012-04-09 16:05:47|3559|12:12|image|Linux.pm:file_exists(1390)|file or
> directory does not exist on alpha-vcl:
> '/vms/repository/vmwarewinxp-WinXPBase19-v0/vmwarewinxp-WinXPBase19-v0.vmdk'
> 2012-04-09 16:05:47|3559|12:12|image|VMware.pm:does_image_exist(3932)|vmdk
> file does not exist in image repository mounted on VM host:
> alpha-vcl.ewp.rpi.edu:/vms/repository/vmwarewinxp-WinXPBase19-v0/vmwarewinxp-WinXPBase19-v0.vmdk
> 2012-04-09 16:05:47|3559|12:12|image|image.pm:process(145)|image
> vmwarewinxp-WinXPBase19-v0 does not exist in the repository
> 2012-04-09 16:05:47|3559|12:12|image|DataStructure.pm:_automethod(834)|data
> structure updated: $self->request_data->{reservation}{12}{image}{lastupdate}
> |3559|12:12|image| image_lastupdate = 2012-04-09 16:05:47
> 2012-04-09 16:05:47|3559|12:12|image|DataStructure.pm:_automethod(834)|data
> structure updated:
> $self->request_data->{reservation}{12}{imagerevision}{datecreated}
> |3559|12:12|image| imagerevision_date_created = 2012-04-09 16:05:47
> 2012-04-09 16:05:47|3559|12:12|image|image.pm:process(161)|calling
> provisioning module's capture() subroutine
> 2012-04-09 16:05:49|3559|12:12|image|OS.pm:is_ssh_responding(401)|vmguest-1
> is responding to SSH, port 22: open, port 24: closed
> 2012-04-09 16:05:50|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:05:50
> 2012-04-09 16:05:51|3559|12:12|image|OS.pm:is_ssh_responding(401)|vmguest-1
> is responding to SSH, port 22: open, port 24: closed
> 2012-04-09 16:05:52|3559|12:12|image|Windows.pm:is_64_bit(8108)|32-bit
> Windows OS detected, PROCESSOR_IDENTIFIER: x86 Family 6 Model 44 Stepping 2,
> GenuineIntel
> 2012-04-09
> 16:05:52|3559|12:12|image|Windows.pm:get_system32_path(8152)|32-bit Windows
> OS installed on vmguest-1, using C:/Windows/System32
> 2012-04-09
> 16:05:52|3559|12:12|image|Windows.pm:get_network_configuration(4949)|attempting
> to retrieve network configuration information from vmguest-1
> 2012-04-09
> 16:05:52|3559|12:12|image|utils.pm:run_ssh_command(5380)|executing SSH
> command on vmguest-1:
> |3559|12:12|image| /usr/bin/ssh -i /etc/vcl/vcl.key -o
> StrictHostKeyChecking=no -l root -p 22 -x vmguest-1
> 'C:/Windows/System32/ipconfig.exe /all' 2>&1
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(4984)|found
> interface: Local Area Connection
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(4984)|found
> interface: Local Area Connection 2
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(5036)|saving
> network configuration in $self->{network_configuration}
> 2012-04-09
> 16:05:53|3559|12:12|image|DataStructure.pm:get_computer_private_ip_address(1581)|attempting
> to retrieve private IP address for computer: vmguest-1
> 2012-04-09
> 16:05:53|3559|12:12|image|DataStructure.pm:get_computer_private_ip_address(1585)|retrieved
> contents of /etc/hosts on this management node, contains 18 lines
> 2012-04-09
> 16:05:53|3559|12:12|image|DataStructure.pm:get_computer_private_ip_address(1645)|returning
> IP address from /etc/hosts file: 10.5.120.11
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(5075)|private
> interface found: Local Area Connection, description: VMware Accelerated AMD
> PCNet Adapter, address(es): 10.5.120.11
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_private_mac_address(5238)|returning
> private MAC address: 00-50-56-1A-01-01
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(5040)|network
> configuration has already been retrieved
> 2012-04-09
> 16:05:53|3559|12:12|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.5.120.11
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(5075)|private
> interface found: Local Area Connection, description: VMware Accelerated AMD
> PCNet Adapter, address(es): 10.5.120.11
> 2012-04-09 16:05:53|3559|12:12|image|utils.pm:is_valid_ip_address(9266)|IP
> address is valid: 129.5.120.48
> 2012-04-09
> 16:05:53|3559|12:12|image|utils.pm:is_public_ip_address(9412)|public IP
> address: 129.5.120.48, returning 1
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_network_configuration(5107)|public
> interface found with default gateway: Local Area Connection 2, address(es):
> 129.5.120.48, default gateway: 129.5.120.1
> 2012-04-09
> 16:05:53|3559|12:12|image|Windows.pm:get_public_mac_address(5268)|returning
> public MAC address: 00-50-56-1A-01-02
> 2012-04-09
> 16:05:53|3559|12:12|image|VMware.pm:get_vmx_file_paths(4331)|attempting to
> find existing vmx files on the VM host
> 2012-04-09
> 16:05:53|3559|12:12|image|VMware.pm:get_vmx_base_directory_path(2745)|determined
> vmx base directory path: /vms/datastore1
> 2012-04-09 16:05:53|3559|12:12|image|Linux.pm:find_files(2074)|attempting to
> find files on alpha-vcl, base directory path: '/vms/datastore1/', pattern:
> *.vmx, command: find "/vms/datastore1/" -iname "*.vmx"
> 2012-04-09 16:05:53|3559|12:12|image|Linux.pm:find_files(2092)|matching file
> count: 2
> 2012-04-09
> 16:05:53|3559|12:12|image|VMware.pm:get_vmx_file_paths(4337)|found 2 vmx
> files under /vms/datastore1
> |3559|12:12|image| /vms/datastore1/Windows XP Base/Windows XP Base.vmx
> |3559|12:12|image| /vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx
> 2012-04-09 16:05:53|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(193)|vim-cmd
> call count: 1 (vmsvc/getallvms)
> 2012-04-09 16:05:54|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(208)|executed
> command on VM host alpha-vcl: vmware-vim-cmd vmsvc/getallvms
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:54|3559|12:12|image|VIM_SSH.pm:_get_vm_list(246)|unable to determine
> VM IDs, unexpected output returned, VIM command arguments:
> 'vmsvc/getallvms', output:
> |3559|12:12|image| Failed to login: vim.fault.NoPermission
> |3559|12:12|image| ( 0) VIM_SSH.pm, _get_vm_list (line: 246)
> |3559|12:12|image| (-1) VIM_SSH.pm, get_registered_vms (line: 826)
> |3559|12:12|image| (-2) VMware.pm, get_vmx_file_paths (line: 4340)
> |3559|12:12|image| (-3) VMware.pm, get_active_vmx_file_path (line: 774)
> |3559|12:12|image| (-4) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-5) image.pm, process (line: 162)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:54|3559|12:12|image|VIM_SSH.pm:get_registered_vms(828)|unable to
> retrieve registered VMs, failed to retrieve list of registered VMs and their
> IDs
> |3559|12:12|image| ( 0) VIM_SSH.pm, get_registered_vms (line: 828)
> |3559|12:12|image| (-1) VMware.pm, get_vmx_file_paths (line: 4340)
> |3559|12:12|image| (-2) VMware.pm, get_active_vmx_file_path (line: 774)
> |3559|12:12|image| (-3) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-4) image.pm, process (line: 162)
> |3559|12:12|image| (-5) vcld, make_new_child (line: 568)
> 2012-04-09
> 16:05:54|3559|12:12|image|VMware.pm:get_vmx_file_paths(4341)|found 0
> registered vmx files
> 2012-04-09
> 16:05:54|3559|12:12|image|VMware.pm:get_vmx_file_paths(4346)|found 2 vmx
> files on VM host
> |3559|12:12|image| /vms/datastore1/Windows XP Base/Windows XP Base.vmx
> |3559|12:12|image| /vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx
> 2012-04-09
> 16:05:54|3559|12:12|image|VMware.pm:get_active_vmx_file_path(775)|retrieved
> vmx file paths currently residing on the VM host:
> |3559|12:12|image| /vms/datastore1/Windows XP Base/Windows XP Base.vmx
> |3559|12:12|image| /vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx
> 2012-04-09
> 16:05:54|3559|12:12|image|VMware.pm:get_active_vmx_file_path(782)|sorted vmx
> file paths so that directories containing vmguest-1 are checked first:
> |3559|12:12|image| /vms/datastore1/Windows XP Base/Windows XP Base.vmx
> |3559|12:12|image| /vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx
> 2012-04-09 16:05:54|3559|12:12|image|VMware.pm:get_vmx_info(4405)|attempting
> to retrieve info from vmx file: /vms/datastore1/Windows XP Base/Windows XP
> Base.vmx
> 2012-04-09
> 16:05:54|3559|12:12|image|Linux.pm:get_file_contents(1626)|retrieved 49
> lines from file on alpha-vcl: '/vms/datastore1/Windows XP Base/Windows XP
> Base.vmx'
> 2012-04-09 16:05:54|3559|12:12|image|VMware.pm:get_vmx_info(4439)|vmx file
> does not contain a computer_id value, attempting to determine matching
> computer
> 2012-04-09 16:05:54|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(193)|vim-cmd
> call count: 2 (hostsvc/datastore/listsummary)
> 2012-04-09 16:05:55|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:05:55
> 2012-04-09 16:05:55|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(208)|executed
> command on VM host alpha-vcl: vmware-vim-cmd hostsvc/datastore/listsummary
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:55|3559|12:12|image|VIM_SSH.pm:_get_datastore_info(490)|unable to
> determine datastore names, unexpected output returned, VIM command
> arguments: 'hostsvc/datastore/listsummary', output:
> |3559|12:12|image| Failed to login: vim.fault.NoPermission
> |3559|12:12|image| ( 0) VIM_SSH.pm, _get_datastore_info (line: 490)
> |3559|12:12|image| (-1) VMware.pm, get_datastore_info (line: 5524)
> |3559|12:12|image| (-2) VMware.pm, _get_datastore_name (line: 5825)
> |3559|12:12|image| (-3) VMware.pm, _get_datastore_path (line: 5638)
> |3559|12:12|image| (-4) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-5) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:55|3559|12:12|image|VMware.pm:get_datastore_info(5527)|failed to
> retrieve datastore info from VCL::Module::Provisioning::VMware::VIM_SSH API
> object
> |3559|12:12|image| ( 0) VMware.pm, get_datastore_info (line: 5527)
> |3559|12:12|image| (-1) VMware.pm, _get_datastore_name (line: 5825)
> |3559|12:12|image| (-2) VMware.pm, _get_datastore_path (line: 5638)
> |3559|12:12|image| (-3) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-4) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-5) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:55|3559|12:12|image|VMware.pm:_get_datastore_name(5848)|unable to
> determine datastore name from path: '/vms/datastore1/Windows XP Base/Windows
> XP Base.vmx', path does not begin with any of the datastore paths:
> |3559|12:12|image| ( 0) VMware.pm, _get_datastore_name (line: 5848)
> |3559|12:12|image| (-1) VMware.pm, _get_datastore_path (line: 5638)
> |3559|12:12|image| (-2) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-3) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-4) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-5) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:55|3559|12:12|image|VMware.pm:_get_datastore_path(5640)|unable to
> determine datastore path, failed to determine datastore name:
> /vms/datastore1/Windows XP Base/Windows XP Base.vmx
> |3559|12:12|image| ( 0) VMware.pm, _get_datastore_path (line: 5640)
> |3559|12:12|image| (-1) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-2) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-3) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-4) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| (-5) VMware.pm, capture (line: 467)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:55|3559|12:12|image|VMware.pm:_get_parent_directory_name(5963)|unable
> to determine parent directory name, path argument could not be converted to
> a datastore path: '/vms/datastore1/Windows XP Base/Windows XP Base.vmx'
> |3559|12:12|image| ( 0) VMware.pm, _get_parent_directory_name (line: 5963)
> |3559|12:12|image| (-1) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-2) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-3) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| (-4) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-5) image.pm, process (line: 162)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:55|3559|12:12|image|VMware.pm:_get_vmx_file_path_computer_name(6150)|unable
> to determine computer name from path '/vms/datastore1/Windows XP
> Base/Windows XP Base.vmx', directory name could not be determined from path
> |3559|12:12|image| ( 0) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6150)
> |3559|12:12|image| (-1) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-2) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| (-3) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-4) image.pm, process (line: 162)
> |3559|12:12|image| (-5) vcld, make_new_child (line: 568)
> 2012-04-09 16:05:55|3559|12:12|image|VMware.pm:get_vmx_info(4453)|unable to
> determine computer name from vmx file path: '/vms/datastore1/Windows XP
> Base/Windows XP Base.vmx'
> 2012-04-09 16:05:55|3559|12:12|image|VMware.pm:get_vmx_info(4462)|ignoring
> ide1:0, filename property not set
> 2012-04-09 16:05:55|3559|12:12|image|VMware.pm:get_vmx_info(4484)|vmdk path
> appears to be relative: Windows XP Base.vmdk, prepending the vmx directory:
> /vms/datastore1/Windows XP Base/Windows XP Base.vmdk
> 2012-04-09
> 16:05:55|3559|12:12|image|VMware.pm:get_active_vmx_file_path(812)|comparing
> MAC addresses
> |3559|12:12|image| used by vmguest-1:
> |3559|12:12|image| 0050561a0101
> |3559|12:12|image| 0050561a0102
> |3559|12:12|image| configured in Windows XP Base.vmx:
> |3559|12:12|image| 000c29be1c01
> |3559|12:12|image| 000c29be1c0b
> |3559|12:12|image| 0050561a0101
> |3559|12:12|image| 0050561a0102
> 2012-04-09 16:05:55|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(193)|vim-cmd
> call count: 3 (vmsvc/getallvms)
> 2012-04-09 16:05:56|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(208)|executed
> command on VM host alpha-vcl: vmware-vim-cmd vmsvc/getallvms
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:56|3559|12:12|image|VIM_SSH.pm:_get_vm_list(246)|unable to determine
> VM IDs, unexpected output returned, VIM command arguments:
> 'vmsvc/getallvms', output:
> |3559|12:12|image| Failed to login: vim.fault.NoPermission
> |3559|12:12|image| ( 0) VIM_SSH.pm, _get_vm_list (line: 246)
> |3559|12:12|image| (-1) VIM_SSH.pm, get_registered_vms (line: 826)
> |3559|12:12|image| (-2) VMware.pm, is_vm_registered (line: 3738)
> |3559|12:12|image| (-3) VMware.pm, get_active_vmx_file_path (line: 821)
> |3559|12:12|image| (-4) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-5) image.pm, process (line: 162)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:56|3559|12:12|image|VIM_SSH.pm:get_registered_vms(828)|unable to
> retrieve registered VMs, failed to retrieve list of registered VMs and their
> IDs
> |3559|12:12|image| ( 0) VIM_SSH.pm, get_registered_vms (line: 828)
> |3559|12:12|image| (-1) VMware.pm, is_vm_registered (line: 3738)
> |3559|12:12|image| (-2) VMware.pm, get_active_vmx_file_path (line: 821)
> |3559|12:12|image| (-3) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-4) image.pm, process (line: 162)
> |3559|12:12|image| (-5) vcld, make_new_child (line: 568)
> 2012-04-09 16:05:56|3559|12:12|image|VMware.pm:is_vm_registered(3747)|VM is
> not registered: '/vms/datastore1/Windows XP Base/Windows XP Base.vmx'
> 2012-04-09
> 16:05:56|3559|12:12|image|VMware.pm:get_active_vmx_file_path(822)|ignoring
> Windows XP Base.vmx because the VM is not registered
> 2012-04-09 16:05:56|3559|12:12|image|VMware.pm:get_vmx_info(4405)|attempting
> to retrieve info from vmx file: /vms/datastore1/Windows XP Base/t2/Windows
> XP Base.vmx
> 2012-04-09
> 16:05:56|3559|12:12|image|Linux.pm:get_file_contents(1626)|retrieved 48
> lines from file on alpha-vcl: '/vms/datastore1/Windows XP Base/t2/Windows XP
> Base.vmx'
> 2012-04-09 16:05:56|3559|12:12|image|VMware.pm:get_vmx_info(4439)|vmx file
> does not contain a computer_id value, attempting to determine matching
> computer
> 2012-04-09 16:05:56|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(193)|vim-cmd
> call count: 4 (hostsvc/datastore/listsummary)
> 2012-04-09 16:05:57|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(208)|executed
> command on VM host alpha-vcl: vmware-vim-cmd hostsvc/datastore/listsummary
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:57|3559|12:12|image|VIM_SSH.pm:_get_datastore_info(490)|unable to
> determine datastore names, unexpected output returned, VIM command
> arguments: 'hostsvc/datastore/listsummary', output:
> |3559|12:12|image| Failed to login: vim.fault.NoPermission
> |3559|12:12|image| ( 0) VIM_SSH.pm, _get_datastore_info (line: 490)
> |3559|12:12|image| (-1) VMware.pm, get_datastore_info (line: 5524)
> |3559|12:12|image| (-2) VMware.pm, _get_datastore_name (line: 5825)
> |3559|12:12|image| (-3) VMware.pm, _get_datastore_path (line: 5638)
> |3559|12:12|image| (-4) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-5) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:57|3559|12:12|image|VMware.pm:get_datastore_info(5527)|failed to
> retrieve datastore info from VCL::Module::Provisioning::VMware::VIM_SSH API
> object
> |3559|12:12|image| ( 0) VMware.pm, get_datastore_info (line: 5527)
> |3559|12:12|image| (-1) VMware.pm, _get_datastore_name (line: 5825)
> |3559|12:12|image| (-2) VMware.pm, _get_datastore_path (line: 5638)
> |3559|12:12|image| (-3) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-4) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-5) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:57|3559|12:12|image|VMware.pm:_get_datastore_name(5848)|unable to
> determine datastore name from path: '/vms/datastore1/Windows XP
> Base/t2/Windows XP Base.vmx', path does not begin with any of the datastore
> paths:
> |3559|12:12|image| ( 0) VMware.pm, _get_datastore_name (line: 5848)
> |3559|12:12|image| (-1) VMware.pm, _get_datastore_path (line: 5638)
> |3559|12:12|image| (-2) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-3) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-4) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-5) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:57|3559|12:12|image|VMware.pm:_get_datastore_path(5640)|unable to
> determine datastore path, failed to determine datastore name:
> /vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx
> |3559|12:12|image| ( 0) VMware.pm, _get_datastore_path (line: 5640)
> |3559|12:12|image| (-1) VMware.pm, _get_parent_directory_name (line: 5961)
> |3559|12:12|image| (-2) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-3) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-4) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| (-5) VMware.pm, capture (line: 467)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:57|3559|12:12|image|VMware.pm:_get_parent_directory_name(5963)|unable
> to determine parent directory name, path argument could not be converted to
> a datastore path: '/vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx'
> |3559|12:12|image| ( 0) VMware.pm, _get_parent_directory_name (line: 5963)
> |3559|12:12|image| (-1) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6148)
> |3559|12:12|image| (-2) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-3) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| (-4) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-5) image.pm, process (line: 162)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:57|3559|12:12|image|VMware.pm:_get_vmx_file_path_computer_name(6150)|unable
> to determine computer name from path '/vms/datastore1/Windows XP
> Base/t2/Windows XP Base.vmx', directory name could not be determined from
> path
> |3559|12:12|image| ( 0) VMware.pm, _get_vmx_file_path_computer_name (line:
> 6150)
> |3559|12:12|image| (-1) VMware.pm, get_vmx_info (line: 4441)
> |3559|12:12|image| (-2) VMware.pm, get_active_vmx_file_path (line: 792)
> |3559|12:12|image| (-3) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-4) image.pm, process (line: 162)
> |3559|12:12|image| (-5) vcld, make_new_child (line: 568)
> 2012-04-09 16:05:57|3559|12:12|image|VMware.pm:get_vmx_info(4453)|unable to
> determine computer name from vmx file path: '/vms/datastore1/Windows XP
> Base/t2/Windows XP Base.vmx'
> 2012-04-09 16:05:57|3559|12:12|image|VMware.pm:get_vmx_info(4462)|ignoring
> ide1:0, filename property not set
> 2012-04-09 16:05:57|3559|12:12|image|VMware.pm:get_vmx_info(4484)|vmdk path
> appears to be relative: Windows XP Base.vmdk, prepending the vmx directory:
> /vms/datastore1/Windows XP Base/t2/Windows XP Base.vmdk
> 2012-04-09
> 16:05:57|3559|12:12|image|VMware.pm:get_active_vmx_file_path(812)|comparing
> MAC addresses
> |3559|12:12|image| used by vmguest-1:
> |3559|12:12|image| 0050561a0101
> |3559|12:12|image| 0050561a0102
> |3559|12:12|image| configured in Windows XP Base.vmx:
> |3559|12:12|image| 000c29be1c01
> |3559|12:12|image| 000c29be1c0b
> |3559|12:12|image| 0050561a0101
> 2012-04-09 16:05:57|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(193)|vim-cmd
> call count: 5 (vmsvc/getallvms)
> 2012-04-09 16:05:58|3559|12:12|image|VIM_SSH.pm:_run_vim_cmd(208)|executed
> command on VM host alpha-vcl: vmware-vim-cmd vmsvc/getallvms
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:58|3559|12:12|image|VIM_SSH.pm:_get_vm_list(246)|unable to determine
> VM IDs, unexpected output returned, VIM command arguments:
> 'vmsvc/getallvms', output:
> |3559|12:12|image| Failed to login: vim.fault.NoPermission
> |3559|12:12|image| ( 0) VIM_SSH.pm, _get_vm_list (line: 246)
> |3559|12:12|image| (-1) VIM_SSH.pm, get_registered_vms (line: 826)
> |3559|12:12|image| (-2) VMware.pm, is_vm_registered (line: 3738)
> |3559|12:12|image| (-3) VMware.pm, get_active_vmx_file_path (line: 821)
> |3559|12:12|image| (-4) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-5) image.pm, process (line: 162)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:58|3559|12:12|image|VIM_SSH.pm:get_registered_vms(828)|unable to
> retrieve registered VMs, failed to retrieve list of registered VMs and their
> IDs
> |3559|12:12|image| ( 0) VIM_SSH.pm, get_registered_vms (line: 828)
> |3559|12:12|image| (-1) VMware.pm, is_vm_registered (line: 3738)
> |3559|12:12|image| (-2) VMware.pm, get_active_vmx_file_path (line: 821)
> |3559|12:12|image| (-3) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-4) image.pm, process (line: 162)
> |3559|12:12|image| (-5) vcld, make_new_child (line: 568)
> 2012-04-09 16:05:58|3559|12:12|image|VMware.pm:is_vm_registered(3747)|VM is
> not registered: '/vms/datastore1/Windows XP Base/t2/Windows XP Base.vmx'
> 2012-04-09
> 16:05:58|3559|12:12|image|VMware.pm:get_active_vmx_file_path(822)|ignoring
> Windows XP Base.vmx because the VM is not registered
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:58|3559|12:12|image|VMware.pm:get_active_vmx_file_path(840)|did not
> find any vmx files on the VM host containing a MAC address matching
> vmguest-1
> |3559|12:12|image| ( 0) VMware.pm, get_active_vmx_file_path (line: 840)
> |3559|12:12|image| (-1) VMware.pm, capture (line: 467)
> |3559|12:12|image| (-2) image.pm, process (line: 162)
> |3559|12:12|image| (-3) vcld, make_new_child (line: 568)
> |3559|12:12|image| (-4) vcld, main (line: 346)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:58|3559|12:12|image|VMware.pm:capture(469)|failed to determine the vmx
> file path actively being used by VM vmguest-1
> |3559|12:12|image| ( 0) VMware.pm, capture (line: 469)
> |3559|12:12|image| (-1) image.pm, process (line: 162)
> |3559|12:12|image| (-2) vcld, make_new_child (line: 568)
> |3559|12:12|image| (-3) vcld, main (line: 346)
> |3559|12:12|image| ---- WARNING ----
> |3559|12:12|image| 2012-04-09
> 16:05:58|3559|12:12|image|image.pm:process(166)|vmwarewinxp-WinXPBase19-v0
> image failed to be captured by provisioning module
> |3559|12:12|image| ( 0) image.pm, process (line: 166)
> |3559|12:12|image| (-1) vcld, make_new_child (line: 568)
> |3559|12:12|image| (-2) vcld, main (line: 346)
> 2012-04-09
> 16:05:58|3559|12:12|image|DataStructure.pm:get_computer_private_ip_address(1557)|returning
> private IP address previously retrieved: 10.5.120.11
> 2012-04-09 16:05:58|3559|12:12|image|utils.pm:is_inblockrequest(6163)|zero
> rows were returned from database select
> 2012-04-09
> 16:05:58|3559|12:12|image|DataStructure.pm:get_image_affiliation_name(2035)|image
> owner id: 1
> 2012-04-09 16:05:58|3559|12:12|image|utils.pm:getnewdbh(2709)|database
> requested (information_schema) does not match handle stored in $ENV{dbh}
> (vcl:hcr08672.ewp.rpi.edu)
> 2012-04-09 16:05:58|3559|12:12|image|utils.pm:getnewdbh(2760)|database
> handle stored in $ENV{dbh}
> 2012-04-09
> 16:05:58|3559|12:12|image|DataStructure.pm:retrieve_user_data(1352)|attempting
> to retrieve and store data for user: user.id = '1'
> 2012-04-09 16:05:58|3559|12:12|image|utils.pm:getnewdbh(2709)|database
> requested (vcl) does not match handle stored in $ENV{dbh}
> (information_schema:hcr08672.ewp.rpi.edu)
> 2012-04-09 16:05:58|3559|12:12|image|utils.pm:getnewdbh(2760)|database
> handle stored in $ENV{dbh}
> 2012-04-09
> 16:05:58|3559|12:12|image|DataStructure.pm:retrieve_user_data(1415)|data has
> been retrieved for user: admin (id: 1)
> 2012-04-09 16:05:59|3559|12:12|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: vcl_adminu...@ewp.rpi.edu, PROBLEM --
> 12:12|image|image.pm|vmguest-1>alpha-vcl.ewp.rpi.edu|vmwarewinxp-WinXPBase19-v0|admin
> |3559|12:12|image| ---- CRITICAL ----
> |3559|12:12|image| 2012-04-09
> 16:05:58|3559|12:12|image|image.pm:reservation_failed(385)|vmwarewinxp-WinXPBase19-v0
> image creation failed
> |3559|12:12|image| ( 0) image.pm, reservation_failed (line: 385)
> |3559|12:12|image| (-1) image.pm, process (line: 167)
> |3559|12:12|image| (-2) vcld, make_new_child (line: 568)
> |3559|12:12|image| (-3) vcld, main (line: 346)
> 2012-04-09 16:05:59|3559|12:12|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: root@localhost, VCL -- NOTICE DELAY Image Creation WinXP Base
> 2012-04-09 16:05:59|3559|12:12|image|utils.pm:mail(1255)|SUCCESS -- Sending
> mail To: vcl_adminu...@ewp.rpi.edu, VCL -- NOTICE FAILED Image Creation
> WinXP Base
> 2012-04-09
> 16:05:59|3559|12:12|image|utils.pm:update_request_state(1991)|request 12
> state updated to: maintenance, laststate to: image
> 2012-04-09
> 16:05:59|3559|12:12|image|image.pm:reservation_failed(437)|request state set
> to maintenance, laststate to image
> 2012-04-09
> 16:05:59|3559|12:12|image|utils.pm:update_computer_state(2033)|computer 2
> state updated to: maintenance
> 2012-04-09
> 16:05:59|3559|12:12|image|image.pm:reservation_failed(445)|vmguest-1 state
> set to maintenance
> 2012-04-09
> 16:05:59|3559|12:12|image|image.pm:reservation_failed(452)|exiting
> 2012-04-09 16:05:59|3559|12:12|image|State.pm:DESTROY(829)|VCL::image
> destructor called, address: 17e256b0
> 2012-04-09
> 16:05:59|3559|12:12|image|utils.pm:delete_computerloadlog_reservation(6742)|removing
> computerloadlog entries matching loadstate = begin
> 2012-04-09
> 16:05:59|3559|12:12|image|utils.pm:delete_computerloadlog_reservation(6789)|deleted
> rows from computerloadlog for reservation id=12
> 2012-04-09 16:05:59|3559|12:12|image|State.pm:DESTROY(848)|number of
> database handles state process created: 3
> 2012-04-09 16:05:59|3559|12:12|image|State.pm:DESTROY(876)|VCL::image
> process duration: 14 seconds
> 2012-04-09 16:05:59|3559|12:12|image|VIM_SSH.pm:DESTROY(1685)|vim-cmd call
> count: 5
> 2012-04-09 16:05:59|3519|vcld:REAPER(718)|VCL process exited for reservation
> 12, PID: 3559, signal: CHLD
> 2012-04-09 16:05:59|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:05:59
> 2012-04-09 16:06:04|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:06:04
> 2012-04-09 16:06:09|3519|vcld:main(167)|lastcheckin time updated for
> management node 1: 2012-04-09 16:06:09
>
> [root@alpha-vcl ~]#
>
> --
> --
> Brian Hartlieb
> System Administrator
> TIS - Rensselaer at Hartford
> Rensselaer Polytechnic Institute (RPI)
> (860) 548-5459
> har...@rpi.edu
