破損したインデックスのため復元できません（破損したインデックスへの対処法に関するヒントあり）

サポート インストール
1

This backup failed several times because of errors like

ERROR:  could not create unique index "index_incoming_referers_on_path_and_incoming_domain_id"
DETAIL:  Key (path, incoming_domain_id)=(/@dataandme, 41) is duplicated.               
ERROR:  current transaction is aborted, commands ignored until end of transaction block

I went and removed all of those records by hand in rails with stuff like
IncomingReferer.where(path: ‘/@dataandme’).destroy_all

Now it’s still failing and I

...
[2019-12-30 20:29:16] 'pfaffman' has started the restore!
[2019-12-30 20:29:16] Marking restore as running...
[2019-12-30 20:29:16] Making sure /var/www/discourse/tmp/restores/default/2019-12-30-202916 exists...
[2019-12-30 20:29:16] Downloading archive to tmp directory...
[2019-12-30 20:29:38] No metadata file to extract.
[2019-12-30 20:29:38] Validating metadata...
[2019-12-30 20:29:38]   Current version: 20191129144706
[2019-12-30 20:29:38]   Restored version: 20191129144706
[2019-12-30 20:29:38] Extracting dump file...
[2019-12-30 20:30:07] Creating missing functions in the discourse_functions schema
[2019-12-30 20:30:08] Cannot restore into different schema, restoring in-place
[2019-12-30 20:30:08] Enabling readonly mode...
[2019-12-30 20:30:08] Pausing sidekiq...
[2019-12-30 20:30:08] Waiting for sidekiq to finish running jobs...
[2019-12-30 20:30:08] Restoring dump file... (can be quite long)

 ----- and so on -----
