Bug 25811 - authentication.t is failing randomly
Summary: authentication.t is failing randomly
Status: RESOLVED FIXED
Alias: None
Product: Koha
Classification: Unclassified
Component: Test Suite (show other bugs)
Version: master
Hardware: All All
: P5 - low normal (vote)
Assignee: Jonathan Druart
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks: 25551
  Show dependency treegraph
 
Reported: 2020-06-19 05:03 UTC by Victor Grousset/tuxayo
Modified: 2020-12-21 09:01 UTC (History)
5 users (show)

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


Attachments
Bug 25811: Debug - Paste the source of the page (1.35 KB, patch)
2020-07-27 13:01 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25811: Debug - Paste the source of the page (1.40 KB, patch)
2020-07-27 17:09 UTC, Tomás Cohen Arazi
Details | Diff | Splinter Review
Bug 25811: (follow-up) Debug - Paste the source of the page (980 bytes, patch)
2020-07-31 10:56 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25811: Try to fix the random failure caused by not finding id=login (950 bytes, patch)
2020-08-03 15:58 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25811: Add debug info to authentication.t (2.01 KB, patch)
2020-08-21 08:51 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 25811: Add debug info to authentication.t (2.01 KB, patch)
2020-08-21 10:19 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 Victor Grousset/tuxayo 2020-06-19 05:03:19 UTC
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.
Comment 1 Victor Grousset/tuxayo 2020-06-19 05:07:20 UTC
Reproduced after:
- first try
- 14 tries
- first try

So it's quite frequent (on my machine)
Comment 2 Jonathan Druart 2020-06-24 11:38:13 UTC
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
Comment 3 Jonathan Druart 2020-06-25 08:26:24 UTC
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
Comment 4 Victor Grousset/tuxayo 2020-06-25 23:41:15 UTC
> 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.
Comment 5 Victor Grousset/tuxayo 2020-06-27 18:12:50 UTC
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.
Comment 6 Jonathan Druart 2020-07-21 11:26:54 UTC
Master_D10 #299 (Docker 1)
Comment 7 Jonathan Druart 2020-07-27 11:08:28 UTC
Master_D9 #1393 (Docker 1)
Comment 8 Jonathan Druart 2020-07-27 13:01:08 UTC
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.
Comment 9 Jonathan Druart 2020-07-27 13:02:04 UTC
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.
Comment 10 Tomás Cohen Arazi 2020-07-27 17:09:52 UTC
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>
Comment 11 Jonathan Druart 2020-07-30 15:47:55 UTC
Debug patch pushed to master.

Letting this opened for now.
Comment 12 Jonathan Druart 2020-07-31 10:56:19 UTC
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.
Comment 13 Jonathan Druart 2020-07-31 10:57:25 UTC
Last patch pushed to master.
Comment 14 Lucas Gass 2020-07-31 21:11:26 UTC
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.
Comment 15 Jonathan Druart 2020-08-03 15:47:33 UTC
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.
Comment 16 Jonathan Druart 2020-08-03 15:47:41 UTC
Master_D9 #1399
Comment 17 Jonathan Druart 2020-08-03 15:49:45 UTC
The last failure uploaded the content of the page: https://gdf3.com/FBHWZ7YH

Which does contain the '<div id="login">' node...
Comment 18 Jonathan Druart 2020-08-03 15:58:30 UTC
Created attachment 107716 [details] [review]
Bug 25811: Try to fix the random failure caused by not finding id=login
Comment 19 Victor Grousset/tuxayo 2020-08-04 12:16:29 UTC
(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.
Comment 20 Jonathan Druart 2020-08-05 08:21:24 UTC
(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.
Comment 21 Jonathan Druart 2020-08-19 12:46:15 UTC
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
Comment 22 Nick Clemens 2020-08-20 18:35:55 UTC
(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?
Comment 23 Jonathan Druart 2020-08-21 08:12:20 UTC
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!
Comment 24 Jonathan Druart 2020-08-21 08:51:05 UTC
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!)
Comment 25 Jonathan Druart 2020-08-21 09:14:57 UTC
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
Comment 26 Jonathan Druart 2020-08-21 10:19:08 UTC
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!)
Comment 27 Jonathan Druart 2020-08-21 10:34:36 UTC
(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!
Comment 28 Jonathan Druart 2020-08-25 15:17:09 UTC
Master_U18 #878
But the screen does not show a logged in user: https://snipboard.io/zq7VIv.jpg
Comment 29 Victor Grousset/tuxayo 2020-12-18 22:03:57 UTC
(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.
Comment 30 Jonathan Druart 2020-12-21 09:01:00 UTC
Marked as pushed, will follow-up on a separate bug report if needed.