[MDEV-16561] rpl.rpl_non_direct_row_mixing_engines failed in buildbot with timeout in master_pos_wait - Jira

Details

Type: Bug
Status: Closed (View Workflow)
Priority: Major
Resolution: Cannot Reproduce
Affects Version/s: 10.1(EOL)
Fix Version/s: N/A
Component/s: Replication, Tests
Labels:
None

Description

http://buildbot.askmonty.org/buildbot/builders/kvm-fulltest-big/builds/1833/steps/mtr_nm/logs/stdio

rpl.rpl_non_direct_row_mixing_engines 'row,xtradb' w2 [ fail ]

        Test ended at 2018-05-27 02:17:15

CURRENT_TEST: rpl.rpl_non_direct_row_mixing_engines

=== SHOW MASTER STATUS ===

---- 1. ----

File	slave-bin.000001

Position	153157

Binlog_Do_DB

Binlog_Ignore_DB

==========================

=== SHOW SLAVE STATUS ===

---- 1. ----

Slave_IO_State	Waiting for master to send event

Master_Host	127.0.0.1

Master_User	root

Master_Port	16020

Connect_Retry	1

Master_Log_File	master-bin.000001

Read_Master_Log_Pos	186436

Relay_Log_File	slave-relay-bin.000002

Relay_Log_Pos	154086

Relay_Master_Log_File	master-bin.000001

Slave_IO_Running	Yes

Slave_SQL_Running	Yes

Replicate_Do_DB

Replicate_Ignore_DB

Replicate_Do_Table

Replicate_Ignore_Table

Replicate_Wild_Do_Table

Replicate_Wild_Ignore_Table

Last_Errno	0

Last_Error

Skip_Counter	0

Exec_Master_Log_Pos	153797

Relay_Log_Space	187023

Until_Condition	None

Until_Log_File

Until_Log_Pos	0

Master_SSL_Allowed	No

Master_SSL_CA_File

Master_SSL_CA_Path

Master_SSL_Cert

Master_SSL_Cipher

Master_SSL_Key

Seconds_Behind_Master	402

Master_SSL_Verify_Server_Cert	No

Last_IO_Errno	0

Last_IO_Error

Last_SQL_Errno	0

Last_SQL_Error

Replicate_Ignore_Server_Ids

Master_Server_Id	1

Master_SSL_Crl

Master_SSL_Crlpath

Using_Gtid	No

Gtid_IO_Pos

Replicate_Do_Domain_Ids

Replicate_Ignore_Domain_Ids

Parallel_Mode	conservative

=========================

=== SHOW PROCESSLIST ===

---- 1. ----

Id	4

User	root

Host	localhost:45332

db	test

Command	Sleep

Time	1095

State

Info

Progress	0.000

---- 2. ----

Id	5

User	root

Host	localhost:45334

db	test

Command	Sleep

Time	1095

State

Info

Progress	0.000

---- 3. ----

Id	6

User	system user

Host

db

Command	Connect

Time	1095

State	Waiting for master to send event

Info

Progress	0.000

---- 4. ----

Id	7

User	system user

Host

db	test

Command	Connect

Time	401

State	Unlocking tables

Info	DROP TABLE IF EXISTS `tt_xx_7`,`nt_xx_7` /* generated by server */

Progress	0.000

---- 5. ----

Id	8

User	root

Host	localhost:45346

db	test

Command	Query

Time	0

State	init

Info	SHOW PROCESSLIST

Progress	0.000

---- 6. ----

Id	9

User	root

Host	localhost:45348

db	test

Command	Sleep

Time	1095

State

Info

Progress	0.000

========================

analyze: sync_with_master

mysqltest: In included file "./extra/rpl_tests/rpl_mixing_engines.test":

included from /mnt/buildbot/build/mariadb-10.1.34/mysql-test/suite/rpl/t/rpl_non_direct_row_mixing_engines.test at line 15:

At line 1803: sync_slave_with_master failed: 'select master_pos_wait('master-bin.000001', 186436, 300, '')' returned -1 indicating timeout after 300 seconds

The result from queries just before the failure was:

< snip >

-e-e-e-e-e-e-e-e-e-e-e- >> set-NT << -e-e-e-e-e-e-e-e-e-e-e-

