[MDEV-23730] s3.replication_partition 'innodb,mix' segv Created: 2020-09-14  Updated: 2020-10-21  Resolved: 2020-10-21

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - S3
Affects Version/s: 10.5
Fix Version/s: 10.5.7

Type: Bug Priority: Critical
Reporter: Daniel Black Assignee: Michael Widenius
Resolution: Fixed Votes: 0
Labels: None
Environment:

minio setup per MDEV-23648

Attachments: File gdb_output.log     Text File s3-server-logs.txt    
Issue Links:
Relates
relates to MDEV-23650 test S3 in buildbot Closed

 Description   

bb-10.5-monty (6844212f01c65a8d78ff218d4f2a731a62e096f8)

 
s3.replication_partition 'innodb,mix'    [ fail ]
 
        Test ended at 2020-09-14 16:55:32
 
 
 
CURRENT_TEST: s3.replication_partition
 
mysqltest: At line 26: query 'ALTER TABLE t1 ADD PARTITION PARTITIONS 6' failed: 2013: Lost connection to MySQL server during query
 
 
 
The result from queries just before the failure was:
 
< snip >
 
use database;
 
connection master;
 
#
 
# Check replication of parititioned S3 tables
 
#
 
CREATE TABLE t1 (
 
c1 INT DEFAULT NULL
 
) ENGINE=Aria
 
PARTITION BY HASH (c1)
 
PARTITIONS 3;
 
INSERT INTO t1 VALUE (1), (2), (101), (102), (201), (202);
 
ALTER TABLE t1 ENGINE=S3;
 
ALTER TABLE t1 ADD PARTITION PARTITIONS 6;
 
 
 
More results from queries before failure can be found in /home/dan/repos/build-mariadb-server-10.5/mysql-test/var/log/replication_partition.log
 
 
 
 
 
Server [mysqld.1 - pid: 1098533, winpid: 1098533, exit: 256] failed during test run
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2020-09-14 16:55:31 0 [Note] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd (mysqld 10.5.6-MariaDB-log) starting as process 1098534 ...
 
2020-09-14 16:55:31 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32190)
 
2020-09-14 16:55:31 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
 
2020-09-14 16:55:31 0 [Warning] Plugin 'S3' is of maturity level gamma while the server is stable
 
2020-09-14 16:55:31 0 [Note] Plugin 'BLACKHOLE' is disabled.
 
2020-09-14 16:55:31 0 [Note] Plugin 'ARCHIVE' is disabled.
 
2020-09-14 16:55:31 0 [Note] Plugin 'FEDERATED' is disabled.
 
2020-09-14 16:55:31 0 [Note] InnoDB: Using Linux native AIO
 
2020-09-14 16:55:31 0 [Note] InnoDB: Uses event mutexes
 
2020-09-14 16:55:31 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2020-09-14 16:55:31 0 [Note] InnoDB: Number of pools: 1
 
2020-09-14 16:55:31 0 [Note] InnoDB: Using SSE4.2 crc32 instructions
 
2020-09-14 16:55:31 0 [Note] mariadbd: O_TMPFILE is not supported on /home/dan/repos/build-mariadb-server-10.5/mysql-test/var/tmp/mysqld.1 (disabling future attempts)
 
2020-09-14 16:55:32 0 [Note] InnoDB: Initializing buffer pool, total size = 8388608, chunk size = 8388608
 
2020-09-14 16:55:32 0 [Note] InnoDB: Completed initialization of buffer pool
 
2020-09-14 16:55:32 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2020-09-14 16:55:32 0 [Note] InnoDB: 128 rollback segments are active.
 
2020-09-14 16:55:32 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2020-09-14 16:55:32 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2020-09-14 16:55:32 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2020-09-14 16:55:32 0 [Note] InnoDB: 10.5.6 started; log sequence number 47235; transaction id 28
 
2020-09-14 16:55:32 0 [Note] InnoDB: Loading buffer pool(s) from /dev/shm/var_auto_Xp9S/mysqld.1/data/ib_buffer_pool
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_CMP' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'THREAD_POOL_WAITS' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'THREAD_POOL_QUEUES' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'FEEDBACK' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'THREAD_POOL_GROUPS' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'user_variables' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'THREAD_POOL_STATS' is disabled.
 
2020-09-14 16:55:32 0 [Note] Plugin 'unix_socket' is disabled.
 
2020-09-14 16:55:32 0 [Note] InnoDB: Buffer pool(s) load completed at 200914 16:55:32
 
2020-09-14 16:55:32 0 [Warning] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: unknown variable 'loose-feedback-debug-startup-interval=20'
 
2020-09-14 16:55:32 0 [Warning] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: unknown variable 'loose-feedback-debug-first-interval=60'
 
2020-09-14 16:55:32 0 [Warning] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: unknown variable 'loose-feedback-debug-interval=60'
 
2020-09-14 16:55:32 0 [Warning] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: unknown option '--loose-pam-debug'
 
2020-09-14 16:55:32 0 [Warning] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: unknown option '--loose-aria'
 
2020-09-14 16:55:32 0 [Warning] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: unknown variable 'loose-debug-sync-timeout=300'
 
2020-09-14 16:55:32 0 [Note] Server socket created on IP: '127.0.0.1'.
 
2020-09-14 16:55:32 0 [Note] Reading of all Master_info entries succeeded
 
2020-09-14 16:55:32 0 [Note] Added new Master_info '' to hash table
 
