Não é possível restaurar devido a índices corrompidos (com algumas dicas sobre como lidar com índices corrompidos)

Suporte Instalação
1

Este backup falhou várias vezes devido a erros como

ERRO:  não foi possível criar índice único "index_incoming_referers_on_path_and_incoming_domain_id"
DETALHE:  A chave (path, incoming_domain_id)=(/@dataandme, 41) está duplicada.               
ERRO:  a transação atual foi abortada, comandos ignorados até o fim do bloco de transação

Eu removi manualmente todos esses registros no Rails com comandos como
IncomingReferer.where(path: ‘/@dataandme’).destroy_all

Agora ainda está falhando e eu

...
[2019-12-30 20:29:16] 'pfaffman' iniciou a restauração!
[2019-12-30 20:29:16] Marcando a restauração como em execução...
[2019-12-30 20:29:16] Verificando se /var/www/discourse/tmp/restores/default/2019-12-30-202916 existe...
[2019-12-30 20:29:16] Baixando o arquivo compactado para o diretório tmp...
[2019-12-30 20:29:38] Nenhum arquivo de metadados para extrair.
[2019-12-30 20:29:38] Validando metadados...
[2019-12-30 20:29:38]   Versão atual: 20191129144706
[2019-12-30 20:29:38]   Versão restaurada: 20191129144706
[2019-12-30 20:29:38] Extraindo o arquivo dump...
[2019-12-30 20:30:07] Criando funções ausentes no esquema discourse_functions
[2019-12-30 20:30:08] Não é possível restaurar em esquema diferente, restaurando no local
[2019-12-30 20:30:08] Habilitando modo somente leitura...
[2019-12-30 20:30:08] Pausando o sidekiq...
[2019-12-30 20:30:08] Aguardando o sidekiq terminar de executar os jobs...
[2019-12-30 20:30:08] Restaurando o arquivo dump... (pode demorar bastante)

 ----- e assim por diante -----
[2019-12-30 20:33:17] ERRO:  a transação atual foi abortada, comandos ignorados até o fim do bloco de transação
[2019-12-30 20:33:17] ERRO:  a transação atual foi abortada, comandos ignorados até o fim do bloco de transação
[2019-12-30 20:33:17] EXCEÇÃO: psql falhou
[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] Tentando rollback...
[2019-12-30 20:33:17] Fazendo rollback...
[2019-12-30 20:33:17] Limpando os arquivos...
[2019-12-30 20:33:17] Removendo função do esquema discourse_functions
[2019-12-30 20:33:17] Removendo o diretório tmp '/var/www/discourse/tmp/restores/default/2019-12-30-202916'...
[2019-12-30 20:33:17] Retomando o sidekiq...
[2019-12-30 20:33:17] Desabilitando modo somente leitura...
[2019-12-30 20:33:17] Marcando a restauração como concluída...
[2019-12-30 20:33:17] Notificando 'pfaffman' sobre o fim da restauração...
[2019-12-30 20:33:34] Concluído!

Agora não vejo nada que eu saiba como corrigir.

Posso atualizar o site de staging para o qual estou tentando restaurar, mas prefiro não atualizar o site de produção sem antes ter certeza de que tudo funciona no staging…

2

Tem certeza de que o psql não registrou nenhum outro erro antes disso? Isso geralmente acontece quando um comando SQL anterior falhou.

Além disso, por que o banco de dados original possui registros duplicados na tabela incoming_referers? O índice único nessa tabela existe desde 2014. Talvez o banco de dados que você está tentando restaurar tenha muitos mais problemas do que apenas este?

3

Obrigado, Gerhard! Agradeço sua ajuda. Essa situação está ficando cada vez mais estranha.

Também não faz sentido para mim que houvesse um problema com incoming_referers. Fiz uma restauração da produção para este site de staging tão recentemente quanto em outubro.

Parece que há algo errado com o banco de dados ou com os índices. Eu suspeitava de um plugin, mas os erros ocorrem em índices tão diversos que parece improvável que um único plugin seja o culpado. Um grep anterior nos plugins em busca dos problemas de índice quebrado não retornou nada.

Em uma restauração, obtive o seguinte:

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

Fiz:

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

E tentei novamente:

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

Aqui está o cabeçalho completo da restauração mais recente:

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

Acho que você vai ter que limpar os dados manualmente até que a restauração funcione e todos os índices únicos possam ser criados.

