Bug #48385 Crash and restart : Invalid pointer
Submitted: 28 Oct 18:43 Modified: 18 Nov 9:10
Reporter: Francis Besset
Status: Need Feedback
Category:Server: InnoDB Severity:S1 (Critical)
Version:5.0.51a-24+lenny2-log OS:Linux (Debian Lenny)
Assigned to: Target Version:
Tags: invalid pointer crash restart

[28 Oct 18:43] Francis Besset
Description:
Hello,

This afternoon, my mysql server have restart.
I have the detail in my log file syslog of Debian.

Oct 28 17:34:40 ns38999 kernel: grsec: From 81.65.xxx.xxx: signal 11 sent to
/usr/sbin/mysqld[mysqld:26830] uid/euid:103/103 gid/egid:106/106, parent
/usr/bin/mysqld_safe[mysqld_safe:24960] uid/euid:0/0 gid/eg$
Oct 28 17:34:40 ns38999 mysqld[14008]: 091028 17:34:40 - mysqld got signal 11;
Oct 28 17:34:40 ns38999 mysqld[14008]: This could be because you hit a bug. It is also
possible that this binary
Oct 28 17:34:40 ns38999 mysqld[14008]: or one of the libraries it was linked against is
corrupt, improperly built,
Oct 28 17:34:40 ns38999 mysqld[14008]: or misconfigured. This error can also be caused by
malfunctioning hardware.
Oct 28 17:34:40 ns38999 mysqld[14008]: We will try our best to scrape up some info that
will hopefully help diagnose
Oct 28 17:34:40 ns38999 mysqld[14008]: the problem, but since we have already crashed,
something is definitely wrong
Oct 28 17:34:40 ns38999 mysqld[14008]: and this may fail.
Oct 28 17:34:40 ns38999 mysqld[14008]:
Oct 28 17:34:40 ns38999 mysqld[14008]: key_buffer_size=16777216
Oct 28 17:34:40 ns38999 mysqld[14008]: read_buffer_size=131072
Oct 28 17:34:40 ns38999 mysqld[14008]: max_used_connections=31
Oct 28 17:34:40 ns38999 mysqld[14008]: max_connections=125
Oct 28 17:34:40 ns38999 mysqld[14008]: threads_connected=5
Oct 28 17:34:40 ns38999 mysqld[14008]: It is possible that mysqld could use up to
Oct 28 17:34:40 ns38999 mysqld[14008]: key_buffer_size + (read_buffer_size +
sort_buffer_size)*max_connections = 288383 K
Oct 28 17:34:40 ns38999 mysqld[14008]: bytes of memory
Oct 28 17:34:40 ns38999 mysqld[14008]: Hope that's ok; if not, decrease some variables in
the equation.
Oct 28 17:34:40 ns38999 mysqld[14008]:
Oct 28 17:34:40 ns38999 mysqld[14008]: thd=0x26d4a20
Oct 28 17:34:40 ns38999 mysqld[14008]: Attempting backtrace. You can use the following
information to find out
Oct 28 17:34:40 ns38999 mysqld[14008]: where mysqld died. If you see no messages after
this, something went
Oct 28 17:34:40 ns38999 mysqld[14008]: terribly wrong...
Oct 28 17:34:40 ns38999 mysqld[14008]: Cannot determine thread, fp=0x26d4a20, backtrace
may not be correct.
Oct 28 17:34:40 ns38999 mysqld[14008]: Bogus stack limit or frame pointer, fp=0x26d4a20,
stack_bottom=0x44580000, thread_stack=131072, aborting backtrace.
Oct 28 17:34:40 ns38999 mysqld[14008]: Trying to get some variables.
Oct 28 17:34:40 ns38999 mysqld[14008]: Some pointers may be invalid and cause the dump to
abort...
Oct 28 17:34:40 ns38999 mysqld[14008]: thd->query at 0x7fbb9404dd70  is invalid pointer
Oct 28 17:34:40 ns38999 mysqld[14008]: thd->thread_id=356069
Oct 28 17:34:40 ns38999 mysqld[14008]: The manual page at
http://www.mysql.com/doc/en/Crashing.html contains
Oct 28 17:34:40 ns38999 mysqld[14008]: information that should help you find out what is
causing the crash.
Oct 28 17:34:40 ns38999 mysqld[14008]: pure virtual method called
Oct 28 17:34:41 ns38999 mysqld_safe[10799]: Number of processes running now: 0
Oct 28 17:34:41 ns38999 mysqld_safe[10803]: restarted
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Log scan progressed past the checkpoint
lsn 2 1426093069
Oct 28 17:34:41 ns38999 mysqld[10806]: 091028 17:34:41  InnoDB: Database was not shut
down normally!
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Starting crash recovery.
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Reading tablespace information from the
.ibd files...
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Restoring possible half-written data pages
from the doublewrite
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: buffer...
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Doing recovery: scanned up to log sequence
number 2 1426104454
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Transaction 0 55487030 was in the XA
prepared state.
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: 2 transaction(s) which must be rolled back
or cleaned up
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: in total 4 row operations to undo
Oct 28 17:34:41 ns38999 mysqld[10806]: InnoDB: Trx id counter is 0 55487488
Oct 28 17:34:41 ns38999 mysqld[10806]: 091028 17:34:41  InnoDB: Starting an apply batch
of log records to the database...
Oct 28 17:34:42 ns38999 mysqld[10806]: 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 46 47 48 49 5$
Oct 28 17:34:42 ns38999 mysqld[10806]: InnoDB: Apply batch completed
Oct 28 17:34:42 ns38999 mysqld[10806]: InnoDB: Last MySQL binlog file position 0
42729252, file name /var/log/mysql/mysql-bin.000104
Oct 28 17:34:42 ns38999 mysqld[10806]: InnoDB: Starting in background the rollback of
uncommitted transactions
Oct 28 17:34:42 ns38999 mysqld[10806]: 091028 17:34:42  InnoDB: Rolling back trx with id
0 55487029, 4 rows to undo
Oct 28 17:34:42 ns38999 mysqld[10806]: 091028 17:34:42  InnoDB: Started; log sequence
number 2 1426104454
Oct 28 17:34:42 ns38999 mysqld[10806]: 091028 17:34:42 [Note] Recovering after a crash
using /var/log/mysql/mysql-bin
Oct 28 17:34:42 ns38999 mysqld[10806]:
Oct 28 17:34:42 ns38999 mysqld[10806]: InnoDB: Rolling back of trx id 0 55487029
completed
Oct 28 17:34:42 ns38999 mysqld[10806]: 091028 17:34:42  InnoDB: Rollback of non-prepared
transactions completed
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43 [Note] Starting crash recovery...
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43  InnoDB: Starting recovery for XA
transactions...
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43  InnoDB: Transaction 0 55487030 in
prepared state after recovery
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43  InnoDB: Transaction contains
changes to 1 rows
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43  InnoDB: 1 transactions in
prepared state after recovery
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43 [Note] Found 1 prepared
transaction(s) in InnoDB
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43 [Note] Crash recovery finished.
Oct 28 17:34:43 ns38999 mysqld[10806]: 091028 17:34:43 [Note] /usr/sbin/mysqld: ready for
connections.
Oct 28 17:34:43 ns38999 mysqld[10806]: Version: '5.0.51a-24+lenny2-log'  socket:
'/var/run/mysqld/mysqld.sock'  port: 3306  (Debian)

