MySQL Bugs: #69942: mysqld fails to start

Bug #69942	mysqld fails to start
Submitted:	6 Aug 2013 20:53	Modified:	27 Oct 2013 17:25
Reporter:	Vinz Meier	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Cluster: Cluster (NDB) storage engine	Severity:	S3 (Non-critical)
Version:	7.3.2	OS:	Linux (rhel 6.4 x86_64)
Assigned to:		CPU Architecture:	Any

Description:
Greetings

There is a problem with the latest mysql-cluster on rhel 6.4

the problem is not within ndb, but mysqld provided my the cluster package

long story short, mysqld fails to start

# rpm -qa|grep -i mysql
MySQL-Cluster-server-gpl-7.3.2-1.el6.x86_64
MySQL-Cluster-shared-compat-gpl-7.3.2-1.el6.x86_64
MySQL-Cluster-client-gpl-7.3.2-1.el6.x86_64
MySQL-Cluster-shared-gpl-7.3.2-1.el6.x86_64

# uname -a
Linux vimdzget-nvrp1d.bluewin.ch 2.6.32-358.11.1.el6.x86_64 #1 SMP Wed May 15 10:48:38 EDT 2013 x86_64 x86_64 x86_64 GNU/Linux

# cat /etc/my.cnf
[mysqld]
ndbcluster
ndb-connectstring = vimdzget-nvrp1d.bluewin.ch
ndb-cluster-connection-pool = 1

ndb-force-send = 1
ndb-use-exact-count = 0
ndb-extra-logging = 1
ndb-autoincrement-prefetch-sz = 4096
#unknown in ndb7.3 engine-condition-pushdown = 1

log-err=error.log
key_buffer = 256M
max_allowed_packet = 16M
sort_buffer_size = 512K
read_buffer_size = 256K
read_rnd_buffer_size = 512K
myisam_sort_buffer_size = 8M
memlock
sysdate_is_now
max-connections = 4096
thread-cache-size = 1500
query-cache-type = 0
query-cache-size = 0
table-open-cache = 1024
#unknown in ndb7.3 table-cache = 512
lower-case-table-names = 0

server-id = 100
ndb-log-updated-only = 1
ndb-log-update-as-write = 0
 binlog-format = ROW
 log-bin = /var/lib/mysql/master-bin
 log-bin-index = /var/lib/mysql/master-bin.index
 master-info-file = /var/lib/mysql/master-bin.info
 log-slave-updates = 1
 sync-binlog = 0
 relay-log = /var/lib/mysql/relay-bin
 relay-log-index = /var/lib/mysql/relay-bin.index
 relay-log-info-file = /var/lib/mysql/relay-bin.info
 show-slave-auth-info = 1
# skip-slave-start = 1
 binlog-do-db = mysql
 binlog-do-db = NSS
 replicate-do-db = mysql
 replicate-do-db = NSS
 replicate-wild-ignore-table = NSS.TNSSA_CACHE_CONFIG%
 expire_logs_days = 2
 max_binlog_size = 268435456
 slave-skip-errors = all

datadir = /var/lib/mysql
socket = /var/lib/mysql/mysql.sock
user = mysql
# Disabling symbolic-links is recommended to prevent assorted security risks
symbolic-links = 0
ndb-wait-setup = 120

[mysql_cluster]
ndb-connectstring = vimdzget-nvrp1d.bluewin.ch

[mysqld_safe]
log-error=/var/log/mysqld.log
pid-file=/var/run/mysqld/mysqld.pid

How to repeat:
# /etc/init.d/mysql start
Starting MySQL....... ERROR! The server quit without updating PID file (/var/lib/mysql/vimdzget-nvrp1d.bluewin.ch.pid).

