Mijn vraag
Vanwaar is mijn MySQL-server gecrashed en hoe kan ik dit voorkómen in toekomst?
Relevante software en hardware die ik gebruik
Ubuntu 18.04 LTS
MySQL 5.7.33
Wat ik al gevonden of geprobeerd heb:
Logboeken bekijken en op basis van foutmelding zoeken naar mogelijke oorzaak. Ik kom geen mensen met gelijke bug tegen die hiermee te maken hebben. Wel dingen met apparmor uiteraard, maar niet vergelijkbaar aan deze, waardoor ik nog geen relatie tot een potentiëel probleem kan vinden. Ik weet niet waar te beginnen/zoeken.
MySQL is al enkele maanden niet bijgewerkt en er zijn geen aanwijzingen in monitoring dat er piekbelasting was (cpu, hvh connecties, netwerkverkeer etc.) of geheugentekort optrad. Het was lijkt "opeens" te zijn. De andere 3 mysql-servers hebben dit ook nog nooit gehad.
Overigens herstartte hij zichzelf en sindsdien werkt alles weer. Paar corrupte databasetabellen die hijzelf wist te repareren.
syslog:
Overigens zie ik het pad niet staan in apparmor-configuratie, geen idee of dit wel bedoeling zou zijn, maar gekke is dan 'waarom' dit plots nodig is na jarenlang geen problemen en al paar maanden geen mysql-udpate (?).
/etc/apparmor.d/usr.sbin.mysqld
Vanwaar is mijn MySQL-server gecrashed en hoe kan ik dit voorkómen in toekomst?
Relevante software en hardware die ik gebruik
Ubuntu 18.04 LTS
MySQL 5.7.33
Wat ik al gevonden of geprobeerd heb:
Logboeken bekijken en op basis van foutmelding zoeken naar mogelijke oorzaak. Ik kom geen mensen met gelijke bug tegen die hiermee te maken hebben. Wel dingen met apparmor uiteraard, maar niet vergelijkbaar aan deze, waardoor ik nog geen relatie tot een potentiëel probleem kan vinden. Ik weet niet waar te beginnen/zoeken.
MySQL is al enkele maanden niet bijgewerkt en er zijn geen aanwijzingen in monitoring dat er piekbelasting was (cpu, hvh connecties, netwerkverkeer etc.) of geheugentekort optrad. Het was lijkt "opeens" te zijn. De andere 3 mysql-servers hebben dit ook nog nooit gehad.
Overigens herstartte hij zichzelf en sindsdien werkt alles weer. Paar corrupte databasetabellen die hijzelf wist te repareren.
syslog:
code:
1
2
3
4
5
6
7
8
| Apr 1 12:05:01 db13 kernel: [7793383.775592] audit: type=1400 audit(1617271501.564:14): apparmor="DENIED" operation="open" profile="/usr/sbin/mysqld" name="/proc/21384/task/28026/mem" pid=21384 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=1005 ouid=1005 Apr 1 12:05:04 db13 systemd[1]: mysql.service: Main process exited, code=exited, status=2/INVALIDARGUMENT Apr 1 12:05:04 db13 systemd[1]: mysql.service: Failed with result 'exit-code'. Apr 1 12:05:04 db13 systemd[1]: mysql.service: Service hold-off time over, scheduling restart. Apr 1 12:05:04 db13 systemd[1]: mysql.service: Scheduled restart job, restart counter is at 1. Apr 1 12:05:04 db13 systemd[1]: Stopped MySQL Community Server. Apr 1 12:05:04 db13 systemd[1]: Starting MySQL Community Server... Apr 1 12:05:31 db13 systemd[1]: Started MySQL Community Server. |
code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
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
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
| 10:05:01 UTC - mysqld got signal 11 ; This could be because you hit a bug. It is also possible that this binary or 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 information collection process might fail. key_buffer_size=16777216 read_buffer_size=131072 max_used_connections=171 max_threads=250 thread_count=116 connection_count=115 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 115729 K bytes of memory Hope that's ok; if not, decrease some variables in the equation. Thread pointer: 0x7f4cec5be1e0 Attempting backtrace. You can use the following information to find out where mysqld died. If you see no messages after this, something went terribly wrong... stack_bottom = 7f4e52315e50 thread_stack 0x40000 /usr/sbin/mysqld(my_print_stacktrace+0x3b)[0xeb8fdb] /usr/sbin/mysqld(handle_fatal_signal+0x377)[0x77bb47] /lib/x86_64-linux-gnu/libpthread.so.0(+0x12980)[0x7f53aa1d0980] /usr/sbin/mysqld(my_hash_sort_bin+0x20)[0x1290350] /usr/sbin/mysqld[0xe987ed] /usr/sbin/mysqld(my_hash_insert+0x198)[0xe98fa8] /usr/sbin/mysqld(_ZN11Query_cache11store_queryEP3THDP10TABLE_LIST+0x400)[0xc1f6c0] /usr/sbin/mysqld(_Z12handle_queryP3THDP3LEXP12Query_resultyy+0x1f9)[0xcaca29] /usr/sbin/mysqld[0x746966] /usr/sbin/mysqld(_Z21mysql_execute_commandP3THDb+0x48ca)[0xc6d23a] /usr/sbin/mysqld(_Z11mysql_parseP3THDP12Parser_state+0x3a5)[0xc6f8a5] /usr/sbin/mysqld(_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command+0xaf6)[0xc70456] /usr/sbin/mysqld(_Z10do_commandP3THD+0x220)[0xc71f40] /usr/sbin/mysqld(handle_connection+0x298)[0xd37c18] /usr/sbin/mysqld(pfs_spawn_thread+0x154)[0x121e9d4] /lib/x86_64-linux-gnu/libpthread.so.0(+0x76db)[0x7f53aa1c56db] /lib/x86_64-linux-gnu/libc.so.6(clone+0x3f)[0x7f53a95af71f] Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (7f4cec024650): is an invalid pointer Connection ID (thread ID): 77698920 Status: NOT_KILLED The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains information that should help you find out what is causing the crash. 2021-04-01T10:05:04.973902Z 0 [Warning] Could not increase number of max_open_files to more than 5000 (request: 10240) 2021-04-01T10:05:04.974266Z 0 [Warning] Changed limits: table_open_cache: 2370 (requested 4000) 2021-04-01T10:05:05.200035Z 0 [Warning] option 'slow_query_log': boolean value '/var/log/mysql/mysql-slow.log' wasn't recognized. Set to OFF. 2021-04-01T10:05:05.200084Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details). 2021-04-01T10:05:05.200120Z 0 [Warning] 'NO_ZERO_DATE', 'NO_ZERO_IN_DATE' and 'ERROR_FOR_DIVISION_BY_ZERO' sql modes should be used with strict mode. They will be merged with strict mode in a future release. 2021-04-01T10:05:05.202734Z 0 [Note] /usr/sbin/mysqld (mysqld 5.7.33-0ubuntu0.18.04.1-log) starting as process 30754 ... 2021-04-01T10:05:05.208780Z 0 [Note] InnoDB: PUNCH HOLE support available 2021-04-01T10:05:05.208805Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins 2021-04-01T10:05:05.208811Z 0 [Note] InnoDB: Uses event mutexes 2021-04-01T10:05:05.208817Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier 2021-04-01T10:05:05.208822Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.11 2021-04-01T10:05:05.208831Z 0 [Note] InnoDB: Using Linux native AIO 2021-04-01T10:05:05.209853Z 0 [Note] InnoDB: Number of pools: 1 2021-04-01T10:05:05.210245Z 0 [Note] InnoDB: Not using CPU crc32 instructions 2021-04-01T10:05:05.212984Z 0 [Note] InnoDB: Initializing buffer pool, total size = 20G, instances = 20, chunk size = 128M 2021-04-01T10:05:07.145024Z 0 [Note] InnoDB: Completed initialization of buffer pool 2021-04-01T10:05:07.469471Z 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority(). 2021-04-01T10:05:07.484263Z 0 [Note] InnoDB: Highest supported file format is Barracuda. 2021-04-01T10:05:07.693907Z 0 [Note] InnoDB: Log scan progressed past the checkpoint lsn 945919095417 2021-04-01T10:05:08.127402Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 945924338176 2021-04-01T10:05:08.236873Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 945929581056 2021-04-01T10:05:08.338605Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 945934823936 2021-04-01T10:05:08.430227Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 945940066816 2021-04-01T10:05:08.488032Z 0 [Note] InnoDB: Doing recovery: scanned up to log sequence number 945942154567 2021-04-01T10:05:08.488697Z 0 [Note] InnoDB: Database was not shutdown normally! 2021-04-01T10:05:08.488710Z 0 [Note] InnoDB: Starting crash recovery. 2021-04-01T10:05:08.677988Z 0 [Note] InnoDB: Transaction 8061128555 was in the XA prepared state. 2021-04-01T10:05:08.684340Z 0 [Note] InnoDB: 1 transaction(s) which must be rolled back or cleaned up in total 0 row operations to undo 2021-04-01T10:05:08.684357Z 0 [Note] InnoDB: Trx id counter is 8061128960 2021-04-01T10:05:08.684496Z 0 [Note] InnoDB: Starting an apply batch of log records to the database... InnoDB: Progress in percent: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 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 2021-04-01T10:05:10.456359Z 0 [Note] InnoDB: Apply batch completed 2021-04-01T10:05:10.456417Z 0 [Note] InnoDB: Last MySQL binlog file position 0 46922584, file name mysql-bin.012671 2021-04-01T10:05:31.006475Z 0 [Note] InnoDB: Starting in background the rollback of uncommitted transactions 2021-04-01T10:05:31.006524Z 0 [Note] InnoDB: Rollback of non-prepared transactions completed 2021-04-01T10:05:31.006871Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1" 2021-04-01T10:05:31.006902Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables 2021-04-01T10:05:31.006963Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ... 2021-04-01T10:05:31.012547Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB. 2021-04-01T10:05:31.016397Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active. 2021-04-01T10:05:31.016425Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active. 2021-04-01T10:05:31.016798Z 0 [Note] InnoDB: Waiting for purge to start 2021-04-01T10:05:31.066927Z 0 [Note] InnoDB: 5.7.33 started; log sequence number 945942154567 2021-04-01T10:05:31.066952Z 0 [Note] InnoDB: page_cleaner: 1000ms intended loop took 23598ms. The settings might not be optimal. (flushed=0 and evicted=0, during the time.) 2021-04-01T10:05:31.067228Z 0 [Note] InnoDB: Loading buffer pool(s) from /mysql/mysql/ib_buffer_pool 2021-04-01T10:05:31.069429Z 0 [Note] Plugin 'FEDERATED' is disabled. 2021-04-01T10:05:31.086995Z 0 [Note] Recovering after a crash using /mysqllog/mysql-bin 2021-04-01T10:05:31.234381Z 0 [Note] Starting crash recovery... 2021-04-01T10:05:31.234442Z 0 [Note] InnoDB: Starting recovery for XA transactions... 2021-04-01T10:05:31.234451Z 0 [Note] InnoDB: Transaction 8061128555 in prepared state after recovery 2021-04-01T10:05:31.234457Z 0 [Note] InnoDB: Transaction contains changes to 1 rows 2021-04-01T10:05:31.234463Z 0 [Note] InnoDB: 1 transactions in prepared state after recovery 2021-04-01T10:05:31.234468Z 0 [Note] Found 1 prepared transaction(s) in InnoDB 2021-04-01T10:05:31.235026Z 0 [Note] Crash recovery finished. 2021-04-01T10:05:31.321941Z 0 [Note] Skipping generation of SSL certificates as options related to SSL are specified. 2021-04-01T10:05:31.324198Z 0 [Warning] CA certificate /etc/mysql/cacert.pem is self signed. 2021-04-01T10:05:31.324673Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory. 2021-04-01T10:05:31.325132Z 0 [Note] Server hostname (bind-address): '192.168.0.97'; port: 3306 2021-04-01T10:05:31.325145Z 0 [Note] - '192.168.0.97' resolves to '192.168.0.97'; 2021-04-01T10:05:31.325180Z 0 [Note] Server socket created on IP: '192.168.0.97'. 2021-04-01T10:05:31.345678Z 0 [Note] Failed to start slave threads for channel '' 2021-04-01T10:05:31.372580Z 0 [Note] Event Scheduler: Loaded 3 events 2021-04-01T10:05:31.372769Z 1 [Note] Event Scheduler: scheduler thread started with id 1 2021-04-01T10:05:31.372944Z 0 [Note] /usr/sbin/mysqld: ready for connections. Version: '5.7.33-0ubuntu0.18.04.1-log' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu) 2021-04-01T10:05:35.809918Z 279 [ERROR] /usr/sbin/mysqld: Table './dbnaam/data_print_cue' is marked as crashed and should be repaired 2021-04-01T10:05:35.810121Z 279 [Warning] Checking table: './dbnaam/data_print_cue' ... diverse kapotte tabellen herstellen ... |
Overigens zie ik het pad niet staan in apparmor-configuratie, geen idee of dit wel bedoeling zou zijn, maar gekke is dan 'waarom' dit plots nodig is na jarenlang geen problemen en al paar maanden geen mysql-udpate (?).
/etc/apparmor.d/usr.sbin.mysqld
code:
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
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
| # vim:syntax=apparmor # Last Modified: Tue Feb 09 15:28:30 2016 #include <tunables/global> /usr/sbin/mysqld { #include <abstractions/base> #include <abstractions/nameservice> #include <abstractions/user-tmp> #include <abstractions/mysql> #include <abstractions/winbind> # Allow system resource access /proc/*/status r, /sys/devices/system/cpu/ r, /sys/devices/system/node/ r, /sys/devices/system/node/** r, capability sys_resource, capability dac_override, capability dac_read_search, capability setuid, capability setgid, # Allow network access network tcp, /etc/hosts.allow r, /etc/hosts.deny r, # Allow config access /etc/mysql/** r, # Allow pid, socket, socket lock file access /var/run/mysqld/mysqld.pid rw, /var/run/mysqld/mysqld.sock rw, /var/run/mysqld/mysqld.sock.lock rw, /run/mysqld/mysqld.pid rw, /run/mysqld/mysqld.sock rw, /run/mysqld/mysqld.sock.lock rw, # Allow systemd notify messages /{,var/}run/systemd/notify w, # Allow execution of server binary /usr/sbin/mysqld mr, /usr/sbin/mysqld-debug mr, # Allow plugin access /usr/lib/mysql/plugin/ r, /usr/lib/mysql/plugin/*.so* mr, # Allow error msg and charset access /usr/share/mysql/ r, /usr/share/mysql/** r, # Allow data dir access /var/lib/mysql/ r, /var/lib/mysql/** rwk, # Allow data files dir access /var/lib/mysql-files/ r, /var/lib/mysql-files/** rwk, # Allow keyring dir access /var/lib/mysql-keyring/ r, /var/lib/mysql-keyring/** rwk, # Allow log file access /var/log/mysql.err rw, /var/log/mysql.log rw, /var/log/mysql/ r, /var/log/mysql/** rw, # Allow read access to OpenSSL config /etc/ssl/openssl.cnf r, # Site-specific additions and overrides. See local/README for details. #include <local/usr.sbin.mysqld> } |
[ Voor 18% gewijzigd door vmsw op 01-04-2021 15:44 ]