Problem/Motivation

If you have a temporary file and for some reason the file on the disk for it no longer exists, it logs an error every time file_cron() runs:

Could not delete temporary file x during garbage collection

Proposed resolution

The file is gone. Maybe log an error or warning once, then drop the record.

Remaining tasks

User interface changes

API changes

Data model changes

CommentFileSizeAuthor
#57 2802803-57.patch3.04 KBalexpott
#57 43-57-interdiff.txt3.82 KBalexpott
#43 interdiff.txt1.03 KBAdamPS
#43 missing-temp-files-stuck-in-table-2802803-43.patch3.08 KBAdamPS
#41 interdiff.txt497 bytesAdamPS
#41 missing-temp-files-stuck-in-table-2802803-41.patch3.06 KBAdamPS
#33 missing-temp-files-stuck-in-table-2802803-33.patch3.07 KBjackbravo
#28 interdiff-11-28.txt599 bytesDarren Oh
#28 missing-temp-files-stuck-in-table-2802803-28.patch2.9 KBDarren Oh
#11 interdiff.txt1.39 KBMunavijayalakshmi
#11 2802803-11.patch2.59 KBMunavijayalakshmi
#7 2802803_6.patch2.6 KBBerdir
#6 2802803_6-test-only.patch1.45 KBBerdir
#6 2802803_6-test-only.patch1.45 KBBerdir
#2 2802803_2.patch1.16 KBslashrsm
Support from Acquia helps fund testing for Drupal Acquia logo

Comments

Berdir created an issue. See original summary.

slashrsm’s picture

Status: Active » Needs review
FileSize
1.16 KB

Something along those lines?

dawehner’s picture

That's non trivial given that many systems drop log messages quite quickly, so potentially you'll never see the message.

Berdir’s picture

Yes, that's true for all log messages yes, also like content being deleted. But it's better than spaming the log and causing even more useful messages to get lost :)

Version: 8.3.x-dev » 8.4.x-dev

Drupal 8.3.0-alpha1 will be released the week of January 30, 2017, which means new developments and disruptive changes should now be targeted against the 8.4.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

Berdir’s picture

Re-rolled and included the test from #2760347: file_cron does not remove orphaned entries. Will close that as duplicate. Please also credit those from that issue. Will also close #2850497: Unclear log message when CRON garbage collection is unable to clean up temporary files as duplicate.

Berdir’s picture

Berdir’s picture

For the record, we're seeing this from time to time on our systems, haven't been able to track down what exactly is causing it yet, but as I said, the file is gone and we wanted to delete it anyway.

The last submitted patch, 6: 2802803_6-test-only.patch, failed testing.

The last submitted patch, 6: 2802803_6-test-only.patch, failed testing.

Munavijayalakshmi’s picture

