`screened_ip_addresses` の SQL エラー（API が 500 をスロー）

pnoeric · 2020 年 4 月 3 日午後 12:37

こんにちは、皆さん。

API で新しい投稿（既存のトピック内）を作成する際にエラー 500 が発生しています。ログには以下のように表示されています：

ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR:  invalid input syntax for type inet: ""
LINE 1: ..._addresses".* FROM "screened_ip_addresses" WHERE ('' <<= ip_...
                                                             ^
)
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-2.0.1/lib/patches/db/pg.rb:69:in `exec_params'

Failed to handle exception in exception app middleware : PG::InvalidTextRepresentation: ERROR:  invalid input syntax for type inet: ""
LINE 1: ..._addresses".* FROM "screened_ip_addresses" WHERE ('' <<= ip_...
                                                             ^

以下が私の「スクリーニング済み IP リスト」です。下のスクリーンショットに加え、API を呼び出しているマシンの IP もホワイトリストに登録しています（古いフォーラムソフトから旧トピックやメッセージを大量インポートするために、システムレベルの API キーを使用しています）。

試しに、API でスクリーニング済み IP リストを問い合わせたところ、同じ結果になりました（https://mydiscourse.com/admin/logs/screened_ip_addresses.json）。

他に確認すべきことがあるのか分かりません。

ご存知の方、教えてください：

1. このエラーの原因は何でしょうか？
2. 今すぐどう修正し、今後同様の問題を防ぐにはどうすればよいでしょうか？

お手数ですが、よろしくお願いします

ありがとうございました！

pnoeric · 2020 年 4 月 3 日午後 6:56

それとも、別の SQL がそのテーブルへの挿入を試みていることについてでしょうか？

blake · 2020 年 4 月 3 日午後 7:58

API リクエストに使用するコードを、認証情報を削除した状態で投稿していただけますか？そうすれば、どのように API リクエストを行っているか確認できます。

pnoeric · 2020 年 4 月 4 日午前 10:37

@blake さん、返信ありがとうございます。私のコードに問題がなかったことを完全に確認するために、基本的な API 呼び出しを Insomnia（Postman に似ていますが、個人的にはよりシンプルで使いやすいです）で準備しました。残念ながら、結果は同じでしたが、少なくとも今は非常に明確になりました：

新しい投稿を作成するために準備した呼び出し（すでに「投稿内の最小単語数」を 1 に設定しています）：

そして結果

これらのテスト呼び出しからログに表示された 2 つのエラーメッセージ：

エラー 1：

メッセージ（15 件のコピーが報告されました）

ActiveRecord::StatementInvalid (PG::InvalidTextRepresentation: ERROR:  inet タイプの無効な入力構文: ""
LINE 1: ..._addresses".* FROM "screened_ip_addresses" WHERE ('' <<= ip_...
                                                             ^
)
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-2.0.1/lib/patches/db/pg.rb:69:in `exec_params'

バックトレース

rack-mini-profiler-2.0.1/lib/patches/db/pg.rb:69:in `exec_params'
rack-mini-profiler-2.0.1/lib/patches/db/pg.rb:69:in `exec_params'
activerecord-6.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
activesupport-6.0.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
activesupport-6.0.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
activesupport-6.0.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
activerecord-6.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:671:in `block in exec_no_cache'
activerecord-6.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:718:in `block (2 levels) in log'
/usr/local/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
activerecord-6.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:717:in `block in log'

エラー 2：

メッセージ（15 件のコピーが報告されました）

例外アプリミドルウェアで例外の処理に失敗しました：PG::InvalidTextRepresentation: ERROR:  inet タイプの無効な入力構文: ""
LINE 1: ..._addresses".* FROM "screened_ip_addresses" WHERE ('' <<= ip_...
                                                             ^


バックトレース

rack-mini-profiler-2.0.1/lib/patches/db/pg.rb:69:in `exec_params'
rack-mini-profiler-2.0.1/lib/patches/db/pg.rb:69:in `exec_params'
activerecord-6.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:672:in `block (2 levels) in exec_no_cache'
activesupport-6.0.1/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'
activesupport-6.0.1/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'
activesupport-6.0.1/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'
activerecord-6.0.1/lib/active_record/connection_adapters/postgresql_adapter.rb:671:in `block in exec_no_cache'
activerecord-6.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:718:in `block (2 levels) in log'
/usr/local/lib/ruby/2.6.0/monitor.rb:235:in `mon_synchronize'
activerecord-6.0.1/lib/active_record/connection_adapters/abstract_adapter.rb:717:in `block in log'

