Plotselinge MySQL-crash zonder duidelijke oorzaak

[vmsw]

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:

code:

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:

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:

# 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]