Bug 31199

Koha_Master/2115

This is something else:

koha_1       |     #   Failed test 'Page title is correct after following modification link'
koha_1       |     #   at t/db_dependent/selenium/patrons_search.t line 209.
koha_1       | Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 125.
koha_1       |     #          got: 'Patrons › Koha'
koha_1       |     #     expected: 'Modify patron ePX0okhY <strong>fir's"tname</strong> \123 ❤ (iCTIZxI) test_patron_1 (b7ybqOJXs6C1SCThMgfQa0) (J7gdPI) › Patrons › Koha'

Koha_22.05_D11/124

22:04:42 koha_1       |     # Looks like you planned 24 tests but ran 23.
22:04:42 koha_1       | 
22:04:42 koha_1       | #   Failed test 'Search patrons'
22:04:42 koha_1       | #   at t/db_dependent/selenium/patrons_search.t line 287.
22:04:42 koha_1       | Cannot wait more for jQuery to be active (wait_for_ajax) at /kohadevbox/koha/t/lib/Selenium.pm line 206.
22:06:03 koha_1       | # Looks like your test exited with 255 just after 1.
22:06:03 koha_1       | [21:04:42] t/db_dependent/selenium/patrons_search.t

Koha_22.05_D11/148

Koha_Master/2363

Is this still an issue?

21:53:14 koha_1       |     #   Failed test 'Page title is correct after following modification link'
21:53:14 koha_1       |     #   at t/db_dependent/selenium/patrons_search.t line 221.
21:53:14 koha_1       | Wide character in print at /usr/share/perl/5.32/Test2/Formatter/TAP.pm line 125.
21:53:14 koha_1       |     #          got: 'Patrons › Koha'
21:53:14 koha_1       |     #     expected: 'Modify patron Oku69f8a <strong>fir's"tname</strong> \123 ❤ MTZK7D (C0wnOPhc) test_patron_1 (Sto7McZYrVrtASCB6OGx) (LQbL06M) › Patrons › Koha'

Koha_Master/2625

1..1
# Subtest: Search patrons
    1..25
    ok 1 - All standard fields are searchable if DefaultPatronSearchFields not set. middle_name is there.
    ok 2 - Standard search uses hard coded list when DefaultPatronSearchFields not set
    ok 3 - All standard fields + middle_name are searchable by filter if DefaultPatronSearchFields not set
    ok 4 - Standard filter uses hard coded list when DefaultPatronSearchFields not set
    ok 5 - New option added when DefaultPatronSearchFields is populated with a field. Note that middle_name disappears, we do not want it if not part of DefaultPatronSearchFields
    ok 6 - Standard search uses DefaultPatronSearchFields when populated
    ok 7 - New filter option added when DefaultPatronSearchFields is populated with a field
    ok 8 - Standard filter uses DefaultPatronSearchFields when populated
    ok 9 - Invalid option not added when DefaultPatronSearchFields is populated with an invalid field
    ok 10 - Invalid filter option not added when DefaultPatronSearchFields is populated with an invalid field
    ok 11 - Column "Name" should be the 3rd and contain the firstname correctly filtered
    ok 12 - Column "Name" should be the 3rd and contain the address correctly filtered
    ok 13 - Column "Name" should be the 3rd and contain the email address correctly filtered
    ok 14 - Column "Library" should be the 6th and contain the html tags - they have been html filtered
    ok 15 - Column "Circ note" should be the 10th and not contain the html tags - they have not been html filtered
    ok 16 - Page title is correct after following modification link
    ok 17 - Searching in standard brings back correct results
    ok 18 - Filtering on library works in combination with main search
    ok 19 - Resetting filters works as expected
    ok 20
    ok 21 - Searching on a non-searchable attribute returns no results
    ok 22 - Searching on a searchable attribute returns correct results
    ok 23 - Refining with DataTables search works to further filter the original query
not ok 1 - Search patrons
WARNING: Cleanup failed!

Koha 22.11_D11/257

About "Cannot wait more for jQuery to be active" it seems that we are failing in the following test (line number from 22.11.x)

276     # Adding the surname of the first patron in the "Name" column
277     # We expect only 1 result
278     $s->driver->find_element('//table[@id="'.$table_id.'"]//input[@placeholder="Name search"]')->send_keys($patrons[0]->surname);
279     $s->wait_for_ajax;
280     is( $driver->find_element('//div[@id="'.$table_id.'_info"]')->get_text, sprintf('Showing 1 to %s of %s entries (filtered from %s total entries)', 1, 1, $total_number_of_patrons), 'Refining with header filt    ers works to further filter the original query' );

