MySQL Bugs: #115480: Test innodb.log_first_rec

Bug #115480	Test innodb.log_first_rec_group failing
Submitted:	2 Jul 2024 4:26	Modified:	27 Oct 16:00
Reporter:	Laurynas Biveinis (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: InnoDB storage engine	Severity:	S3 (Non-critical)
Version:	8.0.44	OS:	MacOS (14.5)
Assigned to:		CPU Architecture:	ARM

Description:
[ 50%] innodb.log_first_rec_group                [ fail ]
        Test ended at 2024-07-02 07:24:48

CURRENT_TEST: innodb.log_first_rec_group
2024-07-02T04:24:43.105997Z 0 [Note] [MY-013667] [Server] Error-log destination "stderr" is not a file. Can not restore error log messages from previous run.
2024-07-02T04:24:43.102536Z 0 [Warning] [MY-013711] [Server] Manifest file '/Users/laurynas/vilniusdb/mysql-8.0.38/_build-debug/runtime_output_directory/mysqld.my' is not read-only. For better security, please make sure that the file is read-only.
2024-07-02T04:24:43.103543Z 0 [Warning] [MY-010099] [Server] Insecure configuration for --secure-file-priv: Data directory is accessible through --secure-file-priv. Consider choosing a different directory.
2024-07-02T04:24:43.103554Z 0 [Warning] [MY-010101] [Server] Insecure configuration for --secure-file-priv: Location is accessible to all OS users. Consider choosing a different directory.
2024-07-02T04:24:43.103601Z 0 [Note] [MY-010949] [Server] Basedir set to /Users/laurynas/vilniusdb/mysql-8.0.38/_build-debug/.
2024-07-02T04:24:43.103609Z 0 [System] [MY-010116] [Server] /Users/laurynas/vilniusdb/mysql-8.0.38/_build-debug/runtime_output_directory/mysqld (mysqld 8.0.38-debug) starting as process 33273
2024-07-02T04:24:43.105340Z 0 [Warning] [MY-010159] [Server] Setting lower_case_table_names=2 because file system for /Users/laurynas/vilniusdb/mysql-8.0.38/_build-debug/mysql-test/var/mysqld.1/data/ is case insensitive
2024-07-02T04:24:43.109559Z 0 [Note] [MY-010747] [Server] Plugin 'FEDERATED' is disabled.
2024-07-02T04:24:43.112531Z 1 [System] [MY-013576] [InnoDB] InnoDB initialization has started.
2024-07-02T04:24:43.112559Z 1 [Note] [MY-013546] [InnoDB] Atomic write enabled
2024-07-02T04:24:43.112642Z 1 [Note] [MY-012937] [InnoDB] !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
2024-07-02T04:24:43.112661Z 1 [Note] [MY-012944] [InnoDB] Uses event mutexes
2024-07-02T04:24:43.112678Z 1 [Note] [MY-012945] [InnoDB] GCC builtin __atomic_thread_fence() is used for memory barrier
2024-07-02T04:24:43.112707Z 1 [Note] [MY-012948] [InnoDB] Compressed tables use zlib 1.2.13
2024-07-02T04:24:43.115104Z 1 [Note] [MY-012951] [InnoDB] Using hardware accelerated crc32 and polynomial multiplication.
2024-07-02T04:24:43.115577Z 1 [Note] [MY-012203] [InnoDB] Directories to scan './'
2024-07-02T04:24:43.115621Z 1 [Note] [MY-012204] [InnoDB] Scanning './'
2024-07-02T04:24:43.117290Z 1 [Note] [MY-012208] [InnoDB] Completed space ID check of 9 files.
2024-07-02T04:24:43.117757Z 1 [Note] [MY-012955] [InnoDB] Initializing buffer pool, total size = 24.000000M, instances = 1, chunk size =24.000000M 
2024-07-02T04:24:43.120246Z 1 [Note] [MY-012957] [InnoDB] Completed initialization of buffer pool
2024-07-02T04:24:43.123838Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2024-07-02T04:24:43.124007Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2024-07-02T04:24:43.128551Z 1 [Note] [MY-013566] [InnoDB] Double write buffer files: 2
2024-07-02T04:24:43.128583Z 1 [Note] [MY-013565] [InnoDB] Double write buffer pages per instance: 4
2024-07-02T04:24:43.128634Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_0.dblwr' for doublewrite
2024-07-02T04:24:43.128677Z 1 [Note] [MY-013532] [InnoDB] Using './#ib_16384_1.dblwr' for doublewrite
2024-07-02T04:24:43.192849Z 1 [Note] [MY-013883] [InnoDB] The latest found checkpoint is at lsn = 20588203 in redo log file ./#innodb_redo/#ib_redo63.
2024-07-02T04:24:43.192968Z 1 [Note] [MY-013086] [InnoDB] Starting to parse redo log at lsn = 20588044, whereas checkpoint_lsn = 20588203 and start_lsn = 20588032
2024-07-02T04:24:43.192985Z 1 [Note] [MY-012547] [InnoDB] Log scan progressed past the checkpoint LSN 20588044.
2024-07-02T04:24:43.193000Z 1 [Note] [MY-012551] [InnoDB] Database was not shutdown normally!
2024-07-02T04:24:43.193034Z 1 [Note] [MY-012552] [InnoDB] Starting crash recovery.
2024-07-02T04:24:43.276453Z 1 [Note] [MY-012550] [InnoDB] Doing recovery: scanned up to log sequence number 20588280
2024-07-02T04:24:43.278345Z 1 [Note] [MY-013083] [InnoDB] Log background threads are being started...
2024-07-02T04:24:43.278717Z 1 [Note] [MY-012532] [InnoDB] Applying a batch of 2 redo log records ...
2024-07-02T04:24:43.279577Z 1 [Note] [MY-012533] [InnoDB] 100%
2024-07-02T04:24:43.785880Z 1 [Note] [MY-012535] [InnoDB] Apply batch completed!
SIGKILL myself
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future version.
WARNING: MYSQL_OPT_RECONNECT is deprecated and will be removed in a future version.
mysqltest: At line 96: Test assertion failed in assert.inc

The result from queries just before the failure was:

**** slave_master_info on default ****
SELECT * FROM mysql.slave_master_info;
Number_of_lines	Master_log_name	Master_log_pos	Host	User_name	User_password	Port	Connect_retry	Enabled_ssl	Ssl_ca	Ssl_capath	Ssl_cert	Ssl_cipher	Ssl_key	Ssl_verify_server_cert	Heartbeat	Bind	Ignored_server_ids	Uuid	Retry_count	Ssl_crl	Ssl_crlpath	Enabled_auto_position	Channel_name	Tls_version	Public_key_path	Get_public_key	Network_namespace	Master_compression_algorithm	Master_zstd_compression_level	Tls_ciphersuites	Source_connection_auto_failover	Gtid_only

**** mysql.gtid_executed on default ****
SELECT * FROM mysql.gtid_executed;
source_uuid	interval_start	interval_end

rpl_topology=
extra debug info if any: ''
connection default;
1 tests executed in this mtr thread: innodb.log_first_rec_group
last error log entry: SERVER_1:<none>
rpl error summary: no errors in workers, receivers, or coordinators
connection default;
Assertion text: 'All must happen within the single log block (this was required for the bug)'
Assertion condition: '[SELECT 20670476 DIV 512] = [SELECT (20671327 + 50) DIV 512]'
Assertion condition, interpolated: '40372 = 40373'
Assertion result: '0'
safe_process[33244]: Child process: 33245, exit: 1

How to repeat:
Server built with -DCMAKE_EXPORT_COMPILE_COMMANDS=ON -DCMAKE_BUILD_TYPE=Debug -DWITH_DEBUG=ON -DMYSQL_MAINTAINER_MODE=ON -DWITH_SYSTEM_LIBS=ON -DWITH_NDBCLUSTER_STORAGE_ENGINE=OFF -DFORCE_COLORED_OUTPUT=ON -DDOWNLOAD_BOOST=ON -DWITH_BOOST=~/vilniusdb/mysql-boost/

Hello Laurynas,

Thank you for the report and feedback!

regards,
Umesh

Hello Laurynas,
Thank you for your report.
The amount of 850 bytes in redo generated during the test is surprisingly high.
Is there anything unusual in your testing environment and the MTR script command line that you've not shared? We can see a failure when non-standard amount of undo tablespaces is created before the test, for example with --init-file. But standard runs on standard environment on multiple systems work fine.
Does it fail always when executed multiple times (e.g. with `--repeat=1000`), and if not, how frequently it fails?
At the start of the test around line 16 there is:
let $debug_test = 0;
Could you try to set it to `1`, repeat it to fail and share the results (they may be available in full in some MTR log file after the failure, as the MTR shares only some last lines of the output in console message).
Thanks!

The most unusual thing about my environment is macOS (on ARM). The test does not fail under Linux virtualized under macOS on that same ARM. I haven't tried x86_64 either OS yet.

--repeat is not necessary, the test fails reliably on the first invocation.

The MTR invocation is the simplest possible: ./mtr innodb.log_first_rec_group

debug_test=1 output:

#
# Scenario 1. Test recovery when recovery starts and ends in the same block as checkpoint_lsn.
#
Pass: 0
# Initialization - create table, resets autoincrement value.
# 0. Move to the next log block.
include/assert.inc [We failed to create log records that would end at boundary between blocks]
State: created trx ending at blocks boundary
Start LSN: 20588017
End LSN: 20588556
# 1. Execute tiny mini-transaction in the current block [only pass 0]
State: after writing first mtr to the block
LSN: 20588663
# 2. Create checkpoint at the current lsn and block further checkpoints
State: after checkpoint write
LSN: 20588715
Checkpoint LSN: 20588715
# 3. Execute transaction to force non-trivial crash recovery: 103.
State: after writing 103
LSN: 20588792
include/assert.inc [All must happen within the single log block (this was required for the bug)]
# 5. Crash when trying to insert B.
# 6. Recover 103, write new redo record X during recovery and crash just before flushing page with 103
# 7. Start recovery and ensure all is recovered - we must recover 103.
#    If first_rec_group was pointing to X we would skip 103.
#    The auto increment value should also be stored properly (with
#    value of 5 in first pass, 4 in second).
SELECT * FROM t;
a       b
100     1
101     2
102     3
103     4
SELECT AUTO_INCREMENT FROM INFORMATION_SCHEMA.TABLES WHERE TABLE_NAME = 't';
AUTO_INCREMENT
5
State: after recovery
LSN: 20588792
Pass: 1
# Initialization - create table, resets autoincrement value.
# 0. Move to the next log block.
include/assert.inc [We failed to create log records that would end at boundary between blocks]
State: created trx ending at blocks boundary
Start LSN: 20655363
End LSN: 20655628
# 1. Execute tiny mini-transaction in the current block [only pass 0]
# 2. Create checkpoint at the current lsn and block further checkpoints
State: after checkpoint write
LSN: 20655680
Checkpoint LSN: 20655680
# 3. Execute transaction to force non-trivial crash recovery: 103.
State: after writing 103
LSN: 20656479
include/assert.inc [All must happen within the single log block (this was required for the bug)]
######## Test assertion failed: All must happen within the single log block (this was required for the bug) ########
...

Same on 8.0.40

Same on 8.0.41

Same on 8.0.42

Same on 8.0.44