Moodle: MySQL crashed and cannot be started again

Zeitgeist 2011-11-13 13:32:17 UTC #1

Hi there,

my bitnami moodle has been running stable for a few weeks now on an amazon t1.micro instance. After trying to use moodle with a big class (27 users) the mysql-db crashed. That happened before, but a server restart fixed everything. Not this time.

Moodle still can´t connect to the database and I also can´t restart mysql with ./ctlscript.sh start mysql I´ll get the error message:

111113 13:10:33 mysqld_safe Logging to '/opt/bitnami/mysql/data/mysqld.log'.




111113 13:10:33 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data




111113 13:10:38 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-2 28-27-28.pid ended




/opt/bitnami/mysql/scripts/ctl.sh : mysql  could not be started

Here´s the mysql-error-log:

  File: mysqld.log        Line 324 Col 0     24880 bytes                                                                                                   100%




    Killed




111111 12:41:40 mysqld_safe Number of processes running now: 0




111111 12:41:56 mysqld_safe mysqld restarted




111111 12:42:40 [Note] Plugin 'FEDERATED' is disabled.




111111 12:42:40  InnoDB: Initializing buffer pool, size = 8.0M




111111 12:42:40  InnoDB: Completed initialization of buffer pool




InnoDB: Log scan progressed past the checkpoint lsn 0 209083665




111111 12:42:40  InnoDB: Database was not shut down normally!




InnoDB: Starting crash recovery.




InnoDB: Reading tablespace information from the .ibd files...




InnoDB: Restoring possible half-written data pages from the doublewrite




InnoDB: buffer...




InnoDB: Doing recovery: scanned up to log sequence number 0 209087217




111111 12:42:41  InnoDB: Starting an apply batch of log records to the database...




InnoDB: Progress in percents: 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 4




6 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




InnoDB: Apply batch completed




111111 12:42:41  InnoDB: Started; log sequence number 0 209087217




111111 12:42:42 [Note] Event Scheduler: Loaded 0 events




111111 12:42:42 [Note] /opt/bitnami/mysql/bin/mysqld.bin: ready for connections.




Version: '5.1.56'  socket: '/opt/bitnami/mysql/tmp/mysql.sock'  port: 3306  MySQL Community Server (GPL)




111112 20:56:43 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data




111112 20:56:43 [Note] Plugin 'FEDERATED' is disabled.




111112 20:56:43  InnoDB: Initializing buffer pool, size = 8.0M




111112 20:56:43  InnoDB: Completed initialization of buffer pool




InnoDB: The log sequence number in ibdata files does not match




InnoDB: the log sequence number in the ib_logfiles!




111112 20:56:43  InnoDB: Database was not shut down normally!




InnoDB: Starting crash recovery.




InnoDB: Reading tablespace information from the .ibd files...




InnoDB: Restoring possible half-written data pages from the doublewrite




InnoDB: buffer...




111112 20:56:44  InnoDB: Started; log sequence number 0 209087415




111112 20:56:44 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use




111112 20:56:44 [ERROR] Do you already have another mysqld server running on port: 3306 ?




111112 20:56:44 [ERROR] Aborting

111112 20:56:44 InnoDB: Starting shutdown...
111112 20:56:49 InnoDB: Shutdown completed; log sequence number 0 209087415
111112 20:56:49 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111112 20:56:49 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended
111112 21:16:50 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111112 21:16:50 [Note] Plugin 'FEDERATED' is disabled.
111112 21:16:50 InnoDB: Initializing buffer pool, size = 8.0M
111112 21:16:50 InnoDB: Completed initialization of buffer pool
111112 21:16:50 InnoDB: Started; log sequence number 0 209087415
111112 21:16:50 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use
111112 21:16:50 [ERROR] Do you already have another mysqld server running on port: 3306 ?
111112 21:16:50 [ERROR] Aborting

111112 21:16:50 InnoDB: Starting shutdown...
111112 21:16:56 InnoDB: Shutdown completed; log sequence number 0 209087415
111112 21:16:56 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111112 21:16:56 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended
111112 21:35:52 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111112 21:35:52 [Note] Plugin 'FEDERATED' is disabled.
111112 21:35:52 InnoDB: Initializing buffer pool, size = 8.0M
111112 21:38:36 InnoDB: Shutdown completed; log sequence number 0 209087415
111112 21:38:36 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111112 21:38:36 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended
111112 21:46:01 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111112 21:46:01 [Note] Plugin 'FEDERATED' is disabled.
111112 21:46:01  InnoDB: Initializing buffer pool, size = 8.0M
111112 21:46:01  InnoDB: Completed initialization of buffer pool
111112 21:46:01  InnoDB: Started; log sequence number 0 209087415
111112 21:46:01 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use
111112 21:46:01 [ERROR] Do you already have another mysqld server running on port: 3306 ?
111112 21:46:01 [ERROR] Aborting

