This is about to inspect apache logs for complete behat runs and fix as many notices / problems are shown there. Aggregating information from all supported themes.

Note that we still have the 3.8 issue (MDL-66881) open, so some of the problems may belong there (and need backport).

Used this regexp against goutte and chrome webserver logs, for reference:

ag -v 'POST|GET|OPTIONS|\] (checking plan|(saving|calculating|loading|setting) controller|(applying|loading|instantiating) (backup|restore|plan)|(activity|section) skipped|setting file inclusion|processing file aliases|Unknown setting: (questionbank|overwrite_conf|course_shortname|course_fullname|course_startdate))|Failed Login: ' aggregated.txt > results.txt

(where aggregated.txt is the union of goutte and chrome web server logs)

Trick: When it's difficult to find which exact behat test is causing the problem, it's useful to run the tests with the --pretty command, getting the date prepended, that way later can match them with the dates in apache error logs. To do so just add the following to your behat run command:

vendor/bin/behat ......  --format pretty --no-colors | awk '{ print strftime("%Y-%m-%d %H:%M:%S"), $0; fflush(); }'

You can see the actual results @ results.txt

Summary:

Problem A: Cannot find session record (maybe it's ok). It happens 1 times.

Happens in scenario "As a student, request deletion of account and data"

52199:[Sat Apr 18 07:01:07.391849 2020] [php7:notice] [pid 7955] [client 172.29.0.8:38944] Cannot find session record 9f87061094b54bc55ebbc3a53f4ffdb0 for user 111000, creating new session., referer: http://runcd9a035d2c706523/behatrun1/user/profile.php?id=111000

Confirmed that it's testing exactly that the session becomes has expired. So 100% ignorable.

Problem B: A required parameter (pageid) was missing. It happens 4 times.

MDL-68995

Happens in scenarios: "questions with images in answers and responses" and "Duplicate question page with image in answer"

73108:[Sat Apr 18 07:48:59.663035 2020] [php7:notice] [pid 31498] [client 172.29.0.9:38992] Default exception handler: A required parameter (pageid) was missing Debug:
Error code: missingparam

• line 498 of /lib/setuplib.php: moodle_exception thrown
• line 562 of /lib/moodlelib.php: call to print_error()
• line 31 of /mod/lesson/editpage.php: call to required_param()
  , referer: http://runcd9a035d2c706523/behatrun2/mod/lesson/editpage.php

In MDL-66881 pholden proposed a possible solution to it. Worth checking. [ link ].

Problem C: Course or activity not accessible (maybe it's ok). It happens 2 times.

MDL-68996

It happens with scenarios: "Do not restore a draft if files have been modified", "Do not restore a draft if text has been modified" and "Content viewed event".

67235:[Sat Apr 18 07:35:51.829527 2020] [php7:notice] [pid 10177] [client 172.29.0.10:38482] Default exception handler: Course or activity not accessible. Debug: You are not logged in
Error code: requireloginerror

• line 2711 of /lib/moodlelib.php: require_login_exception thrown
• line 69 of /lib/editor/atto/autosave-ajax.php: call to require_login()
  , referer: http://runcd9a035d2c706523/behatrun3/course/edit.php?id=105000

The first 2 cases are with the autosave ajax script being not logged in on course edit page. The 3rd with report loglive ajax returning the same. Maybe a pause is needed or something to allow those ajax scripts to know they are logged in.

Problem D: User id 'xxxxxx' already has a grade (recycle bin, maybe it's ok). It happens 1 times.

MDL-68961

Happens with scenario "Delete and restore a quiz with user data.

95836:[Sat Apr 18 08:37:30.503142 2020] [php7:notice] [pid 24203] [client 172.29.0.9:52928] User id '111001' already has a grade entry for grade item id '253000', referer: http://runcd9a035d2c706523/behatrun2/admin/tool/recyclebin/index.php?contextid=101002

The scenario does delete a quiz and then restores it back from the bin. Worth looking which grade-item is still there, because it shouldn't be the quiz one - maybe course one... delegated to MDL subtask.

Problem E: 408 response status. It happens 2 times.

59347:172.29.0.8 - - [18/Apr/2020:07:18:48 +0000] "" 408 0 "" "-"

This had not been reported previously. Requires looking to complete logs trying to find a cause. As of 3.9, haven't been able to reproduce it locally to find a cause / related scenario failing.

 Problem F: Missing contentbank strings in external (sortbyx, sortbyxreverse). It happens 8-10 times.

MDL-68962

Can be reproduced with the "Admins can upload .h5p extension files to content bank" scenario.

52320:[Sat Jun 06 17:30:18.476690 2020] [php7:notice] [pid 516] [client 172.22.0.5:39824] Debugging: Invalid get_string() identifier: 'sortbyx' or component 'contentbank'. Perhaps you are missing $string['sortbyx'] = ''; in lang/en/contentbank.php? in

• line 353 of /lib/classes/string_manager_standard.php: call to debugging()
• line 117 of /lib/external/externallib.php: call to core_string_manager_standard->get_string()
• line 255 of /lib/externallib.php: call to core_external::get_string()
• line 81 of /lib/ajax/service.php: call to external_api::call_external_function()
• line 33 of /lib/ajax/service-nologin.php: call to require_once()
  , referer: http://run43c1f73b3e13e6a1/behatrun3/contentbank/index.php?contextid=1

52321:[Sat Jun 06 17:30:18.477006 2020] [php7:notice] [pid 516] [client 172.22.0.5:39824] Debugging: Invalid get_string() identifier: 'sortbyxreverse' or component 'contentbank'. Perhaps you are missing $string['sortbyxreverse'] = ''; in lang/en/contentbank.php? in

• line 353 of /lib/classes/string_manager_standard.php: call to debugging()
• line 117 of /lib/external/externallib.php: call to core_string_manager_standard->get_string()
• line 255 of /lib/externallib.php: call to core_external::get_string()
• line 81 of /lib/ajax/service.php: call to external_api::call_external_function()
• line 33 of /lib/ajax/service-nologin.php: call to require_once()
  , referer: http://run43c1f73b3e13e6a1/behatrun3/contentbank/index.php?contextid=1

Problem G: Negative limitfrom query parameter detected. It happen 2-3 times.

MDL-68951

Can be reproduced with the "Show all users in a course that match a single filter value" scenario.

77330:[Sat Jun 06 18:29:19.706989 2020] [php7:notice] [pid 15268] [client 172.22.0.5:49594] Debugging: Negative limitfrom parameter detected: -21, did you pass the correct arguments? in

• line 1060 of /lib/dml/moodle_database.php: call to debugging()
• line 867 of /lib/dml/sqlsrv_native_moodle_database.php: call to moodle_database->normalise_limit_from_num()
• line 117 of /user/classes/table/participants_search.php: call to sqlsrv_native_moodle_database->get_recordset_sql()
• line 416 of /user/classes/table/participants.php: call to core_user
  table
  participants_search->get_participants()
• line 2024 of /lib/tablelib.php: call to core_user
  table
  participants->query_db()
• line 210 of /user/classes/table/participants.php: call to table_sql->out()
• line 262 of /lib/table/classes/external/dynamic/get.php: call to core_user
  table
  participants->out()
• line 255 of /lib/externallib.php: call to core_table\\external
  dynamic
  get::execute()
• line 81 of /lib/ajax/service.php: call to external_api::call_external_function()\n
  , referer: http://run43c1f73b3e13e6a1/behatrun3/user/index.php?id=2

And that's all, problems A-D are 100% pre-existing, E-G are new.

I'd propose to check if the B proposal is ok, and apply for it here (backporting to stables). And then confirm the remaining ones to decide if they are real errors or something that we can ignore in the future.

Ciao