Environment Details:
Foreman 1.6
VMware 5.5
VMWare Template: RHEL 6.5 x86_64 (minimal)
Issue:
I am trying to provision VM on vCenter using Foreman using the VMware
template mentioned above. I am able to get the VM created but provisioning
gets hung after the VM is created. Upon further investigation in the logs I
found the following error stacktrace as below
Started GET "/tasks/5cf790ec-ffad-4463-9c14-ba4585723b96" for 10.160.32.77
at 2014-09-23 15:21:47 +0100
Processing by TasksController#show as /
Parameters: {"id"=>"5cf790ec-ffad-4463-9c14-ba4585723b96"}
Rendered tasks/_list.html.erb (0.0ms)
Completed 200 OK in 2ms (Views: 0.3ms | ActiveRecord: 0.4ms)
all authorization methods failed (tried password)
Failed to login via SSH to foremantest2: execution
expired/usr/share/foreman/app/services/foreman/provision/ssh.rb:103:in
sleep' /usr/share/foreman/app/services/foreman/provision/ssh.rb:103:in
rescue in
block in initiate_connection!'
/usr/share/foreman/app/services/foreman/provision/ssh.rb:81:in block in initiate_connection!' /usr/share/foreman/app/services/foreman/provision/ssh.rb:80:in
initiate_connection!'
/usr/share/foreman/app/services/foreman/provision/ssh.rb:21:in initialize' /usr/share/foreman/app/models/concerns/orchestration/ssh_provision.rb:55:in
new'
/usr/share/foreman/app/models/concerns/orchestration/ssh_provision.rb:55:in
setSSHWaitForResponse' /usr/share/foreman/app/models/concerns/orchestration.rb:137:in
execute'
/usr/share/foreman/app/models/concerns/orchestration.rb:85:in block in process' /usr/share/foreman/app/models/concerns/orchestration.rb:77:in
each'
/usr/share/foreman/app/models/concerns/orchestration.rb:77:in process' /usr/share/foreman/app/models/concerns/orchestration.rb:22:in
post_commit'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in
_run__1982321747885022795__commit__2865513910606322382__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in
__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in
_run_commit_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in
run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:263:in
committed!' /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:372:in
block in commit_transaction_records'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:370:in
each' /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:370:in
commit_transaction_records'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/database_statements.rb:218:in
transaction' /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:208:in
transaction'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:293:in
with_transaction_returning_status' /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:241:in
block in save'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:252:in
rollback_active_record_state!' /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/transactions.rb:240:in
save'
/usr/share/foreman/app/models/concerns/foreman/sti.rb:29:in save_with_type' /usr/share/foreman/app/controllers/hosts_controller.rb:90:in
create'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/implicit_render.rb:4:in
send_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:167:in
process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rendering.rb:10:in
process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:18:in
block in process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:538:in
block (3 levels) in _run__1699024991318222732__process_action__1424905914085741037__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in
block in _conditional_callback_around_6981'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in
around' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in
_callback_around_1825'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in
_conditional_callback_around_6981' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:537:in
block (2 levels) in
_run__1699024991318222732__process_action__1424905914085741037__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in
block in _conditional_callback_around_6980' /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:33:in
clear_thread'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in
_conditional_callback_around_6980' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:426:in
block in
_run__1699024991318222732__process_action__1424905914085741037__callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:215:in
block in _conditional_callback_around_6979' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:326:in
around'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:310:in
_callback_around_13' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in
_conditional_callback_around_6979'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:414:in
_run__1699024991318222732__process_action__1424905914085741037__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in
__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in
_run_process_action_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in
run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/callbacks.rb:17:in
process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rescue.rb:29:in
process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:30:in
block in process_action' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in
block in instrument'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications/instrumenter.rb:20:in
instrument' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/notifications.rb:123:in
instrument'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/instrumentation.rb:29:in
process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/params_wrapper.rb:207:in
process_action'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/railties/controller_runtime.rb:18:in
process_action' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/base.rb:121:in
process'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/abstract_controller/rendering.rb:45:in
process' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:203:in
dispatch'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal/rack_delegation.rb:14:in
dispatch' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_controller/metal.rb:246:in
block in action'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:73:in
dispatch'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:36:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:68:in
block in call'
/opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in
each' /opt/rh/ruby193/root/usr/share/gems/gems/journey-1.0.4/lib/journey/router.rb:56:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/routing/route_set.rb:600:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/apipie-rails-0.2.5/lib/apipie/extractor/recorder.rb:97:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/apipie-rails-0.2.5/lib/apipie/middleware/checksum_in_headers.rb:27:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/best_standards_support.rb:17:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/etag.rb:23:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/conditionalget.rb:35:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/head.rb:14:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/params_parser.rb:21:in
call'
/usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:9:in call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/flash.rb:242:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:205:in
context' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/session/abstract/id.rb:200:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/cookies.rb:339:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/query_cache.rb:64:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/activerecord-3.2.8/lib/active_record/connection_adapters/abstract/connection_pool.rb:473:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:28:in
block in call'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in
_run__2506397368143255795__call__2865513910606322382__callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:405:in
__run_callback'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:385:in
_run_call_callbacks' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:81:in
run_callbacks'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/callbacks.rb:27:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/remote_ip.rb:31:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/debug_exceptions.rb:16:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/show_exceptions.rb:56:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/rack/logger.rb:26:in
call_app' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/rack/logger.rb:16:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/request_id.rb:22:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/methodoverride.rb:21:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/runtime.rb:17:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/cache/strategy/local_cache.rb:72:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/lock.rb:15:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:136:in
forward' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:143:in
pass'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:155:in
invalidate' /opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:71:in
call!'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:51:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/engine.rb:479:in
call'
/opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/application.rb:223:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/railties-3.2.8/lib/rails/railtie/configurable.rb:30:in
method_missing'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/builder.rb:134:in
call' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:64:in
block in call'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in
each' /opt/rh/ruby193/root/usr/share/gems/gems/rack-1.4.1/lib/rack/urlmap.rb:49:in
call'
/usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in
process_request' /usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:140:in
accept_and_process_next_request'
/usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:108:in
main_loop' /usr/lib/ruby/gems/1.8/gems/passenger-4.0.18/lib/phusion_passenger/request_handler.rb:441:in
block (3 levels) in start_threads'
Rolling back due to a problem: [Wait for foremantest2.ordsvy.gov.uk to come
online 2001 failed [#<Host::Managed id: 11, name:
"foremantest2.ordsvy.gov.uk", ip: nil, last_compile: nil, last_freshcheck:
nil, last_report: nil, updated_at: "2014-09-23 14:15:48", source_file_id:
nil, created_at: "2014-09-23 14:15:48", mac: "00:50:56:b4:58:a1",
root_pass: nil, serial: nil, puppet_status: 0, domain_id: 1,
architecture_id: 1, operatingsystem_id: 2, environment_id: 1, subnet_id: 1,
ptable_id: 7, medium_id: nil, build: true, comment: "", disk: "",
installed_at: nil, model_id: nil, hostgroup_id: 1, owner_id: 3, owner_type:
"User", enabled: true, puppet_ca_proxy_id: 1, managed: true, use_image:
nil, image_file: nil, uuid: "503440d6-5ab3-6f55-6b06-0aba69e29bd7",
compute_resource_id: 2, puppet_proxy_id: 1, certname: nil, image_id: 4,
organization_id: nil, location_id: nil, type: "Host::Managed", otp: nil,
realm_id: nil, compute_profile_id: 1, provision_method: "image">,
:setSSHWaitForResponse]]
ActiveRecord::Rollback
---- end of error stacktrace
I believe this might be due to some pre-setup I need to do into the
template (e.g. like creating a foreman user to allow ssh or generate ssh
keys). I have searched upon this error and could find something similar
regarding EC2 instances provisioning with SSH keys but with no luck for
VMware compute resource. I am certain that this would have been caught
during the testing of this feature when it was introduced into Foreman and
probably missed in documentation.
Summary:
- Able to create VM using Foreman on vCenter using VMWare template
- Provisioned VM and Foreman not able to talk to each other due to above
error stacktrace resulting in NO 'finish' templates & configurations being
applied on the VM and Foreman UI shows "Pending Build" against the host.
Any help in this regard will be highly appreciated.
Thanks & regards
Soumen