Bug 200831 – Logging in FileSystem::deleteFile should avoid logging unsurprising errors

• Component: WebCore Misc.
• Status: RESOLVED FIXED

[Kate Cheney]

Currently, FileSystem::deleteFile logs every failed delete of a file. To avoid excess logging, a caller should be able to indicate any errors they would expect or be unsurprised to see happen, which should not be logged.

[Kate Cheney]

Created attachment 376787 [details]
Patch

[Darin Adler]

Comment on attachment 376787 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376787&action=review

> Source/WTF/wtf/FileSystem.h:83
> +// Avoids overlogging by enumerating expected errors when deleting a file.
> +// Add additional definitions as needed (integer is the errno value).
> +enum ExpectedError {
> +    FileDoesntExist = 2
> +};

It’s not good abstraction to actually use POSIX error numbers here. This should just be a plain old enumeration without match errno values.

> Source/WTF/wtf/FileSystem.h:113
> +WTF_EXPORT_PRIVATE bool deleteFile(const String&, OptionSet<ExpectedError> expectedErrors = OptionSet<ExpectedError>());

Can write it this way:

    OptionSet<ExpectedError> = { }

No need for an argument name since the type makes it completely clear, it's a set of expected errors. No need to repeat the type since we can use the { } syntax.

> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:77
> +        int error = errno;

I don’t think it’s really OK to convert the errno to an ExpectedError without a switch statement. For now lets just write something more like this:

    Optional<ExpectedError> error;
    switch (errno) {
    case ENOENT:
        error = FileDoesNotExist;
        break;
    }
    if (error && !expectedErrors.contains(error.value()))
        LOG_ERROR("File failed to delete. Error message: %s", strerror(errno));

> Source/WebCore/loader/appcache/ApplicationCacheStorage.cpp:828
> +        if (!fullPath.isEmpty()) {
> +            OptionSet<FileSystem::ExpectedError> expectedErrors = OptionSet<FileSystem::ExpectedError>();
> +            expectedErrors.add(FileSystem::FileDoesntExist);
> +            FileSystem::deleteFile(fullPath, expectedErrors);
> +        }

OptionSet is constructible from a single value in a straightforward way for a case like this. The code should be something more like:

    if (!fullPath.isEmpty())
        FileSystem::deleteFile(fullPath, FileDoesNotExist);

But I think this makes it clear we would be better off with ExpectedError as an enum class instead of an enum, because then it would be the easier to understand:

    if (!fullPath.isEmpty())
        FileSystem::deleteFile(fullPath, ExpectedError::FileDoesNotExist);

Same for the other cases below.

[Darin Adler]

Comment on attachment 376787 [details]
Patch

I’m puzzled by the EWS failures

[Kate Cheney]

Created attachment 376932 [details]
Patch

[Kate Cheney]

