Bug #43005 main.init_connect fails on Windows due to wrong quoting of args
Submitted: 19 Feb 2009 8:54 Modified: 17 Jun 2010 19:29
Reporter: Alexander Nozdrin Email Updates:
Status: Closed Impact on me:
None 
Category:Tools: MTR / mysql-test-run Severity:S2 (Serious)
Version:6.0-TRUNK, 5.1-TRUNK OS:Microsoft Windows
Assigned to: Bjørn Munch
Tags: pb2, sporadic, test failure, tf54
Triage: Triaged: D3 (Medium)

[19 Feb 2009 8:54] Alexander Nozdrin
Description:
Symptoms:
--------------------------------------------------------
CURRENT_TEST: main.init_connect
090217 15:51:48 [Warning] The syntax '--log' is deprecated and will be removed in MySQL 7.0. Please use '--general-log --general-log-file' instead.
090217 15:51:48 [Warning] The syntax '--log-slow-queries' is deprecated and will be removed in MySQL 7.0. Please use '--slow-query-log'/'--slow-query-log-file' instead.
090217 15:51:48 [Note] Plugin 'InnoDB' disabled by command line option
090217 15:51:48 [Note] Falcon: unable to open system data files.
090217 15:51:48 [Note] Falcon: creating new system data files.
090217 15:51:49 [Warning] G:/pb2/test/sb_1-333153-1234874438.38/mysql-6.0.10-alpha-win-x86-test/sql/relwithdebinfo/mysqld.exe: unknown variable 'loose-debug-sync-timeout=300'
G:/pb2/test/sb_1-333153-1234874438.38/mysql-6.0.10-alpha-win-x86-test/sql/relwithdebinfo/mysqld.exe: Too many arguments (first extra is '@a='a\0c'').
Use --verbose --help to get a list of available options
090217 15:51:49 [ERROR] Aborting

090217 15:51:51 [Warning] Forcing shutdown of 2 plugins
090217 15:51:51 [Note] G:/pb2/test/sb_1-333153-1234874438.38/mysql-6.0.10-alpha-win-x86-test/sql/relwithdebinfo/mysqld.exe: Shutdown complete
--------------------------------------------------------

Reported after a failure on 2009-02-17 in 6.0 main.

How to repeat:
XRef2: http://tinyurl.com/ctvo39
[23 Jun 2009 6:46] Georgi Kodinov
Also happens in 5.1. Please re-triage.
[1 Jul 2009 14:59] Lars Heill
Raising priority and severity.  Adding reviewer, who might also weigh in with an evaluation (assignee on vacation almost two weeks more).
[7 Jul 2009 13:56] Magnus Blåudd
The init_connect.test has a related init_connect-master.opt file which contain extra arguments to use when starting the mysqld. 

~/mysql/5.1$ cat mysql-test/t/init_connect-master.opt 
--set-variable=init_connect="set @a='a\\0c'"

Apparently the quoting is no longer working correctly after we switched to use ActiveState perl on windows.

The options are read from .opt file in the function 'process_opts_file' in mysql-test/lib/mtr_cases.pm and then later appended to the arguments used to start the mysqld. It's probably in the latter plave that the argument quoting need to be changed somehow.
[15 Jul 2009 11:30] Bjørn Munch
No, there's nothing wrong with the parsing and MTR actually protects the argument in "s if it contains a space, on Windows. I couldn't find out how but it does, and this is also correctly handled by system() in ActiveState Perl.

No, it's safe_process_win which is to blame, as it concatenates all the arguments into a single string to pass on to CreateProcess, by this time the "s have been stripped and would have to be re-applied.

Working on this now.
[15 Jul 2009 13:24] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/78735

2806 Bjorn Munch	2009-07-15
      Bug #43005 main.init_connect fais on Windows in PB2
      Server args containing spaces do not work on Windows
      Fixed my_safe_rprocess-win to re-apply "" around such args
