Gentoo Websites Logo
Go to: Gentoo Home Documentation Forums Lists Bugs Planet Store Wiki Get Gentoo!

Bug 444054

Summary: dev-db/mysql-5.1.66 crashes in replication setup
Product: Gentoo Linux Reporter: Petre Rodan <pr.gentoo-acct>
Component: [OLD] ServerAssignee: Gentoo Linux MySQL bugs team <mysql-bugs>
Status: RESOLVED OBSOLETE    
Severity: normal CC: alexanderyt
Priority: Normal    
Version: unspecified   
Hardware: AMD64   
OS: Linux   
Whiteboard:
Package list:
Runtime testing required: ---

Description Petre Rodan 2012-11-20 16:32:00 UTC
after the upgrade from 5.1.62-r1 to 5.1.66 mysql starts crashing with segfault. this happens on the production server, where this mysql is a slave in a replication setup. the configuration was not changed after the upgrade and all previous versions worked fine. right after the upgrade:

121120 10:01:39 [Note] Event Scheduler: Purging the queue. 0 events
121120 10:01:39 [Note] Error reading relay log event: slave SQL thread was killed
121120 10:01:39 [Note] Slave I/O thread killed while reading event
121120 10:01:39 [Note] Slave I/O thread exiting, read up to log 'skycaves.000547', position 607196663
121120 10:01:41  InnoDB: Starting shutdown...
121120 10:01:43  InnoDB: Shutdown completed; log sequence number 77 3125296691
121120 10:01:43 [Note] /usr/sbin/mysqld: Shutdown complete

121120 10:01:43  InnoDB: Initializing buffer pool, size = 16.0M
121120 10:01:43  InnoDB: Completed initialization of buffer pool
121120 10:01:43  InnoDB: Started; log sequence number 77 3125296691
121120 10:01:43 [Note] Slave SQL thread initialized, starting replication in log 'skycaves.000547' at position 607196663, relay log './web-relay-bin.012390' position: 8104
121120 10:01:43 [Note] Event Scheduler: Loaded 0 events
121120 10:01:43 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.66-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  Gentoo Linux mysql-5.1.66
121120 10:01:43 [Note] Slave I/O thread: connected to master 'replication@127.0.0.1:3307',replication started in log 'skycaves.000547' at position 607196663
09:12:43 UTC - mysqld got signal 11 ;
This could be because you hit a bug. It is also possible that this binary
or one of the libraries it was linked against is corrupt, improperly built,
or misconfigured. This error can also be caused by malfunctioning hardware.
We will try our best to scrape up some info that will hopefully help
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.

key_buffer_size=50331648
read_buffer_size=262144
max_used_connections=14
max_threads=256
thread_count=0
connection_count=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 248404 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

Thread pointer: 0x7037e8000970
Attempting backtrace. You can use the following information to find out
where mysqld died. If you see no messages after this, something went
terribly wrong...
stack_bottom = 703810698828 thread_stack 0x40000
/usr/sbin/mysqld(my_print_stacktrace+0x3c) [0x31478bbc83c]
/usr/sbin/mysqld(handle_fatal_signal+0x493) [0x314789d9d73]
/lib64/libpthread.so.0(+0x10460) [0x703810300460]
/lib64/libc.so.6(cfree+0x14) [0x70380ed17174]
/usr/sbin/mysqld(Item_func_get_user_var::~Item_func_get_user_var()+0x52) [0x3147883e9b2]
/usr/sbin/mysqld(Item::safe_charset_converter(charset_info_st*)+0x18d) [0x31478809cbd]
/usr/sbin/mysqld(Query_arena::free_items()+0x40) [0x314788c8780]
/usr/sbin/mysqld(THD::cleanup_after_query()+0x5e) [0x314788c881e]
/usr/sbin/mysqld(mysql_parse(THD*, char*, unsigned int, char const**)+0x22f) [0x314788f258f]
/usr/sbin/mysqld(Query_log_event::do_apply_event(Relay_log_info const*, char const*, unsigned int)+0x406) [0x314789a5e56]
/usr/sbin/mysqld(apply_event_and_update_pos(Log_event*, THD*, Relay_log_info*)+0xfd) [0x31478a160fd]
/usr/sbin/mysqld(handle_slave_sql+0x829) [0x31478a16c19]
/lib64/libpthread.so.0(+0x7da6) [0x7038102f7da6]
/lib64/libc.so.6(clone+0x6d) [0x70380ed8250d]

Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7037e809f728): is an invalid pointer
Connection ID (thread ID): 2
Status: NOT_KILLED

