У меня есть экземпляр MySQL RDS с версией MySQL 5.7.19, для которого восстановление на определенный момент времени не удалось со статусом «несовместимое состояние».
Путем экспериментов я определил, что восстановление на определенный момент времени терпит неудачу до следующего снимка и работает сразу после того, как был сделан снимок.
AWS Support сообщает мне, что
Операция восстановления обнаружила вставки / обновления со строками, содержащими некодированные двоичные символы, которые являются известным источником проблем с декодированием. Это проблема терминала, поскольку она мешает нам понять, где именно прервался воспроизведение.
Я пытаюсь определить, как упреждающе решить проблему. Есть ли какой-нибудь журнал, в котором я мог бы заранее найти такие «незашифрованные двоичные символы» без восстановления PIT? Или мне нужно периодически выполнять восстановление и снимать моментальный снимок при сбое, чтобы гарантировать, что восстановление PIT покрыто большим количеством периодов времени?
Обновить
При восстановлении снимка, сделанного до того, как PITR произошел сбой, отображается этот журнал ошибок перед выполнением каких-либо запросов к нему:
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 ----------------------
Проверка на таблицы, отличные от InnoDB, показывает следующее:
+---------------+-------------------------+-------------------------------+------------+--------+---------+------------+------------+----------------+-------------+------------------+--------------+-----------+----------------+---------------------+---------------------+------------+--------------------+----------+----------------+---------------+
| 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 | | |
+---------------+-------------------------+-------------------------------+------------+--------+---------+------------+------------+----------------+-------------+------------------+--------------+-----------+----------------+---------------------+---------------------+------------+--------------------+----------+----------------+---------------+
(не волнуйтесь, ни один из них больше не размещается на этом сервере)
Я запустил select * для всех этих таблиц (все пустые) и вставил в каждую по одной записи. В журнале ошибок нет дополнительных записей в CloudWatch.
Amazon Web Services продолжила исследование этой проблемы и нашла виновника в следующем:
********* 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 ********
Я почти уверен, что это таблица, созданная плагином Wordpress WordFence, я проверю, актуальна ли она и вернусь сюда.
В группе параметров экземпляра установите binlog_format к ROW. По умолчанию RDS MIXED даже несмотря на то, что для этого значения по умолчанию при большинстве условий нет веских причин. В моих системах ROW всегда используется, потому что он имеет существенные преимущества перед MIXED.
Одна из наиболее веских причин этого сценария - это часть объяснения:
Операция восстановления обнаружила вставки / обновления со строками, содержащими некодированные двоичные символы
Хотя это не кажется мне исчерпывающим объяснением (потому что на самом деле это не недействительно, отсутствует ошибка), мы можем легко избежать проблемы, как описано - ROW формат регистрации фиксирует измененные образы строк вместо записи операторов вставки / обновления (/ удаления) в виде «строк», поэтому, если есть проблема с тем, как их обрабатывает инфраструктура RDS или базовая версия MySQL, это должно устранить ее.
В MIXED режим позволяет оптимизатору выбирать, регистрировать ли результаты DML в виде выданного запроса или в виде изображений строк, которые были изменены, и он будет иметь тенденцию регистрировать оператор, если ничто не помечает его как недетерминированный для, или в противном случае несовместимо с воспроизведением - например, использование таких вещей, как UUID() функция (которая не будет генерировать то же значение при вызове в будущем). (Другие функции, например NOW() имеют дополнительные механизмы, встроенные в журнал, что делает их детерминированными для воспроизведения, что противоречит интуиции.)
Единственное важное предостережение, которое приходит на ум, когда ROW режим заключается в том, что все ваши таблицы должны иметь первичные ключи (что в любом случае должно быть стандартной практикой), иначе восстановление и репликация (если у вас есть реплики) могут быть медленнее, поскольку в этом состоянии вся таблица сканируется на предмет удаления и обновления ... но Если отбросить это соображение, преимущества ROW ведение журнала таково, что у меня не было возможности использовать что-либо, кроме ROW на протяжении многих лет.
Вторая проблема заключается в том, чтобы убедиться, что вы не используете MyISAM или какие-либо другие механизмы хранения, за исключением системных таблиц, которые используют их по умолчанию (не пытайтесь их изменить).
MyISAM не имеет возможности восстановления после сбоя InnoDB, и RDS полагается на эту возможность, чтобы сделать снимки пригодными для использования. Требуются меры предосторожности для системных таблиц, поэтому они не представляют проблемы, но для ваших таблиц нет защиты. Таблица, отличная от MyISAM, которая не находится в безопасном объединенном состоянии при создании моментального снимка, может помешать правильной работе моментального снимка.
Хотя служба поддержки не определила это как вашу проблему, вы согласны с тем, что точка во времени не работает, пока вы не создадите новый снимок.
Несмотря на то, что это недокументировано в каких-либо деталях, мое предположение, основанное на неофициальных данных, состоит в том, что момент времени начинается с моментального снимка раньше, но наиболее близок по времени к желаемой точке восстановления, а затем применяет все соответствующие архивные двоичные журналы для воспроизведения до желаемой точка восстановления. Вот как вы делаете это вручную, вне RDS, и на основе наблюдаемых действий пользователя "rdsadmin" нет оснований полагать, что RDS заново изобрела колесо.
Конечно, проблема со снимком, который включает искаженные таблицы MyISAM, заключается в том, что это не то, что проявляется до тех пор, пока после вы восстанавливаете снимок и затем попробуйте получить доступ к одной из таблиц.
Если это действительно проблема, служба поддержки могла предположить, что вы знаете о следующем, и неверно исключила это как возможность:
Механизм хранения MyISAM не поддерживает надежное восстановление и может привести к потере или повреждению данных при перезапуске MySQL после восстановления, что препятствует нормальной работе восстановления на определенный момент времени или восстановления из моментального снимка.
https://docs.aws.amazon.com/AmazonRDS/latest/UserGuide/CHAP_MySQL.html
Если вы используете таблицы MyISAM, вам следует преобразовать их в InnoDB.