重複ヘッダーが存在する場合、メール通知が失敗します

[wusel (Kai 'wusel' Siering)]

See Email notifications fail if duplicate headers exist - #14 by simonk for bug description
Above added by @pfaffman

Original text follows

Hello,

I’m running a rather small Discourse installation for some years now. It’s fairly low traffic, hence it took a while to notice that sending of emails (notifications, digests) obvoiusly began to fail some months ago. Forensics point to the upgrade to 2.8.0.beta7 around 2022-10-22, previously we were at 2.8.0.beta4. At least I haven’t received any email from that installation about posts or messages.

The emails pile up in Sidekiq, with a message I can’t relate to, nor find anything fitting when searching for it — there where reports of undefined method messages, but none of the conditions match mine. (It’s not TLS, it’s no timeout to the mail server, it’s not the events plugin, and the secure media fix should be in already — besides, the exact error messages were different.)

Error in Sidekiq:

Wrapped NoMethodError: undefined method `value' for #<Array:0x00007f7fd5277d68> Did you mean? values_at

The part after #<Array: is different for each held email. I reinstalled Discourse to a new VM last night and restored from a fresh backup — but seemingly the email issue was restored with the data

As the error rate started to climb end of October, I’m rather sure this was introduced by 2.8.0.beta7:

Any help, or hint to debug the issue further, is much appreciated.
バグの説明については、Email notifications fail if duplicate headers exist - #14 by simonk を参照してください。
上記は @pfaffman によって追加されました。

元のテキストは以下の通りです。

こんにちは。

数年前から、かなり小規模なDiscourseのインストールを実行しています。トラフィックはかなり少ないため、数ヶ月前からメール（通知、ダイジェスト）の送信が明らかに失敗し始めていることに気づくのに時間がかかりました。フォレンジック調査によると、2022年10月22日頃に2.8.0.beta7にアップグレードしたことが原因のようです。以前は2.8.0.beta4を使用していました。少なくとも、そのインストールから投稿やメッセージに関するメールは受信していません。

メールはSidekiqに溜まっていますが、関連付けられないメッセージが表示されており、検索しても該当するものが見つかりません。undefined methodメッセージの報告はありましたが、私の状況に一致するものはありませんでした。（TLSではありませんし、メールサーバーへのタイムアウトでもありませんし、イベントプラグインでもありませんし、セキュアメディアの修正は既に入っているはずです。それに、正確なエラーメッセージは異なっていました。）

Sidekiqのエラー：

Wrapped NoMethodError: undefined method `value' for #<Array:0x00007f7fd5277d68> Did you mean? values_at

#<Array: の後の部分は、保持されている各メールで異なります。昨夜、Discourseを新しいVMに再インストールし、最新のバックアップから復元しましたが、どうやらメールの問題もデータと一緒に復元されたようです

10月末にエラー率が上昇し始めたため、これは2.8.0.beta7で導入されたと確信しています。

どのようなヘルプや、問題をさらにデバッグするためのヒントでも、大歓迎です。

[pfaffman (Jay Pfaffman)]

プラグインはインストールされていますか？ 標準以外のプラグインがインストールされている場合は、削除してください。

[wusel (Kai 'wusel' Siering)]

すでに試しましたが、問題は解決しません

## プラグインはここに追加します
## 詳細については、https://meta.discourse.org/t/19157 を参照してください
hooks:
  after_code:
    - exec:
        cd: $home/plugins
        cmd:
          - git clone https://github.com/discourse/docker_manager.git

## ビルド後に実行するカスタムコマンド

編集：参考情報：

意図したプラグイン：

