Bug #84455 Unable to login in MySQL.
Submitted: 10 Jan 2017 11:15 Modified: 25 Jan 18:37
Reporter: Krunal Ramanujsadhu Email Updates:
Status: No Feedback Impact on me:
None 
Category:MySQL Server: InnoDB storage engine Severity:S2 (Serious)
Version:5.7.12 OS:Any
Assigned to: CPU Architecture:Any
Tags: ib_buffer_pool, restore backup

[10 Jan 2017 11:15] Krunal Ramanujsadhu
Description:
We are creating mysql backup using "tar" and execute in data directory. If some thing goes wrong we are restoring the tar. 
After restore, MySQL comes up. But we are unable to login.
If we are trying to login in MySQL we found following error.
MySQL server gone away. Trying to reconnect...

In Error file we have following errors.

2017-01-09T13:28:32.511786Z 0 [Note] InnoDB: 5.7.12 started; log sequence number 12784462932
2017-01-09T13:28:32.512599Z 0 [Note] InnoDB: Loading buffer pool(s) from /var/QS/db/ascii/ib_buffer_pool
2017-01-09T13:28:32.513126Z 0 [Note] Plugin 'FEDERATED' is disabled.
2017-01-09T13:28:32.514623Z 0 [Note] Recovering after a crash using /var/QS/db/ascii/repl
2017-01-09T13:28:32.514650Z 0 [Note] Starting crash recovery...
2017-01-09T13:28:32.514691Z 0 [Note] Crash recovery finished.
2017-01-09T13:28:32.542859Z 0 [Note] Skipping generation of SSL certificates as options related to SSL are specified.
2017-01-09T13:28:32.544203Z 0 [Warning] CA certificate /var/QS/db/ascii/ca.pem is self signed.
2017-01-09T13:28:32.544272Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2017-01-09T13:28:32.544532Z 0 [Note] Server hostname (bind-address): '*'; port: 3308
2017-01-09T13:28:32.544696Z 0 [Note] IPv6 is available.
2017-01-09T13:28:32.544716Z 0 [Note]   - '::' resolves to '::';
2017-01-09T13:28:32.544737Z 0 [Note] Server socket created on IP: '::'.
2017-01-09T13:28:32.702994Z 1 [Warning] Storing MySQL user name or password information in the master info repository is not secure and is therefore not recommended. Please consider using the USER and PASSWORD connection options for START SLAVE; see the 'START SLAVE Syntax' in the MySQL Manual for more information.
2017-01-09T13:28:32.704415Z 2 [Warning] Slave SQL for channel '': If a crash happens this configuration does not guarantee that the relay log info will be consistent, Error_code: 0
2017-01-09T13:28:32.704523Z 2 [Note] Slave SQL thread for channel '' initialized, starting replication in log 'repl.000010' at position 2310, relay log '/var/QS/db/ascii/mysql-relay-bin.000002' position: 2471
2017-01-09T13:28:32.706452Z 2 [Warning] InnoDB: A transaction id in a record of table `mysql`.`innodb_table_stats` is newer than the system-wide maximum.
2017-01-09T13:28:32.706502Z 2 [Warning] InnoDB: A transaction id in a record of table `mysql`.`innodb_table_stats` is newer than the system-wide maximum.
2017-01-09T13:28:32.706524Z 2 [Warning] InnoDB: A transaction id in a record of table `mysql`.`innodb_table_stats` is newer than the system-wide maximum.
2017-01-09T13:28:32.709128Z 0 [Note] Event Scheduler: Loaded 0 events
2017-01-09T13:28:32.709427Z 0 [Note] /usr/sbin/mysqld: ready for connections.
Version: '5.7.12-enterprise-commercial-advanced-log'  socket: '/var/QS/db/ascii/mysql.sock'  port: 3308  MySQL Enterprise Server - Advanced Edition (Commercial)
2017-01-09T13:28:32.827392Z 1 [Note] Slave I/O thread for channel '': connected to master 'qsrepl@2606:b400:0605:b913:004e:c9ff:fed3:a079:3308',replication started in log 'repl.000017' at position 3568
2017-01-09T13:28:33.826487Z 0 [Note] InnoDB: Buffer pool(s) load completed at 170109  8:28:33
2017-01-09T13:29:31.724088Z 2 [ERROR] InnoDB: Cannot allocate 18446744073709540840 bytes of memory after 60 retries over 60 seconds. OS error: Cannot allocate memory (12). Check if you should increase the swap file or ulimits of your operating system. Note that on most 32-bit computers the process memory space is limited to 2 GB or 4 GB.
2017-01-09 08:29:31 0x7f5b813c6700  InnoDB: Assertion failure in thread 140030986970880 in file ut0ut.cc line 935
InnoDB: Failing assertion: !m_fatal
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.7/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
13:29:31 UTC - 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.
Attempting to collect some information that could help diagnose the problem.
As this is a crash and something is definitely wrong, the information
collection process might fail.

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

Thread pointer: 0x7f5b480008c0
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...

Please find the output of "free -m" :
             total       used       free     shared    buffers     cached
Mem:         15789      10353       5436          0        208       8631
-/+ buffers/cache:       1513      14275
Swap:         8063        135       7928

Please find the configuration in my.cnf file.
innodb_log_files_in_group         = 2
innodb_log_file_size              = 64M
innodb_log_buffer_size            = 8M
innodb_buffer_pool_size           = 1G
tmp_table_size                    = 20971520
key_buffer_size                   = 4194304
tmp_table_size                    = 20971520
key_buffer_size                   = 4194304
table_open_cache                  = 2500
performance_schema                = OFF
long_query_time                   = 1
innodb_flush_log_at_trx_commit    = 1
innodb_lock_wait_timeout          = 50
explicit_defaults_for_timestamp   = TRUE
optimizer_switch                  = 'block_nested_loop=off'

How to repeat:
This issue comes intermediate so we are unable to reproduce every time.
[10 Jan 2017 11:37] Umesh Shastry
Hello Krunal,

Thank you for the report.
This is duplicate of Bug #81654, which is marked as !bug.

Thanks,
Umesh
[10 Jan 2017 11:56] Shane Bester
Actually, this is a corruption of some kind because the number is 2^64 or so:
"InnoDB: Cannot allocate 18446744073709540840 bytes of memory"

My guess would be something restored improperly...
[11 Jan 2017 5:41] Krunal Ramanujsadhu
Hi Umesh,

In my.cnf file we have following configuration.
innodb_buffer_pool_size           = 1G

Than why i am getting following error.

[ERROR] InnoDB: Cannot allocate 18446744073709540840 bytes of memory after 60 retries over 60 seconds. OS error: Cannot allocate memory (12). Check if you should increase the swap file or ulimits of your operating system. Note that on most 32-bit computers the process memory space is limited to 2 GB or 4 GB.
2017-01-09 08:29:31 0x7f5b813c6700  InnoDB: Assertion failure in thread 140030986970880 in file ut0ut.cc line 935
[25 Dec 2017 18:37] Shane Bester
Kindly upload the complete mysql error log, compressed.

This is not a duplicate of the bug mentioned previously.
Also, interesting to note the messages like this:

[Warning] InnoDB: A transaction id in a record of table `mysql`.`innodb_table_stats` is newer than the system-wide maximum.

Which I have seen once or twice in tests...
[26 Jan 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".