[MDEV-12724] Multiple tests fail with timeout on mac-1012-bintar Created: 2017-05-07  Updated: 2023-04-27

Status: Open
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.2, 10.3, 10.4
Fix Version/s: 10.4

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Sergei Golubchik
Resolution: Unresolved Votes: 0
Labels: None


 Description   

Various tests fail with timeouts on mac-1012-bintar on 10.2-based branches. The builder is rather new, but it is still suspicious, since it isn't happening on previous versions.

https://buildbot.askmonty.org/buildbot/builders/mac-1012-bintar/builds/1380/steps/test/logs/stdio
All 6 tests failed with timeouts

    binlog_encryption.rpl_skip_replication
    rpl.rpl_loaddata_m
    rpl.rpl_insert_id
    rpl.rpl_dual_pos_advance
    rpl.rpl_circular_for_4_hosts
    perfschema.rpl_statements

https://buildbot.askmonty.org/buildbot/builders/mac-1012-bintar/builds/1378/steps/test/logs/stdio

    rpl.rpl_special_charset
    rpl.rpl_timezone
    rpl.rpl_connection
    rpl.sec_behind_master-5114
    rpl.create_select
    rpl.rpl_gtid_master_promote
    rpl.rpl_gtid_stop_start

etc.



 Comments   
Comment by Daniel Black [ 2017-05-08 ]

binlog_encryption.rpl_skip_replication - disabled - https://travis-ci.org/MariaDB/server/jobs/229524091#L5886
rpl.rpl_loaddata_m - pass: https://travis-ci.org/MariaDB/server/jobs/229524089#L5930
rpl.rpl_dual_pos_advance - fail https://travis-ci.org/MariaDB/server/jobs/229524089#L6997

rpl.rpl_timezone 'mix' - pass https://travis-ci.org/MariaDB/server/jobs/229524089#L6956
rpl.rpl_timezone 'row' - fail https://travis-ci.org/MariaDB/server/jobs/229524089#L6956
rpl.rpl_connection 'mix' - pass https://travis-ci.org/MariaDB/server/jobs/229524089#L6997
rpl.sec_behind_master-5114 - disabled - https://travis-ci.org/MariaDB/server/jobs/229524089#L5871

I'm also suspicious of the number of OSX test failures.

Comment by Alice Sherepa [ 2020-09-04 ]

A lot of failing tests on mac-1012-bintar, all the time
e.g. on 10.3: http://buildbot.askmonty.org/buildbot/builders/mac-1012-bintar/builds/7824/steps/test/logs/stdio

rpl.rpl_gtid_mdev4473 'innodb,mix'       [ fail ]  timeout after 900 seconds
binlog_encryption.rpl_gtid_basic 'cmpr,innodb,row' [ fail ]  timeout after 900 seconds
rpl.rpl_create_database 'row' [ fail ]  At line 119: Timeout in include/wait_for_slave_param.inc
rpl.rpl_checksum_cache 'innodb,mix'     [ fail ]  timeout after 900 seconds
rpl.rpl_row_basic_11bugs 'innodb,row'    [ fail ]  timeout after 900 seconds
rpl.rpl_row_basic_8partition 'row'       [ fail ]  timeout after 900 seconds
rpl.rpl_stm_maria 'stmt'                 [ fail ]  timeout after 900 seconds

rpl.rpl_skip_replication 'innodb,mix'    [ fail ]
        Test ended at 2020-09-04 04:44:39
 
CURRENT_TEST: rpl.rpl_skip_replication
mysqltest: In included file "./include/rpl_connect.inc": 
included from ./include/master-slave.inc at line 46:
included from /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/suite/rpl/include/rpl_skip_replication.inc at line 21:
included from /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/suite/rpl/t/rpl_skip_replication.test at line 2:
At line 55: query 'connect  $rpl_connection_name,127.0.0.1,root,,test,$_rpl_port,' failed: 2013: Lost connection to MySQL server at 'reading authorization packet', system error: 60
 
The result from queries just before the failure was:
include/master-slave.inc

rpl.rpl_init_slave 'row'                 [ fail ]
        Test ended at 2020-09-04 05:59:45
 
