[MDEV-26959] The RQG reporter CrashRecovery generates invalid SQL from exotic key names. Created: 2021-11-02  Updated: 2021-11-02  Resolved: 2021-11-02

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: N/A
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Matthias Leich Assignee: Matthias Leich
Resolution: Fixed Votes: 0
Labels: rr-profile

Attachments: File Y_mini.yy    

 Description   

This is not a server bug!
 
Work flow:
1. Start the server
2. Generate some initial data
3. One session runs a DDL/DML mix
4. During 3. is ongoing SIGKILL the server process
5. Restart attempt with success
6. Run checks on the data and one of them fails unexpected with syntax error
    around the key name `idx2``idx2` or similar.
7. RQG aborts with STATUS_RECOVERY_FAILURE because of 6.
 
SHOW CREATE TABLE t5;
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                                                                                                                                                                                                                               |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| t5    | CREATE TABLE `t5` (
  `col1` int(11) NOT NULL,
  `col2` int(11) DEFAULT NULL,
  `col_int` int(11) DEFAULT NULL,
  `col_string` int(11) DEFAULT NULL,
  `col_varchar` varchar(500) DEFAULT NULL,
  `col_text` text DEFAULT NULL,
  PRIMARY KEY (`col1`),
  KEY `idx2``idx2` (`col_text`(9))     <==== This looks as if it cannot be right.
) ENGINE=InnoDB DEFAULT CHARSET=latin1 ROW_FORMAT=COMPACT `ENCRYPTED`=YES `ENCRYPTION_KEY_ID`=1
 
origin/10.6 83dbf2c99525f4e9bfc313609194c3e4f23292a4 2021-10-27T13:47:58+03:00
 
RQG
====
git clone https://github.com/mleich1/rqg --branch experimental RQG
 
GIT_SHOW: HEAD -> experimental 5d964598d1a7eb7957b1afa9b5950ef927803070 2021-10-29T15:21:01+02:00
rqg.pl  : Version 4.0.2 (2021-10)
 
$RQG_HOME/rqg1.pl \
--duration=30 \
--queries=10000000 \
--no_mask \
--seed=random \
--rpl_mode=none \
--gendata=conf/mariadb/table_stress.zz \
--engine=InnoDB \
--mysqld=--innodb_page_size=32K \
--mysqld=--log_bin_trust_function_creators=1 \
--mysqld=--loose-idle_write_transaction_timeout=0 \
--mysqld=--innodb_stats_persistent=off \
--mysqld=--log-output=none \
--mysqld=--loose_innodb_use_native_aio=0 \
--mysqld=--loose_innodb_lock_schedule_algorithm=fcfs \
--mysqld=--slave_net_timeout=60 \
--mysqld=--innodb_adaptive_hash_index=on \
--mysqld=--net_write_timeout=60 
--mysqld=--file-key-management-filename=$RQG_HOME/conf/mariadb/encryption_keys.txt \
--mysqld=--loose-table_lock_wait_timeout=50 \
--mysqld=--sync-binlog=1 \
--mysqld=--innodb-lock-wait-timeout=50 \
--mysqld=--loose-idle_transaction_timeout=0 \
--mysqld=--plugin-load-add=file_key_management.so \
--mysqld=--innodb-buffer-pool-size=24M \ 
--mysqld=--log-bin \
--mysqld=--loose-innodb-sync-debug \
--mysqld=--loose-innodb_fatal_semaphore_wait_threshold=600 \ 
--mysqld=--loose-idle_readonly_transaction_timeout=0 \
--mysqld=--net_read_timeout=30 \
--mysqld=--connect_timeout=60 \
--mysqld=--wait_timeout=28800 \
--mysqld=--loose-debug_assert_on_not_freed_memory=0 \
--mysqld=--loose-max-statement-time=30 \
--mysqld=--lock-wait-timeout=86400 \
--mysqld=--interactive_timeout=28800 \
--reporters=Backtrace,CrashRecovery1,Deadlock1,ErrorLog \
--validators=None \
--grammar=Y_mini.yy \
--threads=1 \
<certain local settings>



 Comments   
Comment by Matthias Leich [ 2021-11-02 ]

