[MDEV-12848] InnoDB: Assertion failure in file mariadb-10.2.5/storage/innobase/handler/ha_innodb.cc line 2780 Created: 2017-05-19  Updated: 2017-08-23  Resolved: 2017-08-23

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.2.5, 10.2.6
Fix Version/s: 10.2.7

Type: Bug Priority: Major
Reporter: Diogo Oliveira de Melo Assignee: Jan Lindström (Inactive)
Resolution: Fixed Votes: 0
Labels: crash, docker, innodb
Environment:

linux, x86-64

Issue Links:
Relates
relates to MDEV-6076 Persistent AUTO_INCREMENT for InnoDB Closed

 Description   

MariaDB 10.2.5 is constantly crashing.

with the message

2017-05-19 13:33:00 0x7f97f67fe700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.5/storage/innobase/handler/ha_innodb.cc line 2780
 
InnoDB: Failing assertion: block > 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.7/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
170519 13:33:00 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
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.
 
 
 
Server version: 10.2.5-MariaDB-10.2.5+maria~jessie
 
key_buffer_size=134217728
 
read_buffer_size=2097152
 
max_used_connections=2
 
max_threads=102
 
thread_count=9
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759886 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f97880008c8
 
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 = 0x7f97f67fde38 thread_stack 0x49000
 
mysqld(my_print_stacktrace+0x2e)[0x55dafb3c9d4e]
 
mysqld(handle_fatal_signal+0x305)[0x55dafae10205]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f981c996890]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f981acbe067]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f981acbf448]
 
mysqld(+0x4178b2)[0x55dafabb68b2]
 
mysqld(+0x7f08b8)[0x55dafaf8f8b8]
 
mysqld(+0x808879)[0x55dafafa7879]
 
mysqld(_ZN7handler21update_auto_incrementEv+0x2dd)[0x55dafae1637d]
 
mysqld(+0x807699)[0x55dafafa6699]
 
mysqld(_ZN7handler12ha_write_rowEPh+0x1af)[0x55dafae1a62f]
 
mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x6f)[0x55dafac4fc6f]
 
mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x1234)[0x55dafac58e84]
 
mysqld(_Z21mysql_execute_commandP3THD+0x2372)[0x55dafac6d962]
 
mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x28a)[0x55dafac735ca]
 
mysqld(+0x4d4d87)[0x55dafac73d87]
 
mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xfdd)[0x55dafac752bd]
 
mysqld(_Z10do_commandP3THD+0x164)[0x55dafac76874]
 
mysqld(_Z24do_handle_one_connectionP7CONNECT+0x232)[0x55dafad48a62]
 
mysqld(handle_one_connection+0x3d)[0x55dafad48bfd]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x7f981c98f064]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f981ad7162d]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f978800eed0): INSERT INTO `user` ( id, `first_name`,`last_name`,`email`,`password`,`token`,`who_id` ) VALUES    ( NULL, 'John','Doe','john.doe@vblpso.click','64d09d9930c8ecf79e513167a588cb75439b762ce8f9b22ea59765f32aa74ca19d2f1e97dc922a3d4954594a05062917fb24d1f8e72f2ed02a58ed7534f94d27',NULL,1 )
 
Connection ID (thread ID): 65
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
 
 
 
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.

Running from Dockerfile:

FROM vonbraunlabs/mariadb:10.2
 
 
 
RUN apt-get update -y
 
RUN apt-get install -y \
 
        dnsutils \
 
        file \
 
        htop \
 
        procps \
 
        psmisc \
 
        redis-tools \
 
        sudo \
 
        vim
 
 
 
 
 
USER mysql
 
COPY galera.cnf /etc/mysql/conf.d/galera.cnf
 
WORKDIR /opt
 
 
 
COPY start.sh ./
 
COPY recreateall.sql /docker-entrypoint-initdb.d/
 
 
 
EXPOSE 3306 4444 4567 4567/udp 4568
 
 
 
USER root
 
 
 
ENTRYPOINT ["./start.sh"]

The galera.cnf have the content:

[galera]
 
# Mandatory settings
 