+++ b/core/modules/file/file.module
@@ -659,12 +659,10 @@ function file_cron() {
+          \Drupal::logger('file system')->warning('Temporary file "%path" that was deleted during garbage collection did not exist on the filesystem.', array('%path' => $file->getFileUri()));

+++ b/core/modules/file/tests/src/Kernel/DeleteTest.php
@@ -69,4 +69,29 @@ public function testInUse() {
+      ->fields(array(
+        'changed' => \Drupal::time()->getRequestTime() - ($this->config('system.file')->get('temporary_maximum_age') + 1),
+      ))

use short array syntax (new coding standard).

Fixed the short array syntax error.

LittleCoding’s picture

This error can also be triggered via the read permissions of the file being misconfigured. So it does not look like a good practice to force a delete in this case.

gapple’s picture

Closed #2725457: Managed file garbage collector should delete file entity even if physical file does not exst. as a duplicate. The major difference in the patch in that issue is that it also performs an is_writable() check if the file still exists.

gapple’s picture

In the comments for #1401558: Remove the usage handling logic from file_delete() where the file_exists() check was added, there was also a concern about deleting the file entity if the stream wrapper was only disabled.

Dane Powell’s picture

Issue summary: View changes
Status: Needs review » Reviewed & tested by the community

I posted a very similar patch in #2885525: Missing temporary files cause errors on cron (closed as dupe). I also detailed a few of the very many benign causes of this error.

The reason I didn't find this issue is because I was searching for the actual error message, which isn't posted anywhere here. I added it to the issue description.

This patch looks good to me.

catch’s picture

Status: Reviewed & tested by the community » Fixed

#12 and #14 both need answering still I think? What are the implications for trying to delete the file if it exists but can't be read for some reason, couldn't that cause even more errors?

Dane Powell’s picture

Status: Fixed » Needs work

I'm assuming this wasn't meant to be marked "fixed"...

Version: 8.4.x-dev » 8.5.x-dev

Drupal 8.4.0-alpha1 will be released the week of July 31, 2017, which means new developments and disruptive changes should now be targeted against the 8.5.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

lslinnet’s picture

I am not sure if this fits inside of this issue, but there is also the side effect of this "file_exists" check that if 100+ file_managed records turn up with missing files then we have a useless cron job that keeps checking the same 100 records over and over again.

This have happened on my current project which have caused the file_managed table to grow to a few millions records, where a large amount of these are temporary files that should have been deleted along time ago.

Perhaps implementing a sort order in the lookup query, so it takes the most recent first would be a simple way to avoid an endless deadlock?

marcoscano’s picture

I'm experiencing this too. An easy way to reproduce this is to create a custom form with a managed_file element, upload a file, and then in your validate or submit function you execute:

// ...
$fid = $form_state->getValue('my_managed_file_element');
if (!empty($fid[0]) {
  File::load($fid[0])->delete();
}

The file will be erased from disk, as well as the file entity, but the record will still be present in the managed_file table, which will be used during garbage collection.

I was assuming that File::delete() would take care of everything, but I see that it uses file_unmanaged_delete() (source) to delete the file itself... Is it normal? Should I be deleting the file entity differently?

Version: 8.5.x-dev » 8.6.x-dev

Drupal 8.5.0-alpha1 will be released the week of January 17, 2018, which means new developments and disruptive changes should now be targeted against the 8.6.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

mrtndlmt’s picture

Thanks for the patch! Works for me on Drupal 8.4.4!

wiifm’s picture

Status: Needs work » Reviewed & tested by the community

With regards to #12, I can't think of any good reason why you would have a file writeable (so you could delete it), but not readable (like doing a chmod 222). You probably have larger concerns on your hands if this is the chmod value of any of your web server controlled files. So I think that is more of a theoretic issue.

Here is my experience with using this patch.

Before applying patch (stock Drupal core)

I see maybe a few hundred errors like this in the cron logs. These message repeat on every and all cron runs for the impacted sites. There is no easy way to fix this, and the error message is less than helpful.:

    Could not delete temporary file "public://2017-11/main05.jpg" during     [error]
    garbage collection

I believe the problem is exacerbated on large multisites where you clone sites, but for whatever reason do not clone the public files (so the managed_files table references files that never exist). This at least was the cause of the errors for me.

After the patch

Have applied the patch from #11. I see file files being cleaned up in the cron logs, along the lines of:

Temporary file "public://video_thumbnails/4780455931001.jpg" that was  [warning]
    deleted during garbage collection did not exist on the filesystem.

After a few cron runs, the list of files missing reduces to 0, and finally cron runs without producing any errors.

Marking as RTBC, as I feel the patch is well tested (has test cases), fixing the issue at hand, with no unwanted side effects on real life production systems.

larowlan’s picture

Issue summary: View changes
Status: Reviewed & tested by the community » Needs work

Thanks @wiifm for the detailed review, adding a review credit.

However #16 moved this to needs work because #12 and #14 were yet to be answered.

The same scenario exists, I'll update the IS

acbramley’s picture

It seems like @wiifm addressed #12 so all that remains is #14? The linked issue is lengthy with some detailed commentary so I'm wondering if we can get an summary of exactly what the issue is?

From what I can gather, the problem #14 describes is "we don't want to delete files with disabled stream wrappers". The main commentary in #1401558: Remove the usage handling logic from file_delete() about that is here which seems to have been discussed in IRC and dropped soon after. Doing a quick scan of the codebase, the only file API functions I can see file_valid_uri() being used in file_copy, file_move, and file_save_data so it might be safe to say we don't have to worry about it here?

I may have missed something so correct me if I'm wrong :)

Darren Oh’s picture

This patch duplicates existing code. I have confirmed that when running cron as an admin user, the temporary files are removed. We can choose one of two fixes:

  1. Allow cron to delete the files regardless of which user it runs as.
  2. Change the error message to an info message suggesting that cron may be run with an admin account to delete the files.

See DRUPAL: How To Fix The “Could not delete temporary file” error.

bohemier’s picture

I have tested the same as #23 with patch #11. The temporary files were removed from the files table, and cron reported the 2 entries in the log for each file:

[Warning] Temporary file "public://xxx" that was deleted during garbage collection did not exist on the filesystem.
[Info] The file public://xxx was not deleted because it does not exist.

I have tried to run cron as admin as suggested by #26 but the problem persists unless I manually delete the entries from the File table.

Darren Oh’s picture

Sorry, I was testing on Drupal 7. The patch is needed on Drupal 8. I have updated it so that it generates only one error message.

3CWebDev’s picture

Tested Patch #28 and confirmed that it resolved the issue.

Test first without a patch and confirmed the issue exists where a manually deleted file from the disk system causes never-ending watchdog warnings.

Applied that path and ran cron again, this time only one message was received:

	The file public://FILENAME was not deleted because it does not exist.

Subsequent cron runs produced no further watchdog log messages.

Darren Oh’s picture

Status: Needs review » Reviewed & tested by the community
alexpott’s picture

Status: Reviewed & tested by the community » Needs work
+++ b/core/modules/file/file.module
@@ -714,12 +714,7 @@ function file_cron() {
+        $file->delete();

I think we need a comment that we do this even if the file does not exist and rely on the notices produced by file_unmanaged_delete() to inform the user if this is the case. Similar to the comment in \Drupal\file\Entity\File::preDelete().

We still need a definitive answer to #14 - @acbramley has written an answer in #25 but it does not seem definitive. Is their anyway we can detect if this file is using a stream wrapper and do different things if it is?

LittleCoding’s picture

The log message feels a little misleading now. The managed file entry in the database has been deleted even if they file was not.

To address #25 we could do something like CURL the file, reading the response header code with in the IF does not exist. But this may be over kill.

jackbravo’s picture

Status: Needs work » Needs review
FileSize
3.07 KB

Based on the comments on #25, I'm adding a check using file_valid_uri(), if it fails I log that a stream wrapper may be missing. Tests are the same and run fine. In any case, I'm adding back the log message so it is not misleading just seeing in the watchdog a NOT FOUND FILE notice.

Version: 8.6.x-dev » 8.7.x-dev

Drupal 8.6.0-alpha1 will be released the week of July 16, 2018, which means new developments and disruptive changes should now be targeted against the 8.7.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

steveoriol’s picture

The patch #33 works well for me, Thanks.

plato1123’s picture

As others have mentioned if you're just trying to clean out a handful of entries, they exist in the file_managed table. You can do so with phpmyadmin or if you don't have that installed you can do 'drush sql-cli' to get into an sql command interface, and then remove the offending entry with something like
delete from file_managed where filename = "LaKelly.jpg";

edit:

or if you want to clear all listings that pertain to a certain folder (which in my case was long gone), you'd do
delete from file_managed WHERE uri LIKE '%wp-content%';

back up your database before trying the above. Looks like in my case although the logs only showed the first 100 or so error messages, Drupal was trying to delete 3700 files that no longer existed.

Darren Oh’s picture

Issue tags: +fldc19
mmbk’s picture

This problem bothers me for quite a long time, I don't know why I did not find this issue previously - shame on me.

Personally, I don't see any reason, why the database record (that shall be deleted), should be preserved, only because the referring file does not exist or is not readable. So if the file does not exist, I wouldn't even submit a warning, as the absence of the file is the intended state. The file_unmanaged_delete() will submit the warning, that should be enough.

(Rather I would log every file record that is deleted, but this might be out of the scope of this issue)

Nevertheless, the patches #28 & #33 are working fine.

@plato1123 #36 rather than deleting the records from the database, with the danger to mess it up, just touch the file in question inside your 'files'-folder - the next cron run will delete your touched file and cleanup the database. If there are too many entries for doing it manually 'sed' cron's output and do it automatically.

AdamPS’s picture

Issue summary: View changes
Status: Needs review » Needs work

I have reviewed the patch and found one typo:

+            \Drupal::logger('file system')->warning('Temporary file "%path" that was deleted during garbage collection did not exist on the filesystem. This is could be caused by a missing stream wrapper.', ['%path' => $file->getFileUri()]);

"This is could " => "This could "

Once that is fixed I think we can go back to RTBC.

I have deleted this text from the IS

Address #12 and #14

  • #12 was covered in #23
  • #14 is addressed by extra logs in patch #33

Version: 8.7.x-dev » 8.8.x-dev

Drupal 8.7.0-alpha1 will be released the week of March 11, 2019, which means new developments and disruptive changes should now be targeted against the 8.8.x-dev branch. For more information see the Drupal 8 minor version schedule and the Allowed changes during the Drupal 8 release cycle.

AdamPS’s picture

Status: Needs work » Needs review
FileSize
3.06 KB
497 bytes

Fixed #39

Status: Needs review » Needs work

The last submitted patch, 41: missing-temp-files-stuck-in-table-2802803-41.patch, failed testing. View results

AdamPS’s picture

mmbk’s picture

patch #43 works as expected on 8.8.x-dev and still applies to 8.6.10. I did not apply this to 8.7.x

Darren Oh’s picture

Status: Needs review » Reviewed & tested by the community

Thanks for all the contributions on this.

Status: Reviewed & tested by the community » Needs work

The last submitted patch, 43: missing-temp-files-stuck-in-table-2802803-43.patch, failed testing. View results

mmbk’s picture

Hmm very strange.

I checked this locally, with php version 7.1 7.2 7.3 the tests succeed. And the file is deleted correctly from the database table.
(btw. the filename and the uri uses russian characters - it this on purpose?)

I found that:

 if (!isset($filepath)) {
      // Prefix with non-latin characters to ensure that all file-related
      // tests work with international filenames.
      $filepath = 'Файл для тестирования ' . $this->randomMachineName();
    }
mmbk’s picture

Status: Needs work » Reviewed & tested by the community

Put it back to RTBC - test is working

alexpott’s picture

Status: Reviewed & tested by the community » Fixed

Discussed with @catch and @berdir. We all think that this will significantly reduce noise in the logs which is a good thing. @Berdir pointed out that maybe a mounted storage has gone away but even in this case there are no references to these files so the worst that will happen is that the file entity will be deleted and then if a user uploads a file with the same name to the same folder it'll get an _2 ... so not the biggest problem. I think that this answers #14 sufficiently for a commit.

I creditted reviewers and testers who provided test evidence.

Committed and pushed e4188e4dec to 8.8.x and 675ffa2166 to 8.7.x. Thanks!

  • alexpott committed e4188e4 on 8.8.x
    Issue #2802803 by Berdir, AdamPS, Darren Oh, Munavijayalakshmi,...

  • alexpott committed 675ffa2 on 8.7.x
    Issue #2802803 by Berdir, AdamPS, Darren Oh, Munavijayalakshmi,...
Sam152’s picture

Version: 8.8.x-dev » 8.7.x-dev
Status: Fixed » Patch (to be ported)

This has broken 8.7 HEAD.

Edit: Hm, it might just be intermittent, but I noticed it passed on the 8.x branch and failed on the 7.x branch here: https://www.drupal.org/node/3060/qa

  • larowlan committed f1e6647 on 8.7.x
    Revert "Issue #2802803 by Berdir, AdamPS, Darren Oh, Munavijayalakshmi,...
larowlan’s picture

Reverted as f1e6647 and pushed to 8.7.x.

alexpott’s picture

Version: 8.7.x-dev » 8.8.x-dev
Status: Patch (to be ported) » Needs work

Let's revert from 8.8.x too. It seems that this breaks PHP 7.3-dev tests - see https://www.drupal.org/pift-ci-job/1241663

  • alexpott committed 01efa20 on 8.8.x
    Revert "Issue #2802803 by Berdir, AdamPS, Darren Oh, Munavijayalakshmi,...
alexpott’s picture

I suspected that this might be because of using \Drupal::time()->getRequestTime() and not REQUEST_TIME like the underlying cron implementation does. I don't think we can move to \Drupal::time()->getRequestTime() before the code we are testing has.

Berdir’s picture

Status: Needs review » Reviewed & tested by the community

Yes, had the same thought about the request time yesterday in slack, not sure if you saw that or came to the same conclusion on your own, either way, this should be more reliable. Was also thinking about doing a +5 instead of just +1, but using the same constant will be fine, we'll just need to make sure we update both at the same time.

alexpott’s picture

Status: Reviewed & tested by the community » Fixed

Second time lucky - I don;t think my tiny changes to the test in #57 preclude me from committing this.

Committed and pushed 00b3590a1d to 8.8.x and 402dd05297 to 8.7.x. Thanks!

As a bug fix this is eligible for backport to 8.7.x

  • alexpott committed 00b3590 on 8.8.x
    Issue #2802803 by Berdir, AdamPS, Darren Oh, alexpott, Munavijayalakshmi...

  • alexpott committed 402dd05 on 8.7.x
    Issue #2802803 by Berdir, AdamPS, Darren Oh, alexpott, Munavijayalakshmi...
alexpott’s picture

Version: 8.8.x-dev » 8.7.x-dev

Status: Fixed » Closed (fixed)

Automatically closed - issue fixed for 2 weeks with no activity.