[15 Jul 2009 18:28] Bjørn Munch
Pushed to 5.1-mtr
[3 Sep 2009 17:12] Bugs System
Pushed into 5.1.40 (revid:bjorn.munch@sun.com-20090903170735-679d64zp580wl39j) (version source revid:bjorn.munch@sun.com-20090903170735-679d64zp580wl39j) (merge vers: 5.1.40) (pib:11)
[4 Sep 2009 0:47] Paul Dubois
Test suite change. No changelog entry needed.

Setting report to NDI pending push into 5.4.x.
[30 Sep 2009 8:18] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20090929093622-1mooerbh12e97zux) (version source revid:alik@sun.com-20090922182109-vs5ign07cwht12z6) (merge vers: 6.0.14-alpha) (pib:11)
[30 Sep 2009 8:20] Bugs System
Pushed into 5.4.5-beta (revid:alik@sun.com-20090925094254-tjl9eajkzwzgthoe) (version source revid:alik@sun.com-20090922142453-x275o41whpyezh4q) (merge vers: 5.4.4-beta) (pib:11)
[30 Sep 2009 19:36] Paul Dubois
Test suite change. No changelog entry needed.
[21 Oct 2009 15:40] Joerg Bruehe
Sorry for the bad news, but the above change does not fix it:
This bug still occurs in the build of 5.1.40 (44 times),
and the fix is really contained in the sources.

Setting it back to "verified".
[18 Dec 2009 10:40] Bugs System
Pushed into 5.1.41-ndb-7.1.0 (revid:jonas@mysql.com-20091218102229-64tk47xonu3dv6r6) (version source revid:jonas@mysql.com-20091218095730-26gwjidfsdw45dto) (merge vers: 5.1.41-ndb-7.1.0) (pib:15)
[18 Dec 2009 10:55] Bugs System
Pushed into 5.1.41-ndb-6.2.19 (revid:jonas@mysql.com-20091218100224-vtzr0fahhsuhjsmt) (version source revid:jonas@mysql.com-20091217101452-qwzyaig50w74xmye) (merge vers: 5.1.41-ndb-6.2.19) (pib:15)
[18 Dec 2009 11:10] Bugs System
Pushed into 5.1.41-ndb-6.3.31 (revid:jonas@mysql.com-20091218100616-75d9tek96o6ob6k0) (version source revid:jonas@mysql.com-20091217154335-290no45qdins5bwo) (merge vers: 5.1.41-ndb-6.3.31) (pib:15)
[18 Dec 2009 11:24] Bugs System
Pushed into 5.1.41-ndb-7.0.11 (revid:jonas@mysql.com-20091218101303-ga32mrnr15jsa606) (version source revid:jonas@mysql.com-20091218064304-ezreonykd9f4kelk) (merge vers: 5.1.41-ndb-7.0.11) (pib:15)
[21 Dec 2009 16:17] Magnus Blåudd
Unfortunately the fix for this bug broke running with cygwins perl.

$ ./mysql-test-run-pl init_connect --verbose --verbose
<snip>
worker[1] > Generating my.cnf from 'include/default_my.cnf'
worker[1] > MASTER_MYPORT = 13000
worker[1] > MASTER_MYSOCK = c:/mysql/7.0/mysql-test/var/tmp/mysqld.1.sock
worker[1] > mysqld_start:  [' --loose-skip-innodb', '--loose-skip-log-bin', '--set-variable=init_connect=set @a='a\0c' ']

### safe_path: ./lib/My/SafeProcess/relwithdebinfo/my_safe_process.exe --verbose --parent-pid=2644 -- c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe --defaults-group-suffix=.1 --defaults-file=c:/mysql/7.0/mysql-test/var/my.cnf --log-output=file --loose-skip-innodb --loose-skip-log-bin "--set-variable=init_connect=set @a='a\0c'" --core-file --loose-debug-sync-timeout=300 --console
worker[1] > Started [mysqld.1 - pid: 2396, winpid: 2396]
worker[1] mysql-test-run: WARNING: Process [mysqld.1 - pid: 2396, winpid: 2396, exit: 256] died
worker[1] > Stopping all servers...
worker[1] Saving datadirs...
worker[1]  - saving 'c:/mysql/7.0/mysql-test/var/mysqld.1'
worker[1] main.init_connect                        worker[1] [ fail ]
        Test ended at 2009-12-21 19:14:40