The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
information that should help you find out what is causing the crash.




Reproducible: Always




emerge --info

Portage 2.1.11.31 (hardened/linux/amd64, gcc-4.5.4, unavailable, 3.5.4-grsec-a084 x86_64)
=================================================================
System uname: Linux-3.5.4-grsec-a084-x86_64-Intel-R-_Xeon-R-_CPU_E5440_@_2.83GHz-with-gentoo-2.1
Timestamp of tree: Tue, 20 Nov 2012 03:45:01 +0000
ld GNU ld (GNU Binutils) 2.22
app-shells/bash:          4.2_p37
dev-lang/python:          2.6.8, 3.1.5, 3.2.3
dev-util/cmake:           2.8.9
dev-util/pkgconfig:       0.27.1
sys-apps/baselayout:      2.1-r1
sys-apps/openrc:          0.9.8.4
sys-apps/sandbox:         2.5
sys-devel/autoconf:       2.13, 2.68
sys-devel/automake:       1.10.3, 1.11.6
sys-devel/binutils:       2.22-r1
sys-devel/gcc:            4.5.4
sys-devel/gcc-config:     1.7.3
sys-devel/libtool:        2.4-r1
sys-devel/make:           3.82-r3
sys-kernel/linux-headers: 3.4-r2 (virtual/os-headers)
sys-libs/glibc:           2.15-r3
Repositories: gentoo x-overlay
ACCEPT_KEYWORDS="amd64"
ACCEPT_LICENSE="* -@EULA"
CBUILD="x86_64-pc-linux-gnu"
CFLAGS="-O2 -pipe"
CHOST="x86_64-pc-linux-gnu"
CONFIG_PROTECT="/etc /local/adm/bin /usr/share/gnupg/qualified.txt /var/service"
CONFIG_PROTECT_MASK="/etc/ca-certificates.conf /etc/env.d /etc/gconf /etc/gentoo-release /etc/php/apache2-php5.3/ext-active/ /etc/php/cgi-php5.3/ext-active/ /etc/php/cli-php5.3/ext-active/ /etc/revdep-rebuild /etc/sandbox.d /etc/terminfo"
CXXFLAGS="-O2 -pipe"
DISTDIR="/local/portage/distfiles"
FCFLAGS="-O2 -pipe"
FEATURES="assume-digests binpkg-logs buildpkg collision-protect config-protect-if-modified distlocks ebuild-locks fixlafiles merge-sync news parallel-fetch protect-owned sandbox sfperms strict unknown-features-warn unmerge-logs unmerge-orphans userfetch userpriv usersandbox"
FFLAGS="-O2 -pipe"
GENTOO_MIRRORS="http://distfiles.gentoo.org"
LDFLAGS="-Wl,-O1 -Wl,--as-needed"
MAKEOPTS="-j4"
PKGDIR="/local/portage/packages"
PORTAGE_CONFIGROOT="/"
PORTAGE_RSYNC_OPTS="--recursive --links --safe-links --perms --times --compress --force --whole-file --delete --stats --human-readable --timeout=180 --exclude=/distfiles --exclude=/local --exclude=/packages"
PORTAGE_TMPDIR="/local/portage/build"
PORTDIR="/usr/portage"
PORTDIR_OVERLAY="/local/portage/overlay"
SYNC="rsync://rsync.bu.avira.com/gentoo-portage"
USE="amd64 bzip2 caps crypt cxx hardened ipv6 jpeg multilib nptl pam pic png readline sse sse2 ssl truetype unicode xml zlib" APACHE2_MODULES="alias auth_basic authn_dbd authn_default authn_file authz_default authz_groupfile authz_host authz_user autoindex deflate dir env filter headers log_config mime rewrite setenvif" APACHE2_MPMS="prefork" CURL_SSL="openssl" ELIBC="glibc" KERNEL="linux" NGINX_MODULES_HTTP="access auth_basic autoindex browser gzip gzip_static headers_more limit_req limit_zone proxy referer rewrite stub_status" PHP_TARGETS="php5-3" USERLAND="GNU"
Unset:  CPPFLAGS, CTARGET, EMERGE_DEFAULT_OPTS, INSTALL_MASK, LANG, LC_ALL, LINGUAS, PORTAGE_BUNZIP2_COMMAND, PORTAGE_COMPRESS, PORTAGE_COMPRESS_FLAGS, PORTAGE_RSYNC_EXTRA_OPTS, USE_PYTHON
Comment 1 Petre Rodan 2012-11-21 08:30:24 UTC
I guess I should open a bug in the upstream bugzilla?

