Redmineの「メールによるチケット登録」で通知メールが送信されない

前回の投稿と同じく、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         |

バージョンアップ方法：

1. 新しいOSを用意
2. Ruby v3.1をインストール
3. Redmine v5.0のファイルを所定の場所に展開
4. 旧来の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(...)`の中でチケット登録＆通知が同期的に実行される：

```rb
    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`：

```rb
    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ラインタイム全体がシャットダウンし、通知メール送信処理も中断・・・

![image.png](https://qiita-image-store.s3.ap-northeast-1.amazonaws.com/0/50571/c07410ab-6425-e4a6-a785-bd5c591bc382.png)

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

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

:::note info
メール送信のデフォルトの動作が同期→非同期へと変更されたのは Redmine v4である模様。[こちらの公式資料](https://www.redmine.org/projects/redmine/wiki/emailconfiguration)にそれらしいことが記載されている：

> 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.

:::