tests failing with mariadb10.5: Mysql2::Statement #1152

pvalena · 2021-01-07T03:41:17Z

Failures:

  1) Mysql2::Error encoding returns error messages as UTF-8 by default
     Failure/Error: expect(bad_err.message).to include("??}\u001F")
       expected "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1" to include "??}\u001F"
     # ./spec/mysql2/error_spec.rb:59:in `block (4 levels) in <top (required)>'
     # ./spec/spec_helper.rb:17:in `with_internal_encoding'
     # ./spec/mysql2/error_spec.rb:52:in `block (3 levels) in <top (required)>'

  2) Mysql2::Statement should create a statement
     Failure/Error: expect { statement = @client.prepare 'SELECT 1' }.to change(&method(:stmt_count)).by(1)
       expected result to have changed by 1, but was changed by 0
     # ./spec/mysql2/statement_spec.rb:18:in `block (2 levels) in <top (required)>'

  3) Mysql2::Statement close should free server resources
     Failure/Error: expect { stmt.close }.to change(&method(:stmt_count)).by(-1)
       expected result to have changed by -1, but was changed by 0
     # ./spec/mysql2/statement_spec.rb:702:in `block (3 levels) in <top (required)>'

Finished in 11.72 seconds (files took 0.21288 seconds to load)
322 examples, 3 failures

Failed examples:

rspec ./spec/mysql2/error_spec.rb:51 # Mysql2::Error encoding returns error messages as UTF-8 by default
rspec ./spec/mysql2/statement_spec.rb:16 # Mysql2::Statement should create a statement
rspec ./spec/mysql2/statement_spec.rb:699 # Mysql2::Statement close should free server resources

As those tests are old and simple I do not have a clue what is causing this.
Exactly same code builds / passes tests in our Fedora Stable (mariadb: 10.4.17).

The change may have been caused by update to openssl version: 1.1.1i
(According to one of our tools, which might be wrong.)

Ruby version: both 2.7 and 3.0 are failing
mariadb-server version: 10.5.8
gem version: 0.5.3

The text was updated successfully, but these errors were encountered:

junaruga · 2021-01-11T13:57:41Z

This error started on Fedora at the timing [1] of that the following dependency packages to build rubygem-mysql2 were changed. I assume it might be the gcc 11 specific issue.

gcc 10.2.1 => 11.0.0
MariaDB 10.4.17 => 10.5.8

[1] https://koschei.fedoraproject.org/package/rubygem-mysql2?last_seen_ts=1607653395&collection=f34

junaruga · 2021-01-21T12:48:11Z

gcc 10.2.1 => 11.0.0
MariaDB 10.4.17 => 10.5.8

As a updated info, we found this issue comes from MariaDB 10.4.17 => 10.5.8 in Fedora. It's not from upgrading gcc.

voxik · 2021-02-11T14:57:41Z

These two:

  1) Mysql2::Statement should create a statement
     Failure/Error: expect { statement = @client.prepare 'SELECT 1' }.to change(&method(:stmt_count)).by(1)
       expected result to have changed by 1, but was changed by 0
     # ./spec/mysql2/statement_spec.rb:18:in `block (2 levels) in <top (required)>'

  2) Mysql2::Statement close should free server resources
     Failure/Error: expect { stmt.close }.to change(&method(:stmt_count)).by(-1)
       expected result to have changed by -1, but was changed by 0
     # ./spec/mysql2/statement_spec.rb:702:in `block (3 levels) in <top (required)>'

might be related to https://mariadb.com/docs/features/whats-new/whats-new-in-enterprise-server-105/#performance-schema

voxik · 2021-02-11T15:43:12Z

And similar in nature to #965

voxik · 2021-02-11T15:58:04Z

I can confirm that with MariaDB 10.4, the test suite passes, because it triggers the rescue branch:

mysql2/spec/mysql2/statement_spec.rb

Lines 8 to 14 in ad94a79

    
           def stmt_count 
        
             # Use the performance schema in MySQL 5.7 and above 
        
             @client.query("SELECT COUNT(1) AS count FROM performance_schema.prepared_statements_instances").first['count'].to_i 
        
           rescue Mysql2::Error 
        
             # Fall back to the global prepapred statement counter 
        
             @client.query("SHOW STATUS LIKE 'Prepared_stmt_count'").first['Value'].to_i 
        
           end

