1596765 – Upload of Bootdisk ISO throws error even though it uploads

Bug 1596765 - Upload of Bootdisk ISO throws error even though it uploads

Summary: Upload of Bootdisk ISO throws error even though it uploads

Keywords:
Status:	CLOSED WONTFIX
Alias:	None
Product:	Red Hat Satellite
Classification:	Red Hat
Component:	Bootdisk Plugin
Sub Component:
Version:	6.3.1
Hardware:	x86_64
OS:	Linux
Priority:	unspecified
Severity:	medium
Target Milestone:	Unspecified
Assignee:	Lukas Zapletal
QA Contact:
Docs Contact:
URL:
Whiteboard:
Depends On:
Blocks:
TreeView+	depends on / blocked

Reported:	2018-06-29 16:42 UTC by Chris Roberts
Modified:	2020-05-05 09:47 UTC (History)
CC List:	5 users (show)
Fixed In Version:
Doc Type:	If docs needed, set a value
Doc Text:
Clone Of:
Environment:
Last Closed:	2020-02-03 16:30:31 UTC
Target Upstream Version:
Embargoed:

Attachments	(Terms of Use)

Description Chris Roberts 2018-06-29 16:42:23 UTC

Description of problem:
Creating a VM with the Bootdisk option works correctly, but produces failed upload in the production log.

Version-Release number of selected component (if applicable):

tfm-rubygem-foreman_bootdisk-10.0.2.2-1.fm1_15.el7sat.noarch
foreman-1.15.6.45-1.el7sat.noarch


How reproducible:


Steps to Reproduce:
1. Install 6.3 latest
2. setup VMware compute resource
3. Prov with Bootdisk option in OS
4. Tail production.log

Actual results:

2018-06-29 12:37:10 d7fbe5a9 [app] [E] Failed to rebuild Bootdisk image for isaac-jageman.satellite.lab.eng.rdu2.redhat.com
 | RuntimeError: upload failed
 | /opt/theforeman/tfm/root/usr/share/gems/gems/rbvmomi-1.10.0/lib/rbvmomi/vim/Datastore.rb:53:in `upload'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/fog-vsphere-1.7.0/lib/fog/vsphere/requests/compute/upload_iso.rb:29:in `upload_iso'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-10.0.2.2/app/models/concerns/foreman_bootdisk/compute_resources/vmware.rb:36:in `iso_upload'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-10.0.2.2/app/models/concerns/foreman_bootdisk/orchestration/compute.rb:39:in `bootdisk_upload_iso'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-10.0.2.2/app/models/concerns/foreman_bootdisk/orchestration/compute.rb:77:in `rebuild_with_bootdisk'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:228:in `block in halting_and_conditional'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:506:in `block in call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:506:in `each'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:506:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_build_callbacks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /usr/share/foreman/app/models/host/managed.rb:55:in `build_hooks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:263:in `block in simple'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:506:in `block in call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:506:in `each'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:506:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_commit_callbacks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/transactions.rb:314:in `committed!'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb:89:in `commit_records'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb:153:in `commit'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb:175:in `commit_transaction'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/transaction.rb:194:in `within_new_transaction'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/database_statements.rb:213:in `transaction'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/transactions.rb:220:in `transaction'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/transactions.rb:348:in `with_transaction_returning_status'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/transactions.rb:286:in `block in save'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/transactions.rb:301:in `rollback_active_record_state!'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/transactions.rb:285:in `save'
 | /usr/share/foreman/app/models/concerns/foreman/sti.rb:29:in `save_with_type'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.9.6.4/app/models/foreman_tasks/concerns/action_triggering.rb:25:in `block in save_with_dynflow_task_wrap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.9.6.4/app/models/foreman_tasks/concerns/action_triggering.rb:119:in `dynflow_task_wrap'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman-tasks-0.9.6.4/app/models/foreman_tasks/concerns/action_triggering.rb:25:in `save_with_dynflow_task_wrap'
 | /usr/share/foreman/app/controllers/hosts_controller.rb:104:in `create'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/implicit_render.rb:4:in `send_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/abstract_controller/base.rb:198:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/rendering.rb:10:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/abstract_controller/callbacks.rb:20:in `block in process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:117:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:555:in `block (2 levels) in compile'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/controllers/concerns/application_shared.rb:15:in `set_timezone'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in `clear_thread'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in `set_topbar_sweeper_controller'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:432:in `block in make_lambda'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:498:in `block (2 levels) in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:313:in `block (2 levels) in halting'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.4.1/lib/audited/sweeper.rb:14:in `around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:455:in `public_send'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:455:in `block in make_lambda'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:312:in `block in halting'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:497:in `block in around'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:505:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:92:in `__run_callbacks__'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_process_action_callbacks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/abstract_controller/callbacks.rb:19:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/rescue.rb:29:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/instrumentation.rb:32:in `block in process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `block in instrument'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/notifications/instrumenter.rb:20:in `instrument'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/notifications.rb:164:in `instrument'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/instrumentation.rb:30:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/params_wrapper.rb:250:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/railties/controller_runtime.rb:18:in `process_action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/abstract_controller/base.rb:137:in `process'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionview-4.2.6/lib/action_view/rendering.rb:30:in `process'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal.rb:196:in `dispatch'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal/rack_delegation.rb:13:in `dispatch'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_controller/metal.rb:237:in `block in action'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/route_set.rb:74:in `dispatch'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/route_set.rb:43:in `serve'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/journey/router.rb:43:in `block in serve'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/journey/router.rb:30:in `each'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/journey/router.rb:30:in `serve'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/routing/route_set.rb:817:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.6/lib/apipie/static_dispatcher.rb:65:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.6/lib/apipie/extractor/recorder.rb:136:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.6/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/etag.rb:24:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/conditionalget.rb:38:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/head.rb:13:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/params_parser.rb:27:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.4.5.74/lib/katello/params_parser_wrapper.rb:12:in `call'
 | /usr/share/foreman/lib/middleware/catch_json_parse_errors.rb:8:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/flash.rb:260:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:225:in `context'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/session/abstract/id.rb:220:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/cookies.rb:560:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/query_cache.rb:36:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activerecord-4.2.6/lib/active_record/connection_adapters/abstract/connection_pool.rb:653:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:29:in `block in call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:88:in `__run_callbacks__'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:778:in `_run_call_callbacks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/callbacks.rb:81:in `run_callbacks'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/callbacks.rb:27:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/remote_ip.rb:78:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/debug_exceptions.rb:17:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/show_exceptions.rb:30:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/rack/logger.rb:38:in `call_app'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/rack/logger.rb:22:in `call'
 | /usr/share/foreman/lib/middleware/tagged_logging.rb:18:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/request_id.rb:21:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/methodoverride.rb:22:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/runtime.rb:18:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/activesupport-4.2.6/lib/active_support/cache/strategy/local_cache_middleware.rb:28:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/actionpack-4.2.6/lib/action_dispatch/middleware/static.rb:120:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/sendfile.rb:113:in `call'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-3.4.1/lib/secure_headers/middleware.rb:12:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/engine.rb:518:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/application.rb:165:in `call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/railtie.rb:194:in `public_send'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/railties-4.2.6/lib/rails/railtie.rb:194:in `method_missing'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:66:in `block in call'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `each'
 | /opt/rh/rh-ror42/root/usr/share/gems/gems/rack-1.6.2/lib/rack/urlmap.rb:50:in `call'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/rack/thread_handler_extension.rb:77:in `process_request'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:140:in `accept_and_process_next_request'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler/thread_handler.rb:108:in `main_loop'
 | /usr/share/gems/gems/passenger-4.0.18/lib/phusion_passenger/request_handler.rb:441:in `block (3 levels) in start_threads'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'

