Mybatis-3: select bug on 3.4.6 , result contains other classes

[jdkhome]

This picture is from IntelliJ IDEA debug. on package org.mybatis.spring;
Note the value of result , result contains other classes.

Then, here's my code:

@Override
    public User getUser(String phone, String userName, String legalAccountNo) {

        UserExample example = new UserExample();
        UserExample.Criteria criteria = example.createCriteria();

        if (!StringUtils.isEmpty(phone)) {
            criteria.andPhoneEqualTo(phone);
        }
        if (!StringUtils.isEmpty(userName)) {
            criteria.andUsernameEqualTo(userName);
        }
        if (!StringUtils.isBlank(legalAccountNo)) {
            criteria.andLegalAccountNoEqualTo(legalAccountNo);
        }

        List<User> list = userMapper.selectByExample(example); // <-- bug on this

        return list.isEmpty() ? null : list.get(0);
    }

I use mybatis-generator to generate basic code.

And this is log:

2019-02-15 09:42:24.667 DEBUG 4611 --- [nio-8190-exec-8] SQL_CACHE                                : Cache Hit Ratio [SQL_CACHE]: 0.8333333333333334
2019-02-15 09:42:24.691 DEBUG 4611 --- [nio-8190-exec-8] o.s.jdbc.datasource.DataSourceUtils      : Fetching JDBC Connection from DataSource
2019-02-15 09:42:24.971 DEBUG 4611 --- [nio-8190-exec-8] o.a.c.loader.WebappClassLoaderBase       :     findClass(com.mysql.jdbc.MySQLConnection)
2019-02-15 09:42:24.975 DEBUG 4611 --- [nio-8190-exec-8] o.a.c.loader.WebappClassLoaderBase       :     --> Returning ClassNotFoundException
2019-02-15 09:42:24.978 DEBUG 4611 --- [nio-8190-exec-8] o.m.s.t.SpringManagedTransaction         : JDBC Connection [com.mysql.cj.jdbc.ConnectionImpl@524800fd] will not be managed by Spring
2019-02-15 09:42:24.981 DEBUG 4611 --- [nio-8190-exec-8] c.s.b.a.c.g.d.U.selectByExample_COUNT    : ==>  Preparing: SELECT count(0) FROM users WHERE (legal_account_no = ?) 
2019-02-15 09:42:24.984 DEBUG 4611 --- [nio-8190-exec-8] c.s.b.a.c.g.d.U.selectByExample_COUNT    : ==> Parameters: W175359159569481728(String)
2019-02-15 09:42:24.994 DEBUG 4611 --- [nio-8190-exec-8] c.s.b.a.c.g.d.U.selectByExample_COUNT    : <==      Total: 1
2019-02-15 09:42:25.010 DEBUG 4611 --- [nio-8190-exec-8] c.s.b.a.c.g.d.U.selectByExample          : ==>  Preparing: select id, phone, username, password, salt, nickname, icon_url, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time from users WHERE ( legal_account_no = ? ) LIMIT ? 
2019-02-15 09:42:25.015 DEBUG 4611 --- [nio-8190-exec-8] c.s.b.a.c.g.d.U.selectByExample          : ==> Parameters: W175359159569481728(String), 2(Integer)
2019-02-15 09:42:25.050 DEBUG 4611 --- [nio-8190-exec-8] c.s.b.a.c.g.d.U.selectByExample          : <==      Total: 1
2019-02-15 09:42:49.389 DEBUG 4611 --- [nio-8190-exec-8] org.mybatis.spring.SqlSessionUtils       : Creating a new SqlSession
2019-02-15 09:42:49.392 DEBUG 4611 --- [nio-8190-exec-8] org.mybatis.spring.SqlSessionUtils       : SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@46fabf2] was not registered for synchronization because synchronization is not active
2019-02-15 09:42:49.394 DEBUG 4611 --- [nio-8190-exec-8] org.mybatis.spring.SqlSessionUtils       : Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@46fabf2]
2019-02-15 09:42:52.279 DEBUG 4611 --- [nio-8190-exec-8] org.mybatis.spring.SqlSessionUtils       : Creating a new SqlSession
2019-02-15 09:42:52.282 DEBUG 4611 --- [nio-8190-exec-8] org.mybatis.spring.SqlSessionUtils       : SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@6b5a7c95] was not registered for synchronization because synchronization is not active
2019-02-15 09:42:52.284 DEBUG 4611 --- [nio-8190-exec-8] org.mybatis.spring.SqlSessionUtils       : Closing non transactional SqlSession [org.apache.ibatis.session.defaults.DefaultSqlSession@6b5a7c95]