while for the MariaDB 10.5.8, the query succeeds, but returns unexpected result. I am not sure if the difference to MySql is intentional or if that is bug on MariaDB side.

hhorak · 2021-02-11T17:10:57Z

ad 2) It's true that performance_schema.prepared_statements_instances was added in 10.5:
https://mariadb.com/docs/reference/mdb/performance-schema/prepared_statements_instances/#mdb-performance-schema-prepared-statements-instances

ad 1)

  1) Mysql2::Error encoding returns error messages as UTF-8 by default
     Failure/Error: expect(bad_err.message).to include("??}\u001F")
       expected "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1" to include "??}\u001F"
     # ./spec/mysql2/error_spec.rb:59:in `block (4 levels) in <top (required)>'
     # ./spec/spec_helper.rb:17:in `with_internal_encoding'
     # ./spec/mysql2/error_spec.rb:52:in `block (3 levels) in <top (required)>'

IMO (guessing) it checks whether the error messages use encoding by running some wrong SQL statement and looking for the "??}\u001F" in output, while it gets '??}\001F' (double slash). Can you try to patch the expected output to expect the double-slash thing?

voxik · 2021-02-11T17:29:00Z

Looking at the:

  1) Mysql2::Error encoding returns error messages as UTF-8 by default
     Failure/Error: expect(bad_err.message).to include("??}\u001F")
       expected "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1" to include "??}\u001F"
     # ./spec/mysql2/error_spec.rb:59:in `block (4 levels) in <top (required)>'
     # ./spec/spec_helper.rb:17:in `with_internal_encoding'
     # ./spec/mysql2/error_spec.rb:52:in `block (3 levels) in <top (required)>'

It seems that on the MariaDB client library border, the input is correct:

