NoMethodError (undefined method `find'...) when user logs in

[evle-zzz]

Getting following error when user logs in. If user was already logged in before plugin is installed everything works fine.

Environment:
Redmine version 4.0.4.stable
Ruby version 2.5.5-p157 (2019-03-15) [x86_64-linux-gnu]
Rails version 5.2.3

NoMethodError (undefined method `find' for #<ActionController::Parameters:0x000055dd39c946b0>):

plugins/redmine_ldap_sync/app/models/ldap_setting.rb:182:in `user_field'
plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:39:in `block in get_user_fields'
plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:38:in `inject'
plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:38:in `get_user_fields'
plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:181:in `sync_user_fields'
plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:124:in `block in sync_user'
plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:386:in `block in with_ldap_connection'
plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:384:in `with_ldap_connection'
plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:105:in `sync_user'
plugins/redmine_ldap_sync/lib/ldap_sync/infectors/user.rb:94:in `try_to_login_with_ldap_sync'
app/controllers/account_controller.rb:216:in `password_authentication'
app/controllers/account_controller.rb:211:in `authenticate_user'
app/controllers/account_controller.rb:38:in `login'
lib/redmine/sudo_mode.rb:63:in `sudo_mode'

[tainewoo]

Hi @evle-zzz,
sorry i can’t reproduce this issue with my environment, and seems the db migration may not be completed.
But my env may be a little different to yours , redmine4.0.3 with newer rails and ruby.
Would you try provide more info for me to recheck? i will have a further check after i back from holiday.

1. can u help rerun the db migrate for both redmine and plugin
2. can you help check the account type of the failed accounts. the accounts created by the plugin would be categorized as your ldap entry name, and Redmine internal accounts should be “Internal”

[evle-zzz]

Hi, @tainewoo. Unfortunatally I can't upgrade my rails and ruby yet, it's what come with Debian 10.
I tried what you suggested.

1. Both migrations finish without errors.
2. Actually every account I test is failing. Account type is correct and everything was working just fine before I have updated installation to redmine 4 and swithched plugin to this fork.

Also when I try to run redmine:plugins:ldap_sync:sync_users task it updates several users and then fails with this:

rake aborted!
NoMethodError: undefined method `find' for #<ActionController::Parameters:0x0000562ad1285cb0>
/var/data/redmine/plugins/redmine_ldap_sync/app/models/ldap_setting.rb:182:in `user_field'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:39:in `block in get_user_fields'
/var/lib/gems/2.5.0/gems/net-ldap-0.16.1/lib/net/ldap/entry.rb:146:in `block in each'
/var/lib/gems/2.5.0/gems/net-ldap-0.16.1/lib/net/ldap/entry.rb:144:in `each'
/var/lib/gems/2.5.0/gems/net-ldap-0.16.1/lib/net/ldap/entry.rb:144:in `each'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:38:in `inject'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:38:in `get_user_fields'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:181:in `sync_user_fields'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:124:in `block in sync_user'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:376:in `with_ldap_connection'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:105:in `sync_user'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:78:in `block (2 levels) in sync_users'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:65:in `each'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:65:in `block in sync_users'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:386:in `block in with_ldap_connection'
/var/lib/gems/2.5.0/gems/net-ldap-0.16.1/lib/net/ldap.rb:716:in `block in open'
/var/lib/gems/2.5.0/gems/net-ldap-0.16.1/lib/net/ldap/instrumentation.rb:19:in `instrument'
/var/lib/gems/2.5.0/gems/net-ldap-0.16.1/lib/net/ldap.rb:711:in `open'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb:384:in `with_ldap_connection'
/var/data/redmine/plugins/redmine_ldap_sync/lib/ldap_sync/infectors/auth_source_ldap.rb:64:in `sync_users'
/var/data/redmine/plugins/redmine_ldap_sync/lib/tasks/ldap_sync.rake:29:in `block (5 levels) in <top (required)>'
/var/lib/gems/2.5.0/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/var/lib/gems/2.5.0/gems/activerecord-5.2.3/lib/active_record/relation/delegation.rb:71:in `each'
/var/data/redmine/plugins/redmine_ldap_sync/lib/tasks/ldap_sync.rake:27:in `block (4 levels) in <top (required)>'
/var/lib/gems/2.5.0/gems/rake-12.3.3/exe/rake:27:in `<top (required)>'
Tasks: TOP => redmine:plugins:ldap_sync:sync_users
(See full trace by running task with --trace)

Unfortionally I'm not familiar enough with redmine internals to figure out the next step.

[tainewoo]

Hi evle-zzz,

Let me have a check.
Can you help post the file content of your local version for:
plugins\redmine_ldap_sync\lib\ldap_sync\entity_manager.rb

line 24-44
line 373-391

[evle-zzz]

sed '24,44 !d' plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb
    def get_user_fields(username, user_data=nil, options={})
      fields_to_sync = setting.user_fields_to_sync
      if options.try(:fetch, :include_required, false)
        custom_fields = user_required_custom_fields.map {|cf| cf.id.to_s }
        fields_to_sync -= (User::STANDARD_FIELDS + custom_fields)
        fields_to_sync += (User::STANDARD_FIELDS + custom_fields)
      end
      ldap_attrs_to_sync = setting.user_ldap_attrs_to_sync(fields_to_sync)

      user_data ||= with_ldap_connection do |ldap|
        find_user(ldap, username, ldap_attrs_to_sync)
      end
      return {} if user_data.nil?

      user_fields = user_data.inject({}) do |fields, (attr, value)|
        f = setting.user_field(attr)
        if f && fields_to_sync.include?(f)
          fields[f] = value.first unless value.nil? || value.first.blank?
        end
        fields
      end

root@redmine2:/var/data/redmine# sed '373,391 !d' plugins/redmine_ldap_sync/lib/ldap_sync/entity_manager.rb
    def with_ldap_connection(login = nil, password = nil)
      thread = Thread.current

      return yield thread[:local_ldap_con] if thread[:local_ldap_con].present?

      ldap_con = if setting.account && setting.account.include?('$login')
        initialize_ldap_con(setting.account.sub('$login', Net::LDAP::DN.escape(login)), password)
      else
        initialize_ldap_con(setting.account, setting.account_password)
      end

      ldap_con.open do |ldap|
        begin
          yield thread[:local_ldap_con] = ldap
        ensure
          thread[:local_ldap_con] = nil
        end
      end
    end

[susu3621]

Seems I faced the same issue.
I'm using redmine in docker https://hub.docker.com/r/sameersbn/redmine/

The following is the detail redmine information.

Environment:
Redmine version 4.1.0.stable
Ruby version 2.4.9-p362 (2019-10-02) [x86_64-linux-gnu]
Rails version 5.2.4.1
Environment production
Database adapter PostgreSQL
Mailer queue ActiveJob::QueueAdapters::AsyncAdapter
Mailer delivery smtp
SCM:
Subversion 1.9.3
Mercurial 3.7.3
Cvs 1.12.13
Bazaar 2.7.0
Git 2.24.1
Filesystem
Redmine plugins:
redmine_ldap_sync 2.2.0

I opened log level to debug, and the log is as below:

Started GET "/admin/ldap_sync/base_settings.js" for 127.0.0.1 at 2020-01-21 13:27:12 +0000
Processing by LdapSettingsController#base_settings as JS
^[[1m^[[36mToken Update All (1.7ms)^[[0m ^[[1m^[[33mUPDATE "tokens" SET "updated_on" = '2020-01-21 13:27:12.607033' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3^[[0m [["user_id", 1], ["value", "deb2441837d8f2cf3de9900cf95d84c16964345c"], ["action", "session"]]
^[[1m^[[35m (0.8ms)^[[0m ^[[1m^[[34mSELECT MAX("settings"."updated_on") FROM "settings"^[[0m
^[[1m^[[36mUser Load (0.9ms)^[[0m ^[[1m^[[34mSELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3^[[0m [["status", 1], ["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
Rendering plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb
Rendered plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb (3.5ms)
Completed 200 OK in 14ms (Views: 4.6ms | ActiveRecord: 3.4ms)
Started PUT "/admin/ldap_sync/1/test.text" for 127.0.0.1 at 2020-01-21 13:27:16 +0000
Processing by LdapSettingsController#test as TEXT
Parameters: {"id"=>"1"}
^[[1m^[[36mToken Update All (1.0ms)^[[0m ^[[1m^[[33mUPDATE "tokens" SET "updated_on" = '2020-01-21 13:27:16.233281' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3^[[0m [["user_id", 1], ["value", "deb2441837d8f2cf3de9900cf95d84c16964345c"], ["action", "session"]]
^[[1m^[[35m (0.5ms)^[[0m ^[[1m^[[34mSELECT MAX("settings"."updated_on") FROM "settings"^[[0m
^[[1m^[[36mUser Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3^[[0m [["status", 1], ["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
^[[1m^[[36mAuthSourceLdap Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "auth_sources".* FROM "auth_sources" WHERE "auth_sources"."type" IN ('AuthSourceLdap') AND "auth_sources"."id" = $1 LIMIT $2^[[0m [["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
Rendering plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb
Rendered plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb (3.5ms)
Completed 200 OK in 14ms (Views: 4.6ms | ActiveRecord: 3.4ms)
Started PUT "/admin/ldap_sync/1/test.text" for 127.0.0.1 at 2020-01-21 13:27:16 +0000
Processing by LdapSettingsController#test as TEXT
Parameters: {"id"=>"1"}
^[[1m^[[36mToken Update All (1.0ms)^[[0m ^[[1m^[[33mUPDATE "tokens" SET "updated_on" = '2020-01-21 13:27:16.233281' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3^[[0m [["user_id", 1], ["value", "deb2441837d8f2cf3de9900cf95d84c16964345c"], ["action", "session"]]
^[[1m^[[35m (0.5ms)^[[0m ^[[1m^[[34mSELECT MAX("settings"."updated_on") FROM "settings"^[[0m
^[[1m^[[36mUser Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3^[[0m [["status", 1], ["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
^[[1m^[[36mAuthSourceLdap Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "auth_sources".* FROM "auth_sources" WHERE "auth_sources"."type" IN ('AuthSourceLdap') AND "auth_sources"."id" = $1 LIMIT $2^[[0m [["id", 1], ["LIMIT", 1]]
^[[1m^[[36mUserCustomField Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('UserCustomField')^[[0m
^[[1m^[[36mCACHE UserCustomField Load (0.0ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('UserCustomField')^[[0m
^[[1m^[[36mGroupCustomField Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('GroupCustomField')^[[0m
^[[1m^[[36mCACHE GroupCustomField Load (0.0ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('GroupCustomField')^[[0m
Completed 500 Internal Server Error in 13ms (ActiveRecord: 3.5ms)

NoMethodError (undefined method `fetch' for nil:NilClass):

plugins/redmine_ldap_sync/app/controllers/ldap_settings_controller.rb:83:in test' lib/redmine/sudo_mode.rb:65:in sudo_mode'

[yuxinvalo]

Seems I faced the same issue.
I'm using redmine in docker https://hub.docker.com/r/sameersbn/redmine/

The following is the detail redmine information.

Environment:
Redmine version 4.1.0.stable
Ruby version 2.4.9-p362 (2019-10-02) [x86_64-linux-gnu]
Rails version 5.2.4.1
Environment production
Database adapter PostgreSQL
Mailer queue ActiveJob::QueueAdapters::AsyncAdapter
Mailer delivery smtp
SCM:
Subversion 1.9.3
Mercurial 3.7.3
Cvs 1.12.13
Bazaar 2.7.0
Git 2.24.1
Filesystem
Redmine plugins:
redmine_ldap_sync 2.2.0

I opened log level to debug, and the log is as below:

Started GET "/admin/ldap_sync/base_settings.js" for 127.0.0.1 at 2020-01-21 13:27:12 +0000
Processing by LdapSettingsController#base_settings as JS
^[[1m^[[36mToken Update All (1.7ms)^[[0m ^[[1m^[[33mUPDATE "tokens" SET "updated_on" = '2020-01-21 13:27:12.607033' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3^[[0m [["user_id", 1], ["value", "deb2441837d8f2cf3de9900cf95d84c16964345c"], ["action", "session"]]
^[[1m^[[35m (0.8ms)^[[0m ^[[1m^[[34mSELECT MAX("settings"."updated_on") FROM "settings"^[[0m
^[[1m^[[36mUser Load (0.9ms)^[[0m ^[[1m^[[34mSELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3^[[0m [["status", 1], ["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
Rendering plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb
Rendered plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb (3.5ms)
Completed 200 OK in 14ms (Views: 4.6ms | ActiveRecord: 3.4ms)
Started PUT "/admin/ldap_sync/1/test.text" for 127.0.0.1 at 2020-01-21 13:27:16 +0000
Processing by LdapSettingsController#test as TEXT
Parameters: {"id"=>"1"}
^[[1m^[[36mToken Update All (1.0ms)^[[0m ^[[1m^[[33mUPDATE "tokens" SET "updated_on" = '2020-01-21 13:27:16.233281' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3^[[0m [["user_id", 1], ["value", "deb2441837d8f2cf3de9900cf95d84c16964345c"], ["action", "session"]]
^[[1m^[[35m (0.5ms)^[[0m ^[[1m^[[34mSELECT MAX("settings"."updated_on") FROM "settings"^[[0m
^[[1m^[[36mUser Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3^[[0m [["status", 1], ["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
^[[1m^[[36mAuthSourceLdap Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "auth_sources".* FROM "auth_sources" WHERE "auth_sources"."type" IN ('AuthSourceLdap') AND "auth_sources"."id" = $1 LIMIT $2^[[0m [["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
Rendering plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb
Rendered plugins/redmine_ldap_sync/app/views/ldap_settings/base_settings.js.erb (3.5ms)
Completed 200 OK in 14ms (Views: 4.6ms | ActiveRecord: 3.4ms)
Started PUT "/admin/ldap_sync/1/test.text" for 127.0.0.1 at 2020-01-21 13:27:16 +0000
Processing by LdapSettingsController#test as TEXT
Parameters: {"id"=>"1"}
^[[1m^[[36mToken Update All (1.0ms)^[[0m ^[[1m^[[33mUPDATE "tokens" SET "updated_on" = '2020-01-21 13:27:16.233281' WHERE "tokens"."user_id" = $1 AND "tokens"."value" = $2 AND "tokens"."action" = $3^[[0m [["user_id", 1], ["value", "deb2441837d8f2cf3de9900cf95d84c16964345c"], ["action", "session"]]
^[[1m^[[35m (0.5ms)^[[0m ^[[1m^[[34mSELECT MAX("settings"."updated_on") FROM "settings"^[[0m
^[[1m^[[36mUser Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "users".* FROM "users" WHERE "users"."type" IN ('User', 'AnonymousUser') AND "users"."status" = $1 AND "users"."id" = $2 LIMIT $3^[[0m [["status", 1], ["id", 1], ["LIMIT", 1]]
Current user: admin (id=1)
^[[1m^[[36mAuthSourceLdap Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "auth_sources".* FROM "auth_sources" WHERE "auth_sources"."type" IN ('AuthSourceLdap') AND "auth_sources"."id" = $1 LIMIT $2^[[0m [["id", 1], ["LIMIT", 1]]
^[[1m^[[36mUserCustomField Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('UserCustomField')^[[0m
^[[1m^[[36mCACHE UserCustomField Load (0.0ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('UserCustomField')^[[0m
^[[1m^[[36mGroupCustomField Load (0.5ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('GroupCustomField')^[[0m
^[[1m^[[36mCACHE GroupCustomField Load (0.0ms)^[[0m ^[[1m^[[34mSELECT "custom_fields".* FROM "custom_fields" WHERE "custom_fields"."type" IN ('GroupCustomField')^[[0m
Completed 500 Internal Server Error in 13ms (ActiveRecord: 3.5ms)

NoMethodError (undefined method `fetch' for nil:NilClass):

plugins/redmine_ldap_sync/app/controllers/ldap_settings_controller.rb:83:in test' lib/redmine/sudo_mode.rb:65:in sudo_mode'

I have a same issue...

[tainewoo]

Hi all,

sorry for late response due to lots of problems these months.

Please check your LDAP settings: Administration - LDAP Authentication
Possibly the Account/Password is not set and saved before you tried to perform the LDAP sync test.

[evle-zzz]

@tainewoo For me it's not the case. Account is set correct, tests on check page are passed and some users are synced by redmine:plugins:ldap_sync:sync_users before it fails.

[tainewoo]

Hi @evle-zzz ,

can you help confirm if the required fields have particular value from your ldap server?

[vegaaz]

@tainewoo For me it's not the case. Account is set correct, tests on check page are passed and some users are synced by redmine:plugins:ldap_sync:sync_users before it fails.

I got the same Issue.
Environment:
Redmine in Docker (https://hub.docker.com/_/redmine)
Redmine Version: 4.1.1 stable
Ruby Version: 2.6.6
Rails Version: 5.2.4.2

Same behavior as @evle-zzz. Ldap sync start to load some Users and then stops with the said error message.
Do you have any workaround?

[evle-zzz]

Annoyingly I still didn't get this error fixed. I have some guesses but for now that's all. No time to learn ruby to debug this properly. :-(
It's possible that issue has something to do with encoding. There are a lot of encoding conversion errors in the log and I'm not sure how they are related to the problem.

[rembik]

I have the exact same issue as @evle-zzz after updating from Redmine 3.3.9 to 4.0.7 on Ruby 2.3.8. Update migrations were successful and before upgrading Redmine to 4.0.7 and the ldap_sync plugin to this fork everything was working fine.