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

Activity

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.

Tyler Bannister
added a comment - 18/May/11 11:57 PM 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.

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.

Charles Fulton
added a comment - 28/Apr/12 3:28 AM 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.

Dan Poltawski
added a comment - 05/May/12 6:32 PM 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?

Petr Skoda
added a comment - 06/May/12 10:39 PM 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?

Charles Fulton
added a comment - 07/May/12 11:41 AM 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.

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.

Eloy Lafuente (stronk7)
added a comment - 12/May/12 1:35 AM 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

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.

Sam Hemelryk
added a comment - 16/May/12 10:19 AM 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

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.

Charles Fulton
added a comment - 25/May/12 11:54 PM 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.

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.

Sam Hemelryk
added a comment - 06/Jun/12 4:52 AM 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

Eloy Lafuente (stronk7)
added a comment - 12/Jun/12 9:46 AM 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