[MDEV-27952] Improve error log messages with descriptive text already present in the code Created: 2022-02-25  Updated: 2024-01-30

Status: Open
Project: MariaDB Server
Component/s: Server
Fix Version/s: None

Type: Task Priority: Major
Reporter: Roel Van de Paar Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: affects-tests, beginner-friendly


 Description   

It would be great if we could improve the quality of some or all error messages.

For example:

CREATE TABLE t (i INT KEY);
ALTER TABLE t DISCARD TABLESPACE;
SELECT * FROM t;

Will lead to (in the CLI):

10.9.0 b5852ffbeebc3000982988383daeefb0549e058a (Debug)

10.9.0-dbg>SELECT * FROM t;
ERROR 1814 (HY000): Tablespace has been discarded for table `t`

Which is sufficiently clear to understand what is happening, or at least to get a good hint in the case where the SELECT happens much later than the DISCARD TABLESPACE.

However, the error log is much more cryptic:

10.9.0 b5852ffbeebc3000982988383daeefb0549e058a (Debug)

2022-02-26  8:11:50 0 [Note] /test/MD140222-mariadb-10.9.0-linux-x86_64-dbg/bin/mysqld: ready for connections.
Version: '10.9.0-MariaDB-debug'  socket: '/test/MD140222-mariadb-10.9.0-linux-x86_64-dbg/socket.sock'  port: 27815  MariaDB Server
2022-02-26  8:12:08 6 [ERROR] Got error 194 when reading table './test/t'

Sysadmins would have to use the bin/perror tool (if they know it exists), or search online, to find out what is happening. We can save them from having to take this extra and unnecessary step by automating (and improving) the error to message step:

Proposed Output

2022-02-26  8:12:08 6 [ERROR] Got error 194 when reading table './test/t' (Tablespace is missing for a table)

It would seem that this is low hanging fruit and a feature easy to implement.



 Comments   
Comment by Roel Van de Paar [ 2022-03-12 ]

Another example

CREATE TABLE t1(a CHAR) ENGINE=InnoDB;
BINLOG ' O1ZVRw8BAAAAZgAAAGoAAAAAAAQANS4xLjIzLXJjLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAA7VlVHEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC ';  # Table_map
BINLOG 'wlZOTxMBAAAAKgAAADwCAAAAACkAAAAAAAEABHRlc3QAAnQxAAIDAwAC wlZOTxcBAAAAJgAAAGICAAAAACkAAAAAAAEAAv/8AgAAAAgAAAA=';  # Format description

Whilst not commonly used SQL at the CLI, it highlights the issue well. At the CLI this gives:

10.9.0 4a2a9c02cd6611ef36bbb735c2b483dbc83580d4 (Debug)

10.9.0-dbg>BINLOG 'wlZOTxMBAAAAKgAAADwCAAAAACkAAAAAAAEABHRlc3QAAnQxAAIDAwAC wlZOTxcBAAAAJgAAAGICAAAAACkAAAAAAAEAAv/8AgAAAAgAAAA=';  # Format description
ERROR 1105 (HY000): Unknown error

Which is cryptic at best. However the error log clearly explains the issue:

10.9.0 4a2a9c02cd6611ef36bbb735c2b483dbc83580d4 (Debug)

2022-03-12 16:02:49 4 [ERROR]  BINLOG_BASE64_EVENT: Column 0 of table 'test.t1' cannot be converted from type 'int' to type 'char(1 octets) character set latin1', Internal MariaDB error code: 1677

Interestingly, there is another error code here too. Elkin fyi in case that's a bug.

Comment by Roel Van de Paar [ 2022-04-09 ]

Similar to the last example (same output):

BINLOG 'wlZOTw8BAAAA8QAAAPUAAAAAAAQANS41LjIxLU1hcmlhREItZGVidWctbG9nAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAEzgNAAgAEgAEBAQEEgAA2QAEGggAAAAICAgCAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAA371saA==';
CREATE TABLE t1(a INT KEY,b CHAR (1));
BINLOG 'wlZOTxMBAAAAKgAAAGMBAAAAgCkAAAAAAAEABHRlc3QAAnQxAAIDAwAC wlZOTxcBAAAAJgAAAIkBAAAAgCkAAAAAAAEAAv/8AQAAAAgAAAA=';

Comment by Roel Van de Paar [ 2023-03-25 ]

Please also try this testcase against any bug fix

CREATE TABLE t (c INT) ENGINE=InnoDB;
ALTER TABLE t DISCARD TABLESPACE;
ALTER TABLE t ADD INDEX (c);
SELECT * FROM t;

