I came across an interesting error reported on #mysql the other day. When I went through it with the reporter it looks like we uncovered up to two bugs in InnoDB (or rather XtraDB as it was Percona Server). I thought it might be useful to go through the error message, including the stack trace, to show that you don't need to be a developer to track down some useful information.
I just want to share about a strange behavior of one of our MySQL server yesterday.
This server is a 5.1.50 MySQL server on debian 4.0 (Yes, I know…)
When a “mysqld got signal 6” error occurred yesterday, the MySQL server crashed and didn’t want to restart.
Then, I found these informations in the error log file :
/usr/local/mysql/bin/mysqld: File '*** glibc detected *** malloc():memory corruption: 0x00002aac2d5ab460 ***' not found (Errcode: 2) 120306 17:19:47 [ERROR] Failed to open log (file '*** glibc detected *** malloc():memory corruption: 0x00002aac2d5ab460 ***', errno 2) 120306 17:19:47 [ERROR] Could not open log file 120306 17:19:47 [ERROR] Can't init tc log 120306 17:19:47 [ERROR] Aborting
120306 17:19:47 InnoDB: Starting shutdown... 120306 17:19:53 InnoDB: Shutdown completed; log sequence number 55 1061584593 120306 17:19:53 [Note] /usr/local/mysql/bin/mysqld: Shutdown complete
Great, let see what is the Errcode 2 through the perror utility :
# perror 2 OS error code 2: No such file or directory
But where is this missing file ? And have you ever heard about a file called “*** glibc detected *** malloc():memory corruption: 0x00002aac2d5ab460 ***” ?!
No, of course not. But this error message was more meaningful : Could not open log file
The InnoDB log files and binary log files seemed to be ok (file permissions and other checks showed no failure)
But when I did a cat on the binary log index file… surprise ! :
# cat mysql-bin.index /var/database/bin-log/mysql-bin.126242 /var/database/bin-log/mysql-bin.126243 /var/database/bin-log/mysql-bin.126244 /var/database/bin-log/mysql-bin.126245 *** glibc detected *** malloc(): memory corruption: 0x00002aac2d5ab460 ***
The index file was corrupted during the last crash and an error message was inserted inside this file because of a memory corruption.
Deleting files helped to restart the MySQL server but I found very strange that MySQL wasn’t able to deliver a more accurate message about that.
Some days ago while I’m looking for what are saying about a mysql.com server down I found a twitter bug:
Is not a big deal, to repeat this bug you must follow these steps:
1. Find any term, in this case “mysql.com” then in results looking for a word that have the search term as a part of them (ex dev.mysql.com) and select the a part or entire word:
2. Press Ctrl + C, some HTML codes appear from nowhere:
3. Do it again and again, you will see an strange twit like this:
I’m using Firefox 8.0 under Ubuntu, but you will get the same result using Chrome and (maybe) other web clients.
For those who saw my previous post about the crashing (regression) bug with SELECT COUNT(DISTINCT) on InnoDB with Primary Key (PK), you’ll be interested to know my test case does not crash in 5.5.18 (which was just released).
I’ve only tested my test case thus far, but it seems fine.
Unfortunately, the fix is not mentioned in the 5.5.18 changelogs though.
And there is no mention (yet, anyway) of a fix in the bug report I filed (though it was designated a ‘duplicate’, so it wouldn’t necessarily be updated).
I’m trying to get confirmation from the MySQL Dev Team on this (via the bug report), and will update this post if/when I hear anything.
I’ll also perform some of the other tests on my end to see if they all pass as well.
All in all, at least the initial results look very promising! 
If you’re using MySQL and SSL, you might want to glance over this article and give your setup a quick test.
I’ve uncovered an alarming bug in 5.5 where one could gain access to your MySQL instance just knowing the username and password (not having any SSL certificate, key, etc.)!
Of course, I’ve filed a bug about it here:
http://bugs.mysql.com/bug.php?id=62743
It’s been over 4 days now, and not one comment from the MySQL Bug/Dev Team.
So once again, I feel the need to share this bug with the public, in case you are using SSL with 5.5, and think your connections are secure, or that only users with the certs/key could gain access.
For SSL Users, you’ll already have this set up, but for those who don’t, I’ve simply got mysqld (5.5.15 and 5.5.16 thus far) running with the following options:
ssl-ca = "C:/Program Files/MySQL/mysql-5.5.16/certs/ca-cert.pem" ssl-cert = "C:/Program Files/MySQL/mysql-5.5.16/certs/server-cert.pem" ssl-key = "C:/Program Files/MySQL/mysql-5.5.16/certs/server-key.pem"
In theory, any user connecting should either be specifying the –ssl-ca option, path, and file, or both the –ssl-cert and –ssl-key options.
However, at least in 5.5.15 and 5.5.16 (haven’t tested any others yet), one can connect with *just* the –ssl-key option.
What’s worse, and most important, is that you don’t even have to specify a file here. Just specify some bogus text!
I created 2 users, one local and one remote, using these 2 commands:
GRANT ALL PRIVILEGES ON *.* TO 'ssluser'@'localhost' IDENTIFIED BY 'ssluser' REQUIRE SSL;) GRANT ALL PRIVILEGES ON *.* TO 'ssluser'@'remote-hostname' IDENTIFIED BY 'ssluser' REQUIRE SSL;
Now, just specify “buggg” for the -ssl-key option (no path, no file, no nothing):
mysql -ussluser -pssluser -P3430 --ssl-key=buggg
Voila!
The user connects as if it were using an SSL connection. All that was needed to connect to this remote host is the username and password.
Check out the output:
Localhost:
C:\Program Files\MySQL\mysql-5.5.16\bin>mysql -ussluser -pssluser -P3430 --ssl-key=buggg Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 11 Server version: 5.5.16-log MySQL Community Server (GPL) Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved. Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners. Type 'help;' or '\h' for help. Type '\c' to clear the current input statement. mysql> status -------------- mysql Ver 14.14 Distrib 5.5.16, for Win32 (x86) Connection id: 11 Current database: Current user: ssluser@localhost SSL: Cipher in use is DHE-RSA-AES256-SHA Using delimiter: ; Server version: 5.5.16-log MySQL Community Server (GPL) Protocol version: 10 Connection: localhost via TCP/IP Server characterset: latin1 Db characterset: latin1 Client characterset: cp850 Conn. characterset: cp850 TCP port: 3430 Uptime: 35 min 26 sec Threads: 1 Questions: 24 Slow queries: 0 Opens: 33 Flush tables: 1 Open tables: 0 Queries per second avg: 0.011 --------------
Remote Host:
C:\Documents and Settings>mysql -ussluser -pssluser -h192.168.1.100 -P3430 --ssl-key=buggg Welcome to the MySQL monitor. Commands end with ; or \g. Your MySQL connection id is 6 Server version: 5.5.16-log MySQL Community Server (GPL) Type 'help;' or '\h' for help. Type '\c' to clear the buffer. mysql> status -------------- mysql Ver 14.12 Distrib 5.0.70, for Win32 (ia32) Connection id: 6 Current database: Current user: ssluser@HOST-LAPTOP SSL: Cipher in use is DHE-RSA-AES256-SHA Using delimiter: ; Server version: 5.5.16-log MySQL Community Server (GPL) Protocol version: 10 Connection: 192.168.1.100 via TCP/IP Server characterset: latin1 Db characterset: latin1 Client characterset: latin1 Conn. characterset: latin1 TCP port: 3430 Uptime: 13 min 13 sec Threads: 2 Questions: 14 Slow queries: 0 Opens: 33 Flush tables: 1 Open tab les: 26 Queries per second avg: 0.017 --------------
Again, I have no idea how many versions are affected by this yet. I’ve only tested 5.5.15 and 5.5.16 (seen on both Windows and Linux, as well).
In fact, that’s all I thought I would have needed to test, as I thought MySQL would have been all over this bug. But since there’s been no word from them about it, I feel it’s my duty to let the community know about this bug until it gets fixed.
(And I even wonder if the above is secure or not. I mean, it “says” the cipher is in use, but since I didn’t specify a ssl cert or key, how can I be certain this is secure.)
In 5.5, a crashing, regression bug exists if you use SELECT COUNT(DISTINCT) *and* one of the WHERE operands is in the Primary Key (or just a unique index).
This simple crash (if only one row is in the table) will crash mysqld.
Of course I’ve filed a bug report, but that has been nearly 3 months and no updates yet.
Here is the bug I filed (which you won’t be able to view):
http://bugs.mysql.com/bug.php?id=61842
Really, the only thing that happened to my bug report was that it was designated a duplicate of another bug (which we also cannot view):
http://bugs.mysql.com/bug.php?id=61101
Based on the id, and the submitted dates of bugs 61100 and 61102, this initial bug (61101) was filed on May 9, 2011. So, in fact, this bug has been present for over 5 months, and not one breath of an update to the public!
Therefore, I felt it necessary to warn others about this bug, (or possibly you’ll run across this if you’re searching on SELECT COUNT(DISTINCT) in the future).
All I can say is please watch out for it!
It is extremely easy to reproduce:
CREATE TABLE t (a int(1), b int(1), PRIMARY KEY (a,b)) ENGINE=InnoDB; INSERT INTO t VALUES (1, 1); SELECT COUNT(DISTINCT a) FROM t WHERE b = 1;
–> crash <--
For those interested, this was filed against 5.5.14. However, with each new release, I've continued testing, and this bug is present in 5.5.15, 5.5.16, and thus far in 5.5.17 (built from the latest bzr tree).
Hopefully we don't go too many more months before this is finally fixed.
And for reference (and those searching on the stack trace / error log messages), here is my full error log snippet from 5.5.16:
111017 10:54:47 [Note] C:\Program Files\MySQL\MySQL Server 5.5\bin\mysqld: ready for connections. Version: ’5.5.16′ socket: ” port: 3308 MySQL Community Server (GPL) len 128; hex f8aec9037d803805f017fc03189ddc030000000… 111017 10:55:12 InnoDB: Assertion failure in thread 5000 in file btr0pcur.c line 236 InnoDB: We intentionally generate a memory trap. InnoDB: Submit a detailed bug report to http://bugs.mysql.com. InnoDB: If you get repeated assertion failures or crashes, even InnoDB: immediately after the mysqld startup, there may be InnoDB: corruption in the InnoDB tablespace. Please refer to InnoDB: http://dev.mysql.com/doc/refman/5.5/en/forcing-innodb-recovery.html InnoDB: about forcing recovery. 111017 10:55:12 – mysqld got exception 0xc0000005 ; 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=26214400 read_buffer_size=65536 max_used_connections=1 max_threads=100 thread_count=1 connection_count=1 It is possible that mysqld could use up to key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 58325 K bytes of memory Hope that’s ok; if not, decrease some variables in the equation. Thread pointer: 0x3c98428 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… 00CE92EC mysqld.exe!btr_pcur_restore_position_func()[btr0pcur.c:236] 00CA62FB mysqld.exe!sel_restore_position_for_mysql()[row0sel.c:3081] 00CA6CEA mysqld.exe!row_search_for_mysql()[row0sel.c:3820] 00C5FE20 mysqld.exe!ha_innobase::general_fetch()[ha_innodb.cc:5918] 00C5FEDD mysqld.exe!ha_innobase::index_next()[ha_innodb.cc:5956] 00C20DDA mysqld.exe!index_next_different()[opt_range.cc:11038] 00C249BC mysqld.exe!QUICK_GROUP_MIN_MAX_SELECT::next_prefix()[opt_range.cc:11099] 00C26BE7 mysqld.exe!QUICK_GROUP_MIN_MAX_SELECT::get_next()[opt_range.cc:10824] 00B68D01 mysqld.exe!rr_quick()[records.cc:344] 00BC1B9A mysqld.exe!sub_select()[sql_select.cc:11723] 00BD10A7 mysqld.exe!do_select()[sql_select.cc:11483] 00BD37BD mysqld.exe!JOIN::exec()[sql_select.cc:2370] 00BD3A29 mysqld.exe!mysql_select()[sql_select.cc:2581] 00BD3D4B mysqld.exe!handle_select()[sql_select.cc:297] 00ACD76E mysqld.exe!execute_sqlcom_select()[sql_parse.cc:4511] 00ACF816 mysqld.exe!mysql_execute_command()[sql_parse.cc:2118] 00AD2D1F mysqld.exe!mysql_parse()[sql_parse.cc:5548] 00AD3848 mysqld.exe!dispatch_command()[sql_parse.cc:1037] 00AD43BB mysqld.exe!do_command()[sql_parse.cc:771] 00AF2DB6 mysqld.exe!do_handle_one_connection()[sql_connect.cc:789] 00AF2F44 mysqld.exe!handle_one_connection()[sql_connect.cc:708] 00C33DE4 mysqld.exe!pthread_start()[my_winthread.c:61] 00D9C6F3 mysqld.exe!_callthreadstartex()[threadex.c:348] 00D9C79B mysqld.exe!_threadstartex()[threadex.c:326] 765F3823 kernel32.dll!BaseThreadInitThunk() 77CAA9BD ntdll.dll!LdrInitializeThunk() Trying to get some variables. Some pointers may be invalid and cause the dump to abort. Query (03DC0F10): SELECT COUNT(DISTINCT a) FROM t WHERE b = 1 Connection ID (thread ID): 1 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. InnoDB: Thread 5980 stopped in file os0sync.c line 781 InnoDB: Thread 6820 stopped in file os0sync.c line 474 InnoDB: Thread 7532 stopped in file os0sync.c line 474
We wanted to optimize and test backups for one of our new large scale setup before we could finalize on the backup plan. Our challenge was the data volume was almost 30x more than our normal volumes. Since this involved large volume of data we thought this might be a good candidate to test incremental backups. We wrote a wrapper script to save the states between full backups and incremental backups and did some tests with smaller data sets. It worked perfectly fine. The version of xtrabackup we were testing was 1.6.2.
The incremental backups were completing well within 30minutes. We set out to test what would happen if the amount of incremental diff was large. While doing this test, we started getting backup failures with the following error
20110726_225312.log-110727 00:56:10 innobackupex: Starting to backup .frm, .MRG, .MYD, .MYI,
20110726_225312.log-innobackupex: .TRG, .TRN, .ARM, .ARZ, .CSM, .CSV and .opt files in
20110726_225312.log-innobackupex: subdirectories of ‘/var/lib/mysql’
20110726_225312.log:innobackupex: Error: Broken pipe at /var/backups/xtrabackup/bin/innobackupex line 336.
20110726_225312.log-Backup failed.
20110726_225312.log-Deleting bad data directory…
20110726_225312.log-Done. Removed /ddmysql/backups/20110726_225312
Initially we thought this was a one of case and made quite a few reruns. It was failing consistently. We wanted to get to the bottom of this. This was important for us to finalize the backup plan. We ran the innobackupex script through a debugger to find out where it was failing. The broken pipe error was getting triggered when the script was trying to send a ping to the mysql server so that the connection doesn’t timeout after the number of seconds mentioned in “mysql_keep_alive_timeout“ variable. This was set to around 1800. Our conclusion was when the incremental was of smaller size, the script never got to send the timeout ping. We reran the script with a much larger timeout value for a larger incremental data set and the backup was completed successfully.
The script seems to lose the connection handle during course of execution and when it tries to ping on the handle it encounters a broken pipe. Wondering if there are other tried and tested ways to overcome this issue. Bug has been logged with the xtrabackup team to see if there are other options.
Drizzle still has a number of quirks inherited from the MySQL Storage Engine API (e.g. BLOBs, row buffer, CREATE SELECT and lack of DDL transaction boundaries, key tuple format). One of the things we fixed a long time ago was to have proper methods for StorageEngines to be called for: startTransaction, startStatement, endStatement, commit and rollback.
If you’ve had to implement a transactional storage engine in MySQL you will be well aware of the pattern of “in every Storage Engine/handler call: if transaction doesn’t exist, begin.” We’ve tried to fix this in the Drizzle API for a number of reasons. I think having this obvious set of calls will make the API a lot easier to understand. I am also very interested in making things much easier to prove correct.
A while ago I spotted Bug 587772, which was the READ COMMITTED isolation level not working correctly with InnoDB. It turns out that the most basic example for READ COMMITTED failed. Hrrm… this is no good. It worked on MySQL, so this was certainly something that we broke. What was more worrying is that there wasn’t a test for this in the test suite (and at the time I couldn’t find one in the MySQL test suite either, so I think we inherited the missing test).
I recently started delving in, actually going to solve this. I noticed something worrying, endStatement wasn’t being called, which is where the innobase plugin would release the read view that it used for the statement. You’d think that it would grab a new one on startStatement, but because of the previous design of the API (remember “if txn isn’t started, start it!”) this also happened for getting the read view for the statement… so we instead got a REPEATABLE READ isolation level.
I wanted a test.
Previously, I’ve created a dummy storage engine (tableprototester) and used it to test the server code for reading the table protobuf message. I thought about doing a Storage Engine for this problem too, basically looking at the calls to the Storage Engine as transitions between states in a state machine.
A basic view of a transaction could be:
That is, a transaction starts and has zero or more statements before it commits or gets rolled back.
By coding up a data structure of allowable state transitions, a small function to assert() on invalid transitions and enough of the boilerplate to make the engine “work”, I was able to hit an assert() exactly where I’d expected it: at an invalid transition from START STATEMENT to COMMIT.
To fix the initial bug (READ COMMITTED not working), I filled in a few state transitions for the system as a whole that aren’t quite correct. From the diagram below, you can quite obviously see where the obvious bugs are (it helps that I’ve coloured them red):
There is absolutely no sense in going BEGIN -> END STATEMENT or immediately to COMMIT. These should be relatively easy to solve too, but are separate bugs.
I wish to expand this in the future to cover Cursor as well. It will also be useful to ensure that DDL can be wrapped in transactions. Not to mention the last few HTON flags that exist (and should likely go away).
To generate the diagrams, I just wrote a little utility to dump out the state transitions in dot, using it to generate the diagrams.
The bug I talked about a little while ago has now also had the fix I wrote committed to the mysql-trunk 5.5.6-m3 repository.