Temp Files in Cache Directory Fail to Clear #397

raamdev · 2015-01-12T20:01:54Z

Forked from Issue #288 ("Fatal Error: 'Unable to clear dir'").

This has been an ongoing issue since implementing cache locking in #288. The bug presents itself as a cache directory with many *-tmp cache files that fail to clear when the Clear Cache button is clicked or when an automatic clear cache routine is run.

A Quick Cache Pro user reports in a support ticket the following error appears at various times when Quick Cache runs a clear routine, such as when adding a new post:

Warning: rename(/var/sites/f/mydomain.co.uk/public_html/wp-content/cache/quick-cache/cache/http/www-mydomain-co-uk-54b3ed17443a4352558262-tmp,/var/sites/f/mydomain.co.uk/public_html/wp-content/cache/quick-cache/cache/http/www-mydomain-co-uk): File exists in /var/sites/f/mydomain.co.uk/public_html/wp-content/plugins/quick-cache-pro/includes/share.php on line 1688

Fatal error: Uncaught exception 'Exception' with message 'Unable to delete files. Rename failure on tmp directory: `/var/sites/f/mydomain.co.uk/public_html/wp-content/cache/quick-cache/cache/http/www-mydomain-co-uk-54b3ed17443a4352558262-tmp`.' in /var/sites/f/mydomain.co.uk/public_html/wp-content/plugins/quick-cache-pro/includes/share.php:1689 
Stack trace: 
#0 /var/sites/f/mydomain.co.uk/public_html/wp-content/plugins/quick-cache-pro/includes/share.php(1428): quick_cache\share->delete_files_from_host_cache_dir('/^\\//aaegory\\//...') 
#1 /var/sites/f/mydomain.co.uk/public_html/wp-content/plugins/quick-cache-pro/quick-cache-pro.inc.php(2152): quick_cache\share->clear_files_from_host_cache_dir('/^\\//aaegory\\//...') 
#2 [internal function]: quick_cache\plugin->auto_clear_post_terms_cache(9502) 
#3 /var/sites/f/mydomain.co.uk/public_html/wp-includes/plugin.php(496): call_user_func_array(Array, Array) 
#4 /var/sites/f/mydomain.co.uk/public_html/wp-includes/taxonomy.php(3025): do_action(' in/var/sites/f/mydomain.co.uk/public_html/wp-content/plugins/quick-cache-pro/includes/share.php on line 1689

@mchlbrry reports in #288 (comment):

[08-Jan-2015 21:17:03 UTC] PHP Fatal error:  Uncaught exception 'RuntimeException' with message 'SplFileInfo::getMTime(): stat failed for /var/www/html/wordpress/wp-content/cache/quick-cache/cache/http/www-domain-com-54aef3cf69cc8928126844-tmp/album-of-the-year-2013.html' in /var/www/html/wordpress/wp-content/plugins/quick-cache-pro/includes/share.php:1675
Stack trace:
#0 /var/www/html/wordpress/wp-content/plugins/quick-cache-pro/includes/share.php(1675): SplFileInfo->getMTime()
#1 /var/www/html/wordpress/wp-content/plugins/quick-cache-pro/includes/share.php(1462): quick_cache\share->delete_files_from_host_cache_dir('/^.+/i', true)
#2 /var/www/html/wordpress/wp-content/plugins/quick-cache-pro/quick-cache-pro.inc.php(1291): quick_cache\share->purge_files_from_host_cache_dir('/^.+/i')
#3 [internal function]: quick_cache\plugin->purge_cache()
#4 /var/www/html/wordpress/wp-includes/plugin.php(580): call_user_func_array(Array, Array)
#5 /var/www/html/wordpress/wp-cron.php(103): do_action_ref_array('_cron_quick_cac...', Array)
#6 {main}
  thrown in /var/www/html/wordpress/wp-content/plugins/quick-cache-pro/includes/share.php on line 1675

@jaswsinc also reported seeing this 'SplFileInfo::getMTime(): stat failed error on s2Member.com.

The text was updated successfully, but these errors were encountered:

jaswrks · 2015-01-12T20:26:57Z

This has been an ongoing issue since implementing cache locking in #288.

