commit 467e5e091f0bbe42fe60f3564019c1c67cdeb519 Author: Mattias Jonsson Date: Thu Dec 6 15:42:50 2018 +0100 Bug#93240 wait_timeout error not clear and not sent to client. The log entry for a client aborted due to wait_timeout exceeded is not clearly stated. So this creates a specific error for it. Also from the client perspective it only sees that the server closed the connection, not why, so the error will be sent back to the client before closing the connection. Notes: This patch does not work with YaSSL, since it does not clear its errors in report_errors() in debug build, and ERR_clear_error is not supported in release build. This results in write will fail on the previous non-cleared read error (from wait_timeout). Also debug build non-patched clients will fail an assertion, due to it only expects async returned result/error in case of COM_QUIT. And adding protection in net_read_packet like: /* Socket can't be used for reading */ if (net->error == 2 || net->error == 4) return packet_error; will make some rpl tests fail. diff --git a/include/mysql_com.h b/include/mysql_com.h index 9ce72fbaa19..bce391f4666 100644 --- a/include/mysql_com.h +++ b/include/mysql_com.h @@ -359,6 +359,13 @@ typedef struct st_net { */ unsigned char *unused; unsigned int last_errno; + /** + 1 - Error, but socket still usable + 2 - Error, do not use the socket + 3 - Not used, but will result in a recoverable error. + 4 - Read error, OK to try write the error and then close the socket. + 5 - Write error, OK to try read the error and then close the socket. + */ unsigned char error; my_bool unused4; /* Please remove with the next incompatible ABI change. */ my_bool unused5; /* Please remove with the next incompatible ABI change. */ diff --git a/mysql-test/r/ssl.result b/mysql-test/r/ssl.result index 27e2d57c0ef..b1b29536f68 100644 --- a/mysql-test/r/ssl.result +++ b/mysql-test/r/ssl.result @@ -2241,6 +2241,6 @@ Ssl_cipher SSL_CIPHER SET @@SESSION.wait_timeout = 2; # Wait for ssl_con to be disconnected. # Check that ssl_con has been disconnected. -# CR_SERVER_LOST, CR_SERVER_GONE_ERROR +# CR_SERVER_LOST, CR_SERVER_GONE_ERROR, ER_NET_WAIT_ERROR SELECT 1; Got one of the listed errors diff --git a/mysql-test/r/wait_timeout.result b/mysql-test/r/wait_timeout.result index c9e0d2c8ff9..42ca25153f9 100644 --- a/mysql-test/r/wait_timeout.result +++ b/mysql-test/r/wait_timeout.result @@ -9,7 +9,7 @@ SELECT 1; connection wait_con; connection default; SELECT 2; -Got one of the listed errors +ERROR 08S01: wait_timeout exceeded, too long idle time since last command --enable_reconnect; SELECT 3; 3 @@ -24,7 +24,7 @@ SELECT 1; connection wait_con; connection con1; SELECT 2; -Got one of the listed errors +ERROR 08S01: wait_timeout exceeded, too long idle time since last command --enable_reconnect; SELECT 3; 3 @@ -41,9 +41,25 @@ disconnection con1; SET @@SESSION.wait_timeout = 2; # Wait for con1 to be disconnected. # Check that con1 has been disconnected. -# CR_SERVER_LOST, CR_SERVER_GONE_ERROR SELECT 1; -Got one of the listed errors +ERROR 08S01: wait_timeout exceeded, too long idle time since last command +# +# Test UNIX domain sockets timeout with reconnect. +# +# Open con1 and set a timeout. +--enable_reconnect; +SET @is_old_connection = 1; +SELECT @is_old_connection; +@is_old_connection +1 +SET @@SESSION.wait_timeout = 2; +# Wait for con1 to be disconnected. +# Check that con1 has been reconnected. +SELECT "Unix domain socket will hit wait_timeout with reconnect"; +ERROR 08S01: wait_timeout exceeded, too long idle time since last command +SELECT @is_old_connection; +@is_old_connection +NULL # # Test TCP/IP sockets timeout. # @@ -51,6 +67,24 @@ Got one of the listed errors SET @@SESSION.wait_timeout = 2; # Wait for con1 to be disconnected. # Check that con1 has been disconnected. -# CR_SERVER_LOST, CR_SERVER_GONE_ERROR SELECT 1; +ERROR 08S01: wait_timeout exceeded, too long idle time since last command +SELECT "TCP/IP reconnect check"; Got one of the listed errors +# +# Test TCP/IP sockets timeout with reconnect. +# +# Open con1 and set a timeout. +--enable_reconnect; +SET @@SESSION.wait_timeout = 2; +SET @is_old_connection = 1; +SELECT @is_old_connection; +@is_old_connection +1 +# Wait for con1 to be disconnected. +# Check that con1 has been disconnected. +SELECT "TCP/IP will hit wait_timeout with reconnect"; +ERROR 08S01: wait_timeout exceeded, too long idle time since last command +SELECT @is_old_connection; +@is_old_connection +NULL diff --git a/mysql-test/t/ssl.test b/mysql-test/t/ssl.test index d1825bcabbb..d4457c07f2d 100644 --- a/mysql-test/t/ssl.test +++ b/mysql-test/t/ssl.test @@ -52,8 +52,8 @@ let $wait_condition= --echo # Check that ssl_con has been disconnected. connection ssl_con; ---echo # CR_SERVER_LOST, CR_SERVER_GONE_ERROR ---error 2006,2013 +--echo # CR_SERVER_LOST, CR_SERVER_GONE_ERROR, ER_NET_WAIT_ERROR +--error 2006,2013,ER_NET_WAIT_ERROR SELECT 1; connection default; diff --git a/mysql-test/t/wait_timeout.test b/mysql-test/t/wait_timeout.test index 229b0734ea9..46394588c40 100644 --- a/mysql-test/t/wait_timeout.test +++ b/mysql-test/t/wait_timeout.test @@ -66,8 +66,7 @@ let $wait_condition= SELECT COUNT(*)=1 FROM information_schema.processlist; connection default; # When the connection is closed in this way, the error code should # be consistent see Bug#2845 for an explanation -# depending on platform/client, either errno 2006 or 2013 can occur below ---error 2006,2013 +--error ER_NET_WAIT_ERROR SELECT 2; --echo --enable_reconnect; --enable_reconnect @@ -123,8 +122,7 @@ disconnect wait_con; connection con1; # When the connection is closed in this way, the error code should # be consistent see Bug#2845 for an explanation -# depending on platform/client, either errno 2006 or 2013 can occur below ---error 2006,2013 +--error ER_NET_WAIT_ERROR SELECT 2; --echo --enable_reconnect; --enable_reconnect @@ -161,13 +159,45 @@ let $wait_condition= --echo # Check that con1 has been disconnected. connection con1; ---echo # CR_SERVER_LOST, CR_SERVER_GONE_ERROR ---error 2006,2013 +--error ER_NET_WAIT_ERROR SELECT 1; disconnect con1; connection default; +--echo # +--echo # Test UNIX domain sockets timeout with reconnect. +--echo # + +--echo # Open con1 and set a timeout. +connect(con1,localhost,root,,); + +--echo --enable_reconnect; +--enable_reconnect +SET @is_old_connection = 1; +SELECT @is_old_connection; + +LET $ID= `SELECT connection_id()`; +SET @@SESSION.wait_timeout = 2; + +--echo # Wait for con1 to be disconnected. +connection default; +let $wait_condition= + SELECT COUNT(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE ID = $ID; +--source include/wait_condition.inc + +--echo # Check that con1 has been reconnected. +connection con1; +--error ER_NET_WAIT_ERROR +SELECT "Unix domain socket will hit wait_timeout with reconnect"; + +SELECT @is_old_connection; + +disconnect con1; +connection default; + + --echo # --echo # Test TCP/IP sockets timeout. --echo # @@ -187,10 +217,48 @@ let $wait_condition= --echo # Check that con1 has been disconnected. connection con1; ---echo # CR_SERVER_LOST, CR_SERVER_GONE_ERROR ---error 2006,2013 +--error ER_NET_WAIT_ERROR SELECT 1; +# depending on platform/client, either errno 2006 or 2013 can occur below +--error 2006,2013 +SELECT "TCP/IP reconnect check"; + +disconnect con1; +connection default; + + + +--echo # +--echo # Test TCP/IP sockets timeout with reconnect. +--echo # + +--echo # Open con1 and set a timeout. +connect(con1,127.0.0.1,root,,); + +--echo --enable_reconnect; +--enable_reconnect +LET $ID= `SELECT connection_id()`; +SET @@SESSION.wait_timeout = 2; +SET @is_old_connection = 1; +SELECT @is_old_connection; + +--echo # Wait for con1 to be disconnected. +connection default; +let $wait_condition= + SELECT COUNT(*) = 0 FROM INFORMATION_SCHEMA.PROCESSLIST + WHERE ID = $ID; +--source include/wait_condition.inc + +--echo # Check that con1 has been disconnected. +connection con1; +# TODO: Investigate why no error with updated client and old server? +# Expected: https://dev.mysql.com/doc/refman/5.7/en/c-api-auto-reconnect.html +--error ER_NET_WAIT_ERROR +SELECT "TCP/IP will hit wait_timeout with reconnect"; + +SELECT @is_old_connection; + disconnect con1; connection default; diff --git a/sql-common/client.c b/sql-common/client.c index 67e980e4e11..f0a0ecb68c5 100644 --- a/sql-common/client.c +++ b/sql-common/client.c @@ -1232,12 +1232,13 @@ cli_advanced_command(MYSQL *mysql, enum enum_server_command command, mysql->info=0; mysql->affected_rows= ~(my_ulonglong) 0; /* - Do not check the socket/protocol buffer on COM_QUIT as the - result of a previous command might not have been read. This - can happen if a client sends a query but does not reap the - result before attempting to close the connection. + Do not check the socket/protocol buffer as the + result/error/timeout of a previous command might not have been read. + This can happen if a client sends a query but does not reap the result + before attempting to close the connection or wait_timeout occurs on + the server. */ - net_clear(&mysql->net, (command != COM_QUIT)); + net_clear(net, 0); MYSQL_TRACE_STAGE(mysql, READY_FOR_COMMAND); MYSQL_TRACE(SEND_COMMAND, mysql, (command, header_length, arg_length, header, arg)); @@ -1266,6 +1267,24 @@ cli_advanced_command(MYSQL *mysql, enum enum_server_command command, set_mysql_error(mysql, CR_NET_PACKET_TOO_LARGE, unknown_sqlstate); goto end; } + if (net->last_errno == ER_NET_ERROR_ON_WRITE) { + /* + Write error, try to read and see if the server gave an error + before closing the connection. Most likely Unix Domain Socket. + */ + if (net->vio) { + my_net_set_read_timeout(net, 0); + /* + cli_safe_read will also set error variables in net, + and we are already in error state. + */ + if (cli_safe_read(mysql, NULL) == packet_error) { + goto end; + } + /* Can this happen in any other case than COM_QUIT? */ + DBUG_ASSERT(command == COM_QUIT); + } + } end_server(mysql); if (mysql_reconnect(mysql) || stmt_skip) goto end; @@ -4978,7 +4997,8 @@ my_bool mysql_reconnect(MYSQL *mysql) { /* Allow reconnect next time */ mysql->server_status&= ~SERVER_STATUS_IN_TRANS; - set_mysql_error(mysql, CR_SERVER_GONE_ERROR, unknown_sqlstate); + if (mysql->net.last_errno == 0) + set_mysql_error(mysql, CR_SERVER_GONE_ERROR, unknown_sqlstate); DBUG_RETURN(1); } mysql_init(&tmp_mysql); diff --git a/sql/net_serv.cc b/sql/net_serv.cc index a6bc8570f2e..328932fbbfa 100644 --- a/sql/net_serv.cc +++ b/sql/net_serv.cc @@ -150,7 +150,7 @@ my_bool net_realloc(NET *net, size_t length) { DBUG_PRINT("error", ("Packet too large. Max size: %lu", net->max_packet_size)); - /* @todo: 1 and 2 codes are identical. */ + /* Error, but no need to stop using the socket. */ net->error= 1; net->last_errno= ER_NET_PACKET_TOO_LARGE; #ifdef MYSQL_SERVER @@ -170,7 +170,7 @@ my_bool net_realloc(NET *net, size_t length) NET_HEADER_SIZE + COMP_HEADER_SIZE, MYF(MY_WME)))) { - /* @todo: 1 and 2 codes are identical. */ + /* Error, but no need to stop using the socket. */ net->error= 1; net->last_errno= ER_OUT_OF_RESOURCES; /* In the server the error is reported by MY_WME flag. */ @@ -519,8 +519,22 @@ net_write_raw_loop(NET *net, const uchar *buf, size_t count) /* On failure, propagate the error code. */ if (count) { +#ifdef MYSQL_SERVER /* Socket should be closed. */ net->error= 2; +#else + /* Socket should be closed after trying to read. */ + net->error= 5; +# ifdef HAVE_YASSL + /* + YaSSL does not reset errors, so write after failed read also fails. + See lack of support for ERR_clear_error() in YaSSL. + So fall back to pre bug#93240 behavior for YaSSL. + */ + if (vio_type(net->vio) == VIO_TYPE_SSL) + net->error= 2; +# endif +#endif /* Interrupted by a timeout? */ if (vio_was_timeout(net->vio)) @@ -611,8 +625,8 @@ net_write_packet(NET *net, const uchar *packet, size_t length) query_cache_insert((char*) packet, length, net->pkt_nr); #endif - /* Socket can't be used */ - if (net->error == 2) + /* Socket can't be used for writing */ + if (net->error == 2 || net->error == 5) DBUG_RETURN(TRUE); net->reading_or_writing= 2; @@ -645,6 +659,11 @@ net_write_packet(NET *net, const uchar *packet, size_t length) net->reading_or_writing= 0; + /* Socket can't be used any more */ + if (net->error == 4) { + net->error= 2; + DBUG_RETURN(TRUE); + } DBUG_RETURN(res); } @@ -697,9 +716,6 @@ static my_bool net_read_raw_loop(NET *net, size_t count) /* On failure, propagate the error code. */ if (count) { - /* Socket should be closed. */ - net->error= 2; - /* Interrupted by a timeout? */ if (!eof && vio_was_timeout(net->vio)) net->last_errno= ER_NET_READ_INTERRUPTED; @@ -707,7 +723,24 @@ static my_bool net_read_raw_loop(NET *net, size_t count) net->last_errno= ER_NET_READ_ERROR; #ifdef MYSQL_SERVER + /* First packet always wait for net_wait_timeout */ + if (net->pkt_nr == 0 && vio_was_timeout(net->vio)) + net->last_errno= ER_NET_WAIT_ERROR; + /* Socket should be closed after trying to write/send error. */ + net->error= 4; +#ifdef HAVE_YASSL + /* + YaSSL does not reset errors, so write after failed read also fails. + See lack of support for ERR_clear_error() in YaSSL. + So fall back to pre bug#93240 behavior for YaSSL. + */ + if (vio_type(net->vio) == VIO_TYPE_SSL) + net->error= 2; +#endif my_error(net->last_errno, MYF(0)); +#else + /* Socket should be closed. */ + net->error= 2; #endif } @@ -775,7 +808,27 @@ static my_bool net_read_packet_header(NET *net) */ if (pkt_nr != (uchar) net->pkt_nr) { - /* Not a NET error on the client. XXX: why? */ +#if ! defined(MYSQL_SERVER) + DBUG_PRINT("info", ("pkt_nr %u net->pkt_nr %u", pkt_nr, net->pkt_nr)); + if (net->pkt_nr == 1) { + DBUG_ASSERT(net->where_b == 0); + /* + Server may have sent an error before it received our new command. + Perhaps due to wait_timeout. + Only use what is already read and then close the socket. + */ + net->error= 2; + net->last_errno= ER_NET_PACKETS_OUT_OF_ORDER; + net->pkt_nr= pkt_nr + 1; + + /* + The caller should handle the error code in the packet + and the socket are blocked from further usage, + so reading the packet header was OK. + */ + return FALSE; + } +#endif #if defined(MYSQL_SERVER) my_error(ER_NET_PACKETS_OUT_OF_ORDER, MYF(0)); #elif defined(EXTRA_DEBUG) @@ -860,10 +913,14 @@ static size_t net_read_packet(NET *net, size_t *complen) goto error; end: + if (net->error == 5) + net->error= 2; net->reading_or_writing= 0; return pkt_len; error: + if (net->error == 5) + net->error= 2; net->reading_or_writing= 0; return packet_error; } diff --git a/sql/share/errmsg-utf8.txt b/sql/share/errmsg-utf8.txt index 33b8850b1cd..99da84f2192 100644 --- a/sql/share/errmsg-utf8.txt +++ b/sql/share/errmsg-utf8.txt @@ -7774,6 +7774,9 @@ ER_XA_REPLICATION_FILTERS ER_CANT_OPEN_ERROR_LOG eng "Could not open file '%s' for error logging%s%s" +ER_NET_WAIT_ERROR 08S01 + eng "wait_timeout exceeded, too long idle time since last command" + # # End of 5.7 error messages. #