觸發(fā)了MySQL一個(gè)bug導(dǎo)致進(jìn)程不斷crash重啟

2019-11-08 20:38:07

字體：大中小

來(lái)源：轉(zhuǎn)載

供稿：網(wǎng)友

1. 過(guò)程

測(cè)試機(jī)卡死進(jìn)不去，手動(dòng)重啟了一下。重啟后發(fā)現(xiàn)MySQL有張損壞，select特定的條件會(huì)報(bào)錯(cuò):

error_code :2013 Lost connection to MySQL server during query

2013斷開(kāi)連接。難道執(zhí)行超時(shí)了？查看mysql errlog

show variables like ‘%log_error%’

2. 查看MySQL errlog

捕獲到的errlog:

2017-02-10T05:34:50.248538Z 0 [Note] Starting crash recovery...2017-02-10T05:34:50.248667Z 0 [Note] Crash recovery finished.2017-02-10T05:34:50.249289Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170210 13:34:502017-02-10T05:34:50.665378Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and PRivate key2017-02-10T05:34:50.665416Z 0 [Note] Server hostname (bind-address): '0.0.0.0'; port: 33062017-02-10T05:34:50.665443Z 0 [Note] - '0.0.0.0' resolves to '0.0.0.0';2017-02-10T05:34:50.665490Z 0 [Note] Server socket created on Operating system has corrupted its own file cache and rebooting your computer removes the error. If the corrupt page is an index page. You can also try to fix the corruption by dumping, dropping, and reimporting the corrupt table. You can use CHECK TABLE to scan your table for corruption. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.2017-02-10T05:37:03.086952Z 16 [ERROR] InnoDB: Database page corruption on disk or a failed file read of page [page id: space=719, page number=2550]. You may have to recover from a backup.2017-02-10T05:37:03.086964Z 16 [Note] InnoDB: Page dump in ascii and hex (16384 bytes): len 16384; hex 03d99c60000009f6000009f5000009f7000000014c46287045bf0000000000000000000002cf00163b348056000000003a9400020000005400000000000000000000000000000000045800000000000000000000000000000000000000000100020028696e66696d756d0005000b000073757072656d756d100c06120d09000d0c090906000000001000b3800335ec000000d69ebca400000242027c800001fd8000026fe9ad8fe699a8323030303InnoDB: End of page dump2017-02-10T05:37:03.602755Z 16 [Note] InnoDB: Uncompressed page, stored checksum in field1 64592992, calculated checksums for field1: crc32 542883854/1405161966, innodb 1991279791, none 3735928559, stored checksum in field2 64592992, calculated checksums for field2: crc32 542883854/1405161966, innodb 782200846, none 3735928559, page LSN 1 1279666288, low 4 bytes of LSN at page end 1279666288, page number (if stored to page already) 2550, space id (if created with >= MySQL-4.1.1 and stored already) 719InnoDB: Page may be an index page where index id is 11122017-02-10T05:37:03.602788Z 16 [Note] InnoDB: Index 1112 is `PRIMARY` in table `db1`.`tb1`2017-02-10T05:37:03.602798Z 16 [Note] InnoDB: It is also possible that your operating system has corrupted its own file cache and rebooting your computer removes the error. If the corrupt page is an index page. You can also try to fix the corruption by dumping, dropping, and reimporting the corrupt table. You can use CHECK TABLE to scan your table for corruption. Please refer to http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.html for information about forcing recovery.2017-02-10T05:37:03.602821Z 16 [ERROR] [FATAL] InnoDB: Unable to read page [page id: space=719, page number=2550] into the buffer pool after 100 attempts. The most probable cause of this error may be that the table has been corrupted. Or, the table was compressed with with an algorithm that is not supported by this instance. If it is not a decompress failure, you can try to fix this problem by using innodb_force_recovery. Please see http://dev.mysql.com/doc/refman/5.7/en/ for more details. Aborting...2017-02-10 13:37:03 0x7fa31c55a700 InnoDB: Assertion failure in thread 140338531772160 in file ut0ut.cc line 920InnoDB: We intentionally generate a memory trap.InnoDB: Submit a detailed bug report to http://bugs.mysql.com.InnoDB: If you get repeated assertion failures or crashes, evenInnoDB: immediately after the mysqld startup, there may beInnoDB: corruption in the InnoDB tablespace. Please refer toInnoDB: http://dev.mysql.com/doc/refman/5.7/en/forcing-innodb-recovery.htmlInnoDB: about forcing recovery.05:37:03 UTC - mysqld got signal 6 ;This could be because you hit a bug. It is also possible that this binaryor one of the libraries it was linked against is corrupt, improperly built,or misconfigured. This error can also be caused by malfunctioning hardware.Attempting to collect some information that could help diagnose the problem.As this is a crash and something is definitely wrong, the informationcollection process might fail.key_buffer_size=16777216read_buffer_size=262144max_used_connections=7max_threads=600thread_count=7connection_count=7It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 485185 K bytes of memoryHope that's ok; if not, decrease some variables in the equation.Thread pointer: 0x7fa2d00008c0Attempting backtrace. You can use the following information to find outwhere mysqld died. If you see no messages after this, something wentterribly wrong...stack_bottom = 7fa31c559e80 thread_stack 0x40000/usr/local/mysql/bin/mysqld(my_print_stacktrace+0x2c)[0xea97ac]/usr/local/mysql/bin/mysqld(handle_fatal_signal+0x451)[0x7a1861]/lib64/libpthread.so.0(+0xf100)[0x7fa35bf27100]/lib64/libc.so.6(gsignal+0x37)[0x7fa35ab265f7]/lib64/libc.so.6(abort+0x148)[0x7fa35ab27ce8]/usr/local/mysql/bin/mysqld[0x772407]/usr/local/mysql/bin/mysqld(_ZN2ib5fatalD1Ev+0x4d)[0x106ca5d]/usr/local/mysql/bin/mysqld(_Z16buf_page_get_genRK9page_id_tRK11page_size_tmP11buf_block_tmPKcmP5mtr_tb+0x745)[0x10ab895]/usr/local/mysql/bin/mysqld(_Z18btr_validate_indexP12dict_index_tPK5trx_tb+0x11d8)[0x1081428]/usr/local/mysql/bin/mysqld(_ZN11ha_innobase5checkEP3THDP15st_ha_check_opt+0x184)[0xee8524]/usr/local/mysql/bin/mysqld(_ZN7handler8ha_checkEP3THDP15st_ha_check_opt+0x67)[0x7eef07]/usr/local/mysql/bin/mysqld[0xde6853]/usr/local/mysql/bin/mysqld(_ZN19Sql_cmd_check_table7executeEP3THD+0xc1)[0xde7321]/usr/local/mysql/bin/mysqld(_Z21mysql_execute_commandP3THDb+0x5b0)[0xc88660]/usr/local/mysql/bin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x385)[0xc8e865]/usr/local/mysql/bin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0x894)[0xc8f164]/usr/local/mysql/bin/mysqld(_Z10do_commandP3THD+0x177)[0xc909f7]/usr/local/mysql/bin/mysqld(handle_connection+0x278)[0xd48e08]/usr/local/mysql/bin/mysqld(pfs_spawn_thread+0x1b1)[0x1206431]/lib64/libpthread.so.0(+0x7dc5)[0x7fa35bf1fdc5]/lib64/libc.so.6(clone+0x6d)[0x7fa35abe7ced]Trying to get some variables.Some pointers may be invalid and cause the dump to abort.Query (7fa2d0003e50): is an invalid pointerConnection ID (thread ID): 16Status: NOT_KILLEDThe manual page at http://dev.mysql.com/doc/mysql/en/crashing.html containsinformation that should help you find out what is causing the crash.2017-02-10T05:37:03.714250Z mysqld_safe Number of processes running now: 02017-02-10T05:37:03.715526Z mysqld_safe mysqld restarted2017-02-10T05:37:03.873043Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).2017-02-10T05:37:03.873145Z 0 [Warning] Insecure configuration for --secure-file-priv: Current value does not restrict location of generated files. Consider setting it to a valid, non-empty path.2017-02-10T05:37:03.873184Z 0 [Note] /usr/local/mysql/bin/mysqld (mysqld 5.7.12-log) starting as process 30725 ...2017-02-10T05:37:03.878035Z 0 [Note] InnoDB: PUNCH HOLE support available2017-02-10T05:37:03.878069Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins2017-02-10T05:37:03.878076Z 0 [Note] InnoDB: Uses event mutexes2017-02-10T05:37:03.878081Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier2017-02-10T05:37:03.878085Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.32017-02-10T05:37:03.878107Z 0 [Note] InnoDB: Using linux native AIO2017-02-10T05:37:03.878530Z 0 [Note] InnoDB: Number of pools: 12017-02-10T05:37:03.878651Z 0 [Note] InnoDB: Using CPU crc32 instructions2017-02-10T05:37:03.885901Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M2017-02-10T05:37:03.892177Z 0 [Note] InnoDB: Completed initialization of buffer pool2017-02-10T05:37:03.893771Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().2017-02-10T05:37:03.905229Z 0 [Note] InnoDB: Highest supported file format is Barracuda.2017-02-10T05:37:03.905932Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 58106853352017-02-10T05:37:03.905952Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 58106853442017-02-10T05:37:03.906077Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 58106853442017-02-10T05:37:03.906089Z 0 [Note] InnoDB: Database was not shutdown normally!2017-02-10T05:37:03.906094Z 0 [Note] InnoDB: Starting crash recovery.2017-02-10T05:37:03.915478Z 0 [Note] InnoDB: Last MySQL binlog file position 0 607062, file name mysql-bin.0001372017-02-10T05:37:04.036610Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"2017-02-10T05:37:04.036643Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables2017-02-10T05:37:04.036730Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...2017-02-10T05:37:04.061727Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.2017-02-10T05:37:04.062797Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.2017-02-10T05:37:04.062818Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.2017-02-10T05:37:04.063411Z 0 [Note] InnoDB: Waiting for purge to start2017-02-10T05:37:04.113627Z 0 [Note] InnoDB: 5.7.12 started; log sequence number 58106853442017-02-10T05:37:04.113997Z 0 [Note] InnoDB: Loading buffer pool(s) from /usr/local/mysql-5.7.12/data/ib_buffer_pool2017-02-10T05:37:04.114336Z 0 [Note] Plugin 'FEDERATED' is disabled.2017-02-10T05:37:04.115004Z 0 [Note] Recovering after a crash using /usr/local/mysql/mysql-bin-log/mysql-bin2017-02-10T05:37:04.115032Z 0 [Note] Starting crash recovery...2017-02-10T05:37:04.115059Z 0 [Note] Crash recovery finished.2017-02-10T05:37:04.115588Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170210 13:37:042017-02-10T05:37:04.529569Z 0 [Warning] Failed to set up SSL because of the following SSL library error: SSL context is not usable without certificate and private key2017-02-10T05:37:04.529644Z 0 [Note] Server hostname (bind-address): '0.0.0.0'; port: 33062017-02-10T05:37:04.529685Z 0 [Note] - '0.0.0.0' resolves to '0.0.0.0';2017-02-10T05:37:04.529755Z 0 [Note] Server socket created on IP: '0.0.0.0'.2017-02-10T05:37:04.541230Z 0 [Note] Event Scheduler: Loaded 0 events2017-02-10T05:37:04.541419Z 0 [Note] /usr/local/mysql/bin/mysqld: ready for connections.Version: '5.7.12-log' socket: '/var/lib/mysql/mysql.sock' port: 3306 Source distribution

3. errlog分析

通過(guò)log可以看出，像是觸發(fā)了MySQL的bug導(dǎo)致crash了，ps -ef | grep mysql看到重啟時(shí)間確實(shí)是重啟了，然后連接就斷開(kāi)了，所以才返回2013 Lost connection的錯(cuò)誤。原因是因?yàn)?strong>系統(tǒng)被強(qiáng)制重啟導(dǎo)致MySQL相關(guān)核心數(shù)據(jù)未及時(shí)回寫(xiě)。