main.mysql_client_test failing on Mac OSX

[Patrick Crews]

main.mysql_client_test is failing on Mac OSX (currently the only non-'big' bug to fail for me).

Failure output is attached in a separate .txt file (it is verbose), but here is a snippet:
main.mysql_client_test [ fail ] Found warnings/errors in server log file!
        Test ended at 2009-04-17 17:00:54
file_name line
/Users/pcrews/usr/local/bin/data1/maria/maria_exp/maria/mysql-test/var/mysqld.1/mysqld.err 33 bytes at 0x1507648, allocated at line 630 in 'time.cc'
/Users/pcrews/usr/local/bin/data1/maria/maria_exp/maria/mysql-test/var/mysqld.1/mysqld.err 4 bytes at 0x15046d8, allocated at line 2418 in 'sql_plugin.cc'
...
it continues for quite a bit.

I am also attaching a trace file from the test run.
Both files are from a run on Mac OSX 10.5 built with BUILD/compile-pentium-debug-max

[Patrick Crews (patrick-crews)]

Currently, this test isn't failing in a consistent manner. When I tried to run *just* this test, it was successful.

I will troubleshoot further to determine what sequence of tests is causing this failure. Will update this bug as soon as I am able to find further information.

It should be noted that this has not occurred on the standard mysql-5.1 branch.

[Kristian Nielsen (knielsen)]

This problem is detected by mysql-test-run.pl as a number of warnings in the server error log, generated during shutdown of the server.

There is a bug in mysql-test-run.pl in the standard mysql-5.1 branch that makes mysql-test-run.pl ignore many such warnings. This bug is fixed in the mariadb 5.1 branch.

Therefore, this problem may or may not be present also in the standard mysql-5.1 branch, if present it could be hidden by the mysql-test-run.pl bug.

Note that this is not specific to Mac OSX, it has also been seen on Linux by at least two different people. However, it appears to be quite sporadic, and hard to reproduce. Sometimes running the test in a tight loop will make it fail eventually.

[Kristian Nielsen (knielsen)]

BTW, if you can repeat the problem with a debug binary and running with
mysql-test-run.pl --debug, that would provide a trace file of the server that would be very useful. If possible, please attach the server .trace file along with mysqld.err and any log files you can find from the mysql_client_test test program.

[Patrick Crews (patrick-crews)]

Krisitan,
I'll definitely do that and thanks for the extra information.

It is quite odd, I have seen this test fail more than a few times, but when
I decide to write a bug, it starts acting flaky ;-) (Reminds me of those
old WB 'singing frog' cartoons <that is maybe an American-centric
reference...>)

I'll keep you posted and will definitely attach any debug data I can get
once I figure out what is triggering this failure.

Thanks,
Patrick.

On Sat, Apr 18, 2009 at 1:56 AM, Kristian Nielsen
<email address hidden>wrote:

> BTW, if you can repeat the problem with a debug binary and running with
> mysql-test-run.pl --debug, that would provide a trace file of the server
> that would be very useful. If possible, please attach the server .trace file
> along with mysqld.err and any log files you can find from the
> mysql_client_test test program.
>
> --
> main.mysql_client_test failing on Mac OSX
> https://bugs.launchpad.net/bugs/363181
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in Maria: New
>
> Bug description:
> main.mysql_client_test is failing on Mac OSX (currently the only non-'big'
> bug to fail for me).
>
> Failure output is attached in a separate .txt file (it is verbose), but
> here is a snippet:
> main.mysql_client_test [ fail ] Found warnings/errors in
> server log file!
> Test ended at 2009-04-17 17:00:54
> file_name line
> /Users/pcrews/usr/local/bin/data1/maria/maria_exp/maria/mysql-test/var/mysqld.1/mysqld.err
> 33 bytes at 0x1507648, allocated at line 630 in 'time.cc'
> /Users/pcrews/usr/local/bin/data1/maria/maria_exp/maria/mysql-test/var/mysqld.1/mysqld.err
> 4 bytes at 0x15046d8, allocated at line 2418 in
> 'sql_plugin.cc'
> ...
> it continues for quite a bit.
>
> I am also attaching a trace file from the test run.
> Both files are from a run on Mac OSX 10.5 built with
> BUILD/compile-pentium-debug-max
>

[Patrick Crews (patrick-crews)]

Am now able to reproduce regularly.

To repeat:

./mtr --force --repeat=2 mysql_client_test.

New attachment = tarball with all .trace files produced from a failing run + mysqld.err file

[Kristian Nielsen (knielsen)]

Thanks for making this additional information available!

There seems to be something really wrong with the mysql_client_test.trace file,
which would be quite useful to track down what the problem really is.