worker[1] 
Server log is:
safe_process[4064]: parent_pid: 2644
safe_process[4064]: Started child 2368
091221 19:14:40 [Note] Plugin 'FEDERATED' is disabled.
091221 19:14:40 [Note] Plugin 'InnoDB' is disabled.
091221 19:14:40 [Note] Plugin 'ndbcluster' is disabled.
091221 19:14:40 [Warning] c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe: unknown variable 'loose-debug-sync-timeout=300'
c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe: Too many arguments (first extra is '@a='a\0c'').
Use --verbose --help to get a list of available options
091221 19:14:40 [ERROR] Aborting

091221 19:14:40 [Note] c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe: Shutdown complete

safe_process[4064]: Child exit: exit_code: 1
safe_process[4064]: Exiting, child: 2368
safe_process[4064]: Job terminated and closed
safe_process[4064]: Closing handles
safe_process[4064]: Exiting, exit_code: 1

worker[1] 
Failed to start mysqld.1

main.init_connect                        [ fail ]
        Test ended at 2009-12-21 17:14:40

Server log is:
safe_process[4064]: parent_pid: 2644
safe_process[4064]: Started child 2368
091221 19:14:40 [Note] Plugin 'FEDERATED' is disabled.
091221 19:14:40 [Note] Plugin 'InnoDB' is disabled.
091221 19:14:40 [Note] Plugin 'ndbcluster' is disabled.
091221 19:14:40 [Warning] c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe: unknown variable 'loose-debug-sync-timeout=300'
c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe: Too many arguments (first extra is '@a='a\0c'').
Use --verbose --help to get a list of available options
091221 19:14:40 [ERROR] Aborting

091221 19:14:40 [Note] c:/mysql/7.0/sql/relwithdebinfo/mysqld.exe: Shutdown complete

safe_process[4064]: Child exit: exit_code: 1
safe_process[4064]: Exiting, child: 2368
safe_process[4064]: Job terminated and closed
safe_process[4064]: Closing handles
safe_process[4064]: Exiting, exit_code: 1
[21 Dec 2009 19:21] Magnus Blåudd
The arguments are already quoted properly when mtr.pl runs my_safe_process <args>.  But unfortunately the quotes are lost with active state perl and stays with cygwin. Thus the check for "does this arg contain a space" inside safe_process_win.cc should also check "not already quoted"
[21 Dec 2009 19:53] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/95310

3304 Magnus Blaudd	2009-12-21
      Bug#43005 main.init_connect fails on Windows due to wrong quoting of args
      - The arguments are properly quoted when mtr.pl calls my_safe_process but
        unfortunately the all off when running with active state perl and stays
        in cygwin perl.
      - Extend the patch to only quote args that are not already quoted
[22 Dec 2009 9:26] Bjørn Munch
Your patch looks good to me, I presume you've tested it and found it solves the problem, and that it also works with ActiveState perl?
[19 Jan 2010 8:50] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/97327

2876 Bjorn Munch	2010-01-19
      Bug#43005 main.init_connect fails on Windows due to wrong quoting of args
      - The arguments are properly quoted when mtr.pl calls my_safe_process but
        unfortunately the all off when running with active state perl and stays
        in cygwin perl.
      - Extend the patch to only quote args that are not already quoted
      This a redo of previous commit, will be included in next push
[20 Jan 2010 15:54] Bjørn Munch
(Re)pushed to 5.1-mtr, trunk-mtr, next-mr-mtr, 6.0-codebase-mtr
[11 Feb 2010 10:33] Magnus Blåudd
Patch OK
[20 Feb 2010 9:32] Bugs System
Pushed into 6.0.14-alpha (revid:alik@sun.com-20100220092844-jh07ayojyxn8uh9p) (version source revid:bjorn.munch@sun.com-20100120153513-b70e3bs7e06jfvf3) (merge vers: 6.0.14-alpha) (pib:16)
[20 Feb 2010 9:34] Bugs System
Pushed into 5.5.3-m2 (revid:alik@sun.com-20100220092622-wvhh1vfy5tjq4mhu) (version source revid:bjorn.munch@sun.com-20100120133748-0aiuazzbcqje8my0) (merge vers: 5.5.1-m2) (pib:16)
[20 Feb 2010 9:37] Bugs System
Pushed into mysql-next-mr (revid:alik@sun.com-20100220092730-paoo5t9gcajs5dq8) (version source revid:bjorn.munch@sun.com-20100120154314-icr9oiinm588c3sk) (pib:16)
[20 Feb 2010 18:37] Paul Dubois
No changelog entry needed.

