MySQL Bugs: #71104: error on database start activate crashing recovery.

Bug #71104	error on database start activate crashing recovery.
Submitted:	6 Dec 2013 12:43	Modified:	10 Mar 2014 21:59
Reporter:	massimo mico	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Errors	Severity:	S1 (Critical)
Version:	5.7.3-m13	OS:	Windows (w2008 r2)
Assigned to:		CPU Architecture:	Any

Description:
i've installed 5.7.3 version of mysql (and use same configuration of previous 5.7.2 where everything ok) and when server start an error activate crashing recovery. 

i post log:
013-12-06T12:06:26.140880Z 0 [Note] Giving 0 client threads a chance to die gracefully
2013-12-06T12:06:26.141857Z 0 [Note] Shutting down slave threads
2013-12-06T12:06:26.143810Z 0 [Note] Forcefully disconnecting 0 remaining clients
2013-12-06T12:06:26.144786Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2013-12-06T12:06:26.147716Z 0 [Note] Binlog end
2013-12-06T12:07:12.195550Z 0 [Note] Plugin 'FEDERATED' is disabled.
2013-12-06T12:07:12.199456Z 0 [Note] InnoDB: The InnoDB memory heap is disabled
2013-12-06T12:07:12.199456Z 0 [Note] InnoDB: Mutexes and rw_locks use Windows interlocked functions
2013-12-06T12:07:12.202385Z 0 [Note] InnoDB: Uses system mutexes
2013-12-06T12:07:12.203362Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.3
2013-12-06T12:07:12.209221Z 0 [Note] InnoDB: Number of pools: 1
2013-12-06T12:07:12.213127Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2013-12-06T12:07:12.216056Z 0 [Note] InnoDB: Initializing buffer pool, total size = 1.0G, instances = 3
2013-12-06T12:07:12.405497Z 0 [Note] InnoDB: Completed initialization of buffer pool
2013-12-06T12:07:12.442604Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2013-12-06T12:07:12.460181Z 0 [Note] InnoDB: The log sequence numbers 87594636 and 87594636 in ibdata files do not match the log sequence number 88411279 in the ib_logfiles!
2013-12-06T12:07:12.463111Z 0 [Note] InnoDB: Database was not shutdown normally!
2013-12-06T12:07:12.464087Z 0 [Note] InnoDB: Starting crash recovery.
2013-12-06T12:07:12.465064Z 0 [Note] InnoDB: Reading tablespace information from the .ibd files...
2013-12-06T12:07:13.279465Z 0 [Note] InnoDB: Restoring possible half-written data pages 
2013-12-06T12:07:13.280441Z 0 [Note] InnoDB: from the doublewrite buffer...
2013-12-06T12:07:14.174915Z 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
2013-12-06T12:07:14.177845Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2013-12-06T12:07:14.178821Z 0 [Note] InnoDB: Setting file ".\ibtmp1" size to 24 MB
2013-12-06T12:07:14.179798Z 0 [Note] InnoDB: Database physically writes the file full: wait ...
2013-12-06T12:07:14.558680Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2013-12-06T12:07:14.560633Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2013-12-06T12:07:14.693437Z 0 [Note] InnoDB: Waiting for purge to start
2013-12-06T12:07:14.777416Z 0 [Note] InnoDB: 5.7.3 started; log sequence number 88411279
2013-12-06T12:07:14.785228Z 0 [Note] Server hostname (bind-address): '*'; port: 3306
2013-12-06T12:07:14.787181Z 0 [Note] IPv6 is available.
2013-12-06T12:07:14.789134Z 0 [Note]   - '::' resolves to '::';
2013-12-06T12:07:14.790110Z 0 [Note] Server socket created on IP: '::'.
2013-12-06T12:07:14.802805Z 0 [Note] Event Scheduler: Loaded 0 events
2013-12-06T12:07:14.804758Z 0 [Note] C:\MySQL\bin\mysqld: ready for connections.
Version: '5.7.3-m13'  socket: ''  port: 3306  MySQL Community Server (GPL)

How to repeat:
on server start use this configuration:

my.ini:
[client]

port=3306

[mysqld]

port=3306
basedir="C:/MySQL/"
datadir="C:/MySQL/Data/"
tmpdir="C:/MySQL/temp/"
character-set-server=utf8

skip-external-locking

sql-mode="STRICT_TRANS_TABLES,NO_AUTO_CREATE_USER,NO_ENGINE_SUBSTITUTION"

max_connections=1000
key_buffer_size=25M
low_priority_updates=1
table_open_cache = 3000
back_log=150
query_cache_type=0
table_open_cache_instances=1
join_buffer_size = 96K
sort_buffer_size = 96K

innodb_log_buffer_size=8M
innodb_buffer_pool_size=1G
innodb_log_file_size=256M
innodb_temp_data_file_path=ibtmp1:24M:autoextend

#-------TEST----------------
explicit_defaults_for_timestamp
innodb_buffer_pool_instances=3
innodb_thread_concurrency=0
innodb_flush_log_at_trx_commit=2
innodb_max_dirty_pages_pct=50
innodb_use_native_aio=1
innodb_stats_persistent=1
innodb_spin_wait_delay=6
innodb_adaptive_flushing=1
innodb_flush_neighbors=0
innodb_purge_threads=1
innodb_adaptive_hash_index=0
performance_schema=off
innodb_checksum_algorithm=none
innodb_doublewrite=0
innodb_support_xa=0
innodb_file_format=Barracuda
innodb_file_per_table

