Bug #78778 mysqlclient does not return correct mysql_insert_id via database handle
Submitted: 9 Oct 2015 9:45 Modified: 3 Mar 2017 1:51
Reporter: Michiel Beijen Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: C API (client library) Severity:S3 (Non-critical)
Version:5.7.8 OS:Any
Assigned to: Georgi Kodinov CPU Architecture:Any

[9 Oct 2015 9:45] Michiel Beijen
Description:
Hi, I am one of the maintainers of the Perl DBD::mysql module.
I ran the test suite of this module against a MySQL 5.7.8 database and found one of the tests failing:

#   Failed test 'dbh insert id 0 == max(id) 2 in dbd_mysql_t31'
#   at t/31insertid.t line 58.
#          got: 0
#     expected: 2
# Looks like you failed 1 test of 18.

This test inserts some records in a table and then checks mysql_insertid via the statement handle and via the database handle. I found when I use the 5.7.8 client the value returned by the database handle is '0'.

Full code for the test is here: https://github.com/perl5-dbi/DBD-mysql/blob/bb33077f26958872a9b71429fad9711328389ca5/t/31i...

When I run the same test using a 5.5.x client against the 5.7.8 database the tests succeed; so my assumption is the problem would be in libmysqlclient.

How to repeat:
- install 5.7.8 libmysqlclient + headers + make + gcc
- install perl modules DBI and Test::Deep
- install zlib devel modules
- get source from https://github.com/perl5-dbi/DBD-mysql or CPAN

perl Makefile.PL (possibly specify connection info via command line switches)
make
make test

see result!
[15 Oct 2015 16:30] Umesh Shastry
Hello Michiel Beijen,

Thank you for the report.
Verified as described.

Thanks,
Umesh
[15 Oct 2015 16:33] Umesh Shastry
test results

Attachment: 78778.results (application/octet-stream, text), 13.87 KiB.

[6 Nov 2015 15:59] Georgi Kodinov
This seems to be some sort of a Perl::DBD specific problem.

I've tried the following program using libmysql's C API directly:
-----------------
#include <mysql.h>

int main()
{
  MYSQL con;
  const char *cmds[] =
  {
    "SET @@auto_increment_offset = 1",
    "SET @@auto_increment_increment = 1",
    "CREATE TEMPORARY TABLE dbd_mysql_t31 ( "
     " id INT(3) PRIMARY KEY AUTO_INCREMENT NOT NULL, "
     " name VARCHAR(64))",
    NULL
  };

  if (!mysql_init(&con))
  {
    fprintf(stderr, "mysql_init failed\n");
    exit(1);
  }

  if (!mysql_real_connect(&con, "localhost", "root", "", "xx", 3306, NULL, 0))
  {
    fprintf(stderr, "mysql_real_connect failed: %s\n", mysql_error(&con));
    exit(1);
  }

  for (auto idx= 0; cmds[idx] != NULL; idx++)
  {
    if (mysql_query(&con, cmds[idx]))
    {
      fprintf(stderr, "%s failed: %s\n", cmds[idx], mysql_error(&con));
      exit(1);
    }
  }

  MYSQL_STMT *stmt= mysql_stmt_init(&con);

  if (!stmt)
  {
    fprintf(stderr, "mysql_stmt_init failed: %s\n", mysql_error(&con));
    exit(1);
  }
  if (mysql_stmt_prepare(stmt, 
                         "INSERT INTO dbd_mysql_t31 (name) VALUES (?)",
                         sizeof("INSERT INTO dbd_mysql_t31 (name) VALUES (?)") - 1))
  {
    fprintf(stderr, "mysql_stmt_prepare failed: %s\n", mysql_stmt_error(stmt));
    exit(1);
  }

  MYSQL_BIND bind;
  char buffer[50];
  unsigned long str_length;
  unsigned iid;
  
  memset(&bind, 0, sizeof(bind));

  bind.buffer_type= MYSQL_TYPE_STRING;
  bind.buffer= &buffer[0];
  bind.buffer_length= sizeof(buffer) - 1;
  bind.is_null= 0;
  bind.length= &str_length;

  if (mysql_stmt_bind_param(stmt, &bind))
  {
    fprintf(stderr, "mysql_stmt_bind_param failed: %s\n", mysql_stmt_error(stmt));
    exit(1);
  }

  strcpy_s(buffer, "Jochen");
  str_length= strlen(buffer);

  if (mysql_stmt_execute(stmt))
  {
    fprintf(stderr, "mysql_stmt_execute failed: %s\n", mysql_stmt_error(stmt));
    exit(1);
  }
  iid= (unsigned) mysql_insert_id(&con);
  printf("iid after Jochen=%u\n", iid);

  strcpy_s(buffer, "Patrick");
  str_length= strlen(buffer);
  if (mysql_stmt_execute(stmt))
  {
    fprintf(stderr, "mysql_stmt_execute 2 failed: %s\n", mysql_stmt_error(stmt));
    exit(1);
  }
  iid= (unsigned) mysql_insert_id(&con);
  printf("iid after Patrick=%u\n", iid);

  mysql_stmt_close(stmt);

  mysql_close(&con);
}
---------------