111112 21:46:01  InnoDB: Starting shutdown...
111112 21:46:06  InnoDB: Shutdown completed; log sequence number 0 209087415
111112 21:46:06 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111112 21:46:06 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended
111112 22:05:04 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111112 22:05:04 [Note] Plugin 'FEDERATED' is disabled.
111112 22:05:04  InnoDB: Initializing buffer pool, size = 8.0M
111112 22:05:04  InnoDB: Completed initialization of buffer pool
111112 22:05:04  InnoDB: Started; log sequence number 0 209087415
111112 22:05:04 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use
111112 22:05:04 [ERROR] Do you already have another mysqld server running on port: 3306 ?
111112 22:05:04 [ERROR] Aborting

111112 22:05:04  InnoDB: Starting shutdown...
111112 22:05:09  InnoDB: Shutdown completed; log sequence number 0 209087415
111112 22:05:09 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111112 22:05:09 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended
111113 02:54:31 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111113  2:54:31 [Note] Plugin 'FEDERATED' is disabled.
111113  2:54:31  InnoDB: Initializing buffer pool, size = 8.0M
111113  2:54:31  InnoDB: Completed initialization of buffer pool
111113  2:54:32  InnoDB: Started; log sequence number 0 209087415
111113  2:54:32 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use
111113  2:54:32 [ERROR] Do you already have another mysqld server running on port: 3306 ?
111113  2:54:32 [ERROR] Aborting

111113  2:54:32  InnoDB: Starting shutdown...
111113  2:54:37  InnoDB: Shutdown completed; log sequence number 0 209087415
111113  2:54:37 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111113 02:54:37 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended
111113 13:10:33 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111113 13:10:33 [Note] Plugin 'FEDERATED' is disabled.
111113 13:10:33  InnoDB: Initializing buffer pool, size = 8.0M
111113 13:10:33  InnoDB: Completed initialization of buffer pool
111113 13:10:33  InnoDB: Started; log sequence number 0 209087415
111113 13:10:33 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use
111113 13:10:33 [ERROR] Do you already have another mysqld server running on port: 3306 ?
111113 13:10:33 [ERROR] Aborting

111113 13:10:33  InnoDB: Starting shutdown...
111113 13:10:38  InnoDB: Shutdown completed; log sequence number 0 209087415
111113 13:10:38 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111113 13:10:38 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended

beltran 2011-11-13 16:36:16 UTC #2

It seems that you have another instance running:

Can't start server: Bind on TCP/IP port: Address already in use

Could you check if there is another mysql process running?

ps aux | grep mysql




kill -9 [PID of the mysql process]

Then try to start the database again

Zeitgeist 2011-11-13 19:36:22 UTC #3

Just tried it, here´s what I got:

root@ip-***:/home/bitnami# ps aux | grep mysql




mysql     3137  0.1  2.7 145476 18084 ?        Ssl  19:30   0:00 /usr/sbin/mysqld




root      3205  0.0  0.1   3348   812 pts/0    S+   19:31   0:00 grep --color=auto mysql




root@ip-***:/home/bitnami# kill -9 3137




root@ip-***:/home/bitnami# kill -9 3205




bash: kill: (3205) - No such process

The value in the second column is the PID? I´m pretty much a linux beginner. Killing the first process (the second one seems to be not existent) didn´t help. I still cant launch mysql via the ./ctlscript.

Zeitgeist 2011-11-13 19:53:05 UTC #4

This is what I got after trying to start mysql, with nearly a minute passing till the "mysql could not be started":

root@:/opt/bitnami# 111113 19:46:12 mysqld_safe Logging to '/opt/bitnami/mysql/data/mysqld.log'.
111113 19:46:12 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data
111113 19:46:17 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-.pid ended
/opt/bitnami/mysql/scripts/ctl.sh : mysql could not be started

beltran 2011-11-14 09:16:06 UTC #5

could you post the latest lines that you can find in the mysql log file?

Zeitgeist 2011-11-14 10:01:55 UTC #6

I´m in class right now and can´t access the server via SSH from here. But I looked through the Amazon-Server-System-Log and found some sql-entries, maybe these will help. As soon as I´m back home I will post the last lines of the mysql-Logfile.

Amazon-Server-System-Log when MySQL still worked:

landscape-client is not configured, please run landscape-config.




111104 13:54:09 mysqld_safe Logging to '/opt/bitnami/mysql/data/mysqld.log'.




111104 13:54:10 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data




The disk drive for /dev/sda3 is not ready yet or not present




Continue to wait; or Press S to skip mounting or M for manual recovery




/opt/bitnami/mysql/scripts/ctl.sh : mysql  started at port 3306




Syntax OK

Amazon-Server-System-Log when MySQL started to fail:

landscape-client is not configured, please run landscape-config.