Thanks! Just wanted to clarify that errors like these were present both before and after cache locking. The recent cache locking improvements were aimed at resolving this issue.

I'm seeing this issue occur randomly two or three times each week. Looking over the codebase it would seem impossible, and thus I'm guessing at this point that it's still due to some corruption in the stat cache on some versions of PHP. A possible workaround for this might include being more aggressive with clearstatcache() in other areas of Quick Cache.

That said; I'm curious to know if anyone else reporting this problem is still seeing a large number of these errors in a log file; i.e. more than a few times daily? For instance, in the previous issue (#288) it would seem that our latest clearstatcache() adjustments resolved this for most. Anyone out there still with major issues related to this sort of error?

raamdev · 2015-01-12T20:34:37Z

Just wanted to clarify that errors like these were present both before and after cache locking. The recent cache locking improvements were aimed at resolving this issue.

Right, sorry. I should have said that temp files getting left behind have been ongoing since implementing cache locking, since before cache locking we did not have any temp directories. Also, this issue (prior to cache locking) only exhibited itself rarely, on very large and busy sites. Cache locking (with the new creation and renaming of temp directories) seems to have exasperated the issue (for a yet unknown reason), so more users are now experiencing an issue that previously was only experienced by very large and busy sites.

eurobank · 2015-01-14T11:21:58Z

I'm sorry to say that i have also found today some tmp leftovers in the "cache/http" directory.

I'm running LiteSpeed, Cloudlinux, php 5.5.20 and the server is pretty stable. I guess this is a plugin problem and has not been resolved yet.

jaswrks · 2015-01-15T21:26:47Z

Referencing this block of code. The line with getMTime() is where the error occurs.

/** @var $_file_dir \RecursiveDirectoryIterator Regex iterator reference for IDEs. */
foreach(($_dir_regex_iteration = $this->dir_regex_iteration($_host_cache_dir_tmp, $_host_cache_dir_tmp_regex)) as $_file_dir)
{
    if(($_file_dir->isFile() || $_file_dir->isLink()) // Files and/or symlinks only.

       // Don't delete files in the immediate directory; e.g. `zc-advanced-cache` or `.htaccess`, etc.
       // Actual `http|https/...` cache files are nested. Files in the immediate directory are for other purposes.
       && ($_host_cache_dir !== $cache_dir || strpos($_file_dir->getSubpathname(), '/') !== FALSE)

       // If NOT checking max age; or if we ARE, and the file has expired now.
       && (!$check_max_age || (!empty($max_age) && $_file_dir->getMTime() < $max_age))

    ) // Throw an exception if a deletion failure occurs.
    {
        if(!unlink($_file_dir->getPathname())) // Throw exception if unable to delete.
            throw new \exception(sprintf(__('Unable to delete file: `%1$s`.', $this->text_domain), $_file_dir->getPathname()));
        $counter++; // Increment counter for each file we delete.
    }
    else if(!$check_max_age && $regex === '/^.+/i' && $_file_dir->isDir()) // Directories too?
    {
        if(!rmdir($_file_dir->getPathname())) // Throw exception if unable to delete the directory itself.
            throw new \exception(sprintf(__('Unable to delete dir: `%1$s`.', $this->text_domain), $_file_dir->getPathname()));
        # $counter++; // Increment counter for each directory we delete. ~ NO don't do that here.
    }
}
unset($_dir_regex_iteration, $_file_dir); // Housekeeping after this `foreach()` loop.

I'm currently researching PHP bug reports related to SplFileInfo::getMTime(). Something tells me this is not a problem with Quick Cache, but a PHP bug that we need to work around. As you can see from this block of code (which is also wrapped by a cache lock routine and preceded by a clearstatcache() call). It clearly checks that the file exists before it runs getMTime(). So for getMTime() to fail, something very unexpected is taking place at what appears to be random times throughout the week.

I suppose it is possible that DirectoryIterator::isFile() is not working in the way it is documented. If that's the case, we could try adding an additional is_file() call before running SplFileInfo::getMTime().

jaswrks · 2015-01-15T22:38:38Z