Isso posto, me pergunto se embarcamos uma versão com bugs do PostgreSQL em uma das imagens base mais recentes. Houve vários relatos sobre problemas com índices corrompidos no último mês ou dois. Parece uma coincidência estranha. :thinking:

6

Adoraria uma explicação que não fosse apenas “O Jay fez algo estúpido de novo.” :wink:

A propósito, tenho quase certeza de que atualizei o contêiner de dados deste site pouco antes disso começar.

8

Você pode dar uma olhada nas datas created_at dos registros duplicados e tentar descobrir qual versão do Postgres foi usada naquela época. @falco mencionou que o PG 10.0 e o 10.1 tinham problemas com índices corrompidos, mas isso foi há muito tempo (a versão 10.2 foi lançada em 08/02/2018) e só começamos a distribuir o PG 10 em abril de 2018 (ou seja, após o lançamento da 10.2). Então, ou é um novo bug no PG ou apenas azar. :man_shrugging:

9

Hmm. Bem, a produção está na versão 10.10 e o staging na 10.11.

Além disso, alguns dos registros que os logs indicaram como falhos por causa de uma duplicata tinham apenas um registro. Talvez o registro tenha sido excluído, mas não foi removido do índice também? Faz sentido isso?

10

Agora, mas os índices não são recriados a cada atualização.

Sim, pois são objetos diferentes no disco.

11

Bem, aqui está uma dica:

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

Não consigo identificar a diferença entre esses dois registros, mas a primeira consulta encontrou apenas um deles?

12

Se você executar um EXPLAIN ANALYZE select * from tags where name='addins';, descobrirá o motivo.

Ou foi uma varredura apenas de índice (duvido, pois você está selecionando muitas colunas) ou uma varredura de heap bitmap, onde o índice é usado para saber quais linhas selecionar. Como o índice está corrompido…

13

Esse é exatamente o problema que tive recentemente com meu índice corrompido. Acabei inspecionando essas contas e, frequentemente, descobria que eram as mesmas (mesmo endereço de e-mail), renomeava uma e depois as fundia. Foi bastante trabalho, já que era quase tudo manual, mas agora tenho um índice novo e brilhante :slight_smile:

Edição: ops, meu problema estava na tabela de usuários. Mesmo problema de chave duplicada, porém.

14

Este também tinha duas entradas onde ‘shiny-server’ correspondia a apenas uma, mas ‘%hiney-server’ correspondia a ambas. Não vejo como isso me ajuda a entender, mas acho que você está dizendo que o select que estou fazendo espera que apenas um resultado seja retornado e o busca no índice, ignorando o outro, mas quando uso o %, ele pesquisa nos campos.

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)

Duvido bastante que alguém que não conseguiria descobrir isso por conta própria ache isso útil, mas… Fiz uma série de buscas pelos dois tag_ids com o mesmo nome e executei operações como:

 TopicTag.where(tag_id: 717).update_all(tag_id: 611)
 Tag.ensure_consistency!
 Tag.find(717) # garantir que não esteja em nenhum tópico
 Tag.find(717).destroy

e depois executei um reindex table tags; no psql.

E parece que agora precisarei fazer algo semelhante para users, como @bartv descreveu. Embora, com meus usuários, eu veja um usuário David e outro usuário david, além de [Mm]ark.

Aqueles eu corrigi assim:

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

Depois, encontrei o novo Mark em /admin/users e renomeei o usuário ali. Em seguida, tentei executar reindex table users; no psql. (sudo su - discourse e depois psql).

15

Pense nisso da seguinte forma. Se você precisa procurar por Pfaffman em uma lista telefônica, vai até a letra P, depois tenta encontrar as entradas entre Pe e Pg, depois entre Pfa e Pfb, e assim por diante. Você usa o fato de as entradas estarem ordenadas alfabeticamente para localizar rapidamente a entrada. Agora imagine — como um exercício mental — que um dos editores da lista telefônica não memorizou o alfabeto corretamente e inseriu alguns Pfaffmans no lugar errado (um índice corrompido). Você não os encontrará.

Agora, você precisa procurar todas as pessoas cujo sobrenome termine com faffman. Não há uma maneira rápida de fazer isso; você precisará percorrer toda a lista telefônica. Isso dá muito trabalho! Mas… dessa forma, você encontrará os Pfaffmans inseridos incorretamente!