[MDEV-32921] binlog_encryption.rpl_typeconv assertion on aarch64 macos Created: 2023-12-01  Updated: 2023-12-12

Status: Open
Project: MariaDB Server
Component/s: Replication
Affects Version/s: 10.11.6
Fix Version/s: 10.4, 10.5, 10.6, 10.11, 11.0

Type: Bug Priority: Major
Reporter: Daniel Black Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None

Issue Links:
Duplicate
duplicates MDEV-14362 binlog_encryption.rpl_typeconv failed... Closed

 Description   

test failure:

binlog_encryption.rpl_typeconv 'row'     w5 [ fail ]  timeout after 900 seconds
        Test ended at 2023-11-30 12:24:42
Test case timeout after 900 seconds
== /Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/log/rpl_typeconv.log == 
ALL_NON_LOSSY
SET GLOBAL SLAVE_TYPE_CONVERSIONS='ALL_LOSSY';
SELECT @@global.slave_type_conversions;
@@global.slave_type_conversions
ALL_LOSSY
SET GLOBAL SLAVE_TYPE_CONVERSIONS='ALL_LOSSY,ALL_NON_LOSSY';
SELECT @@global.slave_type_conversions;
@@global.slave_type_conversions
ALL_LOSSY,ALL_NON_LOSSY
SET GLOBAL SLAVE_TYPE_CONVERSIONS='ALL_LOSSY,ALL_NON_LOSSY,NONEXISTING_BIT';
ERROR 42000: Variable 'slave_type_conversions' can't be set to the value of 'NONEXISTING_BIT'
SELECT @@global.slave_type_conversions;
@@global.slave_type_conversions
ALL_LOSSY,ALL_NON_LOSSY
connection slave;
SET GLOBAL SLAVE_TYPE_CONVERSIONS='';
**** Running tests with @@SLAVE_TYPE_CONVERSIONS = '' ****
#
# MDEV-15821 Row format replication from LONGBLOB COMPRESSED to LONGBLOB does not work
#
 == /Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/tmp/analyze-timeout-mysqld.1.err ==
mysqltest: Could not open connection 'default': 2013 Lost connection to server at 'handshake: reading initial communication packet', system error: 60
 == /Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/tmp/analyze-timeout-mysqld.2.err ==
mysqltest: Could not open connection 'default': 2013 Lost connection to server at 'handshake: reading initial communication packet', system error: 60
 - found 'core.23917', moving it to '/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/log/binlog_encryption.rpl_typeconv-row'
 - found 'core.24200', moving it to '/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/log/binlog_encryption.rpl_typeconv-row'
 - found 'core.23917' (0/1)
Trying 'dbx' to get a backtrace
Trying 'lldb' to get a backtrace from coredump /Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/log/binlog_encryption.rpl_typeconv-row/core.23917
worker[18] Trying to dump core for [mysqltest - pid: 26724, winpid: 26724]
worker[18] Trying to dump core for [mysqld.1 - pid: 26650, winpid: 26650, exit: 0]
worker[46] Trying to dump core for [mysqltest - pid: 26728, winpid: 26728]
worker[46] Trying to dump core for [mysqld.1 - pid: 26665, winpid: 26665, exit: 0]
worker[38] Trying to dump core for [mysqltest - pid: 26734, winpid: 26734]
worker[38] Trying to dump core for [mysqld.1 - pid: 26671, winpid: 26671, exit: 0]
worker[34] Trying to dump core for [mysqltest - pid: 26822, winpid: 26822]
worker[34] Trying to dump core for [mysqld.1 - pid: 26736, winpid: 26736, exit: 0]
worker[47] Trying to dump core for [mysqltest - pid: 26871, winpid: 26871]
worker[47] Trying to dump core for [mysqld.1 - pid: 26767, winpid: 26767, exit: 0]
worker[32] > Restart  - not started
worker[60] > Restart [mysqld.1 - pid: 27766, winpid: 27766] - using different config file
worker[60] > Restart [mysqld.2 - pid: 28125, winpid: 28125] - using different config file
worker[35] > Restart [mysqld.1 - pid: 27927, winpid: 27927] - using different config file
worker[35] > Restart [mysqld.2 - pid: 28243, winpid: 28243] - using different config file
Output from lldb follows. The first stack trace is from the failing thread.
The following stack traces are from all threads (so the failing one is
duplicated).
--------------------------
(lldb) target create --core "/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/log/binlog_encryption.rpl_typeconv-row/core.23917"
Core file '/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/log/binlog_encryption.rpl_typeconv-row/core.23917' (x86_64) was loaded.
(lldb) command source -s 0 '/var/folders/sk/1rps9wzs79zdj9f2wz8m0yf00000gn/T/HDwcOU7dpX'
Executing commands in '/var/folders/sk/1rps9wzs79zdj9f2wz8m0yf00000gn/T/HDwcOU7dpX'.
(lldb) bt
* thread #1
  * frame #0: 0x0000000000000000
(lldb) thread backtrace all
* thread #1
  * frame #0: 0x0000000000000000
  thread #2
    frame #0: 0x0000000000000000

server error log https://ci.mariadb.org/41154/logs/aarch64-macos/mysqld.1.err.5