I just noticed that getMTime() will look at the modification time of the realpath() in the case of a symlink. That could explain some of this, because in the case of 404 errors being cached, the underlying 404 error file may have already been deleted in the iteration, before we reach the symlinks that pointed to it. Thus, getMTime() would fail in that scenario.

However, in my error logs I'm seeing entries associated with paths that do exist. So that doesn't explain the entire issue reported here in my view; at least not yet.

The fact that symlinks are not returning a file modification time of their own though; that's going to be an issue of it's own for us to look at.

jaswrks · 2015-01-15T22:42:12Z

Referencing: http://php.net/manual/en/function.lstat.php

raamdev · 2015-01-16T02:15:04Z

I just noticed that getMTime() will look at the modification time of the realpath() in the case of a symlink. That could explain some of this, because in the case of 404 errors being cached, the underlying 404 error file may have already been deleted in the iteration, before we reach the symlinks that pointed to it. Thus, getMTime() would fail in that scenario.

Good catch!

The fact that symlinks are not returning a file modification time of their own though; that's going to be an issue of it's own for us to look at.

@jaswsinc Would you like me to open a new GitHub Issue for that, or do you see that being worked on as part of this issue?

jaswrks · 2015-01-16T02:44:31Z

Would you like me to open a new GitHub Issue for that, or do you see that being worked on as part of this issue?

I think I can work on it as part of this issue. I'm working to improve the way this routine handles symlinks as part of the work to help resolve this, so I think I can just include it here.

raamdev · 2015-01-16T02:45:58Z

I can just include it here.

Cool. Sounds great. Thanks!

…rks/comet-cache#397

jaswrks · 2015-01-16T16:53:21Z

@raamdev I submitted some pull requests that are now ready to merge. They work to resolve this issue. However, I'd like to leave this open for a couple of days while I work on a second PR to take things a step further after additional testing.

raamdev · 2015-01-16T17:04:15Z

I submitted some pull requests that are now ready to merge.

Thank you. I reviewed this and merged them.

I'd like to leave this open for a couple of days while I work on a second PR to take things a step further after additional testing.

Copy that. I'll leave this open.

jaswrks · 2015-01-16T19:01:22Z

I'm running the latest changes at s2Member.com to see if the getMTime() issue still occurs there after the last round of improvements.

jaswrks · 2015-01-16T23:04:39Z

So far so good. I'll leave it for another day or so.

jaswrks · 2015-01-17T17:33:42Z

So far so good. I'll leave it until Monday and provide another update.

jaswrks · 2015-01-19T11:34:20Z

@raamdev I think we have knocked this out finally. I'm not seeing the same issue since the latest improvements in the PRs submitted prior. I think it's safe to close this now and gather additional feedback during the RC phase.

raamdev · 2015-01-19T19:54:07Z

I think it's safe to close this now and gather additional feedback during the RC phase.

Copy that. Thank you for the testing! I will close this for further testing in the Release Candidate.

raamdev · 2015-01-19T19:54:23Z

Next release changelog:

Bug Fix: Several fixes for a stubborn bug related to "Fatal Error: 'Unable to clear dir'" error messages and errors referencing "SplFileInfo::getMTime(): stat failed". Props @jaswsinc. See #397.

raamdev · 2015-01-22T23:15:44Z

@eurobank Quick Cache v150121 (Release Candidate) was released yesterday that includes further fixes for this issue. If you'd like to help test the Release Candidate, that would be greatly appreciated! Please see http://www.websharks-inc.com/post/quick-cache-v150121-release-candidate/

eurobank · 2015-01-25T11:14:00Z

Last time i spoke tooo soon and the problem was not fixed. This time, after 3 days, i see no tmp leftover files or anything.

raamdev · 2015-01-28T19:41:25Z

i see no tmp leftover files or anything.

@eurobank That's great to hear! Thank you for the update. :)

Venique · 2015-01-29T10:00:32Z

Unfortunately, this update does not solve the problem for me... still many temp folders. Which information you need for diagnose?

raamdev · 2015-01-29T21:35:39Z

@Venique writes...

this update does not solve the problem for me

Which update are you referring to? Which version number specifically?

raamdev · 2015-01-30T02:20:19Z