After compiling and running it against a 5.7.9 server I'm getting: 

iid after Jochen=1
iid after Patrick=2

Can you please compare the sequence of C API calls with the above and let me know how should the above program be modified to reproduce the issue ?
[7 Dec 2015 1:00] Bugs System
No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".
[5 Mar 2016 19:00] Ryan Perry
I can confirm this is still an issue with 5.10 on FreeBSD.  It does not seem to be a bug in the perl code.  I would ask you re-check your library code.
[10 Mar 2016 13:48] Georgi Kodinov
I understand it's still an issue, since nothing was done to fix it.
Thus I've provided you with a sample program that demonstrates the correct sequence of calls and asked you to compare it with the one the perl driver is producing. 
I need the C API call sequence in order to reproduce the problem.
[10 Apr 2016 11:11] Daniël van Eeden
Running the test
===============================================================
$ make test TEST_VERBOSE=1 TEST_FILES='t/31insertid.t'
PERL_DL_NONLAZY=1 "/usr/bin/perl" "-MExtUtils::Command::MM" "-MTest::Harness" "-e" "undef *Test::Harness::Switches; test_harness(1, 'blib/lib', 'blib/arch')" t/31insertid.t
t/31insertid.t .. 
1..18
ok 1
ok 2
ok 3 - create dbd_mysql_t31
ok 4
ok 5
ok 6
ok 7 - insert id == 1
ok 8
ok 9
ok 10
ok 11
ok 12
ok 13
ok 14 - sth insert id 2 == max(id) 2  in dbd_mysql_t31
not ok 15 - dbh insert id 0 == max(id) 2 in dbd_mysql_t31

#   Failed test 'dbh insert id 0 == max(id) 2 in dbd_mysql_t31'
#   at t/31insertid.t line 58.
#          got: 0
#     expected: 2
ok 16
ok 17
ok 18
# Looks like you failed 1 test of 18.
Dubious, test returned 1 (wstat 256, 0x100)
Failed 1/18 subtests 

Test Summary Report
-------------------
t/31insertid.t (Wstat: 256 Tests: 18 Failed: 1)
  Failed test:  15
  Non-zero exit status: 1
Files=1, Tests=18,  0 wallclock secs ( 0.02 usr  0.00 sys +  0.04 cusr  0.00 csys =  0.06 CPU)
Result: FAIL
Failed 1/1 test programs. 1/18 subtests failed.
Makefile:1161: recipe for target 'test_dynamic' failed
make: *** [test_dynamic] Error 1
===============================================================