Setting report to Need Merge pending push to 5.1.x.
[1 Mar 2010 8:47] Bugs System
Pushed into 5.1.45 (revid:joro@sun.com-20100301083827-xnimmrjg6bh33o1o) (version source revid:azundris@mysql.com-20100222175719-viuh0f3gdsrkgv0r) (merge vers: 5.1.45) (pib:16)
[1 Mar 2010 15:52] Paul Dubois
No changelog entry needed.
[9 Jun 2010 14:12] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/110637

3103 Martin Skold	2010-06-09 [merge]
      Merged in 5.1.45
      added:
        mysql-test/include/not_binlog_format_row.inc
        mysql-test/r/bug39022.result
        mysql-test/r/no_binlog.result
        mysql-test/r/partition_debug_sync.result
        mysql-test/std_data/bug48449.frm
        mysql-test/suite/rpl/r/rpl_slow_query_log.result
        mysql-test/suite/rpl/t/rpl_slow_query_log-slave.opt
        mysql-test/suite/rpl/t/rpl_slow_query_log.test
        mysql-test/t/bug39022.test
        mysql-test/t/no_binlog.test
        mysql-test/t/partition_debug_sync.test
      renamed:
        mysql-test/r/variables+c.result => mysql-test/r/variables_community.result
        mysql-test/t/variables+c.test => mysql-test/t/variables_community.test
      modified:
        client/mysql.cc
        client/mysql_upgrade.c
        client/mysqladmin.cc
        client/mysqlbinlog.cc
        client/mysqlcheck.c
        client/mysqldump.c
        client/mysqlimport.c
        client/mysqlshow.c
        client/mysqlslap.c
        client/mysqltest.cc
        cmd-line-utils/readline/rlmbutil.h
        cmd-line-utils/readline/text.c
        configure.in
        extra/yassl/include/yassl_error.hpp
        extra/yassl/src/ssl.cpp
        extra/yassl/src/yassl_error.cpp
        mysql-test/include/mtr_warnings.sql
        mysql-test/lib/My/ConfigFactory.pm
        mysql-test/lib/My/SafeProcess.pm
        mysql-test/lib/My/SafeProcess/safe_process_win.cc
        mysql-test/lib/mtr_cases.pm
        mysql-test/lib/mtr_gprof.pl
        mysql-test/lib/mtr_misc.pl
        mysql-test/lib/mtr_report.pm
        mysql-test/lib/mtr_stress.pl
        mysql-test/lib/v1/mtr_stress.pl
        mysql-test/lib/v1/mysql-test-run.pl
        mysql-test/mysql-test-run.pl
        mysql-test/r/archive.result
        mysql-test/r/backup.result
        mysql-test/r/bigint.result
        mysql-test/r/csv.result
        mysql-test/r/default.result
        mysql-test/r/delete.result
        mysql-test/r/fulltext.result
        mysql-test/r/func_gconcat.result
        mysql-test/r/func_time.result
        mysql-test/r/group_by.result
        mysql-test/r/group_min_max.result
        mysql-test/r/having.result
        mysql-test/r/innodb-autoinc.result
        mysql-test/r/innodb_mysql.result
        mysql-test/r/join.result
        mysql-test/r/log_state.result
        mysql-test/r/multi_update.result
        mysql-test/r/myisam.result
        mysql-test/r/mysqltest.result
        mysql-test/r/show_check.result
        mysql-test/r/sp-bugs.result
        mysql-test/r/sp-error.result
        mysql-test/r/sp.result
        mysql-test/r/sp_notembedded.result
        mysql-test/r/sp_trans.result
        mysql-test/r/subselect.result
        mysql-test/r/type_bit.result
        mysql-test/r/type_blob.result
        mysql-test/r/type_timestamp.result
        mysql-test/r/view.result
        mysql-test/r/view_grant.result
        mysql-test/r/warnings.result
        mysql-test/suite/rpl/r/rpl_sp.result
        mysql-test/suite/rpl/t/rpl_loaddata_symlink.test
        mysql-test/suite/sys_vars/r/log_basic.result
        mysql-test/suite/sys_vars/r/log_bin_trust_routine_creators_basic.result
        mysql-test/suite/sys_vars/r/slow_query_log_func.result
        mysql-test/suite/sys_vars/t/slow_query_log_func.test
        mysql-test/t/archive.test
        mysql-test/t/bigint.test
        mysql-test/t/csv.test
        mysql-test/t/delete.test
        mysql-test/t/fulltext.test
        mysql-test/t/func_gconcat.test
        mysql-test/t/group_by.test
        mysql-test/t/group_min_max.test
        mysql-test/t/having.test
        mysql-test/t/innodb-autoinc.test
        mysql-test/t/innodb_mysql.test
        mysql-test/t/join.test
        mysql-test/t/multi_update.test
        mysql-test/t/myisam.test
        mysql-test/t/mysqltest.test
        mysql-test/t/sp-bugs.test
        mysql-test/t/sp_notembedded.test
        mysql-test/t/subselect.test
        mysql-test/t/type_bit.test
        mysql-test/t/view.test
        mysql-test/t/view_grant.test
        mysys/default.c
        scripts/mysqld_multi.sh
        server-tools/instance-manager/options.cc
        sql/field.cc
        sql/ha_partition.cc
        sql/item.cc
        sql/item.h
        sql/item_cmpfunc.h
        sql/item_row.cc
        sql/item_sum.cc
        sql/item_timefunc.cc
        sql/log.cc
        sql/log_event.cc
        sql/log_event_old.cc
        sql/mysql_priv.h
        sql/mysqld.cc
        sql/opt_range.cc
        sql/opt_sum.cc
        sql/share/errmsg.txt
        sql/sp.cc
        sql/sp_cache.cc
        sql/sp_head.cc
        sql/sql_base.cc
        sql/sql_class.cc
        sql/sql_class.h
        sql/sql_lex.cc
        sql/sql_lex.h
        sql/sql_parse.cc
        sql/sql_repl.cc
        sql/sql_select.cc
        sql/sql_select.h
        sql/sql_table.cc
        sql/sql_trigger.cc
        sql/sql_update.cc
        sql/sql_view.cc
        sql/table.cc
        sql/table.h
        storage/archive/ha_archive.cc
        storage/csv/ha_tina.cc
        storage/innobase/buf/buf0buf.c
        storage/innobase/buf/buf0rea.c
        storage/innobase/handler/ha_innodb.cc
        storage/innobase/include/buf0rea.h
        storage/innobase/lock/lock0lock.c
        storage/innobase/os/os0file.c
        storage/myisam/ft_boolean_search.c
        storage/myisam/mi_dynrec.c
        storage/myisam/mi_locking.c
        support-files/mysql.spec.sh
[17 Jun 2010 12:01] Bugs System
Pushed into 5.1.47-ndb-7.0.16 (revid:martin.skold@mysql.com-20100617114014-bva0dy24yyd67697) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)
[17 Jun 2010 12:43] Bugs System
Pushed into 5.1.47-ndb-6.2.19 (revid:martin.skold@mysql.com-20100617115448-idrbic6gbki37h1c) (version source revid:martin.skold@mysql.com-20100609140708-52rvuyq4q500sxkq) (merge vers: 5.1.45-ndb-6.2.19) (pib:16)
[17 Jun 2010 13:28] Bugs System
Pushed into 5.1.47-ndb-6.3.35 (revid:martin.skold@mysql.com-20100617114611-61aqbb52j752y116) (version source revid:vasil.dimov@oracle.com-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)