RDS Mysql point in time restore falha - estado incompatível

1

Eu tenho uma instância do RDS MySQL com o MySQL versão 5.7.19 para a qual uma restauração pontual falhou com um status de "estado incompatível".

Por meio da experimentação, determinei que as restaurações de ponto no tempo falham até que o próximo instantâneo seja tirado e funcione imediatamente depois que o instantâneo foi tirado.

O AWS Support me diz que

The restore operation encountered inserts/updates with strings containing non-encoded binary characters which are a known source of decoding issues. This issue is a terminal problem as it prevents us from understanding where exactly the replay broke.

Estou tentando identificar como atenuar proativamente o problema. Existe algum log que eu poderia encontrar tais "caracteres binários não codificados" proativamente sem fazer uma restauração PIT? Ou eu preciso fazer periodicamente uma restauração e captura instantânea de falhas para garantir que eu tenha uma grande quantidade de períodos de tempo cobertos pela restauração PIT?

Atualizar

Restaurar o instantâneo anterior ao PITR com falha mostra esse log de erros antes de executar qualquer consulta:

2018-05-31T07:59:50.880143Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2018-05-31T07:59:50.881641Z 0 [Warning] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2018-05-31T07:59:50.885191Z 0 [Note] /rdsdbbin/mysql/bin/mysqld (mysqld 5.7.19-log) starting as process 3470 ...
2018-05-31T07:59:51.126014Z 0 [Note] InnoDB: PUNCH HOLE support available
2018-05-31T07:59:51.126054Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-05-31T07:59:51.126060Z 0 [Note] InnoDB: Uses event mutexes
2018-05-31T07:59:51.126064Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-05-31T07:59:51.126068Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2018-05-31T07:59:51.126071Z 0 [Note] InnoDB: Using Linux native AIO
2018-05-31T07:59:51.150879Z 0 [Note] InnoDB: Number of pools: 1
2018-05-31T07:59:51.182600Z 0 [Note] InnoDB: Using CPU crc32 instructions
2018-05-31T07:59:51.184624Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1G, instances = 8, chunk size = 128M
2018-05-31T07:59:51.245944Z 0 [Note] InnoDB: Completed initialization of buffer pool
2018-05-31T07:59:51.274809Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
2018-05-31T07:59:51.661104Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2018-05-31T07:59:52.079538Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 205460220725
2018-05-31T07:59:53.616196Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 205460333516
2018-05-31T07:59:54.463445Z 0 [Note] InnoDB: Database was not shutdown normally!
2018-05-31T07:59:54.463472Z 0 [Note] InnoDB: Starting crash recovery.
2018-05-31T07:59:56.869876Z 0 [Note] InnoDB: Transaction 1712897897 was in the XA prepared state.
2018-05-31T07:59:57.059082Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo
2018-05-31T07:59:57.059107Z 0 [Note] InnoDB: Trx id counter is 1712898304
2018-05-31T07:59:57.060227Z 0 [Note] InnoDB: Starting an apply batch of log records to the database...
InnoDB: Progress in percent: 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 
2018-05-31T07:59:57.606094Z 0 [Note] InnoDB: Apply batch completed
2018-05-31T07:59:57.606126Z 0 [Note] InnoDB: Last MySQL binlog file position 0 7766, file name mysql-bin-changelog.196126
2018-05-31T08:01:05.616244Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions
2018-05-31T08:01:05.616271Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed
2018-05-31T08:01:05.617146Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2018-05-31T08:01:05.617158Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2018-05-31T08:01:05.617203Z 0 [Note] InnoDB: Setting file '/rdsdbdata/db/innodb/ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2018-05-31T08:01:07.653103Z 0 [Note] InnoDB: File '/rdsdbdata/db/innodb/ibtmp1' size is now 12 MB.
2018-05-31T08:01:07.654148Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2018-05-31T08:01:07.654159Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2018-05-31T08:01:07.870099Z 0 [Note] InnoDB: Waiting for purge to start
2018-05-31T08:01:07.920296Z 0 [Note] InnoDB: 5.7.19 started; log sequence number 205460333516
2018-05-31T08:01:07.920583Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 76646ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.)
2018-05-31T08:01:07.920723Z 0 [Note] InnoDB: Loading buffer pool(s) from /rdsdbdata/db/innodb/ib_buffer_pool
2018-05-31T08:01:07.924167Z 0 [Note] Plugin 'FEDERATED' is disabled.
2018-05-31T08:01:07.938375Z 0 [Note] Recovering after a crash using /rdsdbdata/log/binlog/mysql-bin-changelog
2018-05-31T08:01:07.938453Z 0 [Note] Starting crash recovery...
2018-05-31T08:01:07.938489Z 0 [Note] InnoDB: Starting recovery for XA transactions...
2018-05-31T08:01:07.938496Z 0 [Note] InnoDB: Transaction 1712897897 in prepared state after recovery
2018-05-31T08:01:07.938500Z 0 [Note] InnoDB: Transaction contains changes to 1 rows
2018-05-31T08:01:07.938504Z 0 [Note] InnoDB: 1 transactions in prepared state after recovery
2018-05-31T08:01:07.938506Z 0 [Note] Found 1 prepared transaction(s) in InnoDB
2018-05-31T08:01:07.975797Z 0 [Note] Crash recovery finished.
2018-05-31T08:01:08.009971Z 0 [Note] Salting uuid generator variables, current_pid: 3470, server_start_time: 1527753590, bytes_sent: 0, 
2018-05-31T08:01:08.013725Z 0 [Note] Generated uuid: 'c65e1206-64a8-11e8-acdc-0642b77ee370', server_start_time: 976718170713733380, bytes_sent: 47057241759744
2018-05-31T08:01:08.013758Z 0 [Warning] No existing UUID has been found, so we assume that this is the first time that this server has been started. Generating a new UUID: c65e1206-64a8-11e8-acdc-0642b77ee370.
2018-05-31T08:01:08.044320Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2018-05-31T08:01:08.044373Z 0 [Note] IPv6 is available.
2018-05-31T08:01:08.044384Z 0 [Note] - '::' resolves to '::';
2018-05-31T08:01:08.044401Z 0 [Note] Server socket created on IP: '::'.
2018-05-31T08:01:09.042028Z 0 [Note] Event Scheduler: Loaded 0 events
2018-05-31T08:01:09.042160Z 0 [Note] /rdsdbbin/mysql/bin/mysqld: ready for connections.
Version: '5.7.19-log' socket: '/tmp/mysql.sock' port: 3306 MySQL Community Server (GPL)
2018-05-31T08:01:09.042169Z 0 [Note] Executing 'SELECT * FROM INFORMATION_SCHEMA.TABLES;' to get a list of tables using the deprecated partition engine. You may use the startup option '--disable-partition-engine-check' to skip this check. 
2018-05-31T08:01:09.042171Z 0 [Note] Beginning of list of non-natively partitioned tables
2018-05-31T08:01:09.889603Z 0 [Note] InnoDB: Buffer pool(s) load completed at 180531 8:01:09
2018-05-31T08:01:14.839437Z 0 [Note] End of list of non-natively partitioned tables
----------------------- END OF LOG ----------------------