At the point of the test "test_mem_overun", the file contains the trace of the
first mysql_query() call. But then the rest of the trace for test_mem_overun
is missing, as is the trace for the following test. Instead, the test
continues with what is clearly the last part of the trace for the test
"test_free_result". And so on, with the trace containing only fragments of
what would be expected from a full trace. The trace ends abruptly in the
middle of the first mysql_query() call in test "test_wl4166_2".

Can you maybe re-run the test, this time making sure there is enough disk
space and no use of ramdisk?

[Patrick Crews (patrick-crews)]

Kristian,
No problems and my apologies for the incomplete .trace files. I gathered
them via ./mysql-test-run.pl --force --repeat=2 mysql_client_test and didn't
do anything beyond packaging them.

However, this seems to now be a moot point. After refreshing my Maria tree,
the failure has gone away and I cannot repeat it any longer. I have tried
multiple runs of the test itself as well as running the full suite without a
failure.

The changes I pulled were to:
M libmysql/libmysql.c
M tests/mysql_client_test.c

Please let me know if I can provide any additional information to get this
bug closed out.

On Tue, Apr 21, 2009 at 8:53 AM, Kristian Nielsen
<email address hidden>wrote:

> Thanks for making this additional information available!
>
> There seems to be something really wrong with the mysql_client_test.trace
> file,
> which would be quite useful to track down what the problem really is.
>
> At the point of the test "test_mem_overun", the file contains the trace of
> the
> first mysql_query() call. But then the rest of the trace for
> test_mem_overun
> is missing, as is the trace for the following test. Instead, the test
> continues with what is clearly the last part of the trace for the test
> "test_free_result". And so on, with the trace containing only fragments of
> what would be expected from a full trace. The trace ends abruptly in the
> middle of the first mysql_query() call in test "test_wl4166_2".
>
> Can you maybe re-run the test, this time making sure there is enough disk
> space and no use of ramdisk?
>
> --
> main.mysql_client_test failing on Mac OSX
> https://bugs.launchpad.net/bugs/363181
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in Maria: New
>
> Bug description:
> main.mysql_client_test is failing on Mac OSX (currently the only non-'big'
> bug to fail for me).
>
> Failure output is attached in a separate .txt file (it is verbose), but
> here is a snippet:
> main.mysql_client_test [ fail ] Found warnings/errors in
> server log file!
> Test ended at 2009-04-17 17:00:54
> file_name line
> /Users/pcrews/usr/local/bin/data1/maria/maria_exp/maria/mysql-test/var/mysqld.1/mysqld.err
> 33 bytes at 0x1507648, allocated at line 630 in 'time.cc'
> /Users/pcrews/usr/local/bin/data1/maria/maria_exp/maria/mysql-test/var/mysqld.1/mysqld.err
> 4 bytes at 0x15046d8, allocated at line 2418 in
> 'sql_plugin.cc'
> ...
> it continues for quite a bit.
>
> I am also attaching a trace file from the test run.
> Both files are from a run on Mac OSX 10.5 built with
> BUILD/compile-pentium-debug-max
>

[Kristian Nielsen (knielsen)]

patrick_crews <email address hidden> writes:

> No problems and my apologies for the incomplete .trace files. I gathered
> them via ./mysql-test-run.pl --force --repeat=2 mysql_client_test and didn't
> do anything beyond packaging them.

No need to apologise. In fact I am completely baffled as to how the trace
files could be incomplete in that way. I thought about disk full, but the
trace files contains traces from two runs (due to --repeat=2 I assume), and
they are identical, including how they are incomplete. It just doesn't make
sense...

> However, this seems to now be a moot point. After refreshing my Maria tree,
> the failure has gone away and I cannot repeat it any longer. I have tried
> multiple runs of the test itself as well as running the full suite without a
> failure.
>
> The changes I pulled were to:
> M libmysql/libmysql.c
> M tests/mysql_client_test.c

Right. I fixed some minor problems with the dbug, which were visible in the
trace file.

Hm. I guess it is remotely possible that this actually fixes the problem. I
somewhat doubt it though.

The problem is that this failure seems extremely fragile, I used to be able to
repeat it as well, but then it disappeared.

One thing you can try is to run the test in a tight loop:

    (for i in `seq 1 100`; do echo XXX $i XXX; ./mysql-test-run.pl mysql_client_test || exit 1; done)

This will run the test up to 100 times until it fails. If you cannot repeat
it this way, we will have to declare the problem fixed by the above changes
until someone else manage to repeat it.

Thanks for the effort,

 - Kristian.

[Kristian Nielsen (knielsen)]

I can confirm this bug exists and is not specific to Mac OSX.

I also see it from time to time on Ubuntu Hardy x86_64.

Unfortunately the problem is very intermittent and hard to reproduce. It seems I only
see it occasionally when running the complete test suite under --parallel=3