507	static void *nogvl_send_query(void *ptr) {
(gdb) n
511	  rv = mysql_send_query(args->mysql, args->sql_ptr, args->sql_len);
(gdb) p args->sql_ptr 
$16 = 0x555555efb128 "\345\306}\037"

While the result is different

MariaDB 10.4:

Breakpoint 1, nogvl_read_query_result (ptr=0x5555560bb6f0) at client.c:532
532	static void *nogvl_read_query_result(void *ptr) {
(gdb) n
534	  my_bool res = mysql_read_query_result(client);
(gdb) n
536	  return (void *)(res == 0 ? Qtrue : Qfalse);
(gdb) n
0x00007ffff7e54537 in rb_nogvl () from /lib64/libruby.so.2.7
(gdb) list 
531	 */
532	static void *nogvl_read_query_result(void *ptr) {
533	  MYSQL * client = ptr;
534	  my_bool res = mysql_read_query_result(client);
535	
536	  return (void *)(res == 0 ? Qtrue : Qfalse);
537	}
538	
539	static void *nogvl_do_result(void *ptr, char use_result) {
540	  mysql_client_wrapper *wrapper = ptr;
(gdb) n
Single stepping until exit from function rb_nogvl,
which has no line number information.
rb_mysql_client_async_result (self=93824998540280) at client.c:596
596	      wrapper->active_thread = Qnil;
(gdb) list
591	    result = (MYSQL_RES *)rb_thread_call_without_gvl(nogvl_store_result, wrapper, RUBY_UBF_IO, 0);
592	  }
593	
594	  if (result == NULL) {
595	    if (mysql_errno(wrapper->client) != 0) {
596	      wrapper->active_thread = Qnil;
597	      rb_raise_mysql2_error(wrapper);
598	    }
599	    /* no data and no error, so query was not a SELECT */
600	    return Qnil;
(gdb)  p wrapper->client
$4 = (MYSQL *) 0x5555560bb6f0
(gdb)  p *wrapperclient
No symbol "wrapperclient" in current context.
(gdb)  p *wrapper.client
$5 = {net = {pvio = 0x555555f4e690, 
    buff = 0x5555560c6400 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\037' at line 1", 
    buff_end = 0x5555560c8400 "", 
    write_pos = 0x5555560c6400 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\037' at line 1", 
    read_pos = 0x5555560c6400 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\037' at line 1", 
    fd = 5, remain_in_buf = 0, length = 0, buf_length = 0, where_b = 0, max_packet = 8192, max_packet_size = 1073741824, pkt_nr = 2, compress_pkt_nr = 2, write_timeout = 0, read_timeout = 30, retry_count = 0, 
    fcntl = 0, return_status = 0x0, reading_or_writing = 0 '\000', save_char = 0 '\000', unused_1 = 0 '\000', unused_2 = 0 '\000', compress = 0 '\000', unused_3 = 0 '\000', unused_4 = 0x0, last_errno = 1064, 
    error = 0 '\000', unused_5 = 0 '\000', unused_6 = 0 '\000', 
    last_error = "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\037' at line 1\000\061", '\000' <repeats 357 times>, sqlstate = "42000", extension = 0x555555ef3f00}, unused_0 = 0x0, host = 0x555555c871a0 "localhost", user = 0x555555f2ae70 "mockbuild", passwd = 0x555555759010 "", 
  unix_socket = 0x555555ef3980 "/builddir/build/BUILD/mysql2-0.5.3/usr/share/gems/gems/mysql2-0.5.3/mysql.sock", server_version = 0x555555c51630 "10.4.17-MariaDB", 
  host_info = 0x555555b8ea90 "Localhost via UNIX socket", info = 0x0, db = 0x555555a3ab90 "test", charset = 0x7ffff41b23a8, fields = 0x0, field_alloc = {free = 0x0, used = 0x0, pre_alloc = 0x0, min_malloc = 0, 
    block_size = 0, block_num = 0, first_block_usage = 0, error_handler = 0x0}, affected_rows = 18446744073709551615, insert_id = 0, extra_info = 0, thread_id = 15, packet_length = 0, port = 13776, 
  client_flag = 2159977100, server_capabilities = 3254779902, protocol_version = 10, field_count = 0, server_status = 16386, server_language = 8, warning_count = 1, options = {connect_timeout = 120, 
    read_timeout = 0, write_timeout = 0, port = 0, protocol = 0, client_flag = 128, host = 0x0, user = 0x0, password = 0x0, unix_socket = 0x0, db = 0x0, init_command = 0x0, my_cnf_file = 0x0, 
    my_cnf_group = 0x0, charset_dir = 0x0, charset_name = 0x555555db4730 "utf8", ssl_key = 0x0, ssl_cert = 0x0, ssl_ca = 0x0, ssl_capath = 0x0, ssl_cipher = 0x0, shared_memory_base_name = 0x0, 
    max_allowed_packet = 0, use_ssl = 0 '\000', compress = 0 '\000', named_pipe = 0 '\000', reconnect = 0 '\000', unused_1 = 0 '\000', unused_2 = 0 '\000', unused_3 = 0 '\000', 
    methods_to_use = MYSQL_OPT_CONNECT_TIMEOUT, bind_address = 0x0, secure_auth = 0 '\000', report_data_truncation = 1 '\001', local_infile_init = 0x7ffff41c7b60 <mysql2_local_infile_init>, 
    local_infile_read = 0x7ffff41c7b00 <mysql2_local_infile_read>, local_infile_end = 0x7ffff41c7ab0 <mysql2_local_infile_end>, local_infile_error = 0x7ffff41c7a50 <mysql2_local_infile_error>, 
    local_infile_userdata = 0x555555b55360, extension = 0x555555f32210}, status = MYSQL_STATUS_READY, free_me = 0 '\000', unused_1 = 0 '\000', scramble_buff = "-(~ea4\"J1S..9rU29dp&", unused_2 = 0 '\000', 
  unused_3 = 0x0, unused_4 = 0x0, unused_5 = 0x0, unused_6 = 0x0, stmts = 0x0, methods = 0x7ffff41ba2e0, thd = 0x0, unbuffered_fetch_owner = 0x0, info_buffer = 0x0, extension = 0x555555f4e7c0}
(gdb) p wrapper->client->net->buff
$6 = (unsigned char *) 0x5555560c6400 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\037' at line 1"

MariaDB 10.5:

Breakpoint 2, nogvl_read_query_result (ptr=0x555555e6c550) at /builddir/build/BUILD/mysql2-0.5.3/usr/share/gems/gems/mysql2-0.5.3/ext/mysql2/client.c:532
532	static void *nogvl_read_query_result(void *ptr) {
(gdb) n
534	  my_bool res = mysql_read_query_result(client);
(gdb) n
536	  return (void *)(res == 0 ? Qtrue : Qfalse);
(gdb) n
0x00007ffff7e47d10 in rb_nogvl () from /lib64/libruby.so.3.0
(gdb) n
Single stepping until exit from function rb_nogvl,
which has no line number information.
rb_mysql_client_async_result (self=93825001644360) at /builddir/build/BUILD/mysql2-0.5.3/usr/share/gems/gems/mysql2-0.5.3/ext/mysql2/client.c:596
596	      wrapper->active_thread = Qnil;
(gdb) p wrapper
$17 = (mysql_client_wrapper *) 0x555555ea2240
(gdb) p *wrapper
$18 = {encoding = 93824993017160, active_thread = 93824992719920, server_version = 100508, reconnect_enabled = 0, connect_timeout = 120, active = 0, automatic_close = 1, initialized = 1, refcount = 1, 
  closed = 0, client = 0x555555e6c550}
(gdb) p *wrapper.client
$19 = {net = {pvio = 0x555555ea2290, 
    buff = 0x555555e607d0 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1", 
    buff_end = 0x555555e627d0 "", 
    write_pos = 0x555555e607d0 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1", 
    read_pos = 0x555555e607d0 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1", 
    fd = 5, remain_in_buf = 0, length = 0, buf_length = 0, where_b = 0, max_packet = 8192, max_packet_size = 1073741824, pkt_nr = 2, compress_pkt_nr = 2, write_timeout = 0, read_timeout = 30, retry_count = 0, 
    fcntl = 0, return_status = 0x0, reading_or_writing = 0 '\000', save_char = 0 '\000', unused_1 = 0 '\000', unused_2 = 0 '\000', compress = 0 '\000', unused_3 = 0 '\000', unused_4 = 0x0, last_errno = 1064, 
    error = 0 '\000', unused_5 = 0 '\000', unused_6 = 0 '\000', 
    last_error = "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1", '\000' <repeats 355 times>, 
    sqlstate = "42000", extension = 0x555555e87510}, unused_0 = 0x0, host = 0x555555ea2320 "localhost", user = 0x555555ea2340 "mockbuild", passwd = 0x555555ea2360 "", 
  unix_socket = 0x5555560cbda0 "/builddir/build/BUILD/mysql2-0.5.3/usr/share/gems/gems/mysql2-0.5.3/mysql.sock", server_version = 0x555555ea2380 "10.5.8-MariaDB", 
  host_info = 0x555555e52a00 "Localhost via UNIX socket", info = 0x0, db = 0x555555e7d630 "test", charset = 0x7ffff4168348, fields = 0x0, field_alloc = {free = 0x0, used = 0x0, pre_alloc = 0x0, min_malloc = 0, 
    block_size = 0, block_num = 0, first_block_usage = 0, error_handler = 0x0}, affected_rows = 18446744073709551615, insert_id = 0, extra_info = 0, thread_id = 35, packet_length = 0, port = 14168, 
  client_flag = 2159977100, server_capabilities = 3254779902, protocol_version = 10, field_count = 0, server_status = 16386, server_language = 8, warning_count = 1, options = {connect_timeout = 120, 
    read_timeout = 0, write_timeout = 0, port = 0, protocol = 0, client_flag = 128, host = 0x0, user = 0x0, password = 0x0, unix_socket = 0x0, db = 0x0, init_command = 0x0, my_cnf_file = 0x0, 
    my_cnf_group = 0x0, charset_dir = 0x0, charset_name = 0x555555e875c0 "utf8", ssl_key = 0x0, ssl_cert = 0x0, ssl_ca = 0x0, ssl_capath = 0x0, ssl_cipher = 0x0, shared_memory_base_name = 0x0, 
    max_allowed_packet = 0, use_ssl = 0 '\000', compress = 0 '\000', named_pipe = 0 '\000', reconnect = 0 '\000', unused_1 = 0 '\000', unused_2 = 0 '\000', unused_3 = 0 '\000', 
    methods_to_use = MYSQL_OPT_CONNECT_TIMEOUT, bind_address = 0x0, secure_auth = 0 '\000', report_data_truncation = 1 '\001', local_infile_init = 0x7ffff417b8b0 <mysql2_local_infile_init>, 
    local_infile_read = 0x7ffff417b970 <mysql2_local_infile_read>, local_infile_end = 0x7ffff417b9d0 <mysql2_local_infile_end>, local_infile_error = 0x7ffff417b860 <mysql2_local_infile_error>, 
    local_infile_userdata = 0x555555ea2240, extension = 0x555555e875e0}, status = MYSQL_STATUS_READY, free_me = 0 '\000', unused_1 = 0 '\000', scramble_buff = ">?cSX?sE=CvM[aWpMnb!", unused_2 = 0 '\000', 
  unused_3 = 0x0, unused_4 = 0x0, unused_5 = 0x0, unused_6 = 0x0, stmts = 0x0, methods = 0x7ffff416f3c0, thd = 0x0, unbuffered_fetch_owner = 0x0, info_buffer = 0x0, extension = 0x555555e87530}
(gdb) p wrapper->client->net->buff
$22 = (unsigned char *) 0x555555e607d0 "\377(\004#42000You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1"

voxik · 2021-02-11T19:50:17Z

ad 1)
  1) Mysql2::Error encoding returns error messages as UTF-8 by default
     Failure/Error: expect(bad_err.message).to include("??}\u001F")
       expected "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1" to include "??}\u001F"
     # ./spec/mysql2/error_spec.rb:59:in `block (4 levels) in <top (required)>'
     # ./spec/spec_helper.rb:17:in `with_internal_encoding'
     # ./spec/mysql2/error_spec.rb:52:in `block (3 levels) in <top (required)>'
IMO (guessing) it checks whether the error messages use encoding by running some wrong SQL statement and looking for the "??}\u001F" in output, while it gets '??}\001F' (double slash). Can you try to patch the expected output to expect the double-slash thing?

Of course we can do that, but

That would not be compatible with older MariaDB and possibly MySQL.
That does not explain what have changed. It seems more like bug in MariaDB, which although does not understand the input, it mangles it. Maybe it is intentional, but it is hard to say without understanding what was changed.

Unfortunately, I'm not that familiar with MariaDB internals to identify the core reason for changed behavior. Looking at recent changes, there are a few places involving ER_SYNTAX_ERROR, but nothing really strikes me at first sight.

junaruga · 2021-02-27T19:57:13Z

You can see the reproducer on the following CI cases in GitHub Actions now.

Container - fedora fedora:rawhide (Ruby 3.0.0, MariaDB 10.5.9)
https://github.com/brianmario/mysql2/runs/1987005360?check_suite_focus=true
macos ruby 2.4 (latest) mariadb (MariaDB 10.5.9). This case will be merged on the PR GitHub Actions: Add macOS cases. #1170 .
https://github.com/brianmario/mysql2/pull/1170/checks?check_run_id=1987005788

junaruga · 2021-03-02T19:43:30Z

For someone who is familiar with Debian based Linux, this issue might be reproduced with the mariadb-server 10.5 on the Ubuntu hirsute or Debian latest version.

junaruga · 2021-03-02T21:22:39Z

@pvalena Do you mind to change this issue ticket's title to more specific one showing the reality we see here? We see the issue is not Fedora specific. The new title can be such as "mariadb10.5: Mysql2::Statement tests failing". I think the new title makes other people facing the issue find the issue ticket easier.

junaruga · 2021-04-13T06:03:19Z

I think this ticket's 3 failures might be separated info 2 kind of issues.

1. Error messages including a UTF-8 charactor.

  1) Mysql2::Error encoding returns error messages as UTF-8 by default
     Failure/Error: expect(bad_err.message).to include("??}\u001F")
       expected "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1" to include "??}\u001F"
     # ./spec/mysql2/error_spec.rb:59:in `block (4 levels) in <top (required)>'
     # ./spec/spec_helper.rb:17:in `with_internal_encoding'
     # ./spec/mysql2/error_spec.rb:52:in `block (3 levels) in <top (required)>'

Reproducer

Here is a reproducer, a little simplifying from the original unit test.

$ cat spec/mysql2/error_debug.rb
$LOAD_PATH << 'lib'
require 'mysql2'
require 'yaml'

DatabaseCredentials = YAML.load_file('spec/configuration.yml')
client = Mysql2::Client.new(DatabaseCredentials['root'])

invalid_utf8 = ["e5c67d1f"].pack('H*').force_encoding(Encoding::UTF_8)
begin
  client.query(invalid_utf8)
rescue Mysql2::Error => bad_err
  p "[DEBUG] include? #{bad_err.message.include?("??}\u001F")}"
  p "[DEBUG] bad_err.message: #{bad_err.message}"