Using tshark to see the network traffic:
===============================================================
# tshark -d tcp.port==5711,mysql -Y mysql -i lo -Tfields -e mysql.insert_id -e mysql.affected_rows -e mysql.query tcp port 5711
Running as user "root" and group "root". This could be dangerous.
Capturing on 'Loopback'
		
		
	0	
		SET @@auto_increment_offset = 1
	0	
		SET @@auto_increment_increment = 1
	0	
		CREATE TEMPORARY TABLE dbd_mysql_t31 (
  id INT(3) PRIMARY KEY AUTO_INCREMENT NOT NULL,
  name VARCHAR(64))

	0	
		INSERT INTO dbd_mysql_t31 (name) VALUES ('Jochen')
1	1	
		INSERT INTO dbd_mysql_t31 (name) VALUES ('Patrick')
2	1	
		SELECT max(id) FROM dbd_mysql_t31
		
		
^C16 packets captured
===============================================================

From ltrace (sudo ltrace -b -f -e 'my*@libmysqlclient.so.20' -o /tmp/ltrace.out make test…)
===============================================================
$ cat /tmp/ltrace.out | egrep -v '[+-]{3}'
14839 libmysqlclient.so.20->mysql_server_init(0, 0, 0, 5711 <unfinished ...>
14839 libmysqlclient.so.20->my_init(0, 0, 0, 5711)                                          = 0
14839 libmysqlclient.so.20->mysql_debug(0, 0x7fccf6789634, 0x8000, 1054)                    = 0
14839 <... mysql_server_init resumed> )                                                     = 0
14839 libmysqlclient.so.20->mysql_options(0x29a0da0, 34, 0x7fcceed14432, 0x2973d40)         = 0
14839 libmysqlclient.so.20->mysql_options(0x29a0da0, 34, 0x7fcceed1443f, 0)                 = 0
14839 libmysqlclient.so.20->mysql_options(0x29a0da0, 34, 0x7fcceed14443, 0)                 = 0
14839 libmysqlclient.so.20->mysql_options(0x29a0da0, 34, 0x7fcceed1444d, 0)                 = 0
14839 libmysqlclient.so.20->mysql_options(0x29a0da0, 34, 0x7fcceed14452, 0)                 = 0
14839 libmysqlclient.so.20->mysql_options(0x29a0da0, 34, 0x7fcceed1445a, 0)                 = 0
14839 libmysqlclient.so.20->mysql_options4(0x29a0da0, 33, 0x7fcceed14432, 0x7fcceed1446a)   = 0
14839 libmysqlclient.so.20->mysql_options4(0x29a0da0, 33, 0x7fcceed1445a, 0x7fcceed13464)   = 0
14839 libmysqlclient.so.20->mysql_options4(0x29a0da0, 33, 0x7fcceed1443f, 0x7fcceed14473)   = 0
14839 libmysqlclient.so.20->mysql_options4(0x29a0da0, 33, 0x7fcceed14443, 0x7fcceed14479)   = 0
14839 libmysqlclient.so.20->mysql_options4(0x29a0da0, 33, 0x7fcceed1444d, 0x7ffe3dccff20)   = 0
14839 libmysqlclient.so.20->mysql_get_option(0, 39, 0x7ffe3dccfd80, 0)                      = 0
14839 libmysqlclient.so.20->mysql_get_option(0, 40, 0x7ffe3dccfd78, 0xfffffffffff64aa0)     = 0
14839 libmysqlclient.so.20->mysql_send_query(0x29a0da0, 0x2968c70, 31, 10)                  = 0
14839 libmysqlclient.so.20->mysql_send_query(0x29a0da0, 0x268f7c0, 34, 10)                  = 0
14839 libmysqlclient.so.20->mysql_send_query(0x29a0da0, 0x253f2e0, 108, 10)                 = 0
14839 libmysqlclient.so.20->mysql_real_escape_string_quote(0x29a0da0, 0x2a5cdaa, 0x2a1cae0, 6) = 6
14839 libmysqlclient.so.20->mysql_send_query(0x29a0da0, 0x2a5cd80, 50, 10)                  = 0
14839 libmysqlclient.so.20->mysql_real_escape_string_quote(0x29a0da0, 0x2a14a5a, 0x2a1cae0, 7) = 7
14839 libmysqlclient.so.20->mysql_send_query(0x29a0da0, 0x2a14a30, 51, 10)                  = 0
14839 libmysqlclient.so.20->mysql_send_query(0x29a0da0, 0x2564ab0, 33, 10)                  = 0
===============================================================
[10 Apr 2016 11:21] Daniël van Eeden
With a more specific ltrace:
sudo ltrace -b -f -e 'mysql_insert_id@mysql.so' -e 'mysql_send_query@libmysqlclient.so.20' -o /tmp/ltrace.out make …