Expected results:

No Error

Additional info:

ISO uploads correctly just throws an error in the production.log which could be cause for alarm.

Comment 3 Lukas Zapletal 2018-07-02 08:13:35 UTC

Chris,

it looks like the gem uses curl to perform the upload. Could you test something for me?

https://github.com/vmware/rbvmomi/blob/master/lib/rbvmomi/vim/Datastore.rb#L45-L54

I believe that in some cases it does not return zero, I see that it could return 18 as "partial file". Would you mind modifying the line to:

fail "upload failed: #{$?}" unless $?.success?

to see the actual return code? Then I can send patch for them.

Can you also check the file is not corrupt? Is there a way to download it back and compare md5sum? Thanks.

Comment 4 Chris Roberts 2018-07-02 18:49:13 UTC

Lukas,

Here is the error with the updated code:

==> /var/log/foreman/production.log <==
2018-07-02 14:46:21 5e8e2533 [app] [E] Failed to rebuild Bootdisk image for sheri-waack.satellite.lab.eng.rdu2.redhat.com
 | RuntimeError: upload failed: pid 16817 exit 22
 | /opt/theforeman/tfm/root/usr/share/gems/gems/rbvmomi-1.10.0/lib/rbvmomi/vim/Datastore.rb:53:in `upload'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/fog-vsphere-1.7.0/lib/fog/vsphere/requests/compute/upload_iso.rb:29:in `upload_iso'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-10.0.2.2/app/models/concerns/foreman_bootdisk/compute_resources/vmware.rb:36:in `iso_upload'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-10.0.2.2/app/models/concerns/foreman_bootdisk/orchestration/compute.rb:39:in `bootdisk_upload_iso'
 | /opt/theforeman/tfm/root/usr/share/gems/gems/foreman_bootdisk-10.0.2.2/app/models/concerns/foreman_bootdisk/orchestration/compute.rb:77:in `rebuild_with_bootdisk'

I can download it and verify the md5sum, is there a way to see the checksum from the bootdisk plugin? I did an updatedb and locate for sheri and could not see anything.

Comment 5 Lukas Zapletal 2018-07-03 06:48:13 UTC

Thanks Chris for this. Well according to man pages code 22 means:

HTTP page not retrieved. The requested url was not found or returned another error with the HTTP  error  code being 400 or above. This return code only appears if -f, --fail is used.

So VMWare returned 4xx for some reason. Do you see anything relevant in the logs in VMWare?

You are right that md5sum can't be done easily. Can you also get the upload URL and path the same way? Then we can dig in the docs what 4xx means.

Comment 6 Chris Roberts 2018-10-24 21:12:05 UTC

Tested this on a 6.4 box and I do not see the traceback with a few VMS I made, not sure what fixed it, closing this out.

Comment 8 Lukas Zapletal 2019-03-20 09:12:58 UTC

We are not seeing this error, customer needs to investigate on the VMWare side what is causing upload to fail.

Comment 11 Lukas Zapletal 2019-03-21 09:53:37 UTC

I was able to modify the code in a way that std error is redirected to a temporary file, here is the output from curl with --verbose option:

< HTTP/1.1 500 Internal Server Error
< Date: Thu, 21 Mar 2019 15:22:35 GMT
< Connection: close
< Content-Security-Policy: block-all-mixed-content
< Content-Type: text/plain; charset=utf-8
< Strict-Transport-Security: max-age=31536000
< X-Content-Type-Options: nosniff
< X-Frame-Options: DENY
< X-XSS-Protection: 1
< Content-Length: 0