end

$ ruby spec/mysql2/error_debug.rb
"[DEBUG] include? false"
"[DEBUG] bad_err.message: You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1"

Debug

Add the following debug flags for gdb debug.

ext/mysql2/extconf.rb

+$CFLAGS.gsub!(/-O[123]/, '-O0')
+$CFLAGS << ' -O0 -gdwarf-2 -ggdb3 -g3'
+$CXXFLAGS.gsub!(/-O[123]/, '-O0')
+$CXXFLAGS << ' -O0 -gdwarf-2 -ggdb3 -g3'

$ bundle exec rake compile

In Fedora, ruby is a shell script to run a binary ruby-mri internally. So, I am using ruby-mri instead of ruby command to read the symbols.

[mockbuild@c86e1c99c615423dbe19c350d4cbfb84 mysql2]$ gdb -q --args ruby-mri spec/mysql2/error_debug.rb
Reading symbols from ruby-mri...
Reading symbols from .gnu_debugdata for /usr/bin/ruby-mri...
(No debugging symbols found in .gnu_debugdata for /usr/bin/ruby-mri)
Missing separate debuginfos, use: dnf debuginfo-install ruby-3.0.0-147.fc35.x86_64
(gdb) set breakpoint pending on 
(gdb) b nogvl_send_query
Function "nogvl_send_query" not defined.
Breakpoint 1 (nogvl_send_query) pending.
(gdb) b ext/mysql2/client.c:523
No symbol table is loaded.  Use the "file" command.
Breakpoint 2 (ext/mysql2/client.c:523) pending.
(gdb) b nogvl_read_query_result
Function "nogvl_read_query_result" not defined.
Breakpoint 3 (nogvl_read_query_result) pending.
(gdb) b ext/mysql2/client.c:548
No symbol table is loaded.  Use the "file" command.
Breakpoint 4 (ext/mysql2/client.c:548) pending.
(gdb) r
Starting program: /usr/bin/ruby-mri spec/mysql2/error_debug.rb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".