How to repeat:
I don't know.
[28 Oct 18:51] Valeriy Kravchuk
Thank you for the problem report. Please, send your my.cnf file content and the results
of:

uname -a
free

Linux commands. 

Had you noted what SQL statement(s) or applications were executed at the moment of crash?
[28 Oct 19:19] Francis Besset
Hello,
Thank you for you response.

my.cnf :
~# cat /etc/mysql/my.cnf 
#
# The MySQL database server configuration file.
#
# You can copy this to one of:
# - "/etc/mysql/my.cnf" to set global options,
# - "~/.my.cnf" to set user-specific options.
# 
# One can use all long options that the program supports.
# Run program with --help to get a list of available options and with
# --print-defaults to see which it would actually understand and use.
#
# For explanations see
# http://dev.mysql.com/doc/mysql/en/server-system-variables.html

# This will be passed to all mysql clients
# It has been reported that passwords should be enclosed with ticks/quotes
# escpecially if they contain "#" chars...
# Remember to edit /etc/mysql/debian.cnf when changing the socket location.
[client]
port		= 3306
socket		= /var/run/mysqld/mysqld.sock

# Here is entries for some specific programs
# The following values assume you have at least 32M ram

# This was formally known as [safe_mysqld]. Both versions are currently parsed.
[mysqld_safe]
socket		= /var/run/mysqld/mysqld.sock
nice		= 0

