[Bug] MySQL 8 + nonexistent user sometimes results in auth plugin switch

[adrianna-chang-shopify]

See #41 and #42 for more context.

I had a bit more time to dig into this, and collected some data about what's going on. Since the context related to this bug is a bit spread out, I thought I'd open this issue to consolidate the information we have so far.

Background

Currently, we're skipping a test that's intended to test connection errors when we attempt to connect using a user account with insufficient privileges / a nonexistent user: https://github.com/adrianna-chang-shopify/trilogy/blob/b54138b188f19722d7f94614ae72064683e56276/contrib/ruby/test/client_test.rb#L533-L537

This test sometimes fails intermittently with:

1) Failure:
ClientTest#test_connection_error [/Users/adriannachang/src/github.com/trilogy/contrib/ruby/test/client_test.rb:536]:
[Trilogy::BaseConnectionError] exception expected, not
Class: <Trilogy::QueryError>
Message: <"trilogy_auth_recv: TRILOGY_PROTOCOL_VIOLATION">

on MySQL 8.0 (example CI build).

More Info

I added a couple of print statements to see what's going on:

diff --git a/contrib/ruby/test/client_test.rb b/contrib/ruby/test/client_test.rb
index 87ae5dc..7a47c0d 100644
--- a/contrib/ruby/test/client_test.rb
+++ b/contrib/ruby/test/client_test.rb
@@ -531,11 +531,12 @@ class ClientTest < TrilogyTest
   end
 
   def test_connection_error
-    skip("Test fails intermittently with TRILOGY_PROTOCOL_VIOLATION. See https://github.com/github/trilogy/pull/42")
-    err = assert_raises Trilogy::ConnectionError do
+    puts "--------------------- RUNNING TEST CONNECTION ERROR ---------------------"
+    err = assert_raises Trilogy::Error do
       new_tcp_client(username: "foo")
     end
 
+   puts "#{err.class}: #{err.message}"
     assert_includes err.message, "Access denied for user 'foo'"
   end