Breakpoint 1, nogvl_send_query (ptr=0x7fffffffd980) at ../../../../ext/mysql2/client.c:520
520	  struct nogvl_send_query_args *args = ptr;
(gdb) c
Continuing.

Breakpoint 2, nogvl_send_query (ptr=0x7fffffffd980) at ../../../../ext/mysql2/client.c:523
523	  rv = mysql_send_query(args->mysql, args->sql_ptr, args->sql_len);
(gdb) i lo
args = 0x7fffffffd980
rv = 32767
(gdb) p *args
$1 = {mysql = 0x5555559e6060, sql = 93824997035680, sql_ptr = 0x5555559e8eb0 "\345\306}\037", 
  sql_len = 4, wrapper = 0x555555907900}
(gdb) c
Continuing.

Breakpoint 3, nogvl_read_query_result (ptr=0x5555559e6060) at ../../../../ext/mysql2/client.c:545
545	  MYSQL * client = ptr;
(gdb) c
Continuing.

Breakpoint 4, nogvl_read_query_result (ptr=0x5555559e6060) at ../../../../ext/mysql2/client.c:548
548	  return (void *)(res == 0 ? Qtrue : Qfalse);
(gdb) i lo
client = 0x5555559e6060
res = 1 '\001'
(gdb) p res
$2 = 1 '\001'
(gdb) p (*client).net.last_error
$3 = "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1", '\000' <repeats 355 times>

