Bug #93606 when use Connector/J preparestatement mysql returns the wrong result
Submitted: 14 Dec 2018 7:53 Modified: 10 Jan 2019 6:54
Reporter: huiping wu Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Optimizer Severity:S2 (Serious)
Version:5.6.40,5.7.24 OS:CentOS (6.9)
Assigned to: CPU Architecture:x86
Tags: prepared statement

[14 Dec 2018 7:53] huiping wu
Description:
Using the cache prepare statement and server prepare statement in the Connector/J driver, the mysql database returns the wrong result.

table Structure:
CREATE TABLE `hhz_user_sign` (
  `box_id` int(11) NOT NULL AUTO_INCREMENT,
  `user_id` int(11) NOT NULL COMMENT '用户',
  `last_time` varchar(18) DEFAULT NULL COMMENT '上一次签到时间',
  `times` int(2) DEFAULT NULL COMMENT '周期连续签到(2017-09-01)次数',
  `time` varchar(10) DEFAULT NULL COMMENT '周期签到时间(2017-09-01)',
  `ctime` bigint(18) DEFAULT NULL COMMENT '签到时间',
  PRIMARY KEY (`box_id`),
  UNIQUE KEY `user_id` (`user_id`) USING BTREE
) ENGINE=InnoDB  DEFAULT CHARSET=utf8;

table data:
insert into hhz_user_sign set box_id=2613932,user_id=451720,last_time='2018-12-09',times=4,time='2018-12-10';

Open the cachePreparedStatement and serverPrepareStatement at the same time in the Connector/J driver, through the Connector/J driver, in the same database connection, and in the case of cross-day, execute the following statement twice:
SELECT IF(time=DATE_FORMAT(DATE_ADD(now(), INTERVAL - 1 DAY),'%Y-%m-%d'),1,0) isContinuity,DATE_FORMAT(DATE_ADD(NOW(), INTERVAL - 1 DAY),'%Y-%m-%d') as day_yesterday,DATE_ADD(NOW(), INTERVAL - 1 DAY) day_yesterdateimte,NOW() as day_now  FROM hhz_user_sign WHERE user_id = 451720 limit 1

Suppose the first query execution time is 2018-12-10 23:59:50, and the correct result is returned. The result of the isContinuity column is 0.

Suppose the second query execution time is 2018-12-11 00:00:00 or later, mysql returns the wrong result. The result of the isContinuity column should be 1, but the result returned is 0. But the result returned by day_yesterday is correct.

In the following cases, mysql returns the correct result:
1. If you do not use cachePreparedStatement in the Connector/J driver, the results of both queries are correct. In this case, mysql will execute prepare twice. In the case of using cachePreparedStatement, mysql only executes prepare once. When performing the second query, the Connector/J driver only sends a preprocessed ID from the cache to the mysql server.

2. Use the prepare statement in the mysql command line to return the correct result.

3. Replace the now() function in the SQL statement with sysdate(), and return the correct result: IF (time=DATE_FORMAT(DATE_ADD(now(), INTERVAL - 1 DAY), '%Y-%m-%d '),1,0) isContinuity changed to IF (time=DATE_FORMAT(DATE_ADD(sysdate(), INTERVAL - 1 DAY), '%Y-%m-%d'),1,0) isContinuity

4. Replace the now() function in the SQL statement with current_date and return the correct result: IF (time=DATE_FORMAT(DATE_ADD(now(), INTERVAL - 1 DAY), '%Y-%m-%d') ,1,0) isContinuity changed to IF ( time = DATE_ADD(current_date, INTERVAL - 1 DAY),1,0) isContinuity

However, in either of the above cases, the result returned by the day_yesterday column is correct. Therefore, I am not sure what the problem is.

How to repeat:
Environmental description:
centos6.9 x86_64
MySQL:5.6.40,5.7.23
JDK:1.8
Connector/J driver:mysql-connector-java-5.1.47.jar

Open server preparedstatement and cachePreparedstatement in the Connector/J driver:
source.setUseServerPreparedStmts(true);
source.setCachePreparedStatements(true);

