MariaDB server times out client connection after 600 seconds

Question

My MariaDB server is timing out my C++ client (using libmariadb) after 600 seconds (10 minutes) of inactivity, and I'm not sure why, because I can't find any configured timeouts that specify that number.

Here's my code, where I execute a simple SELECT query, wait 11 minutes, then run that same query again and get a "server gone" error:

#include <iostream>
#include <unistd.h>

#include <errmsg.h>
#include <mysql.h>

int main(int, char**)
{
    // connect to the database
    MYSQL* connection = mysql_init(NULL);
    my_bool reconnect = 0;
    mysql_options(connection, MYSQL_OPT_RECONNECT, &reconnect);  // don't implicitly reconnect
    mysql_real_connect(connection, "127.0.0.1", "testuser", "password",
                       "my_test_db", 3306, NULL, 0);

    // run a simple query
    mysql_query(connection, "select 5");
    mysql_free_result(mysql_store_result(connection));
    std::cout << "First query done...\n";

    // sleep for 11 minutes
    sleep(660);

    // run the query again
    if(! mysql_query(connection, "select 5"))
    {
        std::cout << "Second query succeeded after " << seconds << " seconds\n";
        mysql_free_result(mysql_store_result(connection));
    }
    else
    {
        if(mysql_errno(connection) == CR_SERVER_GONE_ERROR)
        {
            // **** this happens every time ****
            std::cout << "Server went away after " << seconds << " seconds\n";
        }
    }

    // close the connection
    mysql_close(connection);
    connection = nullptr;

    return 0;
}

The stdout of the server process reports that it timed out my connection:

$ sudo journalctl -u mariadb
...
Jul 24 17:58:31 myhost mysqld[407]: 2018-07-24 17:58:31 139667452651264 [Warning] Aborted connection 222 to db: 'my_test_db' user: 'testuser' host: 'localhost' (Got timeout reading communication packets)
...

Looking at a tcpdump capture, I can also see the server sending the client a TCP FIN packet, which closes the connection.

The reason I'm stumped is because I haven't changed any of the default timeout values, none of which are even 600 seconds:

MariaDB [(none)]> show variables like '%timeout%';
+-------------------------------------+----------+
| Variable_name                       | Value    |
+-------------------------------------+----------+
| connect_timeout                     | 10       |
| deadlock_timeout_long               | 50000000 |
| deadlock_timeout_short              | 10000    |
| delayed_insert_timeout              | 300      |
| innodb_flush_log_at_timeout         | 1        |
| innodb_lock_wait_timeout            | 50       |
| innodb_print_lock_wait_timeout_info | OFF      |
| innodb_rollback_on_timeout          | OFF      |
| interactive_timeout                 | 28800    |
| lock_wait_timeout                   | 31536000 |
| net_read_timeout                    | 30       |
| net_write_timeout                   | 60       |
| slave_net_timeout                   | 3600     |
| thread_pool_idle_timeout            | 60       |
| wait_timeout                        | 28800    |
+-------------------------------------+----------+

So why is the server timing out my connection? Based on the documentation, I would have thought it would have been because of the wait_timeout server variable, but it's left at the default of 8 hours...

BTW I'm using MariaDB 10.0 and libmariadb 2.0 (from the Ubuntu Xenial Universe repo)

---

Edit: here's an image of a tcpdump capture catching the disconnect. My Wireshark filter is tcp.port == 55916, so I'm looking at traffic to/from this one client connection. The FIN packet that the server sends is packet 1199, exactly 600 seconds after the previous packet (884).

Solution 1

wait_timeout is tricky. From the same connection do

SHOW SESSION VARIABLES LIKE '%timeout%';
SHOW SESSION VARIABLES WHERE VALUE BETWEEN 500 AND 700;

You should be able to workaround the issue by executing

mysql_query("SET @@wait_timeout = 22222");

Are you connected as 'root' or not?

More connector details:

See: https://dev.mysql.com/doc/refman/5.5/en/mysql-options.html

CLIENT_INTERACTIVE: Permit interactive_timeout seconds of inactivity (rather than wait_timeout seconds) before closing the connection. The client's session wait_timeout variable is set to the value of the session interactive_timeout variable.