The input to the MariaDB is mysql_send_query function with sql_ptr = 0x5555559e8eb0 "\345\306}\037", sql_len = 4.

mysql2/ext/mysql2/client.c

Line 523 in 346b4a4

rv = mysql_send_query(args->mysql, args->sql_ptr, args->sql_len);

The output from the MariaDB is mysql_read_query_result returning the result: (*client).net.last_error: "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1".

mysql2/ext/mysql2/client.c

Lines 546 to 548 in 346b4a4

    
           my_bool res = mysql_read_query_result(client); 
        
           return (void *)(res == 0 ? Qtrue : Qfalse);

The used MariaDB client library is mariadb-connector-c.

https://github.com/mariadb-corporation/mariadb-connector-c/blob/7d304d26c787a3f0430624db977b615aba56e4bb/libmariadb/mariadb_lib.c#L2369-L2372

2. Mysql2::Statement

  2) Mysql2::Statement should create a statement
     Failure/Error: expect { statement = @client.prepare 'SELECT 1' }.to change(&method(:stmt_count)).by(1)
       expected result to have changed by 1, but was changed by 0
     # ./spec/mysql2/statement_spec.rb:18:in `block (2 levels) in <top (required)>'

  3) Mysql2::Statement close should free server resources
     Failure/Error: expect { stmt.close }.to change(&method(:stmt_count)).by(-1)
       expected result to have changed by -1, but was changed by 0
     # ./spec/mysql2/statement_spec.rb:702:in `block (3 levels) in <top (required)>'

