Moodle
  1. Moodle
  2. MDL-27559

Purging cache can create massive log file output

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 2.0.3, 2.3
    • Fix Version/s: 2.3
    • Component/s: Administration
    • Labels:
    • Environment:
      Red Hat Enterprise Linux Server release 5.6 (64-bit)
    • Testing Instructions:
      Hide

      1. Change the cache/lang directory to restrictive permissions (for example root:root 750) .
      2. Go to your Moodle site.
      3. Turn debug messages on (set them to Developer)
      4. Go to the "Purge all caches" page.
      5. Click the "Purge all caches" button.

      Show
      1. Change the cache/lang directory to restrictive permissions (for example root:root 750) . 2. Go to your Moodle site. 3. Turn debug messages on (set them to Developer) 4. Go to the "Purge all caches" page. 5. Click the "Purge all caches" button.
    • Affected Branches:
      MOODLE_20_STABLE, MOODLE_23_STABLE
    • Fixed Branches:
      MOODLE_23_STABLE
    • Pull from Repository:
    • Pull Master Branch:
      MDL-27559-master-v2
    • Rank:
      17223

      Description

      I noticed an issue on a test site. When permissions were configured incorrectly, clicking the "purge all caches" button generated 400 MB of log file output. The logged errors were variations on:

      [Wed May 18 10:17:35 2011] [error] [client x.x.x.x] PHP Warning: opendir(/var/www/moodledata/cache/lang) [<a href='functi
      on.opendir'>function.opendir</a>]: failed to open dir: Permission denied in /var/www/html/lib/filelib.php on line 2229, referer:
      http://moodle/admin/purgecaches.php
      [Wed May 18 10:17:35 2011] [error] [client x.x.x.x] PHP Warning: readdir() expects parameter 1 to be resource, boolean given in /var/www/html/lib/filelib.php on line 2230, referer: http://moodle/admin/purgecaches.php

      The failure loop that lead to 400 MB of logs involved those two lines repeated over and over and each time an extra slash was added to the end of the directory until the lines looked like this:
      [Wed May 18 10:17:37 2011] [error] [client x.x.x.x] PHP Warning: readdir() expects parameter 1 to be resource, boolean given in /var/www/html/lib/filelib.php on line 2230, referer: http://moodle/admin/purgecaches.php
      [Wed May 18 10:17:37 2011] [error] [client x.x.x.x] PHP Warning: opendir(/var/www/moodledata/cache/lang/////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////// in /var/www/html/lib/filelib.php on line 2229, referer: http://moodle/admin/purgecaches.php
      [Wed May 18 10:17:37 2011] [error] [client x.x.x.x] PHP Warning: unlink(/var/www/moodledata/cache/lang/////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////////// in /var/www/html/lib/filelib.php on line 2238, referer: http://moodle/admin/purgecaches.php
      [Wed May 18 10:17:37 2011] [error] [client x.x.x.x] PHP Warning: mkdir() [<a href='function.mkdir'>function.mkdir</a>]: Permission denied in /var/ww
      w/html/lib/setuplib.php on line 1058, referer: http://moodle/admin/purgecaches.php
      [Wed May 18 10:17:37 2011] [error] [client x.x.x.x] PHP Warning: file_put_contents(/var/www/moodledata/cache/lang/en/core
      _langconfig.php) [<a href='function.file-put-contents'>function.file-put-contents</a>]: failed to open stream: Permission denied in /var/www/html/lib/moodlelib.php on line 5798, referer: http://moodle/admin/purgecaches.php

      Then the whole process repeats again until eventually I get:

      [Wed May 18 10:20:23 2011] [error] [client x.x.x.x] PHP Fatal error: Maximum execution time of 120 seconds exceeded in /var/www/html/moodlelib.php on line 9409, referer: http://moodle/admin/purgecaches.php

      1. filelib.patch
        0.6 kB
        Tyler Bannister

        Activity

        Hide
        Tyler Bannister added a comment -

        It looks to me like this bug could be fixed by checking the return value of line 2229 in lib/filelib.php. If opendir returns false, the function should abort. Additionally, it might be a good idea to check if the value return from readdir is "" since that seems highly unlikely to be a valid file or directory.

        Show
        Tyler Bannister added a comment - It looks to me like this bug could be fixed by checking the return value of line 2229 in lib/filelib.php. If opendir returns false, the function should abort. Additionally, it might be a good idea to check if the value return from readdir is "" since that seems highly unlikely to be a valid file or directory.
        Hide
        Charles Fulton added a comment -

        We just encountered this as well, under almost the exact circumstances as Tyler (bad permissions, RHEL, test site). We encountered it in a different part of the code. Here's the stack trace (in part):

        opendir(/var/www/mpilot/moodledata/cache/simplepie): failed to open dir: Permission denied in /var/www/mpilot/htdocs/lib/moodlelib.php on line 9972 Warning: readdir() expects parameter 1 to be resource, boolean given in /var/www/mpilot/htdocs/lib/moodlelib.php on line 9974

        I'm submitting a patch to test pointers from opendir; I think I've caught most of the places in core where they aren't.

        Show
        Charles Fulton added a comment - We just encountered this as well, under almost the exact circumstances as Tyler (bad permissions, RHEL, test site). We encountered it in a different part of the code. Here's the stack trace (in part): opendir(/var/www/mpilot/moodledata/cache/simplepie): failed to open dir: Permission denied in /var/www/mpilot/htdocs/lib/moodlelib.php on line 9972 Warning: readdir() expects parameter 1 to be resource, boolean given in /var/www/mpilot/htdocs/lib/moodlelib.php on line 9974 I'm submitting a patch to test pointers from opendir; I think I've caught most of the places in core where they aren't.
        Hide
        Dan Poltawski added a comment -

        Hmm, well this looks fine and so I will submit it for integration.

        But I don't really know if i'd classify this as a bug because moodle is expected to have control of the the moodledata directory?

        Show
        Dan Poltawski added a comment - Hmm, well this looks fine and so I will submit it for integration. But I don't really know if i'd classify this as a bug because moodle is expected to have control of the the moodledata directory?
        Hide
        Petr Škoda added a comment -

        to integrators: please verify that at least something gets printed to error log when we hit invalid permissions

        I suppose this usually happens when you do not use sudo when executing CLI scripts, right?

        Show
        Petr Škoda added a comment - to integrators: please verify that at least something gets printed to error log when we hit invalid permissions I suppose this usually happens when you do not use sudo when executing CLI scripts, right?
        Hide
        Charles Fulton added a comment -

        Dan: I guess I'd still say it's a bug because you should never have an endless loop, and it's not a good idea to use a file or directory pointer without validating it first.

        Petr: not necessarily, though it could. We hit this with a new server that didn't have its permissions provisioned correctly. This wasn't even cron; we were installing an admin tool IIRC.

        Show
        Charles Fulton added a comment - Dan: I guess I'd still say it's a bug because you should never have an endless loop, and it's not a good idea to use a file or directory pointer without validating it first. Petr: not necessarily, though it could. We hit this with a new server that didn't have its permissions provisioned correctly. This wasn't even cron; we were installing an admin tool IIRC.
        Hide
        Eloy Lafuente (stronk7) added a comment -

        The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week.

        TIA and ciao

        Show
        Eloy Lafuente (stronk7) added a comment - The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week. TIA and ciao
        Hide
        Sam Hemelryk added a comment -

        Hi guys,

        This is certainly an improvement to file handling within Moodle.
        I do think it is important as Petr suggested to ensure that something is printed to error logs, especially in situations where things going wrong would go unnoticed or would not be easily debugged.

        I'm sending this back so that the following can be cleaned up:

        1. backup/bb/restore_bb.php That function should be returning an empty array rather than false or nothing has been fixed (as an array is expected). I think it would be a much better idea if we are concerned about this area to improve the checks early on in blackboard_convert, we are reading from that directory and creating subdirectories before we get the subdirectories and before we act upon them.
        2. backup/lib.php is unused now and a legacy from the old backup+restore system. Really it needs to be deleted, I'm not sure why it hasn't, but I imagine Eloy has a good reason. Either way I don't think we should be making any changes here. We should leave that file as it is.
        3. moodlelib.php get_list_of_plugins. As this is returning an array of plugins potentially with some excluded I think that the best approach would be to add a debugging notice here. This way at least dev's can pick up on typo's and/or missing directories, and as one of the first things we do is ask people to turn on debugging when things don't go as expected hopefully those experiencing issues will also get to the root of the problem quicker.
        4. rsslib.php rss_delete_file I think that adding a error_log call here is going to be beneficial. This issue is always going to represent a permission error although not a terrible one as hitting it will only lead to orphaned RSS files that will be cleaned up next time caches are purged. error_log would at least aid in diagnosing any problems.
        5. webdavlib.php webdav_client::mput also the same as above.

        Cheers
        Sam

        Show
        Sam Hemelryk added a comment - Hi guys, This is certainly an improvement to file handling within Moodle. I do think it is important as Petr suggested to ensure that something is printed to error logs, especially in situations where things going wrong would go unnoticed or would not be easily debugged. I'm sending this back so that the following can be cleaned up: backup/bb/restore_bb.php That function should be returning an empty array rather than false or nothing has been fixed (as an array is expected). I think it would be a much better idea if we are concerned about this area to improve the checks early on in blackboard_convert, we are reading from that directory and creating subdirectories before we get the subdirectories and before we act upon them. backup/lib.php is unused now and a legacy from the old backup+restore system. Really it needs to be deleted, I'm not sure why it hasn't, but I imagine Eloy has a good reason. Either way I don't think we should be making any changes here. We should leave that file as it is. moodlelib.php get_list_of_plugins. As this is returning an array of plugins potentially with some excluded I think that the best approach would be to add a debugging notice here. This way at least dev's can pick up on typo's and/or missing directories, and as one of the first things we do is ask people to turn on debugging when things don't go as expected hopefully those experiencing issues will also get to the root of the problem quicker. rsslib.php rss_delete_file I think that adding a error_log call here is going to be beneficial. This issue is always going to represent a permission error although not a terrible one as hitting it will only lead to orphaned RSS files that will be cleaned up next time caches are purged. error_log would at least aid in diagnosing any problems. webdavlib.php webdav_client::mput also the same as above. Cheers Sam
        Hide
        Charles Fulton added a comment -

        Rebased and updated per Sam's suggestions. After more digging we've found another way for this to happen: running cron from cli as root; if the cache dir gets deleted and re-created it might get created as root and be inaccessible to the apache user.

        Show
        Charles Fulton added a comment - Rebased and updated per Sam's suggestions. After more digging we've found another way for this to happen: running cron from cli as root; if the cache dir gets deleted and re-created it might get created as root and be inaccessible to the apache user.
        Hide
        Dan Poltawski added a comment -

        Submitting for integration as seems OK and Sams suggestions have been accomodated.

        Show
        Dan Poltawski added a comment - Submitting for integration as seems OK and Sams suggestions have been accomodated.
        Hide
        Sam Hemelryk added a comment -

        Thanks Charles, changes looked spot on this time and it has been integrated now.
        During integration I did tweak the debugging messages a bit (just to make them clearer) and added DEBUG_DEVELOPER so that we only print them when developer debugging is on.

        Cheers
        Sam

        Show
        Sam Hemelryk added a comment - Thanks Charles, changes looked spot on this time and it has been integrated now. During integration I did tweak the debugging messages a bit (just to make them clearer) and added DEBUG_DEVELOPER so that we only print them when developer debugging is on. Cheers Sam
        Hide
        Frédéric Massart added a comment -

        Success on master!

        Show
        Frédéric Massart added a comment - Success on master!
        Hide
        Eloy Lafuente (stronk7) added a comment -

        We could celebrate it today... but better if we perform a bigger party after releasing Moodle 2.3.

        Print this message and come to Perth that day, it's valid for one beer, wine, coke or... water, as you wish.

        Many thanks for your collaboration!

        Ciao

        Show
        Eloy Lafuente (stronk7) added a comment - We could celebrate it today... but better if we perform a bigger party after releasing Moodle 2.3. Print this message and come to Perth that day, it's valid for one beer, wine, coke or... water, as you wish. Many thanks for your collaboration! Ciao

          People

          • Votes:
            7 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: