MySQL Bugs: #103159: error log reports `Got error 203 when reading table` frequently

Bug #103159	error log reports `Got error 203 when reading table` frequently
Submitted:	31 Mar 2021 3:37	Modified:	30 Apr 2021 16:26
Reporter:	Brian Yue (OCA)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	MySQL8.0.22, 8.0.23	OS:	Any (rhel-7.4)
Assigned to:		CPU Architecture:	Any (intel x86-64)
Tags:	Contribution

Description:
Hello,
  Here when I execute a `select for update nowait` statement and failed to get an record lock, an ERROR log is printed in errlog, which may leads to too much disk space occupation. And also, this is a common sql failure, which should not be record into error log.
  Error log message like this: "[ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'".
  Please reference to `How to repeat` for details.

How to repeat:
[session A]

mysql> create database yxx;
Query OK, 1 row affected (0.21 sec)

mysql>
mysql> use yxx
Database changed
mysql> create table tt (id int primary key, age int);
Query OK, 0 rows affected (0.05 sec)

mysql> insert into tt values (1,1);
Query OK, 1 row affected (0.00 sec)

mysql> insert into tt values (2,2);
Query OK, 1 row affected (0.01 sec)

mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> select * from tt where id = 2 for update;
+----+------+
| id | age  |
+----+------+
|  2 |    2 |
+----+------+
1 row in set (0.00 sec)

[session B]

mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.
mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.
mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.
mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.
mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.
mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.
mysql> select * from yxx.tt where id = 2 for update nowait;
ERROR 3572 (HY000): Statement aborted because lock(s) could not be acquired immediately and NOWAIT is set.

[Now let's check the error log]

[yxxdb_8022@localhost ~]$ tail log/mysqld1.log
2021-03-25T10:11:25.086338+08:00 0 [System] [MY-010931] [Server] /home/yxxdb_8022/bin/mysqld: ready for connections. Version: '8.0.22'  socket: '/home/yxxdb_8022/bin/mysql1.sock'  port: 6314  Source distribution.
2021-03-31T09:34:58.223987+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
2021-03-31T09:34:59.048725+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
2021-03-31T09:34:59.706670+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
2021-03-31T09:35:00.282991+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
2021-03-31T09:35:00.925965+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
2021-03-31T09:35:01.544733+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
2021-03-31T09:35:02.233245+08:00 84 [ERROR] [MY-010211] [Server] Got error 203 when reading table './yxx/tt'
[yxxdb_8022@localhost ~]$

Suggested fix:
Don't print this ERROR message into error log of mysqld.

fix like this:

[yxx_git@zxin21 build]$ git diff
diff --git a/sql/sql_executor.cc b/sql/sql_executor.cc
index 0e1b64f..9f2eb8a 100644
--- a/sql/sql_executor.cc
+++ b/sql/sql_executor.cc
@@ -4128,6 +4128,7 @@ int report_handler_error(TABLE *table, int error) {
     Also skip printing to error log if the current thread has been killed.
   */
   if (error != HA_ERR_LOCK_DEADLOCK && error != HA_ERR_LOCK_WAIT_TIMEOUT &&
+      error != HA_ERR_NO_WAIT_LOCK &&
       error != HA_ERR_TABLE_DEF_CHANGED &&
 #ifdef HAVE_ZSQL_LOCK_DEPTH_LIMIT
          error != HA_ERR_TOO_MANY_LOCKS &&

Hello Brian Yue,

Thank you for the report and feedback.
Please ensure to re-send the patch via "Contribution" tab. Otherwise we would not be able to accept it.

regards,
Umesh

fix method of bug #103159 (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: bug_103159_contr.txt (text/plain), 461 bytes.

Documented fix as follows in the MySQL 8.0.26 changelog:

    Whenever a SELECT FOR UPDATE NOWAIT statement was unable to
    obtain a record lock, a message -Got error 203 when reading
    table ...- was written to the error log, even though though this
    is a relatively common occurrence, the logging of which led to
    excessive use of disk space.

    Our thanks to Brian Yue for this contribution.

Closed.