No LDAP information written to log

[leonsp]

I have logging enabled in devise.rb:

config.ldap_logger = true

It shows as enabled in rails console:

2.2.2 :005 > Devise.ldap_logger
 => true

However, when I try to sign in, no LDAP debug information is written to the log:

Started POST "/users/sign_in" for ::1 at 2015-11-23 15:22:25 -0500
  ActiveRecord::SchemaMigration Load (84.2ms)  SELECT schema_migrations.* FROM schema_migrations
Processing by Devise::SessionsController#create as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"0r64ONGOtEOc/J9i+ZzO6b4UCVsGcwzgxZIid8vP2B2Cytdy+i2AIgadQY1OAAArjmeoaXFN2Ec+XJBM3ywUQA==", "user"=>{"login"=>"leonsp", "password"=>"...", "remember_me"=>"0"}}
Completed 401 Unauthorized in 76ms (ActiveRecord: 0.0ms)
Processing by Devise::SessionsController#new as HTML
  Parameters: {"utf8"=>"✓", "authenticity_token"=>"0r64ONGOtEOc/J9i+ZzO6b4UCVsGcwzgxZIid8vP2B2Cytdy+i2AIgadQY1OAAArjmeoaXFN2Ec+XJBM3ywUQA==", "user"=>{"login"=>"leonsp", "password"=>"...", "remember_me"=>"0"}}
  Rendered devise/shared/_links.html.haml (2.6ms)
  Rendered devise/sessions/new.html.haml within layouts/application (24.5ms)
  Rendered shared/_header.html.haml (9.4ms)
  Rendered shared/_footer_links.html.haml (1.3ms)
  Rendered shared/_footer.html.erb (2.8ms)
Completed 200 OK in 705ms (Views: 212.1ms | ActiveRecord: 0.0ms)

I've disabled all Rails gems that do anything with logging, but I'm still not seeing any LDAP log messages.

I can successfully connect to the LDAP server using ldapsearch:

ldapsearch -x -W -D "cn=admin,dc=my_domain,dc=com" -H ldap://my_hostname.my_domain.com -b dc=my_domain,dc=com "(cn=leonsp)"

My devise configuration looks the same:

development:
  host: ldap://my_hostname.my_domain.com
  port: 389
  attribute: cn
  base: dc=my_domain,dc=com
  admin_user: cn=admin,dc=my_domain,dc=com
  admin_password: ...
  ssl: none
  # <<: *AUTHORIZATIONS

Why is there no LDAP information in the log?

What additional diagnostics can I try or collect?

[leonsp]

This user had a similar problem, in the sense that their LDAP code was not being run: http://stackoverflow.com/questions/28489814/how-to-debug-custom-devise-strategy-in-rails-4

I've tried upgrading from released gem level (0.8.5) to github master gem level (0.8.6) to no effect.

Excerpt of my user model:

class User < ActiveRecord::Base
  # Include default devise modules. Others available are:
  # :confirmable, :lockable, :timeoutable and :omniauthable
  devise :ldap_authenticatable, :registerable,
    :recoverable, :rememberable, :trackable, :validatable,
    :confirmable, :lockable, :zxcvbnable

I got the model to work with :database_authenticable before trying :ldap_authenticable.

I've now monkeypatched find_for_ldap_authentication in the User model as well as ldap_auth_username_builder and Devise::Strategies::LdapAuthenticatable.authenticate! to write to the debug Rails log before they do anything, and none of them are writing anything to the log.

Why is the LDAP code not being reached?

[leonsp]

I'm tracing the execution with byebug:

[346, 355] in /Users/leonsp/.rvm/gems/ruby-2.2.2/gems/warden-1.2.3/lib/warden/proxy.rb
   346:         strategies = defaults[scope] || defaults[:_all]
   347:       end
   348:
   349:       (strategies || args).each do |name|
   350:         strategy = _fetch_strategy(name, scope)
=> 351:         next unless strategy && !strategy.performed? && strategy.valid?
   352:
   353:         self.winning_strategy = @winning_strategies[scope] = strategy
   354:         strategy._run!
   355:         break if strategy.halted?

At this point, strategy is an instance of :ldap_authenticatable, !strategy.performed? is true, but strategy.valid? is false.

Why is strategy.valid? false for :ldap_authenticatable? I will try to investigate, but this is all new to me.

[leonsp]

Immediate issue was due to https://github.com/plataformatec/devise/issues/1255

I had optional keys in config.authentication_keys. This makes Devise::Strategies#parse_authentication_key_values fail automatically.