Just realized I can't use the standard grading method

Just realized I can't use the standard grading method

by Greg Lind -
Number of replies: 23

Moodle 4.5.1+ build 20241213, installed via Git.
PHP 8.3.15
MariaDB 11.6.2 (perhaps an issue?)
Rocky Linux 9.5
Apache 2.4.62
I run this on a physical server. I have admin access.

Symptom: I can use quick grading to enter scores on the submissions page. However, when I click the [Grade] button a page opens with an Undefined modal and the rest of the page just spins while it looks like it's attempting to load content.

See https://moodle.org/mod/forum/discuss.php?d=445337 for her screenshot. I have the same symptom.

After this screen and its associated behavior I am logged out of the server.

Further, after going through these steps and logging back in, when I go to Site administration -> Development -> XMLDB editor -> Check foreign keys I see an error with the suggestion SELECT * FROM {logstore_standard_log} t1 LEFT JOIN {course}...

I have run DELETE t1.* FROM mdl_logstore_standard_log... and re-checked to find no key violations, but when I go back through the grading attempt, the foreign keys error message returns.

So from where I sit it looks like when I try to grade with the typical grade method (i.e. not quick grading) I am logged out and I'm getting odd database activity.

I built this server in September using Moodle 4.4.x from Git. The last time I used "typical" grading was in November. Other than incremental moodle upgrades I am unaware of anything that I have done to cause this. I'm not saying it's a Moodle problem--I just don't know where to start looking. Haha I am also in the middle of teaching classes while I write this so will prob get to do some proper digging while on winter break next week.

Notes: I am using the VPL plugin (never caused issues before). I am running a maybe-too-current version of MariaDB. Other than that it's a very vanilla installation.

The reason I'm posting here anyway: This lady's post is the same symptom I'm having, and with an earlier version of Moodle 4.1.2.

Thanks for any help or suggestions. For now I'm using only quick grading which is doable, but I'm unable to use rubrics since I can't grade in the regular way.

Thanks,
Greg

Average of ratings: -
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Leon Stringer -
Picture of Core developers Picture of Particularly helpful Moodlers

... when I go to Site administration -> Development -> XMLDB editor -> Check foreign keys I see an error with the suggestion SELECT * FROM {logstore_standard_log} t1 LEFT JOIN {course} ...

What error? I don't think the problem you're describing – and undefined error – would be related to mdl_logstore_standard_log. Everything writes to this (assuming you have a fairly standard logging configuration) so any problem is unlikely to manifest itself in such an isolated way as an issue with one grading method with one activity type.

First the basics: switch to the default Boost theme if you're not already using this, and enable debugging so any errors include detailed messages (bullet points 8 and 9).

Then go to the page before undefined appears and open your browser's developer tools. Then click the Grade button. Switch to the console tab in the developer tools (for example, in Firefox). Are there any errors? Then try the test again but switch to the network tab (for example, in Firefox). This shows the requests for the page. Do they all show status 200 OK? If not click on any that don't and tell us the status code, the request URL, and any text in the response. If they do all show status 200 OK try clicking on each request and look at the response. Is there anything that indicates an error?

In reply to Leon Stringer

Re: Just realized I can't use the standard grading method

by Greg Lind -
Thanks to Visvanath and Leon.
 
Visvanath, I see what you're saying. Perhaps this issue should be moved to the Activities -> Assignment forum?

Leon, when I use the dev tools in Firefox I see a 403 POST on the moodle/r.php/api/rest/v2/user/current/preferences file with first.js as initiator. As a symptom I see something similar to this post where you also helped, but I see that the error is different. I am using the vanilla Boost theme.
 
Screenshot of error and related info
 
I didn't see anything in my server logs but I will check more carefully later this afternoon. Thanks for any advice. I have checked file permissions and have audited the user permissions. All check out but will revisit this afternoon. My class is starting in 5 minutes. :P
 
I appreciate the community's experience and advice in helping me shave time off of resolving this issue. I can work around it, but I don't like running a system and not knowing why something is wrong or how to fix it. I can do a new installation and restore courses, etc., but without understanding the problem I think it is likely as not to happen again.
 
