TiDB's warning logs for "Data Truncated" Error are not friendly.

[mz1999]

Please answer these questions before submitting your issue. Thanks!

1. What did you do?

I encountered the same error as #5532, but my concern is that the server side warning logs for "Data Truncated" error are not friendly, which caused a lot of trouble in locating the root reason.

mysql> desc test;
+-------+-------------+------+------+---------+-------+
| Field | Type        | Null | Key  | Default | Extra |
+-------+-------------+------+------+---------+-------+
| id    | int(11)     | NO   |      | NULL    |       |
| total | decimal(20) | NO   |      | NULL    |       |
+-------+-------------+------+------+---------+-------+
2 rows in set (0.01 sec)

Java Code snippet：

String DB_URL = "jdbc:mysql://172.20.51.61:4000/test";
Properties info = new Properties();
info.setProperty("user", "root");
info.setProperty("password", "");
info.setProperty("useServerPrepStmts", "true");

Connection conn = DriverManager.getConnection(DB_URL, info);

String sql = "update test set total = total + ? where id = ?";
PreparedStatement preparedStatement = conn.prepareStatement(sql);
preparedStatement.setDouble(1, 1.16);
preparedStatement.setInt(2, 1);
preparedStatement.executeUpdate();

Note: set useServerPrepStmts=true , using Server Prepared Statements

MySQL Connector/J version：

<dependency>
     <groupId>mysql</groupId>
     <artifactId>mysql-connector-java</artifactId>
     <version>6.0.6</version>
</dependency>

2. What did you expect to see?

I expected TiDB's server side warning logs to point out the SQL statement which caused the error.

3. What did you see instead?

2018/02/02 10:47:55.454 conn.go:472: [warning] [33] dispatch error:
id:33, addr:172.20.225.11:64749 status:2, collation:utf8_general_ci, user:root
"\x01\x00\x00\x00\x00\x01\x00\x00\x00\x00\x01\x05\x00\x03\x00\x8f\xc2\xf5(\\\x8f\xf2?\x01\x00\x00\x00"
[types:1265]Data Truncated
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/types/datum.go:1105: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/expression/builtin_cast.go:672: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/expression/scalar_function.go:212: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/write.go:1883: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/write.go:1869: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/write.go:1821: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/executor/adapter.go:284: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/tidb.go:199: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/session.go:910: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/server/driver_tidb.go:70: 
/home/jenkins/workspace/build_tidb_master/go/src/github.com/pingcap/tidb/server/conn_stmt.go:168: 

4. What version of TiDB are you using (tidb-server -V or run select tidb_version(); on TiDB)?

mysql> select tidb_version();
+-------------------------------------------------------------------------
| tidb_version()                
+-------------------------------------------------------------------------
| Release Version: v1.1.0-alpha.1-53-g1f1e5f5
Git Commit Hash: 1f1e5f53eb66acb9ef534d87f4e8daeae2552f73
Git Branch: master
UTC Build Time: 2018-02-01 03:33:14 |
+-------------------------------------------------------------------------
1 row in set (0.02 sec)

[zz-jason]

@mz1999 Thanks for your feed back ! We are working on this currently.

[morgo]

Here is a test-case which uses sql only:

DROP TABLE IF EXISTS test;
CREATE TABLE test (
 id int not null primary key auto_increment,
 total decimal(20) not null
);
INSERT INTO test (id,total) VALUES (1, 1);

PREPARE stmt1 FROM "update test set total = total + ? where id = ?";
SET @a = 1.16;
SET @b = 1;
EXECUTE stmt1 USING @a, @b;
SHOW WARNINGS;
DEALLOCATE PREPARE stmt1;

I ran this against master, and the following was written to the log file:

[2019/03/23 09:17:31.003 -06:00] [INFO] [server.go:398] ["new connection"] [conn=1] [remoteAddr=127.0.0.1:38666]
[2019/03/23 09:17:33.881 -06:00] [INFO] [session.go:1693] ["[CRUCIAL OPERATION]"] [con=1] [schemaVersion=18] [cur_db=test] [sql="DROP TABLE IF EXISTS test"] [user=root@127.0.0.1]
[2019/03/23 09:17:33.883 -06:00] [INFO] [session.go:1693] ["[CRUCIAL OPERATION]"] [con=1] [schemaVersion=18] [cur_db=test] [sql="CREATE TABLE test (\n id int not null primary key auto_increment,\n total decimal(20) not null\n)"] [user=root@127.0.0.1]
[2019/03/23 09:17:33.916 -06:00] [INFO] [ddl.go:559] ["[ddl] start to do DDL job"] [job="ID:38, Type:create table, State:none, SchemaState:none, SchemaID:1, TableID:37, RowCount:0, ArgLen:1, start time: 2019-03-23 09:17:33.877 -0600 MDT, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE test (\n id int not null primary key auto_increment,\n total decimal(20) not null\n)"]
[2019/03/23 09:17:33.919 -06:00] [INFO] [ddl_worker.go:471] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:38, Type:create table, State:none, SchemaState:none, SchemaID:1, TableID:37, RowCount:0, ArgLen:0, start time: 2019-03-23 09:17:33.877 -0600 MDT, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2019/03/23 09:17:33.921 -06:00] [INFO] [split_region.go:31] ["start split region"] [at=dIAAAAAAAAAl]
[2019/03/23 09:17:33.932 -06:00] [INFO] [split_region.go:67] ["split region complete"] [at=dIAAAAAAAAAl] ["new region left"="id:36 start_key:\"t\\200\\000\\000\\000\\000\\000\\000\\377#\\000\\000\\000\\000\\000\\000\\000\\370\" end_key:\"t\\200\\000\\000\\000\\000\\000\\000\\377%\\000\\000\\000\\000\\000\\000\\000\\370\" region_epoch:<conf_ver:1 version:18 > peers:<id:37 store_id:1 > "] ["new region right"="id:2 start_key:\"t\\200\\000\\000\\000\\000\\000\\000\\377%\\000\\000\\000\\000\\000\\000\\000\\370\" region_epoch:<conf_ver:1 version:18 > peers:<id:3 store_id:1 > "]
2019/03/23 09:17:33.941 domain.go:115: [info] [ddl] diff load InfoSchema from version 18 to 19 in 1.250712ms, tableIDs [37]
[2019/03/23 09:17:33.990 -06:00] [INFO] [ddl_worker.go:638] ["[ddl] wait latest schema version changed"] [worker="worker 3, tp general"] [ver=19] [takeTime=51.372191ms] [job="ID:38, Type:create table, State:done, SchemaState:public, SchemaID:1, TableID:37, RowCount:0, ArgLen:1, start time: 2019-03-23 09:17:33.877 -0600 MDT, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2019/03/23 09:17:33.993 -06:00] [INFO] [ddl_worker.go:301] ["[ddl] finish DDL job"] [worker="worker 3, tp general"] [job="ID:38, Type:create table, State:synced, SchemaState:public, SchemaID:1, TableID:37, RowCount:0, ArgLen:0, start time: 2019-03-23 09:17:33.877 -0600 MDT, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2019/03/23 09:17:34.012 -06:00] [INFO] [ddl.go:591] ["[ddl] DDL job is finished"] [jobID=38]
2019/03/23 09:17:34.012 domain.go:547: [info] [ddl] on DDL change, must reload
[2019/03/23 09:18:28.232 -06:00] [INFO] [gc_worker.go:366] ["[gc worker] gc interval haven't past since last run, no need to gc"] ["leaderTick on"=5a6ac833efc000d] [interval=10m0s] ["last run"=2019/03/23 09:17:28.000 -06:00]

