RDS Mysql момент времени восстановления не удается - несовместимое состояние
У меня есть экземпляр RDS MySQL с версией MySQL 5.7.19, для которого не удалось восстановить момент времени со статусом "несовместимое состояние".
С помощью экспериментов я установил, что восстановление в момент времени завершается сбоем до следующего снимка и работает сразу после того, как был сделан снимок.
Служба поддержки AWS сообщает мне, что
Операция восстановления обнаружила вставки / обновления со строками, содержащими некодированные двоичные символы, которые являются известным источником проблем декодирования. Эта проблема является терминальной, поскольку она не позволяет нам понять, где именно прервалось воспроизведение.
Я пытаюсь определить, как активно смягчить проблему. Есть ли какой-нибудь журнал, в котором я мог бы найти такие "некодированные двоичные символы" предварительно, не выполняя 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.
2 ответа
В группе параметров экземпляра установите 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 после восстановления, что препятствует работе Point-In-Time или моментального восстановления, как предполагалось.
https://docs.aws.amazon.com/AmazonRDS/latest/UserGuide/CHAP_MySQL.html
Если вы используете таблицы MyISAM, вы должны преобразовать их в InnoDB.
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, я проверю ее актуальность и сообщу здесь.