[CONC-594] Non blocking api appears to be blocking for secure connections Created: 2022-05-23  Updated: 2023-07-17

Status: Open
Project: MariaDB Connector/C
Component/s: None
Affects Version/s: 3.1.12
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Vladislav Vaintroub Assignee: Georg Richter
Resolution: Unresolved Votes: 0
Labels: None

Attachments: Text File mariadb-async-ssl.patch    

 Description   

From https://mariadb.com/kb/en/non-blocking-api-appears-to-be-blocking-for-secure-connections/

I am encountering delays when using secure connections to AuroraDB, and wondering if the client lib (C-connector) is making lengthy system calls.

Here is a callstack when not connected (and want to connected):

#0  0x00007f34ce333394 in __libc_read (fd=227, buf=0x7e3bc664ed93, nbytes=5) at ../sysdeps/unix/sysv/linux/read.c:27
 
#1  0x00007f34cd1a8b7e in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#2  0x00007f34cd1a3fba in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#3  0x00007f34cd1a2e53 in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#4  0x00007f34cd1a3403 in BIO_read () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#5  0x00007f34cd5e4913 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#6  0x00007f34cd5e8fbd in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#7  0x00007f34cd5e66c2 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#8  0x00007f34cd5ed995 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#9  0x00007f34cd5f8232 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#10 0x00007f34cd5f8353 in SSL_read () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#11 0x00007f34ccec5437 in ma_tls_read_async (pvio=pvio@entry=0x7e3bc6982110, buffer=buffer@entry=0x7e3bc7b9b5b0 "9", length=length@entry=16384) at /mariadb-connector-c-3.1.12-src/libmariadb/secure/openssl.c:589
 
#12 0x00007f34cceb54cc in ma_pvio_read (pvio=pvio@entry=0x7e3bc6982110, buffer=0x7e3bc7b9b5b0 "9", length=length@entry=16384) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_pvio.c:228
 
#13 0x00007f34cceb56e3 in ma_pvio_cache_read (pvio=0x7e3bc6982110, buffer=buffer@entry=0x7e3bc7291cd0 "\021", length=length@entry=7) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_pvio.c:297
 
#14 0x00007f34cceaba76 in ma_real_read (net=net@entry=0x7e13c7594fa8, complen=complen@entry=0x7e3bc756c628) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_net.c:380
 
#15 0x00007f34cceac4ac in ma_net_read (net=net@entry=0x7e13c7594fa8) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_net.c:555
 
#16 0x00007f34cceb1571 in ma_net_safe_read (mysql=mysql@entry=0x7e13c7594fa8) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:200
 
#17 0x00007f34cceb4ca8 in mthd_my_read_query_result (mysql=0x7e13c7594fa8) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:2314
 
#18 0x00007f34cceb27c2 in mthd_my_real_connect (mysql=0x7e13c7594fa8, host=<optimized out>, user=<optimized out>, passwd=0x7e13c74f03b0 "B1b-_1824b448ffb3f497064872ef54fe1a4a035451c1d8478b71e4ce4ce3e76f4f",
 
    db=0x7e13c74f1650 "test_gsilt_1m_common_main_xone_Load7d44167e04", port=<optimized out>, unix_socket=<optimized out>, client_flag=2147549344) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:1678
 
#19 0x00007f34cceaf308 in mysql_real_connect (mysql=0x7e13c7594fa8, host=0x7e13c7594f70 "10.94.7.87", user=0x7e13c74f0774 "rwapp_355bf29784", passwd=0x7e13c74f03b0 "B1b-_1824b448ffb3f497064872ef54fe1a4a035451c1d8478b71e4ce4ce3e76f4f",
 
    db=0x7e13c74f1650 "test_gsilt_1m_common_main_xone_Load7d44167e04", port=3306, unix_socket=0x0, client_flag=2147549184) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:1295
 
#20 0x00007f34cced7031 in mysql_real_connect_start_internal (d=<optimized out>) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_async.c:332
 
#21 0x00007f34cceda851 in my_context_spawn (c=0x7e3bc69c3000, f=0x7e3bc664ed93, d=0x5) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_context.c:201

and callstack when already connected:

#0  0x00007ffb4282d394 in __libc_read (fd=232, buf=0x7f023b656033, nbytes=5) at ../sysdeps/unix/sysv/linux/read.c:27
 
#1  0x00007ffb416a2b7e in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#2  0x00007ffb4169dfba in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#3  0x00007ffb4169ce53 in ?? () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#4  0x00007ffb4169d403 in BIO_read () from /usr/lib/x86_64-linux-gnu/libcrypto.so.1.1
 
#5  0x00007ffb41ade913 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#6  0x00007ffb41ae2fbd in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#7  0x00007ffb41ae06c2 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#8  0x00007ffb41ae7995 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#9  0x00007ffb41af2232 in ?? () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#10 0x00007ffb41af2353 in SSL_read () from /usr/lib/x86_64-linux-gnu/libssl.so.1.1
 
#11 0x00007ffb413bf437 in ma_tls_read_async (pvio=pvio@entry=0x7f023b6495f0, buffer=buffer@entry=0x7f023b6fedf0 "\035", length=length@entry=16384) at /mariadb-connector-c-3.1.12-src/libmariadb/secure/openssl.c:589
 
#12 0x00007ffb413af4cc in ma_pvio_read (pvio=pvio@entry=0x7f023b6495f0, buffer=0x7f023b6fedf0 "\035", length=length@entry=16384) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_pvio.c:228
 
#13 0x00007ffb413af6e3 in ma_pvio_cache_read (pvio=0x7f023b6495f0, buffer=buffer@entry=0x7f023b85e810 "\001", length=length@entry=7) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_pvio.c:297
 
#14 0x00007ffb413a5a76 in ma_real_read (net=net@entry=0x7eda3bab9088, complen=complen@entry=0x7f023b898f08) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_net.c:380
 
#15 0x00007ffb413a64ac in ma_net_read (net=net@entry=0x7eda3bab9088) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_net.c:555
 
#16 0x00007ffb413ab571 in ma_net_safe_read (mysql=mysql@entry=0x7eda3bab9088) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:200
 
#17 0x00007ffb413ad82b in mthd_my_send_cmd (mysql=0x7eda3bab9088, command=<optimized out>, arg=0x7ffb413d8232 "", length=<optimized out>, skipp_check=0 '\000', opt_arg=<optimized out>)
 
    at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:427
 
#18 0x00007ffb413adad8 in mysql_ping (mysql=0x7eda3bab9088) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_lib.c:2792
 
#19 0x00007ffb413d12e4 in mysql_ping_start_internal (d=<optimized out>) at /mariadb-connector-c-3.1.12-src/libmariadb/mariadb_async.c:1028
 
#20 0x00007ffb413d4851 in my_context_spawn (c=0x7f023bb4f480, f=0x7f023b656033, d=0x5) at /mariadb-connector-c-3.1.12-src/libmariadb/ma_context.c:201

Using a more recent version (3.2.6) did not make a difference.

 Comments   
Comment by Georg Richter [ 2022-05-25 ]

Is there a difference when not using init_command option?

Comment by Jacob [ 2022-12-12 ]

Removing the use of init_command option appears to have resolved the blocking occurring from 'mysql_real_connect_start_internal'; however, when testing DB failover failure (by having a read slave become unresponsive) the mysql_ping_start_internal still appears to have the same unexpected blocking behavior.

Comment by Jacob [ 2023-01-03 ]

Hi Georg(georg@mariadb.com) I managed to reproduce several related issues that were causing SSL implementation to block the main thread with async connections. I have made hopefully minimal code changes to address these and have validated that the issues are now all resolved. I am attaching a patch that fixes all the issues found. Please review it and let me know if there are any questions. I hope that this patch (or a variant of it) can be accepted into the mariadb C client library mainline.

One note, among the issues I have identified/fixed with my patch was a double free that appears to have been since fixed in mainline: https://github.com/mariadb-corporation/mariadb-connector-c/commit/da9bb98c0cef8097ee50341722f08d5042efbe49. That said, I believe that my fix may be more robust than the solution above, so I am still including it.

Comment by Jacob [ 2023-01-03 ]

In case it's helpful I am including the steps I use to apply the patch to the 3.3.3 version of the MariaDB C client library.

wget https://downloads.mariadb.com/Connectors/c/connector-c-3.3.3/mariadb-connector-c-3.3.3-src.tar.gz
 