wsrep_on=ON
 
wsrep_provider=/usr/lib/galera/libgalera_smm.so
 
wsrep_cluster_name=vblpso
 
wsrep_cluster_address=GCOMM
 
wsrep_sst_method=rsync
 
binlog_format=row
 
default_storage_engine=InnoDB
 
innodb_autoinc_lock_mode=2
 
 
 
wsrep_node_address=NODEADDRESS
 
#
 
# Allow server to accept connections on all interfaces.
 
#
 
bind-address=0.0.0.0



 Comments   
Comment by Diogo Oliveira de Melo [ 2017-05-23 ]

Problem is also affecting version 10.2.6+mariadb~jessie

2017-05-23 19:52:53 0x7f7865954700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/handler/ha_innodb.cc line 2784
 
InnoDB: Failing assertion: block > 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.7/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
170523 19:52:53 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
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.
 
 
 
Server version: 10.2.6-MariaDB-10.2.6+maria~jessie
 
key_buffer_size=134217728
 
read_buffer_size=2097152
 
max_used_connections=1
 
max_threads=102
 
thread_count=9
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759887 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f77f00008c8
 
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 = 0x7f7865953e38 thread_stack 0x49000
 
mysqld(my_print_stacktrace+0x2e)[0x5568fda85a5e]
 
mysqld(handle_fatal_signal+0x305)[0x5568fd4c64f5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f7883b18890]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f7881e40067]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f7881e41448]
 
mysqld(+0x41c0a0)[0x5568fd26b0a0]
 
mysqld(+0x7f7dd8)[0x5568fd646dd8]
 
mysqld(+0x80cbf9)[0x5568fd65bbf9]
 
mysqld(_ZN7handler21update_auto_incrementEv+0x2dd)[0x5568fd4cc66d]
 
mysqld(+0x80ec49)[0x5568fd65dc49]
 
mysqld(_ZN7handler12ha_write_rowEPh+0x1af)[0x5568fd4d091f]
 
mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x6f)[0x5568fd304b1f]
 
mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x1234)[0x5568fd30dd44]
 
mysqld(_Z21mysql_execute_commandP3THD+0x24ca)[0x5568fd32297a]
 
mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x28a)[0x5568fd32844a]
 
mysqld(+0x4d9c07)[0x5568fd328c07]
 
mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xfdd)[0x5568fd32a13d]
 
mysqld(_Z10do_commandP3THD+0x164)[0x5568fd32b6f4]
 
mysqld(_Z24do_handle_one_connectionP7CONNECT+0x232)[0x5568fd3fde72]
 
mysqld(handle_one_connection+0x3d)[0x5568fd3fe00d]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x7f7883b11064]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f7881ef362d]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f77f000eed0): INSERT INTO `user` ( id, `first_name`,`last_name`,`email`,`password`,`token`,`who_id` ) VALUES    ( NULL, 'John','Doe','john.doe@vblpso.click','64d09d9930c8ecf79e513167a588cb75439b762ce8f9b22ea59765f32aa74ca19d2f1e97dc922a3d4954594a05062917fb24d1f8e72f2ed02a58ed7534f94d27',NULL,1 )
 
Connection ID (thread ID): 72
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
 
 
 
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.

Comment by Marko Mäkelä [ 2017-05-24 ]

The assertion fails in innobase_next_autoinc() when need*step=0. Presumably, one of the parameters is being passed as 0.

The AUTO_INCREMENT code was changed in MariaDB 10.2.5 by MDEV-6076, which introduced persistent AUTO_INCREMENT.

Comment by Marko Mäkelä [ 2017-05-24 ]

dmelo, can you get a core dump? Or can you create a reduced dataset for reproducing the failure?
Based on the input so far, I am assuming that user.id is an AUTO_INCREMENT column, for which the INSERT statement is trying to assign a value.
This failure is probably dependent on the data contents.

Can you repeat the problem on another system after restoring the table from an SQL dump?

I am guessing that this might have something to do with the persistent AUTO_INCREMENT feature (MDEV-6076).
Was IMPORT TABLESPACE ever used on this file? See MDEV-12123.
Can you dump the clustered index root page? That would be something like:

dd if=user.ibd bs=16384 skip=3 count=1 of=page3.bin

If you are using non-default innodb_page_size, please use a matching block size (bs) value in the above command.

Comment by Marko Mäkelä [ 2017-05-24 ]

I think that the most likely explanation for this failure is that handler::update_auto_increment() is invoking ha_innobase::get_auto_increment() with variables->auto_increment_increment=0.
However, I cannot repeat the problem with the following:

--source include/have_innodb.inc
 
SET auto_increment_increment=0;
 
SELECT @@SESSION.auto_increment_increment;
 
CREATE TABLE t(a SERIAL) ENGINE=InnoDB;
 
INSERT INTO t SET a=NULL;
 
DROP TABLE t;

It would run with auto_increment_increment=1.
Also, if I remove the auto_increment_increment references from the test and run

./mtr --mem --mysqld=--auto-increment-increment=0 innodb.the_new_test

it will tell me the following:

Found warnings/errors in server log file!
 
        Test ended at 2017-05-24 09:58:01
 
line
 
2017-05-24  9:58:00 140378799781696 [Warning] option 'auto_increment_increment': unsigned value 0 adjusted to 1

Comment by Diogo Oliveira de Melo [ 2017-05-25 ]

So far, I couldn't determine what triggers the crash. I'm running galera cluster with just one node (dev environment) on my machine. I will try to provide the steps necessary to reproduce the problem.

Comment by Diogo Oliveira de Melo [ 2017-05-26 ]

I was able to reproduce the error on two different machines, but all running Fedora 25:

  • Linux aws-nvirginia-00 4.10.10-200.fc25.x86_64 #1 SMP Thu Apr 13 01:11:51 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux
  • Linux merov2 4.10.14-200.fc25.x86_64+debug #1 SMP Wed May 3 22:26:03 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux

I have placed the code I used on https://github.com/dmelo/mariadb-MDEV-12848 . The results always comes out the same. I have noticed that the time things are executed matters. I wait 5 mins between creating the tables and starting a transaction, to perform an insert, that is when it crashes.

Installing base db
 
Installing MariaDB/MySQL system tables in '/var/lib/mysql' ...
 
OK
 
 
 
To start mysqld at boot time you have to copy
 
support-files/mysql.server to the right place for your system
 
 
 
PLEASE REMEMBER TO SET A PASSWORD FOR THE MariaDB root USER !
 
To do so, start the server, then issue the following commands:
 
 
 
'/usr/bin/mysqladmin' -u root password 'new-password'
 
'/usr/bin/mysqladmin' -u root -h 172.17.0.2 password 'new-password'
 
 
 
Alternatively you can run:
 
'/usr/bin/mysql_secure_installation'
 
 
 
which will also give you the option of removing the test
 
databases and anonymous user created by default.  This is
 
strongly recommended for production servers.
 
 
 
See the MariaDB Knowledgebase at http://mariadb.com/kb or the
 
MySQL manual for more instructions.
 
 
 
You can start the MariaDB daemon with:
 
cd '/usr' ; /usr/bin/mysqld_safe --datadir='/var/lib/mysql'
 
 
 
You can test the MariaDB daemon with mysql-test-run.pl
 
cd '/usr/mysql-test' ; perl mysql-test-run.pl
 
 
 
Please report any problems at http://mariadb.org/jira
 
 
 
The latest information about MariaDB is available at http://mariadb.org/.
 
You can find additional information about the MySQL part at:
 
http://dev.mysql.com
 
Consider joining MariaDB's strong and vibrant community:
 
https://mariadb.org/get-involved/
 
 
 
Starting mysqld
 
MySQL init process in progress...
 
2017-05-26 17:06:38 139656929847168 [Note] mysqld (mysqld 10.2.6-MariaDB-10.2.6+maria~jessie) starting as process 61 ...
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Read nil XID from storage engines, skipping position init
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: wsrep_load(): Galera 25.3.20(r3703) by Codership Oy <info@codership.com> loaded successfully.
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: CRC-32C: using hardware acceleration.
 