[mysqld]
#
# * Basic Settings
#
user		= mysql
pid-file	= /var/run/mysqld/mysqld.pid
socket		= /var/run/mysqld/mysqld.sock
port		= 3306
basedir		= /usr
datadir		= /var/lib/mysql
tmpdir		= /tmp
language	= /usr/share/mysql/english
skip-external-locking
#
# Instead of skip-networking the default is now to listen only on
# localhost which is more compatible and is not less secure.
bind-address		= 127.0.0.1
#
# * Fine Tuning
#
key_buffer		= 16M
max_allowed_packet	= 16M
thread_stack		= 128K
thread_cache_size	= 8

max_heap_table_size	= 32M
tmp_table_size		= 64M

# This replaces the startup script and checks MyISAM tables if needed
# the first time they are touched
myisam-recover		= BACKUP
max_connections        = 125
table_cache            = 350
#thread_concurrency     = 10
#
# * Query Cache Configuration
#
query_cache_limit       = 1M
query_cache_size        = 16M
#
# * 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 :)
#
# Here you can see queries with especially long duration
log_slow_queries	= /var/log/mysql/mysql-slow.log
long_query_time = 5
#log-queries-not-using-indexes

#low_priority_updates	= 1
#concurrent_insert	= 2
#
# The following can be used as easy to replay backup logs or for replication.
# note: if you are setting up a replication slave, see README.Debian about
#       other settings you may need to change.
#server-id		= 1
log_bin			= /var/log/mysql/mysql-bin.log
sync-binlog		= 1
expire_logs_days	= 10
max_binlog_size         = 100M
#binlog_do_db		= include_database_name
#binlog_ignore_db	= include_database_name
#
# * BerkeleyDB
#
# Using BerkeleyDB is now discouraged as its support will cease in 5.1.12.
skip-bdb
#
# * InnoDB
#
# InnoDB is enabled by default with a 10MB datafile in /var/lib/mysql/.
# Read the manual for more InnoDB related options. There are many!
# You might want to disable InnoDB to shrink the mysqld process by circa 100MB.
#skip-innodb
#
# * Security Features
#
# Read the manual, too, if you want chroot!
# chroot = /var/lib/mysql/
#
# For generating SSL certificates I recommend the OpenSSL GUI "tinyca".
#
# ssl-ca=/etc/mysql/cacert.pem
# ssl-cert=/etc/mysql/server-cert.pem
# ssl-key=/etc/mysql/server-key.pem

[mysqldump]
quick
quote-names
max_allowed_packet	= 16M

[mysql]
#no-auto-rehash	# faster start of mysql but no tab completition

[isamchk]
key_buffer		= 16M

#
# * NDB Cluster
#
# See /usr/share/doc/mysql-server-*/README.Debian for more information.
#
# The following configuration is read by the NDB Data Nodes (ndbd processes)
# not from the NDB Management Nodes (ndb_mgmd processes).
#
# [MYSQL_CLUSTER]
# ndb-connectstring=127.0.0.1

#
# * IMPORTANT: Additional settings that can override those from this file!
#   The files must end with '.cnf', otherwise they'll be ignored.
#
!includedir /etc/mysql/conf.d/

The folder /etc/mysql/conf.d is empty.

~# uname -a
Linux ns38999.ovh.net 2.6.27.10-grsec-xxxx-grs-ipv4-64 #6 SMP Fri Aug 14 10:29:05 UTC
2009 x86_64 GNU/Linux

~# free
             total       used       free     shared    buffers     cached
Mem:       2036744    1364980     671764          0     144072     723760
-/+ buffers/cache:     497148    1539596
Swap:      8385912       2724    8383188

Applications run at this moment : Apache, lighttpd, postfix.

I have the binary log.
I have mainly SELECT request with inner join between the tables.
The requests INSERT have often of ON DUPLICATE KEY UPDATE.

Regards.
[30 Oct 13:54] Francis Besset
I still had this problem today except that que MySQL has not restarted again
automatically.

