QA » openQA Project

The relevant code is (and we have similar code in various other places within that test):

        $driver->find_element_by_id('text')->send_keys($description_test_message);
        $driver->find_element_by_id('submitComment')->click();  # alert shows up as if previous call didn't send any keys to the text area
        $driver->get($group_url);  # problem is surfacing here as we can't change the page without dismissing the alert first

• $description_test_message is definitely not empty.
• The ID text is really unique on the page.
• Nevertheless the button click (that basically invokes some JavaScript to be executed) leads to a JavaScript-alert complaining that the textarea text is empty.

So I have no idea why that would sometimes not work. send_keys is expected to be a synchronous call, right? In addition:

• The textarea text is a plain text area (without JavaScript event handlers on key strokes or the like). So typing should really not be broken.
• If text wouldn't exist from the beginning than $driver->find_element_by_id('text') would return an error.
• If text was hidden and send_keys would therefore refuse to send keys we'd get an error.
• I see no way that text would be swapped out in the middle. This is the form to submit a new comment and that's not messed with dynamically in our JavaScript code.

Maybe this is a bug in Selenium/chromedriver? It is not like those were still well maintained and we experienced bugs before.

Not sure what to do? Since I've only saw it once so far (and we have this code without any significant modifications in-place for ages) I'd say that doesn't even justifying to mark this test as unstable (it currently isn't marked unstable).

mkittler wrote:

Not sure what to do? Since I've only saw it once so far (and we have this code without any significant modifications in-place for ages) I'd say that doesn't even justifying to mark this test as unstable (it currently isn't marked unstable).

I agree. Albeit some ideas you could try if you like:

1. Repeatedly (infinitely) run the "find…send_keys…click" test code section to try to reproduce it more easily
2. Implement retry in the test, like a for-loop or something, just in case we run into the problem again

Apparently mkittler is still planning to work on this, so I'll just add my initial thoughts here. I noticed the wait_for_ajax after submitComment->click won't ensure all elements are in place. That can mean the page is not in a consistent state when it returns. Although it "should" be caught by the check that comments can be edited. In general the test seems slow to me, even when running it locally - maybe that can cause problems on low-powered machines?

I noticed the wait_for_ajax after submitComment->click won't ensure all elements are in place.

A wait_for_ajax should be sufficient considering we reload the page anyways. The important part is that the AJAX request is done, not that any elements show up on the page (which we reload anyways). However, in the concrete place this ticket is about there's not even a wait_for_ajax. I've created a PR to fix that: https://github.com/os-autoinst/openQA/pull/4944

The missing wait_for_ajax could not be the reason for the problem we see here, though. That the AJAX request isn't happening in the first place and that we instead get an alert is the problem.

Repeatedly (infinitely) run the "find…send_keys…click" test code section to try to reproduce it more easily

When I reproduce the issue, then what? This doesn't really help solving the conundrum and thus doesn't help fixing the issue.

Implement retry in the test, like a for-loop or something, just in case we run into the problem again

There are many places where we have code like this. Only fixing one of them seems odd and might not help when the same issue next time occurs on a different place.

I'm unassigning. Maybe someone else has an idea what the problem is.

mkittler wrote:

So I have no idea why that would sometimes not work. send_keys is expected to be a synchronous call, right?

That seems to be defined in the WebDriver spec here and how i understand it too.

Just saw it happen for the first time, so for me it's like 1 in 100 test runs now:

t/ui/15-comments.t .. 12/? executeScript: unexpected alert open: {Alert text : The comment text mustn't be empty.} at /home/sri/work/openQA/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:81 at /home/sri/work/openQA/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm line 84.
        OpenQA::SeleniumTest::__ANON__(Test::Selenium::Chrome=HASH(0xaaab02c0b658), "Error while executing command: executeScript: unexpected aler"..., HASH(0xaaab02f5d5a0), HASH(0xaaab02f81f40)) called at /usr/lib/perl5/vendor_perl/5.36.0/Selenium/Remote/Driver.pm line 356
        Selenium::Remote::Driver::catch {...} ("Error while executing command: executeScript: unexpected aler"...) called at /usr/lib/perl5/vendor_perl/5.36.0/Try/Tiny.pm line 123
        Try::Tiny::try(CODE(0xaaab02f6b068), Try::Tiny::Catch=REF(0xaaab02f69378)) called at /usr/lib/perl5/vendor_perl/5.36.0/Selenium/Remote/Driver.pm line 361
        Selenium::Remote::Driver::__ANON__(CODE(0xaaab029a9b18), Test::Selenium::Chrome=HASH(0xaaab02c0b658), HASH(0xaaab02f5d5a0), HASH(0xaaab02f81f40)) called at (eval 1774) line 1
        Selenium::Remote::Driver::__ANON__(Test::Selenium::Chrome=HASH(0xaaab02c0b658), HASH(0xaaab02f5d5a0), HASH(0xaaab02f81f40)) called at (eval 1776) line 2
        Selenium::Remote::Driver::_execute_command(Test::Selenium::Chrome=HASH(0xaaab02c0b658), HASH(0xaaab02f5d5a0), HASH(0xaaab02f81f40)) called at /usr/lib/perl5/vendor_perl/5.36.0/Selenium/Remote/Driver.pm line 1058
        Selenium::Remote::Driver::execute_script(Test::Selenium::Chrome=HASH(0xaaab02c0b658), "return window.jQuery && jQuery.active === 0") called at /home/sri/work/openQA/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm line 163
        OpenQA::SeleniumTest::wait_for_ajax("msg", "comment for job 99938 added by regular user") called at t/ui/15-comments.t line 476
        main::__ANON__() called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        eval {...} called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        Test::Builder::subtest(Test::Builder=HASH(0xaaaaf7fd4300), "test results", CODE(0xaaab02c0b000)) called at /usr/lib/perl5/5.36.0/Test/More.pm line 809
        Test::More::subtest("test results", CODE(0xaaab02c0b000)) called at t/ui/15-comments.t line 479
        main::__ANON__() called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        eval {...} called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        Test::Builder::subtest(Test::Builder=HASH(0xaaaaf7fd4300), "editing when logged in as regular user", CODE(0xaaab02f50178)) called at /usr/lib/perl5/5.36.0/Test/More.pm line 809
        Test::More::subtest("editing when logged in as regular user", CODE(0xaaab02f50178)) called at t/ui/15-comments.t line 507
# Tests were run but no plan was declared and done_testing() was not seen.
t/ui/15-comments.t .. Dubious, test returned 254 (wstat 65024, 0xfe00)
All 13 subtests passed 

Test Summary Report
-------------------
t/ui/15-comments.t (Wstat: 65024 (exited 254) Tests: 13 Failed: 0)
  Non-zero exit status: 254
  Parse errors: No plan found in TAP output
Files=1, Tests=13, 21 wallclock secs ( 0.02 usr  0.01 sys +  2.48 cusr  0.29 csys =  2.80 CPU)
Result: FAIL

It was in a different place than the original problem though, which suggests that it can happen for all similar comment submits in the test.

Two cases in about 300 test runs, same line as before:

t/ui/15-comments.t .. 12/? executeScript: unexpected alert open: {Alert text : The comment text mustn't be empty.} at /home/sri/work/openQA/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm:81 at /home/sri/work/openQA/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm line 84.
        OpenQA::SeleniumTest::__ANON__(Test::Selenium::Chrome=HASH(0xaaab106162b0), "Error while executing command: executeScript: unexpected aler"..., HASH(0xaaab10979088), HASH(0xaaab10962f40)) called at /usr/lib/perl5/vendor_perl/5.36.0/Selenium/Remote/Driver.pm line 356
        Selenium::Remote::Driver::catch {...} ("Error while executing command: executeScript: unexpected aler"...) called at /usr/lib/perl5/vendor_perl/5.36.0/Try/Tiny.pm line 123
        Try::Tiny::try(CODE(0xaaab10985368), Try::Tiny::Catch=REF(0xaaab10984d80)) called at /usr/lib/perl5/vendor_perl/5.36.0/Selenium/Remote/Driver.pm line 361
        Selenium::Remote::Driver::__ANON__(CODE(0xaaab1015e370), Test::Selenium::Chrome=HASH(0xaaab106162b0), HASH(0xaaab10979088), HASH(0xaaab10962f40)) called at (eval 1768) line 1
        Selenium::Remote::Driver::__ANON__(Test::Selenium::Chrome=HASH(0xaaab106162b0), HASH(0xaaab10979088), HASH(0xaaab10962f40)) called at (eval 1770) line 2
        Selenium::Remote::Driver::_execute_command(Test::Selenium::Chrome=HASH(0xaaab106162b0), HASH(0xaaab10979088), HASH(0xaaab10962f40)) called at /usr/lib/perl5/vendor_perl/5.36.0/Selenium/Remote/Driver.pm line 1058
        Selenium::Remote::Driver::execute_script(Test::Selenium::Chrome=HASH(0xaaab106162b0), "return window.jQuery && jQuery.active === 0") called at /home/sri/work/openQA/repos/openQA/t/ui/../lib/OpenQA/SeleniumTest.pm line 163
        OpenQA::SeleniumTest::wait_for_ajax("msg", "comment for job 99938 added by regular user") called at t/ui/15-comments.t line 476
        main::__ANON__() called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        eval {...} called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        Test::Builder::subtest(Test::Builder=HASH(0xaaab059e4b70), "test results", CODE(0xaaab10992618)) called at /usr/lib/perl5/5.36.0/Test/More.pm line 809
        Test::More::subtest("test results", CODE(0xaaab10992618)) called at t/ui/15-comments.t line 479
        main::__ANON__() called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        eval {...} called at /usr/lib/perl5/5.36.0/Test/Builder.pm line 374
        Test::Builder::subtest(Test::Builder=HASH(0xaaab059e4b70), "editing when logged in as regular user", CODE(0xaaab1095dd08)) called at /usr/lib/perl5/5.36.0/Test/More.pm line 809
        Test::More::subtest("editing when logged in as regular user", CODE(0xaaab1095dd08)) called at t/ui/15-comments.t line 507
# Tests were run but no plan was declared and done_testing() was not seen.
t/ui/15-comments.t .. Dubious, test returned 254 (wstat 65024, 0xfe00)
All 13 subtests passed 

Test Summary Report
-------------------
t/ui/15-comments.t (Wstat: 65024 (exited 254) Tests: 13 Failed: 0)
  Non-zero exit status: 254
  Parse errors: No plan found in TAP output
Files=1, Tests=13, 20 wallclock secs ( 0.03 usr  0.00 sys +  2.53 cusr  0.25 csys =  2.81 CPU)
Result: FAIL

All attempts to manually trigger the problem still unsuccessful.

Had the test pass 600 times with the change from this PR: https://github.com/os-autoinst/openQA/pull/4978

I've not been able to replicate the issue with selenium in headful mode though, so still not quite sure about the root cause.

I've just seen it again in a CI run of https://github.com/os-autoinst/openQA/pull/4980: https://app.circleci.com/pipelines/github/os-autoinst/openQA/10868/workflows/0ace4fb7-95fc-473b-8130-fc20fb0c2cbe/jobs/101774

[11:35:50] t/ui/15-comments.t ......................... 12/? executeScript: unexpected alert open: {Alert text : The comment text mustn't be empty.} at /home/squamata/project/t/ui/../lib/OpenQA/SeleniumTest.pm:81 at /home/squamata/project/t/ui/../lib/OpenQA/SeleniumTest.pm line 84.
    OpenQA::SeleniumTest::__ANON__(Test::Selenium::Chrome=HASH(0x55e95e152b00), "Error while executing command: executeScript: unexpected aler"..., HASH(0x55e95e61ebd8), HASH(0x55e95e5f4368)) called at /usr/lib/perl5/vendor_perl/5.26.1/Selenium/Remote/Driver.pm line 356
    Selenium::Remote::Driver::catch {...} ("Error while executing command: executeScript: unexpected aler"...) called at /usr/lib/perl5/vendor_perl/5.26.1/Try/Tiny.pm line 123
    Try::Tiny::try(CODE(0x55e95e5ef618), Try::Tiny::Catch=REF(0x55e95e5fae30)) called at /usr/lib/perl5/vendor_perl/5.26.1/Selenium/Remote/Driver.pm line 361
    Selenium::Remote::Driver::__ANON__(CODE(0x55e95dc905b8), Test::Selenium::Chrome=HASH(0x55e95e152b00), HASH(0x55e95e61ebd8), HASH(0x55e95e5f4368)) called at (eval 1708)[/usr/lib/perl5/vendor_perl/5.26.1/Class/Method/Modifiers.pm:89] line 1
    Selenium::Remote::Driver::__ANON__(Test::Selenium::Chrome=HASH(0x55e95e152b00), HASH(0x55e95e61ebd8), HASH(0x55e95e5f4368)) called at (eval 1710)[/usr/lib/perl5/vendor_perl/5.26.1/Class/Method/Modifiers.pm:148] line 2
    Selenium::Remote::Driver::_execute_command(Test::Selenium::Chrome=HASH(0x55e95e152b00), HASH(0x55e95e61ebd8), HASH(0x55e95e5f4368)) called at /usr/lib/perl5/vendor_perl/5.26.1/Selenium/Remote/Driver.pm line 1053
    Selenium::Remote::Driver::execute_script(Test::Selenium::Chrome=HASH(0x55e95e152b00), "return window.jQuery \x{26}\x{26} jQuery.active === 0") called at /home/squamata/project/t/ui/../lib/OpenQA/SeleniumTest.pm line 163
    OpenQA::SeleniumTest::wait_for_ajax("msg", "comment with pinning for group added by regular user") called at t/ui/15-comments.t line 494
    main::__ANON__() called at /usr/lib/perl5/5.26.1/Test/Builder.pm line 309
    eval {...} called at /usr/lib/perl5/5.26.1/Test/Builder.pm line 309
    Test::Builder::subtest(Test::Builder=HASH(0x55e951b4b9a8), "group overview: /group_overview/1001", CODE(0x55e95e5f6df8)) called at /usr/lib/perl5/5.26.1/Test/More.pm line 807
    Test::More::subtest("group overview: /group_overview/1001", CODE(0x55e95e5f6df8)) called at t/ui/15-comments.t line 507
    main::__ANON__() called at /usr/lib/perl5/5.26.1/Test/Builder.pm line 309
    eval {...} called at /usr/lib/perl5/5.26.1/Test/Builder.pm line 309
    Test::Builder::subtest(Test::Builder=HASH(0x55e951b4b9a8), "editing when logged in as regular user", CODE(0x55e95e5e66c8)) called at /usr/lib/perl5/5.26.1/Test/More.pm line 807
    Test::More::subtest("editing when logged in as regular user", CODE(0x55e95e5e66c8)) called at t/ui/15-comments.t line 508
[11:35:50] t/ui/15-comments.t ......................... 13/? # Tests were run but no plan was declared and done_testing() was not seen.
[11:35:50] t/ui/15-comments.t .........................       Dubious, test returned 254 (wstat 65024, 0xfe00)

This PRs branch is up-to-date and thus contains 3266e22545f3a03272995171ac489db55f9efb9d from https://github.com/os-autoinst/openQA/pull/4978.

As expected, the case Marius encountered is for a different line. It's almost the exact same test code, so the same fix should work there as well. https://github.com/os-autoinst/openQA/pull/4984