create table in mysql server:
CREATE TABLE `hhz_user_sign` (
  `box_id` int(11) NOT NULL AUTO_INCREMENT,
  `user_id` int(11) NOT NULL COMMENT '用户',
  `last_time` varchar(18) DEFAULT NULL COMMENT '上一次签到时间',
  `times` int(2) DEFAULT NULL COMMENT '周期连续签到(2017-09-01)次数',
  `time` varchar(10) DEFAULT NULL COMMENT '周期签到时间(2017-09-01)',
  `ctime` bigint(18) DEFAULT NULL COMMENT '签到时间',
  PRIMARY KEY (`box_id`),
  UNIQUE KEY `user_id` (`user_id`) USING BTREE
) ENGINE=InnoDB  DEFAULT CHARSET=utf8;

insert data:
insert into hhz_user_sign set box_id=2613932,user_id=451720,last_time='2018-12-09',times=4,time='2018-12-10';

Running steps:
1、set the mysql database server time to 2018-12-10 23:59:50
date -s "2018-12-10 23:59:50"

2、Within 10 second, run the java program and specify mysql host, mysql port, mysql user, mysql password, database name, as follows:
java -jar test.jar 172.16.0.1 3306 test test test

The program will lose the result twice in 10 seconds, as follows:
[root@mycentos6 ~]# java -jar test.jar  127.0.0.1 3306 wuhp maxwell maxwell
JDBC ***************** TEST
Mon Dec 10 23:59:52 CST 2018 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
isContinuity=> 0
day_yesterday=> 2018-12-09
day_yesterdateimte=> 2018-12-09 23:59:52.0
day_now=> 2018-12-10 23:59:52.0
===================================
isContinuity=> 0
day_yesterday=> 2018-12-10
day_yesterdateimte=> 2018-12-10 00:00:02.0
day_now=> 2018-12-11 00:00:02.0

The isContinuity is still 0 in the result of the second output, and the correct result should be 1.

Then, run the program again, and the results of the two outputs are correct: isContinuity is 1.

[root@mycentos6 ~]# java -jar test.jar  127.0.0.1 3306 wuhp maxwell maxwell
JDBC ***************** TEST
Tue Dec 11 00:00:10 CST 2018 WARN: Establishing SSL connection without server's identity verification is not recommended. According to MySQL 5.5.45+, 5.6.26+ and 5.7.6+ requirements SSL connection must be established by default if explicit option isn't set. For compliance with existing applications not using SSL the verifyServerCertificate property is set to 'false'. You need either to explicitly disable SSL by setting useSSL=false, or set useSSL=true and provide truststore for server certificate verification.
isContinuity=> 1
day_yesterday=> 2018-12-10
day_yesterdateimte=> 2018-12-10 00:00:10.0
day_now=> 2018-12-11 00:00:10.0
===================================
isContinuity=> 1
day_yesterday=> 2018-12-10
day_yesterdateimte=> 2018-12-10 00:00:20.0
day_now=> 2018-12-11 00:00:20.0

Suggested fix:
I don't know how to add attachments, If you need to test the java program, please contact me at email 113194325@qq.com.I posted the java code below:

public class JDBCTest {
	public static Connection getConnection(String host, String port, String dbname, String user, String password) {
		System.out.println("JDBC ***************** TEST");
		Connection conn = null;
		try {
			Class.forName("com.mysql.jdbc.Driver");
		} catch (ClassNotFoundException e) {
			e.printStackTrace();
		}

		try {
			
			MysqlDataSource source = new MysqlDataSource();
			source.setURL("jdbc:mysql://" + host + ":" + port + "/" + dbname);
			source.setUser(user);
			source.setPassword(password);
			source.setUseServerPreparedStmts(true);
			source.setCachePreparedStatements(true);
			// source.setCachePrepStmts(true);
			source.setPreparedStatementCacheSize(128);
			source.setPreparedStatementCacheSqlLimit(1024);
			conn = source.getConnection();
		} catch (SQLException e) {
			e.printStackTrace();
		}
		return conn;
	}

