Impossible de restaurer en raison d'index corrompus (avec quelques indices sur la manière de traiter les index corrompus)

Soutien Installation
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

Êtes-vous certain que psql n’ait pas enregistré une autre erreur avant celle-ci ? Cela se produit généralement lorsqu’une commande SQL précédente a échoué.

Par ailleurs, pourquoi la base de données d’origine contient-elle des enregistrements en double dans la table incoming_referers ? L’index unique sur cette table existe depuis 2014. Peut-être que la base de données que vous tentez de restaurer présente beaucoup plus de problèmes que celui-ci ?

3

Merci Gerhard ! J’apprécie votre aide. Cette situation devient de plus en plus étrange.

Il n’a pas de sens pour moi non plus qu’il y ait eu un problème avec incoming_referers. J’ai effectué une restauration depuis la production vers ce site de staging aussi récemment qu’en octobre.

Il semble qu’il y ait un problème avec la base de données ou les index. Je soupçonnais un plugin, mais les erreurs touchent des index suffisamment différents pour qu’il soit peu probable qu’un seul plugin en soit responsable. Une recherche préalable avec grep dans les plugins concernant les problèmes d’index brisés n’a rien donné.

Lors d’une restauration, j’ai obtenu ceci :

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

J’ai exécuté :

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

Et j’ai réessayé :

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

Voici l’intégralité du début de la dernière restauration :

[2020-01-03 16:41:34] 'pfaffman' a lancé la restauration !
[2020-01-03 16:41:34] Marquage de la restauration comme en cours...
[2020-01-03 16:41:34] Vérification de l'existence de /var/www/discourse/tmp/restores/default/2020-01-03-164133...
[2020-01-03 16:41:34] Téléchargement de l'archive vers le répertoire tmp...
[2020-01-03 16:45:20] Aucun fichier de métadonnées à extraire.
[2020-01-03 16:45:20] Validation des métadonnées...
[2020-01-03 16:45:20]   Version actuelle : 20191220134101
[2020-01-03 16:45:20]   Version restaurée : 20191129144706
[2020-01-03 16:45:20] Extraction du fichier de dump...
[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

Je suppose que vous devrez nettoyer les données manuellement jusqu’à ce que la restauration fonctionne et que tous les index uniques puissent être créés.

En dehors de cela, je me demande si nous avons livré une version buggy de PostgreSQL dans l’une des images de base récentes. Il y a eu pas mal de rapports sur des problèmes d’index corrompus au cours du dernier mois ou deux. Cela semble être une coïncidence étrange. :thinking:

6

J’aimerais une explication qui ne soit pas simplement « Jay a encore fait une bêtise ». :wink:

Pour info, je suis presque certain d’avoir récemment mis à jour le conteneur de données de ce site juste avant que cela ne commence.

8

Vous pourriez examiner les dates created_at des enregistrements en double et essayer de déterminer quelle version de Postgres était utilisée à cette époque. @falco a mentionné que les versions PG 10.0 et 10.1 présentaient des problèmes d’index corrompus, mais cela remonte à longtemps (la version 10.2 est sortie le 2018-02-08) et nous n’avons commencé à livrer PG 10 qu’en avril 2018 (donc après la sortie de la version 10.2). Donc, soit il s’agit d’un nouveau bug dans PG, soit c’est simplement de la malchance. :man_shrugging:

9

Hmm. Bon, la production tourne sous 10.10 et la staging sous 10.11.

De plus, parmi les enregistrements dont les journaux ont signalé un échec en raison d’un doublon, certains n’en avaient qu’un seul. Peut-être que l’enregistrement a été supprimé, mais pas de l’index ? Est-ce que cela a du sens ?

10

Maintenant, les index ne sont pas recréés à chaque mise à jour.

Oui, car ce sont des objets différents sur le disque.

11

Eh bien, voici un indice :

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

Je ne parviens pas à distinguer la différence entre ces deux-là, mais la première requête n’en a trouvé qu’un seul ?

12

Si vous exécutez EXPLAIN ANALYZE select * from tags where name='addins';, vous comprendrez pourquoi.

Il s’agissait soit d’une lecture par index uniquement (je en doute car vous sélectionnez trop de colonnes), soit d’une lecture bitmap heap, où l’index est utilisé pour déterminer quelles lignes sélectionner. Comme l’index est corrompu…

13

C’est exactement le problème que j’ai rencontré récemment avec mon index corrompu. J’ai fini par inspecter ces comptes, souvent en constatant qu’ils étaient identiques (même adresse e-mail), j’en ai renommé un puis les ai fusionnés. Cela a demandé pas mal de travail car c’était surtout manuel, mais maintenant j’ai un tout nouvel index :slight_smile:

Édité : oups, mon problème se situait dans la table des utilisateurs. C’était toujours le même problème de clé dupliquée.

14

Celui-ci présentait également deux entrées où ‘shiny-server’ correspondait à une seule, mais ‘%hiney-server’ correspondait aux deux. Je ne vois pas en quoi cela m’aide à comprendre, mais je pense que vous voulez dire que le select que j’exécute s’attend à ce qu’un seul élément soit renvoyé et le récupère depuis l’index, en ignorant l’autre, tandis que lorsque j’utilise le %, il recherche dans les champs.

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)

Je doute fort que quiconque ne parvenant pas à comprendre cela de lui-même trouve cela utile, mais… J’ai effectué plusieurs recherches pour trouver les deux tag_id ayant le même nom et j’ai exécuté des opérations comme :

 TopicTag.where(tag_id: 717).update_all(tag_id: 611)
 Tag.ensure_consistency!
 Tag.find(717) # s'assurer qu'il n'est associé à aucun sujet
 Tag.find(717).destroy

puis j’ai exécuté reindex table tags; dans psql.

Il semble maintenant que je doive faire de même pour users, un peu comme l’a décrit @bartv. Cependant, avec mes utilisateurs, je vois un utilisateur nommé David et un autre nommé david, ainsi que [Mm]ark.

Pour ceux-ci, j’ai procédé ainsi :

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

Ensuite, j’ai repéré le nouveau Mark dans /admin/users et renommé l’utilisateur depuis l’interface. Puis j’ai tenté d’exécuter reindex table users; dans psql (sudo su - discourse puis psql).

15

Imaginez les choses ainsi. Si vous devez chercher « Pfaffman » dans un annuaire téléphonique, vous allez à la lettre P, puis vous cherchez les entrées comprises entre « Pe » et « Pg », puis entre « Pfa » et « Pfb », etc. Vous utilisez le fait que les entrées sont triées par ordre alphabétique pour trouver rapidement l’entrée souhaitée. Maintenant, imaginez – dans une expérience mentale – que l’un des éditeurs de l’annuaire n’ait pas mémorisé correctement l’alphabet et ait inséré certains « Pfaffman » au mauvais endroit (un index corrompu). Vous ne les trouverez pas.

Maintenant, vous devez chercher toutes les personnes dont le nom de famille se termine par « faffman ». Il n’existe aucun moyen rapide de le faire ; vous devrez parcourir l’intégralité de l’annuaire. C’est beaucoup de travail ! Mais… vous trouverez ainsi les « Pfaffman » insérés incorrectement !