Please adjust the component if necessary. Its quite possible that InnoDB is not guilty.

Comment by Matthias Leich [ 2021-11-02 ]

origin/bb-10.6-release 3dc0d884ecec0149e35493b3450f610d8ff5d742 2021-11-02T15:24:20+02:00
claims to be a 10.6.5
 
pluto:/data/Results/1635863454/MDEV-26959/dev/shm/vardir/1635863454/6/1/rr
_RR_TRACE_DIR="." rr replay --mark-stdio mysqld-1   # Fate till SIGKILL
_RR_TRACE_DIR="." rr replay --mark-stdio # Fate from restart till SIGUSR1 because of detection of defect
The defect is in the table    test.t5 
What happened in the RQG reporter "CrashRecovery1" ?
The reporter runs
-    SHOW KEYS FROM t5 and gets aside of other data the keyname    `idx2`idx2` 
- generates from that and other data a
   SELECT * FROM test.t5 FORCE INDEX (idx2idx2`)  WHERE col_text IS NULL OR col_text IS NOT NULL
- harvests  1064: You have an error in your SQL syntax
   and decides to abort the test because of that.
 
A copy of the datadir was made before the restart and is located in
        pluto:/data/Results/1635863454/MDEV-26959/dev/shm/vardir/1635863454/6/1/data_copy/

Comment by Marko Mäkelä [ 2021-11-02 ]

Here is some information from a trace. From the t5.frm file, we are really reading the string idx2`idx2.

ssh pluto
rr replay /data/Results/1635863454/MDEV-26959/dev/shm/vardir/1635863454/6/1/rr/latest-trace

bb-10.6-release 3dc0d884ecec0149e35493b3450f610d8ff5d742

Thread 26 hit Hardware watchpoint 3: -location strpos[9]@8
 
Old value = "\276\276\276\276\276\276\276\276"
New value = "idx2`idx"
0x0000000070000002 in ?? ()
(rr) bt
#0  0x0000000070000002 in ?? ()
#1  0x0000164e70fd3766 in _raw_syscall () at /home/roc/rr/rr/src/preload/raw_syscall.S:120
#2  0x0000164e70fcf04e in traced_raw_syscall (call=<optimized out>) at /home/roc/rr/rr/src/preload/syscallbuf.c:272
#3  0x0000164e70fd2efd in sys_read (call=0x7f7b90633fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:2170
#4  syscall_hook_internal (call=0x7f7b90633fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:3223
#5  syscall_hook (call=0x7f7b90633fa0) at /home/roc/rr/rr/src/preload/syscallbuf.c:3329
#6  0x0000164e70fcee50 in _syscall_hook_trampoline () at /home/roc/rr/rr/src/preload/syscall_hook.S:313
#7  0x0000164e70fceeaf in __morestack () at /home/roc/rr/rr/src/preload/syscall_hook.S:458
#8  0x0000164e70fceeca in _syscall_hook_trampoline_48_3d_00_f0_ff_ff () at /home/roc/rr/rr/src/preload/syscall_hook.S:469
#9  0x000037de4d027372 in __libc_read (nbytes=2054, buf=0x61d000242cd8, fd=58) at ../sysdeps/unix/sysv/linux/read.c:26
#10 __libc_read (fd=58, buf=0x61d000242cd8, nbytes=2054) at ../sysdeps/unix/sysv/linux/read.c:24
#11 0x00001a960669f230 in ?? () from /lib/x86_64-linux-gnu/libasan.so.5
#12 0x000055e0cb57c910 in my_read (Filedes=58, Buffer=0x61d000242cd8 "", Count=2054, MyFlags=16) at /data/Server/bb-10.6-releaseA/mysys/my_read.c:51
#13 0x000055e0c9e21e7d in inline_mysql_file_read (file=58, buffer=0x61d000242cd8 "", count=2054, flags=16) at /data/Server/bb-10.6-releaseA/include/mysql/psi/mysql_file.h:1146
#14 0x000055e0c9e25b15 in open_table_def (thd=0x62b0000af218, share=0x61b0000413b8, flags=11) at /data/Server/bb-10.6-releaseA/sql/table.cc:716
#15 0x000055e0ca13037e in tdc_acquire_share (thd=0x62b0000af218, tl=0x629000122238, flags=3, out_table=0x2f50030de1f0) at /data/Server/bb-10.6-releaseA/sql/table_cache.cc:831
#16 0x000055e0c99a06b1 in open_table (thd=0x62b0000af218, table_list=0x629000122238, ot_ctx=0x2f50030de7a0) at /data/Server/bb-10.6-releaseA/sql/sql_base.cc:1854