	public static void main(String[] args) {
		
		if (args.length != 5) {
			System.out.println("Error: parameters error");
			System.out.println("The first parameter is mysql host");
			System.out.println("The second parameter is mysql port");
			System.out.println("The third parameter is mysql dbname");
			System.out.println("The fourth parameter is mysql user");
			System.out.println("The fifth parameter is mysql password");
			System.out.println("Like this: java -jar test.jar 127.0.0.1 3306 dbname user password");
			System.exit(1);
		}

		String host = args[0].trim();
		String port = args[1].trim();
		String dbname = args[2].trim();
		String user = args[3].trim();
		String password = args[4].trim();

		PreparedStatement ps = null;
		ResultSet rs = null;
		Connection con = null;

		String sql = "SELECT IF ( time = DATE_FORMAT(DATE_ADD(now(), INTERVAL - 1 DAY),'%Y-%m-%d'),1,0)  isContinuity,"
				+ "DATE_FORMAT(DATE_ADD(NOW(), INTERVAL - 1 DAY),'%Y-%m-%d') as day_yesterday,DATE_ADD(NOW(), INTERVAL - 1 DAY) day_yesterdateimte,NOW() as day_now"
				+ "  FROM hhz_user_sign WHERE user_id = ? limit 1";
		try {
			con = JDBCTest.getConnection(host, port, dbname, user, password);
			ps = con.prepareStatement(sql);
		        ps.setLong(1, 451720);
			rs = ps.executeQuery();
			while (rs.next()) {
				
				System.out.println("isContinuity=> " + rs.getString("isContinuity"));
				System.out.println("day_yesterday=> " + rs.getString("day_yesterday"));
				System.out.println("day_yesterdateimte=> " + rs.getString("day_yesterdateimte"));
				System.out.println("day_now=> " + rs.getString("day_now"));
				
			}
			ps.close();
			rs.close();
			System.out.println("===================================");
			try {
				Thread.sleep(10 * 1000);
			} catch (InterruptedException e) {
				// TODO Auto-generated catch block
				e.printStackTrace();
			}
			ps = con.prepareStatement(sql);
			ps.setLong(1, 451720);
			rs = ps.executeQuery();
			while (rs.next()) {
				
				System.out.println("isContinuity=> " + rs.getString("isContinuity"));
				System.out.println("day_yesterday=> " + rs.getString("day_yesterday"));
				System.out.println("day_yesterdateimte=> " + rs.getString("day_yesterdateimte"));
				System.out.println("day_now=> " + rs.getString("day_now"));
				
			}
		} catch (SQLException e) {
			e.printStackTrace();
		} finally {
			try {
				ps.close();
				rs.close();
				con.close();
			} catch (SQLException e) {
				e.printStackTrace();
			}

		}
	}
}
[14 Dec 2018 8:02] huiping wu
HI:
Already uploaded to java program to sftp:sftp.oracle.com:/support/incoming/mysql-bug-data-93606.tar.gz
[9 Jan 2019 12:15] MySQL Verification Team
Hello huiping wu,

Thank you for the report and test case.
Verified as described with provided jar.
Could you please confirm exact C/J version used in your environment? Thank you.

regards,
Umesh
[10 Jan 2019 6:54] huiping wu
hello Umesh Shastry!

The C/J version used in the environment is mysql-connector-java-5.1.47.jar.

thanks.
[23 Nov 2021 15:27] Alexander Soklakov
Hi huiping wu,

