Project

General

Profile

action #121042

[sporadic] typing issue in comments UI test size:M

Added by mkittler 2 months ago. Updated 11 days ago.

Status:
Resolved
Priority:
High
Assignee:
Category:
Concrete Bugs
Target version:
Start date:
2022-11-28
Due date:
2023-01-27
% Done:

0%

Estimated time:
Difficulty:

Description

Observation

[12:42:18] t/ui/15-comments.t ......................... 12/? get: 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(0x55cbb5d49500), "Error while executing command: get: unexpected alert open: {A"..., HASH(0x55cbb2ea54f0), HASH(0x55cbb621f7c0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Selenium/Remote/Driver.pm line 356
        Selenium::Remote::Driver::catch {...} ("Error while executing command: get: unexpected alert open: {A"...) called at /usr/lib/perl5/vendor_perl/5.26.1/Try/Tiny.pm line 123
        Try::Tiny::try(CODE(0x55cbb6206820), Try::Tiny::Catch=REF(0x55cbb61f4f10)) called at /usr/lib/perl5/vendor_perl/5.26.1/Selenium/Remote/Driver.pm line 361
        Selenium::Remote::Driver::__ANON__(CODE(0x55cbb5ac8590), Test::Selenium::Chrome=HASH(0x55cbb5d49500), HASH(0x55cbb2ea54f0), HASH(0x55cbb621f7c0)) called at (eval 1713)[/usr/lib/perl5/vendor_perl/5.26.1/Class/Method/Modifiers.pm:89] line 1
        Selenium::Remote::Driver::__ANON__(Test::Selenium::Chrome=HASH(0x55cbb5d49500), HASH(0x55cbb2ea54f0), HASH(0x55cbb621f7c0)) called at (eval 1715)[/usr/lib/perl5/vendor_perl/5.26.1/Class/Method/Modifiers.pm:148] line 2
        Selenium::Remote::Driver::_execute_command(Test::Selenium::Chrome=HASH(0x55cbb5d49500), HASH(0x55cbb2ea54f0), HASH(0x55cbb621f7c0)) called at /usr/lib/perl5/vendor_perl/5.26.1/Selenium/Remote/Driver.pm line 946
        Selenium::Remote::Driver::get(Test::Selenium::Chrome=HASH(0x55cbb5d49500), "/group_overview/1001") called at t/ui/15-comments.t line 493
        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(0x55cba96c1160), "group overview: /group_overview/1001", CODE(0x55cbb61ec710)) called at /usr/lib/perl5/5.26.1/Test/More.pm line 807
        Test::More::subtest("group overview: /group_overview/1001", CODE(0x55cbb61ec710)) called at t/ui/15-comments.t line 505
        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(0x55cba96c1160), "editing when logged in as regular user", CODE(0x55cbb61e0128)) called at /usr/lib/perl5/5.26.1/Test/More.pm line 807
        Test::More::subtest("editing when logged in as regular user", CODE(0x55cbb61e0128)) called at t/ui/15-comments.t line 506
[12:42:18] t/ui/15-comments.t ......................... 13/? # Tests were run but no plan was declared and done_testing() was not seen.
[12:42:18] t/ui/15-comments.t .........................       Dubious, test returned 254 (wstat 65024, 0xfe00)
All 13 subtests passed

(see https://app.circleci.com/pipelines/github/os-autoinst/openQA/10659/workflows/5fa05316-b883-48e5-9680-571ca7baf77b/jobs/99866/steps)

I've encountered it only once so far and retrying helped. Likely it happens only very rarely.

Acceptance criteria

  • AC1: Sporadic issue no longer appears

Suggestions

  • Use Circle CI ssh feature to debug (since it has not been replicated locally)
15-comments.pl (13.5 KB) 15-comments.pl mkittler, 2022-11-28 12:58

History

#1 Updated by mkittler 2 months ago

  • Category set to Concrete Bugs

#2 Updated by okurz 2 months ago

  • Tags set to sporadic, reactive work
  • Subject changed from Sporatic typing issue in comments UI test to [sporadic] typing issue in comments UI test
  • Priority changed from Normal to High
  • Target version set to Ready

#3 Updated by robert.richardson 2 months ago

  • Subject changed from [sporadic] typing issue in comments UI test to [sporadic] typing issue in comments UI test size:M
  • Description updated (diff)
  • Status changed from New to Workable

#4 Updated by mkittler 2 months ago

  • Tags changed from sporadic, reactive work to sporadic
  • Category deleted (Concrete Bugs)
  • Assignee set to mkittler
  • Target version deleted (Ready)

#5 Updated by mkittler 2 months ago

  • Tags changed from sporadic to sporadic, reactive work
  • Category set to Concrete Bugs
  • Target version set to Ready

#6 Updated by mkittler 2 months ago

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).

#7 Updated by okurz 2 months ago

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

#8 Updated by cdywan 2 months ago

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?

#9 Updated by mkittler 2 months ago

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.

#10 Updated by mkittler 2 months ago

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.

#11 Updated by mkittler 2 months ago

  • Assignee deleted (mkittler)

#12 Updated by kraih about 2 months ago

  • Assignee set to kraih

I'll take a look, but will put the ticket back into the queue if i can't find a solution before my vacation.

#13 Updated by kraih about 2 months ago

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.

#14 Updated by kraih about 2 months ago

  • Assignee deleted (kraih)

I've been unable to replicate it in a Circle CI ssh session unfortunately, and didn't see anything obvious in the code.

#15 Updated by kraih about 1 month ago

  • Assignee set to kraih

Since nobody else has made progress and this is still high priority, maybe i'll try looking a bit closer at the code.

#16 Updated by kraih about 1 month ago

  • Status changed from Workable to In Progress

#17 Updated by openqa_review about 1 month ago

  • Due date set to 2023-01-20

Setting due date based on mean cycle time of SUSE QE Tools

#18 Updated by kraih 27 days ago

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.

#19 Updated by kraih 27 days ago

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.

#20 Updated by kraih 26 days ago

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

#21 Updated by kraih 26 days ago

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

#22 Updated by kraih 26 days ago

  • Status changed from In Progress to Feedback

#23 Updated by mkittler 25 days ago

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.

#24 Updated by kraih 17 days ago

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

#25 Updated by kraih 17 days ago

  • Status changed from Feedback to In Progress

#26 Updated by kraih 17 days ago

  • Status changed from In Progress to Feedback

#27 Updated by cdywan 16 days ago

  • Due date changed from 2023-01-20 to 2023-01-27

kraih wrote:

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

This is due today, but given the time it took before I think we need to monitor this another week.

#28 Updated by cdywan 11 days ago

  • Status changed from Feedback to Resolved

It's been 6 days. There's no impact outside the team e.g. failing tests in the worst case so let's assume we're good here.

Also available in: Atom PDF