Please attach the whole error file compressed. Thanks.

I think it is important how the 5.7.2 server was stopped as well as the installation method (using the "MySQL Instller" or some other method).

Obviously 5.7.2 was not shut down properly. This could be both a human error or a bug in an automated installer or a bug in MySQL 5.7.2 (what could then possibly also exist in 5.7.3).

Peter
(not a MySQL/Oracle person)

i've installed mysql 5.7.3 with clean unzip file and copied my.ini file in new mysql directory and next i've restored a dump file created with version 5.7.2. 

Isn't database corruption! because i've tested to make a full clean installation of 5.7.3 version and after start mysql with no restore dump of database, i receive the same error.

I think this is a bug on shutdown or start database procedure.

Thanks

LOG FILE MYSQL

Attachment: SERVER-2-1.zip (application/x-zip-compressed, text), 9.54 KiB.

Question are then: With what tool was the dump created?  

If you used 'mysqldump' what was then the full command? IMO it is interesting if --flush-logs and --single-transaction were used (or what similar options another tool has, if another tool was used.  Decent GUI tolls will have checkboxes or similar for the options). Some old GUI clients may not be fit for dumping InnoDB data (due to lack of proper options support). Not sure about phpMyAdmin.

The problem is with the dump itself. It is/was in an inconsistent state. MySQL 7.0.3 recovery does what it must: bring the database to a consistent state (including rolling back non-committed transactions)

hi Peter,

dump created with mysqldump on mysql 5.7.2 with the following line command:

mysqldump -u root -p --all-databases >c:\mysql\dump20131203.sql

but the problem occur also in full clean installation with no restore dump databases. 

Thanks

ok .. let Miguel or another MySQL supporter handle. 

If this error log occurs first time you start the server - and even before any user data are created, it looks weird.

Thank you for the feedback.

What is the actual file size of InnoDB log files?

Ok, thank Peter!

I precise that mysql server run on virtual machine enviroment, the virtual machine have a Windows 2008 R2 server installed, and the host machine have Windows 2012 server with Hyper-V role.

thanks

hi Sveta,

the actual size of innodb log file is 256M. I've tested also with 64M, 128M. 

Thanks

I think the bug is in shutdown procedure of InnoDB plugin, because in clean installation with no database restore, the server start and create file log, at first shutdown log are cut in shutdown plugin:
2013-12-07T11:19:14.512085Z 0 [Note] Shutting down plugin 'INNODB_SYS_FIELDS'

after this no shutdown plugin is logged when server stop.

i add zip file with log of clean installation  to verify this.

LOG OF CLEAN NEW INSTALLATION 5.7.3

Attachment: CLEAN INST SERVER LOG.zip (application/x-zip-compressed, text), 1.88 KiB.

Something is wrong with your installation. There are no messages about plugins being shut down ... So, server can't find them, which is a consequence of bad installation ...

i've downloaded a Windows x64 version zip file, after i've unzip file in root folder and add in mysql directory MY.INI file and create a temp folder. This is my installation.

The crucial question is:

How do you shutdown MySQL server ????

If you shut it down with any other means except:

mysqladmin shutdown

then what you get is expected behavior !!! This is because you have this value:

innodb_flush_log_at_trx_commit=2

and because you can not have clean startup even if you would set all recovery features on.

I don't think this is the problem! Because i've a 5.7.2-m12 version installed in the same machine with same configuration and no problem occur in this version!

however i stop mysql with command "net stop mysql" (stop Windows service) is the same of mysqladmin shutdown, however i've same problem also i stop with mysqladmin and remove innodb_flush_log_at_trx_commit=2 in configuration file.

i think the bug is in mysqld.exe in shutdown procedure when MySql is installed as Windows service.
Infact, if i start server with command line mysqld and stop server with command mysqladmin shutdown, the server start and stop correctly with no error messages.
When i stop the server as Windows service with net stop Mysql command a shutdown procedure not activated shutdown of INNODB plugin. In log file i've only this:

2013-12-17T11:33:18.660914Z 0 [Note] c:\mysql\bin\mysqld: Normal shutdown

2013-12-17T11:33:18.663844Z 0 [Note] Giving 0 client threads a chance to die gracefully
2013-12-17T11:33:18.664820Z 0 [Note] Shutting down slave threads
2013-12-17T11:33:18.666773Z 0 [Note] Forcefully disconnecting 0 remaining clients
2013-12-17T11:33:18.667750Z 0 [Note] Event Scheduler: Purging the queue. 0 events
2013-12-17T11:33:18.670679Z 0 [Note] Binlog end

Thank you for the bug report. Verified on Windows 8.1.

thank you for verification.,

Noted in MySQL 5.7.5 changelog.

When MySQL runs as service on Windows, NTService.Stop() initiates
shutdown and exit events during shutdown. After a code reorganization
in MySQL 5.7.3, a call to clean_up() was missed, resulting in
initiation of crash recovery.