Bug 1321654

Summary: [RHEL-OSP] Error retrieving OpenStack nodes. Adapter operation failed
Product: Red Hat Quickstart Cloud Installer Reporter: Thom Carlin <tcarlin>
Component: Installation - RHELOSPAssignee: cchase
Status: CLOSED WONTFIX QA Contact: Dave Johnson <dajohnso>
Severity: medium Docs Contact: Dan Macpherson <dmacpher>
Priority: unspecified    
Version: 1.0CC: bthurber, jmatthew
Target Milestone: ---Keywords: FutureFeature, Triaged
Target Release: ---   
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: Doc Type: Bug Fix
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2017-12-15 13:32:27 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:

Description Thom Carlin 2016-03-28 19:07:03 UTC
Description of problem:

Error during "2B. Register Nodes" of OpenStack install

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

TP3 RC2

How reproducible:

Uncertain

Steps to Reproduce:
1. Install QCI and QCI Triple O ISOs
2. Log in each system to run launch-fusor*-installer
3. Start deployment

Actual results:

Error retrieving OpenStack nodes. Adapter operation failed:
Unable to load node ports. GET "/fusor/api/openstack/deployments/1/node_ports" failed with status code 500.

Expected results:

No errors, successfully registered nodes

Additional info:

/var/log/foreman/production.log excerpt:
2016-03-28 14:50:17 [E] Excon::Errors::Timeout: read timeout reached
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:61:in `rescue in read'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:35:in `read'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:95:in `readline'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/response.rb:40:in `parse'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/middlewares/response_parser.rb:6:in `response_call'
/opt/rh/ruby193/root/usr/share/gems/gems/docker-api-1.17.0/lib/excon/middlewares/hijack.rb:45:in `response_call'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/connection.rb:402:in `response'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/connection.rb:272:in `request'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-core-1.24.0/lib/fog/core/connection.rb:64:in `request'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-1.24.1/lib/fog/openstack/baremetal.rb:295:in `request'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-1.24.1/lib/fog/openstack/requests/baremetal/list_nodes_detailed.rb:16:in `list_nodes_detailed'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-1.24.1/lib/fog/openstack/models/baremetal/nodes.rb:15:in `details'
/opt/rh/ruby193/root/usr/share/gems/gems/egon-0.4.8/lib/egon/overcloud/undercloud_handle/node.rb:9:in `list_nodes'
/opt/rh/ruby193/root/usr/share/gems/gems/fusor_server-0.0.1/app/controllers/fusor/api/openstack/nodes_controller.rb:21:in `index'
/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:539:in `block (4 levels) in _run__3137742557254255594__process_action__2161689863786729900__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_11645'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:151:in `disable_json_root'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11645'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:505:in `block (3 levels) in _run__3137742557254255594__process_action__2161689863786729900__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_11644'
/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_3887'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11644'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:493:in `block (2 levels) in _run__3137742557254255594__process_action__2161689863786729900__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_11643'
/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_11643'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:426:in `block in _run__3137742557254255594__process_action__2161689863786729900__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_11642'
/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_11642'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:414:in `_run__3137742557254255594__process_action__2161689863786729900__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/katello-2.2.0.83/app/controllers/katello/concerns/api/api_controller.rb:59: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/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/railtie/configurable.rb:30:in `method_missing'
/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/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62: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/apipie-rails-0.2.5/lib/apipie/extractor/recorder.rb:97: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/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62: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/actionpack-3.2.8/lib/action_dispatch/middleware/static.rb:62: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-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/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:25: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__2224254481398513227__call__3925219232830965256__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/katello-2.2.0.83/lib/katello/middleware/silenced_logger.rb:29: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:245:in `fetch'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:185:in `lookup'
/opt/rh/ruby193/root/usr/share/gems/gems/rack-cache-1.2/lib/rack/cache/context.rb:66: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/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/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `call'
/opt/rh/ruby193/root/usr/share/gems/gems/logging-1.8.1/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
caused by: (Errno::EAGAIN) Resource temporarily unavailable - read would block
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:38:in `read_nonblock'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:38:in `read'
    ... skipped 123 lines
