Bug #54414 on startup mysql moves files from /var/lib/mysql to /var/lib/mysql/@002erelay ?!
Submitted: 11 Jun 2010 1:45 Modified: 15 Jun 2010 5:52
Reporter: Matt Reid Email Updates:
Status: Duplicate Impact on me:
None 
Category:MySQL Server: Installing Severity:S1 (Critical)
Version:5.1.47 OS:Linux (RHEL4 update 8 64bit)
Assigned to: CPU Architecture:Any
Tags: @002erelay, 5.1.47, filesystem, installation, upgrade

[11 Jun 2010 1:45] Matt Reid
Description:
I just upgraded from 5.0.68 to 5.1.47. 

Here's the sequence of the issue:

0. Shut down MySQL
1. Removed innodb_log_arch_dir from cnf
2. Added binlog_format = MIXED to cnf
3. Installed new RPMs and that went as expected and as proved successful in staging.
4. Started MySQL, fine.
5. Logged in via localhost socket connection in /var/lib/mysql/mysql.sock (as specified in cnf)
6. After several minutes (still logged in) the data files were moved from /var/lib/mysql to /var/lib/mysql/@002erelay
7. Spend some time looking at log files and do not find any pertinent information
8. I stop MySQL
9. Symlink /var/lib/mysql to /var/lib/mysql/@002erelay 
10. Start MySQL, login and all is well 

Second server: same issue but I try stopping mysql, moving file from /var/lib/mysql/@002erelay back to /var/lib/mysq/ and remove the @002erelay directory. Then a couple minutes later, after MySQL has been running the whole time, the files have been MOVED back to /var/lib/mysql/@002erelay without anyone intervening.

Question:

I symlinked to fix it and mysql is running now but I am very confused as to why this happened  - and it happened on 2 servers, all redhat 4 64bit

How to repeat:
Follow the process I did above on a RHEL4 64bit server.