2020-09-14 16:55:32 0 [Note] /home/dan/repos/build-mariadb-server-10.5/sql/mariadbd: ready for connections.
 
Version: '10.5.6-MariaDB-log'  socket: '/home/dan/repos/build-mariadb-server-10.5/mysql-test/var/tmp/mysqld.1.sock'  port: 16000  MariaDB Server
 
2020-09-14 16:55:32 6 [Note] Deleted Master_info file '/home/dan/repos/build-mariadb-server-10.5/mysql-test/var/mysqld.1/data/master.info'.
 
2020-09-14 16:55:32 6 [Note] Deleted Master_info file '/home/dan/repos/build-mariadb-server-10.5/mysql-test/var/mysqld.1/data/relay-log.info'.
 
2020-09-14 16:55:32 8 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4), using_gtid(0), gtid('')
 
200914 16:55:32 [ERROR] mysqld got signal 11 ;
 
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.5.6-MariaDB-log
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=6
 
max_threads=153
 
thread_count=8
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63636 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x7f35d4000c58
 
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 = 0x7f3620433d58 thread_stack 0x49000
 
/home/dan/repos/build-mariadb-server-10.5/sql/mariadbd(my_print_stacktrace+0x2e)[0x56434674263e]
 
mysys/stacktrace.c:213(my_print_stacktrace)[0x564346160e15]
 
sigaction.c:0(__restore_rt)[0x7f362e3c8a90]
 
maria/ha_maria.cc:2645(ha_maria::extra(ha_extra_function))[0x56434634ab86]
 
sql/ha_partition.cc:9277(ha_partition::loop_extra_alter(ha_extra_function))[0x5643463d6e30]
 
sql/ha_partition.cc:9006(ha_partition::extra(ha_extra_function))[0x5643463d8515]
 
sql/sql_base.cc:1320(wait_while_table_is_used(THD*, TABLE*, ha_extra_function))[0x564345eead09]
 
sql/sql_partition.cc:6861(handle_alter_part_error(st_lock_param_type*, bool, bool, bool))[0x5643462d84cf]
 
sql/sql_partition.cc:7410(fast_alter_partition_table(THD*, TABLE*, Alter_info*, HA_CREATE_INFO*, TABLE_LIST*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*))[0x5643462e16cf]
 
sql/sql_table.cc:10365(mysql_alter_table(THD*, st_mysql_const_lex_string const*, st_mysql_const_lex_string const*, HA_CREATE_INFO*, TABLE_LIST*, Alter_info*, unsigned int, st_order*, bool, bool))[0x564345ffebc1]
 
sql/sql_alter.cc:534(Sql_cmd_alter_table::execute(THD*))[0x564346060a71]
 
sql/sql_parse.cc:5960(mysql_execute_command(THD*))[0x564345f593fc]
 
sql/sql_class.h:2457(THD::enter_stage(PSI_stage_info_v1 const*, char const*, char const*, unsigned int))[0x564345f5a9bf]
 
sql/sql_parse.cc:1870(dispatch_command(enum_server_command, THD*, char*, unsigned int, bool, bool))[0x564345f5d8fc]
 
sql/sql_parse.cc:1348(do_command(THD*))[0x564345f5f1a0]
 
sql/sql_connect.cc:1410(do_handle_one_connection(CONNECT*, bool))[0x56434605bf51]
 
sql/sql_connect.cc:1312(handle_one_connection)[0x56434605c3cd]
 
perfschema/pfs.cc:2204(pfs_spawn_thread)[0x5643463dc402]
 
pthread_create.c:0(start_thread)[0x7f362e3bd432]
 
:0(__GI___clone)[0x7f362daac913]



 Comments   
Comment by Elena Stepanova [ 2020-09-17 ]

Also reproducible with actual AWS / S3.
May be not 100% deterministic.

Comment by Elena Stepanova [ 2020-09-17 ]

There is a strangely similar stack trace in MDEV-23248, only for MyISAM. So, I wonder if it could be a pure partitioning problem not related to S3 or Aria.

Comment by Daniel Black [ 2020-09-18 ]


storage/maria/ha_maria.cc:2625 is corresponding to inline hander::has_long_unique( table->s->long_unique_table

Comment by Elena Stepanova [ 2020-09-20 ]

Raising to critical because the test has been temporarily disabled. When fixed, please remove it from disabled.def

Comment by Michael Widenius [ 2020-10-15 ]

I have now run this in 10.5 with against Amazon storage:
mtr --repeat=100 --enable-disabled s3.replication_partition

I am not able to repeat the problem

Will ask Elena if she can give me access to a core file that I can examine

Comment by Elena Stepanova [ 2020-10-16 ]

Coredump has been provided.

Comment by Michael Widenius [ 2020-10-16 ]

The problem was that mysql_change_partitions() closes all handler files in case of error, which was not properly reflected in
fast_alter_partition_table(). This caused handle_alter_part_error() to try to close already closed tables, which caused the crash.

Comment by Michael Widenius [ 2020-10-20 ]

Found out that this is a bug in libmarias3 when used with MinIO. The 'move()' function, which internally uses that S3 copy function, is not working with MinIO because of missing character conversions in the filename.
I am working with Andrew to get this fixed.

Comment by Michael Widenius [ 2020-10-21 ]

Pushed into 10.5 tree

Generated at Thu Feb 08 09:24:36 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.