CURRENT_TEST: rpl.rpl_init_slave
 
 
Server [mysqld.1 - pid: 42251, winpid: 42251, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2020-09-04  5:59:44 25 [Note] Deleted Master_info file '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/mysqld.1/data/master.info'.
2020-09-04  5:59:44 25 [Note] Deleted Master_info file '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/mysqld.1/data/relay-log.info'.
2020-09-04  5:59:44 27 [Note] Start binlog_dump to slave_server(2), pos(master-bin.000001, 4), using_gtid(0), gtid('')
200904  5:59:44 [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.3.25-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=7
max_threads=153
thread_count=9
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63200 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7fa2cf078008
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 = 0x700001f23f20 thread_stack 0x49000
Fatal signal 4 while backtracing
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
include/master-slave.inc
[connection master]
set global max_connections=151;
connection slave;
include/stop_slave.inc
include/start_slave.inc

rpl.rpl_circular_for_4_hosts 'innodb,stmt' [ fail ]
        Test ended at 2020-09-04 06:37:02
 
CURRENT_TEST: rpl.rpl_circular_for_4_hosts
 
worker[1] > Restart  - using different config file
worker[1] > Restart  - using different config file
worker[1] > Restart  - using different config file
worker[1] > Restart  - using different config file
 
Server [mysqld.2 - pid: 49595, winpid: 49595, exit: 256] failed during test run
Server log from this test:
----------SERVER LOG START-----------
2020-09-04  6:36:59 0 [Note] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld (mysqld 10.3.25-MariaDB-log) starting as process 49596 ...
2020-09-04  6:36:59 0 [Warning] Could not increase number of max_open_files to more than 1024 (request: 32186)
2020-09-04  6:36:59 0 [Warning] Changed limits: max_open_files: 1024  max_connections: 151 (was 151)  table_cache: 421 (was 2000)
2020-09-04  6:36:59 0 [Warning] Setting lower_case_table_names=2 because file system for /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/mysqld.2/data/ is case insensitive
2020-09-04  6:36:59 0 [Note] Plugin 'partition' is disabled.
2020-09-04  6:36:59 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2020-09-04  6:36:59 0 [Note] InnoDB: Uses event mutexes
2020-09-04  6:36:59 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
2020-09-04  6:36:59 0 [Note] InnoDB: Number of pools: 1
2020-09-04  6:36:59 0 [Note] InnoDB: Using SSE2 crc32 instructions
2020-09-04  6:36:59 0 [Note] InnoDB: Initializing buffer pool, total size = 8M, instances = 1, chunk size = 8M
2020-09-04  6:36:59 0 [Note] InnoDB: Completed initialization of buffer pool
2020-09-04  6:36:59 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
2020-09-04  6:36:59 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2020-09-04  6:36:59 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2020-09-04  6:36:59 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2020-09-04  6:36:59 0 [Note] InnoDB: 10.3.25 started; log sequence number 1636044; transaction id 34
2020-09-04  6:36:59 0 [Note] InnoDB: Loading buffer pool(s) from /Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/mysqld.2/data/ib_buffer_pool
2020-09-04  6:36:59 0 [Note] Plugin 'SEQUENCE' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_MUTEXES' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_CMP' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
2020-09-04  6:36:59 0 [Note] InnoDB: Buffer pool(s) load completed at 200904  6:36:59
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'FEEDBACK' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'user_variables' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
2020-09-04  6:36:59 0 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
2020-09-04  6:36:59 0 [Warning] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
2020-09-04  6:36:59 0 [Warning] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
2020-09-04  6:36:59 0 [Warning] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld: unknown variable 'loose-feedback-debug-interval=60'
2020-09-04  6:36:59 0 [Warning] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld: unknown option '--loose-pam-debug'
2020-09-04  6:36:59 0 [Warning] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld: unknown variable 'loose-debug-sync-timeout=300'
2020-09-04  6:36:59 0 [Note] Server socket created on IP: '127.0.0.1'.
2020-09-04  6:36:59 0 [Note] Reading of all Master_info entries succeeded
2020-09-04  6:36:59 0 [Note] Added new Master_info '' to hash table
2020-09-04  6:36:59 0 [Note] /Users/buildbot/maria-slave/mac-1012-bintar/build/sql/mysqld: ready for connections.
Version: '10.3.25-MariaDB-log'  socket: '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/tmp/mysqld.2.sock'  port: 16001  MariaDB Server
2020-09-04  6:37:01 10 [Note] Deleted Master_info file '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/mysqld.2/data/master.info'.
2020-09-04  6:37:01 10 [Note] Deleted Master_info file '/Users/buildbot/maria-slave/mac-1012-bintar/build/mysql-test/var/mysqld.2/data/relay-log.info'.
2020-09-04  6:37:01 10 [Note] Master connection name: ''  Master_info_file: 'master.info'  Relay_info_file: 'relay-log.info'
2020-09-04  6:37:01 10 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16000', master_log_file='master-bin.000001', master_log_pos='4'.
2020-09-04  6:37:01 12 [Note] Start binlog_dump to slave_server(3), pos(slave-bin.000001, 4), using_gtid(0), gtid('')
2020-09-04  6:37:01 13 [Note] Slave I/O thread: Start asynchronous replication to master 'root@127.0.0.1:16000' in log 'master-bin.000001' at position 4
2020-09-04  6:37:01 14 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './slave-relay-bin.000001' position: 4
2020-09-04  6:37:01 13 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16000',replication started in log 'master-bin.000001' at position 4
200904  6:37:01 [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.3.25-MariaDB-log
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=4
max_threads=153
thread_count=13
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63200 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x7f9c318c5c08
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 = 0x700002536f20 thread_stack 0x49000
Fatal signal 4 while backtracing
----------SERVER LOG END-------------
mysqltest failed but provided no output
The result from queries just before the failure was:
< snip >
Master B	a	b
Master B	5	A
Master B	6	B
Master B	8	D
connection server_3;
SELECT 'Master C',a,b FROM t1 WHERE c = 2 ORDER BY a,b;
Master C	a	b
Master C	6	C
connection server_4;
SELECT 'Master D',a,b FROM t1 WHERE c = 2 ORDER BY a,b;
Master D	a	b
Master D	8	D
 
* Reconfigure replication to schema A->B->D->A *
connection server_3;
include/stop_slave_io.inc
connection server_4;
include/stop_slave.inc
include/rpl_change_topology.inc [new topology=1->2->4->1,2->3]
include/start_slave.inc

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