[MDEV-7775] Wrong error message (Unknown error) when idle sessions are killed after wait_timeout Created: 2015-03-13  Updated: 2016-04-26  Resolved: 2016-04-26

Status: Closed
Project: MariaDB Server
Component/s: OTHER
Affects Version/s: 5.5, 10.0, 10.1
Fix Version/s: 5.5.50, 10.0.25, 10.1.14

Type: Bug Priority: Major
Reporter: Joffrey MICHAIE (Inactive) Assignee: Sergei Golubchik
Resolution: Fixed Votes: 2
Labels: verified

Sprint: 10.0.25

 Description   

Hi,

my server has wait_timeout set to 28800 seconds (8 hours).

Looking at my sessions idling ...

MariaDB [(none)]> select * FROM INFORMATION_SCHEMA.PROCESSLIST ORDER BY TIME DESC LIMIT 10;
 
+-------+-------------+----------------------+--------------+---------+-------+--------------------+------+--------------+-------+-----------+----------+-------------+---------------+----------+
 
| ID    | USER        | HOST                 | DB           | COMMAND | TIME  | STATE              | INFO | TIME_MS      | STAGE | MAX_STAGE | PROGRESS | MEMORY_USED | EXAMINED_ROWS | QUERY_ID |
 
+-------+-------------+----------------------+--------------+---------+-------+--------------------+------+--------------+-------+-----------+----------+-------------+---------------+----------+
 
|     2 | system user |                      | NULL         | Sleep   | 43731 | NULL               | NULL | 43731770.086 |     0 |         0 |    0.000 |       35296 |             0 |        0 |
 
|     1 | system user |                      | NULL         | Sleep   | 43731 | wsrep aborter idle | NULL | 43731770.096 |     0 |         0 |    0.000 |       35296 |             0 |        0 |
 
(...)
 
| 73945 | webapp-xx   | 205.xxx.xx.xxx:12345 | database_name | Sleep   | 28590 |                    | NULL | 28590778.291 |     0 |         0 |    0.000 |       50640 |             0 |  8197323 |
 
 
 
(...)

Then in the log, I can see:

150313 11:18:20 [Warning] Aborted connection 73645 to db: 'database_name user: 'webapp-xx' host: '205.xxx.xx.xxx' (Unknown error)

I think the error message should be more explicit, such as "connection closed due to wait_timeout limit reached".

To reproduce, start mariadb server, with --log_warnings=2, set wait_timeout, and let application session idle until the timeout, then look at error log.

Thanks,
Joffrey

 Comments   
Comment by Elena Stepanova [ 2015-03-16 ]

It is actually a regression. We used to have a proper message in 5.1-5.3, but lost it in 5.5 and higher. MySQL 5.5 produces the correct message.

5.3

 
[Warning] Aborted connection 2 to db: 'test' user: 'root' host: 'localhost' (Got timeout reading communication packets)

5.5

 
[Warning] Aborted connection 2 to db: 'test' user: 'root' host: 'localhost' (Unknown error)

Comment by Peter (Stig) Edwards [ 2016-03-04 ]

I think this commit introduced the change in behaviour:
https://github.com/MariaDB/server/commit/ec38c1bbd709da99fb84e2889f4443247fccfb30
in sql/sql_connect.cc in end_connection, I think that maybe

  thd->print_aborted_warning(1, ER(ER_UNKNOWN_ERROR));

could be:

  thd->print_aborted_warning(1, (thd->stmt_da->is_error() ? thd->stmt_da->message() : ER(ER_UNKNOWN_ERROR));

Thanks.

Comment by Sergei Golubchik [ 2016-04-22 ]

thatsafunnyname, thanks for the fix!

Comment by Peter (Stig) Edwards [ 2016-04-22 ]

Thanks for fixing and adding the test.
https://github.com/MariaDB/server/commit/6bc07728cf09cd0d810c05cfa031a78b4e0057bc

Generated at Thu Feb 08 07:22:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.