We could wrap the wait_for_ajax call into an eval and see if it fixes the random failure, but it's quite ugly...

Koha_Master/2668

koha_1       | #   Failed test 'Search patrons'
koha_1       | #   at t/db_dependent/selenium/patrons_search.t line 401.
koha_1       | Cannot wait more for jQuery to be active (wait_for_ajax) at /kohadevbox/koha/t/lib/Selenium.pm line 206.

Koha_Master/2673

I'm just looking at t/lib/Selenium.pm and it looks like the message in "wait_for_ajax" is a bit misleading.

The "die" message should probably say something more like "Cannot wait more for jQuery to be ready - jQuery still has active AJAX requests (wait_for_ajax)"

--

Well the sort of good news is that I've run "prove -v ./t/db_dependent/selenium/patrons_search.t" again and it failed for me this time. It didn't fail yesterday. 

    ok 24 - Refining with header filters works to further filter the original query
    # Subtest: remember_search
        1..7
        ok 1 - Patrons selected is not displayed
        ok 2 - One patron selected
        ok 3 - Two patrons are selected
        ok 4 - Three patrons are selected
        ok 5 - Three patrons still selected
        ok 6
        ok 7
    ok 25 - remember_search
    # Subtest: filter by date of birth
        1..7
        ok 1 - search by correct year shows the patron
        # Looks like you planned 7 tests but ran 1.
    not ok 26 - filter by date of birth

    #   Failed test 'filter by date of birth'
    #   at ./t/db_dependent/selenium/patrons_search.t line 392.
    # Looks like you failed 1 test of 26.
not ok 1 - Search patrons

#   Failed test 'Search patrons'
#   at ./t/db_dependent/selenium/patrons_search.t line 401.
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.
WARNING: Cleanup failed!
Dubious, test returned 255 (wstat 65280, 0xff00)
Failed 1/1 subtests

Test Summary Report
-------------------
./t/db_dependent/selenium/patrons_search.t (Wstat: 65280 Tests: 1 Failed: 1)
  Failed test:  1
  Non-zero exit status: 255
Files=1, Tests=1, 50 wallclock secs ( 0.02 usr  0.02 sys +  4.80 cusr  1.20 csys =  6.04 CPU)
Result: FAIL


Yikes when it fails you have to do a "reset_all" it seems...

I ran a "reset_all" and now "prove -v ./t/db_dependent/selenium/patrons_search.t" returns "All tests successful" twice.

On the third try it failed again although slightly later this time:

    ok 25 - remember_search
    # Subtest: filter by date of birth
        1..7
        ok 1 - search by correct year shows the patron
        ok 2 - search by incorrect year does not show the patron
        ok 3 - search by correct year-month shows the patron
        ok 4 - search by correct full iso date shows the patron
        ok 5 - search by incorrect full iso date does not show the patron
        # Looks like you planned 7 tests but ran 5.
    not ok 26 - filter by date of birth

    #   Failed test 'filter by date of birth'
    #   at ./t/db_dependent/selenium/patrons_search.t line 392.
    # Looks like you failed 1 test of 26.

Another "reset_all" and successful once.

Tried again and failed again at another different spot:

    ok 23 - Refining with DataTables search works to further filter the original query
    # Looks like you planned 26 tests but ran 23.
not ok 1 - Search patrons

#   Failed test 'Search patrons'
#   at ./t/db_dependent/selenium/patrons_search.t line 401.
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.
WARNING: Cleanup failed!
Dubious, test returned 255 (wstat 65280, 0xff00)
Failed 1/1 subtests

I've started tracking the loop iterations inside "wait_for_ajax" and sometimes it will finish within a few seconds and sometimes it takes longer with 10 re-attempts or 10 seconds being where it times out and fails.

5 seconds seems to be fairly common on my machine. 

I've cranked the max retries up to 20 from 10 and now I'm not getting failures when a search takes 12 seconds instead of 5 seconds. 

Of course, it's not clear why sometimes it takes 12 seconds instead of 5 seconds.