Uma verificação para tabelas não-InnoDB mostra isso:

+---------------+-------------------------+-------------------------------+------------+--------+---------+------------+------------+----------------+-------------+------------------+--------------+-----------+----------------+---------------------+---------------------+------------+--------------------+----------+----------------+---------------+
| TABLE_CATALOG | TABLE_SCHEMA            | TABLE_NAME                    | TABLE_TYPE | ENGINE | VERSION | ROW_FORMAT | TABLE_ROWS | AVG_ROW_LENGTH | DATA_LENGTH | MAX_DATA_LENGTH  | INDEX_LENGTH | DATA_FREE | AUTO_INCREMENT | CREATE_TIME         | UPDATE_TIME         | CHECK_TIME | TABLE_COLLATION    | CHECKSUM | CREATE_OPTIONS | TABLE_COMMENT |
+---------------+-------------------------+-------------------------------+------------+--------+---------+------------+------------+----------------+-------------+------------------+--------------+-----------+----------------+---------------------+---------------------+------------+--------------------+----------+----------------+---------------+
| def           | promosolutions_co_nz    | w90h1_finder_tokens           | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            459 |           0 |         15040512 |            0 |         0 |           NULL | 2018-05-31 08:20:13 | NULL                | NULL       | utf8_general_ci    |     NULL |                |               |
| def           | promosolutions_co_nz    | w90h1_finder_tokens_aggregate | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            474 |           0 |         15061350 |            0 |         0 |           NULL | 2018-05-31 08:20:13 | NULL                | NULL       | utf8_general_ci    |     NULL |                |               |
| def           | vc                      | CORE                          | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            777 |           0 |         16627023 |            0 |         0 |           NULL | 2018-05-31 08:20:23 | NULL                | NULL       | latin1_swedish_ci  |     NULL |                |               |
| def           | vc                      | CORErs                        | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            786 |           0 |         16649838 |            0 |         0 |           NULL | 2018-05-31 08:20:23 | NULL                | NULL       | latin1_swedish_ci  |     NULL |                |               |
| def           | vc                      | vw_mygroups                   | BASE TABLE | MyISAM |      10 | Fixed      |          0 |              0 |           0 | 1970324836974591 |         1024 |         0 |           NULL | 2018-05-01 04:44:19 | 2018-05-01 04:44:19 | NULL       | utf8_general_ci    |     NULL |                |               |
| def           | www_automatem_co_nz     | jos_finder_tokens             | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            623 |           0 |         15553818 |            0 |         0 |           NULL | 2018-05-31 08:20:27 | NULL                | NULL       | utf8mb4_general_ci |     NULL |                |               |
| def           | www_automatem_co_nz     | jos_finder_tokens_aggregate   | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            639 |           0 |         15582015 |            0 |         0 |           NULL | 2018-05-31 08:20:27 | NULL                | NULL       | utf8mb4_general_ci |     NULL |                |               |
| def           | www_bayautomotive_co_nz | jos_finder_tokens             | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            623 |           0 |         15553818 |            0 |         0 |           NULL | 2018-05-31 08:20:28 | NULL                | NULL       | utf8mb4_general_ci |     NULL |                |               |
| def           | www_bayautomotive_co_nz | jos_finder_tokens_aggregate   | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            639 |           0 |         15582015 |            0 |         0 |           NULL | 2018-05-31 08:20:28 | NULL                | NULL       | utf8mb4_general_ci |     NULL |                |               |
| def           | www_xpanda_co_nz        | jos_finder_tokens             | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            623 |           0 |         15553818 |            0 |         0 |           NULL | 2018-05-31 08:20:36 | NULL                | NULL       | utf8mb4_general_ci |     NULL |                |               |
| def           | www_xpanda_co_nz        | jos_finder_tokens_aggregate   | BASE TABLE | MEMORY |      10 | Fixed      |          0 |            639 |           0 |         15582015 |            0 |         0 |           NULL | 2018-05-31 08:20:36 | NULL                | NULL       | utf8mb4_general_ci |     NULL |                |               |
+---------------+-------------------------+-------------------------------+------------+--------+---------+------------+------------+----------------+-------------+------------------+--------------+-----------+----------------+---------------------+---------------------+------------+--------------------+----------+----------------+---------------+

