redmine_helpdesk icon indicating copy to clipboard operation
redmine_helpdesk copied to clipboard
verified publisher icon jfqd

Replies are not processed

Open dvmer opened this issue 2 years ago • 4 comments

Hi, the problem occurs only when a reply is to be processed. The mail in the inbox is marked as read but stays there. New tickets, on the other hand, are processed without any problems.

I use this command as a trigger: sudo /opt/bitnami/ruby/bin/rake -f /opt/bitnami/redmine/Rakefile --silent redmine:email:receive_imap RAILS_ENV="production" host=xxx port=993 username=xxx password=xxx ssl=true project=ticket folder=INBOX move_on_success=success move_on_failure=failed no_permission_check=1 unknown_user=accept allow_override=all no_account_notice=1 --trace

The output:

** Invoke redmine:email:receive_imap (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute redmine:email:receive_imap
rake aborted!
SystemStackError: stack level too deep
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/collectors/substitute_binds.rb:14:in `<<'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:704:in `visit_Arel_Nodes_SqlLiteral'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/visitor.rb:30:in `visit'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:320:in `visit_Arel_Nodes_Grouping'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/visitor.rb:30:in `visit'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:779:in `block in inject_join'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:777:in `each'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:777:in `each_with_index'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:777:in `inject_join'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:177:in `collect_nodes_for'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:157:in `visit_Arel_Nodes_SelectCore'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/mysql.rb:30:in `visit_Arel_Nodes_SelectCore'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:124:in `block in visit_Arel_Nodes_SelectStatement'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:123:in `each'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:123:in `inject'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:123:in `visit_Arel_Nodes_SelectStatement'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/mysql.rb:25:in `visit_Arel_Nodes_SelectStatement'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/visitor.rb:30:in `visit'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/visitor.rb:11:in `accept'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/arel/visitors/to_sql.rb:18:in `compile'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/database_statements.rb:37:in `to_sql_and_binds'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/database_statements.rb:64:in `select_all'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/abstract/query_cache.rb:103:in `select_all'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/connection_adapters/mysql/database_statements.rb:12:in `select_all'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/querying.rb:47:in `find_by_sql'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation.rb:843:in `block in exec_queries'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation.rb:861:in `skip_query_cache_if_necessary'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation.rb:828:in `exec_queries'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation.rb:631:in `load'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation.rb:249:in `records'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation.rb:244:in `to_ary'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation/finder_methods.rb:553:in `find_nth_with_limit'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation/finder_methods.rb:538:in `find_nth'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activerecord-6.1.7.6/lib/active_record/relation/finder_methods.rb:122:in `first'
/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:122:in `custom_field_value'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:98:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'

### hundreds of "...mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'"

/bitnami/redmine/plugins/redmine_helpdesk/lib/redmine_helpdesk/mail_handler_patch.rb:108:in `receive_issue_reply_with_helpdesk'
/opt/bitnami/redmine/app/models/mail_handler.rb:157:in `dispatch'
/opt/bitnami/redmine/app/models/mail_handler.rb:141:in `receive'
/opt/bitnami/redmine/app/models/mail_handler.rb:51:in `block in receive'
/opt/bitnami/redmine/vendor/bundle/ruby/3.0.0/gems/activesupport-6.1.7.6/lib/active_support/notifications.rb:205:in `instrument'
/opt/bitnami/redmine/app/models/mail_handler.rb:48:in `receive'
/opt/bitnami/redmine/app/models/mail_handler.rb:57:in `safe_receive'
/opt/bitnami/redmine/lib/redmine/imap.rb:41:in `block in check'
/opt/bitnami/redmine/lib/redmine/imap.rb:38:in `each'
/opt/bitnami/redmine/lib/redmine/imap.rb:38:in `check'
/opt/bitnami/redmine/lib/tasks/email.rake:121:in `block (4 levels) in <top (required)>'
/opt/bitnami/redmine/app/models/mailer.rb:648:in `with_synched_deliveries'
/opt/bitnami/redmine/lib/tasks/email.rake:120:in `block (3 levels) in <top (required)>'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `block in execute'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `each'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:281:in `execute'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `synchronize'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:199:in `invoke_with_call_chain'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/task.rb:188:in `invoke'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:160:in `invoke_task'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block (2 levels) in top_level'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `each'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:116:in `block in top_level'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:125:in `run_with_threads'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:110:in `top_level'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:83:in `block in run'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:186:in `standard_exception_handling'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/lib/rake/application.rb:80:in `run'
/opt/bitnami/ruby/lib/ruby/gems/3.0.0/gems/rake-13.0.6/exe/rake:27:in `<top (required)>'
/opt/bitnami/ruby/bin/rake:25:in `load'
/opt/bitnami/ruby/bin/rake:25:in `<main>'
Tasks: TOP => redmine:email:receive_imap

Environment:
  Redmine version                5.0.6.stable
  Ruby version                   3.0.6-p216 (2023-03-30) [x86_64-linux]
  Rails version                  6.1.7.6
  Environment                    production
  Database adapter               Mysql2
  Mailer queue                   ActiveJob::QueueAdapters::AsyncAdapter
  Mailer delivery                smtp
Redmine settings:
  Redmine theme                  Classic
SCM:
  Git                            2.30.2
  Filesystem                     
Redmine plugins:
  redmine_checklists             3.1.22
  redmine_helpdesk               0.0.20
  redmine_issue_dynamic_edit     0.9.1
  redmine_questions              1.0.4
  redmine_theme_changer          0.6.0
  redmine_wysiwyg_editor         0.32.0
  redmine_x_lightbox2            1.0.0
  redmine_zenedit                2.0.5
  redmineup_tags                 2.0.13

Edit: production.log with debugging enabled

W, [2023-11-08T16:23:00.372356 #8474]  WARN -- : Creating scope :system. Overwriting existing method Enumeration.system.
W, [2023-11-08T16:23:00.469269 #8474]  WARN -- : Creating scope :sorted. Overwriting existing method User.sorted.
D, [2023-11-08T16:23:01.411286 #8474] DEBUG -- : Receiving message 229
D, [2023-11-08T16:23:01.773878 #8474] DEBUG -- :   [1m[36mSetting Load (0.6ms)[0m  [1m[34mSELECT `settings`.* FROM `settings` WHERE `settings`.`name` = 'mail_from' ORDER BY `settings`.`id` DESC LIMIT 1[0m
D, [2023-11-08T16:23:01.807918 #8474] DEBUG -- :   [1m[36mUser Load (0.7ms)[0m  [1m[34mSELECT DISTINCT `users`.* FROM `users` INNER JOIN `email_addresses` ON `email_addresses`.`user_id` = `users`.`id` WHERE `users`.`type` = 'User' AND (LOWER(email_addresses.address) IN ('[email protected]')) ORDER BY `users`.`id` ASC LIMIT 1[0m
D, [2023-11-08T16:23:01.877033 #8474] DEBUG -- :   [1m[36mIssue Load (0.3ms)[0m  [1m[34mSELECT `issues`.* FROM `issues` WHERE `issues`.`id` = 741 LIMIT 1[0m
D, [2023-11-08T16:23:01.923246 #8474] DEBUG -- :   [1m[36mProject Load (0.2ms)[0m  [1m[34mSELECT `projects`.* FROM `projects` WHERE `projects`.`id` = 6 LIMIT 1[0m
D, [2023-11-08T16:23:01.949505 #8474] DEBUG -- :   [1m[36mCustomField Load (0.3ms)[0m  [1m[34mSELECT `custom_fields`.* FROM `custom_fields` WHERE `custom_fields`.`name` = 'reopen-issues-with' LIMIT 1[0m
D, [2023-11-08T16:23:02.009114 #8474] DEBUG -- :   [1m[36mCustomValue Load (2.8ms)[0m  [1m[34mSELECT `custom_values`.* FROM `custom_values` WHERE (customized_id = 6 AND custom_field_id = 26) ORDER BY `custom_values`.`id` ASC LIMIT 1[0m
D, [2023-11-08T16:23:02.023232 #8474] DEBUG -- :   [1m[36mIssueStatus Load (0.3ms)[0m  [1m[34mSELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` = 4 LIMIT 1[0m
D, [2023-11-08T16:23:02.030425 #8474] DEBUG -- :   [1m[36mIssue Load (0.2ms)[0m  [1m[34mSELECT `issues`.* FROM `issues` WHERE `issues`.`id` = 741 LIMIT 1[0m
D, [2023-11-08T16:23:02.031603 #8474] DEBUG -- :   [1m[36mProject Load (0.2ms)[0m  [1m[34mSELECT `projects`.* FROM `projects` WHERE `projects`.`id` = 6 LIMIT 1[0m
D, [2023-11-08T16:23:02.032336 #8474] DEBUG -- :   [1m[36mCustomField Load (0.2ms)[0m  [1m[34mSELECT `custom_fields`.* FROM `custom_fields` WHERE `custom_fields`.`name` = 'reopen-issues-with' LIMIT 1[0m
D, [2023-11-08T16:23:02.033487 #8474] DEBUG -- :   [1m[36mCustomValue Load (0.3ms)[0m  [1m[34mSELECT `custom_values`.* FROM `custom_values` WHERE (customized_id = 6 AND custom_field_id = 26) ORDER BY `custom_values`.`id` ASC LIMIT 1[0m
D, [2023-11-08T16:23:02.034504 #8474] DEBUG -- :   [1m[36mIssueStatus Load (0.2ms)[0m  [1m[34mSELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` = 4 LIMIT 1[0m
D, [2023-11-08T16:23:02.035185 #8474] DEBUG -- :   [1m[36mIssue Load (0.2ms)[0m  [1m[34mSELECT `issues`.* FROM `issues` WHERE `issues`.`id` = 741 LIMIT 1[0m
D, [2023-11-08T16:23:02.036278 #8474] DEBUG -- :   [1m[36mProject Load (0.2ms)[0m  [1m[34mSELECT `projects`.* FROM `projects` WHERE `projects`.`id` = 6 LIMIT 1[0m
D, [2023-11-08T16:23:02.036958 #8474] DEBUG -- :   [1m[36mCustomField Load (0.2ms)[0m  [1m[34mSELECT `custom_fields`.* FROM `custom_fields` WHERE `custom_fields`.`name` = 'reopen-issues-with' LIMIT 1[0m
D, [2023-11-08T16:23:02.037957 #8474] DEBUG -- :   [1m[36mCustomValue Load (0.2ms)[0m  [1m[34mSELECT `custom_values`.* FROM `custom_values` WHERE (customized_id = 6 AND custom_field_id = 26) ORDER BY `custom_values`.`id` ASC LIMIT 1[0m
D, [2023-11-08T16:23:02.038966 #8474] DEBUG -- :   [1m[36mIssueStatus Load (0.2ms)[0m  [1m[34mSELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` = 4 LIMIT 1[0m
D, [2023-11-08T16:23:02.039617 #8474] DEBUG -- :   [1m[36mIssue Load (0.2ms)[0m  [1m[34mSELECT `issues`.* FROM `issues` WHERE `issues`.`id` = 741 LIMIT 1[0m
D, [2023-11-08T16:23:02.040688 #8474] DEBUG -- :   [1m[36mProject Load (0.2ms)[0m  [1m[34mSELECT `projects`.* FROM `projects` WHERE `projects`.`id` = 6 LIMIT 1[0m
D, [2023-11-08T16:23:02.041421 #8474] DEBUG -- :   [1m[36mCustomField Load (0.2ms)[0m  [1m[34mSELECT `custom_fields`.* FROM `custom_fields` WHERE `custom_fields`.`name` = 'reopen-issues-with' LIMIT 1[0m
D, [2023-11-08T16:23:02.042427 #8474] DEBUG -- :   [1m[36mCustomValue Load (0.2ms)[0m  [1m[34mSELECT `custom_values`.* FROM `custom_values` WHERE (customized_id = 6 AND custom_field_id = 26) ORDER BY `custom_values`.`id` ASC LIMIT 1[0m
D, [2023-11-08T16:23:02.043429 #8474] DEBUG -- :   [1m[36mIssueStatus Load (0.2ms)[0m  [1m[34mSELECT `issue_statuses`.* FROM `issue_statuses` WHERE `issue_statuses`.`id` = 4 LIMIT 1[0m
...

dvmer avatar Oct 25 '23 09:10 dvmer

We are experiencing the same issue in our environment with Redmine 5.1.1. It worked fine in previous versions (4.x.x). Have you found any workaround?

Daugava avatar Jan 31 '25 10:01 Daugava

Yes we migrated to the RedmineUP Helpdesk Plugin.

dvmer avatar Jan 31 '25 12:01 dvmer

I discovered that in my case, the issue was caused by Redmine plugins being loaded twice due to a symlink to the plugin directory in the Bitnami stack. Replacing the symlink with a regular directory resolved the problem.

Daugava avatar Feb 02 '25 00:02 Daugava

Replacing the symlink with a regular directory resolved the problem.

confirmed. Some help from ChatGPT identified a module that is loaded more than once due to the plugins folder symlink. The code in mail_handler_patch.rb can be modified to protect against this.

Modified code attached - protects against multiple loading when the patch is loaded from bitnami symlinked plugins folder. This only fixes the processing of replies.

mail_handler_patch.zip

brooks-eco avatar Nov 22 '25 15:11 brooks-eco