Obviously, VMWare returns 500 with no explanation for the upload request. We can't do much about this, you need to figure out why VMWare does not work.

In the original report, Chris describes that it actually works but the request fails. It might be this problem or a different one.

Comment 12 Lukas Zapletal 2019-03-21 10:06:22 UTC

Ok we were able to find the error in VMWare in /storage/log/vmware/vpxd/vpxd.log:

2019-03-20T19:05:30.175Z warning vpxd[13514] [Originator@6876 sub=Default] [NFC ERROR] NfcFssrvr_FileOpen: Failed to open file '[dl380g9-11-LOCAL-1]foreman_isos/anne-nicastro.gsslab.pnq2.redhat.com.iso': The file is locked or in use (NFC_FILE_LOCKED)

I noticed that the VM was powered on while I was hitting Build button, so I powered it off first, then the log looks like:

2019-03-21T15:36:43.933Z info vpxd[13588] [Originator@6876 sub=vpxLro opID=41e267f8] [VpxLRO] -- BEGIN lro-5295077 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 52ce27c9-d312-ad4f-35db-03cc33c938f8
2019-03-21T15:36:43.933Z info vpxd[13588] [Originator@6876 sub=vpxLro opID=41e267f8] [VpxLRO] -- FINISH lro-5295077
2019-03-21T15:36:43.941Z info vpxd[13637] [Originator@6876 sub=vpxLro opID=7717ec92] [VpxLRO] -- BEGIN lro-5295078 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 525fd9ca-0f79-52b2-208d-4351906a7892
2019-03-21T15:36:43.941Z info vpxd[13637] [Originator@6876 sub=vpxLro opID=7717ec92] [VpxLRO] -- FINISH lro-5295078
2019-03-21T15:36:43.949Z info vpxd[26816] [Originator@6876 sub=vpxLro opID=43aca253] [VpxLRO] -- BEGIN lro-5295079 -- SessionManager -- vim.SessionManager.login -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1
2019-03-21T15:36:43.997Z info vpxd[26816] [Originator@6876 sub=vpxLro opID=43aca253] [VpxLRO] -- FINISH lro-5295079
2019-03-21T15:36:44.013Z info vpxd[13527] [Originator@6876 sub=vpxLro opID=63a777b7] [VpxLRO] -- BEGIN lro-5295081 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.014Z info vpxd[13527] [Originator@6876 sub=vpxLro opID=63a777b7] [VpxLRO] -- FINISH lro-5295081
2019-03-21T15:36:44.044Z info vpxd[13529] [Originator@6876 sub=vpxLro opID=7b2e0e8c] [VpxLRO] -- BEGIN lro-5295085 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.044Z info vpxd[13529] [Originator@6876 sub=vpxLro opID=7b2e0e8c] [VpxLRO] -- FINISH lro-5295085
2019-03-21T15:36:44.779Z info vpxd[13515] [Originator@6876 sub=vpxLro opID=4b69f89f] [VpxLRO] -- BEGIN lro-5295100 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.781Z info vpxd[13515] [Originator@6876 sub=vpxLro opID=4b69f89f] [VpxLRO] -- FINISH lro-5295100
2019-03-21T15:36:44.809Z info vpxd[13594] [Originator@6876 sub=vpxLro opID=480bedc2] [VpxLRO] -- BEGIN lro-5295104 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.810Z info vpxd[13594] [Originator@6876 sub=vpxLro opID=480bedc2] [VpxLRO] -- FINISH lro-5295104
2019-03-21T15:36:44.838Z info vpxd[13580] [Originator@6876 sub=vpxLro opID=104f6947] [VpxLRO] -- BEGIN lro-5295108 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.839Z info vpxd[13580] [Originator@6876 sub=vpxLro opID=104f6947] [VpxLRO] -- FINISH lro-5295108
2019-03-21T15:36:44.867Z info vpxd[13510] [Originator@6876 sub=vpxLro opID=72a4a731] [VpxLRO] -- BEGIN lro-5295112 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.868Z info vpxd[13510] [Originator@6876 sub=vpxLro opID=72a4a731] [VpxLRO] -- FINISH lro-5295112
2019-03-21T15:36:44.898Z info vpxd[26772] [Originator@6876 sub=vpxLro opID=b137d86] [VpxLRO] -- BEGIN lro-5295116 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:44.899Z info vpxd[26772] [Originator@6876 sub=vpxLro opID=b137d86] [VpxLRO] -- FINISH lro-5295116
2019-03-21T15:36:45.003Z info vpxd[13487] [Originator@6876 sub=vpxLro opID=1c9226a9] [VpxLRO] -- BEGIN lro-5295133 -- ViewManager -- vim.view.ViewManager.createContainerView -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.004Z info vpxd[13487] [Originator@6876 sub=vpxLro opID=1c9226a9] [VpxLRO] -- FINISH lro-5295133
2019-03-21T15:36:45.015Z info vpxd[13592] [Originator@6876 sub=vpxLro opID=6760c56e] [VpxLRO] -- BEGIN lro-5295135 -- session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]5228b129-3190-58dc-8f1e-8e0fe49ad6fa -- vim.view.View.destroy -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.015Z info vpxd[13592] [Originator@6876 sub=vpxLro opID=6760c56e] [VpxLRO] -- FINISH lro-5295135
2019-03-21T15:36:45.076Z info vpxd[13569] [Originator@6876 sub=vpxLro opID=18498919] [VpxLRO] -- BEGIN lro-5295145 -- ViewManager -- vim.view.ViewManager.createContainerView -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.077Z info vpxd[13569] [Originator@6876 sub=vpxLro opID=18498919] [VpxLRO] -- FINISH lro-5295145
2019-03-21T15:36:45.088Z info vpxd[13564] [Originator@6876 sub=vpxLro opID=346191cc] [VpxLRO] -- BEGIN lro-5295147 -- session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52683453-74e6-c06b-9053-9868e27d6fa1 -- vim.view.View.destroy -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.088Z info vpxd[13564] [Originator@6876 sub=vpxLro opID=346191cc] [VpxLRO] -- FINISH lro-5295147
2019-03-21T15:36:45.136Z info vpxd[13516] [Originator@6876 sub=vpxLro opID=7dfa1d02] [VpxLRO] -- BEGIN lro-5295155 -- SearchIndex -- vim.SearchIndex.findChild -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.137Z info vpxd[13516] [Originator@6876 sub=vpxLro opID=7dfa1d02] [VpxLRO] -- FINISH lro-5295155
2019-03-21T15:36:45.165Z info vpxd[13632] [Originator@6876 sub=HTTP server /folder req=00007fb47c241460 user=GSSLAB.PNQ2.REDHAT.COM\satadmin] Got HTTP HEAD request for /folder/foreman_isos/?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1
2019-03-21T15:36:45.165Z info vpxd[13488] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-c8] [VpxLRO] -- BEGIN lro-5295160 -- SearchIndex -- vim.SearchIndex.findByInventoryPath -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.166Z info vpxd[13488] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-c8] [VpxLRO] -- FINISH lro-5295160
2019-03-21T15:36:45.167Z info vpxd[13514] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-c7] [VpxLRO] -- BEGIN lro-5295163 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.167Z info vpxd[13514] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-c7] [VpxLRO] -- FINISH lro-5295163
2019-03-21T15:36:45.167Z info vpxd[13514] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-67] [VpxLRO] -- BEGIN session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52c501d5-b1b3-0625-825c-8e8ed91ae0ce -- datastoreBrowser-datastore-17 -- vim.host.DatastoreBrowser.search -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.208Z info vpxd[13514] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-67] [VpxLRO] -- FINISH session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52c501d5-b1b3-0625-825c-8e8ed91ae0ce
2019-03-21T15:36:45.209Z info vpxd[26649] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-35] [VpxLRO] -- BEGIN lro-5295168 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.209Z info vpxd[26649] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-35] [VpxLRO] -- FINISH lro-5295168
2019-03-21T15:36:45.209Z info vpxd[26649] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-1c] [VpxLRO] -- BEGIN session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52d9b8ed-0440-2ec0-3f66-73281495dbd8 -- datastoreBrowser-datastore-17 -- vim.host.DatastoreBrowser.search -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.224Z info vpxd[26649] [Originator@6876 sub=vpxLro opID=req=00007fb47c241460-1c] [VpxLRO] -- FINISH session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52d9b8ed-0440-2ec0-3f66-73281495dbd8
2019-03-21T15:36:45.423Z info vpxd[26814] [Originator@6876 sub=HTTP server /folder req=00007fb4984390f0 user=GSSLAB.PNQ2.REDHAT.COM\satadmin] Got HTTP PUT request for /folder/foreman_isos/anne-nicastro.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1
2019-03-21T15:36:45.423Z info vpxd[13513] [Originator@6876 sub=vpxLro opID=req=00007fb4984390f0-99] [VpxLRO] -- BEGIN lro-5295174 -- SearchIndex -- vim.SearchIndex.findByInventoryPath -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.423Z info vpxd[13513] [Originator@6876 sub=vpxLro opID=req=00007fb4984390f0-99] [VpxLRO] -- FINISH lro-5295174
2019-03-21T15:36:45.425Z info vpxd[13550] [Originator@6876 sub=vpxLro opID=req=00007fb4984390f0-2f] [VpxLRO] -- BEGIN lro-5295177 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.425Z info vpxd[13550] [Originator@6876 sub=vpxLro opID=req=00007fb4984390f0-2f] [VpxLRO] -- FINISH lro-5295177
2019-03-21T15:36:45.425Z info vpxd[13550] [Originator@6876 sub=vpxLro opID=req=00007fb4984390f0-14] [VpxLRO] -- BEGIN session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52cead7a-d6f7-a4ac-bfd6-da8cf792fa7c -- datastoreBrowser-datastore-17 -- vim.host.DatastoreBrowser.search -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.429Z info vpxd[13550] [Originator@6876 sub=vpxLro opID=req=00007fb4984390f0-14] [VpxLRO] -- FINISH session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52cead7a-d6f7-a4ac-bfd6-da8cf792fa7c
2019-03-21T15:36:45.430Z info vpxd[13639] [Originator@6876 sub=vpxLro opID=324b6a17] [VpxLRO] -- BEGIN lro-5295182 -- nfcService -- vim.NfcService.fileManagement -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.436Z info vpxd[13639] [Originator@6876 sub=vpxLro opID=324b6a17] [VpxLRO] -- FINISH lro-5295182
2019-03-21T15:36:45.899Z info vpxd[26813] [Originator@6876 sub=HTTP server /folder req=00007fb48c405a20 user=GSSLAB.PNQ2.REDHAT.COM\satadmin] Got HTTP HEAD request for /folder/foreman_isos/anne-nicastro.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1
2019-03-21T15:36:45.899Z info vpxd[13533] [Originator@6876 sub=vpxLro opID=req=00007fb48c405a20-cc] [VpxLRO] -- BEGIN lro-5295185 -- SearchIndex -- vim.SearchIndex.findByInventoryPath -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.899Z info vpxd[13533] [Originator@6876 sub=vpxLro opID=req=00007fb48c405a20-cc] [VpxLRO] -- FINISH lro-5295185
2019-03-21T15:36:45.901Z info vpxd[13555] [Originator@6876 sub=vpxLro opID=req=00007fb48c405a20-3] [VpxLRO] -- BEGIN session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]5229ba4e-cec1-634d-72c3-05130f49ba9d -- datastoreBrowser-datastore-17 -- vim.host.DatastoreBrowser.search -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.901Z info vpxd[13519] [Originator@6876 sub=vpxLro opID=req=00007fb48c405a20-ad] [VpxLRO] -- BEGIN lro-5295188 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.901Z info vpxd[13519] [Originator@6876 sub=vpxLro opID=req=00007fb48c405a20-ad] [VpxLRO] -- FINISH lro-5295188
2019-03-21T15:36:45.906Z info vpxd[13555] [Originator@6876 sub=vpxLro opID=req=00007fb48c405a20-3] [VpxLRO] -- FINISH session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]5229ba4e-cec1-634d-72c3-05130f49ba9d
2019-03-21T15:36:45.908Z info vpxd[13515] [Originator@6876 sub=vpxLro opID=8d9a884] [VpxLRO] -- BEGIN lro-5295193 -- nfcService -- vim.NfcService.fileManagement -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:45.915Z info vpxd[13515] [Originator@6876 sub=vpxLro opID=8d9a884] [VpxLRO] -- FINISH lro-5295193
2019-03-21T15:36:46.300Z info vpxd[13773] [Originator@6876 sub=vpxLro opID=3ac47969] [VpxLRO] -- BEGIN lro-5295195 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.302Z info vpxd[13773] [Originator@6876 sub=vpxLro opID=3ac47969] [VpxLRO] -- FINISH lro-5295195
2019-03-21T15:36:46.328Z info vpxd[13575] [Originator@6876 sub=vpxLro opID=161dfda7] [VpxLRO] -- BEGIN lro-5295199 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.329Z info vpxd[13575] [Originator@6876 sub=vpxLro opID=161dfda7] [VpxLRO] -- FINISH lro-5295199
2019-03-21T15:36:46.355Z info vpxd[13602] [Originator@6876 sub=vpxLro opID=400750d8] [VpxLRO] -- BEGIN lro-5295203 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.356Z info vpxd[13602] [Originator@6876 sub=vpxLro opID=400750d8] [VpxLRO] -- FINISH lro-5295203
2019-03-21T15:36:46.382Z info vpxd[13641] [Originator@6876 sub=vpxLro opID=f134480] [VpxLRO] -- BEGIN lro-5295207 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.384Z info vpxd[13641] [Originator@6876 sub=vpxLro opID=f134480] [VpxLRO] -- FINISH lro-5295207
2019-03-21T15:36:46.413Z info vpxd[13536] [Originator@6876 sub=vpxLro opID=55c94ab7] [VpxLRO] -- BEGIN lro-5295211 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.414Z info vpxd[13536] [Originator@6876 sub=vpxLro opID=55c94ab7] [VpxLRO] -- FINISH lro-5295211
2019-03-21T15:36:46.440Z info vpxd[26451] [Originator@6876 sub=vpxLro opID=734262ab] [VpxLRO] -- BEGIN lro-5295215 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.441Z info vpxd[26451] [Originator@6876 sub=vpxLro opID=734262ab] [VpxLRO] -- FINISH lro-5295215
2019-03-21T15:36:46.465Z info vpxd[13531] [Originator@6876 sub=vpxLro opID=4ce4b581] [VpxLRO] -- BEGIN lro-5295218 -- SearchIndex -- vim.SearchIndex.findByUuid -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.466Z info vpxd[13531] [Originator@6876 sub=vpxLro opID=4ce4b581] [VpxLRO] -- FINISH lro-5295218
2019-03-21T15:36:46.489Z info vpxd[13545] [Originator@6876 sub=vpxLro opID=3b484f97] [VpxLRO] -- BEGIN task-2219 -- vm-114 -- vim.VirtualMachine.reconfigure -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.492Z info vpxd[13545] [Originator@6876 sub=vpxLro opID=3b484f97-01] [VpxLRO] -- BEGIN lro-5295220 --  -- VmprovWorkflow -- 
2019-03-21T15:36:46.649Z info vpxd[13545] [Originator@6876 sub=vpxLro opID=3b484f97-01] [VpxLRO] -- FINISH lro-5295220
2019-03-21T15:36:46.650Z info vpxd[13545] [Originator@6876 sub=vpxLro opID=3b484f97] [VpxLRO] -- FINISH task-2219
2019-03-21T15:36:46.665Z info vpxd[13635] [Originator@6876 sub=vpxLro opID=3923c429] [VpxLRO] -- BEGIN lro-5295225 -- session[527eae71-f1bf-4b44-8eba-a01bbdc3fde1]52e78833-4181-cb53-2a5f-ff8bd213f476 -- vmodl.query.PropertyCollector.Filter.destroy -- 527eae71-f1bf-4b44-8eba-a01bbdc3fde1(527464b4-b75e-e61b-2b73-76091fe3930a)
2019-03-21T15:36:46.666Z info vpxd[13635] [Originator@6876 sub=vpxLro opID=3923c429] [VpxLRO] -- FINISH lro-5295225
2019-03-21T15:36:47.282Z info vpxd[13561] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-9e] [VpxLRO] -- BEGIN lro-5295229 -- AuthorizationManager -- vim.AuthorizationManager.hasPrivilegeOnEntities -- 5225a50c-4be8-d467-9788-295a098a860e(52920bed-804d-617a-7175-229698f46477)
2019-03-21T15:36:47.283Z info vpxd[13561] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-9e] [VpxLRO] -- FINISH lro-5295229
2019-03-21T15:36:47.345Z info vpxd[13584] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-a4] [VpxLRO] -- BEGIN lro-5295230 -- AuthorizationManager -- vim.AuthorizationManager.hasPrivilegeOnEntities -- 5225a50c-4be8-d467-9788-295a098a860e(52920bed-804d-617a-7175-229698f46477)
2019-03-21T15:36:47.345Z info vpxd[13584] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-a4] [VpxLRO] -- FINISH lro-5295230
2019-03-21T15:36:47.351Z info vpxd[13573] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-W603167-48] [VpxLRO] -- BEGIN lro-5295231 -- ViewManager -- vim.view.ViewManager.createContainerView -- 5225a50c-4be8-d467-9788-295a098a860e(52920bed-804d-617a-7175-229698f46477)
2019-03-21T15:36:47.352Z info vpxd[13573] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-W603167-48] [VpxLRO] -- FINISH lro-5295231
2019-03-21T15:36:47.371Z info vpxd[13579] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-W603167-86] [VpxLRO] -- BEGIN lro-5295234 -- session[5225a50c-4be8-d467-9788-295a098a860e]527cc8c8-5958-628d-56a5-5a3b5cdbf97c -- vim.view.View.destroy -- 5225a50c-4be8-d467-9788-295a098a860e(52920bed-804d-617a-7175-229698f46477)
2019-03-21T15:36:47.371Z info vpxd[13579] [Originator@6876 sub=vpxLro opID=sps-Main-163142-642-W603167-86] [VpxLRO] -- FINISH lro-5295234
2019-03-21T15:36:49.272Z info vpxd[13649] [Originator@6876 sub=HostCnx opID=CheckforMissingHeartbeats-7dc43530] [VpxdHostCnx] No heartbeats received from host; cnx: 52fd0877-5b27-0352-8b11-4ac91b4e9329, h: host-43, time since last heartbeat: 1082132309ms
2019-03-21T15:36:49.521Z info vpxd[13560] [Originator@6876 sub=vpxLro opID=2fba5322] [VpxLRO] -- BEGIN lro-5295235 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 523db535-2611-77c0-2931-9fb8e217c30f
2019-03-21T15:36:49.521Z info vpxd[13560] [Originator@6876 sub=vpxLro opID=2fba5322] [VpxLRO] -- FINISH lro-5295235
2019-03-21T15:36:49.528Z info vpxd[13580] [Originator@6876 sub=vpxLro opID=71a7f5a8] [VpxLRO] -- BEGIN lro-5295236 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 52e97f04-b642-a627-85ea-bed7af5d0827
2019-03-21T15:36:49.529Z info vpxd[13580] [Originator@6876 sub=vpxLro opID=71a7f5a8] [VpxLRO] -- FINISH lro-5295236
2019-03-21T15:36:49.536Z info vpxd[13598] [Originator@6876 sub=vpxLro opID=49f122e3] [VpxLRO] -- BEGIN lro-5295237 -- SessionManager -- vim.SessionManager.login -- 528f773e-7b90-7735-2779-9074406f7706
2019-03-21T15:36:49.570Z info vpxd[13598] [Originator@6876 sub=vpxLro opID=49f122e3] [VpxLRO] -- FINISH lro-5295237
2019-03-21T15:36:49.585Z info vpxd[13602] [Originator@6876 sub=vpxLro opID=299b370f] [VpxLRO] -- BEGIN lro-5295239 -- SearchIndex -- vim.SearchIndex.findByUuid -- 528f773e-7b90-7735-2779-9074406f7706(52e0f13c-3dbb-0ac4-975c-f9c982fff6aa)
2019-03-21T15:36:49.586Z info vpxd[13602] [Originator@6876 sub=vpxLro opID=299b370f] [VpxLRO] -- FINISH lro-5295239
2019-03-21T15:36:49.636Z info vpxd[13635] [Originator@6876 sub=vpxLro opID=259bf827] [VpxLRO] -- BEGIN lro-5295245 -- SearchIndex -- vim.SearchIndex.findByUuid -- 528f773e-7b90-7735-2779-9074406f7706(52e0f13c-3dbb-0ac4-975c-f9c982fff6aa)
2019-03-21T15:36:49.637Z info vpxd[13635] [Originator@6876 sub=vpxLro opID=259bf827] [VpxLRO] -- FINISH lro-5295245
2019-03-21T15:36:49.665Z info vpxd[13581] [Originator@6876 sub=vpxLro opID=560b68f7] [VpxLRO] -- BEGIN lro-5295249 -- SearchIndex -- vim.SearchIndex.findByUuid -- 528f773e-7b90-7735-2779-9074406f7706(52e0f13c-3dbb-0ac4-975c-f9c982fff6aa)
2019-03-21T15:36:49.666Z info vpxd[13581] [Originator@6876 sub=vpxLro opID=560b68f7] [VpxLRO] -- FINISH lro-5295249
2019-03-21T15:36:49.693Z info vpxd[13565] [Originator@6876 sub=vpxLro opID=7ae4ac65] [VpxLRO] -- BEGIN lro-5295253 -- SearchIndex -- vim.SearchIndex.findByUuid -- 528f773e-7b90-7735-2779-9074406f7706(52e0f13c-3dbb-0ac4-975c-f9c982fff6aa)
2019-03-21T15:36:49.694Z info vpxd[13565] [Originator@6876 sub=vpxLro opID=7ae4ac65] [VpxLRO] -- FINISH lro-5295253
2019-03-21T15:36:49.735Z info vpxd[13857] [Originator@6876 sub=vpxLro opID=5f5f75b9] [VpxLRO] -- BEGIN lro-5295257 -- SearchIndex -- vim.SearchIndex.findByUuid -- 528f773e-7b90-7735-2779-9074406f7706(52e0f13c-3dbb-0ac4-975c-f9c982fff6aa)
2019-03-21T15:36:49.736Z info vpxd[13857] [Originator@6876 sub=vpxLro opID=5f5f75b9] [VpxLRO] -- FINISH lro-5295257
2019-03-21T15:36:49.824Z error vpxd[13592] [Originator@6876 sub=VapiEndpoint.HTTPService] Failed to read request; stream: <io_obj p:0x00007fb4ac137b40, h:-1, <TCP '127.0.0.1 : 8093'>, <TCP '0.0.0.0 : 0'> FD Closed>, error: N7Vmacore16TimeoutExceptionE(Operation timed out: Stream: <io_obj p:0x00007fb4ac137b40, h:-1, <TCP '127.0.0.1 : 8093'>, <TCP '0.0.0.0 : 0'> FD Closed>, duration: 00:00:45.128177 (hh:mm:ss.us))
--> [context]zKq7AVECAAAAAPlSnAALdnB4ZAAAlLAqbGlidm1hY29yZS5zbwAAIDcbAG67GABiohoAeGQlAGlRIwChHiMAaiEjAB0IKwHUcwBsaWJwdGhyZWFkLnNvLjAAAp2MDmxpYmMuc28uNgA=[/context]
2019-03-21T15:36:50.467Z info vpxd[13512] [Originator@6876 sub=vpxLro opID=70b923be] [VpxLRO] -- BEGIN lro-5295261 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 52769f40-be5f-df24-acb9-2a540f095761
2019-03-21T15:36:50.468Z info vpxd[13512] [Originator@6876 sub=vpxLro opID=70b923be] [VpxLRO] -- FINISH lro-5295261
2019-03-21T15:36:50.564Z info vpxd[13632] [Originator@6876 sub=vpxLro opID=600b7fc5] [VpxLRO] -- BEGIN lro-5295262 -- ServiceInstance -- vim.ServiceInstance.retrieveContent -- 528f0e42-6472-e94a-34be-251bf3c2272f
2019-03-21T15:36:50.565Z info vpxd[13632] [Originator@6876 sub=vpxLro opID=600b7fc5] [VpxLRO] -- FINISH lro-5295262