this crash happens every time mysqld is started without --skip-slave.

use flags are as follows:
[ebuild   R    ] dev-db/mysql-5.1.66  USE="ssl -berkdb -big-tables -cluster -community -debug -embedded -extraengine -latin1 -max-idx-128 -minimal -pbxt -perl -profiling (-selinux) -static {-test} -xtradb" 0 kB

tried debug, but got a warning about it being broken since 5.1.51

I enabled the general_log, it appears that mysqld parses the relay_logs, starts inserting data from them to the local db, but crashes after a few seconds. based on the relay_log it succeeds in inserting small amounts of data each time it is started. the last sequences are 
                    2 Query     BEGIN
                    2 Query     COMMIT /* implicit, from Xid_log_event */
                    2 Query     BEGIN
                    2 Query     COMMIT /* implicit, from Xid_log_event */
the last meaningful sql command is a simple insert.

I compiled the package with -ggdb and this would be the trace:

web3 ~ # gdb /usr/sbin/mysqld
GNU gdb (Gentoo 7.3.1 p2) 7.3.1
Copyright (C) 2011 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "x86_64-pc-linux-gnu".
For bug reporting instructions, please see:
<http://bugs.gentoo.org/>...
Reading symbols from /usr/sbin/mysqld...done.
(gdb) run
Starting program: /usr/sbin/mysqld 
[New LWP 10609]

Program received signal SIGSEGV, Segmentation fault.
[Switching to LWP 10609]
0x000004c0d4834a64 in Item::delete_self (this=0x6b25e8005b90) at item.h:1030
1030        cleanup();
(gdb) bt
#0  0x000004c0d4834a64 in Item::delete_self (this=0x6b25e8005b90) at item.h:1030
#1  0x000004c0d4830bf3 in Query_arena::free_items (this=0x6b25e8000988) at sql_class.cc:2508
#2  0x000004c0d482c34a in THD::cleanup_after_query (this=0x6b25e8000970) at sql_class.cc:1275
#3  0x000004c0d4863f45 in mysql_parse (thd=0x6b25e8000970, rawbuf=0x6b25e800c811 "BEGIN", length=5, found_semicolon=0x6b260e7057f0)
    at sql_parse.cc:6149
#4  0x000004c0d4948153 in Query_log_event::do_apply_event (this=0x6b25e800ba20, rli=0x4c0d63a62f0, query_arg=0x6b25e800c811 "BEGIN", q_len_arg=5)
    at log_event.cc:3328
#5  0x000004c0d4947851 in Query_log_event::do_apply_event (this=0x6b25e800ba20, rli=0x4c0d63a62f0) at log_event.cc:3121
#6  0x000004c0d49e06ff in Log_event::apply_event (this=0x6b25e800ba20, rli=0x4c0d63a62f0) at log_event.h:1076
#7  0x000004c0d49dbd77 in apply_event_and_update_pos (ev=0x6b25e800ba20, thd=0x6b25e8000970, rli=0x4c0d63a62f0) at slave.cc:2216
#8  0x000004c0d49dbf7d in exec_relay_log_event (thd=0x6b25e8000970, rli=0x4c0d63a62f0) at slave.cc:2355
#9  0x000004c0d49dd94b in handle_slave_sql (arg=0x4c0d63a5000) at slave.cc:3148
#10 0x00006b260e364da6 in ?? ()
#11 0x0000000000000000 in ?? ()
(gdb) info local
No locals.
(gdb) up
#1  0x000004c0d4830bf3 in Query_arena::free_items (this=0x6b25e8000988) at sql_class.cc:2508
warning: Source file is more recent than executable.
2508        free_list->delete_self();
(gdb) info local
next = 0x6b25e8005c08
(gdb) up
#2  0x000004c0d482c34a in THD::cleanup_after_query (this=0x6b25e8000970) at sql_class.cc:1275
1275      free_items();
(gdb) info local
No locals.
(gdb) up
#3  0x000004c0d4863f45 in mysql_parse (thd=0x6b25e8000970, rawbuf=0x6b25e800c811 "BEGIN", length=5, found_semicolon=0x6b260e7057f0)
    at sql_parse.cc:6149