このユーザーはさっき作成したばかりなので、これが何らかの信頼レベルに関連したバグか、あるいは新規ユーザーには完全には権限が付与されていない他の何かによるものか疑問に思っています。これについて少し実験して、API を通じて投稿が通過できるようにする方法を見つけ出せるか試してみます。

いずれにせよ、何らかのバグを表面化させたようですが…？！

pnoeric · 2020 年 4 月 4 日午後 3:44

さて、このバグを回避した方法をお伝えします。実験を始めたんです：

API 呼び出しのユーザーを ‘system’ に変更したら、それが機能しました。
そこで、「ふーん」と思い、まだ試したことがない別のユーザーに変更してみました。これも機能しました。
その後、ユーザーを元のユーザー名に戻しました。つまり、以前 500 エラーを発生させたのと同じ API 呼び出しを繰り返すことになります。しかし今回は、それが機能しました。

もし再び発生したら、どうすれば確実に再現できるか調べてみます。それまで、Discourse のコードを私よりよく知っている方がいれば（;-)）、その部分を一度見て、明らかなバグが潜んでいないか確認していただけると助かります。

pnoeric · 2020 年 4 月 4 日午後 4:05

うーん、ここで明らかに何か奇妙なことが起きているようです。スクリプトを再度実行すると、トピックが大量に作成され、メッセージが投稿され始めます。そして今度は異なるユーザーで試しても、また 500 エラーが発生します。

そのユーザー名を Insomnia に取り込んで API をテストすると、やはり 500 エラーが出ます。ユーザーを ‘system’ に変更すると正常に通過しますが、元のユーザーに戻すと再び 500 エラーで失敗します！

500 エラーを発生させているユーザー（‘system’ を除く、インポートしたすべてのユーザー）は TL1 です。TL1 が投稿できるよう制限を変更しましたが……

これは明らかにレート制限に関連する問題のように感じられます。nginx やその上流の何かによって 500 エラーが引き起こされているのではないかと疑いましたが、nginx からのすべてのレート制限を無効にしても、エラーログには SQL バグを示す 500 エラーが明確に表示されています。

SQL エラーが IP アドレスを参照するカラム付近で発生していることに気づきました。レート制限の動作に関連して、何か奇妙なことが起きてこの問題を引き起こしている可能性はありませんか？IP を変更するために VPN でログインを試みましたが、それでも 500 エラーが発生します。

その間、問題が rack-mini-profiler にあることがわかりました。これは必須ではありません。これを無効にしてみれば問題が解決するかどうか確認しましょう。……ダメでした。管理者アカウントではもう mini-profiler は表示されなくなりましたが、エラーログには同じエラーが表示され、同じ HTTP 500 エラーが発生したままです

更新：ユーザーを TL3 に変更すると、問題が解消されるようです。TL1 に戻すと再び発生します。この仮説を現在テスト中ですが……ダメです。時々うまくいくこともありますが、ユーザーの TL を手動で編集しても、ユーザーが「フリーズ」したままのようです。

@blake または @staff の誰か……助けてください！他に試すことはありますか？エラーを引き起こしているコードに関連して、何か完全にフラッシュして工場出荷状態にリセットできるものはありますか？

codinghorror · 2020 年 4 月 4 日午後 5:26

スタックトレースから判断すると、ネットワークの問題のように思えます。なぜかユーザーのIPアドレスが表示されないことがあります。あるいは、管理者、ログ、スクリーンされたIPアドレスにデータベースのデータに問題があるのでしょうか？