Oct 30 12:04:39 ns38999 kernel: grsec: From 81.65.xxx.xxx: signal 11 sent to
/usr/sbin/mysqld[mysqld:26469] uid/euid:103/103 gid/egid:106/106, parent
/usr/bin/mysqld_safe[mysqld_safe:24960] uid/euid:0/0 gid/eg$
Oct 30 12:04:39 ns38999 mysqld[10806]: 091030 12:04:39 - mysqld got signal 11;
Oct 30 12:04:39 ns38999 mysqld[10806]: This could be because you hit a bug. It is also
possible that this binary
Oct 30 12:04:39 ns38999 mysqld[10806]: or one of the libraries it was linked against is
corrupt, improperly built,
Oct 30 12:04:39 ns38999 mysqld[10806]: or misconfigured. This error can also be caused by
malfunctioning hardware.
Oct 30 12:04:39 ns38999 mysqld[10806]: We will try our best to scrape up some info that
will hopefully help diagnose
Oct 30 12:04:39 ns38999 mysqld[10806]: the problem, but since we have already crashed,
something is definitely wrong
Oct 30 12:04:39 ns38999 mysqld[10806]: and this may fail.
Oct 30 12:04:39 ns38999 mysqld[10806]:
Oct 30 12:04:39 ns38999 mysqld[10806]: key_buffer_size=16777216
Oct 30 12:04:39 ns38999 mysqld[10806]: read_buffer_size=131072
Oct 30 12:04:39 ns38999 mysqld[10806]: max_used_connections=42
Oct 30 12:04:39 ns38999 mysqld[10806]: max_connections=125
Oct 30 12:04:39 ns38999 mysqld[10806]: threads_connected=4
Oct 30 12:04:39 ns38999 mysqld[10806]: It is possible that mysqld could use up to
Oct 30 12:04:39 ns38999 mysqld[10806]: key_buffer_size + (read_buffer_size +
sort_buffer_size)*max_connections = 288383 K
Oct 30 12:04:39 ns38999 mysqld[10806]: bytes of memory
Oct 30 12:04:39 ns38999 mysqld[10806]: Hope that's ok; if not, decrease some variables in
the equation.
Oct 30 12:04:39 ns38999 mysqld[10806]:
Oct 30 12:04:39 ns38999 mysqld[10806]: thd=0x7f74dc05b2b0
Oct 30 12:04:39 ns38999 mysqld[10806]: Attempting backtrace. You can use the following
information to find out
Oct 30 12:04:39 ns38999 mysqld[10806]: where mysqld died. If you see no messages after
this, something went   
Oct 30 12:04:39 ns38999 mysqld[10806]: terribly wrong...
Oct 30 12:04:39 ns38999 mysqld[10806]: Cannot determine thread, fp=0x7f74dc05b2b0,
backtrace may not be correct.
Oct 30 12:04:39 ns38999 mysqld[10806]: Bogus stack limit or frame pointer,
fp=0x7f74dc05b2b0, stack_bottom=0x41030000, thread_stack=131072, aborting backtrace.
Oct 30 12:04:39 ns38999 mysqld[10806]: Trying to get some variables.
Oct 30 12:04:39 ns38999 mysqld[10806]: Some pointers may be invalid and cause the dump to
abort...
Oct 30 12:04:39 ns38999 mysqld[10806]: thd->query at 0x7f74e403c580  is invalid pointer
Oct 30 12:04:39 ns38999 mysqld[10806]: thd->thread_id=471621
Oct 30 12:04:39 ns38999 mysqld[10806]: The manual page at
http://www.mysql.com/doc/en/Crashing.html contains
Oct 30 12:04:39 ns38999 mysqld[10806]: information that should help you find out what is
causing the crash.
Oct 30 12:04:39 ns38999 kernel: mysqld[10805]: segfault at 8 ip 00000000005d1712 sp
00007ffff22055a0 error 6 in mysqld[400000+742000]
Oct 30 12:04:39 ns38999 kernel: grsec: From 81.65.xxx.xxx: signal 11 sent to
/usr/sbin/mysqld[mysqld:10805] uid/euid:103/103 gid/egid:106/106, parent
/usr/bin/mysqld_safe[mysqld_safe:24960] uid/euid:0/0 gid/eg$
Oct 30 12:04:39 ns38999 mysqld_safe[11649]: ended

When I have a SQL problem, I send an automatic email report.
The first two messages have different mistakes of others:
[SQL-ConnectError] SQLSTATE[HY000] [2013] Lost connection to MySQL server at 'reading
initial communication packet', system error: 104
And :
[SQL-ConnectError] SQLSTATE[HY000] [2013] Lost connection to MySQL server at 'reading
initial communication packet', system error: 0

Francis.
[18 Nov 9:10] Sveta Smirnova
Thank you for the feedback.

At first glance setup looks fine. But version 5.0.51 is too old and any bugs were fixed
since. Please upgrade to current version 5.0.87, try with it and if problem still exists
try to find query which caused failure. You can use general query log or proxy (for
example, MySQL Proxy) for it.