warning: Source file is more recent than executable.
6149        thd->cleanup_after_query();
(gdb) info local
lex = 0x6b25e8002338
parser_state = {m_lip = {m_thd = 0x6b25e8000970, yylineno = 1, yytoklen = 0, yylval = 0x6b260e703420, m_ptr = 0x6b25e800c817 "\f", 
    m_tok_start = 0x6b25e800c817 "\f", m_tok_end = 0x6b25e800c817 "\f", m_end_of_query = 0x6b25e800c816 "", m_tok_start_prev = 0x6b25e800c816 "", 
    m_buf = 0x6b25e800c811 "BEGIN", m_buf_length = 5, m_echo = true, m_echo_saved = 4, m_cpp_buf = 0x6b25e8005ba0 "", 
    m_cpp_ptr = 0x6b25e8005ba5 "", m_cpp_tok_start = 0x6b25e8005ba5 "", m_cpp_tok_start_prev = 0x6b25e8005ba5 "", 
    m_cpp_tok_end = 0x6b25e8005ba5 "", m_body_utf8 = 0x0, m_body_utf8_ptr = 0x0, m_cpp_utf8_processed_ptr = 0x0, next_state = MY_LEX_END, 
    found_semicolon = 0x0, tok_bitmap = 17 '\021', ignore_space = false, stmt_prepare_mode = false, in_comment = NO_COMMENT, 
    in_comment_saved = 3892316528, m_cpp_text_start = 0x50ac8f25 <Address 0x50ac8f25 out of bounds>, 
    m_cpp_text_end = 0x23653cf235435b00 <Address 0x23653cf235435b00 out of bounds>, m_underscore_cs = 0x0}, m_yacc = {yacc_yyss = 0x0, 
    yacc_yyvs = 0x0}}
err = false
(gdb) up
#4  0x000004c0d4948153 in Query_log_event::do_apply_event (this=0x6b25e800ba20, rli=0x4c0d63a62f0, query_arg=0x6b25e800c811 "BEGIN", q_len_arg=5)
    at log_event.cc:3328
warning: Source file is more recent than executable.
3328          mysql_parse(thd, thd->query(), thd->query_length(), &found_semicolon);
(gdb) info local
found_semicolon = 0x0
new_db = {str = 0x6b25e800c804 "aviraweb_rep", length = 12}
expected_error = 0
actual_error = 0
db_options = {table_charset = 0x0, default_table_charset = 0x4c0d5103680, connect_string = {str = 0x0, length = 0}, password = 0x0, 
  tablespace = 0x0, comment = {str = 0x0, length = 0}, data_file_name = 0x0, index_file_name = 0x0, alias = 0x0, max_rows = 0, min_rows = 0, 
  auto_increment_value = 0, table_options = 0, avg_row_length = 0, used_fields = 0, key_block_size = 0, 
  merge_list = {<Sql_alloc> = {<No data fields>}, elements = 0, first = 0x0, next = 0x0}, db_type = 0x0, row_type = ROW_TYPE_DEFAULT, 
  null_bits = 0, options = 0, merge_insert_method = 0, extra_size = 0, unused1 = HA_CHOICE_UNDEF, table_existed = false, frm_only = false, 
  varchar = false, storage_media = HA_SM_DEFAULT, unused2 = HA_CHOICE_UNDEF}
(gdb) up
#5  0x000004c0d4947851 in Query_log_event::do_apply_event (this=0x6b25e800ba20, rli=0x4c0d63a62f0) at log_event.cc:3121
3121      return do_apply_event(rli, query, q_len);
(gdb) info local
No locals.
(gdb) up
#6  0x000004c0d49e06ff in Log_event::apply_event (this=0x6b25e800ba20, rli=0x4c0d63a62f0) at log_event.h:1076
1076        return do_apply_event(rli);
(gdb) info local
No locals.
(gdb) up
#7  0x000004c0d49dbd77 in apply_event_and_update_pos (ev=0x6b25e800ba20, thd=0x6b25e8000970, rli=0x4c0d63a62f0) at slave.cc:2216
warning: Source file is more recent than executable.
2216        exec_res= ev->apply_event(rli);
(gdb) info local
exec_res = 0
reason = 0
(gdb) up
#8  0x000004c0d49dbf7d in exec_relay_log_event (thd=0x6b25e8000970, rli=0x4c0d63a62f0) at slave.cc:2355
2355        exec_res= apply_event_and_update_pos(ev, thd, rli);
Comment 2 Petre Rodan 2013-11-04 09:00:22 UTC
stale bug. upstream was also uninterested in it.