supermathie · 2020 年 4 月 5 日午前 4:27

同意します - <<= は「LHS が RHS に含まれる」ことを意味するため、悪い/空の IP アドレスがアプリに到達しているようです。

（なぜアプリに IP アドレスが全く利用できないのか気になります。私の推測では、リクエストが転送された IP 情報ヘッダーを持たない Unix ソケット経由で届いているのでしょう）

pnoeric · 2020 年 4 月 5 日午前 10:57

同意しますが、なぜ IP が時折表示され、時折表示されないのかは理解できません。私のインポートスクリプトでは、少なくとも 5〜7 回の正常な API コールの後にこの 500 エラーが発生します。そのため、データベース内のデータが何らかの形で破損していると考えています。

はい、奇妙ですね。しかし同時に、不正なユーザー名で呼び出すと失敗し、「system」や他のユーザー名で呼び出すと成功します。したがって、私のデータベース内の破損データが原因ではないかと考えています。

破損している可能性のあるデータベーステーブルをクリアまたはリセットするための、簡単な Ruby コマンドライン操作をご教示いただけますでしょうか？

blake · 2020 年 4 月 5 日午後 4:54

エラーは、データベースに空の IP アドレスがあるかどうかではなく、スクリーン済み IP アドレステーブルに空白の IP アドレスが含まれているかどうかがチェックされているため、データベース自体に問題があるとは考えにくいです。

ただし興味深いことに、このコードは 500 エラーを発生させる SQL リクエストを実行する前に、ip_address の存在を確認しています。

Discourse インスタンスのセットアップ方法について詳しく教えてください。インポートから作成されたものですか？最新バージョンを使用していますか？RAM はどれくらい搭載されていますか？このガイドに従いましたか？

このサイト設定を確認してください：max new accounts per registration ip。このケースでは関係ないかもしれませんが、問題の原因になっている可能性があります。

バッチスクリプトで処理速度を落とし、リクエスト間に 1 秒の待機時間を設けて、違いが出るか試してみてください。

これらの API 呼び出しの目的は何ですか？ユーザーと投稿をインポートするための一度限りのスクリプトであれば、API 呼び出しを行わずに実際にサーバー上で実行されるインポートスクリプトの方が適しているかもしれません。

多くの質問をして申し訳ありませんが、この問題に遭遇したことがなく、screened_ip_addresses 周辺のコードは長い間更新されていません。コードベースにどこかバグがないとは言い切れませんが、一時的に確認した限りでは現時点で特に問題は見当たりません。

pnoeric · 2020 年 4 月 5 日午後 5:55

はい、完全に Docker 環境で、Digital Ocean 上で動作しています。あの素晴らしいガイドを忠実に従って設定しました。

はい、その設定をデフォルトの 3 から 99999 に変更しました。しかし変化はなく、まだ 500 エラーが発生しています。

試しましたが、変化はありませんでした。なお、Insomnia を使って「1 つの悪いアカウント」に対してリクエストを送っても、まだ 500 エラーが発生します。つまり、その 1 つのアカウントが破損しているようです。そのアカウントで「メッセージ作成」の API 呼び出しを 1 回だけ行っても（前後に他の呼び出しなし）、500 エラーが発生します。もちろん、私のインポートスクリプトでも 500 エラーが発生します;-)

はい、私は経験豊富なプログラマーですが、RoR/Ruby は全く知りません。そのため、皆さんが提供する既成のオプションを利用できません。しかし、それらが既存のフォーラムを手動で巡回してユーザーを作成するなど、API 経由でその場で処理する方法よりも優れていることは理解しています。そのため、マーケットプレイスの投稿を投稿しました。自分ですべてを動かせるようになりたいですが、厳しい納期もあります;-)

完全に理解できますし、この件への対応に感謝しています。