There is no error then. This looks like the error is caused by the fact that the file is in use in VMWare, VM must be powered off prior uploading.

Comment 13 Lukas Zapletal 2019-03-21 10:19:53 UTC

When creating new host, I see that we upload the image twice or something (?):

Got HTTP PUT request for /folder/foreman_isos/lukaz-vm.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1
Got HTTP HEAD request for /folder/foreman_isos/lukaz-vm.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1
Got HTTP PUT request for /folder/foreman_isos/lukaz-vm.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1
NfcFssrvrOpen: Failed to open '[dl380g9-11-LOCAL-1]foreman_isos/lukaz-vm.gsslab.pnq2.redhat.com.iso': The file is locked or in use (NFC_FILE_LOCKED)

Need to take a look.

Comment 14 Lukas Zapletal 2019-03-21 10:27:43 UTC

Satellite does not schedule this multiple times, it must be the VMWare Ruby library...

2019-03-21T06:09:47 [I|app|52db1] Adding Compute instance for lukaz-vm.gsslab.pnq2.redhat.com
2019-03-21T06:09:48 [I|app|52db1] Generating ISO image for lukaz-vm.gsslab.pnq2.redhat.com
2019-03-21T06:09:48 [I|tem|52db1] Rendering template 'Unnamed'
2019-03-21T06:09:48 [I|blo|52db1] Unattended render of 'Unnamed' = '3cef9bf062b274a0b543b605fee5301c38ea0739f43c1417f5d137ec0fb6f660'
2019-03-21T06:09:48 [I|app|52db1] Uploading ISO image /tmp/d20190321-19972-rxg7ko/lukaz-vm.gsslab.pnq2.redhat.com.iso for lukaz-vm.gsslab.pnq2.redhat.com
2019-03-21T06:09:50 [I|app|52db1] Create DHCP reservation lukaz-vm.gsslab.pnq2.redhat.com for lukaz-vm.gsslab.pnq2.redhat.com-00:50:56:8d:8f:f3/172.20.4.132
2019-03-21T06:09:50 [I|app|52db1] Add DNS PTR record for 172.20.4.132/lukaz-vm.gsslab.pnq2.redhat.com
2019-03-21T06:09:50 [I|app|52db1] Powering up Compute instance for lukaz-vm.gsslab.pnq2.redhat.com
2019-03-21T06:09:51 [I|app|52db1] Attaching ISO image to CDROM drive for lukaz-vm.gsslab.pnq2.redhat.com
2019-03-21T06:09:51 [I|app|52db1] Processed 8 tasks from queue 'Host::Managed Main', completed 8/8

