[solved?] mysqld [fail] on startup?

[chconnor]

I've seen some other posts related to mysql issues on the 9.04 -> 9.10 upgrade, but couldn't solve this exactly...

On startup, mysqld shows a "fail".

In /var/log/syslog, i see:

Nov 14 17:31:16 machinename /etc/init.d/mysql[1436]: 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
Nov 14 17:31:16 machinename /etc/init.d/mysql[1436]: /etc/rc2.d/S19mysql: line 75: /usr/bin/mysqladmin: No such file or directory
Nov 14 17:31:16 machinename /etc/init.d/mysql[1436]:

Indeed, no such binary at /usr/bin.

"which mysqladmin" returns nothing.

/usr/sbin has mysqld and mysqld-akonadi

In synaptic, i see the following mysql-related packages installed:

mysql-common
libqt4-sql-mysql
mysql-server-core-5.1
libmysqlclient15off
libmysqlclient16

apt-get check shows nothing amiss.

I haven't noticed any functionality problems, but i don't use much of the desktop environment stuff. It looks like that script may just be "pinging" the DB to make sure it's alive? Perhaps it's safe to remove from rc2.d?

Any thoughts? Thanks!

-c

[jankushka]

Re: mysqld [fail] on startup?

not sure what the problem could be.
unfortunately i don't have much time to experiment right now.

tough nobody's picked this one up, so...

here a few things that can hopefully help...

i have mysql 5.1 installed for several purposes and have no problems with it.
packages i have installed:

