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).

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, Jul 24 '18 at 20:03

Rick James · Accepted Answer · 2018-07-25T15:07:09.367

6

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.

edited Jul 25 '18 at 15:07

answered Jul 24 '18 at 22:10

Rick James

135,179
13
127
222

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 Jul 25 '18 at 13:31
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? – villapx Jul 25 '18 at 13:53
I added some references. But they tend to provide workarounds, not explanations. – Rick James Jul 25 '18 at 15:09
1

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 Jul 25 '18 at 19:15

score 1 · Answer 2 · answered Jul 25 '18 at 05:27

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.

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 — villapx, Jul 25 '18 at 13:42
@villapx I think queries are sent as packets. Can you try to change it and see if it has any effect? — Nimeshka Srimal, Jul 25 '18 at 13:52
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 — villapx, Jul 25 '18 at 19:17

score 0 · Answer 3 · edited Jan 13 '20 at 12:21

0

Galera cluster with Haproxy Load balancing. Change this parameter on haproxy settings

defaults
    timeout connect 10s
    timeout client 30s
    timeout server 30s

edited Jan 13 '20 at 12:21

William R

37
12

answered May 30 '19 at 05:15

Isahak Ali

1

To improve legibility, please format your answer using the Markdown available to you. – chb May 30 '19 at 05:33

MariaDB server times out client connection after 600 seconds

3 Answers3

Linked