(não se preocupe, nada disso é hospedado por este servidor)

Eu executei o select * em todas essas tabelas (todas vazias) e inseri um registro de singe em cada uma delas. O log de erros não mostra entradas adicionais no CloudWatch.

    
por jdog 29.05.2018 / 23:12

2 respostas

1

No grupo de parâmetros da instância, defina binlog_format para ROW . O padrão no RDS é MIXED , embora não haja um motivo convincente para esse valor padrão na maioria das condições. Nos meus sistemas, ROW é sempre usado porque tem vantagens substanciais sobre MIXED .

Uma das razões mais convincentes neste cenário é esta parte da explicação:

The restore operation encountered inserts/updates with strings containing non-encoded binary characters

Embora isso não me pareça uma explicação completa (porque isso não é realmente inválido, sem um bug), podemos facilmente evitar o problema, conforme descrito - o formato de registro ROW captura imagens de linhas alteradas, em vez de capturar a inserção / update (/ delete) instruções como "strings", por isso, se houver um problema com a maneira como a infraestrutura do RDS ou a versão do MySQL subjacente lida com isso, isso deve eliminá-lo.

O modo MIXED permite que o otimizador escolha se deseja registrar os resultados de DML como a consulta que foi emitida ou como imagens das linhas que foram alteradas, e tenderá a registrar a instrução se nada internamente sinalizar a instrução como não-determinístico para, ou incompatível com, repetição - como usar coisas como a função UUID() (que não geraria o mesmo valor quando chamado, no futuro). (Outras funções, como NOW() , possuem mecanismos complementares embutidos no registro que os tornam determinísticos para reprodução, contra-intuitivamente.)

A única ressalva significativa que vem à mente com o modo ROW é que todas as suas tabelas devem ter chaves primárias (o que deve ser prática padrão, de qualquer forma) senão restauração e replicação (se você tiver réplicas) podem ser mais lentas, pois toda a tabela é verificada quanto a exclusões e atualizações nessa condição ... mas deixando de lado essa consideração, as vantagens do log% ROW são tais que eu não tive a oportunidade de usar nada além de ROW por muitos anos. / p>