# cat /var/log/mysqld.log
130806 22:38:51 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
2013-08-06 22:38:54 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-08-06 22:38:54 29152 [Note] Plugin 'FEDERATED' is disabled.
2013-08-06 22:38:54 29152 [Note] InnoDB: The InnoDB memory heap is disabled
2013-08-06 22:38:54 29152 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-08-06 22:38:54 29152 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-08-06 22:38:54 29152 [Note] InnoDB: Using Linux native AIO
2013-08-06 22:38:54 29152 [Note] InnoDB: Using CPU crc32 instructions
2013-08-06 22:38:54 29152 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2013-08-06 22:38:54 29152 [Note] InnoDB: Completed initialization of buffer pool
2013-08-06 22:38:54 29152 [Note] InnoDB: Highest supported file format is Barracuda.
2013-08-06 22:38:54 29152 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1719290
2013-08-06 22:38:54 29152 [Note] InnoDB: Database was not shutdown normally!
2013-08-06 22:38:54 29152 [Note] InnoDB: Starting crash recovery.
2013-08-06 22:38:54 29152 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-08-06 22:38:54 29152 [Note] InnoDB: Restoring possible half-written data pages 
2013-08-06 22:38:54 29152 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1719316
2013-08-06 22:38:55 29152 [Note] InnoDB: 128 rollback segment(s) are active.
2013-08-06 22:38:55 29152 [Note] InnoDB: Waiting for purge to start
2013-08-06 22:38:55 29152 [Note] InnoDB: 5.6.11 started; log sequence number 1719316
2013-08-06 22:38:55 29152 [Note] NDB: NodeID is 11, management server 'vimdzget-nvrp1d.bluewin.ch:1186'
2013-08-06 22:38:55 29152 [Note] NDB[0]: NodeID: 11, all storage nodes connected
2013-08-06 22:38:55 29152 [Note] Starting Cluster Binlog Thread
2013-08-06 22:38:55 29152 [Note] Recovering after a crash using /var/lib/mysql/master-bin
2013-08-06 22:38:55 29152 [Note] Starting crash recovery...
2013-08-06 22:38:55 29152 [Note] Crash recovery finished.
130806 22:38:58 mysqld_safe mysqld from pid file /var/lib/mysql/vimdzget-nvrp1d.bluewin.ch.pid ended

strace -f /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql  --log-error=/var/log/mysqld.log --pid-file=/var/lib/mysql/vimdzget-nvrp1d.bluewin.ch.pid --socket=/var/lib/mysql/mysql.sock < /dev/null

partial output is attached

Thanks & regards
Vinz

Suggested fix:
to me it looks like a problem with setreuid, but of course I could be wrong

