Bug #98220 with log_slow_extra=on Errno: info not getting updated correctly for error
Submitted: 14 Jan 2020 9:29 Modified: 22 Jan 2021 19:11
Reporter: lalit Choudhary Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:8.0.19 OS:Any
Assigned to: CPU Architecture:Any
Tags: log_slow_extra, slow_query_log

[14 Jan 2020 9:29] lalit Choudhary
Description:
https://dev.mysql.com/doc/refman/8.0/en/server-system-variables.html#sysvar_log_slow_extra
Enabling the log_slow_extra system variable (available as of MySQL 8.0.14) causes the server to write the following extra fields to FILE output

as per the documentation,

Errno: error_number
The statement error number, or 0 if no error occurred.

In a test, I found that even if SQL query fails with error in the slow query log Errno: has '0' value.

How to repeat:
ps 8.0.17

log_slow_extra=on

mysql [localhost] {msandbox} (test) > create table a(d decimal(4,2));
Query OK, 0 rows affected (0.06 sec)

mysql [localhost] {msandbox} (test) > create table b(as invalid);
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'as invalid)' at line 1

# Time: 2020-01-14T09:08:50.703939Z
# User@Host: msandbox[msandbox] @ localhost []  Id:     8
# Query_time: 0.063812  Lock_time: 0.000490 Rows_sent: 0  Rows_examined: 0 Thread_id: 8 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 11 Read_first: 0 Read_last: 0 Read_key: 18 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2020-01-14T09:08:50.640127Z End: 2020-01-14T09:08:50.703939Z Schema: test Rows_affected: 0
SET timestamp=1578992930;
create table a(d decimal(4,2));

# Time: 2020-01-14T09:09:32.811641Z
# User@Host: msandbox[msandbox] @ localhost []  Id:     8
# Query_time: 0.000096  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0 Thread_id: 8 Errno: 0 Killed: 0 Bytes_received: 0 Bytes_sent: 170 Read_first: 0 Read_last: 0 Read_key: 0 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2020-01-14T09:09:32.811545Z End: 2020-01-14T09:09:32.811641Z Schema: test Rows_affected: 0
SET timestamp=1578992972;
create table b(as invalid);

Suggested fix:
Expected behavior: Errno field should have an error number for a failed query with an error.
[14 Jan 2020 9:38] lalit Choudhary
with log_slow_extra=on Errno: info not getting updated correctly for error
[16 Jan 2020 9:58] MySQL Verification Team
Hello Lalit,

Thank you for the report and test case.

regards,
Umesh
[22 Jan 2021 19:11] Paul DuBois
Posted by developer:
 
Fixed in 8.0.24.

With the log_slow_extra system variable enabled to add the Errno
field to slow query log output, the error number was 0 even for
failed statements.