Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-68459

Fix problems reported in apache logs before 3.9 release

    XMLWordPrintable

    Details

    • Affected Branches:
      MOODLE_38_STABLE, MOODLE_39_STABLE
    • Fixed Branches:
      MOODLE_39_STABLE

      Description

      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

      In MDL-66881 Paul Holden 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

      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

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              stronk7 Eloy Lafuente (stronk7)
              Reporter:
              stronk7 Eloy Lafuente (stronk7)
              Participants:
              Component watchers:
              Andrew Nicols, Jun Pataleta, Michael Hawkins, Shamim Rezaie, Simey Lameze
              Votes:
              0 Vote for this issue
              Watchers:
              0 Start watching this issue

                Dates

                Created:
                Updated:
                Resolved:
                Fix Release Date:
                15/Jun/20

                  Time Tracking

                  Estimated:
                  Original Estimate - 0 minutes
                  0m
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 1 day, 31 minutes
                  1d 31m