Downtime caused by multi-field virtual columns in MySQL 8.0

In this article, I will share a crash bug that was fixed in the MySQL 8.0.35 version, and how this bug was discovered through error logs, corefiles, and gdb.

Introduction

A customer's database (MySQL 8.0.27) randomly crashed. Through the error logs, we can see that it was: An Assertion failure caused by a SELECT query.  

Query

Query (7f20ec0f4a78): SELECT a FROM t WHERE ('session' MEMBER OF (a) )

‍

Assertion failure

2023-12-15T22:57:12.408886Z 8 [ERROR] [MY-013183] [InnoDB] Assertion failure: row0mysql.cc:165:len < 256 * 256 thread 139781058020928

‍

Table Structure

CREATE TABLE `t` (
  `id` int,
  `a` json DEFAULT NULL,
  KEY `a` ((cast(`a` as char(255) array)))
) ENGINE=InnoDB
PARTITION BY HASH(id)
PARTITIONS 1;

Error Log Analysis

Error log

2023-12-15T22:57:12.408886Z 8 [ERROR] [MY-013183] [InnoDB] Assertion failure: row0mysql.cc:165:len < 256 * 256 thread 139781058020928
InnoDB: We intentionally generate a memory trap.
InnoDB: Submit a detailed bug report to http://bugs.mysql.com.
InnoDB: If you get repeated assertion failures or crashes, even
InnoDB: immediately after the mysqld startup, there may be
InnoDB: corruption in the InnoDB tablespace. Please refer to
InnoDB: http://dev.mysql.com/doc/refman/8.0/en/forcing-innodb-recovery.html
InnoDB: about forcing recovery.
22:57:12 UTC - mysqld got signal 6 ;
Most likely, you have hit a bug, but this error can also be caused by malfunctioning hardware.
Thread pointer: 0x7f20ec000ed0
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 = 7f21504f3d00 thread_stack 0x100000
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(my_print_stacktrace(unsigned char const*, unsigned long)+0x2e) [0x1f7f4ae]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(handle_fatal_signal+0x323) [0x1029073]
/lib/x86_64-linux-gnu/libc.so.6(+0x42520) [0x7f2167fee520]
/lib/x86_64-linux-gnu/libc.so.6(pthread_kill+0x12c) [0x7f21680429fc]
/lib/x86_64-linux-gnu/libc.so.6(raise+0x16) [0x7f2167fee476]
/lib/x86_64-linux-gnu/libc.so.6(abort+0xd3) [0x7f2167fd47f3]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld() [0xd7f2bb]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld() [0x21702c8]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(row_sel_field_store_in_mysql_format_func(unsigned char*, mysql_row_templ_t const*, dict_index_t const*, unsigned char const*, unsigned long)+0x1a0) [0x219bf30]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(row_sel_store_mysql_rec(unsigned char*, row_prebuilt_t*, unsigned char const*, dtuple_t const*, bool, dict_index_t const*, dict_index_t const*, unsigned long const*, bool, lob::undo_vers_t*, mem_block_info_t*&)+0x1bc) [0x21a089c]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(row_search_mvcc(unsigned char*, page_cur_mode_t, row_prebuilt_t*, unsigned long, unsigned long)+0x37ed) [0x21a86bd]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(ha_innobase::index_read(unsigned char*, unsigned char const*, unsigned int, ha_rkey_function)+0x331) [0x20609c1]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(ha_innopart::index_read_map_in_part(unsigned int, unsigned char*, unsigned char const*, unsigned long, ha_rkey_function)+0x57) [0x207a7a7]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(Partition_helper::handle_unordered_scan_next_partition(unsigned char*)+0x11b) [0xdfef5b]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(handler::ha_index_read_map(unsigned char*, unsigned char const*, unsigned long, ha_rkey_function)+0x2e1) [0x11310e1]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(RefIterator<false>::Read()+0xc1) [0xea4031]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(FilterIterator::Read()+0x14) [0x13ab924]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(Query_expression::ExecuteIteratorQuery(THD*)+0x3c3) [0xfaed93]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(Query_expression::execute(THD*)+0x2c) [0xfaef7c]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(Sql_cmd_dml::execute(THD*)+0x2c5) [0xf3f855]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(mysql_execute_command(THD*, bool)+0xac8) [0xee1e08]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(dispatch_sql_command(THD*, Parser_state*)+0x403) [0xee68f3]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x2089) [0xee8e49]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(do_command(THD*)+0x174) [0xee9d04]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld() [0x1019fa8]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld() [0x249dcec]
/lib/x86_64-linux-gnu/libc.so.6(+0x94ac3) [0x7f2168040ac3]
/lib/x86_64-linux-gnu/libc.so.6(+0x126a40) [0x7f21680d2a40]
ubuntu
Trying to get some variables.
Some pointers may be invalid and cause the dump to abort.
Query (7f20ec0f4a78): SELECT a FROM t WHERE ('session' MEMBER OF (a) )
Connection ID (thread ID): 8
Status: NOT_KILLED