2017-05-26 17:06:38 139656929847168 [Warning] WSREP: Could not open state file for reading: '/var/lib/mysql//grastate.dat'
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1, safe_to_bootsrap: 1
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Passing config to GCS: base_dir = /var/lib/mysql/; base_host = 127.0.0.1; base_port = 4567; cert.log_conflicts = no; debug = no; evs.auto_evict = 0; evs.delay_margin = PT1S; evs.delayed_keep_period = PT30S; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 3; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /var/lib/mysql/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /var/lib/mysql//galera.cache; gcache.page_size = 128M; gcache.recover = no; gcache.size = 128M; gcomm.thread_prio = ; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.igno
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: GCache history reset: old(00000000-0000-0000-0000-000000000000:0) -> new(00000000-0000-0000-0000-000000000000:-1)
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: wsrep_sst_grab()
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Start replication
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: 'wsrep-new-cluster' option used, bootstrapping the cluster
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: protonet asio version 0
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Using CRC-32C for message checksums.
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: backend: asio
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: gcomm thread scheduling priority set to other:0 
2017-05-26 17:06:38 139656929847168 [Warning] WSREP: access file(/var/lib/mysql//gvwstate.dat) failed(No such file or directory)
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: restore pc from disk failed
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: GMCast version 0
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: (ae976865, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: (ae976865, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: EVS version 0
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: gcomm: bootstrapping new group 'vblpso'
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: start_prim is enabled, turn off pc_recovery
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Node ae976865 state prim
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: view(view_id(PRIM,ae976865,1) memb {
 
	ae976865,0
 
} joined {
 
} left {
 
} partitioned {
 
})
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: save pc into disk
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: discarding pending addr without UUID: tcp://127.0.0.1:4567
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: discarding pending addr proto entry 0x5589f122d060
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: gcomm: connected
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Opened channel 'vblpso'
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: Waiting for SST to complete.
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: Starting new group from scratch: ae9805ae-4235-11e7-a92e-1e8c54eeb741
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: STATE_EXCHANGE: sent state UUID: ae98083d-4235-11e7-b34d-eb1ac436ccf8
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: STATE EXCHANGE: sent state msg: ae98083d-4235-11e7-b34d-eb1ac436ccf8
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: STATE EXCHANGE: got state msg: ae98083d-4235-11e7-b34d-eb1ac436ccf8 from 0 (045fe757ed5f)
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: Quorum results:
 
	version    = 4,
 
	component  = PRIMARY,
 
	conf_id    = 0,
 
	members    = 1/1 (joined/total),
 
	act_id     = 0,
 
	last_appl. = -1,
 
	protocols  = 0/7/3 (gcs/repl/appl),
 
	group UUID = ae9805ae-4235-11e7-a92e-1e8c54eeb741
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: Flow-control interval: [16, 16]
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: Restored state OPEN -> JOINED (0)
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: Member 0.0 (045fe757ed5f) synced with group.
 
2017-05-26 17:06:38 139656549091072 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
 
2017-05-26 17:06:38 139656928347904 [Note] WSREP: New cluster view: global state: ae9805ae-4235-11e7-a92e-1e8c54eeb741:0, view# 1: Primary, number of nodes: 1, my index: 0, protocol version 3
 
2017-05-26 17:06:38 139656929847168 [Note] WSREP: SST complete, seqno: 0
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Uses event mutexes
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Compressed tables use zlib 1.2.8
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Using Linux native AIO
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Number of pools: 1
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Using SSE2 crc32 instructions
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Initializing buffer pool, total size = 256M, instances = 1, chunk size = 128M
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Completed initialization of buffer pool
 
2017-05-26 17:06:38 139655736407808 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Highest supported file format is Barracuda.
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2017-05-26 17:06:38 139656929847168 [Note] InnoDB: Waiting for purge to start
 
2017-05-26 17:06:39 139656929847168 [Note] InnoDB: 5.7.14 started; log sequence number 1620098
 
2017-05-26 17:06:39 139655592785664 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2017-05-26 17:06:39 139655592785664 [Note] InnoDB: Buffer pool(s) load completed at 170526 17:06:39
 
2017-05-26 17:06:39 139656929847168 [Note] Plugin 'FEEDBACK' is disabled.
 
2017-05-26 17:06:39 139656929847168 [Note] Server socket created on IP: '0.0.0.0'.
 
2017-05-26 17:06:39 139656929847168 [Warning] 'user' entry 'root@045fe757ed5f' ignored in --skip-name-resolve mode.
 
2017-05-26 17:06:39 139656929847168 [Warning] 'proxies_priv' entry '@% root@045fe757ed5f' ignored in --skip-name-resolve mode.
 
2017-05-26 17:06:39 139656928347904 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
2017-05-26 17:06:39 139656928347904 [Note] WSREP: REPL Protocols: 7 (3, 2)
 
2017-05-26 17:06:39 139656928347904 [Note] WSREP: Assign initial position for certification: 0, protocol version: 3
 
2017-05-26 17:06:39 139656799700736 [Note] WSREP: Service thread queue flushed.
 
2017-05-26 17:06:39 139656929847168 [Note] Reading of all Master_info entries succeded
 
2017-05-26 17:06:39 139656929847168 [Note] Added new Master_info '' to hash table
 
2017-05-26 17:06:39 139656929847168 [Note] mysqld: ready for connections.
 
Version: '10.2.6-MariaDB-10.2.6+maria~jessie'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
2017-05-26 17:06:39 139656928347904 [Note] WSREP: GCache history reset: old(00000000-0000-0000-0000-000000000000:0) -> new(ae9805ae-4235-11e7-a92e-1e8c54eeb741:0)
 
2017-05-26 17:06:39 139656928347904 [Note] WSREP: Synchronized with group, ready for connections
 
2017-05-26 17:06:39 139656928347904 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
 
./start.sh: running /docker-entrypoint-initdb.d/0-create-and-populate.sql
 
 
 
 
 
Fri May 26 17:06:40 UTC 2017
 
Fri May 26 17:11:40 UTC 2017
 
running 1-action.sql
 
2017-05-26 17:11:40 0x7f0450791700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/handler/ha_innodb.cc line 2784
 
InnoDB: Failing assertion: block > 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.7/en/forcing-innodb-recovery.html
 
InnoDB: about forcing recovery.
 
170526 17:11:40 [ERROR] 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.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
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.
 
 
 
Server version: 10.2.6-MariaDB-10.2.6+maria~jessie
 
key_buffer_size=134217728
 
read_buffer_size=2097152
 
max_used_connections=1
 
max_threads=102
 
thread_count=9
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 759887 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f041c000a88
 
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 = 0x7f0450790e38 thread_stack 0x49000
 
mysqld(my_print_stacktrace+0x2e)[0x5589efcb3a5e]
 
mysqld(handle_fatal_signal+0x305)[0x5589ef6f44f5]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0xf890)[0x7f04696fb890]
 
/lib/x86_64-linux-gnu/libc.so.6(gsignal+0x37)[0x7f0467a23067]
 
/lib/x86_64-linux-gnu/libc.so.6(abort+0x148)[0x7f0467a24448]
 
mysqld(+0x41c0a0)[0x5589ef4990a0]
 
mysqld(+0x7f7dd8)[0x5589ef874dd8]
 
mysqld(+0x80cbf9)[0x5589ef889bf9]
 
mysqld(_ZN7handler21update_auto_incrementEv+0x2dd)[0x5589ef6fa66d]
 
mysqld(+0x80ec49)[0x5589ef88bc49]
 
mysqld(_ZN7handler12ha_write_rowEPh+0x1af)[0x5589ef6fe91f]
 
mysqld(_Z12write_recordP3THDP5TABLEP12st_copy_info+0x6f)[0x5589ef532b1f]
 
mysqld(_Z12mysql_insertP3THDP10TABLE_LISTR4ListI4ItemERS3_IS5_ES6_S6_15enum_duplicatesb+0x1234)[0x5589ef53bd44]
 
mysqld(_Z21mysql_execute_commandP3THD+0x24ca)[0x5589ef55097a]
 
mysqld(_Z11mysql_parseP3THDPcjP12Parser_statebb+0x28a)[0x5589ef55644a]
 
mysqld(+0x4d9c07)[0x5589ef556c07]
 
mysqld(_Z16dispatch_command19enum_server_commandP3THDPcjbb+0xfdd)[0x5589ef55813d]
 
mysqld(_Z10do_commandP3THD+0x164)[0x5589ef5596f4]
 
mysqld(_Z24do_handle_one_connectionP7CONNECT+0x232)[0x5589ef62be72]
 
mysqld(handle_one_connection+0x3d)[0x5589ef62c00d]
 
/lib/x86_64-linux-gnu/libpthread.so.0(+0x8064)[0x7f04696f4064]
 
/lib/x86_64-linux-gnu/libc.so.6(clone+0x6d)[0x7f0467ad662d]
 
 
 
Trying to get some variables.
 
Some pointers may be invalid and cause the dump to abort.
 
Query (0x7f041c0c2510): INSERT INTO `user` (`first_name`, `last_name`, `email`, `language_id`, `who_id`) VALUES     ('John', 'Doe', 'jd@example.com', (SELECT `id` FROM `language` WHERE `locale` = 'en-us'), 1)
 
Connection ID (thread ID): 12
 
Status: NOT_KILLED
 
 
 
Optimizer switch: index_merge=on,index_merge_union=on,index_merge_sort_union=on,index_merge_intersection=on,index_merge_sort_intersection=off,engine_condition_pushdown=off,index_condition_pushdown=on,derived_merge=on,derived_with_keys=on,firstmatch=on,loosescan=on,materialization=on,in_to_exists=on,semijoin=on,partial_match_rowid_merge=on,partial_match_table_scan=on,subquery_cache=on,mrr=off,mrr_cost_based=off,mrr_sort_keys=off,outer_join_with_cache=on,semijoin_with_cache=on,join_cache_incremental=on,join_cache_hashed=on,join_cache_bka=on,optimize_join_buffer_size=off,table_elimination=on,extended_keys=on,exists_to_in=on,orderby_uses_equalities=on,condition_pushdown_for_derived=on
 
 
 
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.
 
ERROR 2013 (HY000) at line 2 in file: '1-action.sql': Lost connection to MySQL server during query
 
ERROR 2006 (HY000) at line 4 in file: '1-action.sql': MySQL server has gone away

Comment by Jan Lindström (Inactive) [ 2017-05-31 ]

Can you provide show create table user and preferable use debug build and provide thread apply all bt.

Comment by Juha Pyy [ 2017-07-30 ]

I reproduced the crash by running the docker container.
I also added config wsrep_debug=ON and got this extra bit of information confirming what Marko Mäkelä said above (i.e. variables->auto_increment_increment=0).

2017-07-30  7:39:42 140536165988096 [Note] WSREP: autoinc decrease: 1 -> 0
 
THD: 12, current: 3, autoinc: 3
 
2017-07-30 07:39:42 0x7fd120407700  InnoDB: Assertion failure in file /home/buildbot/buildbot/build/mariadb-10.2.6/storage/innobase/handler/ha_innodb.cc line 2784
 
(.. and all the rest is the same)

From the affected tables, before "1-action.sql" is executed the first time:

MariaDB [test]> show create table user;
 
+-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table | Create Table                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     |
 
+-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| user  | CREATE TABLE `user` (
 
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
 
  `vbuid` varbinary(8) NOT NULL DEFAULT substr(sha(concat(current_timestamp(),rand(),'user')),1,8),
 
  `first_name` varchar(45) NOT NULL,
 
  `last_name` varchar(45) NOT NULL,
 
  `email` varchar(127) NOT NULL,
 
  `password` varbinary(128) DEFAULT NULL,
 
  `token` varbinary(128) DEFAULT NULL,
 
  `token_create_time` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(),
 
  `status` enum('pending_confirmation','confirmed') NOT NULL DEFAULT 'pending_confirmation',
 
  `active` tinyint(1) NOT NULL DEFAULT 1,
 
  `create_by` varchar(32) NOT NULL,
 
  `create_time` timestamp(3) NOT NULL DEFAULT current_timestamp(3),
 
  `update_by` varchar(32) NOT NULL,
 
  `update_time` timestamp(3) NOT NULL DEFAULT current_timestamp(3),
 
  `who_id` int(10) unsigned NOT NULL,
 
  `language_id` int(10) unsigned NOT NULL,
 
  PRIMARY KEY (`id`),
 
  UNIQUE KEY `unique_user_vbuid` (`vbuid`),
 
  UNIQUE KEY `unique_user_email` (`email`),
 
  KEY `fk_user_who_id` (`who_id`),
 
  KEY `fk_user_language_id` (`language_id`),
 
  CONSTRAINT `fk_user_language_id` FOREIGN KEY (`language_id`) REFERENCES `language` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION,
 
  CONSTRAINT `fk_user_who_id` FOREIGN KEY (`who_id`) REFERENCES `user` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION
 
) ENGINE=InnoDB AUTO_INCREMENT=2 DEFAULT CHARSET=latin1 COMMENT='Identifies the application''s users.' |
 
+-------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
1 row in set (0.00 sec)
 
 
 
MariaDB [test]> show create table audit_user;
 
+------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| Table      | Create Table                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                     |
 
+------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
| audit_user | CREATE TABLE `audit_user` (
 
  `id` int(10) unsigned NOT NULL AUTO_INCREMENT,
 
  `user_id` int(10) unsigned NOT NULL,
 
  `vbuid` varbinary(8) NOT NULL DEFAULT substr(sha(concat(current_timestamp(),rand(),'user')),1,8),
 
  `first_name` varchar(45) NOT NULL,
 
  `last_name` varchar(45) NOT NULL,
 
  `email` varchar(127) NOT NULL,
 
  `password` varbinary(128) DEFAULT NULL,
 
  `token` varbinary(128) DEFAULT NULL,
 
  `token_create_time` timestamp NOT NULL DEFAULT current_timestamp() ON UPDATE current_timestamp(),
 
  `status` enum('pending_confirmation','confirmed') NOT NULL DEFAULT 'pending_confirmation',
 
  `active` tinyint(1) NOT NULL DEFAULT 1,
 
  `create_by` varchar(32) NOT NULL,
 
  `create_time` timestamp(3) NOT NULL DEFAULT current_timestamp(3),
 
  `update_by` varchar(32) NOT NULL,
 
  `update_time` timestamp(3) NOT NULL DEFAULT current_timestamp(3),
 
  `who_id` int(10) unsigned NOT NULL,
 
  `language_id` int(10) unsigned NOT NULL,
 
  PRIMARY KEY (`id`),
 
  KEY `fk_audit_user_user_id` (`user_id`),
 
  KEY `fk_audit_user_who_id` (`who_id`),
 
  KEY `fk_audit_user_language_id` (`language_id`),
 
  CONSTRAINT `fk_audit_user_language_id` FOREIGN KEY (`language_id`) REFERENCES `language` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION,
 
  CONSTRAINT `fk_audit_user_user_id` FOREIGN KEY (`user_id`) REFERENCES `user` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION,
 
  CONSTRAINT `fk_audit_user_who_id` FOREIGN KEY (`who_id`) REFERENCES `user` (`id`) ON DELETE NO ACTION ON UPDATE NO ACTION
 
) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=latin1 COMMENT='Identifies the application''s users.' |
 
+------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
 
1 row in set (0.00 sec)

Good news is though, upgrading to 10.2.7+mariadb~jessie within the docker container, the crash did not occur anymore. Not with the original 5 minutes between inserts nor more frequent inserts. So probably some change between 10.2.6 and .7 has fixed the problem.

Comment by Diogo Oliveira de Melo [ 2017-08-22 ]

Indeed. Versions 10.2.7 and 10.2.8 are not being affected by this bug. Should we close the issue?

Generated at Thu Feb 08 08:00:57 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.