2016-03-28 14:50:18 [I] Completed 500 Internal Server Error in 89643ms (Views: 146.9ms | ActiveRecord: 5.7ms)
2016-03-28 14:50:18 [I] Processing by Fusor::Api::Openstack::NodesController#list_ports as JSON
2016-03-28 14:50:18 [I]   Parameters: {"deployment_id"=>"1", "node"=>{}}
2016-03-28 14:50:18 [E] Excon::Errors::Timeout: read timeout reached
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:61:in `rescue in read'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:35:in `read'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/socket.rb:95:in `readline'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/response.rb:40:in `parse'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/middlewares/response_parser.rb:6:in `response_call'
/opt/rh/ruby193/root/usr/share/gems/gems/docker-api-1.17.0/lib/excon/middlewares/hijack.rb:45:in `response_call'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/connection.rb:402:in `response'
/opt/rh/ruby193/root/usr/share/gems/gems/excon-0.38.0/lib/excon/connection.rb:272:in `request'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-core-1.24.0/lib/fog/core/connection.rb:64:in `request'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-1.24.1/lib/fog/openstack/baremetal.rb:295:in `request'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-1.24.1/lib/fog/openstack/requests/baremetal/list_ports_detailed.rb:16:in `list_ports_detailed'
/opt/rh/ruby193/root/usr/share/gems/gems/fog-1.24.1/lib/fog/openstack/models/baremetal/ports.rb:15:in `details'
/opt/rh/ruby193/root/usr/share/gems/gems/egon-0.4.8/lib/egon/overcloud/undercloud_handle/node.rb:17:in `list_ports_detailed'
/opt/rh/ruby193/root/usr/share/gems/gems/fusor_server-0.0.1/app/controllers/fusor/api/openstack/nodes_controller.rb:72:in `list_ports'
/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:528:in `block (4 levels) in _run__3137742557254255594__process_action__2561651995369239667__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_11645'
/usr/share/foreman/app/controllers/api/v2/base_controller.rb:151:in `disable_json_root'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11645'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:505:in `block (3 levels) in _run__3137742557254255594__process_action__2561651995369239667__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_11644'
/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_3887'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:214:in `_conditional_callback_around_11644'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:493:in `block (2 levels) in _run__3137742557254255594__process_action__2561651995369239667__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_11643'
/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_11643'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:426:in `block in _run__3137742557254255594__process_action__2561651995369239667__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_11642'
/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_11642'
/opt/rh/ruby193/root/usr/share/gems/gems/activesupport-3.2.8/lib/active_support/callbacks.rb:414:in `_run__3137742557254255594__process_action__2561651995369239667__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'
[...]

Can we provide better error handling for this case?

Comment 1 Thom Carlin 2016-03-30 12:24:09 UTC
On Director side in /var/log/messages:
ironic-api: 2016-03-30 08:15:08.433 17104 DEBUG keystonemiddleware.auth_token [-] Removing headers from request environment: X-Service-Catalog,X-Identity-Status,X-Service-Identity-Status,X-Roles,X-Service-Roles,X-Domain-Name,X-Service-Domain-Name,X-Project-Id,X-Service-Project-Id,X-Project-Domain-Name,X-Service-Project-Domain-Name,X-User-Id,X-Service-User-Id,X-User-Name,X-Service-User-Name,X-Project-Name,X-Service-Project-Name,X-User-Domain-Id,X-Service-User-Domain-Id,X-Domain-Id,X-Service-Domain-Id,X-User-Domain-Name,X-Service-User-Domain-Name,X-Project-Domain-Id,X-Service-Project-Domain-Id,X-Role,X-User,X-Tenant-Name,X-Tenant-Id,X-Tenant _remove_auth_headers /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:672
ironic-api: 2016-03-30 08:15:08.434 17104 DEBUG keystonemiddleware.auth_token [-] Authenticating user token __call__ /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:581
ironic-api: 2016-03-30 08:15:08.437 17104 DEBUG keystonemiddleware.auth_token [-] Storing token in cache store /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/_cache.py:192
ironic-api: 2016-03-30 08:15:08.438 17104 DEBUG keystonemiddleware.auth_token [-] Authenticating service token __call__ /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:603
ironic-api: 2016-03-30 08:15:08.438 17104 DEBUG keystonemiddleware.auth_token [-] Received request from user: user_id 683a6253f77544edb7a19eb3df380943, project_id 0aa0c758333949448b371eda3d0b285a, roles _member_,admin service: user_id None, project_id None, roles None __call__ /usr/lib/python2.7/site-packages/keystonemiddleware/auth_token/__init__.py:632
ironic-api: <sat6_ip> - - [30/Mar/2016 08:15:08] "GET /ports/detail HTTP/1.1" 200 13
ironic-api: <director_ip> - - [30/Mar/2016 08:15:36] "GET / HTTP/1.0" 200 316
ironic-api: Traceback (most recent call last):
ironic-api: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 86, in run
ironic-api: self.finish_response()
ironic-api: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 128, in finish_response
ironic-api: self.write(data)
ironic-api: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 212, in write
ironic-api: self.send_headers()
ironic-api: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 270, in send_headers
ironic-api: self.send_preamble()
ironic-api: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 191, in send_preamble
ironic-api: self._write('HTTP/%s %s\r\n' % (self.http_version,self.status))
ironic-api: File "/usr/lib64/python2.7/wsgiref/handlers.py", line 391, in _write
ironic-api: self.stdout.write(data)
ironic-api: File "/usr/lib64/python2.7/socket.py", line 324, in write
ironic-api: self.flush()
ironic-api: File "/usr/lib64/python2.7/socket.py", line 303, in flush
ironic-api: self._sock.sendall(view[write_offset:write_offset+buffer_size])
ironic-api: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
ironic-api: tail = self.send(data, flags)
ironic-api: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
ironic-api: total_sent += fd.send(data[total_sent:], flags)
ironic-api: error: [Errno 104] Connection reset by peer
ironic-api: <director_ip> - - [30/Mar/2016 08:15:36] "GET / HTTP/1.0" 500 59
ironic-api: Traceback (most recent call last):
ironic-api: File "/usr/lib64/python2.7/SocketServer.py", line 593, in process_request_thread
ironic-api: self.finish_request(request, client_address)
ironic-api: File "/usr/lib64/python2.7/SocketServer.py", line 334, in finish_request
ironic-api: self.RequestHandlerClass(request, client_address, self)
ironic-api: File "/usr/lib64/python2.7/SocketServer.py", line 651, in __init__
ironic-api: self.finish()
ironic-api: File "/usr/lib64/python2.7/SocketServer.py", line 710, in finish
ironic-api: self.wfile.close()
ironic-api: File "/usr/lib64/python2.7/socket.py", line 279, in close
ironic-api: self.flush()
ironic-api: File "/usr/lib64/python2.7/socket.py", line 303, in flush
ironic-api: self._sock.sendall(view[write_offset:write_offset+buffer_size])
ironic-api: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 377, in sendall
ironic-api: tail = self.send(data, flags)
ironic-api: File "/usr/lib/python2.7/site-packages/eventlet/greenio/base.py", line 359, in send
ironic-api: total_sent += fd.send(data[total_sent:], flags)
ironic-api: error: [Errno 32] Broken pipe

Comment 2 Thom Carlin 2016-03-30 14:07:30 UTC
User errors:
1) DNS was not resolving on Director
2) There were bi-directional networking issues between Satellite 6 and Director.

Once these were resolved, the issue went away.

The question about improved error handling on this use case is the remaining issue.

Comment 3 Thom Carlin 2016-04-20 16:23:45 UTC
The user error was due to firewall configuration involving packets coming from Director.