Project

General

Profile

Actions

action #54548

closed

Use of `record_serialresult` in `validate_script_output` is very confusing

Added by AdamWill almost 5 years ago. Updated over 4 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
Category:
Regressions/Crashes
Target version:
Start date:
2019-07-23
Due date:
% Done:

100%

Estimated time:

Description

This dates back all the way to this commit in 2014:

https://github.com/os-autoinst/os-autoinst/commit/0f4d22fd8c0924b1b448f65084cd03b892787c00

it introduced validate_script_output, with a bit that was commented at the time as being dodgy:

# abusing the function
$autotest::current_test->record_serialresult($output, $res);

well, it's still basically there and it's still dodgy. Currently it reads:

# abusing the function
$autotest::current_test->record_serialresult($output, $res, $output) unless ($args{quiet});

but this does the same thing. In practice what this means is, every time validate_script_output is called, you get a text thumbnail in your test which reads:

# wait_serial expected: (whatever the output was)

# Result:
(whatever the output was)

The two strings will always be identical. If the validate_script_output check failed, the thumbnail will be bordered red, indicating a failure.

In the Fedora tests, we have this check:

validate_script_output 'rpm -q python3-kickstart', sub { $_ !~ m/^python3-kickstart-1-1.noarch$/ };

which basically means "ensure the output of rpm -q python3-kickstart is anything but 'python3-kickstart-1-1.noarch'". When this fails you get an extremely confusing result in the UI: you get a red-bordered text thumbnail reading:

# wait_serial expected: python3-kickstart-1-1.noarch

# Result:
python3-kickstart-1-1.noarch

That does not make it obvious at all what the problem is, and is arguably more misleading than just not including the thumbnail at all.

Really, though, even if the check was a positive assertion, the thumbnail would be equally misleading, because of how both strings will always be the exact output of the command - despite the wording "expected: ", that first string is never actually any kind of representation of what the check "expected".

I'm not sure why this was ever thought to be a good idea, but perhaps we should rethink it?

Example of the above case: https://openqa.fedoraproject.org/tests/424602


Files

validate-script-output.png (27.8 KB) validate-script-output.png validate_script_output tinita, 2019-08-14 15:41

Related issues 1 (0 open1 closed)

Related to openQA Project - action #54347: [tools] Wrong message on serial missmatchResolvedokurz2019-07-17

Actions
Actions #1

Updated by AdamWill almost 5 years ago

For instance, instead of calling record_serialresult from validate_script_output at all, why not just call record_resultfile directly, with more accurate output?

Actions #2

Updated by okurz over 4 years ago

  • Related to action #54347: [tools] Wrong message on serial missmatch added
Actions #3

Updated by okurz over 4 years ago

  • Category set to Regressions/Crashes

I wonder if it really took 5 years for you and dheidler to report about the same issue but then within the very same week – see https://progress.opensuse.org/issues/54347 – or if we really have a regression now.

Actions #4

Updated by AdamWill over 4 years ago

I think it's just a weird coincidence. I can't swear to it, but I think I've run into this before but not bothered to file an issue. The code doesn't look like it's changed recently.

Actions #5

Updated by tinita over 4 years ago

Maybe it was done like that because the argument to validate_script_output() is a coderef and not a regex.

But it would be possible to convert the coderef to a string again with the B::Deparse module.
Additionally it would be nice if one could just pass a regex to validate_script_output(). I guess that's a very common usage.

Then displaying the regex would be even easier.

Actions #6

Updated by tinita over 4 years ago

I just tested my idea with B::Deparse with the following function in console/sqlite3.pm:

validate_script_output("pwd", sub {
    m/foo/
});

This is the output:

# wait_serial expected: {
    package sqlite3;
    use warnings;
    use strict;
    /foo/;
}

# Result:
/root

Would that help?

But maybe it should also use its own function instead of record_serialresult() to avoid the misleading text.

Actions #7

Updated by AdamWill over 4 years ago

mmm...it's a bit hard to understand, I think. As I said in comment #1 here, the implementation of record_serialresult isn't necessarily the problem here - arguably validate_script_output just shouldn't use it.

Actions #8

Updated by tinita over 4 years ago

basically B::Deparse would turn your subroutine into a string again.

In your case it would look like this:

# wait_serial expected: {
    package your::package;
    use warnings;
    use strict;
    not(($_ =~ /^python3-kickstart-1-1.noarch$/));
}

And if we write our own function it could look like this:

# validate_script_output expected: {
    package your::package;
    use warnings;
    use strict;
    not(($_ =~ /^python3-kickstart-1-1.noarch$/));
}
Actions #9

Updated by AdamWill over 4 years ago

yes, but I think your thinking is locked into this whole 'print what was expected' path because that's what record_serialresult does. But we don't actually need to do that. The output here doesn't have to be "expected X, got Y" at all. It can just be something like "validate_script_output on line X failed, output that did not validate was: Y" or something. We don't necessarily need to try and show right in the output what the validation code was, if it comes out awkward.

Actions #10

Updated by tinita over 4 years ago

But it would be nice to show what was expected anyway.

I attached a screenshot of what I just tried out.

Actions #11

Updated by AdamWill over 4 years ago

I mean...that still reads pretty strangely. also your check there looks a bit weird - is there really no $_ =~ or anything in it, or did it get removed by the parsing?

Actions #12

Updated by tinita over 4 years ago

$_ =~ m/foo/

is really the same as

m/foo/

or

/foo/

because $_ is the default variable for regex matches, and the m in m/.../ is optional.

Maybe the result string should be on top, and this deparsed output of the the check subroutine comes below (with a short explanation), for people who would like to see it.

I just wrote my first openqa test a few weeks ago, and this wait_serial output was something which confused me too, and to me the check subroutine would be helpful additional output.

What do others think?

In any case, it should be easy to replace the current confusing output.

Actions #13

Updated by AdamWill over 4 years ago

OK, yeah, that's really super-compressed and hard to understand, then. I think including the deparsed validation coderef can work, but the text around it needs to explain clearly what's going on.

Actions #14

Updated by okurz over 4 years ago

I think we should try to abstract away anything that looks like perl. regex is fine but the idea is that the test API is basically its own language. This is also the reason why we have API methods like get_var and set_var.

Actions #15

Updated by AdamWill over 4 years ago

that's a bit difficult in this case as validate_script_output explicitly compares against an arbitrary code ref, though :/

Actions #16

Updated by okurz over 4 years ago

yes, true. How tinita did it in https://github.com/os-autoinst/os-autoinst/pull/1199 is actually just fine with stripping the automatically added use statements.

@tinita don't be shy and assign a ticket to yourself when you are working on one. When you can't because you are not part of a project yet in progress talk with your managers about missing steps in onboarding :) Added you now in the parent project https://progress.opensuse.org/projects/qa/settings/members

Actions #17

Updated by okurz over 4 years ago

  • Assignee set to tinita
Actions #18

Updated by tinita over 4 years ago

  • Status changed from New to In Progress
  • % Done changed from 0 to 50
  • Difficulty set to easy
Actions #19

Updated by coolo over 4 years ago

  • Target version set to Current Sprint
Actions #20

Updated by okurz over 4 years ago

Actions #21

Updated by tinita over 4 years ago

  • Status changed from In Progress to Feedback
  • % Done changed from 50 to 100
Actions #22

Updated by tinita over 4 years ago

  • Status changed from Feedback to Resolved
Actions #23

Updated by AdamWill over 4 years ago

Thanks again for this, it's a big improvement :)

Actions

Also available in: Atom PDF