Before the server was killed, we had:

rr replay /data/Results/1635863454/MDEV-26959/dev/shm/vardir/1635863454/6/1/rr/mysqld-1

bb-10.6-release 3dc0d884ecec0149e35493b3450f610d8ff5d742

#0  ha_innobase::check_if_supported_inplace_alter (this=0x61d00077f6b8, altered_table=0x400d174c5250, ha_alter_info=0x400d174c4b50)
    at /data/Server/bb-10.6-releaseA/storage/innobase/handler/handler0alter.cc:2001
#1  0x000055e97bccb6e5 in mysql_alter_table (thd=0x62b00010a218, new_db=0x62b00010ec18, new_name=0x62b00010f030, create_info=0x400d174c75d0, table_list=0x62b0001113e0, alter_info=0x400d174c74a0, order_num=0, 
    order=0x0, ignore=false, if_exists=false) at /data/Server/bb-10.6-releaseA/sql/sql_table.cc:10159
#2  0x000055e97be58b95 in Sql_cmd_alter_table::execute (this=0x62b000111c30, thd=0x62b00010a218) at /data/Server/bb-10.6-releaseA/sql/sql_alter.cc:550
#3  0x000055e97ba5db0a in mysql_execute_command (thd=0x62b00010a218, is_called_from_prepared_stmt=false) at /data/Server/bb-10.6-releaseA/sql/sql_parse.cc:5997
#4  0x000055e97ba69fca in mysql_parse (thd=0x62b00010a218, rawbuf=0x62b000111238 "ALTER TABLE t5 ADD INDEX `idx2``idx2` ( col_text(9) ), LOCK = DEFAULT /* E_R Thread1 QNO 12 CON_ID 17 */", length=104, 
    parser_state=0x400d174c8b20) at /data/Server/bb-10.6-releaseA/sql/sql_parse.cc:8030
#5  0x000055e97ba42247 in dispatch_command (command=COM_QUERY, thd=0x62b00010a218, 
    packet=0x629000c1c219 "ALTER TABLE t5 ADD INDEX `idx2``idx2` ( col_text(9) ), LOCK = DEFAULT /* E_R Thread1 QNO 12 CON_ID 17 */ ", packet_length=105, blocking=true)

So, that name was actually requested by SQL.

Note: SQL specifies Pascal-style quoting at least for string literals. The non-standard quote character (backtick) behaves like that: the actual index name will be idx2`idx2. The name is properly quoted in the SHOW KEYS output again. I see no bug in the server yet.

Comment by Matthias Leich [ 2021-11-02 ]

Sorry for that.
The full size grammar leads to the generation of non exotic key names like 'idx1'.
And the RQG reporter CrashRecovery has no problems when parsing such non exotic names.
But the automatic RQG test simplifier works per default quite aggressive and can cause that
- quite frequent and usually harmless:  invalid SQL
- rather rare and in the current case dangerous:  quite exotic names
gets generated.
And in case of the latter the RQG reporter CrashRecovery fails later to generate valid SQL
from such an exotic key name.
So I have to fix the RQG reporter CrashRecovery and several other parts of RQG
using copies of that code.

Comment by Matthias Leich [ 2021-11-02 ]

Some key (I guess also table, column, trigger ....) name could contain a backtick like ->idx1`idx1<-.  (The arrows mark start and end)
A nice RQG grammar would not cause the generation of such names.
But my automatic RQG test simplifier could shrink the grammar in a way that such names get generated.
And than RQG needs to generate some SQL like
SELECT .... FORCE INDEX (`idx1``idx1`) ....
where the backtick is protected by some additional backtick
in order to avoid wrong syntax.

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