Nach Crash kein Starten mehr

[Werner S]

Hallo,

ich habe einen vServer. Der Hoster hat heute einen Umzug von OpenVZ auf LXC durchgeführt. Es kam zu einem MySQL Crash.

2018-08-08 13:41:59 139695811983104 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-08-08 13:41:59 139696482542144 [Note] Starting crash recovery...
2018-08-08 13:41:59 139696482542144 [Note] Crash recovery finished.
2018-08-08 13:41:59 139696482542144 [Note] Server socket created on IP: '::'.
2018-08-08 13:41:59 139696482542144 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.26-MariaDB-0+deb9u1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Debian 9.1
2018-08-08 13:42:02 139696481527552 [ERROR] mysqld: Table './postfix/mailbox' is marked as crashed and should be repaired
2018-08-08 13:42:02 139696481527552 [Warning] Checking table: './postfix/mailbox'
2018-08-08 13:43:28 139696481326848 [Note] /usr/sbin/mysqld: Normal shutdown

So sieht der Log für alle 3 Tabellen aus. Ich kann Ihn starten, dieser läuft auch 2-3 Minuten, crasht aber wieder.

Ich könnte den Server neuinstallieren, allerdings habe ich aufgrun eines Fehlers im Backupscript nur ein Backup von März. Leider erst heute aufgefallen.

Ich vermute das ich die Datenbanken einfach nur Reparieren müsste bzw. das wäre jetzt mein Schritt gewesen, aber ohne laufenden MySQL Server kein Backup.

Wie gehe ich am besten vor?

root@rs36:~# systemctl status mariadb.service
● mariadb.service - MariaDB database server
Loaded: loaded (/lib/systemd/system/mariadb.service; enabled; vendor preset: enabled)
Active: failed (Result: timeout) since Wed 2018-08-08 15:46:36 CEST; 5min ago
Process: 7550 ExecStart=/usr/sbin/mysqld $MYSQLD_OPTS $_WSREP_NEW_CLUSTER $_WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 7454 ExecStartPre=/bin/sh -c [ ! -e /usr/bin/galera_recovery ] && VAR= || VAR=`/usr/bin/galera_recovery`; [ $? -eq 0 ] && systemctl set-environment _WSREP_START_POSITION=$VAR || exit 1 (code=e
xited, status=0/SUCCESS)
Process: 7452 ExecStartPre=/bin/sh -c systemctl unset-environment _WSREP_START_POSITION (code=exited, status=0/SUCCESS)
Process: 7451 ExecStartPre=/usr/bin/install -m 755 -o mysql -g root -d /var/run/mysqld (code=exited, status=0/SUCCESS)
Main PID: 7550 (code=exited, status=0/SUCCESS)

Aug 08 15:45:02 rs36 systemd[1]: Starting MariaDB database server...
Aug 08 15:45:03 rs36 mysqld[7550]: 2018-08-08 15:45:03 140144992461376 [Note] /usr/sbin/mysqld (mysqld 10.1.26-MariaDB-0+deb9u1) starting as process 7550 ...
Aug 08 15:46:33 rs36 systemd[1]: mariadb.service: Start operation timed out. Terminating.
Aug 08 15:46:36 rs36 systemd[1]: Failed to start MariaDB database server.
Aug 08 15:46:36 rs36 systemd[1]: mariadb.service: Unit entered failed state.
Aug 08 15:46:36 rs36 systemd[1]: mariadb.service: Failed with result 'timeout'.

 

[Joe User]

Welche Engine?

 

[danton]

Es könnte auch sein, dass deine MariaDB einfach nur zu lange zum Starten benötigt und daher systemd den Start abbricht. Er meldet ja als Fehlergrund "Timeout".
Du könntest den mysqld direkt von der Kommando-Zeile mit entsprechenden Parametern starten und dann die Tabellen reparieren. Eine zweite Möglichkeit wäre, den Timeout für deinen mariadb.service hochzusetzen, indem du eine Override-Datei mit folgendem Inhalt erstellst:

[Service]
TimeoutStartSec=5min

