Bug 32010 - selenium/authentication_2fa.t is failing randomly
Summary: selenium/authentication_2fa.t is failing randomly
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Test Suite (show other bugs)
Version: unspecified
Hardware: All All
: P5 - low major (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Keywords:
Depends on: 30588
Blocks: 25551
  Show dependency treegraph
 
Reported: 2022-10-27 07:53 UTC by Jonathan Druart
Modified: 2023-12-19 09:01 UTC (History)
3 users (show)

See Also:
Change sponsored?: ---
Patch complexity: ---
Documentation contact:
Documentation submission:
Text to go in the release notes:
Version(s) released in:
22.11.00


Attachments
Bug 32010: Make sure the alert will be displayed after the ajax call (4.08 KB, patch)
2022-11-02 08:11 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 32010: Make sure the alert will be displayed after the ajax call (4.14 KB, patch)
2022-11-18 14:18 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 32010: 2AF selenium tests - Alert can appear when we are waiting for ajax (2.10 KB, patch)
2022-11-21 06:58 UTC, Jonathan Druart
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Jonathan Druart 2022-10-27 07:53:55 UTC
Since bug 30588 t/db_dependent/selenium/authentication_2fa.t is failing randomly.

Well, it seems that it fails consistently on jenkins.

17:28:48 koha_1       | STRACE:	/usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch {...} 
17:28:48 koha_1       | 	/usr/share/perl5/Selenium/Remote/Driver.pm:361 in Try::Tiny::try
17:28:48 koha_1       | 	(eval 541):1 in Selenium::Remote::Driver::__ANON__
17:30:50 koha_1       | 	(eval 543):2 in Selenium::Remote::Driver::__ANON__
17:30:50 koha_1       | 	/usr/share/perl5/Selenium/Remote/Driver.pm:654 in Selenium::Remote::Driver::_execute_command
17:30:50 koha_1       | 	t/db_dependent/selenium/authentication_2fa.t:282 in Selenium::Remote::Driver::get_alert_text
17:30:50 koha_1       | 	/usr/share/perl/5.32/Test/Builder.pm:334 in main::__ANON__
17:30:50 koha_1       | 	/usr/share/perl/5.32/Test/Builder.pm:334 in (eval)
17:30:50 koha_1       | 	/usr/share/perl/5.32/Test/More.pm:809 in Test::Builder::subtest
17:30:50 koha_1       | 	t/db_dependent/selenium/authentication_2fa.t:291 in Test::More::subtest
17:30:50 koha_1       | 
17:30:50 selenium_1   | 1666711728262	Marionette	INFO	Stopped listening on port 35969
17:30:50 selenium_1   | JavaScript error: resource://gre/modules/Prompter.jsm, line 1253: NS_ERROR_NOT_AVAILABLE: prompt aborted by user
17:30:50 selenium_1   | JavaScript error: resource:///modules/Interactions.jsm, line 230: NS_ERROR_FAILURE: Component returned failure code: 0x80004005 (NS_ERROR_FAILURE) [nsIUserIdleService.removeIdleObserver]
17:30:50 koha_1       |     # Looks like you planned 7 tests but ran 4.
17:30:50 koha_1       | 
17:30:50 koha_1       | #   Failed test 'Enforce 2FA setup on first login'
17:30:50 koha_1       | #   at t/db_dependent/selenium/authentication_2fa.t line 291.
17:30:50 koha_1       | Error while executing command: no such alert at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.
17:30:50 koha_1       |  at /usr/share/perl5/Selenium/Remote/Driver.pm line 356.
Comment 1 Jonathan Druart 2022-10-27 07:59:10 UTC
There is another error that I get locally

STRACE: /usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch {...} 
        /usr/share/perl5/Selenium/Remote/Driver.pm:361 in Try::Tiny::try        (eval 541):1 in Selenium::Remote::Driver::__ANON__
        (eval 543):2 in Selenium::Remote::Driver::__ANON__
        /usr/share/perl5/Selenium/Remote/Driver.pm:1058 in Selenium::Remote::Driver::_execute_command        /kohadevbox/koha/t/lib/Selenium.pm:203 in Selenium::Remote::Driver::execute_script
        t/db_dependent/selenium/authentication_2fa.t:264 in t::lib::Selenium::wait_for_ajax
        /usr/share/perl/5.32/Test/Builder.pm:334 in main::__ANON__
        /usr/share/perl/5.32/Test/Builder.pm:334 in (eval)        /usr/share/perl/5.32/Test/More.pm:809 in Test::Builder::subtest
        t/db_dependent/selenium/authentication_2fa.t:291 in Test::More::subtest
    # Looks like you planned 7 tests but ran 2.t/db_dependent/selenium/authentication_2fa.t .. 4/5 
#   Failed test 'Enforce 2FA setup on first login'
#   at t/db_dependent/selenium/authentication_2fa.t line 291.Error while executing command: unexpected alert open: Dismissed user prompt dialog: [object Object] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.
 at /usr/share/perl5/Selenium/Remote/Driver.pm line 356.

There is a 500 in the logs:
 "POST /api/v1/app.pl/api/v1/auth/two-factor/registration HTTP/1.1" 500

That is caused by
[ERROR] POST /api/v1/auth/two-factor/registration: unhandled exception (Mojo::Exception)<<Overflow error. version 8
total bits: 1268  max bits: 1232>>
Comment 2 Jonathan Druart 2022-10-27 08:50:42 UTC
(In reply to Jonathan Druart from comment #1)
> There is another error that I get locally
> 
> STRACE: /usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch
> {...} 
>         /usr/share/perl5/Selenium/Remote/Driver.pm:361 in Try::Tiny::try    
> (eval 541):1 in Selenium::Remote::Driver::__ANON__
>         (eval 543):2 in Selenium::Remote::Driver::__ANON__
>         /usr/share/perl5/Selenium/Remote/Driver.pm:1058 in
> Selenium::Remote::Driver::_execute_command       
> /kohadevbox/koha/t/lib/Selenium.pm:203 in
> Selenium::Remote::Driver::execute_script
>         t/db_dependent/selenium/authentication_2fa.t:264 in
> t::lib::Selenium::wait_for_ajax
>         /usr/share/perl/5.32/Test/Builder.pm:334 in main::__ANON__
>         /usr/share/perl/5.32/Test/Builder.pm:334 in (eval)       
> /usr/share/perl/5.32/Test/More.pm:809 in Test::Builder::subtest
>         t/db_dependent/selenium/authentication_2fa.t:291 in
> Test::More::subtest
>     # Looks like you planned 7 tests but ran
> 2.t/db_dependent/selenium/authentication_2fa.t .. 4/5 
> #   Failed test 'Enforce 2FA setup on first login'
> #   at t/db_dependent/selenium/authentication_2fa.t line 291.Error while
> executing command: unexpected alert open: Dismissed user prompt dialog:
> [object Object] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.
>  at /usr/share/perl5/Selenium/Remote/Driver.pm line 356.
> 
> There is a 500 in the logs:
>  "POST /api/v1/app.pl/api/v1/auth/two-factor/registration HTTP/1.1" 500
> 
> That is caused by
> [ERROR] POST /api/v1/auth/two-factor/registration: unhandled exception
> (Mojo::Exception)<<Overflow error. version 8
> total bits: 1268  max bits: 1232>>

Moved to bug 32011.
Comment 3 Jonathan Druart 2022-10-27 09:04:32 UTC
Hum, might be fixed by bug 32011. Will reopen later if not.

*** This bug has been marked as a duplicate of bug 32011 ***
Comment 4 Victor Grousset/tuxayo 2022-10-31 08:59:49 UTC
In 77 runs I got 17 times "not such alert". (line 282) It might be less frequent but not sure.

But the other errors almost disappeared. So bug 32011 helped!
I got only 3 times:
unexpected alert open: Dismissed user prompt dialog: Two-factor [...]. (line 282)
Seem there is still a rare cause that wasn't solved by bug 32011


"not such alert" still happened in the CI:
https://jenkins.koha-community.org/view/master/job/Koha_Master/2248/consoleText

Another CI run got
unexpected alert open: Dismissed user prompt dialog: Two-factor [...]


I also got twice:
```
t/db_dependent/selenium/authentication_2fa.t .. 1/5     # Looks like you planned 12 tests but ran 6.
#   Failed test 'Setup'
#   at t/db_dependent/selenium/authentication_2fa.t line 114.
Cannot wait more for jQuery to be active (wait_for_ajax) at /kohadevbox/koha/t/lib/Selenium.pm line 206.
# Looks like your test exited with 255 just after 1.
t/db_dependent/selenium/authentication_2fa.t .. Dubious, test returned 255 (wstat 65280, 0xff00)
```
It doesn't show where it was called ^^"
Should I add a strackstrace print in t/lib/Selenium.pm ?


So anyway, authentication_2fa.t is still failing randomly
Comment 5 Jonathan Druart 2022-10-31 10:08:15 UTC
Use Carp::Always to get the stacktrace (`perl -MCarp::Always test.t`).

You can also try and extend max_retries and see if it helps.
Comment 6 Victor Grousset/tuxayo 2022-11-02 01:45:09 UTC
> Use Carp::Always to get the stacktrace (`perl -MCarp::Always test.t`).

I meant if should I submit a patch to make diagnosing this easier as wait_for_ajax is in a lot of places. But maybe it's so rare to fail like that.
So ok for now I'll change from using prove to `perl -MCarp::Always` for running UI tests in a loop.

Meanwhile, "not such alert" and "unexpected alert open" come so much more often than hunting for "Cannot wait more for jQuery to be active" would be tedious.

So should ticket this be reopened?
Comment 7 Jonathan Druart 2022-11-02 08:04:52 UTC
In my understanding there is a missing wait_for_ajax call at after we click

The test:
279         $driver->find_element('//*[@id="pin_code"]')->clear;
280         $driver->find_element('//*[@id="pin_code"]')->send_keys($pin_code);
281         $driver->find_element('//*[@id="register-2FA"]')->click;
282         is( $driver->get_alert_text,
283             "Two-factor authentication correctly configured. You will be redirected to the login screen."
284         );
285         $driver->accept_alert;

But wait_for_ajax is waiting for the return of success, and the alert is there.
The code:
250                 $.ajax({
251                     data: data,
252                     type: 'POST',
253                     url: '/api/v1/auth/two-factor/registration/verification',
254                     success: function (data) {
255                         alert(_("Two-factor authentication correctly configured. You will be redirected to the login screen."));
256                         window.location = "/cgi-bin/koha/mainpage.pl";
257                     },
258                     error: function (data) {
259                         const error = data.responseJSON.error;
260                         if ( error == 'Invalid pin' ) {
261                             $("#errors").html(_("Invalid PIN code")).show();
262                         } else {
263                             alert(error);
264                         }
265                     },
266                 });

So either we remove the test, or adjust the code to make the alert appears after the ajax call is done (which may make the code not very nice).
Comment 8 Jonathan Druart 2022-11-02 08:11:58 UTC
Created attachment 142914 [details] [review]
Bug 32010: Make sure the alert will be displayed after the ajax call

There is a missing wait_for_ajax call at after we click but wait_for_ajax
is waiting for the return of success, and the alert is there.

22:01:57 koha_1       | STRACE:	/usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch {...}
22:01:57 koha_1       | 	/usr/share/perl5/Selenium/Remote/Driver.pm:361 in Try::Tiny::try
22:01:57 koha_1       | 	(eval 541):1 in Selenium::Remote::Driver::__ANON__
22:01:57 koha_1       | 	(eval 543):2 in Selenium::Remote::Driver::__ANON__
22:01:57 koha_1       | 	/usr/share/perl5/Selenium/Remote/Driver.pm:654 in Selenium::Remote::Driver::_execute_command
22:01:57 koha_1       | 	t/db_dependent/selenium/authentication_2fa.t:282 in Selenium::Remote::Driver::get_alert_text
22:01:57 koha_1       | 	/usr/share/perl/5.32/Test/Builder.pm:334 in main::__ANON__
22:01:57 koha_1       | 	/usr/share/perl/5.32/Test/Builder.pm:334 in (eval)
22:01:57 koha_1       | 	/usr/share/perl/5.32/Test/More.pm:809 in Test::Builder::subtest
22:01:57 koha_1       | 	t/db_dependent/selenium/authentication_2fa.t:291 in Test::More::subtest
22:01:57 koha_1       |
22:01:57 koha_1       |     # Looks like you planned 7 tests but ran 4.
22:01:57 koha_1       |
22:01:57 koha_1       | #   Failed test 'Enforce 2FA setup on first login'
22:01:57 koha_1       | #   at t/db_dependent/selenium/authentication_2fa.t line 291.
22:01:57 koha_1       | Error while executing command: no such alert at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.
22:01:57 koha_1       |  at /usr/share/perl5/Selenium/Remote/Driver.pm line 356.
22:01:57 koha_1       | # Looks like your test exited with 255 just after 4.
22:01:57 koha_1       | [20:59:37] t/db_dependent/selenium/authentication_2fa.t

Test plan:
Confirm that the test pass (execute it in a loop, hundreds of times)
Confirm that the behaviour of 2FA "enforced" (see bug 30588) is still
working as expected.
Comment 9 Jonathan Druart 2022-11-16 08:55:10 UTC
Upping severity.
Comment 10 Tomás Cohen Arazi 2022-11-18 14:18:39 UTC
Created attachment 144065 [details] [review]
Bug 32010: Make sure the alert will be displayed after the ajax call

There is a missing wait_for_ajax call at after we click but wait_for_ajax
is waiting for the return of success, and the alert is there.

22:01:57 koha_1       | STRACE:	/usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch {...}
22:01:57 koha_1       | 	/usr/share/perl5/Selenium/Remote/Driver.pm:361 in Try::Tiny::try
22:01:57 koha_1       | 	(eval 541):1 in Selenium::Remote::Driver::__ANON__
22:01:57 koha_1       | 	(eval 543):2 in Selenium::Remote::Driver::__ANON__
22:01:57 koha_1       | 	/usr/share/perl5/Selenium/Remote/Driver.pm:654 in Selenium::Remote::Driver::_execute_command
22:01:57 koha_1       | 	t/db_dependent/selenium/authentication_2fa.t:282 in Selenium::Remote::Driver::get_alert_text
22:01:57 koha_1       | 	/usr/share/perl/5.32/Test/Builder.pm:334 in main::__ANON__
22:01:57 koha_1       | 	/usr/share/perl/5.32/Test/Builder.pm:334 in (eval)
22:01:57 koha_1       | 	/usr/share/perl/5.32/Test/More.pm:809 in Test::Builder::subtest
22:01:57 koha_1       | 	t/db_dependent/selenium/authentication_2fa.t:291 in Test::More::subtest
22:01:57 koha_1       |
22:01:57 koha_1       |     # Looks like you planned 7 tests but ran 4.
22:01:57 koha_1       |
22:01:57 koha_1       | #   Failed test 'Enforce 2FA setup on first login'
22:01:57 koha_1       | #   at t/db_dependent/selenium/authentication_2fa.t line 291.
22:01:57 koha_1       | Error while executing command: no such alert at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.
22:01:57 koha_1       |  at /usr/share/perl5/Selenium/Remote/Driver.pm line 356.
22:01:57 koha_1       | # Looks like your test exited with 255 just after 4.
22:01:57 koha_1       | [20:59:37] t/db_dependent/selenium/authentication_2fa.t

Test plan:
Confirm that the test pass (execute it in a loop, hundreds of times)
Confirm that the behaviour of 2FA "enforced" (see bug 30588) is still
working as expected.

Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Comment 11 Tomás Cohen Arazi 2022-11-18 15:08:08 UTC
Pushed to master for 22.11.

Nice work everyone, thanks!
Comment 12 Jonathan Druart 2022-11-21 06:55:47 UTC
This is still failing.

Jenkins is getting "no such alert" and I have "unexpected alert open" locally...
Comment 13 Jonathan Druart 2022-11-21 06:58:03 UTC
Created attachment 144106 [details] [review]
Bug 32010: 2AF selenium tests - Alert can appear when we are waiting for ajax

If we are waiting for ajax (there is a sleep 1s) and the alert pops up
at the same time, Selenium is raising "unexpected alert open"

We should not wait for the ajax request, but better wait for the
alert actually.
Comment 14 Tomás Cohen Arazi 2022-11-22 12:31:45 UTC
Follow-up pushed to master. Thanks!
Comment 15 Fridolin Somers 2023-11-02 20:53:05 UTC
Can we close ?