(In reply to David Cook from comment #14)
> I've started tracking the loop iterations inside "wait_for_ajax" and
> sometimes it will finish within a few seconds and sometimes it takes longer
> with 10 re-attempts or 10 seconds being where it times out and fails.
> 
> 5 seconds seems to be fairly common on my machine. 
> 
> I've cranked the max retries up to 20 from 10 and now I'm not getting
> failures when a search takes 12 seconds instead of 5 seconds. 
> 
> Of course, it's not clear why sometimes it takes 12 seconds instead of 5
> seconds.

If you recreate this one easily it would be interesting to track it down. Could you maybe enable mysql slow queries and hack the test script to not teardown the data in case of failure, so that we could replay the query and see what's causing the slowness?

Hum, maybe I found a possible cause.

I was seeing "%test_patr%" in the request, but we never send that, we pass "test_patron". Looks like it's missing the delay and several (too many) requests are sent, which is overloading the server.

We expect a 250ms delay between request, it is in 
koha-tmpl/intranet-tmpl/prog/js/datatables.js
114 jQuery.fn.dataTableExt.oApi.fnSetFilteringDelay = function ( oSettings, iDelay ) {

But, the from doc:
https://datatables.net/plug-ins/api/fnSetFilteringDelay
"""
Please note that this plug-in has been deprecated and the dt-init searchDelay option in DataTables 1.10 should now be used. This plug-in will not operate with v1.10+.
"""

(In reply to Jonathan Druart from comment #15)
> If you recreate this one easily it would be interesting to track it down.
> Could you maybe enable mysql slow queries and hack the test script to not
> teardown the data in case of failure, so that we could replay the query and
> see what's causing the slowness?

I haven't found a way to reliably reproduce it. 

(In reply to Jonathan Druart from comment #16)
> Hum, maybe I found a possible cause.
> 
> I was seeing "%test_patr%" in the request, but we never send that, we pass
> "test_patron". Looks like it's missing the delay and several (too many)
> requests are sent, which is overloading the server.

However, I'm tailing plack.log and I think you might be onto something here.

I was looking at "filter by date of birth" and it looks like multiple requests are going out for each of the tests in the subtest with each GET.

It's hard to read the escaped output in plack.log but it looks like each key stroke is sending a GET request. 

I have to head into a meeting, but I think you're on the right track, Jonathan.

However...

I just ran "prove -v ./t/db_dependent/selenium/patrons_search.t" and it failed.

And I see that there is a 9 second gap in between 2 of the test requests which looks like it's just 1 key stroke different. The lack of debouncing might be causing the problem. It looks like Apache or Starman get overwhelmed and that's when this happens... 

--

172.21.0.5 - - [08/Nov/2023:05:30:12 +0000] "GET /api/v1/app.pl/api/v1/patrons?_page=1&_per_page=-1&q=%7B%22-and%22%3A%5B%5B%7B%22me.date_of_birth%22%3A%7B%22like%22%3A%22%2519%25%22%7D%7D%5D%2C%5B%7B%22-and%22%3A%5B%5B%7B%22me.firstname
%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.middle_name%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.surname%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.othernames%22%3A%7B%22like%22%
3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.cardnumber%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.userid%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%5D%5D%7D%2C%7B%22-or%22%3A%5B%7B%22me.firstname%22%3A%7B%22like
%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.middle_name%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.surname%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.othernames%22%3A%7B%22like%22%3A%22%25test_pat
ron%25%22%7D%7D%2C%7B%22me.cardnumber%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.userid%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%5D%7D%2C%7B%22-and%22%3A%5B%5B%7B%22extended_attributes.value%22%3A%7B%22like%2
2%3A%22%25test_patron%25%22%7D%2C%22extended_attributes.code%22%3A%5B%22my%20code2%22%5D%7D%5D%5D%7D%5D%5D%7D&_match=contains&_order_by=%2Bme.surname%2C%2Bme.firstname%2C%2Bme.middle_name%2C%2Bme.othernames%2C%2Bme.street_number%2C%2Bme.
address%2C%2Bme.address2%2C%2Bme.city%2C%2Bme.state%2C%2Bme.postal_code%2C%2Bme.country HTTP/1.1" 200 - "http://kohadev-intra.mydnsname.org:8081/cgi-bin/koha//members/members-home.pl" "Mozilla/5.0 (X11; Linux x86_64; rv:92.0) Gecko/20100
101 Firefox/92.0"


172.21.0.5 - - [08/Nov/2023:05:30:21 +0000] "GET /api/v1/app.pl/api/v1/patrons?_page=1&_per_page=-1&q=%7B%22-and%22%3A%5B%5B%7B%22me.date_of_birth%22%3A%7B%22like%22%3A%22%25198%25%22%7D%7D%5D%2C%5B%7B%22-and%22%3A%5B%5B%7B%22me.firstnam
e%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.middle_name%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.surname%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.othernames%22%3A%7B%22like%22
%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.cardnumber%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.userid%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%5D%5D%7D%2C%7B%22-or%22%3A%5B%7B%22me.firstname%22%3A%7B%22lik
e%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.middle_name%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.surname%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.othernames%22%3A%7B%22like%22%3A%22%25test_pa
tron%25%22%7D%7D%2C%7B%22me.cardnumber%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%2C%7B%22me.userid%22%3A%7B%22like%22%3A%22%25test_patron%25%22%7D%7D%5D%7D%2C%7B%22-and%22%3A%5B%5B%7B%22extended_attributes.value%22%3A%7B%22like%
22%3A%22%25test_patron%25%22%7D%2C%22extended_attributes.code%22%3A%5B%22my%20code2%22%5D%7D%5D%5D%7D%5D%5D%7D&_match=contains&_order_by=%2Bme.surname%2C%2Bme.firstname%2C%2Bme.middle_name%2C%2Bme.othernames%2C%2Bme.street_number%2C%2Bme
.address%2C%2Bme.address2%2C%2Bme.city%2C%2Bme.state%2C%2Bme.postal_code%2C%2Bme.country HTTP/1.1" 200 - "http://kohadev-intra.mydnsname.org:8081/cgi-bin/koha//members/members-home.pl" "Mozilla/5.0 (X11; Linux x86_64; rv:92.0) Gecko/2010
0101 Firefox/92.0"

Aha I think I may have figured it out...

I'm going to do some more testing, but it looks like it fails when the Starman workers have exceeded their request capacity and are restarting.

Starman becomes unavailable while the workers are restarting and that seems to lead to the timeouts.

Going to run a few more times to confirm but was watching "top" to test this theory and I saw a couple seconds after the workers restarted the test failed.

I've been re-running the test and they're passing.

I notice that Starman does restart, but that when it's passing it only restarts 1 Starman worker at a time.

When it failed, I noticed both workers were restarting at the same time.

I've also observed that it takes about 9-10 seconds for a Starman worker to start up in koha-testing-docker.

I was getting bored of endless successful tests so I ran the unit test while also hitting the staff interface main page and I managed to get a test failure, although I wasn't paying enough attention to "top". 

Will try again...

Hmm tough to say. I tried to naturally simulate it but it was tough to try to get them both to restart at the same time. 

But if you do a "kohac-plack --reload kohadev" during "filter by date of birth" you get a failure. 

I've got to run but hopefully that's an additional clue.

I think we just extend "max_retries" to 15 or 20 to allow for a 10 second delay due to restarting Starman workers.

(In reply to Jonathan Druart from comment #16)
> Hum, maybe I found a possible cause.
> 
> I was seeing "%test_patr%" in the request, but we never send that, we pass
> "test_patron". Looks like it's missing the delay and several (too many)
> requests are sent, which is overloading the server.
> 
> We expect a 250ms delay between request, it is in 
> koha-tmpl/intranet-tmpl/prog/js/datatables.js
> 114 jQuery.fn.dataTableExt.oApi.fnSetFilteringDelay = function ( oSettings,
> iDelay ) {
> 
> But, the from doc:
> https://datatables.net/plug-ins/api/fnSetFilteringDelay
> """
> Please note that this plug-in has been deprecated and the dt-init
> searchDelay option in DataTables 1.10 should now be used. This plug-in will
> not operate with v1.10+.
> """

Opened bug 35284.

Created attachment 158690 [details] [review]
Bug 31199: Extend selenium timeout to account for Starman worker restart

Previously, we've had a max retry of 10. If a try takes 1 second, then
the 10 seconds it can take for a Starman worker to restart is enough to
cause a test to fail if both workers are restarting at the same time.

Test plan:
0. DO NOT apply the patch yet
1. Run prove -v ./t/db_dependent/selenium/patrons_search.t
2. When the output says "Subtest: filter by date of birth",
    run "koha-plack --reload kohadev" in a separate window
3. Note that the test fails
4. Run "reset_all"

5. Apply the patch

6. Run prove -v ./t/db_dependent/selenium/patrons_search.t
7. When the output says "Subtest: filter by date of birth",
    run "koha-plack --reload kohadev" in a separate window
8. Note that the test does not fail

I might be wrong but I think that the test is failing because a high volume of requests is causing both Starman workers to restart at the same time. 

You can manually reload the Starman workers to force the tests to fail in this way.

By increasing the max retries for Selenium, the test script will be able to survive a full Starman reload. 

Of course, I think that Bug 35284 is also important. If the unit tests weren't firing off more requests than we want/expect, then the server load would be less, and it would be less likely to trigger a Starman reload. 

But this patch on Bug 31199 should be enough to stop the random failing - I hope.

I don't think this is a good idea, it would hide other problems (like the one caught by this 31199: no more delay between 2 DT requests, which is a quite big problem for server perfs IMO).

I would first try to fix 31199 and see if this is still failing.

(In reply to Jonathan Druart from comment #26)
> I don't think this is a good idea, it would hide other problems (like the
> one caught by this 31199: no more delay between 2 DT requests, which is a
> quite big problem for server perfs IMO).
> 
> I would first try to fix 31199 and see if this is still failing.

I was thinking about that as well. On one hand, I think it's good to be able to survive Starman workers reloading. On the other hand, as you say, it would/could hide other problems. 

I think you meant bug 35284? I'm OK with that one being pushed and then seeing how we go. In theory, if we're not hitting the server with too many requests, then this scenario of having a full Starman reload shouldn't happen I think.

(In reply to David Cook from comment #27)
> I think you meant bug 35284?

Yes!

This test just failed again on yesterday's run:

koha_1       |     # Looks like you planned 27 tests but ran 23.
koha_1       | 
koha_1       | #   Failed test 'Search patrons'
koha_1       | #   at t/db_dependent/selenium/patrons_search.t line 431.
koha_1       | Cannot wait more for jQuery to be active (wait_for_ajax) at /kohadevbox/koha/t/lib/Selenium.pm line 206.
koha_1       | # Looks like your test exited with 255 just after 1.
koha_1       | [18:42:48] t/db_dependent/selenium/patrons_search.t .................................... 
koha_1       | Dubious, test returned 255 (wstat 65280, 0xff00)
koha_1       | Failed 1/1 subtests

Waiting for bug 35396 before getting back to this one.

Reporting here but it's not related with the previous comments:

Koha_Main/2913

10:12:10 koha_1       |     #   Failed test 'Page title is correct after following modification link'
10:12:10 koha_1       |     #   at t/db_dependent/selenium/patrons_search.t line 268.
10:12:10 koha_1       | Wide character in print at /usr/share/perl/5.36/Test2/Formatter/TAP.pm line 125.
10:12:10 koha_1       |     #          got: 'Patrons › Koha'
10:12:10 koha_1       |     #     expected: 'Modify patron Ly_AtV <strong>fir's"tname</strong> \123 ❤ test_patron_1 (tyBRnYVwhHYQtrl36Ph07HyQTDCfzn5) (bDvJbKkmo) › Patrons › Koha'
10:12:10 koha_1       |     # Looks like you failed 1 test of 28.
10:12:10 koha_1       | 
10:12:10 koha_1       | #   Failed test 'Search patrons'
10:12:10 koha_1       | #   at t/db_dependent/selenium/patrons_search.t line 464.
10:12:10 selenium_1   | JavaScript error: http://kohadev-intra.mydnsname.org:8081/cgi-bin/koha//members/members-home.pl, line 3221: TypeError: libraries_map[data] is undefined
10:12:10 koha_1       | # Looks like you failed 1 


This is happening when a library has been created after the page has been loaded. The patron is fetched from the REST API with a given library, but the dropdown list/js variable does not have it.

The good thing is that the previous errors didn't appear since the last fixes

Koha_Main/3075

18:25:57 koha_1       |     #   Failed test 'Page title is correct after following modification link'
18:25:57 koha_1       |     #   at t/db_dependent/selenium/patrons_search.t line 268.
18:25:57 koha_1       | Wide character in print at /usr/share/perl/5.36/Test2/Formatter/TAP.pm line 125.
18:25:57 koha_1       |     #          got: 'Patrons › Koha'
18:25:57 koha_1       |     #     expected: 'Modify patron a0tqFKBK <strong>fir's"tname</strong> \123 ❤ test_patron_1 (kdcCPHHPvgV9sR4KRCpPkDS31A) (tG8Qxn1) › Patrons › Koha'
18:25:57 koha_1       |     # Looks like you failed 1 test of 28.
18:25:57 koha_1       | 
18:25:57 koha_1       | #   Failed test 'Search patrons'
18:25:57 koha_1       | #   at t/db_dependent/selenium/patrons_search.t line 464.
18:25:57 selenium_1   | JavaScript error: http://kohadev-intra.mydnsname.org:8081/cgi-bin/koha//members/members-home.pl, line 3290: TypeError: libraries_map[data] is undefined
18:25:57 koha_1       | # Looks like you failed 1 test of 2.
18:25:57 koha_1       | [17:23:48] t/db_dependent/selenium/patrons_search.t