$ cat /tmp/ltrace.out | egrep -v '[+-]{3}'
15402 libmysqlclient.so.20->mysql_send_query(0x182dcf0, 0x17f5bb0, 31, 10)                  = 0
15402 libmysqlclient.so.20->mysql_send_query(0x182dcf0, 0x14c3630, 34, 10)                  = 0
15402 libmysqlclient.so.20->mysql_send_query(0x182dcf0, 0x13cc2e0, 108, 10)                 = 0
15402 libmysqlclient.so.20->mysql_send_query(0x182dcf0, 0x18e9ce0, 50, 10)                  = 0
15402 mysql.so->mysql_insert_id(0x182dcf0, 0x7fb7a35fcb70, 0x182dcf0, 0)                    = 1
15402 mysql.so->mysql_insert_id(0x182dcf0, 0x18a162f, 0x7fb79bebbe90, 0)                    = 1
15402 mysql.so->mysql_insert_id(0x182dcf0, 0x18a15af, 0x7fb79bebbe90, 0)                    = 1
15402 libmysqlclient.so.20->mysql_send_query(0x182dcf0, 0x18a1950, 51, 10)                  = 0
15402 mysql.so->mysql_insert_id(0x182dcf0, 0x7fb7a35fcb78, 0x182dcf0, 0)                    = 2
15402 libmysqlclient.so.20->mysql_send_query(0x182dcf0, 0x13f1b10, 33, 10)                  = 0
15402 mysql.so->mysql_insert_id(0x182dcf0, 0x18a162f, 0x7fb79bebbe90, 0)                    = 0
15402 mysql.so->mysql_insert_id(0x182dcf0, 0x181cc3f, 0x7fb79bebbe90, 0)                    = 0
[10 Apr 2016 13:04] Michiel Beijen
Daniël, thanks for stepping in. If I'm not mistaken you only attached 5.7 logs. Is there a difference in the trace between the 5.7.8 client and older clients? And is the difference in the data sent from the client or also in the replies from the server?
[28 Jul 2016 14:28] Vladimir Marek
Truss output from 5.6 (successfull) run

Attachment: 5.6.good.txt (text/plain), 150.21 KiB.

[28 Jul 2016 14:28] Vladimir Marek
Truss output from 5.7 (fail) run

Attachment: 5.7.bad.txt (text/plain), 278.66 KiB.

[28 Jul 2016 14:39] Vladimir Marek
Hi,

I'm porting DBD::mysql to Solaris and I found this issue too. I am attaching
truss output of good and bad run. Franky, I can't make any sense of the
difference though. I have modified both output so that it's easier comparable
by vim -d (made some pointers into symbolic name).

You can find the problem by looing for '=='. mysql_insert_id just before that
returns 0.

I know it would be great to have also info on what statements have been
executed, I'll work on providing that. Is it enough to collect what strings
have been passed to mysql_real_query ?

BTW there is corresponding bug against DBD::mysql where I entered my observations too.

https://rt.cpan.org/Public/Bug/Display.html?id=108000

Thank you
__ 
  Vlad
[1 Aug 2016 11:38] Vladimir Marek
The new behaviour of mysql 5.7 is accepted by DBD::mysql perl module. The author
says