111112 20:56:43 mysqld_safe Logging to '/opt/bitnami/mysql/data/mysqld.log'.




111112 20:56:43 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data




The disk drive for /dev/sda3 is not ready yet or not present




Continue to wait; or Press S to skip mounting or M for manual recovery




111112 20:56:49 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended




/opt/bitnami/mysql/scripts/ctl.sh : mysql  could not be started




Syntax OK

Zeitgeist 2011-11-14 10:14:24 UTC #7

Found another thing: The average CPU Utilization got up after the crash happened and stayed at ca. 40% till I restarted the server the day after tomorrow. See here:

http://i.imgur.com/H0QwP.png

Zeitgeist 2011-11-14 15:47:52 UTC #8

Here are the last lines of the mysqld.log-file:

111113 19:46:12 mysqld_safe Starting mysqld.bin daemon with databases from /opt/bitnami/mysql/data




111113 19:46:12 [Note] Plugin 'FEDERATED' is disabled.




111113 19:46:12  InnoDB: Initializing buffer pool, size = 8.0M




111113 19:46:12  InnoDB: Completed initialization of buffer pool




111113 19:46:12  InnoDB: Started; log sequence number 0 209087415




111113 19:46:12 [ERROR] Can't start server: Bind on TCP/IP port: Address already in use




111113 19:46:12 [ERROR] Do you already have another mysqld server running on port: 3306 ?




111113 19:46:12 [ERROR] Aborting

111113 19:46:12 InnoDB: Starting shutdown...
111113 19:46:17 InnoDB: Shutdown completed; log sequence number 0 209087415
111113 19:46:17 [Note] /opt/bitnami/mysql/bin/mysqld.bin: Shutdown complete

111113 19:46:17 mysqld_safe mysqld from pid file /opt/bitnami/mysql/data/ip-10-228-27-28.pid ended

beltran 2011-11-14 15:48:17 UTC #9

It is strange. Check the mysqld.log file when you have a chance and see if you continue having the following error:

[ERROR] Can't start server: Bind on TCP/IP port: Address already in use

Did you install any software in the machine?

Zeitgeist 2011-11-14 18:12:39 UTC #10

I´m getting this error every time I restart the whole server. I installed two moodle-plugins a few weeks ago, but moodle ran without problems all the time. The problems started after the mysql-crash when a big class tried to login to my moodle.

beltran 2011-11-14 19:07:48 UTC #11

It is strange, it should not be any other server running in that port. Try to do kill all the msyql processes that are running in the machine, remove the pid file "$ sudo rm /opt/bitnami/mysql/data/*.pid" and start the database again:

$ sudo /opt/bitnami/ctlscript.sh start mysql

Zeitgeist 2011-11-14 19:58:44 UTC #12

It didn´t work. In the /opt/bitnami/mysql/data directory isn´t any .pid-file, so I couldn´t delete one. But this strange message in the log always tells me something about this file, see

http://imageshack.us/photo/my-images/580/bild000w.png/

Any other ideas? I´m willing to do more drastic things (reinstall mysql?) to get moodle working again. Made big changes to a course and don´t have a backup.

Cannot start MySQL after installing MediaWiki Extension

beltran 2011-11-15 13:15:36 UTC #13

Another suggestion is to start a new instance of the same BitNami Moodle AMI and move the mysql/data/* files to the new one. It is not the proper way to restore the backup but it could work. Once you overwrite the files, change the mysql/data permissions and start the database:

$ sudo chown mysql:mysql /opt/bitnami/msyql/data
$ sudo /opt/bitnami/ctlscript.sh start mysql

Zeitgeist 2011-11-16 18:33:45 UTC #14

With "start a new instance of the same BitNami Moodle AMI" You mean via "Instance Actions" and "Launch more like this" in the AWS-interface? Or another fresh install with an Bitnami Amazon Machine Image?

beltran 2011-11-17 11:01:20 UTC #15

I mean to start a new one, a fresh installation to migrate your data.

[Solved] MySQL keeps on dying on me

Zeitgeist 2011-11-23 15:25:35 UTC #16

Alright, after a lot of pain I got my data back. Started a fresh new instance, copied the /opt/bitnami/mysql/data from my old server, changed permissions. Result: Still database-error when trying to start moodle, but the mysql-server was running.

Tried to fix the mysql-db, failed. Tried to make a db-backup via phpmyadmin, failed. Nailed down table "mdl_log" as the trouble-maker (backup canceled there). Made a new backup without that table, working. Made another fresh instance, copied the backup, finally working.

Now I have proper backups for the next db-crash. Trying to find the cause now.

beltran 2011-11-23 15:34:50 UTC #17

I'm glad to hear that.

system 2017-11-16 12:50:26 UTC #18

Bitnami provides free all-in-one installers, virtual machines and cloud images for popular open source applications. Get them now!