前回の投稿と同じく、Redmine関連の話題。
今回はトラブルシューティングです。

Background

組織内で利用してきたRedmineがEOSL（実はけっこう前に）。
当該のRedmineにはコアレベル（≠ プラグインやテーマのレベル）でカスタマイズが施されていた。
そのRedmineのバージョンアップを行ったところ、課題発生。

バージョンアップ前後の対照表：

製品	バージョンアップ前	バージョンアップ後
OS	CentOS v7.6	Amazon Linux 2023
Ruby	Ruby v1.9	Ruby v3.1
Redmine	Redmine v2.3	Redmine v5.0

バージョンアップ方法：

新しいOSを用意
Ruby v3.1をインストール
Redmine v5.0のファイルを所定の場所に展開
旧来のRedmine（カスタマイズコード入り）を #3 にマージ

Problem

「メールによるチケット登録」で通知メールが送信されない。
100％ではなく、ごく稀に、何かの拍子に送信されることもある。

通知先は有効なメールアドレスを利用するRedmineユーザーで、個人設定の「メール通知」の条件も問題ない。
チケット起票者は「匿名ユーザー」（非ユーザー）でもそうでなくてもかまわない。

「ごく稀に～」のケースをよくよく確認したところ、送信に成功するケースではメールに添付ファイルがついていた（チケットの添付ファイルとして登録される）。

ログの出力されかた

① [ActiveJob] Enqueued ActionMailer::MailDeliveryJob～ というメッセージとともに、メール送信処理（非同期）のためのタスクがキューにプッシュされる：

I, [2023-11-29T08:50:06.389741 #533491]  INFO -- : [ActiveJob] Enqueued ActionMailer::MailDeliveryJob (Job ID: 970b9670-6b48-4110-998f-814fd09e1744) to Async(mailers) with arguments: "Mailer", "issue_add", "deliver_now", {...}
I, [2023-11-29T08:50:06.390571 #533491]  INFO -- : [ActiveJob] Enqueued ActionMailer::MailDeliveryJob (Job ID: 44e73ea0-2577-4bca-a1d2-333936404f85) to Async(mailers) with arguments: "Mailer", "issue_add", "deliver_now", {...

② メール通知が成功する場合はこれにやや遅れて [ActiveJob]...Performing ActionMailer::MailDeliveryJobというメッセージとともに、メール送信のタスクが実行される：

I, [2023-11-29T08:50:06.483766 #533491]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [970b9670-6b48-4110-998f-814fd09e1744] Performing ActionMailer::MailDeliveryJob (Job ID: 970b9670-6b48-4110-998f-814fd09e1744) from Async(ma
ilers) enqueued at 2023-11-28T23:50:06Z with arguments: ...
I, [2023-11-29T08:50:06.485966 #533491]  INFO -- : [ActiveJob] [ActionMailer::MailDeliveryJob] [14178404-dfe1-451b-8930-9e71dac24bce] Performing ActionMailer::MailDeliveryJob (Job ID: 14178404-dfe1-451b-8930-9e71dac24bce) from Async(ma
ilers) enqueued at 2023-11-28T23:50:06Z with arguments: ...

③ そしてこのとき、上記の2種類のログメッセージの間に、Saving attachment...というメッセージが出力されていることが確認できる：

I, [2023-11-29T08:50:06.408305 #533491]  INFO -- : Saving attachment '/var/lib/redmine/files/yyyy/MM/...' (7231 bytes)

メール送信がされない場合は、①は出力されるが②は出力されない（③はあったりなかったり）。

Solution...までの考察含め

原因は、以下の条件が組み合わさたことでメール送信タスクが中断されてしまうこと：

Redmineバージョンアップによりチケット登録後の通知メール送信がデフォルトで非同期になった（メール送信タスクがキューにプッシュされ、別スレッドで動くワーカーがそのタスクをポップして実行する）。
旧来のRedmineはカスタマイズにより「メールによるチケット登録」のコアである Rakeタスクemail:read をラップする新規タスクを追加しており、email.rakeファイルをマージするときに旧を優先した。

従来はチケット登録→通知メール送信という一連の処理が同期的に実行されていた。
次に示すコードが Redmine v2.3のRakeタスクemail:read。 MailHander.receive(...)の中でチケット登録＆通知が同期的に実行される：

    task :read => :environment do
      options = { :issue => {} }
      %w(project status tracker category priority).each { |a| options[:issue][a.to_sym] = ENV[a] if ENV[a] }
      options[:allow_override] = ENV['allow_override'] if ENV['allow_override']
      options[:unknown_user] = ENV['unknown_user'] if ENV['unknown_user']
      options[:no_permission_check] = ENV['no_permission_check'] if ENV['no_permission_check']
      options[:no_account_notice] = ENV['no_account_notice'] if ENV['no_account_notice']
      options[:default_group] = ENV['default_group'] if ENV['default_group']

      MailHandler.receive(STDIN.read, options)
    end

それがバージョンアップ＆マージの結果、チケット登録の後、デフォルトの状態では非同期で通知メール送信を実行するという流れに変わった。

バージョンアップだけなら問題がなかった。
次に示すコードが Redmine v5.0のRakeタスクemail:read：

    task :read => :environment do
      Mailer.with_synched_deliveries do
        MailHandler.safe_receive(STDIN.read, MailHandler.extract_options_from_env(ENV))
      end
    end

ここでは明示的に同期型のメール送信を行うように Mailer.with_synched_deliveries...が利用されている。つまりデフォルトの非同期な通知ではなく、明示的に同期的な通知をするようにしている。これならば従来のようにチケット登録＆通知は同期的に実行される。

しかしマージ過程でこの部分は旧来のコードを維持する形にしてしまっていた。
これによりバージョンアップ後のデフォルトの挙動である、非同期な通知メール送信が起動することに。

結果として、crondにより起動されたRubyランタイムのmainスレッドでチケット登録を進め、途中通知メール送信のためのタスクをキューに積んでmainから枝分かれした別スレッドで非同期処理を開始・・・しかしmainの処理（登録）が終わるとRubyラインタイム全体がシャットダウンし、通知メール送信処理も中断・・・

対策はシンプル。
マージの不備をあらため、Rakeタスクemail:readの内容を Redmine v5.0本来の姿に戻す：

    task :read => :environment do
      Mailer.with_synched_deliveries do
        MailHandler.safe_receive(STDIN.read, MailHandler.extract_options_from_env(ENV))
      end
    end

メール送信のデフォルトの動作が同期→非同期へと変更されたのは Redmine v4である模様。こちらの公式資料にそれらしいことが記載されている：

Please note: Since Redmine 4.0 asynchronous email sending is removed in favour of Rails ActiveJob module which sends emails asynchronously.See https://www.redmine.org/projects/redmine/repository/entry/tags/4.0.0/lib/redmine/configuration.rb#L53 for more details.