-b-b-b-b-b-b-b-b-b-b-b- >> R << -b-b-b-b-b-b-b-b-b-b-b-

ROLLBACK;

Warnings:

Warning	#	Some non-transactional changed tables couldn't be rolled back

include/show_binlog_events.inc

-e-e-e-e-e-e-e-e-e-e-e- >> R << -e-e-e-e-e-e-e-e-e-e-e-

-b-b-b-b-b-b-b-b-b-b-b- >> B set-T set-NT R << -b-b-b-b-b-b-b-b-b-b-b-

include/show_binlog_events.inc

Log_name	Pos	Event_type	Server_id	End_log_pos	Info

master-bin.000001	#	Gtid	#	#	BEGIN GTID #-#-#

master-bin.000001	#	Table_map	#	#	table_id: # (test.nt_3)

master-bin.000001	#	Table_map	#	#	table_id: # (test.nt_3)

master-bin.000001	#	Write_rows_v1	#	#	table_id: # flags: STMT_END_F

master-bin.000001	#	Query	#	#	COMMIT

-e-e-e-e-e-e-e-e-e-e-e- >> B set-T set-NT R << -e-e-e-e-e-e-e-e-e-e-e-

###################################################################################

#                               CHECK CONSISTENCY

###################################################################################

More results from queries before failure can be found in /mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/log/rpl_non_direct_row_mixing_engines.log

 == /mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/tmp/analyze-sync_with_master-mysqld.1.err ==

############################## default ##############################

**** SHOW WARNINGS on default ****

SHOW WARNINGS;

Level	Code	Message

**** SELECT replication-related variables on default ****

SELECT NOW(), @@SERVER_ID;

NOW()	@@SERVER_ID

2018-05-27 02:17:14	1

**** SHOW SLAVE STATUS on default ****

SHOW SLAVE STATUS;

**** SHOW MASTER STATUS on default ****

SHOW MASTER STATUS;

File	master-bin.000001

Position	186436

Binlog_Do_DB

Binlog_Ignore_DB

**** SHOW SLAVE HOSTS on default ****

SHOW SLAVE HOSTS;

Server_id	2

Host	127.0.0.1

Port	16021

Master_id	1

**** SHOW PROCESSLIST on default ****

SHOW PROCESSLIST;

Id	User	Host	db	Command	Time	State	Info	Progress

7	root	localhost:40082	NULL	Binlog Dump	1100	Master has sent all binlog to slave; waiting for binlog to be updated	NULL	0.000

1739	root	localhost	NULL	Query	0	init	SHOW PROCESSLIST	0.000

**** SHOW BINARY LOGS on default ****

SHOW BINARY LOGS;

Log_name	File_size

master-bin.000001	186436

**** SHOW BINLOG EVENTS on default ****

binlog_name = 'master-bin.000001'

SHOW BINLOG EVENTS IN 'master-bin.000001';

Log_name	Pos	Event_type	Server_id	End_log_pos	Info

master-bin.000001	4	Format_desc	1	249	Server ver: 10.1.34-MariaDB, Binlog ver: 4

master-bin.000001	249	Gtid_list	1	274	[]

master-bin.000001	274	Binlog_checkpoint	1	314	master-bin.000001

master-bin.000001	314	Gtid	1	352	BEGIN GTID 0-1-1

master-bin.000001	352	Table_map	1	409	table_id: 30 (mtr.test_suppressions)

master-bin.000001	409	Write_rows_v1	1	537	table_id: 30 flags: STMT_END_F

master-bin.000001	537	Query	1	605	COMMIT

<...>

master-bin.000001	186311	Write_rows_v1	1	186367	table_id: 33 flags: STMT_END_F

master-bin.000001	186367	Query	1	186436	COMMIT

**** SHOW RELAYLOG EVENTS on default ****

relaylog_name = 'No such row'

SHOW RELAYLOG EVENTS IN 'No such row';

Log_name	Pos	Event_type	Server_id	End_log_pos	Info

 == /mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/tmp/analyze-sync_with_master-mysqld.2.err ==

############################## default ##############################

**** SHOW WARNINGS on default ****