I actually think that this is correct for at least INFO level notification. This is a client-related error, the server acted as expected and returned a warning (run SHOW WARNINGS). The warning message was not quite identical between TiDB and MySQL though:

mysql8.0.15> SHOW WARNINGS;
+-------+------+--------------------------------------------+
| Level | Code | Message                                    |
+-------+------+--------------------------------------------+
| Note  | 1265 | Data truncated for column 'total' at row 1 |
+-------+------+--------------------------------------------+
1 row in set (0.00 sec)
..
tidb> SHOW WARNINGS;
+---------+------+----------------+
| Level   | Code | Message        |
+---------+------+----------------+
| Warning | 1265 | Data Truncated |
+---------+------+----------------+
1 row in set (0.00 sec)

[ghost]

The warning has changed slightly in TiDB (incorrect):

+---------+------+-------------------------------------------+
| Level   | Code | Message                                   |
+---------+------+-------------------------------------------+
| Warning | 1292 | Truncated incorrect DECIMAL value: '2.16' |
+---------+------+-------------------------------------------+
1 row in set (0.00 sec)

mysql> SELECT tidb_version()\G
*************************** 1. row ***************************
tidb_version(): Release Version: v4.0.0-beta.2-870-g2a8b96845
Edition: Community
Git Commit Hash: 2a8b968453520e4fcf9d6ff46c9f23b4ad23feee
Git Branch: master
UTC Build Time: 2020-07-31 08:45:35
GoVersion: go1.13
Race Enabled: false
TiKV Min Version: v3.0.0-60965b006877ca7234adaced7890d7b029ed1306
Check Table Before Drop: false
1 row in set (0.00 sec)

[dveeden]

Seems to still affect the latest master:

sql> DROP TABLE IF EXISTS test;
Query OK, 0 rows affected, 1 warning (0.0012 sec)
Note (code 1051): Unknown table 'test.test'

sql> CREATE TABLE test (
   ->  id int not null primary key auto_increment,
   ->  total decimal(20) not null
   -> );
Query OK, 0 rows affected (0.1747 sec)

sql> INSERT INTO test (id,total) VALUES (1, 1);
Query OK, 1 row affected (0.0013 sec)

sql> PREPARE stmt1 FROM "update test set total = total + ? where id = ?";
Query OK, 0 rows affected (0.0008 sec)

sql> SET @a = 1.16;
Query OK, 0 rows affected (0.0009 sec)

sql> SET @b = 1;
Query OK, 0 rows affected (0.0013 sec)

sql> EXECUTE stmt1 USING @a, @b;
Query OK, 1 row affected, 1 warning (0.0026 sec)

Rows matched: 1  Changed: 1  Warnings: 1
Warning (code 1292): Truncated incorrect DECIMAL value: '2.16'

sql> SHOW WARNINGS;
+---------+------+-------------------------------------------+
| Level   | Code | Message                                   |
+---------+------+-------------------------------------------+
| Warning | 1292 | Truncated incorrect DECIMAL value: '2.16' |
+---------+------+-------------------------------------------+
1 row in set (0.0011 sec)

sql> DEALLOCATE PREPARE stmt1;
Query OK, 0 rows affected (0.0008 sec)

sql> SELECT TIDB_VERSION()\G
*************************** 1. row ***************************
TIDB_VERSION(): Release Version: v7.6.0-alpha-218-g5a2d7da5c6
Edition: Community
Git Commit Hash: 5a2d7da5c62d244e273cc4d93351e0bc5774da5c
Git Branch: master
UTC Build Time: 2023-11-17 11:44:22
GoVersion: go1.21.0
Race Enabled: false
Check Table Before Drop: false
Store: unistore
1 row in set (0.0013 sec)

[dveeden]

So this started as a enhancement as Data Truncated isn't helpful, but now it is a bug as Truncated incorrect DECIMAL value: '2.16' is not correct.