"An INSERT statement is executed on the database handle. Subsequently, on the
same database handle, a SELECT is performed. Now $dbh->{mysql_insertid} is 0 on
the database handle; when compiled against libmysqlclient 5.7 or up. That
actually seems more correct to me, although it is of course a change in
behavior when compared to earlier versions of libmysqlclient."

Since we are in the same company I can give you easily Solaris machine with
reproducible case if it helps anything. It would be great to have confirmed
from your side that this is expected behavior. And maybe a little test so that
the behavior does not change in the future.

Many thanks!

__ 
  Vlad
[1 Aug 2016 16:07] Michiel Beijen
What I found is the sample by Georgi Kodinov does not represent the test suite. In the test suite, an additional query is executed on the statement handle:

   SELECT max(id) FROM dbd_mysql_t31;
 
And only after this the value of mysql_insertid is now 0, when using 5.7.x libmysqlclient. For earlier versions, the value of mysql_insertid was still available.
[14 Sep 2016 12:51] Georgi Kodinov
Ok, I was able to reproduce the problem using the following program:
------------------
  if (!mysql_real_connect(&con, "localhost", "root", "", "xx", 3306, NULL, 0))
  {
    fprintf(stderr, "mysql_real_connect failed: %s\n", mysql_error(&con));
    exit(1);
  }

  char *stmt= "INSERT INTO dbd_mysql_t31 (name) VALUES ('Jochen')";

  if (mysql_query(&con, stmt))
  {
    fprintf(stderr, "mysql_query INSERT failed: %s\n", mysql_error(&con));
    exit(1);
  }

  iid= (unsigned) mysql_insert_id(&con);
  printf("iid after Jochen=%u\n", iid);

  if (mysql_query(&con, "SELECT max(id) FROM dbd_mysql_t31"))
  {
    fprintf(stderr, "mysql_query SELECT failed: %s\n", mysql_error(&con));
    exit(1);
  }

  mysql_free_result(mysql_store_result(&con));

  iid= (unsigned) mysql_insert_id(&con);
  printf("iid after the SELECT=%u\n", iid);

  mysql_close(&con);
-------------------------

This prints:
iid after Jochen=4
iid after the SELECT=0

FYI, this does not happen with the server's LAST_INSERT_ID() function. It stays the same even after a SELECT.
[14 Sep 2016 13:18] Georgi Kodinov
Also reproducible with mysql. 

5.6: 

mysql> \s
--------------
..\client\debug\mysql  Ver 14.14 Distrib 5.6.33, for Win64 (x86_64)

Connection id:          1
Current database:       xx
Current user:           root@localhost
SSL:                    Not in use
Using delimiter:        ;
Server version:         5.6.33-debug-log Source distribution
Protocol version:       10
Connection:             localhost via TCP/IP
Server characterset:    latin1
Db     characterset:    latin1
Client characterset:    cp850
Conn.  characterset:    cp850
TCP port:               13000
Uptime:                 1 min 10 sec

Threads: 1  Questions: 10  Slow queries: 0  Opens: 70  Flush tables: 1  Open tables: 63  Queries per second avg: 0.142
--------------

mysql> insert into dbd_mysql_t31 (name) values ('haha');
--------------
insert into dbd_mysql_t31 (name) values ('haha')
--------------

Query OK, 1 row affected (0.01 sec)

mysql> \s
--------------
..\client\debug\mysql  Ver 14.14 Distrib 5.6.33, for Win64 (x86_64)

Connection id:          1
Current database:       xx
Current user:           root@localhost
SSL:                    Not in use
Using delimiter:        ;
Server version:         5.6.33-debug-log Source distribution
Protocol version:       10
Connection:             localhost via TCP/IP
Insert id:              7
Server characterset:    latin1
Db     characterset:    latin1
Client characterset:    cp850
Conn.  characterset:    cp850
TCP port:               13000
Uptime:                 1 min 27 sec