diff --git a/src/client.c b/src/client.c
index 9cdb923..8d65a42 100644
--- a/src/client.c
+++ b/src/client.c
@@ -250,6 +250,7 @@ static int read_eof_packet(trilogy_conn_t *conn)
 
 static int read_auth_switch_packet(trilogy_conn_t *conn, trilogy_handshake_t *handshake)
 {
+    printf("read_auth_switch_packet\n");
     trilogy_auth_switch_request_packet_t auth_switch_packet;
 
     int rc = trilogy_parse_auth_switch_request_packet(conn->packet_buffer.buff, conn->packet_buffer.len,
@@ -259,6 +260,8 @@ static int read_auth_switch_packet(trilogy_conn_t *conn, trilogy_handshake_t *ha
         return rc;
     }
 
+    printf("auth_switch_packet.auth_plugin: %s\n", auth_switch_packet.auth_plugin);
+
     if (strcmp("mysql_native_password", auth_switch_packet.auth_plugin) &&
         strcmp("caching_sha2_password", auth_switch_packet.auth_plugin)) {
         // Only support native password & caching sha2 password here.
@@ -426,14 +429,17 @@ int trilogy_auth_recv(trilogy_conn_t *conn, trilogy_handshake_t *handshake)
 
     switch (current_packet_type(conn)) {
     case TRILOGY_PACKET_OK:
+        printf("READ TRILOGY_PACKET_OK\n");
         trilogy_auth_clear_password(conn);
         return read_ok_packet(conn);
 
     case TRILOGY_PACKET_ERR:
+        printf("READ TRILOGY_PACKET_ERR\n");
         trilogy_auth_clear_password(conn);
         return read_err_packet(conn);
 
     case TRILOGY_PACKET_EOF:
+        printf("READ TRILOGY_PACKET_EOF\n");
         // EOF is returned here if an auth switch is requested.
         // We still need the password for the switch, it will be cleared
         // in a follow up call to this function after the switch.

Note that for all of these tests, I ran them using the CI dockerfiles, i.e. MYSQL_VERSION=5.7 DOCKERFILE=Dockerfile.test.buster script/cibuild and MYSQL_VERSION=8 DOCKERFILE=Dockerfile.test.buster script/cibuild

On MySQL5.7:

--------------------- RUNNING TEST CONNECTION ERROR ---------------------
READ TRILOGY_PACKET_ERR
Trilogy::BaseConnectionError: 1045: Access denied for user 'foo'@'192.168.16.3'(using password: NO)

TEST ALWAYS PASSES. It immediately reads a packet error, and we see ER_ACCESS_DENIED_ERROR and raise the corresponding BaseConnectionError.

On MySQL8.0:

Okay, so all sorts of different things can happen when we run the tests on MySQL8, even with the same seed. This issue is not meant to be diagnostic, simply to share what I observed.

Sometimes the test passes in the same way MySQL5.7 does:

--------------------- RUNNING TEST CONNECTION ERROR ---------------------
READ TRILOGY_PACKET_ERR
Trilogy::BaseConnectionError: 1045: Access denied for user 'foo'@'172.31.0.3' (using password: NO)

Sometimes the test passes, but with an attempted auth switch!

--------------------- RUNNING TEST CONNECTION ERROR ---------------------
READ TRILOGY_PACKET_EOF
read_auth_switch_packet
auth_switch_packet.auth_plugin: mysql_native_password
READ TRILOGY_PACKET_ERR
Trilogy::BaseConnectionError: 1045: Access denied for user 'foo'@'192.168.160.3' (using password: NO)

In this case, we performed an auth switch to mysql_native_password before seeing the access denied error.

The test fails with a protocol violation error if we attempt to perform an auth switch to the unsupported sha256_password (we raise here):

--------------------- RUNNING TEST CONNECTION ERROR ---------------------
READ TRILOGY_PACKET_EOF
read_auth_switch_packet
auth_switch_packet.auth_plugin: sha256_password
Trilogy::QueryError: trilogy_auth_recv: TRILOGY_PROTOCOL_VIOLATION

Other things I investigated

Setting the auth plugin default to mysql_native_password instead of MySQL8's caching_sha2_password:

diff --git a/docker-compose.yml b/docker-compose.yml
index f2e791c..7429638 100644
--- a/docker-compose.yml
+++ b/docker-compose.yml
@@ -8,6 +8,7 @@ services:
     - --gtid-mode=ON
     - --enforce-gtid-consistency=ON
     - --log-bin=mysql-bin.log
+    - --default-authentication-plugin=mysql_native_password
     environment:
       MYSQL_ALLOW_EMPTY_PASSWORD: 1
       MYSQL_DATABASE: test

Results:
Didn't make a difference, still sometimes attempted to switch to sha256_password (failure), and other times attempted to switch to caching_sha2_password (test succeeded with auth switch, and then access denied error).

Using the wrong password instead of a nonexistent user

  def test_connection_error
    puts "--------------------- RUNNING TEST CONNECTION ERROR ---------------------"
    err = assert_raises Trilogy::Error do
      new_tcp_client(username: "native", password: "wrong")
    end

    puts "#{err.class}: #{err.message}"
    assert_includes err.message, "Access denied for user 'native'"
  end

Results:
This always passes with the expected access denied error, and I never saw an attempted auth switch here.

However, if I do the same thing for root user, I get a TRILOGY_UNEXPECTED_PACKET error 🤷‍♀️

  def test_connection_error
    err = assert_raises Trilogy::ConnectionError do
      new_tcp_client(username: "root", password: "incorrect")
    end

    assert_includes err.message, "Access denied for user 'root'"
  end

  1) Failure:
ClientTest#test_connection_error [/Users/adriannachang/src/github.com/trilogy/contrib/ruby/test/client_test.rb:534]:
[Trilogy::ConnectionError] exception expected, not
Class: <Trilogy::QueryError>
Message: <"trilogy_auth_recv: TRILOGY_UNEXPECTED_PACKET">

Takeaways

• Still no idea what the bug is, but it seems to be specifically around reading an auth switch packet when we shouldn't be, on MySQL8. Is it possible that we shouldn't always interpret TRILOGY_PACKET_EOF as an auth switch here?
• I think that, instead of skipping the conn error test, we should change it to use an existing user accouont (e.g. native) and an incorrect password, because this should still produce an access denied err without the auth switch flakiness.

cc @composerinteralia @eileencodes @paarthmadan

[composerinteralia]

Nice digging!

Sometimes the test passes, but with an attempted auth switch!

Wild! I didn't realize that was an option too.

Is it possible that we shouldn't always interpret TRILOGY_PACKET_EOF as an auth switch

It's worth taking a look at what's in that packet to be sure. There's a warning in the docs about needing to check the length to make sure it's not actually some other packet that starts with an int<8>, but I am not seeing any connection-phase packets that start with an int<8> 🤷🏻‍♂️

https://dev.mysql.com/doc/dev/mysql-server/latest/page_protocol_basic_eof_packet.html

I think that, instead of skipping the conn error test, we should change it to use an existing user accouont (e.g. native) and an incorrect password, because this should still produce an access denied err without the auth switch flakiness.

👍🏻