Comment 15 Lukas Zapletal 2019-03-21 10:36:49 UTC

WORKAROUND until we find what is causing this:

Edit /opt/theforeman/tfm/root/usr/share/gems/gems/rbvmomi-1.10.0/lib/rbvmomi/vim/Datastore.rb and remove the "-f" flag from the CURL upload command, restart httpd.

Comment 16 Lukas Zapletal 2019-03-21 14:11:30 UTC

I was able to modify the curl code so it records all its output to files each time. The curl is really spawned twice, first time its HTTP 200 and the second time indeed HTTP 500:

* Connected to sysvcs.gsslab.pnq2.redhat.com (10.74.131.45) port 443 (#0)
* Initializing NSS with certpath: sql:/etc/pki/nssdb
* skipping SSL peer certificate verification
* SSL connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
* Server certificate:
*       subject: C=US,CN=sysvcs.gsslab.pnq2.redhat.com
*       start date: Jan 10 23:26:44 2019 GMT
*       expire date: Jan 04 23:26:43 2029 GMT
*       common name: sysvcs.gsslab.pnq2.redhat.com
*       issuer: OU=VMware Engineering,O=sysvcs.gsslab.pnq2.redhat.com,ST=California,C=US,DC=pnq2.redhat.com,DC=gsslab,CN=CA
> PUT /folder/foreman_isos/jason-demaris.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1 HTTP/1.1
> User-Agent: curl/7.29.0
> Host: sysvcs.gsslab.pnq2.redhat.com
> Accept: */*
> Cookie: vmware_soap_session="110500a40cd916e836f5f01d2185bfa8e6a88d39"; Path=/; HttpOnly; Secure;
> Content-Length: 1048576
> Expect: 100-continue
> 
< HTTP/1.1 100 Continue
  0 1024k    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0} [data not shown]
* We are completely uploaded and fine
< HTTP/1.1 201 Created
< Date: Thu, 21 Mar 2019 19:39:00 GMT
< Connection: close
< Content-Security-Policy: block-all-mixed-content
< Content-Type: text/plain; charset=utf-8
< Strict-Transport-Security: max-age=31536000
< X-Content-Type-Options: nosniff
< X-Frame-Options: DENY
< X-XSS-Protection: 1
< Content-Length: 0
< 
100 1024k    0     0  100 1024k      0  1419k --:--:-- --:--:-- --:--:-- 1418k
* Closing connection 0


* Connected to sysvcs.gsslab.pnq2.redhat.com (10.74.131.45) port 443 (#0)
* Initializing NSS with certpath: sql:/etc/pki/nssdb
* skipping SSL peer certificate verification
* SSL connection using TLS_ECDHE_RSA_WITH_AES_256_GCM_SHA384
* Server certificate:
*       subject: C=US,CN=sysvcs.gsslab.pnq2.redhat.com
*       start date: Jan 10 23:26:44 2019 GMT
*       expire date: Jan 04 23:26:43 2029 GMT
*       common name: sysvcs.gsslab.pnq2.redhat.com
*       issuer: OU=VMware Engineering,O=sysvcs.gsslab.pnq2.redhat.com,ST=California,C=US,DC=pnq2.redhat.com,DC=gsslab,CN=CA
> PUT /folder/foreman_isos/jason-demaris.gsslab.pnq2.redhat.com.iso?dcPath=sysmgmt&dsName=dl380g9-11-LOCAL-1 HTTP/1.1
> User-Agent: curl/7.29.0
> Host: sysvcs.gsslab.pnq2.redhat.com
> Accept: */*
> Cookie: vmware_soap_session="110500a40cd916e836f5f01d2185bfa8e6a88d39"; Path=/; HttpOnly; Secure;
> Content-Length: 1048576
> Expect: 100-continue
> 
< HTTP/1.1 500 Internal Server Error
< Date: Thu, 21 Mar 2019 19:39:03 GMT
< Connection: close
< Content-Security-Policy: block-all-mixed-content
< Content-Type: text/plain; charset=utf-8
< Strict-Transport-Security: max-age=31536000
< X-Content-Type-Options: nosniff
< X-Frame-Options: DENY
< X-XSS-Protection: 1
< Content-Length: 0
< 
  0 1024k    0     0    0     0      0      0 --:--:-- --:--:-- --:--:--     0
* Closing connection 0

Comment 18 Bryan Kearney 2020-01-15 21:01:11 UTC

The Satellite Team is attempting to provide an accurate backlog of bugzilla requests which we feel will be resolved in the next few releases. We do not believe this bugzilla will meet that criteria, and have plans to close it out in 1 month. This is not a reflection on the validity of the request, but a reflection of the many priorities for the product. If you have any concerns about this, feel free to contact Red Hat Technical Support or your account team. If we do not hear from you, we will close this bug out. Thank you.

Comment 19 Bryan Kearney 2020-02-03 16:30:31 UTC

Thank you for your interest in Satellite 6. We have evaluated this request, and while we recognize that it is a valid request, we do not expect this to be implemented in the product in the foreseeable future. This is due to other priorities for the product, and not a reflection on the request itself. We are therefore closing this out as WONTFIX. If you have any concerns about this, please do not reopen. Instead, feel free to contact Red Hat Technical Support. Thank you.

Comment 20 Lukas Zapletal 2020-05-05 09:47:56 UTC

For the record, I believe this was fixed in 6.8, the upcoming release:

https://bugzilla.redhat.com/show_bug.cgi?id=1796205

Note You need to log in before you can comment on or make changes to this bug.