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

"filesize(): stat failed" warnings from cache when running multiple front ends

    XMLWordPrintable

    Details

    • Type: Bug
    • Status: Open
    • Priority: Minor
    • Resolution: Unresolved
    • Affects Version/s: 2.5
    • Fix Version/s: None
    • Component/s: Caching
    • Labels:
      None

      Description

      Whenever we're running with two front ends we get lots of warnings in the httpd/error_log files, reporting "stat failed" for various cache files on /var/moodledata. [We run a separate database server and either one or two front ends, with moodledata on an NFS share, with root squash.]

      Here's a typical chunk of the log:

      [Tue Aug 06 15:45:03 2013] [error] [client 132.181.106.231] PHP Warning: filesize(): stat failed for /var/moodledata/cache/cachestore_file/default_application/core_pluginlist/qbe/qbehaviour-004a9f9bcdbd9d73369643f382c25291.cache in /var/www/html/moodle/cache/stores/file/lib.php on line 354, referer: http://quiz.cosc.canterbury.ac.nz/course/modedit.php?update=200&return=1&sesskey=awXzhclNdO
      [Tue Aug 06 15:45:03 2013] [error] [client 132.181.106.231] PHP Warning: filesize(): stat failed for /var/moodledata/cache/cachestore_file/default_application/core_pluginlist/qui/quizaccess-004a9f9bcdbd9d73369643f382c25291.cache in /var/www/html/moodle/cache/stores/file/lib.php on line 354, referer: http://quiz.cosc.canterbury.ac.nz/course/modedit.php?update=200&return=1&sesskey=awXzhclNdO
      [Tue Aug 06 15:45:05 2013] [error] [client 132.181.106.231] PHP Warning: filesize(): stat failed for /var/moodledata/cache/cachestore_file/default_application/core_pluginlist/loc/local-004a9f9bcdbd9d73369643f382c25291.cache in /var/www/html/moodle/cache/stores/file/lib.php on line 354, referer: http://quiz.cosc.canterbury.ac.nz/course/modedit.php?update=200&return=1&sesskey=awXzhclNdO
      [Tue Aug 06 15:45:05 2013] [error] [client 132.181.106.231] PHP Warning: filesize(): stat failed for /var/moodledata/cache/cachestore_file/default_application/core_pluginlist/cou/coursereport-004a9f9bcdbd9d73369643f382c25291.cache in /var/www/html/moodle/cache/stores/file/lib.php on line 354, referer: http://quiz.cosc.canterbury.ac.nz/course/modedit.php?update=200&return=1&sesskey=awXzhclNdO
      [Tue Aug 06 15:45:05 2013] [error] [client 132.181.106.231] PHP Warning: filesize(): stat failed for /var/moodledata/cache/cachestore_file/default_application/core_pluginlist/rep/report-004a9f9bcdbd9d73369643f382c25291.cache in /var/www/html/moodle/cache/stores/file/lib.php on line 354, referer: http://quiz.cosc.canterbury.ac.nz/course/modedit.php?update=200&return=1&sesskey=awXzhclNdO

      The simplest situation under which these occur is when the apache webserver and the apache cronjob run on different front ends i.e., the front end that runs the cronjob /var/www/html/moodle/admin/cli/cron.php every 15 minutes has the apache service switched off while the one with the apache service on has an empty crontab. We then get floods of the above errors on the webserver front end every 15 minutes when the cron job runs on the other server. The files referred to in the error messages do exist. It we run both the cron job and the webserver on the same machine we get no such errors.

      Reading the code (version 2.5+ Build: 20130606), the above errors look like they just shouldn't be possible, because the existence of the file has already been verified prior to the attempt to stat the file. One could imagine that the file might be unreadable while the directory was readable, but in fact the access rights on the files themselves are less restrictive (rw-rw-rw-) than the directories (drwxrws---). Everything on moodledata is owned by apache, and the apache uids are the same on both front ends.

      A different inexplicable (to me) error occurs if I replace the call to filesize with code that attempts to determine the file size by seeking in the file after it has been opened, as follows:

              //$filesize = filesize($file);
              //if (!$filesize) {
              //    return false;
              //}
              // Open ensuring the file for writing, truncating it and setting the pointer to the start.
              // [The above comment doesn't make much sense, but it's straight from the moodle source.]
              if (!$handle = fopen($file, 'rb')) {
                  trigger_error("Couldn't open file $file", E_USER_WARNING);
                  return false;
              }
              if(!fseek($handle, 0, SEEK_END)) {
                  trigger_error("fseek failed for file $file", E_USER_WARNING);
                  return false;
              }
              $filesize = ftell($handle);
              if ($filesize === FALSE) {
                  trigger_error("ftell failed for file $file", E_USER_WARNING);
                  return false;
              }
              rewind($handle);
      

      Now I get a stream of "fseek failed" error messages instead. Again, how can this happen, when the file has not only been checked for existence but actually opened without errors?!

      This looks like some sort of NFS weirdness when the two frontends are simultaneously reading the file. Has anyone else seen anything like this? Is it perhaps related to the problem described in a comment a few lines later:

              // HACK ALERT
              // There is a problem when reading from the file during PHPUNIT tests. For one reason or another the filesize is not correct
              // Doesn't happen during normal operation, just during unit tests.
      

      .

        Attachments

          Issue Links

            Activity

              People

              Assignee:
              Unassigned
              Reporter:
              trampgeek Richard Lobb
              Participants:
              Component watchers:
              Matteo Scaramuccia, Amaia Anabitarte, Carlos Escobedo, Ferran Recio, Sara Arjona (@sarjona)
              Votes:
              5 Vote for this issue
              Watchers:
              11 Start watching this issue

                Dates

                Created:
                Updated: