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.
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>>
(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.
Hum, might be fixed by bug 32011. Will reopen later if not. *** This bug has been marked as a duplicate of bug 32011 ***
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
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.
> 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?
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).
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.
Upping severity.
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>
Pushed to master for 22.11. Nice work everyone, thanks!
This is still failing. Jenkins is getting "no such alert" and I have "unexpected alert open" locally...
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.
Follow-up pushed to master. Thanks!
Can we close ?