action #121042
closed[sporadic] typing issue in comments UI test size:M
0%
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
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)
Files
Updated by okurz almost 2 years 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
Updated by robert.richardson almost 2 years 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
Updated by mkittler almost 2 years ago
- Tags changed from sporadic, reactive work to sporadic
- Category deleted (
Regressions/Crashes) - Assignee set to mkittler
- Target version deleted (
Ready)
Updated by mkittler almost 2 years ago
- Tags changed from sporadic to sporadic, reactive work
- Category set to Regressions/Crashes
- Target version set to Ready
Updated by mkittler almost 2 years 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 andsend_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).
Updated by okurz almost 2 years 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:
- Repeatedly (infinitely) run the "find…send_keys…click" test code section to try to reproduce it more easily
- Implement retry in the test, like a for-loop or something, just in case we run into the problem again
Updated by livdywan almost 2 years 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?
Updated by mkittler almost 2 years 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.
Updated by mkittler almost 2 years 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.
Updated by kraih almost 2 years 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.
Updated by kraih almost 2 years 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.
Updated by kraih almost 2 years 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.
Updated by kraih almost 2 years 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.
Updated by openqa_review over 1 year ago
- Due date set to 2023-01-20
Setting due date based on mean cycle time of SUSE QE Tools
Updated by kraih over 1 year 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.
Updated by kraih over 1 year 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.
Updated by kraih over 1 year ago
Had the test pass 600 times with the change from this PR: https://github.com/os-autoinst/openQA/pull/4978
Updated by kraih over 1 year 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.
Updated by mkittler over 1 year 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.
Updated by kraih over 1 year 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
Updated by livdywan over 1 year 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.
Updated by livdywan over 1 year 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.
Updated by mkittler over 1 year ago
- Copied to action #128153: [sporadic] typing issue in comments UI test t/15-comments.t size:M added