Thanks,
Greg
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Greg Lind -

From the modsec_audit.log:

--14f47649-A--
[19/Dec/2024:08:47:19.350078 --0800] Z2ROFzdl8YJsDJPfMd3ldwAAAM0 10.51.2.41 52420 {IP} 443
--14f47649-B--
POST /r.php/api/rest/v2/user/current/preferences HTTP/1.1
Host: {url}
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:133.0) Gecko/20100101 Firefox/133.0
Accept: application/json
Accept-Language: en-US,en;q=0.5
Accept-Encoding: gzip, deflate, br, zstd
Referer: {url}/mod/assign/view.php?id=53&action=grader
Content-Type: application/json
Content-Length: 36
Origin: {url}
Connection: keep-alive
Cookie: {cookieStuff}
Sec-Fetch-Dest: empty
Sec-Fetch-Mode: cors
Sec-Fetch-Site: same-origin
Priority: u=4

--14f47649-C--
{"preferences":{"assign_filter":""}}
--14f47649-F--
HTTP/1.1 403 error/You do not have permission to edit this preference.
X-Powered-By: PHP/8.3.15
Expires: Thu, 19 Nov 1981 08:52:00 GMT
Cache-Control: no-store, no-cache, must-revalidate
Pragma: no-cache
Content-Disposition: inline
Access-Control-Allow-Origin: *
Access-Control-Allow-Methods: GET,POST
Access-Control-Allow-Headers: Content-Type, api_key, Authorization
Set-Cookie: MoodleSession=f4r8n0e7tne29davnp4ca2g026; path=/; secure; HttpOnly
Keep-Alive: timeout=5, max=96
Connection: Keep-Alive
Transfer-Encoding: chunked
Content-Type: application/json

In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Greg Lind -
Using the Headers tab, the first notification points to /user/classes/route/api/preferences.php line 128, which reads:

127   foreach ($preferences as $preference => $value) {
128        $this->set_single_preference($user, $preference, $value);
129   }
 

There must be a default preference that is trying to set on page load?

In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Mary Cooch -
Picture of Documentation writers Picture of Moodle HQ Picture of Particularly helpful Moodlers Picture of Testers Picture of Translators
Just moving this to the Assignment forum as suggested...
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Greg Lind -
Using the Request tab (raw view), I see:

{"preferences":{"assign_filter":""}}

So on page load the site is assigning an empty string as or to a filter. (?) At the moment this is the only site I have so I don't know if that's normal behavior.

(this is more info from the POST with the 403 error)
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

In the modsec_audit.log, are there any lines/references that have at the beginning: 

(Rule: 1234)

If so, those rules could be the culprits! modsec doesn't
give the true error but false one. One has to read the
rule.

'SoS', Ken
In reply to Ken Task

Re: Just realized I can't use the standard grading method

by Greg Lind -
Thank you, Ken. I will look for that this afternoon.  [UPDATE: searching the file for (Rule: gets no results :\ I read up here to try to prep myself.]

I made this video showing the problem, but perhaps more importantly showing that it works as expected on version 4.1.x on the same system (i.e. same Apache, PHP, MariaDB, etc.)

I thought maybe showing the symptoms and comparing systems might help others help me debug. I know it's tough trying to visualize what a person on the other end of the screen is experiencing.

Thanks again,
Greg

Average of ratings: Useful (1)
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Leon Stringer -
Picture of Core developers Picture of Particularly helpful Moodlers

Cookie: {cookieStuff}

Getting an undefined error is one thing. But getting logged out as a result? That's very strange. And in your Response Headers screenshot is Set-Cookie: MoodleSession=f4r8.... That looks to me like Moodle logging you out, and indeed that's what's happening to you. But Moodle shouldn't do this just because there's an error.

When you log in Moodle sends a new MoodleSession cookie value. Then every browser request contains that cookie, until you log out when Moodle sends Set-Cookie: MoodleSession=... with a new value.

When you click Grade with Network Monitor open in your browser tools so that the error occurs work back from r.php/api/rest/v2/user/current/preferences and check the Request Headers and Response Headers. The Request Headers should all contain Cookie: MoodleSession= and this should be the same value. The Response Headers should not contain Set-Cookie: MoodleSession=. Is this the case?, i.e. is r.php/api/rest/v2/user/current/preferences the first request containing Set-Cookie: MoodleSession=?

I realise there's a lot of technical debugging here but I'm struggling to imagine what might be causing this. ModSec could be involved, but the fact you're seeing error/You do not have permission to edit this preference – which is sent by Moodle – makes me doubt this, unless ModSec is altering the browser's request for some reason. I think Ken knows ModSec better than me so maybe he's got ideas of places to look.

In reply to Leon Stringer

Re: Just realized I can't use the standard grading method

by Greg Lind -

Thanks, Leon.

I went back to the previous page, turned on Dev Tools->Networking, then clicked Grade.

Below is a screenshot. It looks like the same info, though doing it from the previous page I now see the XHR info.

I fear this is not what you meant by "work back from ...preferences." Do you mean check the request/response headers of the status 200 entries with the GET method? I am trying to be thorough with this post but feel that it's a swing and a miss if it's just repeating the same information. :\

Yes, I am very confused by what's going on. I feel like it's most likely on my end, but can't think of what I did to cause it. I have been running a Moodle server for around 10 years. I'm no expert, but I'm not without experience. I am stumped at the moment but will keep digging.

Another screen shot showing development tools and networking errors while trying to request a page when Grading assignments.

Thanks,
Greg

P.S. I cropped off the request headers in order to show that all previous requests were successful. I checked and it looked like the requests the same as the previous pic, but I didn't do a side-by-side comparison.

In reply to Leon Stringer

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

I gave up on mod_security .... was getting too many false positives and mis-directed errors - but that could have been result of adding rules from OWASP Core Rule Set (CRS) download.

Watch the video ... but ... that only leads to more questions .. sad

You've given software info and versions but not how you are running php - php as php-fpm?

I recently helped someone that had remi repo and somehow got 2 php-fpm www pools running - one from native and one from remi - would see 'you don't have permission' errors.

From command line:

ps aux |grep php

And the fact you are kicked out and have to login again ... sessions related!!!??? ... moodledata/sessions/ is where those files live.

Any issue with space for moodledata?

Also, how is your cron job running?   From command line?

And another also ... in code/admin/cli/ run check_database_schema

'SoS', Ken

In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

Another thought ...

Around ThanksGiving, Rocky had a point release - uname -a

5.14.0-503.16.1.el9_5.x86_64

Rocky is Red Hat family and uses SELinux.

sestatus

if it says enforcing, set to permissive

setenforce permissive

'SoS', Ken

In reply to Ken Task

Re: Just realized I can't use the standard grading method

by Greg Lind -

Ken:

Checking on php-fpm. Here are the results but I don't know what the results mean:

sudo ps aux | grep php

root      330867  0.0  0.1 476912 40160 ?        Ss   07:51   0:00 php-fpm: master process (/etc/php-fpm.conf)
apache    330869  0.0  0.2 480580 62584 ?        S    07:51   0:00 php-fpm: pool www
apache    330870  0.0  0.2 479340 53052 ?        S    07:51   0:00 php-fpm: pool www
apache    330871  0.0  0.2 480536 62888 ?        S    07:51   0:00 php-fpm: pool www
apache    330872  0.0  0.2 480424 60088 ?        S    07:51   0:00 php-fpm: pool www
apache    330873  0.0  0.2 480420 63576 ?        S    07:51   0:00 php-fpm: pool www
apache    330879  0.0  0.2 480620 63136 ?        S    07:52   0:00 php-fpm: pool www
root      331075  1.3  0.4 517704 110108 ?       Ss   07:59   0:01 php /var/www/html/moodle44/admin/cli/cron.php (Dec 20, 08:01:03 Waiting for next scheduled task)
root      331094  1.1  0.3 486600 80132 ?        Ss   08:00   0:00 php /var/www/html/moodle44/admin/cli/cron.php (Dec 20, 08:01:01 Waiting for next scheduled task)
root      363079  4.1  0.2 481424 62968 ?        Ss   08:01   0:00 /usr/bin/php /var/www/html/moodle44/admin/cli/cron.php
greg      365315  0.0  0.0 221664  2432 pts/0    S+   08:01   0:00 grep --color=auto php

I tried for a while with SELinux set to permissive (i.e. setenforce 0 ) but no changes.

Leon:

With SELinux off, I loaded the Grade page in Firefox with the Dev Tool panel open. It looks like MoodleSession within the request headers is the same for all of the requests in the panel except for within the 403 error (and on previous pages, FWIW). However I see that within the 403 error for /preferences we see that the request header contains the MoodleSession value that was consistent while browsing the site normally, but the response header is setting a new MoodleSession value.

I'm guessing that's why we're seeing a permission error (?), but I have no idea why the server is trying to set a new MoodleSession value at this point. Here's a screenshot because I think I may have clipped this info out of a previous pic:

Another screen shot with arrows highlighting where the response header is attempting to reset the value of MoodleSession.

Next steps (or steps in the meantime):

  • I re-enabled SELinux since turning it off had no effect.
  • I'm going to spin up a fresh installation of the latest 4.5+, restore a class, and see what happens. However, even if it works I'd like to figure out what went wrong with this instance.

In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

Your php-fpm looks ok, but the error you see is a 403 .... access denied.

To start a session moodle, code needs to be able to write a file to moodledata/sessions/

See Leon's answer in this thread:
https://moodle.org/mod/forum/discuss.php?d=416606

moodledata needs very liberal permissions.
ugo+rwx

If located in /var/www/ and the path to it is set in config.php correctly it should belong to apache:apache because that's what php-fpm runs under.
See the /etc/php/php-fpm.conf file.

Also the lines related to cron.
'Waiting for next task' kinda looks like cron job never finishes

What happens if you run cron from command line?

'SoS', Ken

In reply to Ken Task

Re: Just realized I can't use the standard grading method

by Greg Lind -

Thanks, Ken.

  • The moodledata/sessions folder is writeable and owned by user & group apache.

  • I checked how cron.php is working in crontab, and it turns out it was running under root. I changed that to run as apache.

  • When I run cron.php from the command line with sudo -u apache ./cron.php I kept getting the message that it had completed, but also "Continuing to check for tasks for 180 more seconds." While I watched the command line update every second I saw additional tasks happening as it counted down to zero and finally stopped. I'm guessing we see multiple instances of cron.php because a new instance is "fired" every minute, but keeps running for three minutes so there is some overlap?

  • This suggests (oddly) that I should set cron to run every three minutes instead of every minute? IDK I haven't done that yet because (a) I'm probably wrong, and (b) that goes against Moodle's recommendations for running it every minute.

In the meantime:

  • I spun up a new moodle instance with the latest 4.5+ (20241219) and I it works as well as the 4.1.9 instance shown in the video in my previous post. The virtual host config files are the same, so I have no idea why my current, live version is experiencing the problems but not the others. It's the same server with the same settings, but obviously pointing to different root directories. Honestly, I was hoping it would have the same problem so that I could maybe triangulate. Perhaps importantly, I imported one class and its assignments, but haven't imported any students yet. It's just me as the administrator/teacher. Which leads me to...

  • The database(s) is the only thing I haven't explored yet. Each instance uses its own database, and only one instance (i.e. my live instance) is throwing this error at the grading page. Perhaps there's a call to data that's corrupted in my live site's database, and this is causing the error? But that almost doesn't make sense because everything works with users, logins, submitting, quick grading, etc. The only issue is the standard grading procedure, and for me that was a sleeper problem. I ran mariadb-check -u root -p --auto-repair --optimize on it. It was not able to optimize so it rebuilt instead. Still no joy--the issue persists.
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

To stop the cron from the looping, add this line to config.php

$CFG->cron_keepalive='0';

Do you have your cron setup with the 'la-la-land' redirect?

You could change that redirect to a log file that is constantly overwritten and be able to watch the log file in realtime with

tail -f /var/log/moodle-cron.log

How to:

touch /var/log/moodle-cron.log

chown apache:apache /var/log/moodle-cron.log

Then in setup of the cron job .... > /var/log/moodle-cron.log

You could do that for all your moodles ... only to different log files.

I have a server with multiple moodles running.

/var/log//mdlandcli-cron.log
/var/log/mdlsamples-cron.log
/var/log/m44sb-cron.log

Can watch those logs via:

tail -f /var/log/m44sb-cron.log

When it runs for the m44sb instance, I see what it is doing in realtime.

Leave setup of cron to run once every minute .... yes, with multiple instances of moodle that will spike memory usage but not for long.

I do multiple moodle sites using a bash shell script that has 3 one liners ... each line runs different moodle instance.

In the setup of cron job, I point to that script ... they each run, 1 at a time.

Not all task in cron will run at same time ... so some runs of cron job are actually less than other runs.   Obviously, the moodle that is used will have more to do and your sandbox instances will have less.

Please run:

cd /path/to/moodle/code/admin/cli/

php check_database_schema.php

'SoS', Ken

In reply to Ken Task

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

Follow up ... do you have a panel?

If not, suggest installing Webmin.

Perl based ... has it's own web server, doesn't use apache so when the moodle is down you do have a way to get to the box.   It updates itself ... and has useful tools ... like Terminal (don't have to use Putty or workstation client and logs on to shell as root), MySQL tool, and others.

One could also setup a 'support' account in webmin ... restrict that account as to what modules of Webmin could be used.   One could invite then a person to use ... for looksee's or fixes.

'SoS', Ken

In reply to Ken Task

Re: Just realized I can't use the standard grading method

by Greg Lind -
Ah, Redis.

About two months ago I switched from Memcached to Redis. While adding cron_keepalive="0" I saw this glaring difference between the three instances. The 4.1.9 and the newest 4.5+ don't have any $CFG->session_redis entries. I tested the server with Redis and everything seemed to be working well. This might have something to do with the problem, but also might not. I'm going to comment out the Redis-related key/values and see if that has any effect. It might actually mess things up since Moodle's cache settings expect it, but at least it's a switch I can flip. (Argh, see below!)

I ran check_database_schema.php and found that there were multiple issues with my instance of the VPL plugin. I uninstalled the plugin as I don't need it this semester. Here is the message:
-------------------------------------------------------------------------------
vpl
* Unexpected index 'mdl_vpl_cou_ix'.
* Unexpected index 'mdl_vpl_sta_ix'.
* column 'course' is not expected (I)
* column 'name' is not expected (C)
* column 'shortdescription' is not expected (X)
* column 'intro' is not expected (X)
* column 'introformat' is not expected (I)
* column 'startdate' is not expected (I)
* column 'duedate' is not expected (I)
* column 'maxfiles' is not expected (I)
* column 'maxfilesize' is not expected (I)
* column 'requirednet' is not expected (C)
* column 'password' is not expected (C)
* column 'grade' is not expected (I)
* column 'visiblegrade' is not expected (I)
* column 'usevariations' is not expected (I)
* column 'variationtitle' is not expected (C)
* column 'basedon' is not expected (I)
* column 'run' is not expected (I)
* column 'debug' is not expected (I)
* column 'evaluate' is not expected (I)
* column 'evaluateonsubmission' is not expected (I)
* column 'automaticgrading' is not expected (I)
* column 'maxexetime' is not expected (I)
* column 'restrictededitor' is not expected (I)
* column 'example' is not expected (I)
* column 'maxexememory' is not expected (I)
* column 'maxexefilesize' is not expected (I)
* column 'maxexeprocesses' is not expected (I)
* column 'jailservers' is not expected (X)
* column 'worktype' is not expected (I)
* column 'emailteachers' is not expected (I)
* column 'timemodified' is not expected (I)
* column 'freeevaluations' is not expected (I)
* column 'reductionbyevaluation' is not expected (C)
* column 'sebrequired' is not expected (I)
* column 'sebkeys' is not expected (C)
* column 'runscript' is not expected (C)
* column 'debugscript' is not expected (C)
-------------------------------------------------------------------------------
vpl_assigned_overrides
* table is not expected
-------------------------------------------------------------------------------
vpl_assigned_variations
* table is not expected
-------------------------------------------------------------------------------
vpl_jailservers
* table is not expected
-------------------------------------------------------------------------------
vpl_overrides
* table is not expected
-------------------------------------------------------------------------------
vpl_running_processes
* table is not expected
-------------------------------------------------------------------------------
vpl_submissions
* table is not expected
-------------------------------------------------------------------------------
vpl_variations
* table is not expected
-------------------------------------------------------------------------------

I used phpMyAdmin to delete the unexpected tables, as they persisted after uninstalling through Moodle. After manual removal running the script shows Database structure is ok. I went back and re-tried grading but got the same errors. At least my DB is in better shape and perhaps my goofy log errors will stop happening. (note to self to go back and check :P) For the record I don't think this is a fault in VPL, but I think when I made a new server I restored a course that uses the VPL plugin before I installed the plugin on Moodle. I'll investigate that further, but again I think that's an ID10T error on my part, not VPL.
 
I just commented out the Redis config entries and I'm no longer getting the logout grading error. 
 
By Alex E. Proimos - https://www.flickr.com/photos/proimos/4199675334/, CC BY 2.0, https://commons.wikimedia.org/w/index.php?
 
I want to thank everyone so far for helping me get to this point. By looking at other installations it seemed pretty clear that I had done something to cause the problem. Working through the issue with you all helped me look in places I wasn't looking. I'm surprised it was my Redis config, but also this was my first time playing with that and I'm surprised that I didn't have bigger issues since there was clearly a problem all along. TBH, my Redis settings in the config.php file were a kludge of suggestions I found while trying to set it up. 
In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

So is the problem resolved?

If so, put RESOLVED at beginning of the subject line in a response.

I've learned ... over the years ... to really check a site for everything before upgrading and make sure it's functioning like it should ... 0 issues.   An upgrade will more than likely bring issues - especially if going after a .0, or a .1, or even a .2.  

If I do it that way, I know then the newer version is where i need to look.

BTW ... all of my Rocky 9's had some updates today ... how about yours?

'SoS', Ken

In reply to Greg Lind

Re: Just realized I can't use the standard grading method

by Ken Task -
Picture of Particularly helpful Moodlers

if you've been running your cron job as root all this time, that could be the culprit.   Changes to anything in moodledata/ could get tagged as belonging to root user ... apache user would be denied.

So now that you have your cron job running as apache, reset ownerships/permissions on all of moodledata

chown apache:apache moodledata -R

chmod ugo+rwx moodledata -R

'SoS', Ken

Average of ratings: Useful (1)
In reply to Ken Task

RESOLVED: Just realized I can't use the standard grading method

by Greg Lind -

Thanks Ken, Leon, and Visvanath. 

Ken: yes there had been several Rocky 9.5 updates, including the kernel. However, I feel pretty confident it was my lack of understanding of how to properly implement Redis within Moodle that was the problem all along. I will probably tinker with it again now that I know what to look for. But of course I'll also experiment on my sandbox instances before adding back to my live site. ;). I re-ran chown on moodledata as advised.

The initial problem/issue is resolved and anything remaining (if anything at all) would be related and now relatively easy to resolve.

If there are any related follow-ups I'll post them here, but I don't expect any more issues.

Thanks again to the Moodle community for taking the time to help out someone in need.

-Greg

In reply to Greg Lind

Just realized I can't use the standard grading method

by hubert klang -

For info, we had a similar problem ("Undefined" javascript popup box) happening on Moodle 4.5.4+ on a recently-setup test system.  The problem happened immediately after selecting the 'grade' button for an assignment activity. 

My colleague traced our issue to the current user preferences, and after setting the user's editor to TinyMCE the problem was then resolved.

A clue was a HTTP 500 error in the user's browser network info F12 page for url: / api/rest/v2/user/current/preferences/