I assume that perhaps this issue might happen on the environment where performance_schema is off. I noticed that it is disabled as a default on MariaDB seeing the upstream ticket related to performance schema. See #965 (comment) .

MariaDB [test]> SHOW VARIABLES LIKE 'performance_schema';
+--------------------+-------+
| Variable_name      | Value |
+--------------------+-------+
| performance_schema | OFF   |
+--------------------+-------+
1 row in set (0.002 sec)

Then I see the something about the performance schema is changed on MariaDB 10.5 seeing the following document.

https://mariadb.com/kb/en/performance-schema-overview/#activating-the-performance-schema

Until MariaDB 10.4, all memory used by the Performance Schema is allocated at startup. From MariaDB 10.5, some memory is allocated dynamically, depending on load, number of connections, number of tables open etc.

junaruga · 2021-04-13T08:11:03Z

For the 1. error message issue, I opened the issue ticket on MariaDB project.
https://jira.mariadb.org/browse/MDEV-25400

junaruga · 2021-04-14T22:04:06Z

@sodabrew Fantastic news!

For 2. Mysql2::Statement, I confirmed the test failures do not happen when enabling performance schema (performance_schema: ON) on MariaDB 10.5 on my Fedora 35! For the 1. error message issue, the failure still happens when enabling performance schema. But it is expected result. See #965 (comment) for detail.

junaruga · 2021-04-15T14:15:10Z

For the 1. error message issue, I updated the MariaDB ticket "MDEV-25400" with client and server's character sets info. A pattern of the results show the issue is MariaDB 10.5 specific. It might not related to a characterset on a database server or client.

I also share a updated minimal reproducer again.

Here is the code.

bundle exec irb
require 'mysql2'
client = Mysql2::Client.new(:host => "127.0.0.1", :port => '13306', :username => "root")
str = ["e5c67d1f"].pack('H*')
invalid_utf8 = str.force_encoding(Encoding::UTF_8)
begin
  client.query(invalid_utf8)
rescue Mysql2::Error => bad_err
  p bad_err.message
end

Here is result by irb.

$ bundle exec irb
irb(main):001:0> require 'mysql2'
=> true
irb(main):002:0> client = Mysql2::Client.new(:host => "127.0.0.1", :port => '13306', :username => "root")
=> 
#<Mysql2::Client:0x0000000002989ac0
...
irb(main):003:0> str = ["e5c67d1f"].pack('H*')
=> "\xE5\xC6}\x1F"
irb(main):004:0> str.class
=> String
irb(main):005:0> invalid_utf8 = str.force_encoding(Encoding::UTF_8)
=> "\xE5\xC6}\u001F"
irb(main):006:1* begin
irb(main):007:1*   client.query(invalid_utf8)
irb(main):008:1* rescue Mysql2::Error => bad_err
irb(main):009:1*   p bad_err.message
irb(main):010:0> end
"You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1"
=> "You have an error in your SQL syntax; check the manual that corresponds to your MariaDB server version for the right syntax to use near '??}\\001F' at line 1"

I checked the case by client = Mysql2::Client.new(:host => "127.0.0.1", :port => '13306', :username => "root", :encoding => 'utf8mb4') setting :encoding => 'utf8mb4' instead of the default value utf8. But the message by p bad_err.message was same.

junaruga · 2021-04-16T13:10:11Z

For 2 Mysql2:Statement issue, I found the reason

Here is a minimal reproducer.