This is definitely not a Connector/J bug. The case you reproduce with useServerPrepStmts=true and cachePrepStmts=true just reflects the situation when the real (not the emulated one) prepared statement is prepared on the server side, it is executed several times and the date switch happens between the executions. The test could be simplified a bit:

    @Test
    public void testBug93606() throws Exception {
        createTable("testBug93606", "(" //
                + "`time` varchar(10) DEFAULT NULL" //
                + ") ENGINE=InnoDB  DEFAULT CHARSET=utf8");
        this.stmt.executeUpdate("insert into testBug93606 set time=DATE_FORMAT(DATE_ADD(NOW(), INTERVAL - 1 DAY),'%Y-%m-%d')");

        Properties props = new Properties();
        props.setProperty(PropertyKey.sslMode.getKeyName(), SslMode.DISABLED.name());
        props.setProperty(PropertyKey.allowPublicKeyRetrieval.getKeyName(), "true");
        props.setProperty(PropertyKey.useServerPrepStmts.getKeyName(), "true");

        Connection con = getConnectionWithProps(props);
        this.pstmt = con.prepareStatement("SELECT " //
                + "IF(time=DATE_FORMAT(DATE_ADD(NOW(), INTERVAL - 1 DAY),'%Y-%m-%d'),1,0) isContinuity1," //
                + "IF(time=DATE_FORMAT(DATE_ADD(sysdate(), INTERVAL - 1 DAY),'%Y-%m-%d'),1,0) isContinuity2," //
                + "DATE_FORMAT(DATE_ADD(NOW(), INTERVAL - 1 DAY),'%Y-%m-%d') as yesterday," //
                + "DATE_ADD(NOW(), INTERVAL - 1 DAY) yesterdatetime," //
                + "NOW() as now, sysdate() as sysdate  FROM testBug93606");

        this.pstmt.execute();
        this.rs = this.pstmt.getResultSet();
        this.rs.next();
        System.out.println("isContinuity with now() = " + this.rs.getString(1));
        System.out.println("isContinuity with sysdate() = " + this.rs.getString(2));
        System.out.println("yesterday = " + this.rs.getString(3));
        System.out.println("yesterdatetime = " + this.rs.getString(4));
        System.out.println("now = " + this.rs.getString(5));
        System.out.println("sysdate = " + this.rs.getString(6));

        System.out.println();
        Thread.sleep(15000); // switch server date manually during this sleep

        this.pstmt.execute();
        this.rs = this.pstmt.getResultSet();
        this.rs.next();

        System.out.println("isContinuity with now() = " + this.rs.getString(1));
        System.out.println("isContinuity with sysdate() = " + this.rs.getString(2));
        System.out.println("yesterday = " + this.rs.getString(3));
        System.out.println("yesterdatetime = " + this.rs.getString(4));
        System.out.println("now = " + this.rs.getString(5));
        System.out.println("sysdate = " + this.rs.getString(6));

        con.close();
    }

And the output is:
===
Connected to 5.6.46-log
isContinuity with now() = 1
isContinuity with sysdate() = 1
yesterday = 2021-11-22
yesterdatetime = 2021-11-22 18:25:07
now = 2021-11-23 18:25:07
sysdate = 2021-11-23 18:25:07

isContinuity with now() = 1
isContinuity with sysdate() = 0
yesterday = 2021-11-23
yesterdatetime = 2021-11-23 18:25:10
now = 2021-11-24 18:25:10
sysdate = 2021-11-24 18:25:10
===

For me it looks like a side effect of the behaviour described here https://dev.mysql.com/doc/refman/8.0/en/date-and-time-functions.html#function_now :

"NOW() returns a constant time that indicates the time at which the statement began to execute. (Within a stored function or trigger, NOW() returns the time at which the function or triggering statement began to execute.) This differs from the behavior for SYSDATE(), which returns the exact time at which it executes."

I.e., it seems that the NOW() value nested into IF() is calculated only once during the PREPARE step or on the first execution. Since it is inconsistent with other NOW() results on the same query then it could be a bug in parser but I can't say for sure. Let's reassign this bug to the server team to know their opinion.

BTW, MySQL 8.0 is not affected:

===
Connected to 8.0.26
isContinuity with now() = 1
isContinuity with sysdate() = 1
yesterday = 2021-11-22
yesterdatetime = 2021-11-22 18:56:36
now = 2021-11-23 18:56:36
sysdate = 2021-11-23 18:56:36

isContinuity with now() = 0
isContinuity with sysdate() = 0
yesterday = 2021-11-23
yesterdatetime = 2021-11-23 18:56:12
now = 2021-11-24 18:56:12
sysdate = 2021-11-24 18:56:12
===

Thanks,
Alex