Bug 35506 - selenium/regressions.t is failing randomly
Summary: selenium/regressions.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 normal (vote)
Assignee: Victor Grousset/tuxayo
QA Contact: Testopia
URL:
Keywords:
Depends on:
Blocks: 36581
  Show dependency treegraph
 
Reported: 2023-12-06 15:49 UTC by Jonathan Druart
Modified: 2024-04-11 20:11 UTC (History)
5 users (show)

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


Attachments
Bug 35506: Trying to fix selenium error: Can't call method "get_text" (1.26 KB, patch)
2024-01-04 10:46 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 35506: sabotage checkouts.js to reproduce flacky tests (1.60 KB, patch)
2024-01-12 14:58 UTC, Victor Grousset/tuxayo
Details | Diff | Splinter Review
Bug 35506: Demo of the fix that uses flag in page JS (2.79 KB, patch)
2024-01-12 14:58 UTC, Victor Grousset/tuxayo
Details | Diff | Splinter Review
Bug 35506: [ALTERNATIVE PATCH] Move the checkouts table load delay logic out of document ready (58.22 KB, patch)
2024-01-23 15:05 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 35506: [ALTERNATIVE PATCH] Move the checkouts table load delay logic out of document ready (46.32 KB, patch)
2024-01-23 15:12 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 35506: [ALTERNATIVE PATCH] Move the checkouts table load delay logic out of document ready (46.11 KB, patch)
2024-01-29 16:35 UTC, Jonathan Druart
Details | Diff | Splinter Review
Bug 35506: Move the checkouts table load delay logic out of document ready (46.24 KB, patch)
2024-01-30 11:09 UTC, Victor Grousset/tuxayo
Details | Diff | Splinter Review
Bug 35506: additional hardening of selenium/regressions.t (5.17 KB, patch)
2024-01-30 11:09 UTC, Victor Grousset/tuxayo
Details | Diff | Splinter Review

