Bug #97625 for DBD-mysql: use-after-free in mysql_dr_error

On Wed Jul 30 13:02:12 2014, RURBAN wrote: Show quoted text
Nope, imp_dbh->pmysql is freed seperately later in dbd_db_destroy(). The fail login free needs to happen at the end of my_login. The patch is on github as pull request #26 -- Reini Urban

Hi there! thank you very much! I need to see why it fails here: https://travis-ci.org/perl5-dbi/DBD-mysql/builds/31262431 I think it might be completely unrelated to your changes. I need to spin up a Docker container with perl 5.8 and see if I can reproduce the error. On Wed Jul 30 14:09:24 2014, RURBAN wrote: Show quoted text

On Fri Aug 01 09:29:10 2014, CAPTTOFU wrote: Show quoted text
It can be reproduced on every single perl version, and there are still remaining errors. My PR #26 only fixed one instance of the problem. travis fails here because of a bad test with failed login. This tests needs to be improved still. Another reproducer with mysql_auto_reconnect is this: system(qw(sudo service mysql start)); use DBI; my $dbh = DBI->connect("DBI:mysql:database=test:port=3306"); $dbh->{mysql_auto_reconnect} = 1; # without this is works my $select = sub { $dbh->do(q{SELECT 1}) for 1 .. 10; }; $select->(); system qw(sudo service mysql stop); $select->(); ok(1, "dbh did not crash on closed connection"); system(qw(sudo service mysql start)); restarting the service is of course system dependent. I could not repro it with a KILL me sub, like this: sub killme { my $dbh = shift; my $sth = $dbh->prepare("SHOW FULL PROCESSLIST"); $sth->execute(); while (my $ps = $sth->fetchrow_hashref()) { my $process_id = $ps->{Id}; if ($ENV{USER}) { if ($ps->{User} eq $ENV{USER} and $ps->{Time} < 20) { diag "killme $process_id"; $dbh->do("KILL $process_id"); } } else { if ($ps->{Time} < 20) { diag "killme $process_id"; $dbh->do("KILL $process_id"); } } } } because then DESTROY handles the cleanup properly. The big problem with lost connections is that business logic wants to keep reporting errors to a file in case of lost server connections. This is related to RT #85919, though the root cause is this use-after free here. With asan you e.g. see that's a heap-use-after-free: $ sudo service mysql start; pb -e'use DBI; my $dbh = DBI->connect("dbi:mysql:database=test:port=3306"); $dbh->{mysql_auto_reconnect} = 1; my $stmt = sub { $dbh->do(q{SELECT 1}) for 1 .. 10; }; $stmt->(); system qw(sudo service mysql stop); $stmt->()'; sudo service mysql start [ ok ] Starting MySQL database server: mysqld already running. [ ok ] Stopping MySQL database server: mysqld. ================================================================= ==4163== ERROR: AddressSanitizer: heap-use-after-free on address 0x7f339bc1a0d7 at pc 0x41549a bp 0x7fff42cbd490 sp 0x7fff42cbd470 READ of size 1 at 0x7f339bc1a0d7 thread T0 #0 0x415499 in strlen (/usr/local/bin/perl5.14.4d-nt-asan+0x415499) #1 0x7f339dc0d116 in Perl_sv_setpv /home/rurban/Perl/src/build-5.14.4d-nt-asan/sv.c:4568 #2 0x7f339a8f317d in mysql_dr_error /home/rurban/Perl/DBD-mysql/dbdimp.c:1441 #3 0x7f339a937d07 in mysql_db_reconnect /home/rurban/Perl/DBD-mysql/dbdimp.c:4911 #4 0x7f339a92f05d in mysql_st_internal_execute /home/rurban/Perl/DBD-mysql/dbdimp.c:3304 #5 0x7f339a9a3ab1 in XS_DBD__mysql__db_do /home/rurban/Perl/DBD-mysql/mysql.xs:532 #6 0x7f339b3e23e1 in XS_DBI_dispatch /home/rurban/.cpan/build/DBI-1.628-SjeX_f/DBI.xs:3715 #7 0x7f339da81566 in Perl_pp_entersub /home/rurban/Perl/src/build-5.14.4d-nt-asan/pp_hot.c:3046 #8 0x7f339d729357 in Perl_runops_debug /home/rurban/Perl/src/build-5.14.4d-nt-asan/dump.c:2266 #9 0x7f339d1807d4 in S_run_body /home/rurban/Perl/src/build-5.14.4d-nt-asan/perl.c:2366 #10 0x7f339d17c04e in perl_run /home/rurban/Perl/src/build-5.14.4d-nt-asan/perl.c:2284 #11 0x408916 in main /home/rurban/Perl/src/build-5.14.4d-nt-asan/perlmain.c:120 #12 0x7f339c087b44 (/lib/x86_64-linux-gnu/libc.so.6+0x21b44) 0x7f339bc1a0d7 is located 151 bytes inside of 1272-byte region [0x7f339bc1a040,0x7f339bc1a538) freed by thread T0 here: previously allocated by thread T0 here: Shadow byte and word: 0x1fe67378341a: fd 0x1fe673783418: fd fd fd fd fd fd fd fd More shadow bytes: 0x1fe6737833f8: fa fa fa fa fa fa fa fa 0x1fe673783400: fa fa fa fa fa fa fa fa 0x1fe673783408: fd fd fd fd fd fd fd fd 0x1fe673783410: fd fd fd fd fd fd fd fd =>0x1fe673783418: fd fd fd fd fd fd fd fd 0x1fe673783420: fd fd fd fd fd fd fd fd 0x1fe673783428: fd fd fd fd fd fd fd fd 0x1fe673783430: fd fd fd fd fd fd fd fd 0x1fe673783438: fd fd fd fd fd fd fd fd Stats: 4M malloced (6M for red zones) by 55806 calls Stats: 0M realloced by 2899 calls Stats: 1M freed by 26103 calls Stats: 0M really freed by 0 calls Stats: 14M (3593 full pages) mmaped in 28 calls mmaps by size class: 7:49140; 8:8188; 9:1023; 10:511; 1 valgrind reports the invalid free as: ==12942== Invalid free() / delete / delete[] / realloc() ==12942== at 0x40282F4: free (vg_replace_malloc.c:446) ==12942== by 0x51172F: Perl_safesysfree (util.c:284) ==12942== by 0x6BCBEB5: my_login (dbdimp.c:2052) ==12942== by 0x6BD458D: mysql_db_reconnect (dbdimp.c:4908) ==12942== by 0x6BD019F: mysql_st_internal_execute (dbdimp.c:3304) ==12942== by 0x6BDE922: XS_DBD__mysql__db_do (mysql.xs:532) ==12942== by 0x5F691FF: XS_DBI_dispatch (DBI.xs:3746) ==12942== by 0x57C4AB: Perl_pp_entersub (pp_hot.c:3046) ==12942== by 0x510BC2: Perl_runops_debug (dump.c:2266) ==12942== by 0x44BB39: S_run_body (perl.c:2366) ==12942== by 0x44AF02: perl_run (perl.c:2284) ==12942== by 0x41C4BC: main (perlmain.c:120) ==12942== Address 0x68557f0 is 0 bytes inside a block of size 1,272 free'd ==12942== at 0x40282F4: free (vg_replace_malloc.c:446) ==12942== by 0x51172F: Perl_safesysfree (util.c:284) ==12942== by 0x6BCBEB5: my_login (dbdimp.c:2052) ==12942== by 0x6BD458D: mysql_db_reconnect (dbdimp.c:4908) ==12942== by 0x6BD019F: mysql_st_internal_execute (dbdimp.c:3304) ==12942== by 0x6BDE922: XS_DBD__mysql__db_do (mysql.xs:532) ==12942== by 0x5F691FF: XS_DBI_dispatch (DBI.xs:3746) ==12942== by 0x57C4AB: Perl_pp_entersub (pp_hot.c:3046) ==12942== by 0x510BC2: Perl_runops_debug (dump.c:2266) ==12942== by 0x44BB39: S_run_body (perl.c:2366) ==12942== by 0x44AF02: perl_run (perl.c:2284) ==12942== by 0x41C4BC: main (perlmain.c:120) and more invalid writes as: ==12942== Invalid write of size 8 ==12942== at 0x6E1C4C6: ??? (in /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18.0.0) ==12942== by 0x6E1F76C: mysql_real_connect (in /usr/lib/x86_64-linux-gnu/libmysqlclient.so.18.0.0) ==12942== by 0x6BCBA2F: mysql_dr_connect (dbdimp.c:1924) ==12942== by 0x6BCBE8C: my_login (dbdimp.c:2049) ==12942== by 0x6BD458D: mysql_db_reconnect (dbdimp.c:4908) ==12942== by 0x6BD019F: mysql_st_internal_execute (dbdimp.c:3304) ==12942== by 0x6BDE922: XS_DBD__mysql__db_do (mysql.xs:532) ==12942== by 0x5F691FF: XS_DBI_dispatch (DBI.xs:3746) ==12942== by 0x57C4AB: Perl_pp_entersub (pp_hot.c:3046) ==12942== by 0x510BC2: Perl_runops_debug (dump.c:2266) ==12942== by 0x44BB39: S_run_body (perl.c:2366) ==12942== by 0x44AF02: perl_run (perl.c:2284) ==12942== Address 0x6855b80 is 912 bytes inside a block of size 1,272 free'd ==12942== at 0x40282F4: free (vg_replace_malloc.c:446) ==12942== by 0x51172F: Perl_safesysfree (util.c:284) ==12942== by 0x6BCBEB5: my_login (dbdimp.c:2052) ==12942== by 0x6BD458D: mysql_db_reconnect (dbdimp.c:4908) ==12942== by 0x6BD019F: mysql_st_internal_execute (dbdimp.c:3304) ==12942== by 0x6BDE922: XS_DBD__mysql__db_do (mysql.xs:532) ==12942== by 0x5F691FF: XS_DBI_dispatch (DBI.xs:3746) ==12942== by 0x57C4AB: Perl_pp_entersub (pp_hot.c:3046) ==12942== by 0x510BC2: Perl_runops_debug (dump.c:2266) ==12942== by 0x44BB39: S_run_body (perl.c:2366) ==12942== by 0x44AF02: perl_run (perl.c:2284) ==12942== by 0x41C4BC: main (perlmain.c:120) So the my_login logic needs to be something like: --- dbdimp.c +++ dbdimp.c @@ -1995,7 +1995,7 @@ static int my_login(pTHX_ SV* dbh, imp_dbh_t *imp_dbh) char* user; char* password; char* mysql_socket; - int result; + int result, fresh; D_imp_xxh(dbh); /* TODO- resolve this so that it is set only if DBI is 1.607 */ @@ -2044,12 +2044,15 @@ static int my_login(pTHX_ SV* dbh, imp_dbh_t *imp_dbh) port ? port : "NULL"); if (!imp_dbh->pmysql) { + fresh = 1; Newz(908, imp_dbh->pmysql, 1, MYSQL); } result = mysql_dr_connect(dbh, imp_dbh->pmysql, mysql_socket, host, port, user, password, dbname, imp_dbh) ? TRUE : FALSE; - if (!result) + if (fresh && !result) { + /* Prevent leaks, but do not free in case of a reconnect. See #97625 */ Safefree(imp_dbh->pmysql); + } return result; } but this is still not good enough. Show quoted text
-- Reini Urban

4.029 release contains this fix - thank you!