そこで、役立つかもしれない情報を提供します。これは市販のインストール版で、カスタマイズはほとんど行っていないため、かつ私のコードを使わなくてもバグが簡単に再現でき（Insomnia を使うだけ）、さらにフォーラムはまだ公開していないため、Digital Ocean インスタンスの root ログイン情報や API キーなどを渡すことに問題ありません。私としては、あなたが何でもいじって構いません。現在の Discourse フォーラムは空のカテゴリと数件の特別な導入メッセージが設定されているだけで、実質的には空の状態です。実際のユーザーはまだおらず、管理者のみがいます。そのため、テストのためにトピックやメッセージを作成・削除しても問題ありません。

これはあなたが直接バグを確認するための最も迅速な方法です。また、root としてアクセスできるため、この問題の原因を特定するために、Discourse の低レベルの仕組みを自由にいじることができます。

E

blake · 2020 年 4 月 5 日午後 7:18

SSOを無効化するとどうなりますか？

pnoeric · 2020 年 4 月 5 日午後 7:19

違いはありません。引き続き 500 エラーが発生します。

riking · 2020 年 4 月 6 日午前 4:26

別のアイデア：動作したすべてのアカウントが管理者権限を持っている可能性はありませんか？アプリケーションレベルのレート制限の一部は管理者に対して回避されていることを知っています。

一般的には、インポートスクリプトを単純に作成する方がはるかに簡単です。このトピック全体が「たくさん」の具体例です

pnoeric · 2020 年 4 月 6 日午前 8:57

ふむ、何か手がかりがあったはずなのに…私のテストで「汚染」した問題ユーザーの george21 は TL0 でした。なので彼を TL1 に変更すると、今度は動作しました。なるほど！もしかしてそれが原因かもしれません！そこで george21 を再び TL0 に戻しましたが…今度はもう「汚染」されていません。TL0 のままでも API 呼び出しが可能です。

次に、インポートスクリプトを再度実行すると、ああっ、今度は george21 がインポートスクリプトで 500 エラーを発生させます。Insomnia で試しても失敗します。そこで george21 を再び TL1 に戻すと…はい、HTTP 呼び出しが実行できました。

つまり、私が再現できている現象は以下の通りです：

一連の API 呼び出しが行われると（？）、何らかの理由で、その後の API 呼び出しが TL0 ユーザーで失敗する。
TL0 ユーザーを TL1 に変更すると、API 呼び出しが成功する。
奇妙なことに、その後、同じユーザーを再び TL0 に戻しても、API 呼び出しは成功したままになる。
スクリプトを再度実行すると問題ないが、やがて別の TL0 ユーザーで再び失敗する。

注意点：

私の知る限り、TL0 のすべての最低要件などは引き上げられています（つまり、TL0 ユーザーが投稿できないようにするすべてのブロックを除去しようと試みました）。
もしこれが TL0 ユーザー向けの何らかの内部レート制限の問題だとしても、API が 500 エラーをスローしてエラーログに SQL エラーを記録すべきではありません。したがって、現時点でどこかに明らかなバグが存在すると断言できます。

ええ、はい、知っています。すでに私が独自のインポートスクリプトを作成しない理由（提供された例に基づいて）を 4 回も説明しました。そのため、アプローチを変更しました。

その間も、このバグの発見と修正に貢献し続けています。今日は私のインポートスクリプトに影響が出ていますが、明日はあなたのサイトにある重要なスクリプトで API を使用する必要があるかもしれません…

トピック		返信	表示
User can't post: 500 internal server error Support	12	1401	2018 年 4 月 18 日
Error While Trying to load, New and Admin accounts Support	15	3119	2015 年 7 月 20 日
40 Fatals and 7 Errors in recent logs Support	13	1645	2024 年 6 月 8 日
How to block an IP range? "Screened IPs" not being blocked Support	22	373	2025 年 12 月 5 日
"500 Internal Server Error" when approving a post in review Self-hosting	10	1471	2020 年 10 月 31 日

`screened_ip_addresses` の SQL エラー（API が 500 をスロー）

関連トピック