Threads: 1  Questions: 14  Slow queries: 0  Opens: 71  Flush tables: 1  Open tables: 64  Queries per second avg: 0.160
--------------

5.7:

mysql> \s
--------------
client\Debug\mysql.exe  Ver 14.14 Distrib 8.0.1-dmr, for Win64 (x86_64)

Connection id:          4
Current database:       xx
Current user:           root@localhost
SSL:                    Not in use
Using delimiter:        ;
Server version:         8.0.1-dmr-debug Source distribution
Protocol version:       10
Connection:             localhost via TCP/IP
Server characterset:    latin1
Db     characterset:    latin1
Client characterset:    cp850
Conn.  characterset:    cp850
TCP port:               3306
Uptime:                 3 min 30 sec

Threads: 1  Questions: 6  Slow queries: 0  Opens: 163  Flush tables: 2  Open tables: 139  Queries per second avg: 0.028
--------------

mysql> insert into dbd_mysql_t31 (name) values ('haha');
Query OK, 1 row affected (0.01 sec)

mysql> \s
--------------
client\Debug\mysql.exe  Ver 14.14 Distrib 8.0.1-dmr, for Win64 (x86_64)

Connection id:          4
Current database:       xx
Current user:           root@localhost
SSL:                    Not in use
Using delimiter:        ;
Server version:         8.0.1-dmr-debug Source distribution
Protocol version:       10
Connection:             localhost via TCP/IP
Server characterset:    latin1
Db     characterset:    latin1
Client characterset:    cp850
Conn.  characterset:    cp850
TCP port:               3306
Uptime:                 3 min 37 sec

Threads: 1  Questions: 10  Slow queries: 0  Opens: 163  Flush tables: 2  Open tables: 139  Queries per second avg: 0.046
--------------

Note the absence of Insert id:
[3 Mar 2017 1:51] Paul Dubois
Posted by developer:
 
Noted in 5.7.18, 8.0.1 changelogs.

After performing inserts in a table containing an AUTO_INCREMENT
column and then performing a SELECT operation, the LAST_INSERT_ID()
returns the correct value, but the value of the mysql_insert_id() C
API function was being reset to 0.
[11 Apr 2017 7:15] Daniël van Eeden
commit 06484eda0bf3e80530fd9762a0b1159f629c85dd
Author: Anushree Prakash B <anushree.prakash.b@oracle.com>
Date:   Mon Feb 20 14:02:14 2017 +0530

    BUG#22028117 - MYSQLCLIENT DOES NOT RETURN CORRECT
                   MYSQL_INSERT_ID VIA DATABASE HANDLE
    
    DESCRIPTION
    ===========
    mysql_insert_id() does not return correct values after
    performing inserts in a table containing an AUTO_INCREMENT
    field and then performing a SELECT operation.
    The value of insert_id is getting reset to 0 after
    performing SELECT. However, LAST_INSERT_ID() gives the
    correct value.
    
    ANALYSIS
    ========
    An OK packet is sent from the server to the client to
    signal successful completion of a command.
    As of MySQL 5.7.5, OK packes are also used to indicate EOF,
    as EOF packets are deprecated. The packet identifier 0x00
    represents an OK packet whereas the packet identifier OxFE
    represents an EOF packet. The EOF packet has valid values
    for the following fields: packet header, warnings and
    server status. The fields affected_rows and insert_id will
    have valid values only if it was an OK packet and not for
    an EOF packet. Reading the values of the above two fields
    for an EOF packet will result in inconsistent values being
    assigned to the connection handle.
    
    FIX
    ====
    The fix is to assign the affected_rows and insert_id fields
    to the connection handle only if they were read from an OK
    packet. In case of an EOF packet, skip the assignment and
    proceed to the next valid fields. This way we can make sure
    that they don't get wrongly updated in the connection
    handle.

 sql-common/client.c             | 29 ++++++++++++++++++++++-------
 testclients/mysql_client_test.c | 71 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
 2 files changed, 93 insertions(+), 7 deletions(-)