Mysql recipe error on ubuntu 12.04

Chef Infra (archive)
1

Just fired up an ec2 instance and ran chef-solo on ubuntu 12.04, I am
seeing this error below. I can’t seem to understand what the reason is for
the error?

[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:40+00:00]
INFO: Processing package[mysql-client] action install (mysql::client line
40)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:50+00:00]
INFO: Processing package[libmysqlclient-dev] action install (mysql::client
line 40)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:53+00:00]
INFO: Processing package[libmysql-ruby] action install (mysql::client line
48)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: Processing directory[/var/cache/local/preseeding] action create
(mysql::server line 31)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: directory[/var/cache/local/preseeding] mode changed to 755
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: Processing execute[preseed mysql-server] action nothing
(mysql::server line 38)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: Processing template[/var/cache/local/preseeding/mysql-server.seed]
action create (mysql::server line 43)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/var/cache/local/preseeding/mysql-server.seed] updated
content
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/var/cache/local/preseeding/mysql-server.seed] owner changed
to 0
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/var/cache/local/preseeding/mysql-server.seed] group changed
to 0
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/var/cache/local/preseeding/mysql-server.seed] mode changed
to 600
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/var/cache/local/preseeding/mysql-server.seed] sending run
action to execute[preseed mysql-server] (immediate)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: Processing execute[preseed mysql-server] action run (mysql::server
line 38)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: execute[preseed mysql-server] ran successfully
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: Processing template[/etc/mysql/debian.cnf] action create
(mysql::server line 51)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/etc/mysql/debian.cnf] updated content
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/etc/mysql/debian.cnf] owner changed to 0
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/etc/mysql/debian.cnf] group changed to 0
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: template[/etc/mysql/debian.cnf] mode changed to 600
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:46:56+00:00]
INFO: Processing package[mysql-server] action install (mysql::server line
60)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: Processing directory[/etc/mysql/mysql/conf.d] action create
(mysql::server line 64)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: directory[/etc/mysql/mysql/conf.d] created directory
/etc/mysql/mysql/conf.d
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: directory[/etc/mysql/mysql/conf.d] owner changed to 106
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: directory[/etc/mysql/mysql/conf.d] group changed to 112
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: Processing service[mysql] action nothing (mysql::server line 71)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: Processing template[/etc/mysql/my.cnf] action create (mysql::server
line 91)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: template[/etc/mysql/my.cnf] backed up to
/var/chef/backup/etc/mysql/my.cnf.chef-20121111044720
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: template[/etc/mysql/my.cnf] updated content
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: template[/etc/mysql/my.cnf] owner changed to 0
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: template[/etc/mysql/my.cnf] group changed to 0
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: template[/etc/mysql/my.cnf] mode changed to 644
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: template[/etc/mysql/my.cnf] sending restart action to service[mysql]
(immediate)
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:20+00:00]
INFO: Processing service[mysql] action restart (mysql::server line 71)
[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out:

[ec2-removed.compute-1.amazonaws.com] out: Error executing action restart
on resource ‘service[mysql]’
[ec2-removed.compute-1.amazonaws.com] out:

[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out:
Mixlib::ShellOut::ShellCommandFailed
[ec2-removed.compute-1.amazonaws.com] out:

[ec2-removed.compute-1.amazonaws.com] out: Expected process to exit with
[0], but received ‘1’
[ec2-removed.compute-1.amazonaws.com] out: ---- Begin output of restart
mysql ----
[ec2-removed.compute-1.amazonaws.com] out: STDOUT:
[ec2-removed.compute-1.amazonaws.com] out: STDERR: restart: Job failed to
restart
[ec2-removed.compute-1.amazonaws.com] out: ---- End output of restart mysql

[ec2-removed.compute-1.amazonaws.com] out: Ran restart mysql returned 1
[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out: Resource Declaration:
[ec2-removed.compute-1.amazonaws.com] out: ---------------------
[ec2-removed.compute-1.amazonaws.com] out: # In
/home/ubuntu/chef/cookbooks/mysql/recipes/server.rb
[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out: 71: service “mysql” do
[ec2-removed.compute-1.amazonaws.com] out: 72: service_name
node[‘mysql’][‘service_name’]
[ec2-removed.compute-1.amazonaws.com] out: 73: if (platform?(“ubuntu”)
&& node.platform_version.to_f >= 10.04)
[ec2-removed.compute-1.amazonaws.com] out: 74: restart_command
"restart mysql"
[ec2-removed.compute-1.amazonaws.com] out: 75: stop_command “stop
mysql”
[ec2-removed.compute-1.amazonaws.com] out: 76: start_command “start
mysql”
[ec2-removed.compute-1.amazonaws.com] out: 77: end
[ec2-removed.compute-1.amazonaws.com] out: 78: supports :status => true,
:restart => true, :reload => true
[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out: Compiled Resource:
[ec2-removed.compute-1.amazonaws.com] out: ------------------
[ec2-removed.compute-1.amazonaws.com] out: # Declared in
/home/ubuntu/chef/cookbooks/mysql/recipes/server.rb:71:in `from_file’
[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out: service(“mysql”) do
[ec2-removed.compute-1.amazonaws.com] out: retry_delay 2
[ec2-removed.compute-1.amazonaws.com] out: action [:nothing]
[ec2-removed.compute-1.amazonaws.com] out: recipe_name “server”
[ec2-removed.compute-1.amazonaws.com] out: restart_command “restart mysql”
[ec2-removed.compute-1.amazonaws.com] out: retries 0
[ec2-removed.compute-1.amazonaws.com] out: running true
[ec2-removed.compute-1.amazonaws.com] out: startup_type :automatic
[ec2-removed.compute-1.amazonaws.com] out: cookbook_name :mysql
[ec2-removed.compute-1.amazonaws.com] out: stop_command “stop mysql”
[ec2-removed.compute-1.amazonaws.com] out: pattern “mysql”
[ec2-removed.compute-1.amazonaws.com] out: service_name “mysql”
[ec2-removed.compute-1.amazonaws.com] out: start_command “start mysql”
[ec2-removed.compute-1.amazonaws.com] out: supports {:status=>true,
:restart=>true, :reload=>true}
[ec2-removed.compute-1.amazonaws.com] out: end
[ec2-removed.compute-1.amazonaws.com] out:
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:23+00:00]
ERROR: Running exception handlers
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:23+00:00]
ERROR: Exception handlers complete
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:23+00:00]
FATAL: Stacktrace dumped to /home/ubuntu/chef/chef-stacktrace.out
[ec2-removed.compute-1.amazonaws.com] out: [2012-11-11T04:47:23+00:00]
FATAL: Mixlib::ShellOut::ShellCommandFailed: service[mysql] (mysql::server
line 71) had an error: Mixlib::ShellOut::ShellCommandFailed: Expected
process to exit with [0], but received ‘1’
[ec2-removed.compute-1.amazonaws.com] out: ---- Begin output of restart
mysql ----
[ec2-removed.compute-1.amazonaws.com] out: STDOUT:
[ec2-removed.compute-1.amazonaws.com] out: STDERR: restart: Job failed to
restart
[ec2-removed.compute-1.amazonaws.com] out: ---- End output of restart mysql

[ec2-removed.compute-1.amazonaws.com] out: Ran restart mysql returned 1
[ec2-removed.compute-1.amazonaws.com] out:

Fatal error: run() received nonzero return code 1 while executing!

2

On 11/10/2012 07:15 PM, S Ahmed wrote:

service[mysql] (mysql::server line 71) had an error:
Mixlib::ShellOut::ShellCommandFailed: Expected process to exit with
[0], but received '1'
This is telling you that the service resource was run but the exit
status of the command it ran was 1 instead of 0, which usually indicates
an error of some description.
Unfortunately it's impossible to tell what that error is from what chef
has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul

3

Small error of fact from Paul. It should be 'restart mysql' on ubuntu
because of upstart.

Random Stabs
12.04 uses mysql 5.5 so that might be worth looking at as a cause.

The mysql error lodging is usually pretty helpful. It will either be in
/var/log or where /etc/mysql/ my.cnf says it will be
On Nov 10, 2012 11:38 PM, "Paul Graydon" paul@paulgraydon.co.uk wrote:

On 11/10/2012 07:15 PM, S Ahmed wrote:

service[mysql] (mysql::server line 71) had an error: Mixlib::ShellOut::**ShellCommandFailed:
Expected process to exit with [0], but received '1'

This is telling you that the service resource was run but the exit status
of the command it ran was 1 instead of 0, which usually indicates an error
of some description.
Unfortunately it's impossible to tell what that error is from what chef
has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul

4

Boyd/Paul,

Thanks for the help.

Boyd, according to my.cnf it seems logging is in syslog, it reads:

* Logging and Replication

Both location gets rotated by the cronjob.

Be aware that this log type is a performance killer.

#log = /var/log/mysql/mysql.log

Error logging goes to syslog. This is a Debian improvement :slight_smile:

restart mysql
estart: Rejected send message, 1 matched rules; type="method_call",
sender=":1.7" (uid=1000 pid=1128 comm="restart mysql ")
interface="com.ubuntu.Upstart0_6.Job" member="Restart" error name="(unset)"
requested_reply="0" destination="com.ubuntu.Upstart" (uid=0 pid=1
comm="/sbin/init")
sudo restart mysql
restart: Unknown instance:

syslog shows:

Nov 11 16:46:23 removed kernel: [54062688.327783] audit_printk_skb: 9
callbacks suppressed
Nov 11 16:46:23 removed kernel: [54062688.327787] type=1400
audit(1352652383.807:14): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=745
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:23 removed kernel: [54062688.329541] init: mysql main process
(745) terminated with status 1
Nov 11 16:46:23 removed kernel: [54062688.329586] init: mysql main process
ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.210421] init: mysql post-start
process (752) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.225176] type=1400
audit(1352652384.703:15): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=821 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.244978] type=1400
audit(1352652384.723:16): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=825
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.246024] init: mysql main process
(825) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.246068] init: mysql main process
ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.255999] init: mysql post-start
process (826) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.272705] type=1400
audit(1352652384.751:17): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=841 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.291636] type=1400
audit(1352652384.771:18): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=845
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.292787] init: mysql main process
(845) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.292832] init: mysql respawning
too fast, stopped
Nov 11 16:46:29 removed ntpdate[470]: adjust time server 91.189.94.4 offset
0.408380 sec
Nov 11 16:46:31 ip-10removed-114-198-63 kernel: [54062696.205953] eth0: no
IPv6 routers present

On Sun, Nov 11, 2012 at 7:57 AM, Boyd Hemphill behemphi@gmail.com wrote:

Small error of fact from Paul. It should be 'restart mysql' on ubuntu
because of upstart.

Random Stabs
12.04 uses mysql 5.5 so that might be worth looking at as a cause.

The mysql error lodging is usually pretty helpful. It will either be in
/var/log or where /etc/mysql/ my.cnf says it will be
On Nov 10, 2012 11:38 PM, "Paul Graydon" paul@paulgraydon.co.uk wrote:

On 11/10/2012 07:15 PM, S Ahmed wrote:

service[mysql] (mysql::server line 71) had an error: Mixlib::ShellOut::*
*ShellCommandFailed: Expected process to exit with [0], but received '1'

This is telling you that the service resource was run but the exit status
of the command it ran was 1 instead of 0, which usually indicates an error
of some description.
Unfortunately it's impossible to tell what that error is from what chef
has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul

5

The my.cnf snip seees to have everything commented out. Usually the log
would be /var/log/mysqld.log or /var/log/mysql/error.log.

I have not seen this issue with MySQL starting before and I am not
currently using 5.5 or 12.04. I am about to migrate.

An absolute guess on my part is that mysql was installed b/f the recipe ran
and something is colliding in terms of the server trying to gain access to
a resource.

Sorry I cannot be more specific.

Boyd

On Sun, Nov 11, 2012 at 11:05 AM, S Ahmed sahmed1020@gmail.com wrote:

Boyd/Paul,

Thanks for the help.

Boyd, according to my.cnf it seems logging is in syslog, it reads:

* Logging and Replication

Both location gets rotated by the cronjob.

Be aware that this log type is a performance killer.

#log = /var/log/mysql/mysql.log

Error logging goes to syslog. This is a Debian improvement :slight_smile:

restart mysql
estart: Rejected send message, 1 matched rules; type="method_call",
sender=":1.7" (uid=1000 pid=1128 comm="restart mysql ")
interface="com.ubuntu.Upstart0_6.Job" member="Restart" error name="(unset)"
requested_reply="0" destination="com.ubuntu.Upstart" (uid=0 pid=1
comm="/sbin/init")
sudo restart mysql
restart: Unknown instance:

syslog shows:

Nov 11 16:46:23 removed kernel: [54062688.327783] audit_printk_skb: 9
callbacks suppressed
Nov 11 16:46:23 removed kernel: [54062688.327787] type=1400
audit(1352652383.807:14): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=745
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:23 removed kernel: [54062688.329541] init: mysql main process
(745) terminated with status 1
Nov 11 16:46:23 removed kernel: [54062688.329586] init: mysql main process
ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.210421] init: mysql post-start
process (752) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.225176] type=1400
audit(1352652384.703:15): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=821 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.244978] type=1400
audit(1352652384.723:16): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=825
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.246024] init: mysql main process
(825) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.246068] init: mysql main process
ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.255999] init: mysql post-start
process (826) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.272705] type=1400
audit(1352652384.751:17): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=841 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.291636] type=1400
audit(1352652384.771:18): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=845
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.292787] init: mysql main process
(845) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.292832] init: mysql respawning
too fast, stopped
Nov 11 16:46:29 removed ntpdate[470]: adjust time server 91.189.94.4
offset 0.408380 sec
Nov 11 16:46:31 ip-10removed-114-198-63 kernel: [54062696.205953] eth0: no
IPv6 routers present

On Sun, Nov 11, 2012 at 7:57 AM, Boyd Hemphill behemphi@gmail.com wrote:

Small error of fact from Paul. It should be 'restart mysql' on ubuntu
because of upstart.

Random Stabs
12.04 uses mysql 5.5 so that might be worth looking at as a cause.

The mysql error lodging is usually pretty helpful. It will either be in
/var/log or where /etc/mysql/ my.cnf says it will be
On Nov 10, 2012 11:38 PM, "Paul Graydon" paul@paulgraydon.co.uk wrote:

On 11/10/2012 07:15 PM, S Ahmed wrote:

service[mysql] (mysql::server line 71) had an error: Mixlib::ShellOut::
**ShellCommandFailed: Expected process to exit with [0], but received
'1'

This is telling you that the service resource was run but the exit
status of the command it ran was 1 instead of 0, which usually indicates an
error of some description.
Unfortunately it's impossible to tell what that error is from what chef
has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul

6

so what you are saying is that 12.04 has mysql pre-installed and running?
(as a guess)

On Sun, Nov 11, 2012 at 1:52 PM, Boyd Hemphill behemphi@gmail.com wrote:

The my.cnf snip seees to have everything commented out. Usually the log
would be /var/log/mysqld.log or /var/log/mysql/error.log.

I have not seen this issue with MySQL starting before and I am not
currently using 5.5 or 12.04. I am about to migrate.

An absolute guess on my part is that mysql was installed b/f the recipe
ran and something is colliding in terms of the server trying to gain access
to a resource.

Sorry I cannot be more specific.

Boyd

On Sun, Nov 11, 2012 at 11:05 AM, S Ahmed sahmed1020@gmail.com wrote:

Boyd/Paul,

Thanks for the help.

Boyd, according to my.cnf it seems logging is in syslog, it reads:

* Logging and Replication

Both location gets rotated by the cronjob.

Be aware that this log type is a performance killer.

#log = /var/log/mysql/mysql.log

Error logging goes to syslog. This is a Debian improvement :slight_smile:

restart mysql
estart: Rejected send message, 1 matched rules; type="method_call",
sender=":1.7" (uid=1000 pid=1128 comm="restart mysql ")
interface="com.ubuntu.Upstart0_6.Job" member="Restart" error name="(unset)"
requested_reply="0" destination="com.ubuntu.Upstart" (uid=0 pid=1
comm="/sbin/init")
sudo restart mysql
restart: Unknown instance:

syslog shows:

Nov 11 16:46:23 removed kernel: [54062688.327783] audit_printk_skb: 9
callbacks suppressed
Nov 11 16:46:23 removed kernel: [54062688.327787] type=1400
audit(1352652383.807:14): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=745
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:23 removed kernel: [54062688.329541] init: mysql main
process (745) terminated with status 1
Nov 11 16:46:23 removed kernel: [54062688.329586] init: mysql main
process ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.210421] init: mysql post-start
process (752) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.225176] type=1400
audit(1352652384.703:15): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=821 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.244978] type=1400
audit(1352652384.723:16): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=825
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.246024] init: mysql main
process (825) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.246068] init: mysql main
process ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.255999] init: mysql post-start
process (826) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.272705] type=1400
audit(1352652384.751:17): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=841 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.291636] type=1400
audit(1352652384.771:18): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=845
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.292787] init: mysql main
process (845) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.292832] init: mysql respawning
too fast, stopped
Nov 11 16:46:29 removed ntpdate[470]: adjust time server 91.189.94.4
offset 0.408380 sec
Nov 11 16:46:31 ip-10removed-114-198-63 kernel: [54062696.205953] eth0:
no IPv6 routers present

On Sun, Nov 11, 2012 at 7:57 AM, Boyd Hemphill behemphi@gmail.comwrote:

Small error of fact from Paul. It should be 'restart mysql' on ubuntu
because of upstart.

Random Stabs
12.04 uses mysql 5.5 so that might be worth looking at as a cause.

The mysql error lodging is usually pretty helpful. It will either be in
/var/log or where /etc/mysql/ my.cnf says it will be
On Nov 10, 2012 11:38 PM, "Paul Graydon" paul@paulgraydon.co.uk wrote:

On 11/10/2012 07:15 PM, S Ahmed wrote:

service[mysql] (mysql::server line 71) had an error: Mixlib::ShellOut::
**ShellCommandFailed: Expected process to exit with [0], but received
'1'

This is telling you that the service resource was run but the exit
status of the command it ran was 1 instead of 0, which usually indicates an
error of some description.
Unfortunately it's impossible to tell what that error is from what chef
has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul

7

Could it be related to this issue?

Thanks,
--Charles

--
Charles Johnson
Solutions Engineer - Opscode, Inc.
(510) 545-9485 - Direct Line
charles@opscode.com

From: Boyd Hemphill <behemphi@gmail.commailto:behemphi@gmail.com>
Reply-To: "chef@lists.opscode.commailto:chef@lists.opscode.com" <chef@lists.opscode.commailto:chef@lists.opscode.com>
Date: Sunday, November 11, 2012 10:52 AM
To: "chef@lists.opscode.commailto:chef@lists.opscode.com" <chef@lists.opscode.commailto:chef@lists.opscode.com>
Subject: [chef] Re: Re: Re: Re: mysql recipe error on ubuntu 12.04

The my.cnf snip seees to have everything commented out. Usually the log would be /var/log/mysqld.log or /var/log/mysql/error.log.

I have not seen this issue with MySQL starting before and I am not currently using 5.5 or 12.04. I am about to migrate.

An absolute guess on my part is that mysql was installed b/f the recipe ran and something is colliding in terms of the server trying to gain access to a resource.

Sorry I cannot be more specific.

Boyd

On Sun, Nov 11, 2012 at 11:05 AM, S Ahmed <sahmed1020@gmail.commailto:sahmed1020@gmail.com> wrote:
Boyd/Paul,

Thanks for the help.

Boyd, according to my.cnf it seems logging is in syslog, it reads:

* Logging and Replication

Both location gets rotated by the cronjob.

Be aware that this log type is a performance killer.

#log = /var/log/mysql/mysql.log

Error logging goes to syslog. This is a Debian improvement :slight_smile:

restart mysql
estart: Rejected send message, 1 matched rules; type="method_call", sender=":1.7" (uid=1000 pid=1128 comm="restart mysql ") interface="com.ubuntu.Upstart0_6.Job" member="Restart" error name="(unset)" requested_reply="0" destination="com.ubuntu.Upstart" (uid=0 pid=1 comm="/sbin/init")
sudo restart mysql
restart: Unknown instance:

syslog shows:

Nov 11 16:46:23 removed kernel: [54062688.327783] audit_printk_skb: 9 callbacks suppressed
Nov 11 16:46:23 removed kernel: [54062688.327787] type=1400 audit(1352652383.807:14): apparmor="DENIED" operation="open" parent=1 profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=745 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:23 removed kernel: [54062688.329541] init: mysql main process (745) terminated with status 1
Nov 11 16:46:23 removed kernel: [54062688.329586] init: mysql main process ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.210421] init: mysql post-start process (752) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.225176] type=1400 audit(1352652384.703:15): apparmor="STATUS" operation="profile_replace" name="/usr/sbin/mysqld" pid=821 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.244978] type=1400 audit(1352652384.723:16): apparmor="DENIED" operation="open" parent=1 profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=825 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.246024] init: mysql main process (825) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.246068] init: mysql main process ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.255999] init: mysql post-start process (826) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.272705] type=1400 audit(1352652384.751:17): apparmor="STATUS" operation="profile_replace" name="/usr/sbin/mysqld" pid=841 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.291636] type=1400 audit(1352652384.771:18): apparmor="DENIED" operation="open" parent=1 profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=845 comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.292787] init: mysql main process (845) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.292832] init: mysql respawning too fast, stopped
Nov 11 16:46:29 removed ntpdate[470]: adjust time server 91.189.94.4 offset 0.408380 sec
Nov 11 16:46:31 ip-10removed-114-198-63 kernel: [54062696.205953] eth0: no IPv6 routers present

On Sun, Nov 11, 2012 at 7:57 AM, Boyd Hemphill <behemphi@gmail.commailto:behemphi@gmail.com> wrote:

Small error of fact from Paul. It should be 'restart mysql' on ubuntu because of upstart.

Random Stabs
12.04 uses mysql 5.5 so that might be worth looking at as a cause.

The mysql error lodging is usually pretty helpful. It will either be in /var/log or where /etc/mysql/ my.cnf says it will be

On Nov 10, 2012 11:38 PM, "Paul Graydon" <paul@paulgraydon.co.ukmailto:paul@paulgraydon.co.uk> wrote:
On 11/10/2012 07:15 PM, S Ahmed wrote:
service[mysql] (mysql::server line 71) had an error: Mixlib::ShellOut::ShellCommandFailed: Expected process to exit with [0], but received '1'
This is telling you that the service resource was run but the exit status of the command it ran was 1 instead of 0, which usually indicates an error of some description.
Unfortunately it's impossible to tell what that error is from what chef has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul

8

Ok I just swapped my mysql recipe with the latest from:
https://github.com/opscode-cookbooks

My old ec2 instance is now back in the clouds so I am starting over :slight_smile:

*** Install is now failing due to this:
GitHub - sous-chefs/mysql: Development repository for the mysql cookbook Confused, where
do I put the following, it says in the json_attr?? Which file is that?

{
"mysql": {
"server_root_password": "iloverandompasswordsbutthiswilldo",
"server_repl_password": "iloverandompasswordsbutthiswilldo",
"server_debian_password": "iloverandompasswordsbutthiswilldo"
},
"run_list":["recipe[mysql::server]"]
}

On Sun, Nov 11, 2012 at 4:08 PM, Charles Johnson charles@opscode.comwrote:

Could it be related to this issue?

init.d - Can't start mysql - mysql respawning too fast, stopped - Ask Ubuntu

Thanks,
--Charles

--
Charles Johnson

Solutions Engineer - Opscode, Inc.****

(510) 545-9485 - Direct Line****

charles@opscode.com

From: Boyd Hemphill behemphi@gmail.com
Reply-To: "chef@lists.opscode.com" chef@lists.opscode.com
Date: Sunday, November 11, 2012 10:52 AM
To: "chef@lists.opscode.com" chef@lists.opscode.com
Subject: [chef] Re: Re: Re: Re: mysql recipe error on ubuntu 12.04

The my.cnf snip seees to have everything commented out. Usually the log
would be /var/log/mysqld.log or /var/log/mysql/error.log.

I have not seen this issue with MySQL starting before and I am not
currently using 5.5 or 12.04. I am about to migrate.

An absolute guess on my part is that mysql was installed b/f the recipe
ran and something is colliding in terms of the server trying to gain access
to a resource.

Sorry I cannot be more specific.

Boyd

On Sun, Nov 11, 2012 at 11:05 AM, S Ahmed sahmed1020@gmail.com wrote:

Boyd/Paul,

Thanks for the help.

Boyd, according to my.cnf it seems logging is in syslog, it reads:

* Logging and Replication

Both location gets rotated by the cronjob.

Be aware that this log type is a performance killer.

#log = /var/log/mysql/mysql.log

Error logging goes to syslog. This is a Debian improvement :slight_smile:

restart mysql
estart: Rejected send message, 1 matched rules; type="method_call",
sender=":1.7" (uid=1000 pid=1128 comm="restart mysql ")
interface="com.ubuntu.Upstart0_6.Job" member="Restart" error name="(unset)"
requested_reply="0" destination="com.ubuntu.Upstart" (uid=0 pid=1
comm="/sbin/init")
sudo restart mysql
restart: Unknown instance:

syslog shows:

Nov 11 16:46:23 removed kernel: [54062688.327783] audit_printk_skb: 9
callbacks suppressed
Nov 11 16:46:23 removed kernel: [54062688.327787] type=1400
audit(1352652383.807:14): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=745
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:23 removed kernel: [54062688.329541] init: mysql main
process (745) terminated with status 1
Nov 11 16:46:23 removed kernel: [54062688.329586] init: mysql main
process ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.210421] init: mysql post-start
process (752) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.225176] type=1400
audit(1352652384.703:15): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=821 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.244978] type=1400
audit(1352652384.723:16): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=825
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.246024] init: mysql main
process (825) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.246068] init: mysql main
process ended, respawning
Nov 11 16:46:24 removed kernel: [54062689.255999] init: mysql post-start
process (826) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.272705] type=1400
audit(1352652384.751:17): apparmor="STATUS" operation="profile_replace"
name="/usr/sbin/mysqld" pid=841 comm="apparmor_parser"
Nov 11 16:46:24 removed kernel: [54062689.291636] type=1400
audit(1352652384.771:18): apparmor="DENIED" operation="open" parent=1
profile="/usr/sbin/mysqld" name="/etc/mysql/mysql/conf.d/" pid=845
comm="mysqld" requested_mask="r" denied_mask="r" fsuid=0 ouid=106
Nov 11 16:46:24 removed kernel: [54062689.292787] init: mysql main
process (845) terminated with status 1
Nov 11 16:46:24 removed kernel: [54062689.292832] init: mysql respawning
too fast, stopped
Nov 11 16:46:29 removed ntpdate[470]: adjust time server 91.189.94.4
offset 0.408380 sec
Nov 11 16:46:31 ip-10removed-114-198-63 kernel: [54062696.205953] eth0:
no IPv6 routers present

On Sun, Nov 11, 2012 at 7:57 AM, Boyd Hemphill behemphi@gmail.comwrote:

Small error of fact from Paul. It should be 'restart mysql' on ubuntu
because of upstart.

Random Stabs
12.04 uses mysql 5.5 so that might be worth looking at as a cause.

The mysql error lodging is usually pretty helpful. It will either be in
/var/log or where /etc/mysql/ my.cnf says it will be
On Nov 10, 2012 11:38 PM, "Paul Graydon" paul@paulgraydon.co.uk
wrote:

On 11/10/2012 07:15 PM, S Ahmed wrote:

service[mysql] (mysql::server line 71) had an error: Mixlib::ShellOut::
**ShellCommandFailed: Expected process to exit with [0], but received
'1'

This is telling you that the service resource was run but the exit
status of the command it ran was 1 instead of 0, which usually indicates an
error of some description.
Unfortunately it's impossible to tell what that error is from what chef
has provided.
You'll need to run:

service mysql restart

yourself and see what it returns on the command line.

Paul