‍

1. The Assertion failure in the source code

The assertion is at line 165 in the file row0mysql.cc.

2023-12-15T22:57:12.408886Z 8 [ERROR] [MY-013183] [InnoDB] Assertion failure: row0mysql.cc:165:len < 256 * 256 thread 139781058020928

When we open the file ./innobase/row/row0mysql.cc, we can find the corresponding ut_a(len < 256 * 256); in the function row_mysql_store_true_var_len.  

/** Stores a >= 5.0.3 format true VARCHAR length to dest, in the MySQL row
 format.
 @return pointer to the data, we skip the 1 or 2 bytes at the start
 that are used to store the len */
byte *row_mysql_store_true_var_len(
    byte *dest,   /*!< in: where to store */
    ulint len,    /*!< in: length, must fit in two bytes */
    ulint lenlen) /*!< in: storage length of len: either 1 or 2 bytes */
{
  if (lenlen == 2) {
    ut_a(len < 256 * 256);

    mach_write_to_2_little_endian(dest, len);

    return (dest + 2);
  }

  ut_a(lenlen == 1);
  ut_a(len < 256);

  mach_write_to_1(dest, len);

  return (dest + 1);
}

‍

Question: Why does InnoDB determine that this len should be less than 256 * 256?

Through the comments, we can see that this is related to the length of VARCHAR. If you are relatively familiar with MySQL, you should be able to associate it with the maximum length of VARCHAR (of course, I didn't think of it when analyzing the problem. A colleague reminded me that it should be a length issue).  

The length can be specified as a value from 0 to 65,535. The effective maximum length of a VARCHAR is subject to the maximum row size (65,535 bytes, which is shared among all columns) and the character set used.

from https://dev.mysql.com/doc/refman/8.0/en/char.html

The key point is that the range of values is 0 - 65,535, and 256 * 256 is 65,536. Here we can understand why there is this assertion: Because InnoDB needs to confirm that all lengths must be less than 65,536! If not, then InnoDB can only commit suicide, which in turn leads to a crash.

‍

2. The corresponding macro of the assertion, ut_a

When EXPR is not TRUE in the ut_a macro, then it calls ut_dbg_assertion_failed to commit suicide.

/** Abort execution if EXPR does not evaluate to nonzero.
@param EXPR assertion expression that should hold */
#define ut_a(EXPR)                                               \
  do {                                                           \
    if (UNIV_UNLIKELY(!(ulint)(EXPR))) {                         \
      ut_dbg_assertion_failed(#EXPR, __FILE__, (ulint)__LINE__); \
    }                                                            \
  } while (0)

‍

In our case, len < 256 * 256 is FALSE.  

‍

3. Call ut_dbg_assertion_failed

In ut_dbg_assertion_failed, InnoDB will print some crash information (that is what we saw in the error log). At the final stage, it calls abort() to end the process.

/** Report a failed assertion.
@param[in] expr The failed assertion
@param[in] file Source file containing the assertion
@param[in] line Line number of the assertion */
[[noreturn]] void ut_dbg_assertion_failed(const char *expr, const char *file,
                                          ulint line) {
#if !defined(UNIV_HOTBACKUP) && !defined(UNIV_NO_ERR_MSGS)
  ib::error(ER_IB_MSG_1273)
      << "Assertion failure: " << innobase_basename(file) << ":" << line
      << ((expr != nullptr) ? ":" : "") << ((expr != nullptr) ? expr : "")
      << " thread " << to_string(std::this_thread::get_id());

  flush_error_log_messages();

#else  /* !UNIV_HOTBACKUP && !defined(UNIV_NO_ERR_MSGS) */
  auto filename = base_name(file);

  if (filename == nullptr) {
    filename = "null";
  }

  fprintf(stderr,
          "InnoDB: Assertion failure: %s:" ULINTPF
          "%s%s\n"
          "InnoDB: thread %s",
          filename, line, expr != nullptr ? ":" : "",
          expr != nullptr ? expr : "",
          to_string(std::this_thread::get_id()).c_str());
#endif /* !UNIV_HOTBACKUP */

  fputs(
      "InnoDB: We intentionally generate a memory trap.\n"
      "InnoDB: Submit a detailed bug report"
      " to http://bugs.mysql.com.\n"
      "InnoDB: If you get repeated assertion failures"
      " or crashes, even\n"
      "InnoDB: immediately after the mysqld startup, there may be\n"
      "InnoDB: corruption in the InnoDB tablespace. Please refer to\n"
      "InnoDB: " REFMAN
      "forcing-innodb-recovery.html\n"
      "InnoDB: about forcing recovery.\n",
      stderr);

  fflush(stderr);
  fflush(stdout);
  /* Call any registered callback function. */
  if (assert_callback) {
    assert_callback();
  }
  abort();
}

4. Call abort

This is the introduction about abort() seen in the man manual:  

NAME
       abort - cause abnormal process termination

SYNOPSIS
       #include <stdlib.h>

       void abort(void);

DESCRIPTION
       The  abort() function first unblocks the SIGABRT signal, and then raises that signal for the calling process (as though raise(3) was called).  This results
       in the abnormal termination of the process unless the SIGABRT signal is caught and the signal handler does not return (see longjmp(3)).

       If the SIGABRT signal is ignored, or caught by a handler that returns, the abort() function will still terminate the process.  It does  this  by  restoring
       the default disposition for SIGABRT and then raising the signal for a second time.

‍

The corresponding value of the SIGABRT signal is 6.  

shell> kill -l SIGABRT
6

‍

5. Signal 6

This is also why we would see signal 6 in the error log.

22:57:12 UTC - mysqld got signal 6 ;

‍

6. Backtrace

By querying this function name row_mysql_store_true_var_len, we see that it is called in two places.

• row_sel_field_store_in_mysql_format_func
• innobase_col_to_mysql

shell> grep -nr row_mysql_store_true_var_len .
./innobase/row/row0mysql.cc:159:byte *row_mysql_store_true_var_len(
./innobase/row/row0sel.cc:2605:            row_mysql_store_true_var_len(dest, len, templ->mysql_length_bytes);
./innobase/handler/handler0alter.cc:1935:            row_mysql_store_true_var_len(dest, len, flen - field->key_length());
./innobase/include/row0mysql.h:102:byte *row_mysql_store_true_var_len(

We can see row_sel_field_store_in_mysql_format_func in the error log:  

/lib/x86_64-linux-gnu/libc.so.6(abort+0xd3) [0x7f2167fd47f3]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld() [0xd7f2bb]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld() [0x21702c8]
/home/ubuntu/opt/mysql/8.0.27/bin/mysqld(row_sel_field_store_in_mysql_format_func(unsigned char*, mysql_row_templ_t const*, dict_index_t const*, unsigned char const*, unsigned long)+0x1a0) [0x219bf30]

This function calls a relative address (0x21702c8), and the command addr2line can convert this relative address (0x21702c8) to the corresponding function name.

shell> addr2line -fie  ~/opt/mysql/8.0.27/bin/mysqld  0x21702c8
_Z28row_mysql_store_true_var_lenPhmm
??:?

The calling relationship of the functions is:  

row_sel_field_store_in_mysql_format_func
  -> row_mysql_store_true_var_len
    -> ut_ad (ut_dbg_assertion_failed)
      -> abort

Analysis of corefile

Since the information we obtain through the error log is limited (unable to obtain the specific value of len), we suggest the customer to enable corefile.

Here is an additional document about how to enable corefile in MariaDB.

‍

1. GDB analysis of corefile

The customer then sent us the corefile.

shell> gdb -ex "set print pretty on" -ex "set pagination off" -ex "set debuginfod enabled on" -ex "set print thread-events off" -ex "file /home/ubuntu/opt/mysql/8.0.27/bin/mysqld" -ex "core /home/ubuntu/corefiles/core.8027"

Core was generated by `/home/ubuntu/opt/mysql/8.0.27/bin/mysqld --defaults-file=/home/ubuntu/sandbox'.
Program terminated with signal SIGABRT, Aborted.
#0  __pthread_kill_implementation (no_tid=3, signo=6, threadid=140132373239360) at ./nptl/pthread_kill.c:44
44      ./nptl/pthread_kill.c: No such file or directory.
[Current thread is 1 (Thread 0x7f731c541640 (LWP 1534610))]

The customer's MySQL was installed through a binary package, so debuginfo is included in mysqld by default.

‍

2. Specific backtrace

(gdb) bt
#0  __pthread_kill_implementation (no_tid=3, signo=6, threadid=140132373239360) at ./nptl/pthread_kill.c:44
#1  __pthread_kill_esrch (threadid=140132373239360, signo=signo@entry=6) at ./nptl/pthread_kill.c:108
#2  0x0000000001f7e9e7 in my_write_core (sig=sig@entry=6) at ../../mysql-8.0.27/mysys/stacktrace.cc:294
#3  0x000000000102909d in handle_fatal_signal (sig=6) at ../../mysql-8.0.27/sql/signal_handler.cc:171
#4  <signal handler called>
#5  __pthread_kill_implementation (no_tid=0, signo=6, threadid=140132373239360) at ./nptl/pthread_kill.c:44
#6  __pthread_kill_internal (signo=6, threadid=140132373239360) at ./nptl/pthread_kill.c:78
#7  __GI___pthread_kill (threadid=140132373239360, signo=signo@entry=6) at ./nptl/pthread_kill.c:89
#8  0x00007f7347bee476 in __GI_raise (sig=sig@entry=6) at ../sysdeps/posix/raise.c:26
#9  0x00007f7347bd47f3 in __GI_abort () at ./stdlib/abort.c:79
#10 0x0000000000d7f2bb in ut_dbg_assertion_failed (expr=expr@entry=0x279263f "len < 256 * 256", file=file@entry=0x2f55fa0 "../../../mysql-8.0.27/storage/innobase/row/row0mysql.cc", line=line@entry=165) at ../../../mysql-8.0.27/storage/innobase/ut/ut0dbg.cc:99
#11 0x00000000021702c8 in row_mysql_store_true_var_len (dest=<optimised out>, len=len@entry=4294967292, lenlen=<optimised out>) at ../../../mysql-8.0.27/storage/innobase/row/row0mysql.cc:165
#12 0x000000000219bf30 in row_sel_field_store_in_mysql_format_func (dest=<optimised out>, templ=0x7f72c80ecae0, index=<optimised out>, data=0x7f72c8191be8 "\020\034\031\310r\177", len=4294967292) at ../../../mysql-8.0.27/storage/innobase/row/row0sel.cc:2605
#13 0x00000000021a089c in row_sel_store_mysql_rec (mysql_rec=0x7f72c80da818 "\370\001", prebuilt=0x7f72c8194938, rec=0x7f72c817c39f "", vrow=0x7f72c8191b28, rec_clust=true, rec_index=0x7f72c8148878, prebuilt_index=0x7f72c80d93a8, offsets=0x7f731c53d940, clust_templ_for_sec=false, lob_undo=0x7f72c8194b58, blob_heap=@0x7f72c8194a98: 0x7f72c8aa5c30) at ../../../mysql-8.0.27/storage/innobase/row/row0sel.cc:3013
#14 0x00000000021a86bd in row_search_mvcc (buf=buf@entry=0x7f72c80da818 "\370\001", mode=mode@entry=PAGE_CUR_GE, prebuilt=0x7f72c8194938, match_mode=match_mode@entry=1, direction=direction@entry=0) at ../../../mysql-8.0.27/storage/innobase/include/row0mysql.h:875
#15 0x00000000020609c1 in ha_innobase::index_read (this=0x7f72c8189938, buf=0x7f72c80da818 "\370\001", key_ptr=<optimised out>, key_len=<optimised out>, find_flag=<optimised out>) at ../../../mysql-8.0.27/storage/innobase/handler/ha_innodb.cc:10069
#16 0x000000000207a7a7 in handler::index_read_map (find_flag=HA_READ_KEY_EXACT, keypart_map=1, key=0x7f72c816f6c0 "", buf=0x7f72c80da818 "\370\001", this=0x7f72c8189938) at ../../../mysql-8.0.27/sql/handler.h:5078
#17 ha_innopart::index_read_map_in_part (this=0x7f72c8189938, part=0, record=0x7f72c80da818 "\370\001", key=0x7f72c816f6c0 "", keypart_map=1, find_flag=HA_READ_KEY_EXACT) at ../../../mysql-8.0.27/storage/innobase/handler/ha_innopart.cc:1894
#18 0x0000000000dfef5b in Partition_helper::handle_unordered_scan_next_partition (this=0x7f72c818afc8, buf=0x7f72c80da818 "\370\001") at ../../mysql-8.0.27/sql/partitioning/partition_handler.cc:2364
#19 0x00000000011310e1 in handler::ha_index_read_map (this=0x7f72c8189938, buf=0x7f72c80da818 "\370\001", key=0x7f72c816f6c0 "", keypart_map=1, find_flag=find_flag@entry=HA_READ_KEY_EXACT) at ../../mysql-8.0.27/sql/handler.cc:3253
#20 0x0000000000ea4031 in RefIterator<false>::Read (this=0x7f72c8170398) at ../../mysql-8.0.27/sql/row_iterator.h:208
#21 0x00000000013ab924 in FilterIterator::Read (this=0x7f72c81703d8) at ../../mysql-8.0.27/sql/composite_iterators.cc:72
#22 FilterIterator::Read (this=0x7f72c81703d8) at ../../mysql-8.0.27/sql/composite_iterators.cc:70
#23 0x0000000000faed93 in Query_expression::ExecuteIteratorQuery (this=0x7f72c818dd18, thd=0x7f72c8000ed0) at ../../mysql-8.0.27/sql/sql_union.cc:1300
#24 0x0000000000faef7c in Query_expression::execute (this=<optimised out>, thd=0x7f72c8000ed0) at ../../mysql-8.0.27/sql/sql_union.cc:1353
#25 0x0000000000f3f855 in Sql_cmd_dml::execute (this=0x7f72c8190390, thd=0x7f72c8000ed0) at ../../mysql-8.0.27/sql/sql_select.cc:579
#26 0x0000000000ee1e08 in mysql_execute_command (thd=0x7f72c8000ed0, first_level=<optimised out>) at ../../mysql-8.0.27/sql/sql_parse.cc:4505
#27 0x0000000000ee68f3 in dispatch_sql_command (thd=thd@entry=0x7f72c8000ed0, parser_state=parser_state@entry=0x7f731c53ff10) at ../../mysql-8.0.27/sql/sql_parse.cc:5135
#28 0x0000000000ee8e49 in dispatch_command (thd=0x7f72c8000ed0, com_data=<optimised out>, command=COM_QUERY) at ../../mysql-8.0.27/sql/sql_parse.cc:1922
#29 0x0000000000ee9d04 in do_command (thd=thd@entry=0x7f72c8000ed0) at ../../mysql-8.0.27/sql/sql_parse.cc:1343
#30 0x0000000001019fa8 in handle_connection (arg=arg@entry=0x703d4b0) at ../../mysql-8.0.27/sql/conn_handler/connection_handler_per_thread.cc:302
#31 0x000000000249dcec in pfs_spawn_thread (arg=0x71008f0) at ../../../mysql-8.0.27/storage/perfschema/pfs.cc:2946
#32 0x00007f7347c40ac3 in start_thread (arg=<optimised out>) at ./nptl/pthread_create.c:442
#33 0x00007f7347cd2a40 in clone3 () at ../sysdeps/unix/sysv/linux/x86_64/clone3.S:81

We can find row_mysql_store_true_var_len in frame 11:

(gdb) frame 11
#11 0x00000000021702c8 in row_mysql_store_true_var_len (dest=<optimised out>, len=len@entry=4294967292, lenlen=<optimised out>) at ../../../mysql-8.0.27/storage/innoba
se/row/row0mysql.cc:165
165     ../../../mysql-8.0.27/storage/innobase/row/row0mysql.cc: No such file or directory.

‍

3. Correct display of the source code

//Download the source code 
shell> git clone https://github.com/mysql/mysql-server.git
shell> cd mysql-server/
shell> git tag --list | grep 8.0.27
mysql-8.0.27
mysql-cluster-8.0.27
shell> git checkout mysql-8.0.27

We need to switch to MySQL 8.0.27 branch.

// Map directories in gdb 
(gdb) set substitute-path ../../../mysql-8.0.27 /home/ubuntu/mysql-server

‍

4. Analysis of corefile

What is the value of len?

In row_mysql_store_true_var_len, len is 4294967292, which is obviously greater than the limit range of 65,535!

(gdb) frame 11
#11 0x00000000021702c8 in row_mysql_store_true_var_len (dest=<optimised out>, len=len@entry=4294967292, lenlen=<optimised out>) at ../../../mysql-8.0.27/storage/innobase/row/row0mysql.cc:165
165         ut_a(len < 256 * 256);
(gdb) p len
$2 = 4294967292
(gdb) p len  < 256 * 256
$3 = false

‍

Where does len come from?

In frame 13, we see that len comes from dfield->len, but dfield has been optimized away.

(gdb) frame 13
#13 0x00000000021a089c in row_sel_store_mysql_rec (mysql_rec=0x7f72c80da818 "\370\001", prebuilt=0x7f72c8194938, rec=0x7f72c817c39f "", vrow=0x7f72c8191b28, rec_clust=true, rec_index=0x7f72c8148878, prebuilt_index=0x7f72c80d93a8, offsets=0x7f731c53d940, clust_templ_for_sec=false, lob_undo=0x7f72c8194b58, blob_heap=@0x7f72c8194a98: 0x7f72c8aa5c30) at ../../../mysql-8.0.27/storage/innobase/row/row0sel.cc:3013
(gdb) list
3008                (byte)templ->mysql_null_bit_mask;
3009            memcpy(mysql_rec + templ->mysql_col_offset,
3010                   (const byte *)prebuilt->default_rec + templ->mysql_col_offset,
3011                   templ->mysql_col_len);
3012          } else {
3013            row_sel_field_store_in_mysql_format(
3014                mysql_rec + templ->mysql_col_offset, templ, rec_index,
3015                templ->clust_rec_field_no, (const byte *)dfield->data, dfield->len,
3016                ULINT_UNDEFINED);
3017            if (templ->mysql_null_bit_mask) {
(gdb) p dfield
$7 = <optimised out>

‍

Where is dfield again?

Originally in row_sel_store_mysql_rec in frame 13, we found it.

const auto dfield = dtuple_get_nth_v_field(vrow, col->v_pos);

This dfield is calculated through vrow and col->v_pos in dtuple_get_nth_v_field. We can find vrow, but again col has been optimized away.

(gdb) p vrow
$8 = (const dtuple_t *) 0x7f72c8191b28
(gdb) p col
$9 = <optimised out>

‍

How much is col?  

The above col is calculated by dict_table_get_nth_v_col through rec_index->table and templ->clust_rec_field_no.

Let's take a look at the specific content in dict_table_get_nth_v_col:  

/** Gets the nth virtual column of a table.
@param[in] table table
@param[in] pos position of virtual column
@return pointer to virtual column object */
static inline dict_v_col_t *dict_table_get_nth_v_col(const dict_table_t *table,
                                                     ulint pos) {
  ut_ad(table);
  ut_ad(pos < table->n_v_def);
  ut_ad(table->magic_n == DICT_TABLE_MAGIC_N);

  return (static_cast<dict_v_col_t *>(table->v_cols) + pos);
}
#endif /* UNIV_DEBUG */

‍

The col value can be calculated as:  

(gdb) p rec_index->table->v_cols + 0
$17 = (dict_v_col_t *) 0x7f72c8148140

‍

Calculate dfield

With col, we can calculate dfield:

      const auto dfield = dtuple_get_nth_v_field(vrow, col->v_pos);

‍

The definition of dtuple_get_nth_v_field:

/** Gets nth virtual field of a tuple.
@param[in] tuple tuple
@oaran[in] n the nth field to get
@return nth field */
static inline dfield_t *dtuple_get_nth_v_field(const dtuple_t *tuple, ulint n) {
  ut_ad(tuple);
  ut_ad(n < tuple->n_v_fields);

  return (static_cast<dfield_t *>(tuple->v_fields + n));
}
#endif /* UNIV_DEBUG */

‍

The value of dfield is 0x7f72c8191bd0.

(gdb) p vrow->v_fields + (rec_index->table->v_cols + 0)->v_pos
$18 = (dfield_t *) 0x7f72c8191bd0
(gdb) p *(vrow->v_fields + (rec_index->table->v_cols + 0)->v_pos)
$19 = {
  data = 0x7f72c8191be8,
  ext = 0,
  spatial_status = 0,
  len = 4294967292,
  type = {
    prtype = 20279311,
    mtype = 12,
    len = 1020,
    mbminmaxlen = 21
  }
}

5. who set the len to 4294967292

The most important part is to analyze why len is 4294967292.

By searching for dtuple_get_nth_v_field, we see the related files as follows:

shell> grep -nr  'dfield = dtuple_get_nth_v_field' .
./row/row0mysql.cc:578:      dfield = dtuple_get_nth_v_field(row, n_v_col);
./row/row0row.cc:117:      dfield = dtuple_get_nth_v_field(entry, i - entry_len);
./row/row0sel.cc:2988:      const auto dfield = dtuple_get_nth_v_field(vrow, col->v_pos);
./row/row0sel.cc:4242:      dfield_t *dfield = dtuple_get_nth_v_field(*vrow, vcol->v_pos);
./row/row0upd.cc:917:      dfield = dtuple_get_nth_v_field(entry, i);
./row/row0upd.cc:1224:  dfield_t *dfield = dtuple_get_nth_v_field(row, vcol->v_pos);
./row/row0upd.cc:1270:    dfield = dtuple_get_nth_v_field(row, col_no);
./row/row0upd.cc:1324:          dfield = dtuple_get_nth_v_field(row, vcol->v_pos);
./row/row0upd.cc:1508:      dfield = dtuple_get_nth_v_field(row, vcol->v_pos);
./row/row0upd.cc:1856:      dfield_t *dfield = dtuple_get_nth_v_field(node->row, col_no);
./include/data0data.ic:457:    dfield_t *dfield = dtuple_get_nth_v_field(vrow, i);
./include/data0data.ic:470:    dfield_t *dfield = dtuple_get_nth_v_field(vrow, i);
./dict/dict0dict.cc:2892:    dfield_t *dfield = dtuple_get_nth_v_field(tuple, i);
./trx/trx0rec.cc:2001:        dfield = dtuple_get_nth_v_field(*row, vcol->v_pos);
./trx/trx0rec.cc:2729:    dfield = dtuple_get_nth_v_field(row, col_no);

‍

By analyzing all the calls to dtuple_get_nth_v_field, we can finally see a function trx_undo_rec_get_partial_row at line 2001 in the file trx/trx0rec.cc.

if (is_virtual) {
  ptr = trx_undo_read_v_idx(index->table, ptr, first_v_col, &is_undo_log,
                            &field_no);
  first_v_col = false;
  if (field_no != ULINT_UNDEFINED) {
    vcol = dict_table_get_nth_v_col(index->table, field_no);
    col = &vcol->m_col;
    col_no = dict_col_get_no(col);
    dfield = dtuple_get_nth_v_field(*row, vcol->v_pos);
    vcol->m_col.copy_type(dfield_get_type(dfield));
  }
}

if ((vcol != nullptr && vcol->m_col.is_multi_value()) ||
    trx_undo_rec_is_multi_value(ptr)) {
  ut_ad(is_virtual);
  ut_ad(vcol != nullptr || field_no == ULINT_UNDEFINED);
  ut_ad(dfield != nullptr || field_no == ULINT_UNDEFINED);
  ptr = trx_undo_rec_get_multi_value(ptr, dfield, heap);
  continue;
} else {
  ptr = trx_undo_rec_get_col_val(ptr, &field, &len, &orig_len);
}

trx_undo_rec_get_multi_value calls Multi_value_logger::read to modify dfield.

/** Read from an undo log record of a multi-value virtual column.
@param[in] ptr pointer to remaining part of the undo record
@param[in,out] field stored field, nullptr if the col is no longer
                        indexed or existing, in the latter case,
                        this function will only skip the log
@param[in,out] heap memory heap
@return remaining part of undo log record after reading these values */
const byte *trx_undo_rec_get_multi_value(const byte *ptr, dfield_t *field,
                                         mem_heap_t *heap) {
  if (field == nullptr) {
    return (ptr + Multi_value_logger::read_log_len(ptr));
  }

  return (Multi_value_logger::read(ptr, field, heap));
}

‍

The Multi_value_logger::read method finally modifies defield->len to UNIV_MULTI_VALUE_ARRAY_MARKER.

const byte *Multi_value_logger::read(const byte *ptr, dfield_t *field,
                                     mem_heap_t *heap) {
  ut_ad(is_multi_value_log(ptr));

  ++ptr;

  uint32_t total_len = mach_read_from_2(ptr);
  const byte *old_ptr = ptr;

  ptr += s_log_length_for_null_or_empty;

  if (total_len == s_multi_value_null) {
    dfield_set_null(field);
    return (ptr);
  } else if (total_len == s_multi_value_no_index_value) {
    dfield_set_data(field, nullptr, UNIV_NO_INDEX_VALUE);
    return (ptr);
  }

  uint32_t num = mach_read_next_compressed(&ptr);
  field->data = mem_heap_alloc(heap, sizeof(multi_value_data));
  field->len = UNIV_MULTI_VALUE_ARRAY_MARKER;

  multi_value_data *multi_val = static_cast<multi_value_data *>(field->data);

  multi_val->num_v = num;
  multi_val->alloc(num, false, heap);

  for (uint32_t i = 0; i < num; ++i) {
    uint32_t len = mach_read_next_compressed(&ptr);
    multi_val->datap[i] = ptr;
    multi_val->data_len[i] = len;

    ptr += len;
  }

  if (ptr < old_ptr + total_len) {
    multi_val->alloc_bitset(heap);
    multi_val->bitset->copy(ptr, UT_BITS_IN_BYTES(num));
    ptr += UT_BITS_IN_BYTES(num);
  }

  ut_ad(ptr == old_ptr + total_len);
  return (ptr);
}

We can see that UNIV_MULTI_VALUE_ARRAY_MARKER is 4294967292.

/** The follwoing number as the length marker of a logical field, which
is only used for multi-value field data, means the data itself of the
field is actually an array. */
const uint32_t UNIV_MULTI_VALUE_ARRAY_MARKER = UNIV_NO_INDEX_VALUE - 1;

‍

(gdb) p UNIV_MULTI_VALUE_ARRAY_MARKER
$23 = 4294967292

‍

Fault reproduction

So far, we have clarified why this len is 4294967292. Next, we are going to reproduce the failure caused by this bug.

The function trx_undo_rec_get_multi_value builds a multi-field virtual column Multi-Value Virtual Column from the Undo Log record.

We need to find a way to make MySQL read data from the Undo Log.

1. Create the table structure and insert data.

CREATE TABLE `t` (
  `id` int,
  `a` json DEFAULT NULL,
  KEY `a` ((cast(`a` as char(255) array)))
) ENGINE=InnoDB
PARTITION BY HASH(id)
PARTITIONS 1;
insert into t (id, a) values 
( 1, 
  JSON_ARRAY("session","1")
);

‍

2. Keep a REPEATABLE-READ transaction in session 1.

--- session 1 ---
set transaction_isolation = 'REPEATABLE-READ';
begin;
select count(*) from t;

‍

3. Update the data in session 2.

update t set a = JSON_ARRAY('session', '2') where id = 1;

‍

4. Back to session 1 to query the data. Then InnoDB must use Undo to ensure the consistency of the transaction.

SELECT a FROM t WHERE ('session' MEMBER OF (a) ); 
ERROR 2013 (HY000): Lost connection to MySQL server during query
No connection. Trying to reconnect...
ERROR 2002 (HY000): Can't connect to local MySQL server through socket '/tmp/mysql_sandbox8028.sock' (111)
ERROR:
Can't connect to the server

‍

Successfully reproduced!!!

Bug feedback

This issue was reported to the Oracle official in July 2023. The Oracle official replied that they have fixed this issue.

Fixed in the upcoming 8.0.35, 8.2.0 under the heading of Bug#35039937 Multi-value virtual columns should not be materialized

In October 2023, MySQL 8.0.35 fixed this bug.

‍