randgen team mailing list archive

["John H. Embretsen" <1108572@xxxxxxxxxxxxxxxxxx>]

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 high
concurrency is used. We know that Perl is not that thread-safe when it
comes to printing. However nothing like this was specified in this bug
report.

The reason that in ErrorLogAlarm code print() is used and not say() is
that we wanted the matching line to be printed as close to reality as
possible, that is without any prefix from the RQG. Maybe this is not so
important anyway, so we can switch to using say(). Using say()
definitely makes more sense when log4perl is used (if necessary one can
also make a special version of say() which does not print a prefix).

I did an experiment replacing "print($line)" with "say($line)" in
ErrorLogAlarm, and then I could see the matching line in the trial logs
(with the RQG timestamp prefix):

# 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:
# 2013-01-29T08:43:02 ERROR: 1231  Variable 'optimizer_switch' can't be set to the value of 'index_m3rge=off'

So, with such a fix I see no further issues with ErrorLogAlarm reporter
currently.

-- 
You received this bug notification because you are a member of Random
Query Generator Team, which is subscribed to Random Query Generator.
https://bugs.launchpad.net/bugs/1108572

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

Status in SQL Generator for testing SQL servers (MySQL, JavaDB, PostgreSQL):
  Confirmed

Bug description:
  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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/randgen/+bug/1108572/+subscriptions