2023-11-30 12:06:32 0 [Note] /Users/ec2-user/buildbot/aarch64-macos/build/sql/mariadbd: ready for connections.
Version: '10.11.7-MariaDB-debug-log'  socket: '/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/tmp/5/mysqld.1.sock'  port: 16040  Source distribution
2023-11-30 12:06:40 6 [Note] Deleted Master_info file '/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/mysqld.1/data/master.info'.
2023-11-30 12:06:40 6 [Note] Deleted Master_info file '/Users/ec2-user/buildbot/aarch64-macos/build/mysql-test/var/5/mysqld.1/data/relay-log.info'.
2023-11-30 12:06:40 7 [Note] Start binlog_dump to slave_server(2), pos(, 4), using_gtid(1), gtid('')
2023-11-30 12:21:44 9 [Warning] Aborted connection 9 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
231130 12:21:44 2023-11-30 12:21:44 8 [Warning] Aborted connection 8 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
[ERROR] mysqld got signal 6 ;
2023-11-30 12:21:44 5 [Warning] Aborted connection 5 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
Sorry, we probably made a mistake, and this is a bug.
 
Your assistance in bug reporting will enable us to fix this for the next release.
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
2023-11-30 12:21:44 6 [Warning] Aborted connection 6 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
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.11.7-MariaDB-debug-log source revision: 6d0bcfc4b9c9205504b67b191ddfb2766ba25bdc
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=5
max_threads=153
thread_count=5
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63847 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
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 = 0x0 thread_stack 0x49000
Printing to addr2line failed
0   mariadbd                            0x0000000103d4fd0b my_print_stacktrace + 75
0   mariadbd                            0x0000000102edbbfa handle_fatal_signal + 810
0   libsystem_platform.dylib            0x00007ff80d80a5ed _sigtramp + 29
0   ???                                 0x00007fdb90807170 0x0 + 140580998902128
0   mariadbd                            0x00000001030e10d4 _Z11mysqld_mainiPPc + 3140
0   mariadbd                            0x0000000102df8b12 main + 34
0   dyld                                0x00007ff80d48341f start + 1903
The manual page at https://mariadb.com/kb/en/how-to-produce-a-full-stack-trace-for-mariadbd/ contains
information that should help you find out what is causing the crash.
Core pattern: /cores/core.%P

https://ci.mariadb.org/41154/logs/aarch64-macos/mysqld.2.err.5

2023-11-30 12:21:24 126 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./slave-relay-bin.000002', relay_log_pos='101850', master_log_name='master-bin.000001', master_log_pos='101590', GTID '0-1-404';  and new position at relay_log_file='./slave-relay-bin.000002', relay_log_pos='102205', master_log_name='master-bin.000001', master_log_pos='101945', GTID '0-1-405';  
2023-11-30 12:21:35 126 [ERROR] Slave SQL: Column 1 of table 'test.t1' cannot be converted from type 'mediumblob compressed' to type 'varbinary(65500)', Gtid 0-1-408, Internal MariaDB error code: 1677
2023-11-30 12:21:35 126 [ERROR] Error running query, slave SQL thread aborted. Fix the problem, and restart the slave SQL thread with "SLAVE START". We stopped at log 'master-bin.000001' position 102317; GTID position '0-1-407'
2023-11-30 12:21:35 126 [Note] Slave SQL thread exiting, replication stopped in log 'master-bin.000001' at position 102317; GTID position '0-1-407', master: 127.0.0.1:16040
2023-11-30 12:21:36 127 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 102317, relay log './slave-relay-bin.000002' position: 102577; GTID position '0-1-407'
2023-11-30 12:21:37 127 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./slave-relay-bin.000002', relay_log_pos='102577', master_log_name='master-bin.000001', master_log_pos='102317', GTID '0-1-407';  and new position at relay_log_file='./slave-relay-bin.000002', relay_log_pos='102932', master_log_name='master-bin.000001', master_log_pos='102672', GTID '0-1-408';  
2023-11-30 12:21:44 8 [Warning] Aborted connection 8 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
2023-11-30 12:21:44 9 [Warning] Aborted connection 9 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
2023-11-30 12:21:44 5 [Warning] Aborted connection 5 to db: 'test' user: 'root' host: 'localhost' (Got an error reading communication packets)
231130 12:22:04 [ERROR] mysqld got signal 6 ;
Sorry, we probably made a mistake, and this is a bug.
 
Your assistance in bug reporting will enable us to fix this for the next release.
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.11.7-MariaDB-debug-log source revision: 6d0bcfc4b9c9205504b67b191ddfb2766ba25bdc
key_buffer_size=1048576
read_buffer_size=131072
max_used_connections=3
max_threads=153
thread_count=5
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 63847 K  bytes of memory
Hope that's ok; if not, decrease some variables in the equation.
 
Thread pointer: 0x0
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 = 0x0 thread_stack 0x49000
Printing to addr2line failed
0   mariadbd                            0x000000010f334d0b my_print_stacktrace + 75
0   mariadbd                            0x000000010e4c0bfa handle_fatal_signal + 810
0   libsystem_platform.dylib            0x00007ff80d80a5ed _sigtramp + 29
0   ???                                 0x00007fa090809c50 0x0 + 140327595842640
0   mariadbd                            0x000000010e6c60d4 _Z11mysqld_mainiPPc + 3140
0   mariadbd                            0x000000010e3ddb12 main + 34
0   dyld                                0x00007ff80d48341f start + 1903

var.tar.gz doesn't have core files in it.


Generated at Thu Feb 08 10:35:02 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.