No text from say() or print() within ErrorLogAlarm makes it to the trial/runall log.

[Roel Van de Paar]

Though the ErrorLogAlarm reporter works (and greatly so [I've been extending it to make it very powerful for finding previously potentially missed issues]), it does not show any output in the rqg trial logs when using combinations.pl (have not tested runall.pl yet). When issues are found, it correctly exists with STATUS_ALARM, but except for the last two lines:

[...]
# 2013-01-27T11:50:16 Query: ALTER TABLE `table100_innodb_dynamic_int_autoinc` MODIFY `c40` SET('a','b','c') DEFAULT 0 AFTER `c40` failed: 1054 Unknown column
'%s' in 'table%d_innodb_dynamic_int_autoinc'. Further errors of this kind will be suppressed.
# 2013-01-27T11:50:18 Query: ALTER TABLE `table100_innodb_default_int` MODIFY `c6` BINARY AFTER `c6` failed: 1054 Unknown column '%s' in 'table%d_innodb_defau
lt_int'. Further errors of this kind will be suppressed.
# 2013-01-27T11:50:51 gentest.pl exited with exit status STATUS_ALARM (109)
2013-01-27T11:50:51 [3340] runall.pl will exit with exit status STATUS_ALARM (109)

Nothing is reported. In this case, there are some 'higher-up' reports of impending rqg shutdown:

# 2013-01-27T11:50:46 Child worker process completed successfully.

The error in the log on which ErrorLogAlarm picked up had happened around 47:56.

So, why did the ErrorLogAlarm not pickup on the issue earlier? And why did it not print anything in the log at all? Searching for 'ErrorLogAlarm' only gives things like this:

# 2013-01-27T11:46:46 reporters => ['Shutdown', 'Backtrace', 'QueryTimeout', 'ErrorLog', 'ErrorLogAlarm']

(i.e. non-ErrorLogAlarm text), but actual text from ErrorLogAlarm.pm, for instance:

say("ErrorLogAlarm Reporter will monitor the log file ".$errorlog);

Is not seen at all. One would expect at the very least that to be there at the start somewhere.

So, summary: no text from say() or print() within ErrorLogAlarm makes it to the trial/runall log.

[John H. Embretsen (johnemb)]

I see some issue with print() in ErrorLogAlarm reporter, but not as sever as reported in this bug. Please provide steps to repeat if you continue to see the issue as described earlier.

My test was as follows:

1. Created init-file with intentionally misspelled server setting, stored as bad.init:

SET GLOBAL OPTIMIZER_SWITCH = 'index_m3rge=off';

2. Created config file for combinations.pl as follows, stored as temp.cc:

$combinations=
[
 [
  '--seed=random '.
  '--threads=1 '.
  '--duration=40 '.
  '--reporter=Shutdown,Backtrace,ErrorLog,ErrorLogAlarm '
 ],[
  "--mysqld=--init-file=$ENV{'PWD'}/bad.init",
  ''
 ],[
  "--engine=INNODB --views --grammar=conf/optimizer/optimizer_no_subquery_portable.yy",
  "--engine=MYISAM --views --grammar=conf/optimizer/optimizer_subquery_semijoin.yy"
 ]
];

With this cc-file there will be a total of 4 trials, 2 of which will use the bad init-file and should therefore result in a failure triggered by ErrorLogAlarm.

I used the following command to run combinations.pl:

perl ./combinations.pl --basedir=/path/to/mysql/install --config=temp.cc --workdir=/path/to/workdir --no-log --run-all-combinations-once --parallel=2 --force --no-mask

The result I saw was as follows:

As expected, two of the trials resulted in STATUS_OK, and the other two resulted in STATUS_ALARM. The end result from combinations.pl was STATUS_ALARM.

Looking in trial logs, I could see some message from ErrorLogAlarm. In all trial logs, I could see:

# 2013-01-29T08:42:06 ErrorLogAlarm Reporter will monitor the log file /home/johnemb/mysql/randgen/workdir-temp/current1_1/master-data/../log/master.err

In the trial logs for failing tests I could also see:

# 2013-01-29T08:43:02 ALARM from ErrorLogAlarm reporter: Pattern '^Error:|^ERROR|\[ERROR\]|allocated at line|missing DBUG_RETURN|^safe_mutex:|InnoDB: Warning|InnoDB: Error:|InnoDB: Operating system error|Error while setting value' was found in error log. Matching line was:

But, I don't see any such matching line.

At the end of the log I see

runall.pl will exit with exit status STATUS_ALARM (109)

so at least the status indicates that there is a problem with the test.

Looking in the code of ErrorLogAlarm I see the difference between the "Alarm from ErrorLogAlarm reporter" line and the matchine line:

             say("ALARM from ErrorLogAlarm reporter: Pattern '$pattern' was".
                    " found in error log. Matching line was:");
            print($line);

To conclude:

- I am not able to verify that there is a generic problem with all say()/print() calls from the ErrorLogAlarm reporter. It seems that the say() calls actually end up in the output.

- I am able to verify that print() calls, such as printing the matching line, does not seem to work. I am not sure why, but one possible reason may be that for say() log4perl logging is used if available, and for print() log4perl is bypassed. This may affect what end up in the final output.

So, it may be worth while checking if log4perl is installed and used when you run the RQG. If it is not, and you still do not see the print() output, then log4perl is not the issue.

One other possible reason for missing some output could be if hig...

[Roel Van de Paar (roel11)]

John, good to hear from you. Thanks for the feedback. Agree re: say(), I've updated that already, and now checking to see if I can get a good testcase for issue I have been seeing.

[Roel Van de Paar (roel11)]

John, so, I used your testcase on MySQL 5.5.29 and still had the same issue.

As a test, I installed Log4Perl (sudo perl -MCPAN -e'install Log::Log4perl') and the error log now contained all the correct information strings.

To make sure, I uninstall Log4Perl (sudo perl -MCPAN -e 'install App::pmuninstall' ; sudo /usr/local/bin/pm-uninstall Log::Log4perl) and re-checked: all info was gone from the log as per the original description.

So, there is some interaction issue with Log4Perl it seems. Bernt may be able to help?

Can you re-check on your end with uninstall of log4Perl?

Ftm, I have already updated the RQG manual with this new [workaround?] requirement:
https://github.com/RQG/RQG-Documentation/wiki/RandomQueryGeneratorQuickStart#wiki-43_LogLog4perl_module_required_for_properly_printing_things_for_example_in_ErrorLogAlarm

[John H. Embretsen (johnemb)]

I tried the same on a machine without Log4perl and I see that all output from ErrorLogAlarm reporter is missing, both print() and say() calls. This happens only with runall.pl (or runall.pl via combinations.pl).

When using runall-new.pl (or combinations.pl using --new option) all expected output is present.

I don't know why this is happening...

[Bernt M Johnsen (bernt-johnsen)]

On 01/29/2013 01:48 PM, John H. Embretsen wrote:
> I tried the same on a machine without Log4perl and I see that all output
> from ErrorLogAlarm reporter is missing, both print() and say() calls.
> This happens only with runall.pl (or runall.pl via combinations.pl).
>
> When using runall-new.pl (or combinations.pl using --new option) all
> expected output is present.
>
> I don't know why this is happening...
The snippet:

my $logger;
eval
{
     require Log::Log4perl;
     Log::Log4perl->import();
     $logger = Log::Log4perl->get_logger('randgen.gentest');
};

Must ALWAYS be run. So it is the first thing in all scripts. And in all
base modules, e.g. lib/GenTest.pm. It is required that "use Gentest;"
comes before all "use GenTest::blabla...;" and that "use GenTest;" is in
ALL subclasses (recursively) of GenTest.

Might be a hint to why it does not work (don't know if this is the case
though)

Bernt