dbstore2002 s2 instance crashed:
| 1 | Aug 24 09:10:59 dbstore2002 mysqld[3550]: 2018-08-24 9:10:59 140612790758144 [ERROR] Slave I/O: error reconnecting to master 'repl@db2035.codfw.wmnet:3306' - retry-time: 60 maximum-retries: 86400 message: Can't connect to MySQL server on 'db2035.codfw.wmnet' (111 "Connection refused"), Internal MariaDB error code: 2003 |
|---|---|
| 2 | Aug 24 09:12:59 dbstore2002 mysqld[3550]: 2018-08-24 9:12:59 140612790758144 [Note] Slave: connected to master 'repl@db2035.codfw.wmnet:3306',replication resumed in log 'db2035-bin.004846' at position 924796334 |
| 3 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: InnoDB: tried to purge sec index entry not marked for deletion in |
| 4 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: InnoDB: index "cl_sortkey" of table "nowiki"."categorylinks" |
| 5 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: InnoDB: tuple DATA TUPLE: 4 fields; |
| 6 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 0: len 36; hex 417274696b6c65725f6d65645f66696c6d6c656e6b65725f6672615f57696b6964617461; asc Artikler_med_filmlenker_fra_Wikidata;; |
| 7 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 1: len 1; hex 01; asc ;; |
| 8 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 2: len 25; hex 2b454b4f314333454b044d4f393f3f37314f3143011801dc17; asc +EKO1C3EK MO9??71O1C ;; |
| 9 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 3: len 4; hex 00058d34; asc 4;; |
| 10 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: InnoDB: record PHYSICAL RECORD: n_fields 4; compact format; info bits 0 |
| 11 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 0: len 30; hex 417274696b6c65725f6d65645f66696c6d6c656e6b65725f6672615f5769; asc Artikler_med_filmlenker_fra_Wi; (total 36 bytes); |
| 12 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 1: len 1; hex 01; asc ;; |
| 13 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 2: len 25; hex 2b454b4f314333454b044d4f393f3f37314f3143011801dc17; asc +EKO1C3EK MO9??71O1C ;; |
| 14 | Sep 17 17:23:58 dbstore2002 mysqld[3550]: 3: len 4; hex 00058d34; asc 4;; |
| 15 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: 2018-09-17 17:25:05 7fe2f76d0b00 InnoDB: Assertion failure in thread 140612790455040 in file row0ins.cc line 285 |
| 16 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: Failing assertion: *cursor->index->name == TEMP_INDEX_PREFIX |
| 17 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: We intentionally generate a memory trap. |
| 18 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: Submit a detailed bug report to https://jira.mariadb.org/ |
| 19 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: If you get repeated assertion failures or crashes, even |
| 20 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: immediately after the mysqld startup, there may be |
| 21 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: corruption in the InnoDB tablespace. Please refer to |
| 22 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: http://dev.mysql.com/doc/refman/5.6/en/forcing-innodb-recovery.html |
| 23 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: InnoDB: about forcing recovery. |
| 24 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: 180917 17:25:05 [ERROR] mysqld got signal 6 ; |
| 25 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: This could be because you hit a bug. It is also possible that this binary |
| 26 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: or one of the libraries it was linked against is corrupt, improperly built, |
| 27 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: or misconfigured. This error can also be caused by malfunctioning hardware. |
| 28 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: To report this bug, see https://mariadb.com/kb/en/reporting-bugs |
| 29 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: We will try our best to scrape up some info that will hopefully help |
| 30 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: diagnose the problem, but since we have already crashed, |
| 31 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: something is definitely wrong and this may fail. |
| 32 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: Server version: 10.1.35-MariaDB |
| 33 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: key_buffer_size=1048576 |
| 34 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: read_buffer_size=131072 |
| 35 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: max_used_connections=20 |
| 36 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: max_threads=252 |
| 37 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: thread_count=15 |
| 38 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: It is possible that mysqld could use up to |
| 39 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 554601 K bytes of memory |
| 40 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: Hope that's ok; if not, decrease some variables in the equation. |
| 41 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: Thread pointer: 0x7fdd7c42b008 |
| 42 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: Attempting backtrace. You can use the following information to find out |
| 43 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: where mysqld died. If you see no messages after this, something went |
| 44 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: terribly wrong... |
| 45 | Sep 17 17:25:05 dbstore2002 mysqld[3550]: stack_bottom = 0x7fe2f76cf838 thread_stack 0x48400 |
| 46 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: *** buffer overflow detected ***: /opt/wmf-mariadb101/bin/mysqld terminated |
| 47 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: ======= Backtrace: ========= |
| 48 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libc.so.6(+0x70bfb)[0x7fe3051a7bfb] |
| 49 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libc.so.6(__fortify_fail+0x37)[0x7fe3052301f7] |
| 50 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libc.so.6(+0xf7330)[0x7fe30522e330] |
| 51 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libc.so.6(+0xf916a)[0x7fe30523016a] |
| 52 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(my_addr_resolve+0xd8)[0x562689cabcd8] |
| 53 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(my_print_stacktrace+0x1bb)[0x562689c9502b] |
| 54 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(handle_fatal_signal+0x3bd)[0x5626897d62fd] |
| 55 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libpthread.so.0(+0x110c0)[0x7fe306a880c0] |
| 56 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libc.so.6(gsignal+0xcf)[0x7fe305169fff] |
| 57 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /lib/x86_64-linux-gnu/libc.so.6(abort+0x16a)[0x7fe30516b42a] |
| 58 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(+0x8dbd90)[0x562689b01d90] |
| 59 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(+0x8dde8b)[0x562689b03e8b] |
| 60 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(+0x8de2b4)[0x562689b042b4] |
| 61 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(+0x8ea4f7)[0x562689b104f7] |
| 62 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(+0x83f615)[0x562689a65615] |
| 63 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(_ZN7handler12ha_write_rowEPh+0x4cf)[0x5626897e0eff] |
| 64 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x72)[0x562689622af2] |
| 65 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x1216)[0x56268962ce66] |
| 66 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(_Z21mysql_execute_commandP3THD+0x3a52)[0x562689641bc2] |
| 67 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(_Z11mysql_parseP3THDPcjP12Parser_state+0x311)[0x5626896473b1] |
| 68 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(_ZN15Query_log_event14do_apply_eventEP14rpl_group_infoPKcj+0x131d)[0x5626898a2d5d] |
| 69 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(+0x39903b)[0x5626895bf03b] |
| 70 | Sep 17 17:25:06 dbstore2002 mysqld[3550]: /opt/wmf-mariadb101/bin/mysqld(handle_slave_sql+0x2bf3)[0x5626895ca2c3] |
| 71 | Sep 17 17:25:07 dbstore2002 systemd[1]: mariadb@s2.service: Main process exited, code=killed, status=6/ABRT |
| 72 | Sep 17 17:25:07 dbstore2002 systemd[1]: mariadb@s2.service: Unit entered failed state. |
| 73 | Sep 17 17:25:07 dbstore2002 systemd[1]: mariadb@s2.service: Failed with result 'signal'. |
| 74 | Sep 17 17:25:13 dbstore2002 systemd[1]: mariadb@s2.service: Service hold-off time over, scheduling restart. |
| 75 | Sep 17 17:25:13 dbstore2002 systemd[1]: Stopped mariadb database server. |
| 76 | Sep 17 17:25:13 dbstore2002 systemd[1]: Starting mariadb database server... |
| 77 | Sep 17 17:25:13 dbstore2002 mysqld[23213]: 2018-09-17 17:25:13 140666393803008 [Note] /opt/wmf-mariadb101/bin/mysqld (mysqld 10.1.35-MariaDB) starting as process 23213 ... |
| 78 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [ERROR] Plugin 'unix_socket' already installed |
| 79 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 7fef726f3900 InnoDB: Warning: Using innodb_locks_unsafe_for_binlog is DEPRECATED. This option may be removed in future releases. Please use READ COMMITTED transaction isolation level instead, see http://dev.mysql.com/doc/refman/5.6/en/set-transaction.html. |
| 80 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: Using mutexes to ref count buffer pool pages |
| 81 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: The InnoDB memory heap is disabled |
| 82 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins |
| 83 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier |
| 84 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: Compressed tables use zlib 1.2.3 |
| 85 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: Using Linux native AIO |
| 86 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: Using SSE crc32 instructions |
| 87 | Sep 17 17:25:14 dbstore2002 mysqld[23213]: 2018-09-17 17:25:14 140666393803008 [Note] InnoDB: Initializing buffer pool, size = 20.0G |
| 88 | Sep 17 17:25:15 dbstore2002 mysqld[23213]: 2018-09-17 17:25:15 140666393803008 [Note] InnoDB: Completed initialization of buffer pool |
| 89 | Sep 17 17:25:15 dbstore2002 mysqld[23213]: 2018-09-17 17:25:15 140666393803008 [Note] InnoDB: Highest supported file format is Barracuda. |
| 90 | Sep 17 17:25:15 dbstore2002 mysqld[23213]: 2018-09-17 17:25:15 140666393803008 [Note] InnoDB: Starting crash recovery from checkpoint LSN=34186413407073 |
| 91 | Sep 17 17:25:31 dbstore2002 mysqld[23213]: 2018-09-17 17:25:31 140666393803008 [Note] InnoDB: Processed 1650 .ibd/.isl files |
| 92 | Sep 17 17:25:32 dbstore2002 mysqld[23213]: 2018-09-17 17:25:32 140666393803008 [Note] InnoDB: Restoring possible half-written data pages from the doublewrite buffer... |
| 93 | Sep 17 17:25:32 dbstore2002 mysqld[23213]: 2018-09-17 17:25:32 140666393803008 [Note] InnoDB: Read redo log up to LSN=34186413537792 |
| 94 | Sep 17 17:25:47 dbstore2002 mysqld[23213]: 2018-09-17 17:25:47 140666393803008 [Note] InnoDB: To recover: 194027 pages from log |
| 95 | Sep 17 17:25:48 dbstore2002 mysqld[23213]: InnoDB: 1 transaction(s) which must be rolled back or cleaned up |
| 96 | Sep 17 17:25:48 dbstore2002 mysqld[23213]: InnoDB: in total 1 row operations to undo |
| 97 | Sep 17 17:25:48 dbstore2002 mysqld[23213]: InnoDB: Trx id counter is 43927584256 |
| 98 | Sep 17 17:25:48 dbstore2002 mysqld[23213]: 2018-09-17 17:25:48 140666393803008 [Note] InnoDB: Starting final batch to recover 193656 pages from redo log |
| 99 | Sep 17 17:26:02 dbstore2002 mysqld[23213]: 2018-09-17 17:26:02 140642936145664 [Note] InnoDB: To recover: 160469 pages from log |
| 100 | Sep 17 17:26:17 dbstore2002 mysqld[23213]: 2018-09-17 17:26:17 140642927752960 [Note] InnoDB: To recover: 116522 pages from log |
| 101 | Sep 17 17:26:32 dbstore2002 mysqld[23213]: 2018-09-17 17:26:32 140642919360256 [Note] InnoDB: To recover: 71081 pages from log |
| 102 | Sep 17 17:26:47 dbstore2002 mysqld[23213]: 2018-09-17 17:26:47 140642927752960 [Note] InnoDB: To recover: 33458 pages from log |
| 103 | Sep 17 17:26:59 dbstore2002 mysqld[23213]: InnoDB: In a MySQL replication slave the last master binlog file |
| 104 | Sep 17 17:26:59 dbstore2002 mysqld[23213]: InnoDB: position 0 713880055, file name db1024-bin.000534 |
| 105 | Sep 17 17:26:59 dbstore2002 mysqld[23213]: InnoDB: Last MySQL binlog file position 0 140307185, file name ./db2056-bin.002629 |
| 106 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140666393803008 [Note] InnoDB: 128 rollback segment(s) are active. |
| 107 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140642516723456 [Note] InnoDB: Starting in background the rollback of recovered transactions |
| 108 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140666393803008 [Note] InnoDB: Waiting for purge to start |
| 109 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140642516723456 [Note] InnoDB: To roll back: 1 transactions, 1 rows |
| 110 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140666393803008 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.39-83.1 started; log sequence number 34188143428820 |
| 111 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140642516723456 [Note] InnoDB: Rollback of trx with id 43927583911 completed |
| 112 | Sep 17 17:27:24 dbstore2002 mysqld[23213]: 2018-09-17 17:27:24 140642516723456 [Note] InnoDB: Rollback of non-prepared transactions completed |
| 113 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140642516723456 [Note] InnoDB: Dumping buffer pool(s) not yet started |
| 114 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 7fe9e33fe700 InnoDB: Loading buffer pool(s) from .//ib_buffer_pool |
| 115 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [Note] Plugin 'FEEDBACK' is disabled. |
| 116 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [Note] Recovering after a crash using tc.log |
| 117 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [Note] Starting crash recovery... |
| 118 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [Note] Crash recovery finished. |
| 119 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [Note] Server socket created on IP: '::'. |
| 120 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [ERROR] mysqld: Table './mysql/user' is marked as crashed and should be repaired |
| 121 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [Warning] Checking table: './mysql/user' |
| 122 | Sep 17 17:28:52 dbstore2002 mysqld[23213]: 2018-09-17 17:28:52 140666393803008 [ERROR] mysql.user: 1 client is using or hasn't closed the table properly |
| 123 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [ERROR] mysqld: Table './mysql/db' is marked as crashed and should be repaired |
| 124 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [Warning] Checking table: './mysql/db' |
| 125 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [ERROR] mysql.db: 1 client is using or hasn't closed the table properly |
| 126 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [ERROR] mysqld: Table './mysql/event' is marked as crashed and should be repaired |
| 127 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [Warning] Checking table: './mysql/event' |
| 128 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [ERROR] mysql.event: 1 client is using or hasn't closed the table properly |
| 129 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393242368 [Note] Event Scheduler: scheduler thread started with id 1 |
| 130 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [Warning] Neither --relay-log nor --relay-log-index were used; so replication may break when this MySQL server acts as a slave and has his hostname changed!! Please use '--log-basename=#' or '--relay-log=dbstore2002-relay-bin' to avoid this problem. |
| 131 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: 2018-09-17 17:28:53 140666393803008 [Note] /opt/wmf-mariadb101/bin/mysqld: ready for connections. |
| 132 | Sep 17 17:28:53 dbstore2002 mysqld[23213]: Version: '10.1.35-MariaDB' socket: '/run/mysqld/mysqld.s2.sock' port: 3312 MariaDB Server |
| 133 | Sep 17 17:28:53 dbstore2002 systemd[1]: Started mariadb database server. |
| 134 | Sep 17 17:31:32 dbstore2002 mysqld[23213]: 2018-09-17 17:31:32 7fe9e33fe700 InnoDB: Buffer pool(s) load completed at 180917 17:31:32 |
https://grafana.wikimedia.org/dashboard/db/mysql?orgId=1&from=1537192110814&to=1537213710814&var-dc=codfw%20prometheus%2Fops&var-server=dbstore2002&var-port=13312
https://grafana.wikimedia.org/dashboard/db/prometheus-machine-stats?orgId=1&var-server=dbstore2002&var-datasource=codfw%20prometheus%2Fops&from=1537192187956&to=1537213727956