(In reply to Darin Adler from comment #3)
> Comment on attachment 376787 [details]
> Patch
> 
> I’m puzzled by the EWS failures

Thanks for the feedback! All looks good. I ran a small manual test and realized the enum values default to 0, which was causing the OptionSet to think that it was empty (it was performing bitwise & operations on a 0 value). So the only change I made to your suggestions was I set an FileDoesNotExist bit to 1.

[Kate Cheney]

(In reply to Darin Adler from comment #3)
> Comment on attachment 376787 [details]
> Patch
> 
> I’m puzzled by the EWS failures

I am equally puzzled. I will look into this.

[Chris Dumez]

Comment on attachment 376932 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376932&action=review

> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:65
> +bool deleteFile(const String& path, OptionSet<ExpectedError> expectedErrors)

I personally do not like that we're making the API more complex just to avoid some debug logging. My suggestion would be to not change the API and never log_error in the ENOENT case (since the file is already not there).

> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:-77
> -        LOG_ERROR("File failed to delete. Error message: %s", strerror(errno));

Note that this is debug only logging.

[Chris Dumez]

(In reply to Katherine_cheney from comment #6)
> (In reply to Darin Adler from comment #3)
> > Comment on attachment 376787 [details]
> > Patch
> > 
> > I’m puzzled by the EWS failures
> 
> I am equally puzzled. I will look into this.

The latest EWS failures seem to be because the patch failed to update the deleteFile() implementation used by other ports than macOS/iOS:
Source/WTF/wtf/glib/FileSystemGlib.cpp:bool deleteFile(const String& path)
Source/WTF/wtf/win/FileSystemWin.cpp:bool deleteFile(const String& path)

[Darin Adler]

Comment on attachment 376932 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376932&action=review

>> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:65
>> +bool deleteFile(const String& path, OptionSet<ExpectedError> expectedErrors)
> 
> I personally do not like that we're making the API more complex just to avoid some debug logging. My suggestion would be to not change the API and never log_error in the ENOENT case (since the file is already not there).

Since I suggested this more-complex change in the first place then I suppose I should give my opinion on this feedback:

- If it’s always a good idea to not log when it’s ENOENT and we still achieve our goals (whatever our reason was for wanting this logged), then we can go with that, and come back to a more complex solution only if there is a good reason.

- If there are some cases where we want to log even for ENOENT we could consider having two deleteFile functions with the different expectations and logging behaviors rather than the more complex argument; internally they would call a common helper but the interface would stay a little simpler.

- This complex solution might still be a good idea if it turns out we do have more complex needs.

By the way, I think it is worthwhile to keep harmless messages out of the logs, even only the debug logs. So it’s OK to have the code be slightly more complex to achieve that. But I agree that we should not make it *unnecessarily* complex.

>> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:-77
>> -        LOG_ERROR("File failed to delete. Error message: %s", strerror(errno));
> 
> Note that this is debug only logging.

Good point. Is that OK? Do we achieve our goals with debug-only logging?

[Chris Dumez]

Comment on attachment 376932 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=376932&action=review

Sorry, I had not realized I overruled the previous reviewer, I should have read previous comments, instead of simply clicking the review link in the mail notification.

>>> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:65
>>> +bool deleteFile(const String& path, OptionSet<ExpectedError> expectedErrors)
>> 
>> I personally do not like that we're making the API more complex just to avoid some debug logging. My suggestion would be to not change the API and never log_error in the ENOENT case (since the file is already not there).
> 
> Since I suggested this more-complex change in the first place then I suppose I should give my opinion on this feedback:
> 
> - If it’s always a good idea to not log when it’s ENOENT and we still achieve our goals (whatever our reason was for wanting this logged), then we can go with that, and come back to a more complex solution only if there is a good reason.
> 
> - If there are some cases where we want to log even for ENOENT we could consider having two deleteFile functions with the different expectations and logging behaviors rather than the more complex argument; internally they would call a common helper but the interface would stay a little simpler.
> 
> - This complex solution might still be a good idea if it turns out we do have more complex needs.
> 
> By the way, I think it is worthwhile to keep harmless messages out of the logs, even only the debug logs. So it’s OK to have the code be slightly more complex to achieve that. But I agree that we should not make it *unnecessarily* complex.

I agree we should not log harmless messages and my proposal achieves that. My belief is that the only reason we currently log an error when the file is missing is simply an oversight.

If there were more types of errors we’d like to ignore then I think the new API would make a lot of sense. However, in the currently state, it seems unnecessary complex to me. I am hoping we can go with my simpler proposal for now.

>>> Source/WTF/wtf/posix/FileSystemPOSIX.cpp:-77
>>> -        LOG_ERROR("File failed to delete. Error message: %s", strerror(errno));
>> 
>> Note that this is debug only logging.
> 
> Good point. Is that OK? Do we achieve our goals with debug-only logging?

If we do not log an error when the file is missing, then I would support moving to a RELEASE_LOG_ERROR().

[Kate Cheney]

I agree that we shouldn't make things unnecessarily complex. In terms of ignoring all ENOENT errors, I propose a scenario where a user tries to delete an incorrect path (like cookies) and it fails to delete. It might be useful in that case to know that the error was ENOENT so that even if you can't see the path itself, it leads you to discover the incorrect-path bug.

Another idea is the OptionSet could default to hold ENOENT, so in most all cases logging for a missing file would be ignored. Then a caller could pass an empty OptionSet (with an apt constant name like logAllErrors) to the deleteFile call if they wanted to see ENOENT errors. 

This doesn't solve the complex API problem, but it probably would reduce unnecessary logging of ENOENT.

[Chris Dumez]

(In reply to Katherine_cheney from comment #11)
> I agree that we shouldn't make things unnecessarily complex. In terms of
> ignoring all ENOENT errors, I propose a scenario where a user tries to
> delete an incorrect path (like cookies) and it fails to delete. It might be
> useful in that case to know that the error was ENOENT so that even if you
> can't see the path itself, it leads you to discover the incorrect-path bug.

This seems theoretical at this point since your patch seems to ignore ENOENT at all call sites, unless I missed something. So until we actually need the behavior you suggest, I would hold off on changing the API.

[Kate Cheney]

(In reply to Chris Dumez from comment #12)
> (In reply to Katherine_cheney from comment #11)
> > I agree that we shouldn't make things unnecessarily complex. In terms of
> > ignoring all ENOENT errors, I propose a scenario where a user tries to
> > delete an incorrect path (like cookies) and it fails to delete. It might be
> > useful in that case to know that the error was ENOENT so that even if you
> > can't see the path itself, it leads you to discover the incorrect-path bug.
> 
> This seems theoretical at this point since your patch seems to ignore ENOENT
> at all call sites, unless I missed something. So until we actually need the
> behavior you suggest, I would hold off on changing the API.

Okay. I'll go ahead and upload a patch that ignores ENOENT errors because I've been getting some feedback that the additional logging is a little too verbose when running layout tests. We can always revisit changing the API if the need arises in the future.

[Kate Cheney]

Created attachment 377040 [details]
Patch

[Chris Dumez]

Comment on attachment 377040 [details]
Patch

r=me

[WebKit Commit Bot]

Comment on attachment 377040 [details]
Patch

Clearing flags on attachment: 377040

Committed r249027: <https://trac.webkit.org/changeset/249027>

[WebKit Commit Bot]

All reviewed patches have been landed.  Closing bug.

[Radar WebKit Bug Importer]

<rdar://problem/54614611>