Thank you for reading my Chinglish : )
Strangely enough, this problem is not inevitable. I request the interface again to trigger it. About half of the time it happens.

[kezhenxu94]

@jdkhome Can you provide a complete yet minimal project to reproduce this issue on GitHub?

[jdkhome]

@jdkhome Can you provide a complete yet minimal project to reproduce this issue on GitHub?

Wait a minute. I'll try to extract this code into a separate project.

[kezhenxu94]

@jdkhome thanks

[jdkhome]

@kezhenxu94

https://github.com/jdkhome/temp_mybatis_bug

When I tried to reproduce in a new project, I found the cause of the problem( thanks :) ), but I still think that such query results should not appear, and should avoid or throw an exception.
If you want to fix this BUG, you can reproduce it in the project above.

[harawata]

So, what was the cause?
There seems to be no class named AdvertisementManageVO or DDL (CREATE TABLE, etc.) in the repo.
Could you show us the exact steps to reproduce the issue?

[jdkhome]

I created an open database and Resubmitted code.
Project entry is com.jdkhome.mybatis_bug.ServerApplication:main.

Startup project, repeatedly execute curl can reproduce.

➜  ~ curl http://localhost:8080/api/test
{"timestamp":"2019-02-21 15:38:05","status":500,"error":"Internal Server Error","message":"class com.jdkhome.mybatis_bug.pojo.OrderDetailLegalContractDTO cannot be cast to class com.jdkhome.mybatis_bug.generator.model.User (com.jdkhome.mybatis_bug.pojo.OrderDetailLegalContractDTO and com.jdkhome.mybatis_bug.generator.model.User are in unnamed module of loader 'app')","path":"/api/test"}%                                                                              
➜  ~ curl http://localhost:8080/api/test
{"total":2,"list":[{"orderNo":"OLC176127537817059328","accountNo":"W175359159569481728","action":"BUY","symbol":"ETH","reference":null,"totalAmount":200.000000000000000000000000000000,"balanceAmount":200.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":1,"createTime":"2019-02-14 17:10:23"},{"orderNo":"OLC175768616627601408","accountNo":"W175359159569481728","action":"SELL","symbol":"USDT","reference":null,"totalAmount":500.000000000000000000000000000000,"balanceAmount":500.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":0,"createTime":"2019-02-13 17:24:10"}],"pageNum":1,"pageSize":2,"size":2,"startRow":1,"endRow":2,"pages":1,"prePage":0,"nextPage":0,"isFirstPage":true,"isLastPage":true,"hasPreviousPage":false,"hasNextPage":false,"navigatePages":8,"navigatepageNums":[1],"navigateFirstPage":1,"navigateLastPage":1,"firstPage":1,"lastPage":1}%                    
➜  ~ curl http://localhost:8080/api/test
{"total":2,"list":[{"orderNo":"OLC176127537817059328","accountNo":"W175359159569481728","action":"BUY","symbol":"ETH","reference":null,"totalAmount":200.000000000000000000000000000000,"balanceAmount":200.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":1,"createTime":"2019-02-14 17:10:23"},{"orderNo":"OLC175768616627601408","accountNo":"W175359159569481728","action":"SELL","symbol":"USDT","reference":null,"totalAmount":500.000000000000000000000000000000,"balanceAmount":500.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":0,"createTime":"2019-02-13 17:24:10"}],"pageNum":1,"pageSize":2,"size":2,"startRow":1,"endRow":2,"pages":1,"prePage":0,"nextPage":0,"isFirstPage":true,"isLastPage":true,"hasPreviousPage":false,"hasNextPage":false,"navigatePages":8,"navigatepageNums":[1],"navigateFirstPage":1,"navigateLastPage":1,"firstPage":1,"lastPage":1}%                    ➜  ~ curl http://localhost:8080/api/test
{"total":2,"list":[{"orderNo":"OLC176127537817059328","accountNo":"W175359159569481728","action":"BUY","symbol":"ETH","reference":null,"totalAmount":200.000000000000000000000000000000,"balanceAmount":200.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":1,"createTime":"2019-02-14 17:10:23"},{"orderNo":"OLC175768616627601408","accountNo":"W175359159569481728","action":"SELL","symbol":"USDT","reference":null,"totalAmount":500.000000000000000000000000000000,"balanceAmount":500.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":0,"createTime":"2019-02-13 17:24:10"}],"pageNum":1,"pageSize":2,"size":2,"startRow":1,"endRow":2,"pages":1,"prePage":0,"nextPage":0,"isFirstPage":true,"isLastPage":true,"hasPreviousPage":false,"hasNextPage":false,"navigatePages":8,"navigatepageNums":[1],"navigateFirstPage":1,"navigateLastPage":1,"firstPage":1,"lastPage":1}%                    
➜  ~ curl http://localhost:8080/api/test
{"total":2,"list":[{"orderNo":"OLC176127537817059328","accountNo":"W175359159569481728","action":"BUY","symbol":"ETH","reference":null,"totalAmount":200.000000000000000000000000000000,"balanceAmount":200.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":1,"createTime":"2019-02-14 17:10:23"},{"orderNo":"OLC175768616627601408","accountNo":"W175359159569481728","action":"SELL","symbol":"USDT","reference":null,"totalAmount":500.000000000000000000000000000000,"balanceAmount":500.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":0,"createTime":"2019-02-13 17:24:10"}],"pageNum":1,"pageSize":2,"size":2,"startRow":1,"endRow":2,"pages":1,"prePage":0,"nextPage":0,"isFirstPage":true,"isLastPage":true,"hasPreviousPage":false,"hasNextPage":false,"navigatePages":8,"navigatepageNums":[1],"navigateFirstPage":1,"navigateLastPage":1,"firstPage":1,"lastPage":1}%                    
➜  ~ curl http://localhost:8080/api/test
{"total":2,"list":[{"orderNo":"OLC176127537817059328","accountNo":"W175359159569481728","action":"BUY","symbol":"ETH","reference":null,"totalAmount":200.000000000000000000000000000000,"balanceAmount":200.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":1,"createTime":"2019-02-14 17:10:23"},{"orderNo":"OLC175768616627601408","accountNo":"W175359159569481728","action":"SELL","symbol":"USDT","reference":null,"totalAmount":500.000000000000000000000000000000,"balanceAmount":500.000000000000000000000000000000,"lockAmount":0E-30,"minAmount":500.000000000000000000000000000000,"maxAmount":10000.000000000000000000000000000000,"price":123.000000000000000000000000000000,"status":0,"createTime":"2019-02-13 17:24:10"}],"pageNum":1,"pageSize":2,"size":2,"startRow":1,"endRow":2,"pages":1,"prePage":0,"nextPage":0,"isFirstPage":true,"isLastPage":true,"hasPreviousPage":false,"hasNextPage":false,"navigatePages":8,"navigatepageNums":[1],"navigateFirstPage":1,"navigateLastPage":1,"firstPage":1,"lastPage":1}%                    
➜  ~ curl http://localhost:8080/api/test
{"timestamp":"2019-02-21 15:38:11","status":500,"error":"Internal Server Error","message":"class com.jdkhome.mybatis_bug.pojo.OrderDetailLegalContractDTO cannot be cast to class com.jdkhome.mybatis_bug.generator.model.User (com.jdkhome.mybatis_bug.pojo.OrderDetailLegalContractDTO and com.jdkhome.mybatis_bug.generator.model.User are in unnamed module of loader 'app')","path":"/api/test"}%                                                                              
➜  ~ 

[harawata]

I ran the updated app with logging enabled.
For a successful invocation, the output looks as follows.

2019-02-21 22:47:08.781 DEBUG 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : ==>  Preparing: select id, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time from users WHERE ( legal_account_no = ? ) 
2019-02-21 22:47:08.820 DEBUG 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : ==> Parameters: W175359159569481728(String)
2019-02-21 22:47:09.062 TRACE 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : <==    Columns: id, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time
2019-02-21 22:47:09.063 TRACE 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : <==        Row: 35, iOS, iOS_679517012NBRVZAURQ6V2X9U, 86, W120644455681228800, SUB130073129849454592, MSUB155387126236577792, W175359159569481728, ce733e499482333afe083325fb8621a0, 1, 2018-05-28 08:37:59, 2019-02-13 17:23:52
2019-02-21 22:47:09.065 DEBUG 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : <==      Total: 1
2019-02-21 22:47:09.067 DEBUG 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : ==>  Preparing: select id, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time from users WHERE ( legal_account_no = ? ) 
2019-02-21 22:47:09.068 DEBUG 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : ==> Parameters: W175359159569481728(String)
2019-02-21 22:47:09.377 TRACE 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : <==    Columns: id, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time
2019-02-21 22:47:09.378 TRACE 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : <==        Row: 35, iOS, iOS_679517012NBRVZAURQ6V2X9U, 86, W120644455681228800, SUB130073129849454592, MSUB155387126236577792, W175359159569481728, ce733e499482333afe083325fb8621a0, 1, 2018-05-28 08:37:59, 2019-02-13 17:23:52
2019-02-21 22:47:09.379 DEBUG 55030 --- [nio-8080-exec-1] c.j.m.g.dao.UserMapper.selectByExample   : <==      Total: 1

As you can see, the same query is executed twice.
And here is the output for a failed one.

2019-02-21 22:50:53.767 DEBUG 55030 --- [nio-8080-exec-2] c.j.m.g.d.U.selectByExample_COUNT        : ==>  Preparing: SELECT count(0) FROM users WHERE (legal_account_no = ?) 
2019-02-21 22:50:53.767 DEBUG 55030 --- [nio-8080-exec-2] c.j.m.g.d.U.selectByExample_COUNT        : ==> Parameters: W175359159569481728(String)
2019-02-21 22:50:53.960 TRACE 55030 --- [nio-8080-exec-2] c.j.m.g.d.U.selectByExample_COUNT        : <==    Columns: count(0)
2019-02-21 22:50:53.960 TRACE 55030 --- [nio-8080-exec-2] c.j.m.g.d.U.selectByExample_COUNT        : <==        Row: 1
2019-02-21 22:50:53.961 DEBUG 55030 --- [nio-8080-exec-2] c.j.m.g.d.U.selectByExample_COUNT        : <==      Total: 1
2019-02-21 22:50:53.963 DEBUG 55030 --- [nio-8080-exec-2] c.j.m.g.dao.UserMapper.selectByExample   : ==>  Preparing: select id, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time from users WHERE ( legal_account_no = ? ) LIMIT ? 
2019-02-21 22:50:53.963 DEBUG 55030 --- [nio-8080-exec-2] c.j.m.g.dao.UserMapper.selectByExample   : ==> Parameters: W175359159569481728(String), 2(Integer)
2019-02-21 22:50:54.160 TRACE 55030 --- [nio-8080-exec-2] c.j.m.g.dao.UserMapper.selectByExample   : <==    Columns: id, platform, equipment_id, country_code, wallet_account_no, asset_sub_account_no, asset_mock_sub_account_no, legal_account_no, asset_password, status, create_time, update_time
2019-02-21 22:50:54.160 TRACE 55030 --- [nio-8080-exec-2] c.j.m.g.dao.UserMapper.selectByExample   : <==        Row: 35, iOS, iOS_679517012NBRVZAURQ6V2X9U, 86, W120644455681228800, SUB130073129849454592, MSUB155387126236577792, W175359159569481728, ce733e499482333afe083325fb8621a0, 1, 2018-05-28 08:37:59, 2019-02-13 17:23:52
2019-02-21 22:50:54.161 DEBUG 55030 --- [nio-8080-exec-2] c.j.m.g.dao.UserMapper.selectByExample   : <==      Total: 1

A query named selectByExample_COUNT is executed first.
There is no such statement defined in the mapper, so I suspect it is executed by the plugin 'pagehelper' for somehow (the plugin is not developed by us).
Try removing the plugin and see if the problem still reproduces.

[jdkhome]

thanks , It's really the result of improper use of 'pagehelper'.