Das setzt den Timeout von 30 Sekunden auf 5 Minuten. Ich einen MariaDB-Server, der hin und wieder mal den Start abgebrochen hat (virtueller Server), weil das Host-System unter bestimmten Bedingungen einfach mit den HDD-Zugriffen zu stark ausgelastet ist, so dass die 30 Sekunden nicht immer gereicht haben. Der o.g. Override hat in meinem Fall geholfen.

 

[Werner S]

Mit dem Timeout erhöhen brachte wohl "etwas" Erfolg.

In den Logs ist über ein Timeout nichts mehr zu finden, dafür jetzt andere Sachen wie zb. der nicht mehr vorhandene Slaveserver der beim Umzug durch den Hoster komplett geschottet wurde.

2018-08-08 22:22:26 140559349262080 [Note] /usr/sbin/mysqld: Normal shutdown

2018-08-08 22:22:26 140559349262080 [Note] Event Scheduler: Purging the queue. 0 events
2018-08-08 22:22:26 140558752261888 [Note] InnoDB: FTS optimize thread exiting.
2018-08-08 22:22:26 140559349262080 [Note] InnoDB: Starting shutdown...
2018-08-08 22:22:27 140559349262080 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-08-08 22:22:29 140559349262080 [Note] InnoDB: Shutdown completed; log sequence number 1600709
2018-08-08 22:22:29 140559349262080 [Note] /usr/sbin/mysqld: Shutdown complete

2018-08-08 22:22:33 140349138797120 [Note] InnoDB: innodb_empty_free_list_algorithm has been changed to legacy because of small buffer pool size. In order to use backoff, increase buffer pool at least up to 20MB.

2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Using mutexes to ref count buffer pool pages
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: The InnoDB memory heap is disabled
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Compressed tables use zlib 1.2.8
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Using Linux native AIO
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Using SSE crc32 instructions
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Completed initialization of buffer pool
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Highest supported file format is Barracuda.
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: 128 rollback segment(s) are active.
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Waiting for purge to start
2018-08-08 22:22:33 140349138797120 [Note] InnoDB: Percona XtraDB (http://www.percona.com) 5.6.36-82.1 started; log sequence number 1600709
2018-08-08 22:22:34 140349138797120 [Note] Plugin 'FEEDBACK' is disabled.
2018-08-08 22:22:34 140348479239936 [Note] InnoDB: Dumping buffer pool(s) not yet started
2018-08-08 22:22:34 140349138797120 [Note] Server socket created on IP: '::'.
2018-08-08 22:22:34 140349138360064 [Warning] InnoDB: Cannot open table mysql/gtid_slave_pos from the internal data dictionary of InnoDB though the .frm file for the table exists. See http://dev.mysql.com/doc/refman/5.6/en/innodb-troubleshooting.html for how you can resolve the problem.
2018-08-08 22:22:34 140349138360064 [Warning] Failed to load slave replication state from table mysql.gtid_slave_pos: 1932: Table 'mysql.gtid_slave_pos' doesn't exist in engine
2018-08-08 22:22:34 140349138797120 [Note] /usr/sbin/mysqld: ready for connections.
Version: '10.1.26-MariaDB-0+deb9u1' socket: '/var/run/mysqld/mysqld.sock' port: 3306 Debian 9.1
2018-08-08 22:24:03 140349137757952 [Note] /usr/sbin/mysqld: Normal shutdown

2018-08-08 22:24:03 140349137757952 [Note] Event Scheduler: Purging the queue. 0 events
2018-08-08 22:24:03 140348533741312 [Note] InnoDB: FTS optimize thread exiting.
2018-08-08 22:24:03 140349137757952 [Note] InnoDB: Starting shutdown...
2018-08-08 22:24:04 140349137757952 [Note] InnoDB: Waiting for page_cleaner to finish flushing of buffer pool
2018-08-08 22:24:05 140349137757952 [Note] InnoDB: Shutdown completed; log sequence number 1600719
2018-08-08 22:24:05 140349137757952 [Note] /usr/sbin/mysqld: Shutdown complete