[2019-12-30 20:33:17] ERROR:  current transaction is aborted, commands ignored until end of transaction block
[2019-12-30 20:33:17] ERROR:  current transaction is aborted, commands ignored until end of transaction block
[2019-12-30 20:33:17] EXCEPTION: psql failed
[2019-12-30 20:33:17] /var/www/discourse/lib/backup_restore/restorer.rb:331:in `restore_dump'
/var/www/discourse/lib/backup_restore/restorer.rb:75:in `run'
/var/www/discourse/lib/backup_restore.rb:166:in `block in start!'
/var/www/discourse/lib/backup_restore.rb:163:in `fork'
/var/www/discourse/lib/backup_restore.rb:163:in `start!'
/var/www/discourse/lib/backup_restore.rb:22:in `restore!'
/var/www/discourse/app/controllers/admin/backups_controller.rb:119:in `restore'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal/basic_implicit_render.rb:6:in `send_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/abstract_controller/base.rb:196:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal/rendering.rb:30:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/abstract_controller/callbacks.rb:42:in `block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-6.0.1/lib/active_support/callbacks.rb:135:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-6.0.1/lib/active_support/notifications.rb:180:in `block in instrument'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-6.0.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-6.0.1/lib/active_support/notifications.rb:180:in `instrument'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activerecord-6.0.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/abstract_controller/base.rb:136:in `process'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionview-6.0.1/lib/action_view/rendering.rb:39:in `process'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-1.1.3/lib/mini_profiler/profiling_methods.rb:104:in `block in profile_method'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal.rb:191:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_controller/metal.rb:252:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/routing/route_set.rb:51:in `dispatch'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/routing/mapper.rb:18:in `block in <class:Constraints>'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/journey/router.rb:32:in `each'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/routing/route_set.rb:837:in `call'
/var/www/discourse/lib/middleware/omniauth_bypass_middleware.rb:68:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/tempfile_reaper.rb:15:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/conditional_get.rb:38:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/head.rb:12:in `call'
/var/www/discourse/lib/content_security_policy/middleware.rb:12:in `call'
/var/www/discourse/lib/middleware/anonymous_cache.rb:318:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:232:in `context'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/session/abstract/id.rb:226:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/cookies.rb:648:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/activesupport-6.0.1/lib/active_support/callbacks.rb:101:in `run_callbacks'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/logster-2.4.2/lib/logster/middleware/reporter.rb:43:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-6.0.1/lib/rails/rack/logger.rb:38:in `call_app'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-6.0.1/lib/rails/rack/logger.rb:28:in `call'
/var/www/discourse/config/initializers/100-quiet_logger.rb:18:in `call'
/var/www/discourse/config/initializers/100-silence_logger.rb:31:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/var/www/discourse/lib/middleware/enforce_hostname.rb:17:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/method_override.rb:22:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/sendfile.rb:111:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/actionpack-6.0.1/lib/action_dispatch/middleware/host_authorization.rb:77:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-mini-profiler-1.1.3/lib/mini_profiler/profiler.rb:296:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/message_bus-2.2.3/lib/message_bus/rack/middleware.rb:57:in `call'
/var/www/discourse/lib/middleware/request_tracker.rb:181:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-6.0.1/lib/rails/engine.rb:526:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-6.0.1/lib/rails/railtie.rb:190:in `public_send'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/railties-6.0.1/lib/rails/railtie.rb:190:in `method_missing'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/urlmap.rb:68:in `block in call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/urlmap.rb:53:in `each'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/rack-2.0.7/lib/rack/urlmap.rb:53:in `call'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:605:in `process_client'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:700:in `worker_loop'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:548:in `spawn_missing_workers'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/lib/unicorn/http_server.rb:144:in `start'
/var/www/discourse/vendor/bundle/ruby/2.6.0/gems/unicorn-5.5.1/bin/unicorn:128:in `<top (required)>'
/var/www/discourse/vendor/bundle/ruby/2.6.0/bin/unicorn:23:in `load'
/var/www/discourse/vendor/bundle/ruby/2.6.0/bin/unicorn:23:in `<main>'
[2019-12-30 20:33:17] Trying to rollback...
[2019-12-30 20:33:17] Rolling back...
[2019-12-30 20:33:17] Cleaning stuff up...
[2019-12-30 20:33:17] Dropping function from the discourse_functions schema
[2019-12-30 20:33:17] Removing tmp '/var/www/discourse/tmp/restores/default/2019-12-30-202916' directory...
[2019-12-30 20:33:17] Unpausing sidekiq...
[2019-12-30 20:33:17] Disabling readonly mode...
[2019-12-30 20:33:17] Marking restore as finished...
[2019-12-30 20:33:17] Notifying 'pfaffman' of the end of the restore...
[2019-12-30 20:33:34] Finished!

Now I don’t see anything that I know how to fix.

I can upgrade the staging site that I’m trying to restore to, but would rather not upgrade the production site without first being able to see that things work on staging. . .

2

psql がその前に他のエラーをログに記録していないか確認しましたか？通常、これは以前の SQL コマンドが失敗した場合に発生します。

また、なぜ元のデータベースに incoming_referers テーブルに重複レコードが存在するのでしょうか？そのテーブルの一意インデックスは 2014 年から存在しています。復元しようとしているデータベースには、この問題以外にも多くの問題があるかもしれませんね。

3

Gerhard、ありがとうございます！ご支援に感謝します。これはますます奇妙になってきています。

incoming_referers に問題があったとしても、私には意味がわかりません。私はこのステージングサイトに対して、最近でも10月に本番環境からのリストアを行いました。

データベースかインデックスに何か問題があるように思えます。プラグインが原因だと疑いましたが、エラーが多様なインデックスに散らばっているため、単一のプラグインが原因であるとは考えにくいです。以前、壊れたインデックスの問題についてプラグイン全体を grep しましたが、何もヒットしませんでした。

あるリストアでは、以下のエラーが出ました：

[2020-01-03 16:25:30] ERROR:  could not create unique index "index_plugin_store_rows_on_plugin_name_and_key"

私は以下を実行しました：

[10] pry(main)> PluginStoreRow.where(plugin_name: 'discourse-data-explorer',key: 'q:-8').destroy_all

そして再度試みました：

[2020-01-03 16:49:16] ERROR:  could not create unique index "index_tags_on_lower_name"
[2020-01-03 16:49:16] DETAIL:  Key (lower(name::text))=(addins) is duplicated.

最新のリストアの完全な先頭部分はこちらです：

[2020-01-03 16:41:34] 'pfaffman' has started the restore!
[2020-01-03 16:41:34] Marking restore as running...
[2020-01-03 16:41:34] Making sure /var/www/discourse/tmp/restores/default/2020-01-03-164133 exists...
[2020-01-03 16:41:34] Downloading archive to tmp directory...
[2020-01-03 16:45:20] No metadata file to extract.
[2020-01-03 16:45:20] Validating metadata...
[2020-01-03 16:45:20]   Current version: 20191220134101
[2020-01-03 16:45:20]   Restored version: 20191129144706
[2020-01-03 16:45:20] Extracting dump file...
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:15] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] CREATE INDEX
[2020-01-03 16:49:16] ERROR:  could not create unique index "index_tags_on_lower_name"
[2020-01-03 16:49:16] DETAIL:  Key (lower(name::text))=(addins) is duplicated.
[2020-01-03 16:49:16] ERROR:  current transaction is aborted, commands ignored until end of transaction block
[2020-01-03 16:49:16] ERROR:  current transaction is aborted, commands ignored until end of transaction block
[2020-01-03 16:49:16] ERROR:  current transaction is aborted, commands ignored until end of transaction block
4

復旧が完了し、すべての一意インデックスが作成できるまで、データのクリーンアップを手動で行う必要があるかと思います。

それとは別に、最近のベースイメージのいずれかに、バグのある PostgreSQL のバージョンを誤って出荷したのではないかと思い始めます。過去 1〜2 ヶ月の間に、破損したインデックスに関する問題が多数報告されています。これは奇妙な偶然に思えますね :thinking:

6

「ジェイがまた何か愚かなことをした」というだけの説明は避けたいですね :wink:

参考までに、この問題が始まる直前に、このサイトのデータコンテナを最近アップグレードしたことを確信しています。

8

created_at の重複レコードの日付を確認し、その時点で使用されていた Postgres のバージョンを特定してみてください。@falco は PG 10.0 と 10.1 で破損したインデックスに関する問題があったと指摘していましたが、それはかなり前の話です（10.2 は 2018 年 2 月 8 日にリリース）。私たちが PG 10 の配布を開始したのは 2018 年 4 月以降（つまり 10.2 リリース後）です。したがって、これは PG の新しいバグか、単に運が悪かったかのどちらかでしょう。:man_shrugging:

9

なるほど。本番環境は10.10、ステージング環境は10.11ですね。

また、ログで重複のため失敗したと報告されたレコードのうち、いくつかは実際には1件しか存在しませんでした。もしかすると、レコード自体は削除されたものの、インデックスからは削除されなかったのかもしれません。これはあり得る話でしょうか？

10

しかし、インデックスはすべての更新時に再作成されるわけではありません。

はい、ディスク上で異なるオブジェクトであるためです。

11

さて、ヒントを一つ。

discourse=> reindex table tags;
ERROR:  could not create unique index "index_tags_on_lower_name"
DETAIL:  Key (lower(name::text))=(addins) is duplicated.

discourse=> select * from tags where name='addins';
 id  |  name  | topic_count |         created_at         |         updated_at         | pm_topic_count 
-----+--------+-------------+----------------------------+----------------------------+----------------
 143 | addins |          16 | 2017-11-13 20:08:51.345607 | 2017-11-13 20:08:51.345607 |              0
(1 row)

discourse=> select * from tags where name like '%dins';
 id  |  name  | topic_count |         created_at         |         updated_at         | pm_topic_count 
-----+--------+-------------+----------------------------+----------------------------+----------------
 143 | addins |          16 | 2017-11-13 20:08:51.345607 | 2017-11-13 20:08:51.345607 |              0
 721 | addins |           3 | 2019-11-19 10:01:32.406178 | 2019-11-19 10:01:32.406178 |              0

この 2 つの違いがわかりませんが、最初の SELECT ではそのうちの 1 つしか見つかりませんでした。

12

EXPLAIN ANALYZE select * from tags where name='addins'; を実行すれば、その理由がわかります。

インデックスのみスキャン（多くの列を選択しているため、これは疑わしいですが）か、インデックスを使用してどの行を選択するかを判断するビットマップヒープスキャンのいずれかだったはずです。インデックスが破損しているため……

13

これは、私が最近破損したインデックスで直面した問題と全く同じです。私はこれらのアカウントを検査し、同じもの（同じメールアドレス）であることが多かったため、一方の名前を変更してからマージしました。これは主に手作業だったため、かなりの作業を要しましたが、今はピカピカの新インデックスが手に入りました :slight_smile:

編集：おっと、私の問題は users テーブルにありました。ただし、重複キーの問題は同じです。

14

このケースでも、‘shiny-server’ は 1 つにしか一致しませんが、‘%hiney-server’ は両方に一致する 2 つのエントリがありました。これが私の理解にどう役立つのかはわかりませんが、私が行っている select は 1 つの結果のみを想定しており、インデックスからそれを取得して他を無視しているが、% を使用するとフィールドを検索するというおっしゃる意味だと考えられます。

discourse=> EXPLAIN ANALYZE select * from tags where name='shiny-server'; 
                                                        QUERY PLAN                                                        
--------------------------------------------------------------------------------------------------------------------------
 Index Scan using index_tags_on_name on tags  (cost=0.28..8.29 rows=1 width=36) (actual time=0.038..0.040 rows=1 loops=1)
   Index Cond: ((name)::text = 'shiny-server'::text)
 Planning time: 0.129 ms
 Execution time: 0.070 ms
(4 rows)

自分でこの問題を解決できない人がこれを見つけて役に立つとは思えませんが、……同じ名前の 2 つの tag_id を見つけて、以下のような処理を行いました。

 TopicTag.where(tag_id: 717).update_all(tag_id: 611)
 Tag.ensure_consistency!
 Tag.find(717) # どのトピックにも含まれていないことを確認
 Tag.find(717).destroy

その後、psql で reindex table tags; を実行しました。

そして、@bartv が説明したように、今度は users についても同様の処理を行う必要があるようです。私のユーザーを見ると、David というユーザーと david というユーザー、さらに [Mm]ark が見られます。

これらは以下のように修正しました。

marks=User.where("username similar to  '[Mm]+ark'").pluck(:id,:username,:created_at)

その後、/admin/users で新しい Mark を見つけ、そこでユーザー名を変更します。それから psql で reindex table users; を実行します（sudo su - discourse を実行してから psql）。

15

次のように考えてみてください。電話帳で Pfaffman という名前を探す必要がある場合、まず P の欄に行き、次に Pe と Pg の間のエントリを探し、さらに Pfa と Pfb の間を探し、といったように進みます。エントリがアルファベット順に並んでいるという性質を利用して、素早く該当するエントリを検索します。ここで、ある電話帳の編集者がアルファベットを正しく覚えておらず、いくつかの Pfaffman を誤った位置に挿入してしまった（インデックスが破損している）と想像してみてください（これは思考実験です）。その場合、それらを見つけることはできません。

次に、名字が faffman で終わる人すべてを検索する必要があります。これを素早く行う方法はありません。電話帳全体を調べる必要があります。これは非常に手間がかかります！しかし、この方法であれば、誤って挿入された Pfaffman たちを見つけることができます！