root@discourse:/var/discourse# grep -B5 "git clone" containers/app.yml-with-plugins
hooks:
  after_code:
    - exec:
        cd: $home/plugins
        cmd:
          - git clone https://github.com/discourse/docker_manager.git
          - git clone https://github.com/discourse/discourse-spoiler-alert.git
          - git clone https://github.com/discourse/discourse-prometheus.git
          - git clone https://github.com/discourse/discourse-solved.git
          - git clone https://github.com/discourse/discourse-chat-integration.git
          - git clone https://github.com/discourse/discourse-voting.git
          - git clone https://github.com/discourse/discourse-checklist.git
          - git clone https://github.com/discourse/discourse-whos-online.git
          - git clone https://github.com/discourse/discourse-calendar.git
          - git clone https://github.com/discourse/discourse-affiliate.git
          - git clone https://github.com/discourse/discourse-reactions.git
          - git clone https://github.com/discourse/discourse-surveys.git

古いインストールには以下が含まれています：

root@discourse-old:/var/discourse# grep -B5 "git clone" containers/app.yml
hooks:
  after_code:
    - exec:
        cd: $home/plugins
        cmd:
          - git clone https://github.com/discourse/docker_manager.git
          - git clone https://github.com/discourse/discourse-spoiler-alert.git
          - git clone https://github.com/discourse/discourse-prometheus.git
          - git clone https://github.com/discourse/discourse-solved.git
          - git clone https://github.com/discourse/discourse-chat-integration.git
          - git clone https://github.com/discourse/discourse-voting.git
          - git clone https://github.com/discourse/discourse-checklist.git
          - git clone https://github.com/davidtaylorhq/discourse-whos-online.git

[pfaffman (Jay Pfaffman)]

これは標準的なインストールですか？ データコンテナが別にある場合、再構築されましたか？ Postgresは最新ですか？ （ただし、コードでまだチェックがあると思いますが）

[wusel (Kai 'wusel' Siering)]

はい、標準のインストールです。私の知る限り、実行されているコンテナは1つだけです。（新しいVMを起動し、DNSを再設定し、apt update、apt dist-upgrade、再起動、git pull、./discourse-setup、Webベースのセットアップ、バックアップのアップロード、バックアップの復元、メールの再有効化を行い、エラーが再度発生するか確認します。）古いインストールではバックアップへのリンクをメールで送信できましたが、新しいインストールでもテストメールの送信は機能していますが、メール送信関連の問題は投稿関連のメールのみで発生しているようです。

[wusel (Kai 'wusel' Siering)]

より正確に言うと、これは最小限の Debian 10 インストールで、その上に Discourse をインストールしました。

root@discourse:~# history
    1  apt update
    2  apt dist-upgrade
    3  reboot ; exit
    4  git clone https://github.com/discourse/discourse_docker.git /var/discourse
    5  apt install git rsync
    6  git clone https://github.com/discourse/discourse_docker.git /var/discourse
    7  cd /var/discourse
       [attach /dev/vdb, fdisk, mkfs.ext4, mount as /var/lib/docker]
   18  apt-get install git apt-transport-https ca-certificates curl gnupg2 software-properties-common -y
   19  df -h
   20  curl -fsSL https://download.docker.com/linux/$(. /etc/os-release; echo \"$ID\")/gpg | apt-key add -
   21  add-apt-repository \"deb [arch=amd64] https://download.docker.com/linux/$(. /etc/os-release; echo \"$ID\") $(lsb_release -cs) stable\"
   22  apt-get update -y
   23  apt-get install docker-ce -y
   24  ./discourse-setup

そしてコンテナが1つあります。

root@discourse:~# docker ps
CONTAINER ID   IMAGE                 COMMAND        CREATED        STATUS        PORTS                                                                      NAMES
ac408a70305d   local_discourse/app   \"/sbin/boot\"   12 hours ago   Up 12 hours   0.0.0.0:80-\u003e80/tcp, :::80-\u003e80/tcp, 0.0.0.0:443-\u003e443/tcp, :::443-\u003e443/tcp   app

編集:

@pfaffman

postgres は最新の状態ですか？

root@discourse:~# apt update
Hit:1 https://download.docker.com/linux/debian buster InRelease
Hit:2 http://deb.debian.org/debian buster InRelease
Get:3 http://deb.debian.org/debian buster-updates InRelease [51,9 kB]
Get:4 http://security.debian.org/debian-security buster/updates InRelease [65,4 kB]
Fetched 117 kB in 2s (60,5 kB/s)    
Reading package lists... Done
Building dependency tree       
Reading state information... Done
All packages are up to date.