require 'mysql2'
client = Mysql2::Client.new(:host => "localhost", :port => '3306', :socket => '/mnt/mysql2/test_db/mysql.sock', :username => "mockbuild", :database => "test")
statement = client.prepare 'SELECT 1'

results = client.query("SELECT COUNT(1) AS count FROM performance_schema.prepared_statements_instances");
p results.each

results = client.query("SHOW STATUS LIKE 'Prepared_stmt_count'");
p results.each

While the spec/mysql2/statement_spec.rb#stmt_count method expected to return 1 on the "should create a statement" test,

On MariaDB <= 10.4, client.query("SELECT COUNT(1) AS count FROM performance_schema.prepared_statements_instances") raises Mysql2:Errror when the performance_schema is OFF.
But on MariaDB 10.5, it does not raise the error, but just returns 0 without raising the error.

irb(main):004:0> results = client.query("SELECT COUNT(1) AS count FROM performance_schema.prepared_state
ments_instances");
=> 
#<Mysql2::Result:0x0000555f4fac7598
...
irb(main):005:0> p results.each
[{"count"=>0}]
=> [{"count"=>0}]

But the following existing logic still returns 1. So, we can use this logic on the environment where on performance_schema is not ON.

irb(main):009:0> results = client.query("SHOW STATUS LIKE 'Prepared_stmt_count'");
=> 
#<Mysql2::Result:0x0000555f4fb06b30
...
irb(main):010:0> p results.each
[{"Variable_name"=>"Prepared_stmt_count", "Value"=>"1"}]
=> [{"Variable_name"=>"Prepared_stmt_count", "Value"=>"1"}]

I will send the PR.

junaruga mentioned this issue Feb 24, 2021

GitHub Actions: Add macOS cases. #1170

Merged

pvalena changed the title ~~Tests failing in Fedora~~ tests failing with mariadb10.5: Mysql2::Statement Mar 3, 2021

junaruga mentioned this issue Apr 14, 2021

Test failures on MariaDB performance_schema: OFF #965

Closed

junaruga mentioned this issue Apr 15, 2021

How to get the result by SQL "STATUS"? #1191

Closed

This was referenced Apr 16, 2021

Fix test failures on MariaDB #1193

Merged

Can't enable SSL with MariaDB driver library. (#1182) #1183

Merged

sodabrew closed this as completed in #1193 May 19, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

tests failing with mariadb10.5: Mysql2::Statement #1152

tests failing with mariadb10.5: Mysql2::Statement #1152

pvalena commented Jan 7, 2021

junaruga commented Jan 11, 2021

junaruga commented Jan 21, 2021

voxik commented Feb 11, 2021

voxik commented Feb 11, 2021

voxik commented Feb 11, 2021

hhorak commented Feb 11, 2021 •

edited

Loading

voxik commented Feb 11, 2021

voxik commented Feb 11, 2021

junaruga commented Feb 27, 2021

junaruga commented Mar 2, 2021

junaruga commented Mar 2, 2021

junaruga commented Apr 13, 2021 •

edited

Loading

junaruga commented Apr 13, 2021

junaruga commented Apr 14, 2021

junaruga commented Apr 15, 2021

junaruga commented Apr 16, 2021

tests failing with mariadb10.5: Mysql2::Statement #1152

tests failing with mariadb10.5: Mysql2::Statement #1152

Comments

pvalena commented Jan 7, 2021

junaruga commented Jan 11, 2021

junaruga commented Jan 21, 2021

voxik commented Feb 11, 2021

voxik commented Feb 11, 2021

voxik commented Feb 11, 2021

hhorak commented Feb 11, 2021 • edited Loading

voxik commented Feb 11, 2021

MariaDB 10.4:

MariaDB 10.5:

voxik commented Feb 11, 2021

junaruga commented Feb 27, 2021

junaruga commented Mar 2, 2021

junaruga commented Mar 2, 2021

junaruga commented Apr 13, 2021 • edited Loading

1. Error messages including a UTF-8 charactor.

Reproducer

Debug

2. Mysql2::Statement

junaruga commented Apr 13, 2021

junaruga commented Apr 14, 2021

junaruga commented Apr 15, 2021

junaruga commented Apr 16, 2021

hhorak commented Feb 11, 2021 •

edited

Loading

junaruga commented Apr 13, 2021 •

edited

Loading