SHOW WARNINGS;

Level	Code	Message

**** SELECT replication-related variables on default ****

SELECT NOW(), @@SERVER_ID;

NOW()	@@SERVER_ID

2018-05-27 02:17:14	2

**** SHOW SLAVE STATUS on default ****

SHOW SLAVE STATUS;

Slave_IO_State	Waiting for master to send event

Master_Host	127.0.0.1

Master_User	root

Master_Port	16020

Connect_Retry	1

Master_Log_File	master-bin.000001

Read_Master_Log_Pos	186436

Relay_Log_File	slave-relay-bin.000002

Relay_Log_Pos	154086

Relay_Master_Log_File	master-bin.000001

Slave_IO_Running	Yes

Slave_SQL_Running	Yes

Replicate_Do_DB

Replicate_Ignore_DB

Replicate_Do_Table

Replicate_Ignore_Table

Replicate_Wild_Do_Table

Replicate_Wild_Ignore_Table

Last_Errno	0

Last_Error

Skip_Counter	0

Exec_Master_Log_Pos	153797

Relay_Log_Space	187023

Until_Condition	None

Until_Log_File

Until_Log_Pos	0

Master_SSL_Allowed	No

Master_SSL_CA_File

Master_SSL_CA_Path

Master_SSL_Cert

Master_SSL_Cipher

Master_SSL_Key

Seconds_Behind_Master	406

Master_SSL_Verify_Server_Cert	No

Last_IO_Errno	0

Last_IO_Error

Last_SQL_Errno	0

Last_SQL_Error

Replicate_Ignore_Server_Ids

Master_Server_Id	1

Master_SSL_Crl

Master_SSL_Crlpath

Using_Gtid	No

Gtid_IO_Pos

Replicate_Do_Domain_Ids

Replicate_Ignore_Domain_Ids

Parallel_Mode	conservative

**** SHOW MASTER STATUS on default ****

SHOW MASTER STATUS;

File	slave-bin.000001

Position	153157

Binlog_Do_DB

Binlog_Ignore_DB

**** SHOW SLAVE HOSTS on default ****

SHOW SLAVE HOSTS;

**** SHOW PROCESSLIST on default ****

SHOW PROCESSLIST;

Id	User	Host	db	Command	Time	State	Info	Progress

6	system user		NULL	Connect	1100	Waiting for master to send event	NULL	0.000

7	system user		test	Connect	406	Unlocking tables	DROP TABLE IF EXISTS `tt_xx_7`,`nt_xx_7` /* generated by server */	0.000

10	root	localhost	NULL	Query	0	init	SHOW PROCESSLIST	0.000

**** SHOW BINARY LOGS on default ****

SHOW BINARY LOGS;

Log_name	File_size

slave-bin.000001	153157

<...>

 - saving '/mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/2/log/rpl.rpl_non_direct_row_mixing_engines-row,xtradb/' to '/mnt/buildbot/build/mariadb-10.1.34/mysql-test/var/log/rpl.rpl_non_direct_row_mixing_engines-row,xtradb/'

worker[2] > Restart  - not started

worker[2] > Restart  - not started

***Warnings generated in error logs during shutdown after running tests: rpl.rpl_non_direct_row_mixing_engines

InnoDB: Error: Waited for 5 secs for hash index ref_count (1) to drop to 0.

InnoDB: Error: Waited for 10 secs for hash index ref_count (1) to drop to 0.

<...>

InnoDB: Error: Waited for 235 secs for hash index ref_count (1) to drop to 0.

InnoDB: Warning: semaphore wait:

InnoDB: Error: Waited for 240 secs for hash index ref_count (1) to drop to 0.

<...>

InnoDB: Error: Waited for 395 secs for hash index ref_count (1) to drop to 0.

Attachments

Activity

People

Assignee:: Unassigned

Reporter:: Elena Stepanova

Votes:: 0 Vote for this issue

Watchers:: 4 Start watching this issue

Dates

Created:: 2018-06-25 07:28

Updated:: 2023-07-31 00:58

Resolved:: 2023-07-31 00:58

Git Integration

Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.

MariaDB Server

Details

Description

Attachments

Activity

People

Dates

Git Integration