最初の復元は失敗しました。database_restorer.rb が restore_dump で、post_id 3841 の重複リンクが原因で失敗しました。2017 年の投稿のリンクを、古いインストールのスクリーンショットに置き換えてから、再度バックアップを作成しました。その後、新しいインストールにバックアップを復元することができました。postgres について言及されたように、これは CREATE INDEX の際に ERROR: could not create unique index \"unique_post_links\" というエラーで発生しました。詳細: EXCEPTION: psql failed: DETAIL: Key (topic_id, post_id, url)=(1300, 3841, [redacted]) is duplicated。

これに直接関係があるとは思いませんが、念のため報告しておきます。

[wusel (Kai 'wusel' Siering)]

もし誰もこれを修正する簡単な方法を知らなければ、きちんとデバッグしましょう。しかし、Discourseは私が慣れていない多くの技術を使用するかなり複雑なアプリケーションなので、あなたの助けが必要です。それで、メールはどのようにSidekiqに「送信」されるのでしょうか？

Sidekiqのエラー：

Wrapped NoMethodError: undefined method `value' for #<Array:0x00007f7fd5277d68> Did you mean? values_at

DiscourseのどのコンポーネントがSitekiqに「value」メソッドを提供しているのでしょうか？

アップグレード後にメール通知が機能しなくなると、Discourseは残念ながらほとんど役に立たなくなります。即時の注意の代わりに、トピックが注意を引くのに数日かかるようになります。人々は2022年にアクティブなポーリングを行わないためです。通知がない ⇒ 何も起こらなかった ⇒ サイトを確認する必要はない

[pfaffman (Jay Pfaffman)]

@wusel

EXCEPTION: psql failed: DETAIL: Key (topic_id, post_id, url)=(1300, 3841, [redacted]) is duplicated .

これはインデックスの破損のように見えます。Postgres 13でこれを見たのは初めてだと思います。古いサイトでそれらを修正し、バックアップして新しいサイトに復元することでアップグレードしたということでしょうか？

通知を送信しているコード内の何かが原因のようですが、それはSidekiqの問題のようです。

[wusel (Kai 'wusel' Siering)]

@pfaffman

これは破損したインデックスのようですね。Postgres 13でこれを見たことはありません。古いサイトで修正し、バックアップと復元を行って新しいサイトに移行したということでしょうか？

前述の通り、古いサイトは稼働しています。バックアップを取得し、それを新規インストールに適用しましたが、復元に失敗しました。復元が新規インストールで機能するまで、問題のある投稿を修正しました。しかし、Sitekiqの問題が再び発生しました。

古いサイトもPostgres 13を実行しています（ただし、数年前から稼働しているため、このバージョンから始まったわけではない可能性が高いです:slightly_smiling_face:）

root@discourse-old:/var/discourse# ./launcher enter app
x86_64 arch detected.
root@discourse-app:/var/www/discourse# psql --version
psql (PostgreSQL) 13.5 (Debian 13.5-1.pgdg110+1)

したがって、この投稿の最後のコメントによると、Discourseのデータベースは破損する可能性があり、そして修正されるとのことです。

新しいユーザーで試したところ、登録メールは正常に送信されました。しかし、投稿への返信通知は送信されず、Sidekiqでエラーが発生します。

これは、Discourseが通知を送信するように指示する際に、Sidekiqに誤った情報を提供している（登録メールとは対照的に）ことを意味すると考えられます。さらにデバッグするにはどうすればよいでしょうか？

[pfaffman (Jay Pfaffman)]

@wusel

> Wrapped NoMethodError: undefined method `value' for #<Array:0x00007f7fd5277d68> Did you mean? values_at
> ```

OK、インデックスが修正されたのであれば、これは value を持つモデルではなく配列で何かが呼び出されていることを示唆しています。問題は Sidekiq 自体ではなく、Sidekiq が呼び出す原因となっている関数にあります。

したがって、単一のアイテムではなく配列を返すものが呼び出されているようですが、それが何であるかは推測できません。/var/discourse/shared/standalone/logs/rails/production.log（私の指や記憶が不確かであれば、それに非常に似たもの）を確認する必要があると思います。そこでそのエラーをログで検索するか（または再度発生させてファイルの末尾に表示させる）、何が失敗しているかについての詳細情報を取得できます。

[wusel (Kai 'wusel' Siering)]

ありがとうございます。しかし、あまり情報がありません。

Started POST "/sidekiq/retries" for 185.39.142.187 at 2022-04-11 16:31:35 +0000
start
Started GET "/sidekiq/retries" for 185.39.142.187 at 2022-04-11 16:31:35 +0000
  Rendered email/notification.html.erb (Duration: 42.8ms | Allocations: 4323)
  Rendered layouts/email_template.html.erb (Duration: 0.3ms | Allocations: 29)
Job exception: undefined method `value' for #<Array:0x00007ff393af6c78>
Did you mean?  values_at