Note You need to log in before you can comment on or make changes to this bug.
Description Jonathan Druart 2023-12-06 15:49:50 UTC
koha_1       | 
koha_1       |     #   Failed test 'Checkouts table must be correctly aligned'
koha_1       |     #   at t/db_dependent/selenium/regressions.t line 204.
koha_1       |     #          got: ''
koha_1       |     #     expected: '1'
koha_1       |     # thead: 0 ; tfoot: 18 ; tbody: 0
koha_1       |     # Looks like you failed 1 test of 1.
koha_1       | 
koha_1       | #   Failed test 'Display circulation table correctly'
koha_1       | #   at t/db_dependent/selenium/regressions.t line 211.
selenium_1   | JavaScript error: http://kohadev.mydnsname.org:8080/cgi-bin/koha/opac-user.pl, line 859: ReferenceError: ssGPCYcY is not defined
selenium_1   | [Child 2137, MediaDecoderStateMachine #1] WARNING: 7f7ec97e4d60 OpenCubeb() failed to init cubeb: file /builds/worker/checkouts/gecko/dom/media/AudioStream.cpp:324
selenium_1   | [Child 2137, MediaDecoderStateMachine #1] WARNING: Decoder=7f7ecb817400 [OnMediaSinkAudioError]: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3980
selenium_1   | [Child 2137, MediaDecoderStateMachine #1] WARNING: Decoder=7f7ecb817400 Decode error: NS_ERROR_DOM_MEDIA_MEDIASINK_ERR (0x806e000b) - OnMediaSinkAudioError: file /builds/worker/checkouts/gecko/dom/media/MediaDecoderStateMachine.cpp:3541
koha_1       | [13:36:29] t/db_dependent/00-strict.t .................................................. ok       87 ms ( 0.08 usr  0.00 sys + 496.36 cusr 72.29 csys = 568.73 CPU)
koha_1       |     # Looks like you planned 18 tests but ran 1.
koha_1       | 
koha_1       | #   Failed test 'Encoding in session variables'
koha_1       | #   at t/db_dependent/selenium/regressions.t line 340.
koha_1       | Can't call method "get_text" on an undefined value at t/db_dependent/selenium/regressions.t line 325.
koha_1       | # Looks like your test exited with 11 just after 7.
koha_1       | [13:36:34] t/db_dependent/selenium/regressions.t ....................................... 
koha_1       | Dubious, test returned 11 (wstat 2816, 0xb00)
koha_1       | Failed 3/8 subtests 


This was failing on Koha_Master/2760 (Docker_11) but fixed on 2761 (Docker_15). Nothing has been pushed in between.
Comment 1 Jonathan Druart 2023-12-06 15:50:48 UTC
Same failure Koha_Master/2758 on Docker_8
Comment 2 Jonathan Druart 2023-12-06 15:51:30 UTC
Different one Koha_Master/2759 Docker_11

koha_1       | #   Failed test 'Encoding in session variables'
koha_1       | #   at t/db_dependent/selenium/regressions.t line 340.
koha_1       | Can't call method "get_text" on an undefined value at t/db_dependent/selenium/regressions.t line 325.
koha_1       | # Looks like your test exited with 11 just after 7.
koha_1       | [15:45:46] t/db_dependent/selenium/regressions.t ....................................... 
koha_1       | Dubious, test returned 11 (wstat 2816, 0xb00)
Comment 3 Katrin Fischer 2023-12-07 13:36:23 UTC
Failing again with today's run:
https://jenkins.koha-community.org/job/Koha_Master/2762/

t_db_dependent_selenium_regressions_t.Display circulation table correctly (344)
t_db_dependent_selenium_regressions_t.Encoding in session variables (344)
t_db_dependent_selenium_regressions_t.Number of runned tests does not match plan. (344)
Comment 4 Katrin Fischer 2023-12-18 15:54:29 UTC
Still failing as of today on D11

not ok 7 - Encoding in session variables

OK when run locally:

prove t/db_dependent/selenium/regressions.t 
t/db_dependent/selenium/regressions.t .. 6/8 Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 156.
Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 156.
Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 156.
Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 156.
Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 156.
Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 156.
t/db_dependent/selenium/regressions.t .. ok   
All tests successful.
Files=1, Tests=8, 43 wallclock secs ( 0.02 usr  0.01 sys +  3.28 cusr  0.65 csys =  3.96 CPU)
Result: PASS

Can we narrow this down some more somehow?
Comment 5 Jonathan Druart 2023-12-19 09:06:36 UTC
(In reply to Katrin Fischer from comment #4)
> Still failing as of today on D11
> 
> not ok 7 - Encoding in session variables

koha_1       |     #   Failed test 'Checkouts table must be correctly aligned'
koha_1       |     #   at t/db_dependent/selenium/regressions.t line 204.
koha_1       |     #          got: ''
koha_1       |     #     expected: '1'
koha_1       |     # thead: 0 ; tfoot: 18 ; tbody: 0
koha_1       |     # Looks like you failed 1 test of 1.
koha_1       | 
koha_1       | #   Failed test 'Display circulation table correctly'
koha_1       | #   at t/db_dependent/selenium/regressions.t line 211.
selenium_1   | JavaScript error: http://kohadev.mydnsname.org:8080/cgi-bin/koha/opac-user.pl, line 819: ReferenceError: jeKqAq_N is not defined
koha_1       | [15:04:43] t/db_dependent/00-strict.t .................................................. ok       95 ms ( 0.08 usr  0.00 sys + 456.35 cusr 67.23 csys = 523.66 CPU)
koha_1       |     # Looks like you planned 18 tests but ran 1.
koha_1       | 
koha_1       | #   Failed test 'Encoding in session variables'
koha_1       | #   at t/db_dependent/selenium/regressions.t line 340.
koha_1       | Can't call method "get_text" on an undefined value at t/db_dependent/selenium/regressions.t line 325.
koha_1       | # Looks like your test exited with 11 just after 7.
koha_1       | [15:04:44] t/db_dependent/selenium/regressions.t 

Koha_Master/2767 on Docker_15.
Comment 6 Jonathan Druart 2023-12-19 10:45:29 UTC
(In reply to Jonathan Druart from comment #5)
> koha_1       |     #   Failed test 'Checkouts table must be correctly
> aligned'
> koha_1       |     #   at t/db_dependent/selenium/regressions.t line 204.
> koha_1       |     #          got: ''
> koha_1       |     #     expected: '1'
> koha_1       |     # thead: 0 ; tfoot: 18 ; tbody: 0
> koha_1       |     # Looks like you failed 1 test of 1.

Going to submit a patch on bug 35600 that may fix this one.
Comment 7 Jonathan Druart 2023-12-19 10:53:21 UTC
Or fix both, will see.

Another thing to confirm: we click "#issues-table-load-now-button" but we do not make sure it's ticked (maybe we untick it?!)

317             $driver->find_element('//a[@id="issues-table-load-now-button"]')
318               ->click;
Comment 8 Victor Grousset/tuxayo 2023-12-20 00:08:12 UTC
I can reproduce «Can't call method "get_text" on an undefined value»

And I also get this new thing:

	t/db_dependent/selenium/regressions.t:66 in Selenium::Remote::Driver::find_element
[...]
Error while executing command: no such element: Unable to locate element: //span[@class="loggedinusername"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

----

(In reply to Jonathan Druart from comment #6)
> > koha_1       |     #   Failed test 'Checkouts table must be correctly
> > aligned'
> [...] 
> Going to submit a patch on bug 35600 that may fix this one.

Unfortunately I can still get it with and without bug 35600 T_T It doesn't seem to even make it rarer.
Comment 9 Jonathan Druart 2023-12-20 07:29:40 UTC
(In reply to Victor Grousset/tuxayo from comment #8)
> I can reproduce «Can't call method "get_text" on an undefined value»

How? Can you screenshot at this step?

> (In reply to Jonathan Druart from comment #6)
> > > koha_1       |     #   Failed test 'Checkouts table must be correctly
> > > aligned'
> > [...] 
> > Going to submit a patch on bug 35600 that may fix this one.
> 
> Unfortunately I can still get it with and without bug 35600 T_T It doesn't
> seem to even make it rarer.

Same, how?
Comment 10 Martin Renvoize 2023-12-20 10:54:25 UTC
I'm failing to replicate this locally :(.
Comment 11 Victor Grousset/tuxayo 2023-12-20 23:50:58 UTC
(In reply to Jonathan Druart from comment #9)
> (In reply to Victor Grousset/tuxayo from comment #8)
> > I can reproduce «Can't call method "get_text" on an undefined value»
> 
> How? Can you screenshot at this step?

Here is a successful run: https://pic.infini.fr/vZZ7XIKC/1cUjbCHh.png*
And a fail: https://pic.infini.fr/XEdIlOHF/NlCpzGlS.png

"show checkouts" button is greyed. Either it got clicked too fast before having it's handler and stayed like that with no action triggered. Or it tries very fast to do get_text after the button is still somehow not released.
Comment 12 Nick Clemens 2023-12-21 14:04:43 UTC
(In reply to Martin Renvoize from comment #10)
> I'm failing to replicate this locally :(.

I reproduced it with KitchenSink installed, which prevented the checkout because of barcode mismatch - not sure if that could be relevant
Comment 13 Victor Grousset/tuxayo 2023-12-21 16:39:27 UTC
> "show checkouts" button is greyed. Either it got clicked too fast before having it's 
> handler and stayed like that with no action triggered. Or it tries very fast to do 
> get_text after the button is still somehow not released.

I added a 3 second sleep before the screenshot (which is before the get_text) and the button is still greyed. So it's like stuck?! :o

Now with a 10 seconds sleep it seems it stops failing (wow 3 sec sleep is not enough for flaky tests!), so previous hypothesis is unlikely.
Comment 14 Victor Grousset/tuxayo 2023-12-27 16:42:16 UTC
Found some tactics that seem effective on test 'Encoding in session variables'
and test 'Display circulation table correctly'

I'm still letting run over and over to confirm stability and filter all my changes to keep only the necessary ones.
Comment 15 Katrin Fischer 2023-12-28 08:54:50 UTC
Failed again with yesterday's run #2771.
Comment 16 Jonathan Druart 2024-01-04 10:25:45 UTC
(In reply to Victor Grousset/tuxayo from comment #14)
> Found some tactics that seem effective on test 'Encoding in session
> variables'
> and test 'Display circulation table correctly'

Which ones?
Comment 17 Jonathan Druart 2024-01-04 10:46:06 UTC
Created attachment 160511 [details] [review]
Bug 35506: Trying to fix selenium error: Can't call method "get_text"

Just a guess, we should wait for the ajax response before looking for
the element in the table.
Comment 18 Victor Grousset/tuxayo 2024-01-04 23:00:58 UTC
> Created attachment
> Just a guess, we should wait for the ajax response before looking for
> the element in the table.

Wait, I'm really on this! Yes, that's one of things, at this same place. What is DT_delay for?


(In reply to Jonathan Druart from comment #16)
> (In reply to Victor Grousset/tuxayo from comment #14)
> > Found some tactics that seem effective on test 'Encoding in session
> > variables'
> > and test 'Display circulation table correctly'
> 
> Which ones?

https://gitlab.com/tuxayo/Koha/-/commits/bug-35506-selenium-regressions.t-failing-randomly

Here is a summary of what my WIP patch has:
- After asking in Selenium and JavaScript chats, there must be added a way to know if a button is ready to be clicked on. Because $(document).ready() content is long enough so that Selenium can be faster to click on the button before it has it's callback set. The proper thing is something telling the users that the page is still loading or visibly showing that the button isn't ready. For lack of time to go for something on the UI side with a lot of uncertainties, setting a flag at the end of $(document).ready() is one line way to cover a whole page regardless of how many problematic buttons there are.
So the idea is to set in the JS window._pageFullyReady and having the tests wait (with wait_for_page_fully_ready()) for it like wait_for_ajax does. And that can be used on other page by adding the same flag in their $(document).ready() callback.
- Next, so yes wait_for_ajax is needed, but in the +2000 runs I did, dozens of times I got way more than 10 sec wait (noted in the comments next to the calls). For this I had to make max_retries a variable and not a constant so I started doing a getter/setter and messed things up with confusing various ways to do it in Perl and finally noticed that we had __PACKAGE__->mk_accessors ^^"
- A weird thing about having to reload the checkouts page because it's not refreshed after doing a checkout! (more details in the code comment)
- Needing wait_for_ajax to output a stack trace (can't even know which call fail otherwise) and take a screenshot on timeout

So it's almost done. Questions:
1. What is DT_delay for?
2. I only though of it just now: instead of having the flag window._pageFullyReady, should the problematic buttons be hidden in the HTML? (and maybe have a dummy button with a loading icon in place to show the user that stuff it loading) And then the stuff in $(document).ready() makes them visible after setting the onclick callback. And the test just waits for the button to be visible instead of the flag to be set.
Comment 19 Jonathan Druart 2024-01-05 05:40:58 UTC
(In reply to Victor Grousset/tuxayo from comment #18)
> So it's almost done. Questions:
> 1. What is DT_delay for?

We want to make sure the AJAX request is there. In some cases (see bug 35284), the wait_for_ajax was called but the AJAX request was not triggered yet, so we didn't wait for it to finished.

> 2. I only though of it just now: instead of having the flag
> window._pageFullyReady, should the problematic buttons be hidden in the
> HTML? (and maybe have a dummy button with a loading icon in place to show
> the user that stuff it loading) And then the stuff in $(document).ready()
> makes them visible after setting the onclick callback. And the test just
> waits for the button to be visible instead of the flag to be set.

We should not need more than wait_for_ajax here IMO. If it takes more than 10 sec then there is something wrong somewhere else. We could extend the delay specifically for this call.
Comment 20 Victor Grousset/tuxayo 2024-01-05 15:15:46 UTC
(In reply to Jonathan Druart from comment #19)
> > 1. What is DT_delay for?
> 
> We want to make sure the AJAX request is there. In some cases (see bug
> 35284), the wait_for_ajax was called but the AJAX request was not triggered
> yet, so we didn't wait for it to finished.

Ouch, yet another bad thing that can happen >_<
Thankfully, I had no sign of that happening in my +2000 runs. But it might happen on the CI thanks to Murphy's law. So I added it in my WIP patch.

-----

> > 2. I only though of it just now: instead of having the flag
> > window._pageFullyReady, should the problematic buttons be hidden in the
> > HTML? (and maybe have a dummy button with a loading icon in place to show
> > the user that stuff it loading) And then the stuff in $(document).ready()
> > makes them visible after setting the onclick callback. And the test just
> > waits for the button to be visible instead of the flag to be set.
> 
> We should not need more than wait_for_ajax here IMO. 

That's not what is happening here. The wait_for_page_fully_ready uses are for distinct places than wait_for_ajax. Each time it's about not clicking the "Show checkouts" button before it's callback is set. So no XHR involved here to wait for as an alternative.

> If it takes more than
> 10 sec then there is something wrong somewhere else. 

That's another thing than the use of wait_for_page_fully_ready. At least on my machine, the XHR can indeed take more than 10 sec to return (and still work), many times over all my runs. I'm not sure there is really a problem other than a perfect storm that makes the request horribly slow sometimes.

> We could extend the
> delay specifically for this call.

That's precisely what it done in my patch. That's why I had to turn max_retries from a constant to a field with accessors.
Comment 21 Jonathan Druart 2024-01-05 15:32:30 UTC
window._pageFullyReady

I don't understand how this is useful. Selenium should wait for the page to be loaded before starting the tests.

If it's because of async statements, then this won't help.
Comment 22 Victor Grousset/tuxayo 2024-01-05 16:45:50 UTC
(In reply to Jonathan Druart from comment #21)
> window._pageFullyReady
> 
> I don't understand how this is useful. Selenium should wait for the page to
> be loaded before starting the tests.

No, it's not about the page to be loaded. It's about $(document).ready() to have finished all it's content. The event Selenium waits for is the same as the one $(document).ready() waits for IIUC.

So they both start at the same time and from time to time, Selenium reaches the "Show checkouts" button before $(document).ready() {[...]} has reached the point where it give the button it's callback. So Selenium click on an inactive button and nothing happens. That's what I understood from the screenshots showing the button looking like blocked in the pressed position and Koha no doing the expected action. And it seems confirmed by the usage of window._pageFullyReady preventing the issue.

> If it's because of async statements, then this won't help.

I don't know if the following is async, whether attaching the callback is async. But by the time it reaches setting window._pageFullyReady. Then the button is functional and all works as expected.

    $('#issues-table-load-now-button').click(function(){
[....]
    });
Comment 23 Victor Grousset/tuxayo 2024-01-05 16:49:05 UTC
I commented the calls to wait_for_page_fully_ready and after 7 run, I got again this error:

Can't call method "get_text" on an undefined value at t/db_dependent/selenium/regressions.t line 349.
Comment 24 Victor Grousset/tuxayo 2024-01-05 17:00:44 UTC
After rerunning 2 times, I got the other error

    #   Failed test 'Checkouts table must be correctly aligned'
    #   at t/db_dependent/selenium/regressions.t line 213.
    #          got: ''
    #     expected: '1'
    # thead: 0 ; tfoot: 18 ; tbody: 0


So the two main errors of this ticket are fixed by wait_for_page_fully_ready.
I'm not even sure wait_for_ajax fixed anything the CI was hitting. But anyway, I needed them on my PC to be able to do a lot of runs of 'Encoding in session variables' and 'Checkouts table must be correctly aligned' without having interruptions due to long XHR responses.
Comment 25 Jonathan Druart 2024-01-08 13:00:40 UTC
What's the next step then, Victor?
Comment 26 Victor Grousset/tuxayo 2024-01-08 20:41:10 UTC
Great, so the main idea of the patch doesn't have a fatal flaw. That was the main focus of the last few days.

> What's the next step then

There is this question remaining:
Instead of having the flag window._pageFullyReady, should the problematic buttons be hidden in the HTML? (and *maybe* have a dummy button with a loading icon in place to show the user that stuff it loading) And then the stuff in $(document).ready() makes them visible after setting the onclick callback. And the test just waits for the button to be visible instead of the flag to be set.

----

Also, can we try without the sleeps (DT_delay) before wait_for_ajax? That's 10 seconds of sleep in total (because loop). And in my very numerous runs, I never had a failure where wait_for_ajax instantly returned and the table content wasn't loaded. So there are fair chances that the show checkout button isn't affected by the same issue as seen in bug 35284.
Comment 27 Jonathan Druart 2024-01-09 08:13:40 UTC
I do not longer recreate the failure locally so it's hard to help here.

However I do not see how your approach is correct. Selenium waits for the page to load before starting the tests.
I would add a wait_for_element_visible on the page before selecting the th. And I would not add more delay, 10 should be enough.
Comment 28 Victor Grousset/tuxayo 2024-01-09 20:01:34 UTC
(In reply to Jonathan Druart from comment #27)
> However I do not see how your approach is correct. Selenium waits for the
> page to load before starting the tests.

It's a confusing trap ^^ This is a thing that was systematically causing confusion when I was trying to get help on a JavaScript chat.
It's not about the page to be loaded. It's about $(document).ready() to have finished all it's content. The event Selenium waits for is the same as the one $(document).ready() waits for to start executing IIUC. The content of $(document).ready() callback is our stuff and there is no event to mark it's end. The flag is a way to replace that lack.

> I would add a wait_for_element_visible on the page before selecting the th.

IIRC, at the beginning I added a sleep after clicking the "show checkouts" button and the screenshot still showed the button pressed and not even the message that checkouts are loading.
Stuff is just not loading and there is nothing to wait for, the click was too early and didn't trigger the request for checkout list.

Ok here is a way to replicate what happens in the tests! :D

In checkouts.js
After `$(document).ready(function() {`
Add `wait (5000);`

So now it's possible to go hit the "show checkouts" button faster than the callback is set. And we see the same things that the screenshot showed in the early work on this ticket: the button stays down and checkouts never load.

> And I would not add more delay, 10 should be enough.

If there is no sign that the CI is hitting the timeout (we will see since there was no wait_for_ajax here) yeah, let's not have those crazy high ones.
Question 1: Can we still keep the possibility of changing it? (the accessors added by the patch) Because next time I work on flaky tests elsewhere, I'll again need to extend the timeouts to be able to run a lot of times the rest of the tests without hindrance from the very long XHR response times I get.
Question 2: I'm only thinking of this now: shouldn't I have not used accessors but instead have given wait_for_ajax() an optional param to overload the default max_retries? That would be easier to use than
- getting the old max_retries value,
- setting the new value
- after the wait, setting back the original.

Question 3: For a similar reason as to why we won't keep a high max_retries. (we can expect the CI to not hit this need) Can we try without the sleeps (DT_delay) before wait_for_ajax? It's to spare us unconditional sleep() (10 in total) which is more bothering than a timeout and even on my machine that seems to be very good at exposing flaky tests, the need for sleep $DT_delay didn't show up.
Comment 29 Jonathan Druart 2024-01-10 08:22:16 UTC
(In reply to Victor Grousset/tuxayo from comment #28)
> In checkouts.js
> After `$(document).ready(function() {`
> Add `wait (5000);`

"Uncaught ReferenceError: wait is not defined"
Comment 30 Jonathan Druart 2024-01-10 08:23:20 UTC
Can you attach here one patch to recreate the problem and one (as simple as possible) patch to fix it?
Comment 31 Katrin Fischer 2024-01-11 12:52:13 UTC
This one is back on D11 as of today:


koha_1       | 
koha_1       |     #   Failed test 'Checkouts table must be correctly aligned'
koha_1       |     #   at t/db_dependent/selenium/regressions.t line 204.
koha_1       |     #          got: ''
koha_1       |     #     expected: '1'
koha_1       |     # thead: 0 ; tfoot: 18 ; tbody: 0
koha_1       |     # Looks like you failed 1 test of 1.
koha_1       |
Comment 32 Victor Grousset/tuxayo 2024-01-12 14:58:02 UTC
Created attachment 160975 [details] [review]
Bug 35506: sabotage checkouts.js to reproduce flacky tests

== test plan ==
1. apply this patch
2. prove t/db_dependent/selenium/regressions.t
3 . ↓↓↓↓ you get the two failures
t/db_dependent/selenium/regressions.t .. 4/8
    #   at t/db_dependent/selenium/regressions.t line 204.
    #          got: ''
    #     expected: '1'
[...]
Can't call method "get_text" on an undefined value at t/db_dependent/selenium/regressions.t line 325.
Comment 33 Victor Grousset/tuxayo 2024-01-12 14:58:05 UTC
Created attachment 160976 [details] [review]
Bug 35506: Demo of the fix that uses flag in page JS
Comment 34 Victor Grousset/tuxayo 2024-01-12 15:17:22 UTC
(In reply to Jonathan Druart from comment #29)
> (In reply to Victor Grousset/tuxayo from comment #28)
> > In checkouts.js
> > After `$(document).ready(function() {`
> > Add `wait (5000);`
> 
> "Uncaught ReferenceError: wait is not defined"

Oh, it accidentally did the desired effect by acting as a die() and making the buttons never getting the callback.

Sorry for the confusion. It still achieves the goal, you may disregard the error and witness how the "show checkout" button behaves as it was caught by the past screenshot: https://pic.infini.fr/XEdIlOHF/NlCpzGlS.png

-----

(In reply to Jonathan Druart from comment #30)
> Can you attach here one patch to recreate the problem and one (as simple as
> possible) patch to fix it?

After many attempts, there is no possible way to have really a blocking sleep() in JS without also blocking the whole page (can't click on anything).
So something close enough is to delay only the addition of the handler of the "Show checkouts" button.
The PoC of the fix is also changed because the flag can't be set at the end of the content of $(document).ready([...]) but has be set just after the addition of the handler (in the whole code block delayed by the 1st commit replicating the issue).
But that's still close enough logic to demonstrate what the main part of the WIP patch on my repo is doing.

So it here is for the minimal PoC :)
That shows that the main issue is clicking too fast on the button when it has not handler. And showing that the approach with a flag fixes that.
Comment 35 Jonathan Druart 2024-01-23 15:05:47 UTC
Created attachment 161301 [details] [review]
Bug 35506: [ALTERNATIVE PATCH] Move the checkouts table load delay logic out of document ready
Comment 36 Jonathan Druart 2024-01-23 15:06:38 UTC
Then why don't we simply add the event outside of the document.ready?
Comment 37 Jonathan Druart 2024-01-23 15:12:14 UTC
Created attachment 161302 [details] [review]
Bug 35506: [ALTERNATIVE PATCH] Move the checkouts table load delay logic out of document ready
Comment 38 Victor Grousset/tuxayo 2024-01-27 00:45:38 UTC
(In reply to Jonathan Druart from comment #36)
> Then why don't we simply add the event outside of the document.ready?

There is a reason to waiting for the document to be ready. **By default.** But here if we are lucky it's not something that risks not being attached if it's tried too early. So good idea, hundreds of runs will tell if that's something we can get away with.
Comment 39 Victor Grousset/tuxayo 2024-01-29 03:31:31 UTC
note: I'm running on top of b54da05c73 and not main/master since the last big push makes the alternate patch not apply.
If the alternate patch still is pursued, the refactor that moves the function definitions would be easier to deal with in a separate commit to not miss other changes in the diff.

----------------------------------------------------------------------------------------------

Unfortunately it failed. (23 runs)

	t/db_dependent/selenium/regressions.t:190 in Selenium::Remote::Driver::find_element
...
#   Failed test 'No tests run for subtest "Display circulation table correctly"'
...
Error while executing command: no such element: Unable to locate element: //a[@id="issues-table-load-now-button"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

Screenshot shows login screen without filled in credentials. I don't know what is this failure case, my branch doesn't have anything that would have prevented this. So, non conclusive.

----------------------------------------------------------------------------------------------

Another fail (760 runs)
	t/db_dependent/selenium/regressions.t:317 in Selenium::Remote::Driver::find_element
...
#   Failed test 'Encoding in session variables'
....
Error while executing command: no such element: Unable to locate element: //a[@id="issues-table-load-now-button"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

This one might be caused by this weird bug (I'll confirm it if it happens again): https://gitlab.com/tuxayo/Koha/-/commit/759a8dffb7ecedb0feff8ffac81231d0016d8c0d#b635f6d9de31295e092d44725ae114697e8ff560_316_325
So it might not be a sign of the alternate patch failure.
760 runs I almost though the alternate patch was reliable but now I'm not sure, continuing.

----------------------------------------------------------------------------------------------

Another fail (2 run) the variance is insane!
    #   Failed test 'Checkouts table must be correctly aligned'
    #   at t/db_dependent/selenium/regressions.t line 204.
    #          got: ''
    #     expected: '1'
    # thead: 16 ; tfoot: 16 ; tbody: 0
#   Failed test 'Display circulation table correctly'

That might be a need for wait_for_ajax, so I'm adding to be able to continue to test.
That's what I have in my branch before the place it fails.
https://gitlab.com/tuxayo/Koha/-/commit/759a8dffb7ecedb0feff8ffac81231d0016d8c0d#b635f6d9de31295e092d44725ae114697e8ff560_192_198
If it was the previous wait_for_page_fully_ready that was needed, I think we would not see the thead: 16 ; tfoot 16 but the body at 0 size. Likely it means that the table is waiting to load.

----------------------------------------------------------------------------------------------

Another fail (8 runs)
#   Failed test 'Encoding in session variables'
#   at t/db_dependent/selenium/regressions.t line 342.
Can't call method "get_text" on an undefined value at t/db_dependent/selenium/regressions.t line 327.

plack.log shows that /intranet/svc/checkouts?borrowernumber=71 was done. So it's certain it's a need for wait_for_ajax

----------------------------------------------------------------------------------------------

Another fail (3 runs), the difference with the 760 runs is that now I'm using the computer in parallel. Browsing, writing messages in chat mostly. Crazy how that makes a difference.
	t/db_dependent/selenium/regressions.t:319 in Selenium::Remote::Driver::find_element
...
#   Failed test 'Encoding in session variables'
...
Error while executing command: no such element: Unable to locate element: //a[@id="issues-table-load-now-button"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

Ok, I see the checkout is done (in earlier fail, I reset the DB before thinking ok checking this), that confirms I'm hitting this issue.
https://gitlab.com/tuxayo/Koha/-/commit/759a8dffb7ecedb0feff8ffac81231d0016d8c0d#b635f6d9de31295e092d44725ae114697e8ff560_316_326

I'm basically redoing all the secondary fixes again >_<
I hope that will be as quick. The good thing is that it solidifies their utility.

----------------------------------------------------------------------------------------------

after 65 runs
	t/db_dependent/selenium/regressions.t:308 in Selenium::Remote::Driver::find_element
...
#   Failed test 'Encoding in session variables'
....
Error while executing command: no such element: Unable to locate element: //span[@class="logged-in-branch-name"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

Screenshot shows logged out screen. Issue is not something handled in my branch (and I'm not sure I got it) so it's just one more random issue that doesn't tell about the alternate patch.

----------------------------------------------------------------------------------------------

after 30 runs
	t/db_dependent/selenium/regressions.t:325 in Selenium::Remote::Driver::find_element
...
#   Failed test 'Encoding in session variables'
...
Error while executing command: no such element: Unable to locate element: //a[@id="issues-table-load-now-button"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

And screenshot showing checkout page with 0 checkouts. It refreshed per the previous hack introduced to fix another issue that happened twice in previous failures. But why no checkout then? Looking at the logs. Just before the refresh, I see
"GET errors/404.pl HTTP/1.1" 404 29830 "http://koha:8081/cgi-bin/koha/circ/circulation.pl" "Mozilla/5.0 (X11; Linux x86_64; rv:92.0) Gecko/20100101 Firefox/92.0"

Why 404? No idea. No fix to add/attempt :(

----------------------------------------------------------------------------------------------

after 590 runs
	t/db_dependent/selenium/regressions.t:190 in Selenium::Remote::Driver::find_element
...
#   Failed test 'No tests run for subtest "Display circulation table correctly"'
...
Error while executing command: no such element: Unable to locate element: //a[@id="issues-table-load-now-button"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

Screenshot shows logged out screen, session timed out (I know the message isn't always relevant). No idea why.

----------------------------------------------------------------------------------------------

after 6 runs (PC not even used. I though that was when I would almost never fail. But then it fails quick, what is that terrible variance!)
	t/db_dependent/selenium/regressions.t:308 in Selenium::Remote::Driver::find_element
...
#   Failed test 'Encoding in session variables'
...
Error while executing command: no such element: Unable to locate element: //span[@class="logged-in-branch-name"] at /usr/share/perl5/Selenium/Remote/Driver.pm line 411.

Screenshot shows logged out screen, session timed out. Again, no idea why.

----------------------------------------------------------------------------------------------

That's really tough to draw clear conclusions. At least it's certain the alternate patch helps. My only idea to confirm it's as reliable as the 1st proposal is to do to still more runs. Then rebase my branch on top of b54da05c73 and do 1000 or 1500 runs and see if I have the same unexplained fails. I think I had the logout thing only once back when I did the 1st fix proposal.
Comment 40 Jonathan Druart 2024-01-29 16:35:12 UTC
Created attachment 161609 [details] [review]
Bug 35506: [ALTERNATIVE PATCH] Move the checkouts table load delay logic out of document ready
Comment 41 Jonathan Druart 2024-01-29 16:35:32 UTC
(In reply to Victor Grousset/tuxayo from comment #39)
> note: I'm running on top of b54da05c73 and not main/master since the last
> big push makes the alternate patch not apply.

Rebased.

> If the alternate patch still is pursued, the refactor that moves the
> function definitions would be easier to deal with in a separate commit to
> not miss other changes in the diff.

There is nothing else, it's just moving up some code (outside of document.ready).

> That's really tough to draw clear conclusions. At least it's certain the
> alternate patch helps. My only idea to confirm it's as reliable as the 1st
> proposal is to do to still more runs. Then rebase my branch on top of
> b54da05c73 and do 1000 or 1500 runs and see if I have the same unexplained
> fails. I think I had the logout thing only once back when I did the 1st fix
> proposal.

I would push it and see how jenkins behave.
Comment 42 Victor Grousset/tuxayo 2024-01-30 11:07:46 UTC
After some quick testing, the unexpected login page is also something that can happen with the 1st proposal.

(In reply to Jonathan Druart from comment #41)
> There is nothing else, it's just moving up some code (outside of
> document.ready).

I didn't have a reliable way to proofread but here it is:
git show --color-moved --color-moved-ws=allow-indentation-change

It's a perfect tool for this patch :)

> > That's really tough to draw clear conclusions. At least it's certain the
> > alternate patch helps. My only idea to confirm it's as reliable as the 1st
> > proposal is to do to still more runs. Then rebase my branch on top of
> > b54da05c73 and do 1000 or 1500 runs and see if I have the same unexplained
> > fails. I think I had the logout thing only once back when I did the 1st fix
> > proposal.
> 
> I would push it and see how jenkins behave.

The alternate patch had such an easier time vs the 1st proposal to gain trust in it's reliability 🤯

Looking at the patch approach: in the end it's cleaner. Even if moving handler setup out of $(document).ready() looked dodgy, the automated tests should have been the first thing to fail if that was an issue. So nice intuition :) No need for ugly flag and probing for it!

Coming back on previous questions plus some related:
- Can we keep the wait_for_ajax calls? If I need to rerun these tests on a loop, finding again were the calls are needed means having to get a few batches of runs with failures to reintroduce them locally before being able to run the tests long enough to get the relevant failures.
- And without a sleep $DT_delay. I never had a sign of wait_for_ajax returning immediately (due to XHR not yet started) and the test still failing due the request not over. So this place in Koha looks safe regarding the issue needing a sleep. So we can push it and see how jenkins behaves.
- And in wait_for_ajax(), it was sleeping before checking for in progress XHR. Which is redundant with the use of sleep $DT_delay. Better that all the sleep is in one place. And that allow for cases like this test to have 0 sleep and have zero cost of having these wait_for_ajax(). But still being covered when it's needed. Whether locally of if for some reason the CI worker changes and become prone to failing due to XHR here.
- Can we have wait_for_ajax taking a screenshot and printing the stack trace? I had failures that I couldn't diagnose and had to wait to happen again due to lack of screenshot or stack trace.
- And keep the possibility of changing max_retries for wait_for_ajax. (this time I just made it an optional param) So it's easier to investigate flaky tests anywhere else in the suite with wait_for_ajax being fully ready to not cause irrelevant fails with this and the above change.

See the second patch for the above secondary fixes and improvements in t/lib/Selenium.pm

Also, added test plan.

So if that's okay I think all is ready and it just needs someone else to run the test and signoff. And then even if we are both of the authors of a part of the changes, we can QA the part of the other and have this passed QA without needing someone else besides signoff. And finally have this test reliable :D
Comment 43 Victor Grousset/tuxayo 2024-01-30 11:09:06 UTC
Created attachment 161630 [details] [review]
Bug 35506: Move the checkouts table load delay logic out of document ready

== Test plan ==
0. Have Selenium running
   ktd --selenium up
1. prove t/db_dependent/selenium/regressions.t
2. It should still work
Comment 44 Victor Grousset/tuxayo 2024-01-30 11:09:09 UTC
Created attachment 161631 [details] [review]
Bug 35506: additional hardening of selenium/regressions.t

For "Encoding in session variables"
and "Display circulation table correctly"
Using wait_for_ajax.
And a manual refresh of the page.

And make wait_for_ajax display a stack trace and take a screenshot when
timeout.
And make wait_for_ajax taking an optional param for the number of
retries.
Comment 45 Katrin Fischer 2024-01-30 12:33:39 UTC
Hi Victor, did you get a chance to look at Joubu's alternative patch approach?
Comment 46 Victor Grousset/tuxayo 2024-01-30 20:50:01 UTC
Yes, that's the one I was talking about and which looks reliable to fix the issue without creating a new one. And is a cleaner approach.
My additional patch is just a complement to have secondary fixes than were necessary to run the tests 2000 times. And have better debugging because wait_for_ajax in case of timeout was just dying without a screenshot of stack trace to know where was the call.
Comment 47 Katrin Fischer 2024-01-31 10:33:31 UTC
We are still stuck in ASSIGNED here, what is needed to move forward? Can someone else help with review maybe?
Comment 48 Victor Grousset/tuxayo 2024-02-01 02:22:52 UTC
(In reply to Katrin Fischer from comment #47)
> what is needed to move forward?

The questions on comment 42 for Jonathan that are mostly about whether or not the changes that I added in the second patch are ok. (with all the reasons detailed in the comment)
Comment 49 Katrin Fischer 2024-02-02 08:29:37 UTC
I have pushed the first patch yesterday as a compromise and to get this moving. So far, Jenkins seems happy, but as this was a random failure, we are not totally out of the woods yet.
Comment 50 Katrin Fischer 2024-03-15 07:01:28 UTC
We haven't had trouble with this one again, closing for now.
Comment 51 Victor Grousset/tuxayo 2024-03-15 21:33:10 UTC
Nice :D

I'll submit my additional changes in another ticket.