Comment by Zhibo Zhang [ 2023-06-15 ]

investigating it

Comment by Zhibo Zhang [ 2023-06-19 ]

The error message for the example given in the body part of this Jira is already informative: https://github.com/MariaDB/server/blob/3883eb63dc5e663558571c33d086c9fd3aa0cf8f/storage/innobase/dict/dict0load.cc#L2234

Comment by Zhibo Zhang [ 2023-06-19 ]

Execution result in the database:

{{Welcome to the MariaDB monitor. Commands end with ; or \g.
Your MariaDB connection id is 4
Server version: 11.1.2-MariaDB Source distribution

Copyright (c) 2000, 2018, Oracle, MariaDB Corporation Ab and others.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

MariaDB [(none)]> show databases;
--------------------

Database

--------------------

information_schema

--------------------
1 row in set (0.000 sec)

MariaDB [(none)]> create database zhibo;
Query OK, 1 row affected (0.001 sec)

MariaDB [(none)]> use zhibo;
Database changed
MariaDB [zhibo]> CREATE TABLE t (i INT KEY);
Query OK, 0 rows affected (0.007 sec)

MariaDB [zhibo]> ALTER TABLE t DISCARD TABLESPACE;
Query OK, 0 rows affected (0.002 sec)

MariaDB [zhibo]> SELECT * FROM t;
ERROR 1814 (HY000): Tablespace has been discarded for table `t`}}

According error log:

2023-06-19 15:11:10 3 [Warning] InnoDB: Tablespace for table `zhibo`.`t` is set as discarded.

Comment by Zhibo Zhang [ 2023-06-19 ]

Reproduction of the second case mentioned in the comments:

```
MariaDB [test]> CREATE TABLE t1(a CHAR) ENGINE=InnoDB;
Query OK, 0 rows affected (0.007 sec)

MariaDB [test]> BINLOG ' O1ZVRw8BAAAAZgAAAGoAAAAAAAQANS4xLjIzLXJjLWRlYnVnLWxvZwAAAAAAAAAAAAAAAAAAAAAA AAAAAAAAAAAAAAAAAAA7VlVHEzgNAAgAEgAEBAQEEgAAUwAEGggAAAAICAgC '; # Table_map
Query OK, 0 rows affected (0.000 sec)

MariaDB [test]> BINLOG 'wlZOTxMBAAAAKgAAADwCAAAAACkAAAAAAAEABHRlc3QAAnQxAAIDAwAC wlZOTxcBAAAAJgAAAGICAAAAACkAAAAAAAEAAv/8AgAAAAgAAAA='; # Format description
ERROR 1105 (HY000): Unknown error
```

In the error log:
2023-06-19 16:47:06 5 [ERROR] BINLOG_BASE64_EVENT: Column 0 of table 'test.t1' cannot be converted from type 'int' to type 'char(1 octets) character set latin1', Internal MariaDB error code: 1677

Comment by Roel Van de Paar [ 2023-06-28 ]

zhibozhang You can use {noformat} tags in JIRA.

Comment by Roel Van de Paar [ 2023-06-28 ]

In 11.1.2 rev 3883eb63dc5e663558571c33d086c9fd3aa0cf8f the Got error 194 seen with the original testcase is confirmed gone. However, the error remains for this testcase:

CREATE TABLE t (c INT) ENGINE=InnoDB;
ALTER TABLE t DISCARD TABLESPACE;
ALTER TABLE t ADD INDEX (c);
SELECT * FROM t;

Leads to:

11.1.2 3883eb63dc5e663558571c33d086c9fd3aa0cf8f (Debug)

2023-06-28 12:34:03 4 [ERROR] Got error 194 when reading table './test/t'

Which now makes me wonder if there is another issue/error at play here.

Comment by Zhibo Zhang [ 2023-12-06 ]

The place where error code 194 is defined https://github.com/MariaDB/server/blob/1a5e69b42b4ff0a3fd4585f1463adf01127241cd/include/my_base.h#L533

Comment by Zhibo Zhang [ 2024-01-30 ]

Error code 194 uses a default error message as shown in https://github.com/MariaDB/server/blob/d039346a7acac7c72f264377a8cd6b0273c548df/sql/unireg.h#L53

Comment by Zhibo Zhang [ 2024-01-30 ]

We need to replace the default error message with a customized error message for error code 194 in this line https://github.com/MariaDB/server/blob/b0e77c08e55c433e443a2cfbcb7315dd6f006b3e/sql/handler.cc#L498

Generated at Thu Feb 08 09:56:53 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.