fail

shared/standalone/log/rails/production_errors.log は空です。

[simonk (Simon King)]

エラーは管理者 → ログ → エラーログに表示されますか？もしそうであれば、役立つ可能性のある完全なスタックトレースを取得できます。

[wusel (Kai 'wusel' Siering)]

ああ、いいですね — はい、そうです。

ですから、もし私がこれを正しく理解しているなら、

 433    def header_value(name)
 434      header = @message.header[name]
 435      return nil unless header
*436      header.value
 437    end

は、Discource のコードで Sidekiq が処理を中断する場所ということでしょうか？

これは…から呼び出されます。

 228      MessageBuilder.custom_headers(SiteSetting.email_custom_headers).each do |key, _|
*229        value = header_value(key)
 230
 231        # Remove Auto-Submitted header for group private message emails, it does
 232        # not make sense there and may hurt deliverability.

ですから、カスタムヘッダーである可能性があるということですね？

実際、そこにはエントリがあります。

これをデフォルトにリセットしたところ…実際、読者によって確認されたように、メール通知が再び送信されているようです。

ありがとうございます！

ただし、疑問が一つ残っています。「Auto-Submitted: auto-generated|Precedence: bulk」がこの失敗を引き起こすのはなぜでしょうか？カスタムヘッダーは「|」で区切られると記載されています。

[simonk (Simon King)]

(免責事項: Rubyプログラマーではありません)

Discourseが使用しているメールライブラリの非常に厄介な動作だと思います。以下はheader_value関数です。

lib/email/sender.rb

私の理解では、@message.header[name]はこのメソッドを呼び出しています。

https://www.rubydoc.info/github/mikel/mail/Mail%2FHeader:[]

RFCによると、多くのフィールドは複数回出現する可能性があります。ヘッダーが1つしかない場合は文字列を返し、一致するヘッダーが複数ある場合は、ヘッダーの上から下への順序で値の配列を返します。

Discourseは「Precedence」ヘッダーを自動的に設定するため、email_custom_headers設定を通じて追加しているため、現在2つの「Precedence」ヘッダーがあり、@message.header["Precedence"]は文字列ではなく配列を返しています。

このバグは、email_custom_headersにメッセージオブジェクトに既に存在するヘッダーが含まれている場合にトリガーされると思います。

[pfaffman (Jay Pfaffman)]

これは、私が（配列ではなく単一のアイテムであると提案しましたが、それがどのように真実であるかを想像できませんでした）発生していることのように思われ、バグです。

このトピックのタイトルとカテゴリを変更します。

[martin (Martin Brennan)]

本日、この修正をマージしました。重複ヘッダーを検出した場合、サイト設定のカスタムヘッダーではなく、Discourseコアで定義されているヘッダーを使用します。

FIX: Use our header value instead of custom header on duplicates