Two recent failures in the CI https://jenkins.koha-community.org/view/19.05/job/Koha_19.05_D8/244/consoleText https://jenkins.koha-community.org/view/19.05/job/Koha_19.05_U18/239/consoleText And I could reproduce locally in Debian 10 on master.
Reproduced after: - first try - 14 tries - first try So it's quite frequent (on my machine)
20.05_D10 run #17 12:50:09 koha_1 | STRACE: /usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch {...} 12:50:09 koha_1 | /usr/local/share/perl/5.28.1/Selenium/Remote/Driver.pm:353 in Try::Tiny::try 12:50:09 koha_1 | (eval 444):1 in Selenium::Remote::Driver::__ANON__ 12:50:09 koha_1 | (eval 446):2 in Selenium::Remote::Driver::__ANON__ 12:50:09 koha_1 | /usr/local/share/perl/5.28.1/Selenium/Remote/Driver.pm:1330 in Selenium::Remote::Driver::_execute_command 12:50:09 koha_1 | /usr/local/share/perl/5.28.1/Selenium/Remote/Driver.pm:1330 in (eval) 12:50:09 koha_1 | t/db_dependent/selenium/authentication.t:99 in Selenium::Remote::Driver::find_element 12:50:09 koha_1 | /usr/share/perl/5.28/Test/Builder.pm:339 in main::__ANON__ 12:50:09 koha_1 | /usr/share/perl/5.28/Test/Builder.pm:339 in (eval) 12:50:09 koha_1 | /usr/share/perl/5.28/Test/More.pm:807 in Test::Builder::subtest 12:50:09 koha_1 | t/db_dependent/selenium/authentication.t:133 in Test::More::subtest 12:50:09 koha_1 | 12:50:09 selenium_1 | 03:50:09.385 INFO - Executing: [take screenshot]) 12:50:09 selenium_1 | 03:50:09.476 INFO - Done: [take screenshot] 12:50:12 koha_1 | 12:50:12 koha_1 | SCREENSHOT: https://framapic.org/0HLdlQpPzrUy/vDNet1p63c6U 12:50:12 koha_1 | # Looks like you planned 6 tests but ran 3. 12:50:12 koha_1 | 12:50:12 koha_1 | # Failed test 'OPAC interface authentication' 12:50:12 koha_1 | # at t/db_dependent/selenium/authentication.t line 133. 12:50:12 koha_1 | An element could not be located on the page using the given search parameters: //div[@id="login"],xpath at t/db_dependent/selenium/authentication.t line 99. 12:50:12 koha_1 | # Looks like your test exited with 255 just after 2. 12:50:12 koha_1 | [10:50:12] t/db_dependent/selenium/authentication.t The screenshot is https://snipboard.io/IQWdmc.jpg
I still don't recreate locally. Victor, can you try to call $driver->get_page_source(); and share the content? Maybe in both t::lib::Selenium->add_error_handler and authentication.t, just after we click #logout
> Victor, can you try to call $driver->get_page_source(); and share the content? Okay! Did 113 run recreating it >_< disabled the additional logging to see if that was the cause. After 20 runs, got this error. it's not related right? t/db_dependent/selenium/authentication.t .. 1/2 STRACE: /usr/share/perl5/Try/Tiny.pm:123 in Selenium::Remote::Driver::catch {...} /usr/local/share/perl/5.28.1/Selenium/Remote/Driver.pm:353 in Try::Tiny::try (eval 444):1 in Selenium::Remote::Driver::__ANON__ (eval 446):2 in Selenium::Remote::Driver::__ANON__ /usr/local/share/perl/5.28.1/Selenium/Remote/Driver.pm:1330 in Selenium::Remote::Driver::_execute_command /usr/local/share/perl/5.28.1/Selenium/Remote/Driver.pm:1330 in (eval) t/db_dependent/selenium/authentication.t:99 in Selenium::Remote::Driver::find_element /usr/share/perl/5.28/Test/Builder.pm:339 in main::__ANON__ /usr/share/perl/5.28/Test/Builder.pm:339 in (eval) /usr/share/perl/5.28/Test/More.pm:807 in Test::Builder::subtest t/db_dependent/selenium/authentication.t:133 in Test::More::subtest # Looks like you planned 6 tests but ran 3. t/db_dependent/selenium/authentication.t .. 2/2 # Failed test 'OPAC interface authentication' # at t/db_dependent/selenium/authentication.t line 133. malformed JSON string, neither tag, array, object, number, string or atom, at character offset 0 (before "(end of string)") at /usr/share/perl5/JSON.pm line 190. # Looks like your test exited with 255 just after 2. t/db_dependent/selenium/authentication.t .. Dubious, test returned 255 (wstat 65280, 0xff00) I'm retrying with the logging added and hoping the original issue to happen.
The previous error might have been due to Selenium being in an invalid state. I got it often until I restarted koha-testing-docker. So. Tested with commit 7b54b529078756556252530bb72903caa88e94e7 to have closer conditions. (master was there when I previously got the error) Still can't get it again after 3438 runs! We will see it some day that happens again. For the record I got this error: t/db_dependent/selenium/authentication.t .. # Failed test 'Patron without permission should be redirected to the login form' # at t/db_dependent/selenium/authentication.t line 57. # '502 Bad Gateway' # doesn't match '(?^u:Access denied)' # Looks like you failed 1 test of 5. t/db_dependent/selenium/authentication.t .. 1/2 # Failed test 'Staff interface authentication' # at t/db_dependent/selenium/authentication.t line 72. It's just to find it in case it happens again. Not worthy of a bug now IMHO.
Master_D10 #299 (Docker 1)
Master_D9 #1393 (Docker 1)
Created attachment 107414 [details] [review] Bug 25811: Debug - Paste the source of the page I am really struggling finding the problem here. Posting the source of the page may help.
Can I have a stamp on this one? I will push it and wait until the next failure in hope it gives us more hint.
Created attachment 107444 [details] [review] Bug 25811: Debug - Paste the source of the page I am really struggling finding the problem here. Posting the source of the page may help. Signed-off-by: Tomas Cohen Arazi <tomascohen@theke.io>
Debug patch pushed to master. Letting this opened for now.
Created attachment 107635 [details] [review] Bug 25811: (follow-up) Debug - Paste the source of the page Wide character in syswrite at /usr/share/perl5/File/Slurp.pm line 506.
Last patch pushed to master.
I'm not too sure whats going on here. I see this bug has a status of assigned and its dependency, 25824, is set to NEW. not backporting, yet.
Hi Lucas, The dependency was wrong. I've pushed this patch for debugging purpose, it's not supposed to be backported. The bug will remain opened until we found the reason of the failure.
Master_D9 #1399
The last failure uploaded the content of the page: https://gdf3.com/FBHWZ7YH Which does contain the '<div id="login">' node...
Created attachment 107716 [details] [review] Bug 25811: Try to fix the random failure caused by not finding id=login
(In reply to Jonathan Druart from comment #17) > The last failure uploaded the content of the page: https://gdf3.com/FBHWZ7YH > > Which does contain the '<div id="login">' node... As the analysis of the failure happens after it, the missing elements can have the time to be loaded. Thanks for the patch, fingers crossed.
(In reply to Jonathan Druart from comment #18) > Created attachment 107716 [details] [review] [review] > Bug 25811: Try to fix the random failure caused by not finding id=login Pushed to master.
Koha_Master_U18 #871 12:20:17 koha_1 | # Failed test 'OPAC interface authentication' 12:20:17 koha_1 | # at t/db_dependent/selenium/authentication.t line 134. 12:20:17 koha_1 | An element could not be located on the page using the given search parameters: //div[@id="login"],xpath at t/db_dependent/selenium/authentication.t line 100. 12:20:17 koha_1 | # Looks like your test exited with 255 just after 2. 12:20:18 koha_1 | [10:20:18] t/db_dependent/selenium/authentication.t https://snipboard.io/6dYKtk.jpg
(In reply to Jonathan Druart from comment #21) > Koha_Master_U18 #871 > > 12:20:17 koha_1 | # Failed test 'OPAC interface authentication' > 12:20:17 koha_1 | # at t/db_dependent/selenium/authentication.t line > 134. > 12:20:17 koha_1 | An element could not be located on the page using > the given search parameters: //div[@id="login"],xpath at > t/db_dependent/selenium/authentication.t line 100. > 12:20:17 koha_1 | # Looks like your test exited with 255 just after 2. > 12:20:18 koha_1 | [10:20:18] t/db_dependent/selenium/authentication.t > > https://snipboard.io/6dYKtk.jpg The screen capture shows we are still logged in. Is it possible: 1 - That the mainpage has been cached and when we 'get' it we are still seeing when we were logged in? 2 - That we are somehow being logged in by another test running at same time? LDAP or Shib or something retaining a logged in cookie? 3 - Could we dump the patron info so we can see if it is this patron that has not been logged out, or another patron that is logged in?
Yes Nick, you are right. And this is the first time it happens actually. Previously we had a logged out screen and the test complained because id="login" did not exist. Now at least it makes sense!
Created attachment 108782 [details] [review] Bug 25811: Add debug info to authentication.t Trying to know if the logged in patron is the one we are expecting to (well, we are not expecting anybody to be logged in at this point!)
Something worth noting, in the last failure there is: 12:20:17 koha_1 | # Failed test 'OPAC interface authentication' 12:20:17 koha_1 | # at t/db_dependent/selenium/authentication.t line 134. 12:20:17 koha_1 | An element could not be located on the page using the given search parameters: //div[@id="login"],xpath at t/db_dependent/selenium/authentication.t line 100. 12:20:17 koha_1 | # Looks like your test exited with 255 just after 2. 12:20:18 koha_1 | [10:20:18] t/db_dependent/selenium/authentication.t ................................ 12:20:18 koha_1 | Dubious, test returned 255 (wstat 65280, 0xff00) 12:20:18 koha_1 | Failed 1/2 subtests 12:20:33 koha_1 | [10:20:33] t/db_dependent/ArticleRequests.t ........................................ ok 14397 ms ( 0.04 usr 0.00 sys + 6.17 cusr 1.18 csys = 7.39 CPU) 12:20:41 koha_1 | [10:20:41] t/db_dependent/Koha/Authorities.t ....................................... ok 7718 ms ( 0.02 usr 0.00 sys + 3.57 cusr 0.60 csys = 4.19 CPU) 12:20:48 koha_1 | [10:20:48] t/db_dependent/Koha/Reviews.t ........................................... ok 7408 ms ( 0.01 usr 0.00 sys + 4.13 cusr 0.73 csys = 4.87 CPU) 12:20:54 selenium_1 | 03:20:54.710 INFO - Executing: [new session: Capabilities [{acceptSslCerts=true, browserName=firefox, javascriptEnabled=true, version=, platform=ANY}]]) 12:20:54 selenium_1 | 03:20:54.722 INFO - Creating a new session for Capabilities [{acceptSslCerts=true, browserName=firefox, javascriptEnabled=true, version=, platform=ANY}] 12:21:25 es_1 | [2020-08-19T10:21:25,083][INFO ][o.e.m.j.JvmGcMonitorService] [aKRN8xK] [gc][1920] overhead, spent [385ms] collecting in the last [1.4s] 12:23:56 koha_1 | Could not create new session: Server returned error message read timeout at /usr/share/perl5/Net/HTTP/Methods.pm line 268. 12:23:56 koha_1 | instead of data at /kohadevbox/koha/t/lib/Selenium.pm line 58. 12:24:06 koha_1 | # Looks like your test exited with 255 before it could output anything. 12:24:10 koha_1 | [10:24:10] t/db_dependent/selenium/basic_workflow.t ................................ 12:24:10 koha_1 | Dubious, test returned 255 (wstat 65280, 0xff00) 12:24:10 koha_1 | Failed 22/22 subtests 12:24:12 selenium_1 | 03:24:12.637 INFO - Done: [new session: Capabilities [{acceptSslCerts=true, browserName=firefox, javascriptEnabled=true, version=, platform=ANY}]] 12:24:39 koha_1 | [10:24:39] t/db_dependent/Koha/Patron/Category.t ................................... ok 27476 ms ( 0.03 usr 0.00 sys + 4.74 cusr 2.53 csys = 7.30 CPU) 12:24:50 koha_1 | [10:24:50] t/db_dependent/Cache.t .................................................. ok 10851 ms ( 0.02 usr 0.01 sys + 1.05 cusr 0.26 csys = 1.34 CPU) 12:25:31 es_1 | [2020-08-19T10:25:23,875][INFO ][o.e.x.m.p.NativeController] [aKRN8xK] Native controller process has stopped - no new native processes can be started 12:25:32 koha_es_1 exited with code 137 koha_es crashed and basic_workflow failed with an unusual error
Created attachment 108796 [details] [review] Bug 25811: Add debug info to authentication.t Trying to know if the logged in patron is the one we are expecting to (well, we are not expecting anybody to be logged in at this point!)
(In reply to Jonathan Druart from comment #26) > Created attachment 108796 [details] [review] [review] > Bug 25811: Add debug info to authentication.t > > Trying to know if the logged in patron is the one we are expecting to > (well, we are not expecting anybody to be logged in at this point!) Pushed to master, wait and see!
Master_U18 #878 But the screen does not show a logged in user: https://snipboard.io/zq7VIv.jpg
(In reply to Victor Grousset/tuxayo from comment #1) > Reproduced after: > - first try > - 14 tries > - first try Should be fixed with bug 27055, the whole test suite was stable during more than a whole night of looping.
Marked as pushed, will follow-up on a separate bug report if needed.