A segunda questão é garantir que você não esteja usando o MyISAM ou qualquer outro mecanismo de armazenamento, exceto as tabelas do sistema que as utilizam por padrão (não tente alterá-las).

O MyISAM não possui o recurso de recuperação de falhas do InnoDB, e o RDS depende dessa capacidade para tornar os instantâneos utilizáveis. Ele toma precauções nas tabelas do sistema, portanto elas não representam um problema, mas, para as suas tabelas, nenhuma proteção está em vigor. Uma tabela não-MyISAM que não esteja em um estado consolidado com segurança quando a captura instantânea ocorrer pode impedir que a captura instantânea funcione corretamente.

Embora o suporte não identifique isso como sendo seu problema, é consistente com sua observação de que o horário não funciona até que você crie um novo instantâneo.

Apesar de não documentado em detalhes, minha suposição baseada em evidências anedóticas é que o ponto no tempo começa com o instantâneo antes, mas está mais próximo do ponto de recuperação desejado e, em seguida, aplica todos os logs binários arquivados relevantes para avançar para o ponto de recuperação desejado. É assim que você faz isso manualmente, fora do RDS, e com base nas ações observáveis do usuário "rdsadmin", não há razão para acreditar que o RDS reinventou a roda.

É claro que o problema com um snapshot que inclui tabelas MyISAM desfiguradas é que isso não é algo que se apresenta até após você restaurar o snapshot e e tentar acessar uma das tabelas.

Se este for realmente o problema, o suporte pode ter assumido que você estava ciente do seguinte e, incorretamente, excluiu-o como uma possibilidade:

The MyISAM storage engine does not support reliable recovery and can result in lost or corrupt data when MySQL is restarted after a recovery, preventing Point-In-Time restore or snapshot restore from working as intended.

https://docs.aws.amazon.com/AmazonRDS/latest/UserGuide/CHAP_MySQL.html

Se você estiver usando tabelas MyISAM, você deve convertê-las para o InnoDB.

    
por 30.05.2018 / 12:56
1

A Amazon Web Services pesquisou mais sobre esse problema e encontrou o culpado da seguinte forma:

********* update from service team ***********

This is decoded DDL in the binary log that blocked point-in-time restore for restore-markovina-aws-support. It is a "create table if not exists" for the drsarahhart_com.wp_wfBlocks7 table. I had to manually skip it (as the table already existed) to push the restore to completion (there was also a similar DDL in a later binary log).

# at 375050
#180523 19:10:46 server id 153211832  end_log_pos 375115 CRC32 0x1eec997a       Anonymous_GTID  last_committed=301      sequence_number=302     rbr_only=no
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 375115
#180523 19:10:46 server id 153211832  end_log_pos 375785 CRC32 0xc43c076b       Query   thread_id=584850        exec_time=0     error_code=0
SET TIMESTAMP=1527102646/*!*/;
create table IF NOT EXISTS wp_wfBlocks7 (
  'id' bigint(20) unsigned NOT NULL AUTO_INCREMENT,
  'type' int(10) unsigned NOT NULL DEFAULT '0',
  'IP' binary(16) NOT NULL DEFAULT '\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@',
  'blockedTime' bigint(20) NOT NULL,
  'reason' varchar(255) NOT NULL,
  'lastAttempt' int(10) unsigned DEFAULT '0',
  'blockedHits' int(10) unsigned DEFAULT '0',
  'expiration' bigint(20) unsigned NOT NULL DEFAULT '0',
  'parameters' text,
  PRIMARY KEY ('id'),
  KEY 'type' ('type'),
  KEY 'IP' ('IP'),
  KEY 'expiration' ('expiration')
) DEFAULT CHARSET=utf8
/*!*/;
# at 375785

The problematic characters were in the sequence: '\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@\^@'
This corresponds to this ASCII code point sequence: 5c 27 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 5c 00 27 00

How is the customer executing the DDL in the first place to create this table? Is the DDL being auto-generated or is someone running a script? If using a script how are they encoding the script contents? 

********* end update from service team ********

Tenho certeza que esta é uma tabela criada pelo Wordpress WordFence plugin, vou verificar se isso ainda é atual e reportar de volta aqui.

    
por 21.06.2018 / 03:00