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

[6 Aug 2013 20:53] Vinz Meier
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)
[6 Aug 2013 20:54] Vinz Meier
strace output

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

[6 Aug 2013 21:14] Vinz Meier
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
[27 Sep 2013 17:25] Umesh Shastry
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
[28 Oct 2013 1:00] Bugs System
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".