MySQL Bugs: #10308: purge log fails

Bug #10308	purge log fails
Submitted:	2 May 2005 10:32	Modified:	13 Oct 2005 1:54
Reporter:	Marten Lehmann	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Replication	Severity:	S2 (Serious)
Version:	4.1.11	OS:	Linux (Linux 2.4.21-27.0.4.EL)
Assigned to:	Bugs System	CPU Architecture:	Any

Description:
the current 4.1.11 implementation of PURGE LOGS doesn't seem to work any more. I created a script running once each day doing the following statement:

purge master logs before (select adddate(current_timestamp(), interval -4 day))

That way, all logs prior to today - 4 days will become deleted. This worked fine with 4.1.9. But since I upgraded from 4.1.9 to 4.1.11 I alway get this error:

DBD::mysql::db do failed: Lost connection to MySQL server during query at /vrmd/admin/cron/apps/purge_logs/purge_logs.pl line 15.

This also happens when I'm doing the query manually logged in at the mysql-prompt. Mysql is dieing in both cases. This is the error-log output:

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=402653184
read_buffer_size=2093056
max_used_connections=24
max_connections=1000
threads_connected=2
It is possible that mysqld could use up to
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_connections = 290904 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd=0xa3500490
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...
Cannot determine thread, fp=0xbe5fe748, backtrace may not be correct.
Stack range sanity check OK, backtrace follows:
0x80b2589
0x82cb328
0x808f73b
0x808ce7e
0x80db3d5
0x80ca97b
0x80c45e1
0x80c4226
0x80c3a1d
0x82c6c21
0x82f916a
New value of fp=(nil) failed sanity check, terminating stack trace!
Please read http://dev.mysql.com/doc/mysql/en/Using_stack_trace.html and follow instructions on how to resolve the stack trace. Resolved
stack trace is much more helpful in diagnosing the problem, so please do
resolve it
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort...
thd->query at 0xa68e960 = purge master logs before (select adddate(current_timestamp(), interval -4 day))
thd->thread_id=106601
The manual page at http://www.mysql.com/doc/en/Crashing.html contains
information that should help you find out what is causing the crash.

Number of processes running now: 0
050428 21:44:17 mysqld restarted
050428 21:44:17 InnoDB: Database was not shut down normally!
InnoDB: Starting crash recovery.
InnoDB: Reading tablespace information from the .ibd files...
InnoDB: Restoring possible half-written data pages from the doublewrite
InnoDB: buffer...
050428 21:44:18 InnoDB: Starting log scan based on checkpoint at
InnoDB: log sequence number 0 1226476.
InnoDB: Doing recovery: scanned up to log sequence number 0 1226476
InnoDB: Last MySQL binlog file position 0 79, file name ./vm23-bin.000102
050428 21:44:18 InnoDB: Flushing modified pages from the buffer pool...
050428 21:44:18 InnoDB: Started; log sequence number 0 1226476
/usr/mysql/mysql-4.1.11/libexec/mysqld: ready for connections.
Version: '4.1.11-log' socket: '/tmp/mysql.sock' port: 3306 Source distribution

For testing, I simplified to statement and removed the subquery:

purge master logs before '2005-04-24';

Now I don't loose the connection, but on the other hand, the purging isn't done. All logfiles are remaining at their position as if I had not run the statement. To clear a bit of space, I was running "reset master". But that way all logfiles are removed, but I want to keep the logfiles for at least the last 4 days to be able to track statements in case of errors. Any idea what is going wrong? As it worked in 4.1.9, I guess there's a problem in the mysql-server?

How to repeat:
Just enter one of the following statements:

purge master logs before (select adddate(current_timestamp(), interval -4 day));

result: mysql dies.

purge master logs before '2005-04-24';

result: logfiles are unchanged

Suggested fix:
I don't know what has been changed internally, but the purge-log command is correct as of the documentation and it worked correctly with 4.1.9. Unfortunately, I haven't checked with 4.1.10 so I can't tell if it's broken there, too.

Verified, works on 4.1.9 but fails on 4.1.10 and .11

Hello!
Until we fix it, --expire-logs-days may help (if it does not crash!) "If non-zero, binary logs will be purged after expire_logs_days days; possible purges happen at startup and at binary log rotation."

Just want to confirm that this long-outstanding bug is still a major problem for us too.. hope it can be fixed soon!

Here is the backtrace I get from examining a core file produced by this crash on OS X:

Thread 11 (core thread 10):
#0  0x900138ac in close ()
#1  0x0036120c in my_close (fd=7, MyFlags=0) at my_open.c:92
#2  0x000d72f8 in MYSQL_LOG::close (this=0x575a10, exiting=1) at log.cc:1925
#3  0x000d9004 in MYSQL_LOG::cleanup (this=0x575a10) at log.cc:158
#4  0x000d9064 in MYSQL_LOG::~MYSQL_LOG (this=0x0) at log.cc:147
#5  0x000d90e4 in __static_initialization_and_destruction_0 (__initialize_p=0, __priority=0) at log.cc:37
#6  0x000d9144 in global destructors keyed to mysql_log () at log.cc:2379
#7  0x8fe109dc in __dyld__ZN16ImageLoaderMachO13doTerminationERKN11ImageLoader11LinkContextE ()
#8  0x8fe038ec in __dyld__ZN4dyld14runTerminatorsEv ()
#9  0x90013a5c in __cxa_finalize ()
#10 0x90013904 in exit ()
#11 0x901209a4 in abort ()
#12 0x00397e78 in __eprintf () at TCP_Transporter.cpp:289
#13 0x00046600 in subselect_single_select_engine::cols (this=0x0) at item_subselect.cc:1579
#14 0x000456f0 in Item_singlerow_subselect::check_cols (this=0x0, c=1) at item_subselect.cc:423
#15 0x0009d2f4 in yyparse (yythd=0x384f818) at sql_yacc.yy:4718
#16 0x00089f6c in mysql_parse (thd=0x384f818, inBuf=0x384f854 "", length=79) at sql_parse.cc:4318
#17 0x0008a6a8 in dispatch_command (command=COM_QUERY, thd=0x384f818, packet=0x3089019 "purge master logs before (select adddate(current_timestamp(), interval -4\nday))", packet_length=59058295) at sql_parse.cc:1499
#18 0x0008b684 in do_command (thd=0x384f818) at sql_parse.cc:1312
#19 0x0008c1d8 in handle_one_connection (arg=0x384f818) at sql_parse.cc:1044
#20 0x9002c3b4 in _pthread_body () 

Looks like the expression is somehow ending up with a null object in the case where a subselect is used. odd.

Elliot says in private mail:

The crash doesn't happen when a literal date is given, only when the
subselect is used.

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/30867

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/30898

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/internals/30946

Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html

Additional info:

Fix was pushed for 4.1.16.
This issue was fixed in a different way some time back for 5.0, but went ahead and merged the test case for 5.0.15.

Documented in 4.1.16 changelog:

 <listitem>
        <para>
          <literal>PURGE MASTER LOGS</literal> statement that used
          subselect for date crashed server. (Bug #10308)
        </para>
      </listitem>