tar -xvf mariadb-connector-*.tar.gz
 
patch -s -p0 < mariadb-async-ssl.patch

Comment by Georg Richter [ 2023-01-03 ]

Hi Jacob,

thanks for your contribution would it be possible to open a PR on github for your patch?

Thanks!

/Georg

Comment by Jacob [ 2023-01-03 ]

Hi Georg

Unfortunately I haven't got a GitHub account setup yet. Is it required to have the patch considered for inclusion? If so, I'll schedule time to setup an account/fork the branch and go through the steps of creating a proper pull request.

Comment by Sergei Golubchik [ 2023-01-04 ]

No, it's not required, we can apply a patch too. PRs help to provide proper attribution though (you'll be shown as an author).

Comment by Jacob [ 2023-01-09 ]

I created a pull request: https://github.com/mariadb-corporation/mariadb-connector-c/pull/211 but it seems to have failed a newly added unit test. However, when I ran the test locally with my changes it passes.

The error reported in the unit test: https://app.travis-ci.com/github/mariadb-corporation/mariadb-connector-c/jobs/592736627

21: # Testing against MySQL Server 10.3.37-MariaDB-1:10.3.37+maria~ubu1804-log
 
21: # Host: mariadb.example.com via TCP/IP
 
21: # Client library: 3.3.4
 
21: ok 1 - test_async
 
21: ok 2 - async1
 
21: ok 3 - test_conc131
 
21: ok 4 - test_conc129
 
21: # Expected error when connection to host '0.0.0.0'
 
21: not ok 5 - test_conc622
 
21: # close default
 
21: # Failed 1 tests!
 
21/21 Test #21: async ............................***Failed    0.12 sec

Seems to indicate that this code is triggering:

    /* Returns 0 when done, else flag for what to wait for when need to block. */
 
    status= mysql_real_connect_start(&ret, &mysql, "0.0.0.0", username, password, schema, port, socketname, 0);
 
    while (status)
 
    {
 
      status= wait_for_mysql(&mysql, status);
 
      status= mysql_real_connect_cont(&ret, &mysql, status);
 
    }
 
    if (!ret)
 
    {
 
      status= mysql_close_start(&mysql);
 
      while (status)
 
      {
 
        status= wait_for_mysql(&mysql, status);
 
        status= mysql_close_cont(&mysql, status);
 
      }
 
    } else {
 
      diag("Expected error when connection to host '0.0.0.0'");               /// ERROR reported here
 
      return FAIL;
 
    }

One thing I am not clear about is why does returning ret != NULL constitute an error in this case when the purpose of the test is to validate connection failure? Probably it would also be good to report the mysq_errno(&mysql) in this case so that it can be determined what precisely is failing.

Comment by Jacob [ 2023-01-10 ]

Hi Georg, I have managed to address the above issues of failing async.c unit test when run by the travis pipeline. Seems like the usage of 0.0.0.0 IP was causing the connection to succeed due to there being a locally hosted mysql instance that was being successfully connected to, which caused the test to fail to err... fail to connect. Anyhow by changing the ip to 1.2.3.4 it started passing (sort of) I actually had to reduce the number of iterations from 100 to 10 since 100 iterations was running really close to the 180s of running time in travis for some reason. I cannot repro such a long running time locally either for this test.

Anyhow there is now still one remaining unit test issue that I cannot seem to repro locally, this time in connection.c unit test: test_auth256

Details are in this pull request but the errors are a bit confusing to me:

15: # error: Access denied for user 'sha256user'@'172.18.0.1' (using password: YES)
 
15: # error: Access denied for user 'sha256user'@'172.18.0.1' (using password: YES)
 
15: not ok 23 - test_auth256

It looks like the mysql 5.7 and 8.0 versions of these tests are the only ones failing, but when I run it locally against 5.7.40 MYSQL server it passes for me.

Would you be able to take a look and let me know if this test passes without my changes?

Comment by Jacob Cossairt [ 2023-07-17 ]

Hi Georg, Just following up on the status of this. It would be great to get the changes from the other Jacob ( https://github.com/mariadb-corporation/mariadb-connector-c/pull/216 ) included in a future version.

Generated at Thu Feb 08 03:06:26 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.