Hi Michael and team,
Could you share your vmware host server and vmware profile information
that you have stored in your setup? Based on the log output there
might be some missing information or it's not setup correctly.
Since this is a public list, if there are any public IP address or
anything important feel free to obscure that info or send to me
privately.
Thanks,
Aaron
On Wed, Jun 20, 2012 at 10:01 AM, Michael Jinks <mji...@uchicago.edu> wrote:
> We're using 2.2.1. When I downloaded the package it was the only
> release I could find without going to svn.
>
>
> On Wed, Jun 20, 2012 at 08:48:01AM -0400, Aaron Peeler wrote:
>> Hello Michael,
>>
>> Which version are you using? VCL 2.2.1 or the pre-release of 2.3? The
>> execute subroutine is not implemented is concerning.
>>
>> Thanks,
>> Aaron
>>
>> On Tue, Jun 19, 2012 at 7:53 PM, Michael Jinks <mji...@uchicago.edu> wrote:
>> > Hi List. ?As threatened, here's the tale of our attempt to capture our
>> > first Windows image. ?As with our Linux capture, it appears that the VM
>> > disk image is being copied into our Data and Repository paths, but
>> > something goes wrong later in the process, but the warnings we find in
>> > the log are different for our Windows image than for the Linux one.
>> >
>> > As before, I'll paste the full log from the "PROBLEM" mail below, but it
>> > looks like this is significant:
>> >
>> > ?|19609|20:20|image| ---- WARNING ----
>> > ?|19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|VIM_SSH.pm:initialize(112)|required VM host OS
>> > subroutine is not implemented: execute
>> > ?|19609|20:20|image| ( 0) VIM_SSH.pm, initialize (line: 112)
>> > ?|19609|20:20|image| (-1) Module.pm, new (line: 207)
>> > ?|19609|20:20|image| (-2) VMware.pm, (eval) (line: 1303)
>> > ?|19609|20:20|image| (-3) VMware.pm, get_vmhost_api_object (line: 1303)
>> > ?|19609|20:20|image| (-4) VMware.pm, initialize (line: 278)
>> > ?|19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > ?2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1313)|API
>> > object could not be created: VCL::Module::Provisioning::VMware::VIM_SSH
>> >
>> > This looks to me like there must be something missing, maybe within the
>> > Windows VM itself? ?Did we leave out a package somewhere?
>> >
>> > Thanks,
>> > -m
>> > --
>> > Michael Jinks :: mji...@uchicago.edu
>> > University of Chicago IT Services
>> >
>> > Complete log message follows:
>> >
>> > VCL::image object could not be created and initialized
>> > ------------------------------------------------------------------------
>> > time: 2012-06-19 14:36:58
>> > caller: vcld:make_new_child(571)
>> > ( 0) vcld, make_new_child (line: 571)
>> > (-1) vcld, main (line: 346)
>> > ------------------------------------------------------------------------
>> > management node: pilot-lab.uchicago.edu
>> > reservation PID: 19609
>> > parent vcld PID: 2491
>> >
>> > request ID: 20
>> > reservation ID: 20
>> > request state/laststate: image/image
>> > request start time: 2012-06-19 14:36:50
>> > request end time: 2012-06-19 15:36:50
>> > for imaging: no
>> > log ID: none
>> >
>> > computer: vcl-win7-test
>> > computer id: 8
>> > computer type: virtualmachine
>> > computer eth0 MAC address: <undefined>
>> > computer eth1 MAC address: <undefined>
>> > computer private IP address: 10.50.84.16
>> > computer public IP address: 10.50.84.16
>> > computer in block allocation: no
>> > provisioning module: VCL::Module::Provisioning::VMware::VMware
>> >
>> > vm host: <undefined>
>> > vm host ID: <undefined>
>> > vm host computer ID: <undefined>
>> > vm profile: <undefined>
>> > vm profile VM path: <undefined>
>> > vm profile repository path: <undefined>
>> > vm profile datastore path: <undefined>
>> > vm profile disk type: <undefined>
>> >
>> > image: vmwarewin7-win7vmimage27-v0
>> > image display name: win7-vm-image
>> > image ID: 27
>> > image revision ID: 23
>> > image size: 1450 MB
>> > use Sysprep: no
>> > root access: yes
>> > image owner ID: 1
>> > image owner affiliation: Local
>> > image revision date created: 2012-06-19 14:36:50
>> > image revision production: yes
>> > OS module: VCL::Module::OS::Windows::Version_6::7
>> >
>> > user: admin
>> > user name: vcl admin
>> > user ID: 1
>> > user affiliation: Local
>> > ------------------------------------------------------------------------
>> > RECENT LOG ENTRIES FOR THIS PROCESS:
>> > |19609|20:20|image| (-1) Autoload.pm, __ANON__ (line: 80)
>> > |19609|20:20|image| (-2) VMware.pm, get_vmhost_datastructure (line: 1161)
>> > |19609|20:20|image| (-3) VMware.pm, get_vmhost_api_object (line: 1282)
>> > |19609|20:20|image| (-4) VMware.pm, initialize (line: 278)
>> > |19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:_automethod(812)|corresponding
>> > data has not been initialized for get_vmhost_profile_image_id:
>> > $self->request_data->{reservation}{20}{computer}{vmhost}{vmprofile}{imageid}
>> > |19609|20:20|image| ( 0) DataStructure.pm, _automethod (line: 812)
>> > |19609|20:20|image| (-1) Autoload.pm, __ANON__ (line: 80)
>> > |19609|20:20|image| (-2) VMware.pm, get_vmhost_datastructure (line: 1162)
>> > |19609|20:20|image| (-3) VMware.pm, get_vmhost_api_object (line: 1282)
>> > |19609|20:20|image| (-4) VMware.pm, initialize (line: 278)
>> > |19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_datastructure(1190)|created
>> > DataStructure object for VM host: vcl-win7-test
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1293)|attempting
>> > to load VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1299)|loaded
>> > VMware control module: VCL::Module::Provisioning::VMware::VIM_SSH
>> > 2012-06-19 14:36:58|19609|20:20|image|Module.pm:new(172)|set 'vmhost_data'
>> > key for VCL::Module::Provisioning::VMware::VIM_SSH object from arguments
>> > 2012-06-19 14:36:58|19609|20:20|image|Module.pm:new(172)|set 'vmhost_os'
>> > key for VCL::Module::Provisioning::VMware::VIM_SSH object from arguments
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|Module.pm:create_mn_os_object(335)|management
>> > node OS object has already been created, address: 37c3000, returning 1
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::VIM_SSH
>> > object created for computer vcl-win7-test, address: 25dc9b0
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|VIM_SSH.pm:initialize(112)|required VM host OS
>> > subroutine is not implemented: execute
>> > |19609|20:20|image| ( 0) VIM_SSH.pm, initialize (line: 112)
>> > |19609|20:20|image| (-1) Module.pm, new (line: 207)
>> > |19609|20:20|image| (-2) VMware.pm, (eval) (line: 1303)
>> > |19609|20:20|image| (-3) VMware.pm, get_vmhost_api_object (line: 1303)
>> > |19609|20:20|image| (-4) VMware.pm, initialize (line: 278)
>> > |19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1313)|API
>> > object could not be created: VCL::Module::Provisioning::VMware::VIM_SSH
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:_automethod(812)|corresponding
>> > data has not been initialized for get_vmhost_computer_id:
>> > $self->request_data->{reservation}{20}{computer}{vmhost}{computerid}
>> > |19609|20:20|image| ( 0) DataStructure.pm, _automethod (line: 812)
>> > |19609|20:20|image| (-1) Autoload.pm, __ANON__ (line: 80)
>> > |19609|20:20|image| (-2) VMware.pm, get_vmhost_datastructure (line: 1161)
>> > |19609|20:20|image| (-3) VMware.pm, get_vmhost_api_object (line: 1282)
>> > |19609|20:20|image| (-4) VMware.pm, initialize (line: 278)
>> > |19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:_automethod(812)|corresponding
>> > data has not been initialized for get_vmhost_profile_image_id:
>> > $self->request_data->{reservation}{20}{computer}{vmhost}{vmprofile}{imageid}
>> > |19609|20:20|image| ( 0) DataStructure.pm, _automethod (line: 812)
>> > |19609|20:20|image| (-1) Autoload.pm, __ANON__ (line: 80)
>> > |19609|20:20|image| (-2) VMware.pm, get_vmhost_datastructure (line: 1162)
>> > |19609|20:20|image| (-3) VMware.pm, get_vmhost_api_object (line: 1282)
>> > |19609|20:20|image| (-4) VMware.pm, initialize (line: 278)
>> > |19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_datastructure(1190)|created
>> > DataStructure object for VM host: vcl-win7-test
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1293)|attempting
>> > to load VMware control module:
>> > VCL::Module::Provisioning::VMware::vmware_cmd
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1299)|loaded
>> > VMware control module: VCL::Module::Provisioning::VMware::vmware_cmd
>> > 2012-06-19 14:36:58|19609|20:20|image|Module.pm:new(172)|set 'vmhost_data'
>> > key for VCL::Module::Provisioning::VMware::vmware_cmd object from arguments
>> > 2012-06-19 14:36:58|19609|20:20|image|Module.pm:new(172)|set 'vmhost_os'
>> > key for VCL::Module::Provisioning::VMware::vmware_cmd object from arguments
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|Module.pm:create_mn_os_object(335)|management
>> > node OS object has already been created, address: 37c3000, returning 1
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|Module.pm:new(200)|VCL::Module::Provisioning::VMware::vmware_cmd
>> > object created for computer vcl-win7-test, address: 25db108
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:get_vmhost_api_object(1309)|API
>> > object could not be created:
>> > VCL::Module::Provisioning::VMware::vmware_cmd, error:
>> > |19609|20:20|image| Can't locate object method "execute" via package
>> > "VCL::Module::OS::Windows::Version_6::7" at
>> > /usr/local/vcl/bin/../lib/VCL/Module/Provisioning/VMware/vmware_cmd.pm
>> > line 101.
>> > |19609|20:20|image| ( 0) VMware.pm, get_vmhost_api_object (line: 1309)
>> > |19609|20:20|image| (-1) VMware.pm, initialize (line: 278)
>> > |19609|20:20|image| (-2) Module.pm, new (line: 207)
>> > |19609|20:20|image| (-3) Module.pm, create_provisioning_object (line: 423)
>> > |19609|20:20|image| (-4) State.pm, initialize (line: 117)
>> > |19609|20:20|image| (-5) Module.pm, new (line: 207)
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|VMware.pm:initialize(285)|failed to create an
>> > object to control VMware on VM host: vcl-win7-test
>> > |19609|20:20|image| ( 0) VMware.pm, initialize (line: 285)
>> > |19609|20:20|image| (-1) Module.pm, new (line: 207)
>> > |19609|20:20|image| (-2) Module.pm, create_provisioning_object (line: 423)
>> > |19609|20:20|image| (-3) State.pm, initialize (line: 117)
>> > |19609|20:20|image| (-4) Module.pm, new (line: 207)
>> > |19609|20:20|image| (-5) vcld, make_new_child (line: 564)
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|Module.pm:create_provisioning_object(431)|provisioning
>> > object could not be created, returning 0
>> > |19609|20:20|image| ( 0) Module.pm, create_provisioning_object (line: 431)
>> > |19609|20:20|image| (-1) State.pm, initialize (line: 117)
>> > |19609|20:20|image| (-2) Module.pm, new (line: 207)
>> > |19609|20:20|image| (-3) vcld, make_new_child (line: 564)
>> > |19609|20:20|image| (-4) vcld, main (line: 346)
>> > |19609|20:20|image| ---- WARNING ----
>> > |19609|20:20|image| 2012-06-19
>> > 14:36:58|19609|20:20|image|State.pm:initialize(118)|failed to create
>> > provisioning object
>> > |19609|20:20|image| ( 0) State.pm, initialize (line: 118)
>> > |19609|20:20|image| (-1) Module.pm, new (line: 207)
>> > |19609|20:20|image| (-2) vcld, make_new_child (line: 564)
>> > |19609|20:20|image| (-3) vcld, main (line: 346)
>> > 2012-06-19 14:36:58|19609|20:20|image|State.pm:DESTROY(829)|VCL::image
>> > destructor called, address: 35a4ae8
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|utils.pm:delete_computerloadlog_reservation(6742)|removing
>> > computerloadlog entries matching loadstate = begin
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|utils.pm:delete_computerloadlog_reservation(6789)|deleted
>> > rows from computerloadlog for reservation id=20
>> > 2012-06-19 14:36:58|19609|20:20|image|State.pm:DESTROY(848)|number of
>> > database handles state process created: 1
>> > 2012-06-19 14:36:58|19609|20:20|image|State.pm:DESTROY(876)|VCL::image
>> > process duration: 6 seconds
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:get_computer_private_ip_address(1581)|attempting
>> > to retrieve private IP address for computer: vcl-win7-test
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:get_computer_private_ip_address(1585)|retrieved
>> > contents of /etc/hosts on this management node, contains 18 lines
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:get_computer_private_ip_address(1645)|returning
>> > IP address from /etc/hosts file: 10.50.84.16
>> > 2012-06-19 14:36:58|19609|20:20|image|utils.pm:getnewdbh(2703)|unable to
>> > use database handle stored in $ENV{dbh}
>> > 2012-06-19 14:36:58|19609|20:20|image|utils.pm:getnewdbh(2760)|database
>> > handle stored in $ENV{dbh}
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|utils.pm:is_inblockrequest(6163)|zero rows were
>> > returned from database select
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:get_image_affiliation_name(2035)|image
>> > owner id: 1
>> > 2012-06-19 14:36:58|19609|20:20|image|utils.pm:getnewdbh(2709)|database
>> > requested (information_schema) does not match handle stored in $ENV{dbh}
>> > (vcl:128.135.107.122)
>> > 2012-06-19 14:36:58|19609|20:20|image|utils.pm:getnewdbh(2760)|database
>> > handle stored in $ENV{dbh}
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:retrieve_user_data(1352)|attempting
>> > to retrieve and store data for user: user.id = '1'
>> > 2012-06-19 14:36:58|19609|20:20|image|utils.pm:getnewdbh(2709)|database
>> > requested (vcl) does not match handle stored in $ENV{dbh}
>> > (information_schema:128.135.107.122)
>> > 2012-06-19 14:36:58|19609|20:20|image|utils.pm:getnewdbh(2760)|database
>> > handle stored in $ENV{dbh}
>> > 2012-06-19
>> > 14:36:58|19609|20:20|image|DataStructure.pm:retrieve_user_data(1415)|data
>> > has been retrieved for user: admin (id: 1)
>> >
>>
>>
>>
>> --
>> Aaron Peeler
>> Program Manager
>> Virtual Computing Lab
>> NC State University
>>
>> All electronic mail messages in connection with State business which
>> are sent to or received by this account are subject to the NC Public
>> Records Law and may be disclosed to third parties.
>
> --
> Michael Jinks :: mji...@uchicago.edu :: 773-469-9688
> University of Chicago IT Services
--
Aaron Peeler
Program Manager
Virtual Computing Lab
NC State University
All electronic mail messages in connection with State business which
are sent to or received by this account are subject to the NC Public
Records Law and may be disclosed to third parties.
