Self-registration automatic account activation result in session expired #70

efabris · 2025-02-18T15:38:19Z

When self-registration is enabled and automatic account activation is selected, at the first login we got this error:

Environment:
  Redmine version                6.0.3.stable
  Ruby version                   3.2.3-p157 (2024-01-18) [x86_64-linux-gnu]
  Rails version                  7.2.2.1
  Environment                    production
  Database adapter               Mysql2
  Mailer queue                   ActiveJob::QueueAdapters::AsyncAdapter
  Mailer delivery                smtp
Redmine settings:
  Redmine theme                  Default
SCM:
  Git                            2.43.0
  Filesystem                     
Redmine plugins:
  redmine_oauth                  3.0.2

Log Output:

I, [2025-02-18T15:30:42.517176 #230567]  INFO -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8] Started GET "/support/oauth?back_url=%2Fsupport%2F&login-oauth=" for 95.251.190.204 at 2025-02-18 15:30:42 +0000
I, [2025-02-18T15:30:42.518707 #230567]  INFO -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8] Processing by RedmineOauthController#oauth as HTML
I, [2025-02-18T15:30:42.519021 #230567]  INFO -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8]   Parameters: {"back_url"=>"/support/", "login-oauth"=>""}
D, [2025-02-18T15:30:42.521043 #230567] DEBUG -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8]   Setting Maximum (0.5ms)  SELECT MAX(`settings`.`updated_on`) FROM `settings`
D, [2025-02-18T15:30:42.522602 #230567] DEBUG -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8]   AnonymousUser Load (0.4ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
I, [2025-02-18T15:30:42.523004 #230567]  INFO -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8]   Current user: anonymous
I, [2025-02-18T15:30:42.524207 #230567]  INFO -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8] Redirected to https://XXXXXXXXXXXXXX/XXXXXXXXXXXXXXXXX/authorize?client_id=XXXXXXXXXXXXX&code_challenge=XXXXXXXXXXXXXXXXX&code_challenge_method=S256&redirect_uri=https%3A%2F%2FXXXXXXXXXXXXXX%2Fsupport%2Foauth2callback&response_type=code&scope=openid+profile+email&state=XXXXXXXXXXXXXXXXXXXX
I, [2025-02-18T15:30:42.524527 #230567]  INFO -- : [f037c809-d3e9-41b2-b40e-ff1453499cd8] Completed 302 Found in 5ms (ActiveRecord: 0.9ms (2 queries, 0 cached) | GC: 0.0ms)
I, [2025-02-18T15:30:43.438532 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] Started GET "/support/oauth2callback?code=c9810811-e50d-433a-b4ee-972cb436edce&state=XXXXXXXXXXXXXXXXXXXX" for 95.251.190.204 at 2025-02-18 15:30:43 +0000
I, [2025-02-18T15:30:43.440083 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] Processing by RedmineOauthController#oauth_callback as HTML
I, [2025-02-18T15:30:43.440289 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Parameters: {"code"=>"c9810811-e50d-433a-b4ee-972cb436edce", "state"=>"XXXXXXXXXXXXXXXXXXXX"}
D, [2025-02-18T15:30:43.442212 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Setting Maximum (0.5ms)  SELECT MAX(`settings`.`updated_on`) FROM `settings`
D, [2025-02-18T15:30:43.443830 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   AnonymousUser Load (0.6ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
I, [2025-02-18T15:30:43.444164 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Current user: anonymous
I, [2025-02-18T15:30:43.983906 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] >>> email
I, [2025-02-18T15:30:43.984183 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] >>> XXXXXXXXXXXXXXXXX
I, [2025-02-18T15:30:43.984299 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] >>> {"family_name"=>"Fabris", "given_name"=>"Enrico", "preferred_username"=>"XXXXXXXXXXXXXXXXX", "organization"=>"undefined", "email"=>"XXXXXXXXXXXXXXXXX", "roles"=>["admin", "user"], "login"=>"XXXXXXXXXXXXXXXXX"}
D, [2025-02-18T15:30:43.987053 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Load (0.7ms)  SELECT `users`.* FROM `users` INNER JOIN `email_addresses` ON `email_addresses`.`user_id` = `users`.`id` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `email_addresses`.`address` = 'XXXXXXXXXXXXXXXXX' ORDER BY `users`.`id` ASC LIMIT 1
D, [2025-02-18T15:30:43.989813 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (0.2ms)  BEGIN
D, [2025-02-18T15:30:43.990551 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   EmailAddress Exists? (1.0ms)  SELECT 1 AS one FROM `email_addresses` WHERE `email_addresses`.`address` = 'XXXXXXXXXXXXXXXXX' LIMIT 1
D, [2025-02-18T15:30:43.991466 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   CustomField Load (0.3ms)  SELECT `custom_fields`.* FROM `custom_fields` WHERE (type = 'UserCustomField') ORDER BY `custom_fields`.`position` ASC
D, [2025-02-18T15:30:43.992374 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Exists? (0.3ms)  SELECT 1 AS one FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`login` = 'XXXXXXXXXXXXXXXXX' LIMIT 1
D, [2025-02-18T15:30:43.994195 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Create (0.3ms)  INSERT INTO `users` (`login`, `hashed_password`, `firstname`, `lastname`, `last_login_on`, `created_on`, `updated_on`, `type`, `mail_notification`, `salt`, `passwd_changed_on`) VALUES ('XXXXXXXXXXXXXXXXX', '29a83c51b542caa7a1155292fa7d6fc2d90e390b', 'Enrico', 'Fabris', '2025-02-18 15:30:43', '2025-02-18 15:30:43', '2025-02-18 15:30:43', 'User', 'only_assigned', '4cbe70355584705bb2ebec675ad9c0f5', '2025-02-18 15:30:43')
D, [2025-02-18T15:30:43.995688 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   EmailAddress Create (0.4ms)  INSERT INTO `email_addresses` (`user_id`, `address`, `is_default`, `created_on`, `updated_on`) VALUES (34, 'XXXXXXXXXXXXXXXXX', TRUE, '2025-02-18 15:30:43', '2025-02-18 15:30:43')
D, [2025-02-18T15:30:43.997006 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   CustomValue Load (0.4ms)  SELECT `custom_values`.* FROM `custom_values` WHERE `custom_values`.`customized_id` = 34 AND `custom_values`.`customized_type` = 'Principal'
D, [2025-02-18T15:30:43.998833 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Delete All (0.3ms)  DELETE FROM `tokens` WHERE `tokens`.`user_id` = 34 AND `tokens`.`action` IN ('recovery', 'autologin', 'session')
D, [2025-02-18T15:30:44.011955 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (12.9ms)  COMMIT
D, [2025-02-18T15:30:44.013470 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Load (0.4ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
D, [2025-02-18T15:30:44.015025 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   EmailAddress Pluck (0.3ms)  SELECT `email_addresses`.`address` FROM `email_addresses` WHERE `email_addresses`.`user_id` = 34
D, [2025-02-18T15:30:44.016382 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (0.2ms)  BEGIN
D, [2025-02-18T15:30:44.017265 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Exists? (1.1ms)  SELECT 1 AS one FROM `tokens` WHERE `tokens`.`value` = CAST('' AS BINARY) LIMIT 1
D, [2025-02-18T15:30:44.018340 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   CACHE User Load (0.0ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
D, [2025-02-18T15:30:44.019569 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Ids (0.3ms)  SELECT `tokens`.`id` FROM `tokens` WHERE `tokens`.`user_id` = 34 AND `tokens`.`action` = 'session' ORDER BY `tokens`.`updated_on` DESC LIMIT 18446744073709551615 OFFSET 9
D, [2025-02-18T15:30:44.020827 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Create (0.4ms)  INSERT INTO `tokens` (`user_id`, `action`, `value`, `created_on`, `updated_on`) VALUES (34, 'session', '3ed3d1b19f42d3497aac77f45611361e3691f9df', '2025-02-18 15:30:44', '2025-02-18 15:30:44')
D, [2025-02-18T15:30:44.031637 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (10.5ms)  COMMIT
D, [2025-02-18T15:30:44.033832 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Group Load (0.5ms)  SELECT `users`.* FROM `users` INNER JOIN `groups_users` ON `users`.`id` = `groups_users`.`group_id` WHERE `users`.`type` IN ('Group', 'GroupBuiltin', 'GroupNonMember', 'GroupAnonymous') AND `groups_users`.`user_id` = 34
D, [2025-02-18T15:30:44.034964 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (0.1ms)  BEGIN
D, [2025-02-18T15:30:44.035315 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Exists? (0.5ms)  SELECT 1 AS one FROM `tokens` WHERE `tokens`.`value` = CAST('' AS BINARY) LIMIT 1
D, [2025-02-18T15:30:44.036286 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Load (0.3ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
D, [2025-02-18T15:30:44.037373 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Ids (0.3ms)  SELECT `tokens`.`id` FROM `tokens` WHERE `tokens`.`user_id` = 34 AND `tokens`.`action` = 'session' ORDER BY `tokens`.`updated_on` DESC LIMIT 18446744073709551615 OFFSET 9
D, [2025-02-18T15:30:44.038728 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Create (0.5ms)  INSERT INTO `tokens` (`user_id`, `action`, `value`, `created_on`, `updated_on`) VALUES (34, 'session', 'fa9d008156f2453b029ba3dad40cbbdf2b8cb9e5', '2025-02-18 15:30:44', '2025-02-18 15:30:44')
D, [2025-02-18T15:30:44.050207 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (11.1ms)  COMMIT
I, [2025-02-18T15:30:44.050986 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] Redirected to https://XXXXXXXXXXXXXX/support/my/account
D, [2025-02-18T15:30:44.052608 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (0.2ms)  BEGIN
D, [2025-02-18T15:30:44.053254 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Update (0.3ms)  UPDATE `users` SET `users`.`hashed_password` = '9b072c8b88fdec39dccd88343c0918a8979d2456', `users`.`admin` = TRUE, `users`.`updated_on` = '2025-02-18 15:30:44', `users`.`salt` = 'e83269f5295a8df0f32d8c4472ec4637', `users`.`passwd_changed_on` = '2025-02-18 15:30:44' WHERE `users`.`id` = 34
D, [2025-02-18T15:30:44.054450 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   Token Delete All (0.3ms)  DELETE FROM `tokens` WHERE `tokens`.`user_id` = 34 AND `tokens`.`action` IN ('recovery', 'autologin', 'session')
D, [2025-02-18T15:30:44.055552 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   User Load (0.3ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`status` = 1 AND `users`.`admin` = TRUE
I, [2025-02-18T15:30:44.057018 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] [ActiveJob] Enqueued Mailer::DeliveryJob (Job ID: 90a5ca6d-3c49-430c-b5b4-88cdbafed329) to Async(mailers) with arguments: "Mailer", "security_notification", "deliver_now", {:args=>[#<GlobalID:0x0000778ab8a408e8 @uri=#<URI::GID gid://redmine-app/User/1>>, #<GlobalID:0x0000778ab87cf988 @uri=#<URI::GID gid://redmine-app/User/34>>, {:field=>"field_admin", :value=>"XXXXXXXXXXXXXXXXX", :title=>"label_user_plural", :url=>{:controller=>"users", :action=>"index"}, :message=>"mail_body_security_notification_add", :remote_ip=>nil}]}
I, [2025-02-18T15:30:44.058814 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] [ActiveJob] Enqueued Mailer::DeliveryJob (Job ID: b267e5af-98d1-46eb-af90-2f2e41807bc1) to Async(mailers) with arguments: "Mailer", "security_notification", "deliver_now", {:args=>[#<GlobalID:0x0000778ab87c6b30 @uri=#<URI::GID gid://redmine-app/User/19>>, #<GlobalID:0x0000778ab87c6338 @uri=#<URI::GID gid://redmine-app/User/34>>, {:field=>"field_admin", :value=>"XXXXXXXXXXXXXXXXX", :title=>"label_user_plural", :url=>{:controller=>"users", :action=>"index"}, :message=>"mail_body_security_notification_add", :remote_ip=>nil}]}
I, [2025-02-18T15:30:44.059756 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] [ActiveJob] Enqueued Mailer::DeliveryJob (Job ID: d8e7b242-6a8a-4725-80a8-f01a80d4d1cc) to Async(mailers) with arguments: "Mailer", "security_notification", "deliver_now", {:args=>[#<GlobalID:0x0000778ab87c1ab8 @uri=#<URI::GID gid://redmine-app/User/34>>, #<GlobalID:0x0000778ab87c13b0 @uri=#<URI::GID gid://redmine-app/User/34>>, {:field=>"field_admin", :value=>"XXXXXXXXXXXXXXXXX", :title=>"label_user_plural", :url=>{:controller=>"users", :action=>"index"}, :message=>"mail_body_security_notification_add", :remote_ip=>nil}]}
D, [2025-02-18T15:30:44.059138 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   User Load (1.2ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 1 LIMIT 1
D, [2025-02-18T15:30:44.064577 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   User Load (3.8ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
I, [2025-02-18T15:30:44.065226 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329] Performing Mailer::DeliveryJob (Job ID: 90a5ca6d-3c49-430c-b5b4-88cdbafed329) from Async(mailers) enqueued at 2025-02-18T15:30:44.056437430Z with arguments: "Mailer", "security_notification", "deliver_now", {:args=>[#<GlobalID:0x0000778ab87dba80 @uri=#<URI::GID gid://redmine-app/User/1>>, #<GlobalID:0x0000778ab87db418 @uri=#<URI::GID gid://redmine-app/User/34>>, {:field=>"field_admin", :value=>"XXXXXXXXXXXXXXXXX", :title=>"label_user_plural", :url=>{:controller=>"users", :action=>"index"}, :message=>"mail_body_security_notification_add", :remote_ip=>nil}]}
D, [2025-02-18T15:30:44.066918 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   AnonymousUser Load (0.5ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
D, [2025-02-18T15:30:44.068901 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   EmailAddress Pluck (0.4ms)  SELECT `email_addresses`.`address` FROM `email_addresses` WHERE `email_addresses`.`user_id` = 1 AND (is_default = '1' OR notify = '1')
D, [2025-02-18T15:30:44.069976 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendering layout layouts/mailer.text.erb
D, [2025-02-18T15:30:44.070086 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendering mailer/security_notification.text.erb within layouts/mailer
D, [2025-02-18T15:30:44.071407 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   UserPreference Load (0.3ms)  SELECT `user_preferences`.* FROM `user_preferences` WHERE `user_preferences`.`user_id` = 1 LIMIT 1
I, [2025-02-18T15:30:44.071893 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendered mailer/security_notification.text.erb within layouts/mailer (Duration: 1.8ms | GC: 0.2ms)
I, [2025-02-18T15:30:44.072185 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendered layout layouts/mailer.text.erb (Duration: 2.1ms | GC: 0.2ms)
D, [2025-02-18T15:30:44.072753 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendering layout layouts/mailer.html.erb
D, [2025-02-18T15:30:44.072971 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendering mailer/security_notification.html.erb within layouts/mailer
I, [2025-02-18T15:30:44.073427 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendered mailer/security_notification.html.erb within layouts/mailer (Duration: 0.3ms | GC: 0.0ms)
I, [2025-02-18T15:30:44.075681 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329]   Rendered layout layouts/mailer.html.erb (Duration: 2.7ms | GC: 0.0ms)
D, [2025-02-18T15:30:44.085848 #230567] DEBUG -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa]   TRANSACTION (25.8ms)  COMMIT
I, [2025-02-18T15:30:44.086175 #230567]  INFO -- : [e08e8b6c-ad73-446c-9b92-e9781866b0fa] Completed 302 Found in 646ms (ActiveRecord: 70.7ms (24 queries, 1 cached) | GC: 2.5ms)
I, [2025-02-18T15:30:44.125700 #230567]  INFO -- : [39869682-0091-448d-91a6-51fcffcd0913] Started GET "/support/my/account" for 95.251.190.204 at 2025-02-18 15:30:44 +0000
I, [2025-02-18T15:30:44.126836 #230567]  INFO -- : [39869682-0091-448d-91a6-51fcffcd0913] Processing by MyController#account as HTML
D, [2025-02-18T15:30:44.129195 #230567] DEBUG -- : [39869682-0091-448d-91a6-51fcffcd0913]   Token Maximum (0.5ms)  SELECT MAX(`tokens`.`updated_on`) FROM `tokens` WHERE `tokens`.`user_id` = 34 AND `tokens`.`value` = 'fa9d008156f2453b029ba3dad40cbbdf2b8cb9e5' AND `tokens`.`action` = 'session'
D, [2025-02-18T15:30:44.130711 #230567] DEBUG -- : [39869682-0091-448d-91a6-51fcffcd0913]   User Load (0.4ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`status` = 1 AND `users`.`id` = 34 LIMIT 1
D, [2025-02-18T15:30:44.132352 #230567] DEBUG -- : [39869682-0091-448d-91a6-51fcffcd0913]   AnonymousUser Load (0.3ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
I, [2025-02-18T15:30:44.133249 #230567]  INFO -- : [39869682-0091-448d-91a6-51fcffcd0913] Redirected to https://XXXXXXXXXXXXXX/support/login?back_url=https%3A%2F%2FXXXXXXXXXXXXXX%2Fsupport%2Fmy%2Faccount
I, [2025-02-18T15:30:44.133491 #230567]  INFO -- : [39869682-0091-448d-91a6-51fcffcd0913] Filter chain halted as :session_expiration rendered or redirected
I, [2025-02-18T15:30:44.133738 #230567]  INFO -- : [39869682-0091-448d-91a6-51fcffcd0913] Completed 302 Found in 7ms (ActiveRecord: 1.3ms (3 queries, 0 cached) | GC: 0.0ms)
I, [2025-02-18T15:30:44.171536 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85] Started GET "/support/login?back_url=https%3A%2F%2FXXXXXXXXXXXXXX%2Fsupport%2Fmy%2Faccount" for 95.251.190.204 at 2025-02-18 15:30:44 +0000
I, [2025-02-18T15:30:44.172475 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85] Processing by AccountController#login as HTML
I, [2025-02-18T15:30:44.172602 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Parameters: {"back_url"=>"https://XXXXXXXXXXXXXX/support/my/account"}
D, [2025-02-18T15:30:44.174812 #230567] DEBUG -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Setting Maximum (0.4ms)  SELECT MAX(`settings`.`updated_on`) FROM `settings`
D, [2025-02-18T15:30:44.176389 #230567] DEBUG -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   AnonymousUser Load (0.4ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
I, [2025-02-18T15:30:44.176844 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Current user: anonymous
D, [2025-02-18T15:30:44.177714 #230567] DEBUG -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Rendering layout layouts/base.html.erb
D, [2025-02-18T15:30:44.177944 #230567] DEBUG -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Rendering account/login.html.erb within layouts/base
D, [2025-02-18T15:30:44.179941 #230567] DEBUG -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Rendered plugins/redmine_oauth/app/views/hooks/redmine_oauth/_view_account_login_bottom.html.erb (Duration: 0.8ms | GC: 0.0ms)
I, [2025-02-18T15:30:44.180181 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Rendered account/login.html.erb within layouts/base (Duration: 2.1ms | GC: 0.0ms)
I, [2025-02-18T15:30:44.185655 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85]   Rendered layout layouts/base.html.erb (Duration: 7.7ms | GC: 0.0ms)
I, [2025-02-18T15:30:44.186065 #230567]  INFO -- : [2bb70cc5-071e-4b59-9d57-767d41378c85] Completed 200 OK in 13ms (Views: 8.5ms | ActiveRecord: 0.8ms (2 queries, 0 cached) | GC: 0.3ms)
I, [2025-02-18T15:30:44.702542 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [90a5ca6d-3c49-430c-b5b4-88cdbafed329] Performed Mailer::DeliveryJob (Job ID: 90a5ca6d-3c49-430c-b5b4-88cdbafed329) from Async(mailers) in 645.08ms
D, [2025-02-18T15:30:44.705473 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   User Load (0.6ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 19 LIMIT 1
D, [2025-02-18T15:30:44.707475 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   User Load (0.5ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
I, [2025-02-18T15:30:44.708428 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1] Performing Mailer::DeliveryJob (Job ID: b267e5af-98d1-46eb-af90-2f2e41807bc1) from Async(mailers) enqueued at 2025-02-18T15:30:44.058314555Z with arguments: "Mailer", "security_notification", "deliver_now", {:args=>[#<GlobalID:0x0000778ab8675678 @uri=#<URI::GID gid://redmine-app/User/19>>, #<GlobalID:0x0000778ab86750d8 @uri=#<URI::GID gid://redmine-app/User/34>>, {:field=>"field_admin", :value=>"XXXXXXXXXXXXXXXXX", :title=>"label_user_plural", :url=>{:controller=>"users", :action=>"index"}, :message=>"mail_body_security_notification_add", :remote_ip=>nil}]}
D, [2025-02-18T15:30:44.710403 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   AnonymousUser Load (0.5ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
D, [2025-02-18T15:30:44.713417 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   EmailAddress Pluck (0.5ms)  SELECT `email_addresses`.`address` FROM `email_addresses` WHERE `email_addresses`.`user_id` = 19 AND (is_default = '1' OR notify = '1')
D, [2025-02-18T15:30:44.714872 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendering layout layouts/mailer.text.erb
D, [2025-02-18T15:30:44.715208 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendering mailer/security_notification.text.erb within layouts/mailer
D, [2025-02-18T15:30:44.716951 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   UserPreference Load (0.4ms)  SELECT `user_preferences`.* FROM `user_preferences` WHERE `user_preferences`.`user_id` = 19 LIMIT 1
I, [2025-02-18T15:30:44.717677 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendered mailer/security_notification.text.erb within layouts/mailer (Duration: 2.3ms | GC: 0.0ms)
I, [2025-02-18T15:30:44.717949 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendered layout layouts/mailer.text.erb (Duration: 2.8ms | GC: 0.0ms)
D, [2025-02-18T15:30:44.718392 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendering layout layouts/mailer.html.erb
D, [2025-02-18T15:30:44.718564 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendering mailer/security_notification.html.erb within layouts/mailer
I, [2025-02-18T15:30:44.718999 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendered mailer/security_notification.html.erb within layouts/mailer (Duration: 0.3ms | GC: 0.0ms)
I, [2025-02-18T15:30:44.720992 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1]   Rendered layout layouts/mailer.html.erb (Duration: 2.4ms | GC: 0.0ms)
I, [2025-02-18T15:30:45.396747 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [b267e5af-98d1-46eb-af90-2f2e41807bc1] Performed Mailer::DeliveryJob (Job ID: b267e5af-98d1-46eb-af90-2f2e41807bc1) from Async(mailers) in 693.15ms
D, [2025-02-18T15:30:45.400429 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   User Load (0.8ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
D, [2025-02-18T15:30:45.401569 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   CACHE User Load (0.0ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` IN ('User', 'AnonymousUser') AND `users`.`id` = 34 LIMIT 1
I, [2025-02-18T15:30:45.402179 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc] Performing Mailer::DeliveryJob (Job ID: d8e7b242-6a8a-4725-80a8-f01a80d4d1cc) from Async(mailers) enqueued at 2025-02-18T15:30:44.059568071Z with arguments: "Mailer", "security_notification", "deliver_now", {:args=>[#<GlobalID:0x0000778ab851dc30 @uri=#<URI::GID gid://redmine-app/User/34>>, #<GlobalID:0x0000778ab851cfd8 @uri=#<URI::GID gid://redmine-app/User/34>>, {:field=>"field_admin", :value=>"XXXXXXXXXXXXXXXXX", :title=>"label_user_plural", :url=>{:controller=>"users", :action=>"index"}, :message=>"mail_body_security_notification_add", :remote_ip=>nil}]}
D, [2025-02-18T15:30:45.403959 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   AnonymousUser Load (0.6ms)  SELECT `users`.* FROM `users` WHERE `users`.`type` = 'AnonymousUser' AND `users`.`lastname` = 'Anonymous' LIMIT 1
D, [2025-02-18T15:30:45.405844 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   EmailAddress Pluck (0.3ms)  SELECT `email_addresses`.`address` FROM `email_addresses` WHERE `email_addresses`.`user_id` = 34 AND (is_default = '1' OR notify = '1')
D, [2025-02-18T15:30:45.407246 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendering layout layouts/mailer.text.erb
D, [2025-02-18T15:30:45.407464 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendering mailer/security_notification.text.erb within layouts/mailer
D, [2025-02-18T15:30:45.408672 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   UserPreference Load (0.3ms)  SELECT `user_preferences`.* FROM `user_preferences` WHERE `user_preferences`.`user_id` = 34 LIMIT 1
D, [2025-02-18T15:30:45.416936 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   TRANSACTION (0.1ms)  BEGIN
D, [2025-02-18T15:30:45.417842 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   UserPreference Create (1.0ms)  INSERT INTO `user_preferences` (`user_id`, `others`, `time_zone`) VALUES (34, '---\n:no_self_notified: \'1\'\n:auto_watch_on:\n- issue_created\n- issue_contributed_to\n:my_page_layout:\n  left:\n  - issuesassignedtome\n  right:\n  - issuesreportedbyme\n:my_page_settings: {}\n', '')
D, [2025-02-18T15:30:45.432723 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   TRANSACTION (13.5ms)  COMMIT
I, [2025-02-18T15:30:45.433111 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendered mailer/security_notification.text.erb within layouts/mailer (Duration: 25.5ms | GC: 0.0ms)
I, [2025-02-18T15:30:45.433235 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendered layout layouts/mailer.text.erb (Duration: 25.8ms | GC: 0.0ms)
D, [2025-02-18T15:30:45.433564 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendering layout layouts/mailer.html.erb
D, [2025-02-18T15:30:45.433821 #230567] DEBUG -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendering mailer/security_notification.html.erb within layouts/mailer
I, [2025-02-18T15:30:45.434425 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendered mailer/security_notification.html.erb within layouts/mailer (Duration: 0.4ms | GC: 0.0ms)
I, [2025-02-18T15:30:45.437111 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc]   Rendered layout layouts/mailer.html.erb (Duration: 3.5ms | GC: 0.3ms)
I, [2025-02-18T15:30:46.390169 #230567]  INFO -- : [ActiveJob] [Mailer::DeliveryJob] [d8e7b242-6a8a-4725-80a8-f01a80d4d1cc] Performed Mailer::DeliveryJob (Job ID: d8e7b242-6a8a-4725-80a8-f01a80d4d1cc) from Async(mailers) in 991.93ms

The text was updated successfully, but these errors were encountered:

picman · 2025-02-19T09:32:34Z

I've the following settings:

Redmine

Self-registration: automatic account activation

OAuth plugin

Self-registration: automatic account activation

After a login a new account is successfully created and activated and I am redirected to my/account page.

Do you use the latest release of the plugin? Can't be there another reason why the session expires?

efabris · 2025-02-19T09:44:43Z

We are using the 3.0.2 with the following configuration:

The only non-standard aspect is that we expose Redmine under a non-standard path (/support). Could this be a problem?

picman · 2025-02-19T09:47:31Z

In Redmine's settings you have also set automatic account activation? How about sessions options?

efabris · 2025-02-19T10:00:12Z

Thank you for your prompt response. Here are the authentication options:

The problem occurs with both automatic account activation and disabled settings for self-registration.

picman · 2025-02-19T10:03:21Z

Hm, I've no idea what could be the cause. Any other plugins installed?

efabris · 2025-02-19T11:12:31Z

No, any other plugin installed. How the session is created after successful user creation? It could be a missing attribute in the user after creation? The strange fact is that the user is created correctly and the next login work just fine.

picman · 2025-02-19T15:30:35Z

Can't it be related to this problem?

https://www.redmine.org/issues/42199

efabris · 2025-02-19T16:30:38Z

The log is different, we got an error about session expired. We put some log inside the check of the session and simply it's not presents in the db. The session id is created but never inserted in the DB. We are still investiganting.

efabris changed the title ~~Self-registration automtic account activation result in session expired~~ Self-registration automatic account activation result in session expired Feb 18, 2025

picman added the bug Something isn't working label Feb 19, 2025

picman self-assigned this Feb 19, 2025

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Self-registration automatic account activation result in session expired #70

Self-registration automatic account activation result in session expired #70

efabris commented Feb 18, 2025 •

edited

Loading

picman commented Feb 19, 2025

efabris commented Feb 19, 2025

picman commented Feb 19, 2025

efabris commented Feb 19, 2025

picman commented Feb 19, 2025

efabris commented Feb 19, 2025

picman commented Feb 19, 2025

efabris commented Feb 19, 2025 •

edited

Loading

Self-registration automatic account activation result in session expired #70

Self-registration automatic account activation result in session expired #70

Comments

efabris commented Feb 18, 2025 • edited Loading

picman commented Feb 19, 2025

efabris commented Feb 19, 2025

picman commented Feb 19, 2025

efabris commented Feb 19, 2025

picman commented Feb 19, 2025

efabris commented Feb 19, 2025

picman commented Feb 19, 2025

efabris commented Feb 19, 2025 • edited Loading

efabris commented Feb 18, 2025 •

edited

Loading

efabris commented Feb 19, 2025 •

edited

Loading