[pid  3946] setreuid(4294967295, 0 <unfinished ...>

# grep mysql /etc/passwd
mysql:x:497:497:MySQL server:/var/lib/mysql:/bin/bash

# id mysql
uid=497(mysql) gid=497(mysql) groups=497(mysql)

strace output

Attachment: mysqld_strace.txt (text/plain), 24.58 KiB.

starting mysqld as user mysql works, sort of...

-bash-4.1$ id
uid=497(mysql) gid=497(mysql) groups=497(mysql)

-bash-4.1$ >/var/log/mysqld.log; /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql  --log-error=/var/log/mysqld.log --pid-file=/var/lib/mysql/vimdzget-nvrp1d.bluewin.ch.pid --socket=/var/lib/mysql/mysql.sock < /dev/null
2013-08-06 23:12:35 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2013-08-06 23:12:35 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 214  table_cache: 400

# cat /var/log/mysqld.log 
2013-08-06 23:12:36 19497 [Note] Plugin 'FEDERATED' is disabled.
2013-08-06 23:12:36 19497 [Note] InnoDB: The InnoDB memory heap is disabled
2013-08-06 23:12:36 19497 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2013-08-06 23:12:36 19497 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-08-06 23:12:36 19497 [Note] InnoDB: Using Linux native AIO
2013-08-06 23:12:36 19497 [Note] InnoDB: Using CPU crc32 instructions
2013-08-06 23:12:36 19497 [Note] InnoDB: Initializing buffer pool, size = 128.0M
2013-08-06 23:12:36 19497 [Note] InnoDB: Completed initialization of buffer pool
2013-08-06 23:12:36 19497 [Note] InnoDB: Highest supported file format is Barracuda.
2013-08-06 23:12:36 19497 [Note] InnoDB: Log scan progressed past the checkpoint lsn 1719476
2013-08-06 23:12:36 19497 [Note] InnoDB: Database was not shutdown normally!
2013-08-06 23:12:36 19497 [Note] InnoDB: Starting crash recovery.
2013-08-06 23:12:36 19497 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-08-06 23:12:36 19497 [Note] InnoDB: Restoring possible half-written data pages 
2013-08-06 23:12:36 19497 [Note] InnoDB: from the doublewrite buffer...
InnoDB: Doing recovery: scanned up to log sequence number 1719486
2013-08-06 23:12:36 19497 [Note] InnoDB: 128 rollback segment(s) are active.
2013-08-06 23:12:36 19497 [Note] InnoDB: Waiting for purge to start
2013-08-06 23:12:36 19497 [Note] InnoDB: 5.6.11 started; log sequence number 1719486
2013-08-06 23:12:36 19497 [Note] NDB: NodeID is 11, management server 'vimdzget-nvrp1d.bluewin.ch:1186'
2013-08-06 23:12:37 19497 [Note] NDB[0]: NodeID: 11, all storage nodes connected
2013-08-06 23:12:37 19497 [Note] Starting Cluster Binlog Thread
2013-08-06 23:12:37 19497 [Note] Recovering after a crash using /var/lib/mysql/master-bin
2013-08-06 23:12:37 19497 [Note] Starting crash recovery...
2013-08-06 23:12:37 19497 [Note] Crash recovery finished.
2013-08-06 23:12:37 19497 [Note] Server hostname (bind-address): '*'; port: 3306
2013-08-06 23:12:37 19497 [Note] IPv6 is available.
2013-08-06 23:12:37 19497 [Note]   - '::' resolves to '::';
2013-08-06 23:12:37 19497 [Note] Server socket created on IP: '::'.
2013-08-06 23:12:37 19497 [Note] Event Scheduler: Loaded 0 events
2013-08-06 23:12:37 19497 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.6.11-ndb-7.3.2-cluster-gpl-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Cluster Community Server (GPL)
2013-08-06 23:12:37 19497 [Note] NDB Binlog: Ndb tables initially read only.
2013-08-06 23:12:37 19497 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_schema
2013-08-06 23:12:37 19497 [Note] NDB Binlog: logging ./mysql/ndb_schema (UPDATED,USE_UPDATE)
2013-08-06 23:12:37 19497 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_apply_status
2013-08-06 23:12:37 19497 [Note] NDB Binlog: logging ./mysql/ndb_apply_status (UPDATED,USE_UPDATE)
2013-08-06 23:12:37 19497 [Note] NDB: Cleaning stray tables from database 'information_schema'
2013-08-06 23:12:37 19497 [Note] NDB: Cleaning stray tables from database 'NSS'
2013-08-06 23:12:37 19497 [Note] NDB: Cleaning stray tables from database 'ndbinfo'
2013-08-06 23:12:37 19497 [Note] NDB: Cleaning stray tables from database 'performance_schema'
2013-08-06 23:12:37 19497 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_index_stat_sample
2013-08-06 23:12:37 19497 [Note] NDB Binlog: logging ./mysql/ndb_index_stat_sample (UPDATED,USE_UPDATE)
2013-08-06 23:12:37 19497 [Note] NDB Binlog: DISCOVER TABLE Event: REPL$mysql/ndb_index_stat_head
2013-08-06 23:12:37 19497 [Note] NDB Binlog: logging ./mysql/ndb_index_stat_head (UPDATED,USE_UPDATE)
2013-08-06 23:12:37 [NdbApi] INFO     -- Flushing incomplete GCI:s < 315422/11
2013-08-06 23:12:37 [NdbApi] INFO     -- Flushing incomplete GCI:s < 315422/11
2013-08-06 23:12:37 19497 [Note] NDB Binlog: starting log at epoch 315422/11
2013-08-06 23:12:37 19497 [Note] NDB Binlog: ndb tables writable

Hello Vinz,

Thank you for the report.
I can not repeat described behavior with/without starting with mysql user.
If you are still having this issue then could you please provide the complete mysqld log?

Thanks,
Umesh

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".