root@crisps# dpkg-query -l '*mysql*' | grep ^ii
ii libdbd-mysql-perl           4.011-1ubuntu1               A Perl5 database interface to the MySQL data
ii libmysql-java             5.1.6+dfsg-1ubuntu2            Java database (JDBC) driver for MySQL
ii libmysqlclient16           5.1.37-1ubuntu5              MySQL database client library
ii libqt4-sql-mysql           4.5.3really4.5.2-0ubuntu1         Qt 4 MySQL database driver
ii mysql-client             5.1.37-1ubuntu5              MySQL database client (metapackage depending
ii mysql-client-5.1           5.1.37-1ubuntu5              MySQL database client binaries
ii mysql-common             5.1.37-1ubuntu5              MySQL database common files (e.g. /etc/mysql
ii mysql-server             5.1.37-1ubuntu5              MySQL database server (metapackage depending
ii mysql-server-5.1           5.1.37-1ubuntu5              MySQL database server binaries
ii mysql-server-core-5.1         5.1.37-1ubuntu5              MySQL database core server files
ii php5-mysql              5.2.10.dfsg.1-2ubuntu6.1          MySQL module for php5

Indeed, no such binary at /usr/bin.

"which mysqladmin" returns nothing.

the which command only looks for stuff in directories defined in the path env var.
should this binary be elsewhere, you wouldn't find it with that command.

i find mysqladmin in the mysql-client package

dpkg-query -S /usr/bin/mysqladmin
mysql-client-5.1: /usr/bin/mysqladmin

it might therefore just be that things ended up in different packages.
though they weren't supposed to.
resulting in having to install the client stuff even if you only really need/want the server stuff.



hth

[chconnor]

Re: mysqld [fail] on startup?

Thanks! I'm installing mysql-client now and i'll see if that clears things up... will report back...

-c

[chconnor]

Re: mysqld [fail] on startup?

Thanks for the assistance... unfortunately, still not working. The error has changed, now. Seems like mysqld isn't actually starting?

/etc/mysql/my.cnf seems to point to /var/run/mysqld/mysqld.sock as the socket location, and the errors shown in the log seem to indicate that this socket is not present:

2009-11-19 21:00:53 mymachine /etc/init.d/mysql[1440] 0 processes alive and '/usr/bin/mysqladmin --defaults-file=/etc/mysql/debian.cnf ping' resulted in
2009-11-19 21:00:53 mymachine /etc/init.d/mysql[1440] #007/usr/bin/mysqladmin: connect to server at 'localhost' failed
2009-11-19 21:00:53 mymachine /etc/init.d/mysql[1440] error: 'Can't connect to local MySQL server through socket '/var/run/mysqld/mysqld.sock' (2)'
2009-11-19 21:00:53 mymachine /etc/init.d/mysql[1440] Check that mysqld is running and that the socket: '/var/run/mysqld/mysqld.sock' exists!

...indeed the socket is not there (even /var/run/mysqld is not there).

ps -eF shows that mysqld is not running.

Previously in the log, I see:

2009-11-19 21:00:03 caseylinux kernel [ 3.419482] type=1505 audit(1258664387.917:7): operation="profile_load" pid=390 name=/usr/sbin/mysqld
2009-11-19 21:00:03 caseylinux kernel [ 3.424962] type=1505 audit(1258664387.925:8): operation="profile_load" pid=391 name=/usr/sbin/mysqld-akonadi
2009-11-19 21:00:03 caseylinux kernel [ 13.205348] type=1505 audit(1258693197.705:15): operation="profile_replace" pid=841 name=/usr/sbin/mysqld
2009-11-19 21:00:03 caseylinux kernel [ 13.206908] type=1505 audit(1258693197.705:16): operation="profile_replace" pid=842 name=/usr/sbin/mysqld-akonadi

Followed by 17 of these:

2009-11-19 21:00:38 caseylinux kernel [ 53.824461] type=1503 audit(1258693238.325:18): operation="open" pid=1199 parent=1198 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"

Followed by the errors shown above ("0 processes alive", etc.)

Oh, gosh, and I just realized that dpkg-query -l '*mysql*' | grep ^ii shows me that I only have these packages installed:

ii libdbd-mysql-perl 4.011-1ubuntu1 A Perl5 database interface to the MySQL database
ii libmysqlclient15off 5.1.30really5.0.83-0ubuntu3 MySQL database client library
ii libmysqlclient16 5.1.37-1ubuntu5 MySQL database client library
ii libqt4-sql-mysql 4.5.3really4.5.2-0ubuntu1 Qt 4 MySQL database driver
ii mysql-client 5.1.37-1ubuntu5 MySQL database client (metapackage depending on
ii mysql-client-5.1 5.1.37-1ubuntu5 MySQL database client binaries
ii mysql-common 5.1.37-1ubuntu5 MySQL database common files (e.g. /etc/mysql/my.
ii mysql-server-core-5.1 5.1.37-1ubuntu5 MySQL database core server files

...so perhaps i'm missing "mysql-server", eh?? That might explain things. Perhaps the upgrade removed 5.0 but failed to install most of 5.1?

I'm going to go ahead and install 5.1 (via package "mysql-server") -- if you think that may be a bad idea lemme know soon :-). I guess I'm not sure if i should expect it to work, since there may well be configurations and so on that the OS needs in place for it to function however the OS is expecting it to function? I guess we'll see.

Thanks again!
-c

[chconnor]

Re: mysqld [fail] on startup?

Hmmm... seems to start up without complaint (although there doesn't seem to be a message on startup that mysqld is starting, it does start... not sure if that's a concern...)

These are the syslog messages with "mysql" in them after the apparently-OK startup. (ps -eF shows mysqld running.)

Nov 19 21:41:59 mymachine kernel: [ 3.463455] type=1505 audit(1258666909.960:7): operation="profile_load" pid=396 name=/usr/sbin/mysqld
Nov 19 21:41:59 mymachine kernel: [ 3.480028] type=1505 audit(1258666909.980:8): operation="profile_load" pid=397 name=/usr/sbin/mysqld-akonadi
Nov 19 21:42:03 mymachine kernel: [ 16.958266] type=1505 audit(1258695723.456:15): operation="profile_replace" pid=880 name=/usr/sbin/mysqld
Nov 19 21:42:03 mymachine kernel: [ 16.959845] type=1505 audit(1258695723.456:16): operation="profile_replace" pid=881 name=/usr/sbin/mysqld-akonadi
Nov 19 21:42:15 mymachine kernel: [ 28.566150] type=1503 audit(1258695735.066:18): operation="open" pid=1250 parent=1249 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:16 mymachine kernel: [ 30.099468] type=1503 audit(1258695736.596:19): operation="open" pid=1271 parent=1270 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:17 mymachine mysqld_safe: Starting mysqld daemon with databases from /var/lib/mysql
Nov 19 21:42:17 mymachine kernel: [ 31.250062] type=1503 audit(1258695737.748:20): operation="open" pid=1388 parent=1278 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:17 mymachine kernel: [ 31.485909] type=1503 audit(1258695737.984:21): operation="open" pid=1394 parent=1393 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:18 mymachine mysqld: 091119 21:42:18 [Note] Plugin 'FEDERATED' is disabled.
Nov 19 21:42:19 mymachine kernel: [ 32.500112] type=1503 audit(1258695739.000:22): operation="open" pid=1404 parent=1403 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:20 mymachine kernel: [ 33.515240] type=1503 audit(1258695740.012:23): operation="open" pid=1414 parent=1413 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:21 mymachine kernel: [ 34.530934] type=1503 audit(1258695741.028:24): operation="open" pid=1437 parent=1436 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:21 mymachine mysqld: 091119 21:42:21 InnoDB: Started; log sequence number 0 43655
Nov 19 21:42:22 mymachine mysqld: 091119 21:42:22 [Note] Event Scheduler: Loaded 0 events
Nov 19 21:42:22 mymachine mysqld: 091119 21:42:22 [Note] /usr/sbin/mysqld: ready for connections.
Nov 19 21:42:22 mymachine mysqld: Version: '5.1.37-1ubuntu5' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
Nov 19 21:42:22 mymachine kernel: [ 36.391405] type=1503 audit(1258695742.888:25): operation="open" pid=1475 parent=1474 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:23 mymachine kernel: [ 36.894497] type=1503 audit(1258695743.392:26): operation="open" pid=1495 parent=1494 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:42:23 mymachine /etc/mysql/debian-start[1510]: Upgrading MySQL tables if necessary.
Nov 19 21:42:25 mymachine /etc/mysql/debian-start[1515]: Looking for 'mysql' as: /usr/bin/mysql
Nov 19 21:42:25 mymachine /etc/mysql/debian-start[1515]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Nov 19 21:42:25 mymachine /etc/mysql/debian-start[1515]: This installation of MySQL is already upgraded to 5.1.37, use --force if you still need to run mysql_upgrade
Nov 19 21:42:25 mymachine /etc/mysql/debian-start[1558]: Checking for insecure root accounts.
Nov 19 21:42:26 mymachine /etc/mysql/debian-start[1562]: Triggering myisam-recover for all MyISAM tables

So I guess that looks OK (?).... However, in perusing syslog for when the install of package "mysql-server" happened, it sure looks messy. Not to drown this thread in logs, but i'll post the lines anyway in case they matter. Lots of scary-sounding errors in there, but i'm not sure what to worry about. Thanks again for any thoughts.

-c

[quote]
Nov 19 21:30:24 mymachine kernel: [ 1839.893177] type=1503 audit(1258695024.393:35): operation="open" pid=3760 parent=3759 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:24 mymachine kernel: [ 1839.917010] type=1503 audit(1258695024.417:36): operation="open" pid=3770 parent=3769 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:28 mymachine kernel: [ 1843.603140] type=1503 audit(1258695028.101:37): operation="open" pid=4086 parent=4085 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:28 mymachine kernel: [ 1843.622698] type=1503 audit(1258695028.121:38): operation="open" pid=4095 parent=4094 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:28 mymachine kernel: [ 1843.926239] type=1503 audit(1258695028.425:39): operation="open" pid=4141 parent=4118 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:29 mymachine mysqld_safe[4119]: ERROR: 1136 Column count doesn't match value count at row 1
Nov 19 21:30:29 mymachine mysqld_safe[4119]: 091119 21:30:29 [ERROR] Aborting
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: 091119 21:30:29 [Warning] Forcing shutdown of 2 plugins
Nov 19 21:30:29 mymachine mysqld_safe[4119]: 091119 21:30:29 [Note] /usr/sbin/mysqld: Shutdown complete
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: Installation of system tables failed! Examine the logs in
Nov 19 21:30:29 mymachine mysqld_safe[4119]: /var/lib/mysql for more information.
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: You can try to start the mysqld daemon with:
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: shell> /usr/sbin/mysqld --skip-grant &
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: and use the command line tool /usr/bin/mysql
Nov 19 21:30:29 mymachine mysqld_safe[4119]: to connect to the mysql database and look at the grant tables:
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: shell> /usr/bin/mysql -u root mysql
Nov 19 21:30:29 mymachine mysqld_safe[4119]: mysql> show tables
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: Try 'mysqld --help' if you have problems with paths. Using --log
Nov 19 21:30:29 mymachine mysqld_safe[4119]: gives you a log in /var/lib/mysql that may be helpful.
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: The latest information about MySQL is available on the web at
Nov 19 21:30:29 mymachine mysqld_safe[4119]: http://www.mysql.com/. Please consult the MySQL manual section
Nov 19 21:30:29 mymachine mysqld_safe[4119]: 'Problems running mysql_install_db', and the manual section that
Nov 19 21:30:29 mymachine mysqld_safe[4119]: describes problems on your OS. Another information source are the
Nov 19 21:30:29 mymachine mysqld_safe[4119]: MySQL email archives available at http://lists.mysql.com/.
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine mysqld_safe[4119]: Please check all of the above before mailing us! And remember, if
Nov 19 21:30:29 mymachine mysqld_safe[4119]: you do mail us, you MUST use the /usr/scripts/mysqlbug script!
Nov 19 21:30:29 mymachine mysqld_safe[4119]:
Nov 19 21:30:29 mymachine kernel: [ 1844.703627] type=1503 audit(1258695029.201:40): operation="open" pid=4157 parent=4052 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:29 mymachine mysqld_safe[4159]: 091119 21:30:29 [Note] Plugin 'FEDERATED' is disabled.
Nov 19 21:30:29 mymachine mysqld_safe[4159]: 091119 21:30:29 InnoDB: Started; log sequence number 0 43655
Nov 19 21:30:29 mymachine mysqld_safe[4159]: 091119 21:30:29 InnoDB: Starting shutdown...
Nov 19 21:30:31 mymachine mysqld_safe[4159]: 091119 21:30:30 InnoDB: Shutdown completed; log sequence number 0 43655
Nov 19 21:30:31 mymachine mysqld_safe[4159]: 091119 21:30:30 [Warning] Forcing shutdown of 1 plugins
Nov 19 21:30:31 mymachine kernel: [ 1846.541289] type=1503 audit(1258695031.041:41): operation="open" pid=4178 parent=4052 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:31 mymachine mysqld_safe[4180]: 091119 21:30:31 [Note] Plugin 'FEDERATED' is disabled.
Nov 19 21:30:31 mymachine mysqld_safe[4180]: 091119 21:30:31 InnoDB: Started; log sequence number 0 43655
Nov 19 21:30:31 mymachine mysqld_safe[4180]: ERROR: 1064 You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'ALTER TABLE user ADD column Show_view_priv enum('N','Y') CHARACTER SET utf8 NOT ' at line 1
Nov 19 21:30:31 mymachine mysqld_safe[4180]: 091119 21:30:31 [ERROR] Aborting
Nov 19 21:30:31 mymachine mysqld_safe[4180]:
Nov 19 21:30:31 mymachine mysqld_safe[4180]: 091119 21:30:31 InnoDB: Starting shutdown...
Nov 19 21:30:32 mymachine mysqld_safe[4180]: 091119 21:30:32 InnoDB: Shutdown completed; log sequence number 0 43655
Nov 19 21:30:32 mymachine mysqld_safe[4180]: 091119 21:30:32 [Warning] Forcing shutdown of 1 plugins
Nov 19 21:30:32 mymachine mysqld_safe[4180]: 091119 21:30:32 [Note] /usr/sbin/mysqld: Shutdown complete
Nov 19 21:30:32 mymachine mysqld_safe[4180]:
Nov 19 21:30:32 mymachine kernel: [ 1847.831405] type=1503 audit(1258695032.329:42): operation="open" pid=4192 parent=4052 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:32 mymachine mysqld_safe[4194]: 091119 21:30:32 [Note] Plugin 'FEDERATED' is disabled.
Nov 19 21:30:32 mymachine mysqld_safe[4194]: 091119 21:30:32 InnoDB: Started; log sequence number 0 43655
Nov 19 21:30:32 mymachine mysqld_safe[4194]: ERROR: 1054 Unknown column 'Event_priv' in 'field list'
Nov 19 21:30:32 mymachine mysqld_safe[4194]: 091119 21:30:32 [ERROR] Aborting
Nov 19 21:30:32 mymachine mysqld_safe[4194]:
Nov 19 21:30:32 mymachine mysqld_safe[4194]: 091119 21:30:32 InnoDB: Starting shutdown...
Nov 19 21:30:33 mymachine mysqld_safe[4194]: 091119 21:30:33 InnoDB: Shutdown completed; log sequence number 0 43655
Nov 19 21:30:33 mymachine mysqld_safe[4194]: 091119 21:30:33 [Warning] Forcing shutdown of 1 plugins
Nov 19 21:30:33 mymachine mysqld_safe[4194]: 091119 21:30:33 [Note] /usr/sbin/mysqld: Shutdown complete
Nov 19 21:30:33 mymachine mysqld_safe[4194]:
Nov 19 21:30:33 mymachine kernel: [ 1849.158636] type=1503 audit(1258695033.657:43): operation="open" pid=4206 parent=4052 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:33 mymachine mysqld_safe[4208]: 091119 21:30:33 [Note] Plugin 'FEDERATED' is disabled.
Nov 19 21:30:33 mymachine mysqld_safe[4208]: 091119 21:30:33 InnoDB: Started; log sequence number 0 43655
Nov 19 21:30:33 mymachine mysqld_safe[4208]: ERROR: 1050 Table 'plugin' already exists
Nov 19 21:30:33 mymachine mysqld_safe[4208]: 091119 21:30:33 [ERROR] Aborting
Nov 19 21:30:33 mymachine mysqld_safe[4208]:
Nov 19 21:30:33 mymachine mysqld_safe[4208]: 091119 21:30:33 InnoDB: Starting shutdown...
Nov 19 21:30:34 mymachine mysqld_safe[4208]: 091119 21:30:34 InnoDB: Shutdown completed; log sequence number 0 43655
Nov 19 21:30:34 mymachine mysqld_safe[4208]: 091119 21:30:34 [Warning] Forcing shutdown of 1 plugins
Nov 19 21:30:34 mymachine mysqld_safe[4208]: 091119 21:30:34 [Note] /usr/sbin/mysqld: Shutdown complete
Nov 19 21:30:34 mymachine mysqld_safe[4208]:
Nov 19 21:30:35 mymachine kernel: [ 1850.521185] type=1505 audit(1258695035.021:44): operation="profile_replace" pid=4222 name=/usr/sbin/mysqld
Nov 19 21:30:35 mymachine kernel: [ 1850.688748] type=1503 audit(1258695035.189:45): operation="open" pid=4250 parent=4249 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:35 mymachine kernel: [ 1850.721704] type=1503 audit(1258695035.221:46): operation="open" pid=4271 parent=4270 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:35 mymachine mysqld_safe: Starting mysqld daemon with databases from /var/lib/mysql
Nov 19 21:30:35 mymachine kernel: [ 1850.878438] type=1503 audit(1258695035.377:47): operation="open" pid=4385 parent=4277 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:35 mymachine mysqld: 091119 21:30:35 [Note] Plugin 'FEDERATED' is disabled.
Nov 19 21:30:35 mymachine mysqld: 091119 21:30:35 InnoDB: Started; log sequence number 0 43655
Nov 19 21:30:35 mymachine mysqld: 091119 21:30:35 [ERROR] Column count of mysql.db is wrong. Expected 22, found 20. Created with MySQL 50075, now running 50137. Please use mysql_upgrade to fix this error.
Nov 19 21:30:35 mymachine mysqld: 091119 21:30:35 [ERROR] mysql.user has no `Event_priv` column at position 29
Nov 19 21:30:35 mymachine mysqld: 091119 21:30:35 [ERROR] Event Scheduler: An error occurred when initializing system tables. Disabling the Event Scheduler.
Nov 19 21:30:35 mymachine mysqld: 091119 21:30:35 [Note] /usr/sbin/mysqld: ready for connections.
Nov 19 21:30:35 mymachine mysqld: Version: '5.1.37-1ubuntu5' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
Nov 19 21:30:36 mymachine kernel: [ 1851.810169] type=1503 audit(1258695036.309:48): operation="open" pid=4401 parent=4400 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:36 mymachine kernel: [ 1851.837652] type=1503 audit(1258695036.337:49): operation="open" pid=4412 parent=4411 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
Nov 19 21:30:36 mymachine /etc/mysql/debian-start[4425]: Upgrading MySQL tables if necessary.
Nov 19 21:30:36 mymachine mysqld:
Nov 19 21:30:36 mymachine mysqld: Status information:
Nov 19 21:30:36 mymachine mysqld:
Nov 19 21:30:36 mymachine mysqld: Current dir: /var/lib/mysql/
Nov 19 21:30:36 mymachine mysqld: Running threads: 1 Stack size: 196608
Nov 19 21:30:36 mymachine mysqld: Current locks:
Nov 19 21:30:36 mymachine mysqld: lock: 0x2256980: write
Nov 19 21:30:36 mymachine mysqld: write : 0x2256ea0 (5:13);
Nov 19 21:30:36 mymachine mysqld:

[ukchucktown]

Re: mysqld [fail] on startup?

From the logs you posted looks like a hiccup trying to upgrade the system tables from 5.0 to 5.1. You did get the package right, mysql-server-5.1 is correct. Watch the log on the next reboot/startup. Post the relevant log messages again if the start-up errors persist.

[chconnor]

Re: mysqld [fail] on startup?

Thanks! - it started up this time just like last time (same log messages, no errors shown, seems OK.) This time the mysql startup lines were displayed on startup (i think that's an unrelated issue... i'm having X startup issues detailed at http://kubuntuforums.net/forums/inde...opic=3108243.0 and i believe that's the cause of "sometimes see it sometimes don't" phenomenon...)

So i guess i'll just proceed as if everything is good to go unless someone advises otherwise. :-)

Is there some aspect of the system i can poke to make sure that mysqld is running smoothly?

-c

[chconnor]

Re: [solved?] mysqld [fail] on startup?

Not to resurrect this issue, but i'm wondering if this is normal for anyone else when mysqld starts up (especially the last 6 or so lines)... I've included a snapshot of the bootchart section where mysql is apparently starting... looks like it takes 15 seconds, which seems way long.

From syslog (via ksystemlog and filter "mysql"):

2009-11-22 12:53:30 machinename kernel [ 3.467985] type=1505 audit(1258894399.980:7): operation="profile_load" pid=418 name=/usr/sbin/mysqld
2009-11-22 12:53:30 machinename kernel [ 3.484575] type=1505 audit(1258894400.000:8): operation="profile_load" pid=419 name=/usr/sbin/mysqld-akonadi
2009-11-22 12:53:35 machinename kernel [ 19.400349] type=1505 audit(1258923215.916:15): operation="profile_replace" pid=958 name=/usr/sbin/mysqld
2009-11-22 12:53:35 machinename kernel [ 19.401915] type=1505 audit(1258923215.916:16): operation="profile_replace" pid=959 name=/usr/sbin/mysqld-akonadi
2009-11-22 12:53:42 machinename kernel [ 26.400894] type=1503 audit(1258923222.916:18): operation="open" pid=1281 parent=1280 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
2009-11-22 12:53:44 machinename kernel [ 27.849184] type=1503 audit(1258923224.364:19): operation="open" pid=1304 parent=1303 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
2009-11-22 12:53:44 machinename mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2009-11-22 12:53:45 machinename kernel [ 28.487286] type=1503 audit(1258923225.000:20): operation="open" pid=1419 parent=1311 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
2009-11-22 12:53:45 machinename mysqld 091122 12:53:45 [Note] Plugin 'FEDERATED' is disabled.
2009-11-22 12:53:45 machinename kernel [ 29.258944] type=1503 audit(1258923225.772:21): operation="open" pid=1434 parent=1433 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
2009-11-22 12:53:46 machinename mysqld 091122 12:53:46 InnoDB: Started; log sequence number 0 43655
2009-11-22 12:53:47 machinename mysqld 091122 12:53:47 [Note] Event Scheduler: Loaded 0 events
2009-11-22 12:53:47 machinename mysqld 091122 12:53:47 [Note] /usr/sbin/mysqld: ready for connections.
2009-11-22 12:53:47 machinename mysqld Version: '5.1.37-1ubuntu5' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
2009-11-22 12:53:47 machinename kernel [ 30.725949] type=1503 audit(1258923227.240:22): operation="open" pid=1472 parent=1471 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
2009-11-22 12:53:47 machinename kernel [ 30.774736] type=1503 audit(1258923227.288:23): operation="open" pid=1483 parent=1482 profile="/usr/sbin/mysqld" requested_mask="r::" denied_mask="r::" fsuid=0 ouid=0 name="/sys/devices/system/cpu/"
2009-11-22 12:53:47 machinename /etc/mysql/debian-start[1495] Upgrading MySQL tables if necessary.
2009-11-22 12:53:47 machinename /etc/mysql/debian-start[1500] Looking for 'mysql' as: /usr/bin/mysql
2009-11-22 12:53:47 machinename /etc/mysql/debian-start[1500] Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
2009-11-22 12:53:47 machinename /etc/mysql/debian-start[1500] This installation of MySQL is already upgraded to 5.1.37, use --force if you still need to run mysql_upgrade
2009-11-22 12:53:47 machinename /etc/mysql/debian-start[1539] Checking for insecure root accounts.
2009-11-22 12:53:48 machinename /etc/mysql/debian-start[1543] Triggering myisam-recover for all MyISAM tables

Any thoughts? Is this normal? Thanks!
-c

[greenshirt11]

Re: [solved?] mysqld [fail] on startup?

why i missed your message before i started my thread (http://kubuntuforums.net/forums/inde...opic=3108222.0) i don't know.

on my system now:

user@dharana:~/workarea$ dpkg-query -l '*mysql*' | grep ^ii
ii libdbd-mysql-perl             4.011-1ubuntu1               A Perl5 database interface to the MySQL data
ii libmysqlclient16              5.1.37-1ubuntu5              MySQL database client library
ii libqt4-sql-mysql              4.5.3really4.5.2-0ubuntu1         Qt 4 MySQL database driver
ii mysql-client                5.1.37-1ubuntu5              MySQL database client (metapackage depending
ii mysql-client-5.1              5.1.37-1ubuntu5              MySQL database client binaries
ii mysql-common                5.1.37-1ubuntu5              MySQL database common files (e.g. /etc/mysql
ii mysql-server                5.1.37-1ubuntu5              MySQL database server (metapackage depending
ii mysql-server-5.1              5.1.37-1ubuntu5              MySQL database server binaries
ii mysql-server-core-5.1           5.1.37-1ubuntu5              MySQL database core server files
ii php5-mysql                 5.2.10.dfsg.1-2ubuntu6.1          MySQL module for php5

The syslog shows:

Nov 24 08:45:30 dharana kernel: [  19.952594] type=1503 audit(1259048730.644:18): operation="open" pid=1295 parent=1294 profile="/usr/sbin/mysqld" ...
Nov 24 08:45:31 dharana kernel: [  20.438916] type=1503 audit(1259048731.128:19): operation="open" pid=1318 parent=1317 profile="/usr/sbin/mysqld" ...
Nov 24 08:45:31 dharana mysqld_safe: Starting mysqld daemon with databases from /var/lib/mysql
Nov 24 08:45:31 dharana kernel: [  20.913489] type=1503 audit(1259048731.604:20): operation="open" pid=1440 parent=1325 profile="/usr/sbin/mysqld" ...
Nov 24 08:45:32 dharana mysqld: 091124 8:45:32 [Note] Plugin 'FEDERATED' is disabled.
Nov 24 08:45:32 dharana kernel: [  21.536692] type=1503 audit(1259048732.228:21): operation="open" pid=1447 parent=1446 profile="/usr/sbin/mysqld" ...
Nov 24 08:45:32 dharana mysqld: 091124 8:45:32 InnoDB: Started; log sequence number 0 43655
Nov 24 08:45:33 dharana mysqld: 091124 8:45:33 [Note] Event Scheduler: Loaded 0 events
Nov 24 08:45:33 dharana mysqld: 091124 8:45:33 [Note] /usr/sbin/mysqld: ready for connections.
Nov 24 08:45:33 dharana mysqld: Version: '5.1.37-1ubuntu5' socket: '/var/run/mysqld/mysqld.sock' port: 3306 (Ubuntu)
Nov 24 08:45:33 dharana kernel: [  22.627860] type=1503 audit(1259048733.316:22): operation="open" pid=1467 parent=1466 profile="/usr/sbin/mysqld" ...
Nov 24 08:45:33 dharana kernel: [  22.721790] type=1503 audit(1259048733.412:23): operation="open" pid=1478 parent=1477 profile="/usr/sbin/mysqld" ...
Nov 24 08:45:33 dharana /etc/mysql/debian-start[1490]: Upgrading MySQL tables if necessary.
Nov 24 08:45:34 dharana /etc/mysql/debian-start[1495]: Looking for 'mysql' as: /usr/bin/mysql
Nov 24 08:45:34 dharana /etc/mysql/debian-start[1495]: Looking for 'mysqlcheck' as: /usr/bin/mysqlcheck
Nov 24 08:45:34 dharana /etc/mysql/debian-start[1495]: This installation of MySQL is already upgraded to 5.1.37, use --force if you still need to run mysql_upgrade
Nov 24 08:45:34 dharana /etc/mysql/debian-start[1600]: Checking for insecure root accounts.
Nov 24 08:45:34 dharana /etc/mysql/debian-start[1608]: Triggering myisam-recover for all MyISAM tables
Nov 24 08:45:38 dharana kernel: [  27.332008] eth1: no IPv6 routers present

Don't know if it can be due to hw difference:
- Intel(R) Pentium(R) 4 CPU 2.80GHz stepping 03
- Memory: 1Gb

[chconnor]

Re: [solved?] mysqld [fail] on startup?

Thanks... I read those release notes and must have either forgotten or misunderstood the mysql part. The release notes don't really make a lot of sense to me, exactly :-), (e.g. the difference between dist-upgrade and "upgrading" via update-manager (=kpackagekit?); if it's a bug that mysql is handled differently or a choice for some reason; if a choice, why it would work that way; and why removing packages would cause the dist-upgrade to go to 5.0 but upgrading before a dist-upgrade goes to 5.1, etc etc. I trust/hope there are good reasons :-) ). At least your log looks similar to mine, that's reassuring. The boot chart was a little stranger, since it seemed like such a long time for mysql to start, but perhaps it's just due to the busy system when starting up. Thanks, -c