https://dev.mysql.com/doc/relnotes/connector-cpp/en/news-1-1-5.html (MySQL Connector/C++ 1.1.5)

It is also possible to get and set the statement execution-time limit using the MySQL_Statement::getQueryTimeout() and MySQL_Statement::setQueryTimeout() methods.

There may also be a TCP/IP timeout.

Solution 2

I'm not sure about the exact reason. But I'm sure wait_timeout is not the only thing which has an effect on this. According to the only error message you have included in your question, it seems like there was a problem reading the packet.

Got timeout reading communication packets

I believe it was more like MariaDB had an issue reading the packet rather than attempting to connect or so. I also had a look at the MariaDB client library, and found this block;

if (ma_net_write_command(net,(uchar) command,arg,
            length ? length : (ulong) strlen(arg), 0))
  {
    if (net->last_errno == ER_NET_PACKET_TOO_LARGE)
    {
      my_set_error(mysql, CR_NET_PACKET_TOO_LARGE, SQLSTATE_UNKNOWN, 0);
      goto end;
    }
    end_server(mysql);
    if (mariadb_reconnect(mysql))
      goto end;
    if (ma_net_write_command(net,(uchar) command,arg,
              length ? length : (ulong) strlen(arg), 0))
    {
      my_set_error(mysql, CR_SERVER_GONE_ERROR, SQLSTATE_UNKNOWN, 0);
      goto end;
    }
}

https://github.com/MariaDB/mariadb-connector-c/blob/master/libmariadb/mariadb_lib.c

So it seems like it sets the error code to server gone away when it get a packet size issue. I suggest you to change the max_allowed_packet variable to some large value and see whether it has any effect.

SET @@global.max_allowed_packet = <some large value>;

https://mariadb.com/kb/en/library/server-system-variables/#max_allowed_packet

I hope it will help, or at least it will set you in some path to solve the problem :) and finally, I think you should handle the disconnects in your code rather than relying on the timeouts.

Comments

[Nimeshka Srimal]

Is there anything in the logs?

[villapx]

Unfortunately no, none of the server's log files have even been updated in the last day (I just ran this code like an hour ago). The timestamps are all yesterday. What are some ways I can turn up the server's logging verbosity?

[villapx]

I'm not connected as 'root'; when I did the SHOW SESSION VARIABLES statement, I was connected as the same user that my C++ application connects as. Running SHOW SESSION VARIABLES WHERE VALUE BETWEEN 500 AND 700 gives me: aria_pagecache_file_hash_size = 512, innodb_fatal_semaphore_wait_threshold = 600, key_cache_file_hash_size = 512 and thread_pool_stall_limit = 500. I'll look at those variables in the docs, see what I find

[villapx]

Thanks for the response. See my edit - I don't think it has to do with max packet size, since there aren't even any packets being sent. The last MySQL-specific packet sent was a MySQL Response OK packet, whose length was only 118 bytes, obviously much smaller than the default max_allowed_packet value of 16777216 bytes

[Nimeshka Srimal]

@villapx I think queries are sent as packets. Can you try to change it and see if it has any effect?

[villapx]

Wow, nice catch! I just did as you suggested, SHOW SESSION VARIABLES LIKE '%timeout%' from that same connection, and it showed wait_timeout = 600! So now, I'm curious why that's happening? Any ideas?

[Rick James]

I added some references. But they tend to provide workarounds, not explanations.

[villapx]

Indeed, it was the wait_timeout. I was stumped because on my interactive sessions, wait_timeout was 28800, but it was 600 in my non-interactive sessions. I did a grep -rn wait_timeout /etc/mysql/, and sure enough, there's a config entry [mysqld] wait_timeout = 600 in /etc/mysql/my.cnf. Per that documentation section you cited, the wait_timeout variable is set to the value of interactive_timeout when you're in an interactive session, hence the behavior I was seeing in the mysql interactive client. You're a lifesaver

[villapx]

I did try setting it to 256MB (268435456 bytes), and that didn't have any effect. It turned out it did have to do with wait_timeout, and I was unclear on why wait_timeout was showing up as a different value in my interactive mysql client session

[chb]

To improve legibility, please format your answer using the Markdown available to you.