Bug #17811
closedLDAP authentication SSL failures are not reported in an understandable way down the stack
Description
Description of problem:
LDAP authentication failures are ofter reported as failures in other components of the stack, making it hard to spot and work on.
hammer -d -u test host list ... [ INFO 2016-12-21T09:35:56 API] GET /api/hosts [DEBUG 2016-12-21T09:35:56 API] Params: { "page" => 1, "per_page" => 1000 } [DEBUG 2016-12-21T09:35:56 API] Headers: { :params => { "page" => 1, "per_page" => 1000 } } [DEBUG 2016-12-21T09:35:56 API] Using authenticator: HammerCLIForeman::Api::InteractiveBasicAuth [ERROR 2016-12-21T09:35:56 API] 500 Internal Server Error [DEBUG 2016-12-21T09:35:56 API] { "error" => { "message" => "SSL_connect SYSCALL returned=5 errno=0 state=SSLv3 read finished A" } } [ERROR 2016-12-21T09:35:56 Exception] SSL_connect SYSCALL returned=5 errno=0 state=SSLv3 read finished A SSL_connect SYSCALL returned=5 errno=0 state=SSLv3 read finished A [ERROR 2016-12-21T09:35:56 Exception] RestClient::InternalServerError (500 Internal Server Error): /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/abstract_response.rb:223:in `exception_with_response' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/abstract_response.rb:103:in `return!' /usr/local/rvm/gems/ruby-2.3.0/gems/apipie-bindings-0.0.19/lib/apipie_bindings/api.rb:332:in `block in rest_client_call_block' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/request.rb:858:in `process_result' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/request.rb:776:in `block in transmit' /usr/local/rvm/rubies/ruby-2.3.0/lib/ruby/2.3.0/net/http.rb:853:in `start' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/request.rb:766:in `transmit' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/request.rb:215:in `execute' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/request.rb:52:in `execute' /usr/local/rvm/gems/ruby-2.3.0/gems/rest-client-2.0.0/lib/restclient/resource.rb:51:in `get' /usr/local/rvm/gems/ruby-2.3.0/gems/apipie-bindings-0.0.19/lib/apipie_bindings/api.rb:313:in `call_client' /usr/local/rvm/gems/ruby-2.3.0/gems/apipie-bindings-0.0.19/lib/apipie_bindings/api.rb:229:in `http_call' /usr/local/rvm/gems/ruby-2.3.0/gems/apipie-bindings-0.0.19/lib/apipie_bindings/api.rb:179:in `call_action' /usr/local/rvm/gems/ruby-2.3.0/gems/apipie-bindings-0.0.19/lib/apipie_bindings/api.rb:174:in `call' /usr/local/rvm/gems/ruby-2.3.0/gems/apipie-bindings-0.0.19/lib/apipie_bindings/resource.rb:21:in `call' /root/hammer/hammer-cli/lib/hammer_cli/apipie/command.rb:43:in `send_request' /root/hammer/hammer-cli-foreman/lib/hammer_cli_foreman/commands.rb:161:in `send_request' /root/hammer/hammer-cli-foreman/lib/hammer_cli_foreman/commands.rb:251:in `send_request' /root/hammer/hammer-cli-foreman/lib/hammer_cli_foreman/commands.rb:286:in `retrieve_all' /root/hammer/hammer-cli-foreman/lib/hammer_cli_foreman/commands.rb:270:in `execute' /usr/local/rvm/gems/ruby-2.3.0/gems/clamp-1.1.1/lib/clamp/command.rb:63:in `run' /root/hammer/hammer-cli/lib/hammer_cli/abstract.rb:24:in `run' /usr/local/rvm/gems/ruby-2.3.0/gems/clamp-1.1.1/lib/clamp/subcommand/execution.rb:11:in `execute' /usr/local/rvm/gems/ruby-2.3.0/gems/clamp-1.1.1/lib/clamp/command.rb:63:in `run' /root/hammer/hammer-cli/lib/hammer_cli/abstract.rb:24:in `run' /usr/local/rvm/gems/ruby-2.3.0/gems/clamp-1.1.1/lib/clamp/subcommand/execution.rb:11:in `execute' /usr/local/rvm/gems/ruby-2.3.0/gems/clamp-1.1.1/lib/clamp/command.rb:63:in `run' /root/hammer/hammer-cli/lib/hammer_cli/abstract.rb:24:in `run' /usr/local/rvm/gems/ruby-2.3.0/gems/clamp-1.1.1/lib/clamp/command.rb:132:in `run' ./bin/hammer:125:in `<main>'
Server logs:
2016-12-21T09:38:05 8a2b9de4 [app] [I] Started GET "/api/hosts?page=1&per_page=1000" for fe80::5054:ff:fef5:1b57 at 2016-12-21 09:38:05 +0000 2016-12-21T09:38:05 8a2b9de4 [app] [I] Processing by Api::V2::HostsController#index as JSON 2016-12-21T09:38:05 8a2b9de4 [app] [I] Parameters: {"page"=>"1", "per_page"=>"1000", "apiv"=>"v2", :host=>{}} 2016-12-21T09:38:05 8a2b9de4 [app] [W] Action failed | OpenSSL::SSL::SSLError: SSL_connect SYSCALL returned=5 errno=0 state=SSLv3 read finished A | /usr/local/rvm/gems/ruby-2.3.0/gems/net-ldap-0.15.0/lib/net/ldap.rb:1303:in `new_connection' | /usr/local/rvm/gems/ruby-2.3.0/gems/net-ldap-0.15.0/lib/net/ldap.rb:854:in `block in bind' | /usr/local/rvm/gems/ruby-2.3.0/gems/net-ldap-0.15.0/lib/net/ldap/instrumentation.rb:16:in `block in instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in `block in instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in `instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/net-ldap-0.15.0/lib/net/ldap/instrumentation.rb:15:in `instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/net-ldap-0.15.0/lib/net/ldap.rb:848:in `bind' | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/freeipa.rb:12:in `bind? | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/generic.rb:58:in `service_bind' | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/generic.rb:20:in `user_exists? | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/ldap_fluff.rb:63:in `block in valid_user? | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/ldap_fluff.rb:94:in `block in instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in `block in instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications/instrumenter.rb:20:in `instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/activesupport-4.2.7.1/lib/active_support/notifications.rb:164:in `instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/ldap_fluff.rb:93:in `instrument' | /usr/local/rvm/gems/ruby-2.3.0/gems/ldap_fluff-0.4.4/lib/ldap_fluff/ldap_fluff.rb:62:in `valid_user? | /root/foreman/foreman/app/models/auth_sources/auth_source_ldap.rb:61:in `authenticate' | /root/foreman/foreman/app/models/user.rb:189:in `try_to_login' | /root/foreman/foreman/app/services/sso/basic.rb:10:in `block in authenticate! | /usr/local/rvm/gems/ruby-2.3.0/gems/actionpack-4.2.7.1/lib/action_controller/metal/http_authentication.rb:97:in `authenticate' | /usr/local/rvm/gems/ruby-2.3.0/gems/actionpack-4.2.7.1/lib/action_controller/metal/http_authentication.rb:87:in `authenticate_with_http_basic' | /root/foreman/foreman/app/services/sso/basic.rb:8:in `authenticate! | /root/foreman/foreman/app/services/sso/basic.rb:17:in `authenticated? | /root/foreman/foreman/app/controllers/concerns/foreman/controller/authentication.rb:62:in `sso_authentication' | /root/foreman/foreman/app/controllers/concerns/foreman/controller/authentication.rb:14:in `authenticate' | /root/foreman/foreman/app/controllers/api/base_controller.rb:156:in `authorize' ... 2016-12-21T09:38:05 8a2b9de4 [app] [I] Rendered api/v2/errors/standard_error.json.rabl within api/v2/layouts/error_layout (0.5ms) 2016-12-21T09:38:05 8a2b9de4 [app] [I] Completed 500 Internal Server Error in 13ms (Views: 3.4ms | ActiveRecord: 0.9ms)
500 internal server error is misleading, if the ssl issue is on ldaps connection.
Version-Release number of selected component (if applicable):
foreman 1.14
Steps to Reproduce:
1. Perform an action (through Hammer, for example) that would trigger a SSL handshake
2. Have the server drop the connection
3. Inspect the error reported by the tool used (Hammer, for example)
Actual results:
Unuseful error message such as
2016-06-10 16:52:08 [I] Completed 500 Internal Server Error in 116ms (Views: 0.4ms | ActiveRecord: 0.9ms)
Expected results:
More useful error message, that points out the target LDAP server has dropped the connection or had problems completing the request.