The fixes applied from this issue have been released today with v150129:

Bug Fix: Several fixes for a stubborn bug related to "Fatal Error: 'Unable to clear dir'" error messages and errors referencing "SplFileInfo::getMTime(): stat failed". Props @jaswsinc. See #397.

See the v150129 announcement post.

This issue will now be locked to further updates. If you have something to add related to this Issue, please open a new GitHub Issue and mention this one (#397).

raamdev added bug lite pro labels Jan 12, 2015

raamdev mentioned this issue Jan 12, 2015

"Fatal Error: 'Unable to clear dir'" #288

Closed

raamdev added this to the Next Release milestone Jan 12, 2015

jaswrks self-assigned this Jan 12, 2015

jaswrks added the ready for work label Jan 12, 2015

jaswrks added in progress and removed ready for work labels Jan 15, 2015

jaswrks pushed a commit to wpsharks/zencache-pro-original that referenced this issue Jan 16, 2015

Improving clear/purge/wipe utilities in the share class. See: wpsha…

3777535

…rks/comet-cache#397

jaswrks pushed a commit to wpsharks/comet-cache-pro that referenced this issue Jan 16, 2015

Improving clear/purge/wipe utilities in the share class. See: wpsha…

39dffa4

…rks/comet-cache#397

jaswrks pushed a commit that referenced this issue Jan 16, 2015

Improving clear/purge/wipe utilities in the share class. See: #397

660608c

raamdev added a commit that referenced this issue Jan 16, 2015

Merge branch 'feature/#397' into 000000-dev

370cedd

jaswrks added ready to merge and removed in progress labels Jan 19, 2015

raamdev closed this as completed Jan 19, 2015

raamdev removed the ready to merge label Jan 19, 2015

wpsharks locked and limited conversation to collaborators Jan 30, 2015

raamdev added a commit that referenced this issue Mar 6, 2015

Merge branch 'feature/#397' into 000000-dev

978a994

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Temp Files in Cache Directory Fail to Clear #397

Temp Files in Cache Directory Fail to Clear #397

raamdev commented Jan 12, 2015

jaswrks commented Jan 12, 2015

raamdev commented Jan 12, 2015

eurobank commented Jan 14, 2015

jaswrks commented Jan 15, 2015

jaswrks commented Jan 15, 2015

jaswrks commented Jan 15, 2015

raamdev commented Jan 16, 2015

jaswrks commented Jan 16, 2015

raamdev commented Jan 16, 2015

jaswrks commented Jan 16, 2015

raamdev commented Jan 16, 2015

jaswrks commented Jan 16, 2015

jaswrks commented Jan 16, 2015

jaswrks commented Jan 17, 2015

jaswrks commented Jan 19, 2015

raamdev commented Jan 19, 2015

raamdev commented Jan 19, 2015

raamdev commented Jan 22, 2015

eurobank commented Jan 25, 2015

raamdev commented Jan 28, 2015

Venique commented Jan 29, 2015

raamdev commented Jan 29, 2015

raamdev commented Jan 30, 2015

Temp Files in Cache Directory Fail to Clear #397

Temp Files in Cache Directory Fail to Clear #397

Comments

raamdev commented Jan 12, 2015

jaswrks commented Jan 12, 2015

raamdev commented Jan 12, 2015

eurobank commented Jan 14, 2015

jaswrks commented Jan 15, 2015

jaswrks commented Jan 15, 2015

jaswrks commented Jan 15, 2015

raamdev commented Jan 16, 2015

jaswrks commented Jan 16, 2015

raamdev commented Jan 16, 2015

jaswrks commented Jan 16, 2015

raamdev commented Jan 16, 2015

jaswrks commented Jan 16, 2015

jaswrks commented Jan 16, 2015

jaswrks commented Jan 17, 2015

jaswrks commented Jan 19, 2015

raamdev commented Jan 19, 2015

raamdev commented Jan 19, 2015

raamdev commented Jan 22, 2015

eurobank commented Jan 25, 2015

raamdev commented Jan 28, 2015

Venique commented Jan 29, 2015

raamdev commented Jan 29, 2015

raamdev commented Jan 30, 2015