Suggested fix:
Please advise.
[11 Jun 2010 2:05] Matt Reid
Some bits from the logile
----
100610 21:05:24 [Note] Slave: connected to master 'repliad05@10.64.14.25:3306',replication resumed in log 'mysql-bin.001233' at position 1046412482
100610 21:05:24 [ERROR] Slave SQL: Query caused different errors on master and slave.     Error on master: 'Invalid error code' (7), Error on slave: 'no error' (0). Default database: ''. Query: 'ALTER DATABASE `#mysql50#.relay` UPGRADE DATA DIRECTORY NAME', Error_code: 0
100610 21:05:24 [Warning] Slave: Error on rename of './/@002erelay' to './@002erelay/@002erelay' (Errcode: 22) Error_code: 7
100610 21:05:24 [Warning] Slave: Error dropping database (can't rmdir './/', errno: 17) Error_code: 1010
100610 21:05:24 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.001234' position 106
.
.
.
.
Version: '5.1.47-community-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
100610 21:48:59 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001234' at position 106, relay log '/var/lib/mysql/mysql-relay-bin.000551' position: 251
100610 21:48:59 [Note] Slave I/O thread: connected to master 'repliad05@10.64.14.25:3306',replication started in log 'mysql-bin.001241' at position 6412440
100610 21:48:59 [ERROR] Slave SQL: Query caused different errors on master and slave.     Error on master: 'Invalid error code' (7), Error on slave: 'no error' (0). Default database: ''. Query: 'ALTER DATABASE `#mysql50#.relay` UPGRADE DATA DIRECTORY NAME', Error_code: 0
100610 21:48:59 [Warning] Slave: Error on rename of './/@002erelay' to './@002erelay/@002erelay' (Errcode: 22) Error_code: 7
100610 21:48:59 [Warning] Slave: Error dropping database (can't rmdir './/', errno: 17) Error_code: 1010
100610 21:48:59 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.001234' position 106
100610 21:49:00  InnoDB: Operating system error number 2 in a file operation.
InnoDB: The error means the system cannot find the path specified.
100610 21:49:00  InnoDB: Fatal error: cannot open ./acorn_repository/GLOBAL_REVISION.ibd
.InnoDB: Have you deleted .ibd files under a running mysqld server?
100610 21:49:00  InnoDB: Assertion failure in thread 1168148832 in file fil/fil0fil.c line 541
InnoDB: Failing assertion: 0
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.1/en/forcing-recovery.html
InnoDB: about forcing recovery.
100610 21:49:00 - mysqld got signal 6 ;
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=268435456
read_buffer_size=2097152
max_used_connections=0
max_threads=550
threads_connected=0
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 2520607 K
bytes of memory
Hope that's ok; if not, decrease some variables in the equation.

thd: 0x0
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 = (nil) thread_stack 0x20000
/usr/sbin/mysqld(my_print_stacktrace+0x2e)[0x84ae1e]
/usr/sbin/mysqld(handle_segfault+0x31d)[0x5c783d]
/lib64/tls/libpthread.so.0[0x3b1560c5b0]
/lib64/tls/libc.so.6(gsignal+0x3d)[0x3b14f2e26d]
/lib64/tls/libc.so.6(abort+0xfe)[0x3b14f2fa6e]
/usr/sbin/mysqld[0x764a15]
/usr/sbin/mysqld[0x765c20]
/usr/sbin/mysqld(fil_space_get_size+0x114)[0x768884]
/usr/sbin/mysqld(buf_read_page+0x134)[0x7544f4]
/usr/sbin/mysqld(buf_page_get_gen+0x123)[0x74d003]
/usr/sbin/mysqld(btr_cur_search_to_nth_level+0x52f)[0x74142f]
/usr/sbin/mysqld(row_search_on_row_ref+0x76)[0x7b86a6]
/usr/sbin/mysqld[0x7b6160]
/usr/sbin/mysqld[0x7b6254]
/usr/sbin/mysqld(row_purge_step+0x99b)[0x7b734b]
/usr/sbin/mysqld(que_run_threads+0x482)[0x7a6d72]
/usr/sbin/mysqld(trx_purge+0x320)[0x7d1970]
/usr/sbin/mysqld(srv_master_thread+0x379)[0x7c9b59]
/lib64/tls/libpthread.so.0[0x3b15606137]
/lib64/tls/libc.so.6(__clone+0x73)[0x3b14fc9f03]
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.
100610 21:58:02 mysqld_safe Starting mysqld daemon with databases from /var/lib/mysql
100610 21:58:02 [Warning] '--log_slow_queries' is deprecated and will be removed in a future release. Please use ''--slow_query_log'/'--slow_query_log_file'' instead.
100610 21:58:02 [Warning] --myisam_max_extra_sort_file_size is deprecated and does nothing in this version.  It will be removed in a future release.
100610 21:58:02 [Note] Plugin 'FEDERATED' is disabled.
100610 21:58:06  InnoDB: Started; log sequence number 334 4179307497
100610 21:58:06 [Note] Recovering after a crash using /var/lib/mysql/mysql-bin
100610 21:58:06 [Note] Starting crash recovery...
100610 21:58:06 [Note] Crash recovery finished.
100610 21:58:06 [Warning] 'user' entry 'root@iadadobcndb01p.ood.ops' ignored in --skip-name-resolve mode.
100610 21:58:06 [Note] Event Scheduler: Loaded 0 events
100610 21:58:06 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.1.47-community-log'  socket: '/var/lib/mysql/mysql.sock'  port: 3306  MySQL Community Server (GPL)
100610 21:58:06 [Note] Slave SQL thread initialized, starting replication in log 'mysql-bin.001234' at position 106, relay log '/var/lib/mysql/mysql-relay-bin.000551' position: 251
100610 21:58:06 [ERROR] Slave SQL: Query caused different errors on master and slave.     Error on master: 'Invalid error code' (7), Error on slave: 'Can't create database '.relay'; database exists' (1007). Default database: ''. Query: 'ALTER DATABASE `#mysql50#.relay` UPGRADE DATA DIRECTORY NAME', Error_code: 0
100610 21:58:06 [ERROR] Slave SQL: Can't create database '.relay'; database exists, Error_code: 1007
100610 21:58:06 [Warning] Slave: Can't create database '.relay'; database exists Error_code: 1007
100610 21:58:06 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'mysql-bin.001234' position 106
100610 21:58:06 [Note] Slave I/O thread: connected to master 'repliad05@10.64.14.25:3306',replication started in log 'mysql-bin.001241' at position 10089918
[11 Jun 2010 2:10] Matt Reid
NOTE: if I leave the @002erelay directory in the data directory and start mysql - the new @002erelay subdirectory will not be created and the data files (and logs) will not be moved.
[11 Jun 2010 2:16] Matt Reid
Also for reference: the logs pasted above are from the slave. This happened on the master as well - which is not a slave to anything. It does not have a database called .relay so I'm not sure why the slave is reporting about a .relay database from the master.
[11 Jun 2010 5:16] MySQL Verification Team
this might be due to bug #53804 !
[11 Jun 2010 5:17] Sveta Smirnova
Thank you for the report.

Please send us your configuration file.
[11 Jun 2010 15:43] Matt Reid
"You do not have access to bug #53804." - can you see why that is?

System Info:
8 Core XEON E5410  @ 2.33GHz
32GB RAM
Linux 2.6.9-89.0.11.ELsmp #1 SMP Mon Aug 31 11:00:34 EDT 2009 x86_64 
Red Hat Enterprise Linux ES release 4 (Nahant Update 8)

MySQL Info
Overall DB Data size: 190.4 GB
Overall DB Index size: 2.7 GB
Overall DB Total size: 190.4 GB
MySQL version: 5.1.47-community-log	
Default engine: InnoDB	
Overall DB InnoDB Tables: 16
Overall DB InnoDB Size: 190.4 GB
Overall DB MyISAM Tables: 30
Overall DB MyISAM Size: 531.6 KB
Uptime: 1 days	
30 day % Growth : 103.04%	 
Avg Load: 0.36	
Memory Used: 59 %	
Memory Size: 31.4 GB	
Queries/sec: 80.10	
Connections: 51	

Here's the config file:
####
[mysql]
host = 127.0.0.1

[mysqld_safe]
nice = -15

[mysqld]
## Files
back_log = 300
open-files-limit = 8192
open-files = 1024
port = 3306
socket = /var/lib/mysql/mysql.sock
## pid-file = /var/lib/mysql/mysql.pid
pid-file = /var/run/mysqld/mysql.pid
skip-external-locking
skip-name-resolve

## Logging
relay_log=/var/lib/mysql/mysql-relay-bin
relay_log_index=/var/lib/mysql/mysql-relay-index
#log=/var/lib/mysql/mysql-gen.log
log_error=/var/lib/mysql/mysql-error
log_warnings
log_bin=/var/lib/mysql/mysql-bin
log_slow_queries=/var/lib/mysql/mysql-slow.log
log_queries_not_using_indexes
long_query_time = 10
max_binlog_size = 1024M
expire_logs_days = 10
log-slave-updates = 1

## Buffers and Connections
key_buffer = 256M
max_allowed_packet = 32M
thread_stack = 128K
thread_cache_size = 150
table_cache = 512
sort_buffer_size = 2M
read_buffer_size = 2M
read_rnd_buffer_size = 2M
join_buffer_size = 2M
query_cache_size = 32M
query_cache_limit = 1M
max_connections = 550
max_connect_errors = 100
concurrent_insert=2
connect_timeout=30

## Default Table Settings
default_table_type = INNODB
sql_mode = NO_AUTO_CREATE_USER
binlog_format = MIXED

## Alt settings
max_heap_table_size = 1G
bulk_insert_buffer_size = 64M
tmp_table_size=1G

## Number of CPU's*2 for thread_concurrency
thread_concurrency = 16

## Replication
server_id = 1221
replicate_do_db=acorn_repository
replicate_do_db=tob
replicate_do_db=whitcomb_mstr
#read_only

## MyISAM Engine
myisam_sort_buffer_size = 1G
myisam_max_sort_file_size = 2G
myisam_max_extra_sort_file_size = 2G
myisam_repair_threads = 1
myisam_recover

## InnoDB Engine
innodb_data_home_dir = /var/lib/mysql/
innodb_data_file_path = ibdata1:512M;ibdata2:10M:autoextend
innodb_log_group_home_dir = /var/lib/mysql/
#innodb_log_arch_dir = /var/lib/mysql/
innodb_log_file_size=1G
innodb_buffer_pool_size = 20G
innodb_additional_mem_pool_size = 16M
innodb_file_io_threads = 4
innodb_status_file
innodb_file_per_table
innodb_flush_log_at_trx_commit = 0
innodb_table_locks=0
innodb_log_buffer_size = 32M
innodb_lock_wait_timeout = 60
innodb_thread_concurrency=16
innodb_commit_concurrency=8
innodb_flush_method=O_DIRECT
innodb_support_xa=0
sync_binlog=1

## TX Isolation
transaction-isolation=READ-COMMITTED

[mysqldump]
quick
quote-names
max_allowed_packet = 128M
[15 Jun 2010 5:52] Sveta Smirnova
Thank you for the feedback.

> "You do not have access to bug #53804." - can you see why that is?

This bug marked as "private". But it is exactly same problem, so closing this as duplicate of bug #53804. Bug #53804 fixed in version 5.1.48 at June, 2. If you build yourself you can get fixed version from Launchpad https://launchpad.net/mysql or wait when version 5.1.48 is released. Don't use snapshots right now: they built before June, 2